Go: testing: bad formatting in "Log in goroutine after" panic message

[bcmills]

On go1.11, the following test silently drops a log message: https://play.golang.org/p/2gLqWOYcREv

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.

[neild]

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, and c.name will 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]

CC @wselwood

[ianlancetaylor]

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]

Change https://golang.org/cl/157617 mentions this issue: testing: report the failing test in a late log panic

[neild]

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]

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]

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

[andybons]

Is this still considered a release blocker for 1.12?

[ianlancetaylor]

This is not a release blocker for 1.12.

[ianlancetaylor]

In fact, the core of this issue is fixed. Opening the remaining portion as a separate issue in #30389.