async: provide information when starting to wait

[pohly]

Problem

While debugging a test which uses Eventually and Consistently, I want to know what the test is currently doing. With Kubernetes, I might run "kubectl" in parallel to the running test check some additional things. I run ginkgo -v -focus=<the test>.

Option 1

Manually add log output before each Eventually and Consistently:

By("Waiting for foo")
Eventually(...)

Downsides:

• writing tests is more work
• not very informative (for example, no information how long it's going to wait)
• noisy because the log output is printed also for checks that usually pass quickly after polling once

Option 2

Use --progress-poll-interval=<some low value>.

Downsides:

• very noisy: detailed reports get printed frequently

Option 3

Run under a debugger.

Downsides:

• lot of work
• hard to find relevant information (backtrace, print internals of Gomega)

Proposal

The first time that polling fails in Eventually (whether it's due to an error or the matcher), some message could be logged about it:

Eventually(..).Timeout(10 * time.Second).Should(Be..., "pod should be running")
=>
Waiting 10s to reach expected state "pod should be running". First check did not succeed:
<first few (5?) lines>

Let's keep the tone neutral. This is not an error or failure, therefore "did not succeed" instead of "failed". The practical difference is that the test log viewer in Kubernetes might match the "failed" and emphasize it unnecessarily.

Let's not dump too much of the usual failure. That could be very long. It might also work to not dump the check result when there is a description and only fall back to that when there isn't.

With Consistently it's simpler, as long as Should has an additional description:

Eventually(..).Timeout(10 * time.Second).Should(Be..., "pod should keep running")
=>
Waiting 10s to ensure that state "pod should keep running" remains as expected.

Without description it's less informative because there is no information from the matcher.

[pohly]

I'm aware that Gomega usually cannot log anything when using the global instance (= gomega.Eventually). When using gomega.NewWithT, it would have been possible to require T.Log method, but currently GomegaTestingT doesn't require it and it can't be added without breaking users. A NewWithTLog and extended interface could work.

For integration with Ginkgo, the progress reporting API could be extended.

[onsi]

hey @pohly - i want to get a clarification first. is the problem you are trying to solve “i want additional information in the logs for the test so that i can go back after the test later and understand what happened/why” or is it “i am actively running a test and waiting for it to complete but it is stuck doing something and i’m not sure what so would like to know.”

if it’s the latter then you can, today, send SIGINFO to get a progress report. If the Eventually has a context it will print out its last failure message.

---

setting that aside. we can stick with gomega.NewWithT and have Gomega look for methods on the concrete instance that was passed in at runtime - if it finds Log then it can emit the pre-Eventually log. however I can imagine users wanting to make that configurable and so we’re back to needing to configure the gomega instance in some way (e.g. g := gomega.NewWithT(t); g.SetVerboseLogging(true))

I could imagine providing a global override SetGomegaVerboseLogging(true) that gomega instances inherit from but can override. Similarly I can imagine adding a global RegisterGinkgoT() so that the global gomega instance could have access to the GinkgoWriter and also emit more verbose logs. This could supersede RegisterFailHandler() (which would stick around for backward compatibility) and give users a single entry point to connect Gomega and Ginkgo.

Those are some ideas - but let me know if SIGINFO begins to address your need.

[pohly]

It is primarily “I am actively running a test". I know that I can send SIGINFO, but that produces more information than I need. My main motivation is "tell me immediately when it gets stuck and on what". Having said that, perhaps SIGINFO is good enough. If I let something run for 30 seconds and it's not complete, then I pretty much can be sure that it is currently polling. Chances are good that I get a report for something that blocks long and not for something that is quick.

But I also see value for running tests in the CI. Some tests are slow and its not obvious why unless one liberally adds ginkgo.By or other log output with time stamps throughout the test. If polling did that automatically, then most of the reasons for slow tests would be covered without additional manual instrumentation of the test.