Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

testr: prevent panic when test keeps goroutines running #168

Closed
wants to merge 1 commit into from

Conversation

pohly
Copy link
Contributor

@pohly pohly commented Dec 8, 2022

When a test completes, the testing.T becomes unusable. If a test hasn't properly stopped goroutines, those might continue to use the testr instance for logging. It's better to silently discard the log output than to panic.

Fixes: #145

Without the testr.go changes, this new test triggers that panic:

=== RUN   TestStop
--- PASS: TestStop (0.00s)
PASS
panic: Log in goroutine after TestStop has completed: "level"=0 "msg"="simple info message"

$ go test -run=TestStop -v .
goroutine 7 [running]:
testing.(*common).logDepth(0xc000007860, {0xc00011e060, 0x26}, 0x3)
	/nvme/gopath/go-1.19/src/testing/testing.go:894 +0x4c7
testing.(*common).log(...)
	/nvme/gopath/go-1.19/src/testing/testing.go:876
testing.(*common).Log(0xc000007860, {0xc00011a010?, 0x4bb194?, 0x0?})
	/nvme/gopath/go-1.19/src/testing/testing.go:917 +0x4e
github.com/go-logr/logr/testr.logInfo({0x561d88, 0xc000007860}, 0x420e27?, 0x400000?, {0x53544b?, 0xc000086d38?}, {0x0?, 0x64d480?, 0x40c75e?})
	/nvme/gopath/src/github.com/go-logr/logr/testr/testr.go:101 +0x11d
github.com/go-logr/logr/testr.testloggerInterface.Info({{0x0, {0x560eb8, 0x0}, {0x0, 0x0, 0x0}, {0x0, 0x0}, 0x1, 0xc0000ae190}, ...}, ...)
	/nvme/gopath/src/github.com/go-logr/logr/testr/testr.go:148 +0x106
github.com/go-logr/logr.Logger.Info({{0x5621c8?, 0xc000014300?}, 0x0?}, {0x53544b, 0x13}, {0x0, 0x0, 0x0})
	/nvme/gopath/src/github.com/go-logr/logr/logr.go:278 +0xe4
github.com/go-logr/logr/testr.TestStop.func1()
	/nvme/gopath/src/github.com/go-logr/logr/testr/testr_test.go:124 +0xd4
created by github.com/go-logr/logr/testr.TestStop
	/nvme/gopath/src/github.com/go-logr/logr/testr/testr_test.go:116 +0xd8
FAIL	github.com/go-logr/logr/testr	0.006s
FAIL

When a test completes, the testing.T becomes unusable. If a test hasn't
properly stopped goroutines, those might continue to use the testr instance for
logging. It's better to silently discard the log output than to panic.

Without the testr.go changes, this new test triggers that panic:

=== RUN   TestStop
--- PASS: TestStop (0.00s)
PASS
panic: Log in goroutine after TestStop has completed: "level"=0 "msg"="simple info message"

$ go test -run=TestStop -v .
goroutine 7 [running]:
testing.(*common).logDepth(0xc000007860, {0xc00011e060, 0x26}, 0x3)
	/nvme/gopath/go-1.19/src/testing/testing.go:894 +0x4c7
testing.(*common).log(...)
	/nvme/gopath/go-1.19/src/testing/testing.go:876
testing.(*common).Log(0xc000007860, {0xc00011a010?, 0x4bb194?, 0x0?})
	/nvme/gopath/go-1.19/src/testing/testing.go:917 +0x4e
github.com/go-logr/logr/testr.logInfo({0x561d88, 0xc000007860}, 0x420e27?, 0x400000?, {0x53544b?, 0xc000086d38?}, {0x0?, 0x64d480?, 0x40c75e?})
	/nvme/gopath/src/github.com/go-logr/logr/testr/testr.go:101 +0x11d
github.com/go-logr/logr/testr.testloggerInterface.Info({{0x0, {0x560eb8, 0x0}, {0x0, 0x0, 0x0}, {0x0, 0x0}, 0x1, 0xc0000ae190}, ...}, ...)
	/nvme/gopath/src/github.com/go-logr/logr/testr/testr.go:148 +0x106
github.com/go-logr/logr.Logger.Info({{0x5621c8?, 0xc000014300?}, 0x0?}, {0x53544b, 0x13}, {0x0, 0x0, 0x0})
	/nvme/gopath/src/github.com/go-logr/logr/logr.go:278 +0xe4
github.com/go-logr/logr/testr.TestStop.func1()
	/nvme/gopath/src/github.com/go-logr/logr/testr/testr_test.go:124 +0xd4
created by github.com/go-logr/logr/testr.TestStop
	/nvme/gopath/src/github.com/go-logr/logr/testr/testr_test.go:116 +0xd8
FAIL	github.com/go-logr/logr/testr	0.006s
FAIL
@pohly
Copy link
Contributor Author

pohly commented Dec 8, 2022

It's better to silently discard the log output than to panic.

@thockin: That's a bit debatable. If you prefer to not fix this and let goroutines panic, then that's also fine with me.

@@ -87,6 +106,8 @@ type Underlier interface {
// callers only have a logr.Logger, they have to know which
// implementation is in use, so this interface is less of an
// abstraction and more of a way to test type conversion.
//
// Returns nil when the test has already completed.
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Slight change of behavior. OTOH, code calling this after test completion didn't get a usable TestingT either, so not a big difference in practice.

@thockin
Copy link
Contributor

thockin commented Dec 8, 2022

It's better to silently discard the log output than to panic.

@thockin: That's a bit debatable. If you prefer to not fix this and let goroutines panic, then that's also fine with me.

Instictively I think this SHOULD panic - the test is broken and if they want to not fix it, that's on the test to fix, not testr. This is not super complicated, but it takes something which should be nearly trivial and makes it non-trivial. AND it hides a real bug.

If we add this - maybe it should be an Option? So you can specify testr.New(t, testr.Options{dontPanic: true}) ?

@pohly
Copy link
Contributor Author

pohly commented Dec 8, 2022

We could make it an option, but even that might not be worth it - let's close.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

testing: testing.T.Log panics when called after test completion
2 participants