cmd/test2json: panic output after test pass incorrectly associated with test output #75284
Description
Go version
tip
Output of go env in your module/workspace:
AR='ar'
CC='gcc'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='g++'
GCCGO='gccgo'
GO111MODULE=''
GOAMD64='v1'
GOARCH='amd64'
GOAUTH='netrc'
GOBIN=''
GOCACHE='/usr/local/google/home/mpratt/.cache/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/usr/local/google/home/mpratt/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build4182293715=/tmp/go-build -gno-record-gcc-switches'
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMOD='/tmp/throw/go.mod'
GOMODCACHE='/usr/local/google/home/mpratt/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/usr/local/google/home/mpratt/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/google/home/mpratt/src/go'
GOSUMDB='sum.golang.org'
GOTELEMETRY='on'
GOTELEMETRYDIR='/usr/local/google/home/mpratt/.config/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/google/home/mpratt/src/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.26-devel_0b1eed09a3 Fri Sep 5 09:33:49 2025 -0700'
GOWORK=''
PKG_CONFIG='pkg-config'What did you do?
package main
import (
"testing"
)
func causeThrow() {
var fn func()
go fn()
}
func TestConcurrentThrow(t *testing.T) {
go causeThrow()
}
$ go test -json
What did you see happen?
{"Time":"2025-09-05T13:31:03.175934213-04:00","Action":"start","Package":"example.com"}
{"Time":"2025-09-05T13:31:03.18920636-04:00","Action":"run","Package":"example.com","Test":"TestConcurrentThrow"}
{"Time":"2025-09-05T13:31:03.189230282-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"=== RUN TestConcurrentThrow\n"}
{"Time":"2025-09-05T13:31:03.189248164-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"--- PASS: TestConcurrentThrow (0.00s)\n"}
{"Time":"2025-09-05T13:31:03.189254578-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"fatal error: go of nil func value\n"}
{"Time":"2025-09-05T13:31:03.191347786-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\n"}
{"Time":"2025-09-05T13:31:03.191368117-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"goroutine 7 [running]:\n"}
{"Time":"2025-09-05T13:31:03.191389595-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"example%2ecom.causeThrow()\n"}
{"Time":"2025-09-05T13:31:03.191394285-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/tmp/throw/main_test.go:10 +0x15\n"}
{"Time":"2025-09-05T13:31:03.191398861-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"created by example%2ecom.TestConcurrentThrow in goroutine 6\n"}
{"Time":"2025-09-05T13:31:03.19140574-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/tmp/throw/main_test.go:14 +0x1a\n"}
{"Time":"2025-09-05T13:31:03.191410147-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\n"}
{"Time":"2025-09-05T13:31:03.191421331-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"goroutine 1 [chan receive]:\n"}
{"Time":"2025-09-05T13:31:03.191442018-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"testing.(*T).Run(0xc000007500, {0x57d0c9?, 0xc000104b28?}, 0x587718)\n"}
{"Time":"2025-09-05T13:31:03.191481424-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:2007 +0x485\n"}
{"Time":"2025-09-05T13:31:03.191487777-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"testing.runTests.func1(0xc000007500)\n"}
{"Time":"2025-09-05T13:31:03.191496169-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:2480 +0x37\n"}
{"Time":"2025-09-05T13:31:03.191501661-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"testing.tRunner(0xc000007500, 0xc000104c68)\n"}
{"Time":"2025-09-05T13:31:03.191513159-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:1936 +0xea\n"}
{"Time":"2025-09-05T13:31:03.191569579-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"testing.runTests(0xc0000100d8, {0x6b2e70, 0x1, 0x1}, {0x7?, 0xc00010c8c0?, 0x6bd400?})\n"}
{"Time":"2025-09-05T13:31:03.191584913-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:2478 +0x494\n"}
{"Time":"2025-09-05T13:31:03.191593643-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"testing.(*M).Run(0xc00007c280)\n"}
{"Time":"2025-09-05T13:31:03.191610102-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:2339 +0x633\n"}
{"Time":"2025-09-05T13:31:03.191618346-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"main.main()\n"}
{"Time":"2025-09-05T13:31:03.19163419-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t_testmain.go:45 +0x9b\n"}
{"Time":"2025-09-05T13:31:03.191640152-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\n"}
{"Time":"2025-09-05T13:31:03.191647663-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"goroutine 6 [sleep]:\n"}
{"Time":"2025-09-05T13:31:03.19165827-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"time.Sleep(0x5f5e100)\n"}
{"Time":"2025-09-05T13:31:03.191674675-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/runtime/time.go:363 +0x165\n"}
{"Time":"2025-09-05T13:31:03.191686185-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"testing.(*T).report(0xc0000076c0)\n"}
{"Time":"2025-09-05T13:31:03.19170062-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:2403 +0x2a6\n"}
{"Time":"2025-09-05T13:31:03.191711198-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"testing.tRunner.func1()\n"}
{"Time":"2025-09-05T13:31:03.191727097-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:1919 +0x5c8\n"}
{"Time":"2025-09-05T13:31:03.191739184-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"testing.tRunner(0xc0000076c0, 0x587718)\n"}
{"Time":"2025-09-05T13:31:03.191755263-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:1942 +0x123\n"}
{"Time":"2025-09-05T13:31:03.191767543-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"created by testing.(*T).Run in goroutine 1\n"}
{"Time":"2025-09-05T13:31:03.191786511-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"\t/usr/local/google/home/mpratt/src/go/src/testing/testing.go:1999 +0x465\n"}
{"Time":"2025-09-05T13:31:03.192264979-04:00","Action":"output","Package":"example.com","Test":"TestConcurrentThrow","Output":"exit status 2\n"}
{"Time":"2025-09-05T13:31:03.19228341-04:00","Action":"pass","Package":"example.com","Test":"TestConcurrentThrow","Elapsed":0}
{"Time":"2025-09-05T13:31:03.192290212-04:00","Action":"output","Package":"example.com","Output":"FAIL\texample.com\t0.016s\n"}
{"Time":"2025-09-05T13:31:03.192298737-04:00","Action":"fail","Package":"example.com","Elapsed":0.016}
Notice that the throw output is associated with TestConcurrentThrow, even though it occurs after --- PASS: TestConcurrentThrow.
This behavior is fundamentally racy. In this minimal case, most likely the test binary simply exits before it can even crash. I encouraged this interleaving by adding a sleep after https://cs.opensource.google/go/go/+/master:src/testing/testing.go;l=2400;drc=ba9e1ddccfe55e711ac3987f74109393dfb736af.
What did you expect to see?
I think the appropriate behavior would be for output after PASS to get associated with the overall package output, not a specific test. i.e.,
{"Time":"2025-09-05T13:31:03.192290212-04:00","Action":"output","Package":"example.com","Output":"fatal error: go of nil func value\n"}
...
This sounds very niche, but it comes from a real-world failure on LUCI: https://ci.chromium.org/ui/p/golang/builders/ci/gotip-linux-amd64-staticlockranking/b8704554488014429329/overview
There, we have
{"Time":"2025-09-05T15:53:02.012004194Z","Action":"output","Package":"net/http","Test":"TestNewClientServerTest/synctest/h1","Output":"--- PASS: TestNewClientServerTest/synctest/h1 (0.00s)\n"}
{"Time":"2025-09-05T15:53:02.01201022Z","Action":"output","Package":"net/http","Test":"TestNewClientServerTest/synctest/h1","Output":"fatal error: sync: WaitGroup.Add called from multiple synctest bubbles\n"}
... traceback ...
{"Time":"2025-09-05T15:53:02.131725657Z","Action":"pass","Package":"net/http","Test":"TestNewClientServerTest/synctest/h1","Elapsed":0}
{"Time":"2025-09-05T15:53:02.131755283Z","Action":"output","Package":"net/http","Output":"FAIL\tnet/http\t0.642s\n"}
{"Time":"2025-09-05T15:53:02.131767839Z","Action":"fail","Package":"net/http","Elapsed":0.642}
Since the package failed, but all test cases passed, the LUCI UI only displays the package-level log, which only consists of FAIL net/http 0.642s, which is supremely unhelpful.