TestFileWatcher/does_not_emit_events_for_empty_files/emits_a_create_event_once_something_is_written_to_the_empty_file

[belimawr]

Flaky Test

• Test Name: TestFileWatcher/does_not_emit_events_for_empty_files/emits_a_create_event_once_something_is_written_to_the_empty_file
• Link: https://buildkite.com/elastic/filebeat/builds/10071#01927d37-f10c-420b-9c98-f05d31df75a1/207-425
• PR: Use journald for system module on Debian 12 #41061
• Notes: I tired on my machine (Windows) and it passes. Even when running with -count=10

Stack Trace

=== Failed
--
  | === FAIL: filebeat/input/filestream TestFileWatcher/does_not_emit_events_for_empty_files/emits_a_create_event_once_something_is_written_to_the_empty_file (0.15s)
  | fswatch_test.go:308:
  | Error Trace:	C:/buildkite-agent/builds/bk-agent-prod-gcp-1728677677733351255/elastic/filebeat/filebeat/input/filestream/fswatch_test.go:941
  | C:/buildkite-agent/builds/bk-agent-prod-gcp-1728677677733351255/elastic/filebeat/filebeat/input/filestream/fswatch_test.go:308
  | Error:      	Not equal:
  | expected: "C:\\Users\\BUILDK~1\\AppData\\Local\\Temp\\TestFileWatcherdoes_not_emit_events_for_empty_files2622111839\\001\\created.log"
  | actual  : ""
  |  
  | Diff:
  | --- Expected
  | +++ Actual
  | @@ -1 +1 @@
  | -C:\Users\BUILDK~1\AppData\Local\Temp\TestFileWatcherdoes_not_emit_events_for_empty_files2622111839\001\created.log
  | +
  | Test:       	TestFileWatcher/does_not_emit_events_for_empty_files/emits_a_create_event_once_something_is_written_to_the_empty_file
  | Messages:   	NewPath
  |  
  | === FAIL: filebeat/input/filestream TestFileWatcher/does_not_emit_events_for_empty_files (0.19s)

[elasticmachine]

Pinging @elastic/elastic-agent-data-plane (Team:Elastic-Agent-Data-Plane)

[belimawr]

I ran the same tests on main today, 1000 times and it fails, but on a different subtest

PS C:\devel\beats\filebeat\input\filestream> go test -count=1000 -run=TestFileWatcher
--- FAIL: TestFileWatcher (1.79s)
    --- FAIL: TestFileWatcher/does_not_emit_an_event_for_a_fingerprint_collision (0.12s)
        fswatch_test.go:342:
                Error Trace:    C:/devel/beats/filebeat/input/filestream/fswatch_test.go:941
                                                        C:/devel/beats/filebeat/input/filestream/fswatch_test.go:342
                Error:          Not equal:
                                expected: "C:\\Users\\Tiago\\AppData\\Local\\Temp\\TestFileWatcherdoes_not_emit_an_event_for_a_fingerprint_collision982624479\\001\\created.log"
                                actual  : ""

                                Diff:
                                --- Expected
                                +++ Actual
                                @@ -1 +1 @@
                                -C:\Users\Tiago\AppData\Local\Temp\TestFileWatcherdoes_not_emit_an_event_for_a_fingerprint_collision982624479\001\created.log
                                +
                Test:           TestFileWatcher/does_not_emit_an_event_for_a_fingerprint_collision
                Messages:       NewPath
panic: test timed out after 10m0s
        running tests:
                TestFileWatcher (1s)
                TestFileWatcher/does_not_emit_events_if_a_file_is_touched_and_resend_on_touch_is_disabled (1s)

goroutine 10314 [running]:
testing.(*M).startAlarm.func1()
        C:/Program Files/Go/src/testing/testing.go:2373 +0x385
created by time.goFunc
        C:/Program Files/Go/src/time/sleep.go:215 +0x2d

goroutine 1 [chan receive]:
testing.(*T).Run(0xc00043eea0, {0xfc5c30?, 0x7fff42130e50?}, 0x107efe0)
        C:/Program Files/Go/src/testing/testing.go:1751 +0x392
testing.runTests.func1(0xc00043eea0)
        C:/Program Files/Go/src/testing/testing.go:2168 +0x37
testing.tRunner(0xc00043eea0, 0xc00050fc70)
        C:/Program Files/Go/src/testing/testing.go:1690 +0xcb
testing.runTests(0xc0003143d8, {0x1958740, 0x12, 0x12}, {0x51322d?, 0xc000227dd0?, 0x197e100?})
        C:/Program Files/Go/src/testing/testing.go:2166 +0x43d
