Add zaptest option to suppress logging after test completion

[theunrepentantgeek]

Is your feature request related to a problem? Please describe.

When using zaptest to provide logging during tests, I'm seeing a small number of test flakes due to logs emitted after the test completes - when zaptest calls t.Log(), it panic, failing the test.

Describe the solution you'd like

I'd like to add an option to "mute" a test logger after test completion, avoiding the panic and eliminating the flake.

As per CONTRIBUTING.md, I'm raising this issue first - but I'm happy to contribute the code if you're happy with the idea.

Proposed api design:

log := zaptest.NewLogger(w, zaptest.MuteAfterTestCompletion())

• Opt-in to preserve current behaviour (in case anyone is depending on it in their tests), but avoiding the issues we're seeing.

• Check for the prefix "Log in goroutine after" (see below) so we don't suppress any other panic that occurs

Describe alternatives you've considered

My errant/extra log calls are coming from subsidary goroutines that don't always shut down in time. We've done a number of things to reduce the flakes, including some guard rails like this:

if !testing {
	x.log.Info("...")
}

Unfortunately, this itself has a race condition and thus does not eliminate all flakes. It's also ugly to have this in production code.

I'm considering writing a wrapper around zaptest that will do the same thing as this feature, but that would only benefit my project. Contributing the idea back to zaptest would allow others to benefit.

Is this a breaking change?

No. Without the new option MuteAFterTestCompletion() existing behaviour would be preserved.

Additional context

Why check for a prefix? The panics themselves originate from this code in the standard Go library (testing.go):

n := c.destination()
if n == nil {
	// The test and all its parents are done. The log cannot be output.
	panic("Log in goroutine after " + c.name + " has completed: " + s)
}

If a different panic occurred while calling t.Log(), that wouldn't be something to suppress.

[jkanywhere]

small number of test flakes due to logs emitted after the test completes
panic("Log in goroutine after " + c.name + " has completed: " + s)

I ran into that once recently.

The solution for my case was to make sure the test was waiting for the system under test to finish (aka stop, close, shutdown).

Basically I added a call to sync.WaitGroup.Go, something like:

var wg sync.WaitGroup
wg.Go(func() { thingUnderTest.Run(t.Context()) })
t.Cleanup(wg.Wait)

In other cases it might look like

assert.NoError(t, systemUnderTest.Start(t.Context()))
t.Cleanup( func() { assert.NoError(t,  systemUnderTest.Stop(context.Backgound())) } )

That does assume that all components under test are likewise built to wait for spawned go routines.

In a system that does not well-manage go routines, and has reason to be OK with that, I can imagine zaptest.MuteAfterTestCompletion() would be helpful.

[theunrepentantgeek]

That does assume that all components under test are likewise built to wait for spawned go routines.

In my context, considerable effort has already gone into making things well behaved in production; further changes risk distorting the system in order to artificially constrain things purely during testing.

In a system that does not well-manage go routines, and has reason to be OK with that, I can imagine zaptest.MuteAfterTestCompletion() would be helpful.

Part of our issue stems from the size of the "system under test" - when we're testing the whole thing, everything behaves. But some of our tests are exercising system fragments (entire subsystems) and that's where things become complicated.