Repository navigation
testing: bad formatting in "Log in goroutine after" panic message #29388
Description
On go1.11, the following test silently drops a log message: https://play.golang.org/p/2gLqWOYcREv
Details
package main
import (
"os"
"testing"
)
var done = make(chan struct{})
var logged = make(chan struct{})
func TestBadness(t *testing.T) {
t.Parallel()
go func() {
defer close(logged)
<-done
t.Log("BWA ha ha ha ha!")
}()
t.Log("Hmm?")
}
func TestMain(m *testing.M) {
code := m.Run()
close(done)
<-logged
os.Exit(code)
}On go1.12beta1, as a result of https://golang.org/cl/127596 (#26720), it instead prints:
$ go1.12beta1 test
PASS
panic: Log in goroutine after has completed
goroutine 7 [running]:
testing.(*common).logDepth(0xc00009c000, 0xc0000142a0, 0x11, 0x4)
/usr/local/google/home/bcmills/sdk/go1.12beta1/src/testing/testing.go:628 +0x256
testing.(*common).logDepth(0xc00009c100, 0xc0000142a0, 0x11, 0x3)
/usr/local/google/home/bcmills/sdk/go1.12beta1/src/testing/testing.go:626 +0xa6
testing.(*common).log(...)
/usr/local/google/home/bcmills/sdk/go1.12beta1/src/testing/testing.go:614
testing.(*common).Log(0xc00009c100, 0xc00003afb8, 0x1, 0x1)
/usr/local/google/home/bcmills/sdk/go1.12beta1/src/testing/testing.go:639 +0x6a
golang.org/issue/scratch_test.TestBadness.func1(0xc00009c100)
/tmp/tmp.RMuhgfzwru/bad_test.go:16 +0xae
created by golang.org/issue/scratch_test.TestBadness
/tmp/tmp.RMuhgfzwru/bad_test.go:13 +0x51
exit status 2
FAIL golang.org/issue/scratch 0.021s
Note the lack of test name in the log message: for some reason, c.name is no longer populated at that point.
Activity
neild commentedon Jan 11, 2019
The panic message is definitely wrong, and I don't think this should be a panic at all.
#26720 makes t.Log log to t's parent if t is done. If t is a subtest, this promotes the log message to the parent test.
If t is not a subtest, then the parent of t is a per-cpu T created by
testing.runTests. This T only becomes done after all tests are complete. If the log happens while any tests are still running, the log message is silently discarded. If the log happens after all tests have completed, the panic occurs. This is, so far as I can tell, the only case where the "Log in goroutine after" panic can occur, andc.namewill never be populated.So #26720 adds a panic in the narrow window between all tests completing and the process exiting. This does not seem useful; if logging after panic completion is worthwhile, then it should happen for any log after the test has completed.
In addition, I do not see a case for having different panic behavior for logging after top-level test completion and logging after subtest completion. These should behave the same.
On a related note, #26720 includes a comment: "If this test has already finished try and log this message with our parent with this test name tagged so we know where it came from." However, there is no such tagging. The comment should be dropped or the tagging added.
ianlancetaylor commentedon Jan 11, 2019
CC @wselwood
ianlancetaylor commentedon Jan 11, 2019
There is clearly a bug here but I don't follow the logic for why there shouldn't be a panic.
The most important guideline should be that we never lose a log message. Currently we are losing log messages. That is a bug. For the cases where we are losing log messages today, we should probably panic.
But at this point in the release we should perhaps push this back to 1.13.
gopherbot commentedon Jan 11, 2019
Change https://golang.org/cl/157617 mentions this issue:
testing: report the failing test in a late log panicneild commentedon Jan 11, 2019
I think it would be fine to panic where we lose log messages today, but that's going to be an upgrade in the number of situations where we panic from the current state of affairs. I think that change needs to be pushed back to 1.13.
I also suspect that panicking in all situations where a log is lost might trigger too many failures to be feasible. I'd be delighted to be proven wrong.
ianlancetaylor commentedon Jan 11, 2019
The current code panics on a few cases where log messages are lost, and that code has been in the tree since October 10, 2018. I don't think we need to roll that back at this point.
I agree that we shouldn't add additional panic cases until 1.13.
emilyselwood commentedon Jan 14, 2019
The only two cases I know of since the original change went in are #28169 which tripped the race detector on a test in a the std lib, and this one.
@neild Re: Your related note a few comments back. Fair spot. I stopped pre-pending the name after a review comment from @ianlancetaylor looks like I forgot to take out the comment. https://go-review.googlesource.com/c/go/+/127596/5/src/testing/testing.go#607
testing: report the failing test in a late log panic
andybons commentedon Feb 23, 2019
Is this still considered a release blocker for 1.12?
ianlancetaylor commentedon Feb 25, 2019
This is not a release blocker for 1.12.
ianlancetaylor commentedon Feb 25, 2019
In fact, the core of this issue is fixed. Opening the remaining portion as a separate issue in #30389.