internal/internal_integration/node_spec_events_test.go:33 may be flaky

[siretart]

While looking at the debian package of ginkgo, I can across https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1078516 that indicates that the Integration Tests may be flaky. Here are two instances where the same test fails in a very similar manner:

• https://buildd.debian.org/status/fetch.php?pkg=golang-github-onsi-ginkgo-v2&arch=arm64&ver=2.15.0-1%2Bb1&stamp=1723382580&raw=0
• https://buildd.debian.org/status/fetch.php?pkg=golang-github-onsi-ginkgo-v2&arch=arm64&ver=2.12.1-2%2Bb1&stamp=1697640325&raw=0

Usually this passes on a retry.

The test in question appears to be here: https://github.com/onsi/ginkgo/blob/master/internal/internal_integration/node_spec_events_test.go#L33-L70

It is possible that this test is affected by heavy load on the host, I couldn't reproduce it yet on my laptop.

[onsi]

Thanks for reporting this - I don't know who/how the debian packages are maintained but it seems odd to me that installing ginkgo ends up running all the tests. There's no need to run these and they (especially the integration tests run in series) will add several minutes to the build time. Do you know where we could go to change how ginkgo is built and installed?

[siretart]

Happy to clarify as needed.

Installing the ginkgo package does not run any tests. The tests are being run as part of the build process (and there is another way to execute them using the autopkgtest machinery, but that's unrelated to this bug).

As you can see from the build logs above, this is how the tests are being invoked:

	cd build && go test -vet=off -v -p 8 -timeout=1h github.com/onsi/ginkgo/v2 github.com/onsi/ginkgo/v2/config github.com/onsi/ginkgo/v2/docs github.com/onsi/ginkgo/v2/dsl github.com/onsi/ginkgo/v2/dsl/core github.com/onsi/ginkgo/v2/dsl/decorators github.com/onsi/ginkgo/v2/dsl/reporting github.com/onsi/ginkgo/v2/dsl/table github.com/onsi/ginkgo/v2/extensions/globals github.com/onsi/ginkgo/v2/extensions/table github.com/onsi/ginkgo/v2/formatter github.com/onsi/ginkgo/v2/ginkgo github.com/onsi/ginkgo/v2/ginkgo/build github.com/onsi/ginkgo/v2/ginkgo/command github.com/onsi/ginkgo/v2/ginkgo/generators github.com/onsi/ginkgo/v2/ginkgo/internal github.com/onsi/ginkgo/v2/ginkgo/labels github.com/onsi/ginkgo/v2/ginkgo/outline github.com/onsi/ginkgo/v2/ginkgo/performance github.com/onsi/ginkgo/v2/ginkgo/run github.com/onsi/ginkgo/v2/ginkgo/unfocus github.com/onsi/ginkgo/v2/ginkgo/watch github.com/onsi/ginkgo/v2/integration github.com/onsi/ginkgo/v2/internal github.com/onsi/ginkgo/v2/internal/global github.com/onsi/ginkgo/v2/internal/internal_integration github.com/onsi/ginkgo/v2/internal/interrupt_handler github.com/onsi/ginkgo/v2/internal/parallel_support github.com/onsi/ginkgo/v2/internal/test_helpers github.com/onsi/ginkgo/v2/internal/testingtproxy github.com/onsi/ginkgo/v2/reporters github.com/onsi/ginkgo/v2/types

the long list of packages is dynamically generated with go list. If you feel that some of those packages are inappropriate to run as part of the package build, I can easily exclude them. Please just let me know.

[onsi]

ah, thanks for clarifying. yes this is likely due to a slow build machine. The test is a bit too finnicky about the measured duration so I'm pushing a fix that will make it more lenient (I generally try to avoid testing code with actual time.Sleeps but in this case with a black-box integration test it's the cleanest approach). I'll but a new release with the fix soon.

as for the invocation. you can use go test but I would recommend using the ginkgo cli to run the tests. more recent versions of ginkgo ship with a makefile so you could just run make test.

[onsi]

v2.20.1 has the fix. I don't generally backport bugfixes to prior minor releases, however, so this will not resolve flakiness issues on older version of Ginkgo.

[siretart]

Thank you so much!

I've backported your commit as https://salsa.debian.org/go-team/packages/golang-github-onsi-ginkgo-v2/-/commit/107e820 so that it can be included in the next package update.

[onsi]

sounds good. let me know if you see it flake again (i wasn't able to reproduce it locally but am pretty sure this is the issue).

[siretart]

I finally got around to actually upload this change to debian, only to find another timeout on armel:
https://ci.debian.net/packages/g/golang-github-onsi-ginkgo-v2/testing/armel/51760224/

726s �[0mEmitting Node SpecEvents �[38;5;9m�[1m[It] emits each spec event as it goes�[0m
726s �[38;5;243m/tmp/autopkgtest-lxc.kf8bgbeu/downtmp/autopkgtest_tmp/build/src/github.com/onsi/ginkgo/v2/internal/internal_integration/node_spec_events_test.go:72�[0m
726s 
726s   �[38;5;9m[FAILED] Timeline failed to match:
726s 
726s     Failed at index 5:
726s           <types.SpecEvent>: [Node (End) SpecEvent] Message="A",Duration=35.765684ms,NodeType=It,CL=/tmp/autopkgtest-lxc.kf8bgbeu/downtmp/autopkgtest_tmp/build/src/github.com/onsi/ginkgo/v2/internal/internal_integration/node_spec_events_test.go:19,TL.Offset=6
726s   Value for field 'Duration' failed to satisfy matcher.
726s   Expected
726s       <time.Duration>: 35765684
726s   to be within 10ms of ~
726s       <time.Duration>: 20000000
726s   �[0m
726s   �[38;5;9mIn �[1m[It]�[0m�[38;5;9m at: �[1m/tmp/autopkgtest-lxc.kf8bgbeu/downtmp/autopkgtest_tmp/build/src/github.com/onsi/ginkgo/v2/internal/internal_integration/node_spec_events_test.go:77�[0m �[38;5;243m@ 09/16/24 15:44:08.618�[0m
726s �[38;5;243m------------------------------�[0m
726s �[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m�[38;5;10m•�[0m
726s 
726s �[38;5;9m�[1mSummarizing 1 Failure:�[0m
726s   �[38;5;9m[FAIL]�[0m �[0mEmitting Node SpecEvents �[38;5;9m�[1m[It] emits each spec event as it goes�[0m

At least the issue originally in this bugreport didn't get triggered.

I can file a separate issue, if you prefer. let me know.

Thanks!

[onsi]

hey sorry for the long latency. i've bumped this threshold as well and will cut another release oon