testing.(*M).Run(0xc00036a460)
        C:/Program Files/Go/src/testing/testing.go:2034 +0x64a
main.main()
        _testmain.go:87 +0x9b

goroutine 10310 [select]:
github.com/elastic/go-concert/timed.Periodic({0x151fdd71980, 0xc000153880}, 0xc000153880?, 0xc000051f80)
        C:/Users/Tiago/go/pkg/mod/github.com/elastic/[email protected]/timed/timed.go:82 +0xf5
github.com/elastic/beats/v7/filebeat/input/filestream.(*fileWatcher).Run(0xc0001d3680, {0x151ff7040e8, 0xc000153880})
        C:/devel/beats/filebeat/input/filestream/fswatch.go:117 +0xb5
created by github.com/elastic/beats/v7/filebeat/input/filestream.TestFileWatcher in goroutine 10308
        C:/devel/beats/filebeat/input/filestream/fswatch_test.go:58 +0x1ce

goroutine 10295 [select]:
github.com/elastic/go-concert/timed.Periodic({0x151fdd71980, 0xc000590690}, 0xc000590690?, 0xc000375f80)
        C:/Users/Tiago/go/pkg/mod/github.com/elastic/[email protected]/timed/timed.go:82 +0xf5
github.com/elastic/beats/v7/filebeat/input/filestream.(*fileWatcher).Run(0xc0002f4090, {0x151ff7040e8, 0xc000590690})
        C:/devel/beats/filebeat/input/filestream/fswatch.go:117 +0xb5
created by github.com/elastic/beats/v7/filebeat/input/filestream.TestFileWatcher.func8 in goroutine 10293
        C:/devel/beats/filebeat/input/filestream/fswatch_test.go:232 +0x217

goroutine 10308 [chan receive]:
testing.(*T).Run(0xc00043f040, {0xff90a7?, 0x1?}, 0x107f1a0)
        C:/Program Files/Go/src/testing/testing.go:1751 +0x392
github.com/elastic/beats/v7/filebeat/input/filestream.TestFileWatcher(0xc00043f040)
        C:/devel/beats/filebeat/input/filestream/fswatch_test.go:220 +0x4dc
testing.tRunner(0xc00043f040, 0x107efe0)
        C:/Program Files/Go/src/testing/testing.go:1690 +0xcb
created by testing.(*T).Run in goroutine 1
        C:/Program Files/Go/src/testing/testing.go:1743 +0x377

goroutine 10293 [chan receive]:
github.com/elastic/beats/v7/filebeat/input/filestream.(*fileWatcher).Event(0xc00038aa20?)
        C:/devel/beats/filebeat/input/filestream/fswatch.go:255 +0x6a
github.com/elastic/beats/v7/filebeat/input/filestream.TestFileWatcher.func8(0xc0002e6000)
        C:/devel/beats/filebeat/input/filestream/fswatch_test.go:254 +0x5bb
testing.tRunner(0xc0002e6000, 0x107f1a0)
        C:/Program Files/Go/src/testing/testing.go:1690 +0xcb
created by testing.(*T).Run in goroutine 10308
        C:/Program Files/Go/src/testing/testing.go:1743 +0x377
exit status 2
FAIL    github.com/elastic/beats/v7/filebeat/input/filestream   600.073s
PS C:\devel\beats\filebeat\input\filestream>

[mauri870]

Could this be a timming issue? These tests have a check interval of 10 ms, which seems quite suspicious.

[belimawr]

Could this be a timming issue? These tests have a check interval of 10 ms, which seems quite suspicious.

It could be, I didn't look at the test code, I just reported it as I'm trying to get my PR green on CI and understand what is related and what is unrelated to mu changes.

If the test just waits 10ms and checks for the condition, that should be replaces by a assert.Eventually so we're not depending on timing/scheduling.

[mauri870]

Got it, thanks. I will see if I can reproduce on my windows machine.

[mauri870]

I managed to reproduce it, using stress makes it a bit easier to reproduce but it still takes a couple thousand runs to manifest:

$ cd filebeat/input/filestream
$ go test -c
$ go run golang.org/x/tools/cmd/stress@latest ./filestream.test -test.run TestFileWatcher -test.v

[belimawr]

I managed to reproduce it, using stress makes it a bit easier to reproduce but it still takes a couple thousand runs to manifest:

$ cd filebeat/input/filestream
$ go test -c
$ go run golang.org/x/tools/cmd/stress@latest ./filestream.test -test.run TestFileWatcher -test.v

That's a nice tool! -count tents to keep some global states among test runs which makes some some of our tests fail, running as independent process is awesome!

[belimawr]

I'm gonna create a PR to skip those flaky tests and unblock my PR (#41061) and others that might also be affected by them.