search

elastic / beats

:tropical_fish: Beats - Lightweight shippers for Elasticsearch & Logstash
https://www.elastic.co/products/beats
Other
111 stars 4.93k forks source link

TestFileWatcher/does_not_emit_events_for_empty_files/emits_a_create_event_once_something_is_written_to_the_empty_file #41209

Open belimawr opened 1 month ago

belimawr commented 1 month ago

Flaky Test

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 commented 1 month ago

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

belimawr commented 1 month ago

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/go-concert@v0.3.0/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/go-concert@v0.3.0/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 commented 1 month ago

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

belimawr commented 1 month ago

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 commented 1 month ago

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

mauri870 commented 1 month ago

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 commented 1 month ago

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 commented 1 month ago

I'm gonna create a PR to skip those flaky tests and unblock my PR (https://github.com/elastic/beats/pull/41061) and others that might also be affected by them.