cmd/go: go test -json has package output incorrectly attributed to the last test when a test panics

[ailurarctos]

What version of Go are you using (go version)?

$ go version
go version go1.13.3 linux/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/me/.cache/go-build"
GOENV="/home/me/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/me/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/me/example.com/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build644999187=/tmp/go-build -gno-record-gcc-switches"
GOROOT/bin/go version: go version go1.13.3 linux/amd64
GOROOT/bin/go tool compile -V: compile version go1.13.3
uname -sr: Linux 5.3.7-arch1-1-ARCH
/usr/lib/libc.so.6: GNU C Library (GNU libc) stable release version 2.30.

What did you do?

Create a package with a single example_test.go as follows:

package example

import "testing"

func Test_panic(t *testing.T) {
	panic("panic")
}

Run the tests with go test -json.

What did you expect to see?

I expected to see JSON events similar to what is printed for a test failure (except with the panic output). Here is an example:

{"Time":"2019-10-26T16:31:24.490841764+09:00","Action":"run","Package":"example.com","Test":"Test_panic"}
{"Time":"2019-10-26T16:31:24.490999482+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"=== RUN   Test_panic\n"}
{"Time":"2019-10-26T16:31:24.491019239+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"--- FAIL: Test_panic (0.00s)\n"}
{"Time":"2019-10-26T16:31:24.493039733+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"panic: panic [recovered]\n"}
{"Time":"2019-10-26T16:31:24.493074736+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\tpanic: panic\n"}
{"Time":"2019-10-26T16:31:24.493091009+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\n"}
{"Time":"2019-10-26T16:31:24.493105541+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"goroutine 7 [running]:\n"}
{"Time":"2019-10-26T16:31:24.49312058+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"testing.tRunner.func1(0xc00009a100)\n"}
{"Time":"2019-10-26T16:31:24.493138782+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:874 +0x3a3\n"}
{"Time":"2019-10-26T16:31:24.493154221+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"panic(0x50f620, 0x568e00)\n"}
{"Time":"2019-10-26T16:31:24.493169603+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/runtime/panic.go:679 +0x1b2\n"}
{"Time":"2019-10-26T16:31:24.493181468+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"example%2ecom.Test_panic(0xc00009a100)\n"}
{"Time":"2019-10-26T16:31:24.493193647+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/home/me/example.com/example_test.go:6 +0x39\n"}
{"Time":"2019-10-26T16:31:24.493206542+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"testing.tRunner(0xc00009a100, 0x54e1b0)\n"}
{"Time":"2019-10-26T16:31:24.49322095+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:909 +0xc9\n"}
{"Time":"2019-10-26T16:31:24.493233314+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"created by testing.(*T).Run\n"}
{"Time":"2019-10-26T16:31:24.49324471+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:960 +0x350\n"}
{"Time":"2019-10-26T16:31:24.493309065+09:00","Action":"fail","Package":"example.com","Test":"Test_panic","Elapsed":0.003}
{"Time":"2019-10-26T16:31:24.493459617+09:00","Action":"output","Package":"example.com","Output":"exit status 2\n"}
{"Time":"2019-10-26T16:31:24.493491032+09:00","Action":"output","Package":"example.com","Output":"FAIL\texample.com\t0.004s\n"}
{"Time":"2019-10-26T16:31:24.493509065+09:00","Action":"fail","Package":"example.com","Elapsed":0.004}

In the example above the output

exit status 2
FAIL	example.com	0.004s

related to the package failing is attributed to the package, not the test (i.e. no "Test" key).

There is also a JSON event for the package result:

{"Time":"2019-10-26T16:31:24.493509065+09:00","Action":"fail","Package":"example.com","Elapsed":0.004}

This matches the behavior for when a test fails. For example take the following failing test:

package example

import "testing"

func Test_fail(t *testing.T) {
	t.Fail()
}

Running the above with go test -json results in the following:

{"Time":"2019-10-26T16:43:43.127664589+09:00","Action":"run","Package":"example.com","Test":"Test_fail"}
{"Time":"2019-10-26T16:43:43.12785779+09:00","Action":"output","Package":"example.com","Test":"Test_fail","Output":"=== RUN   Test_fail\n"}
{"Time":"2019-10-26T16:43:43.127884525+09:00","Action":"output","Package":"example.com","Test":"Test_fail","Output":"--- FAIL: Test_fail (0.00s)\n"}
{"Time":"2019-10-26T16:43:43.127899069+09:00","Action":"fail","Package":"example.com","Test":"Test_fail","Elapsed":0}
{"Time":"2019-10-26T16:43:43.127911351+09:00","Action":"output","Package":"example.com","Output":"FAIL\n"}
{"Time":"2019-10-26T16:43:43.127980332+09:00","Action":"output","Package":"example.com","Output":"exit status 1\n"}
{"Time":"2019-10-26T16:43:43.128011943+09:00","Action":"output","Package":"example.com","Output":"FAIL\texample.com\t0.002s\n"}
{"Time":"2019-10-26T16:43:43.128023373+09:00","Action":"fail","Package":"example.com","Elapsed":0.002}

What did you see instead?

The output

exit status 2
FAIL	example.com	0.004s

related to the failure of the package is attributed to the last test and the "fail" action for the package is missing. Here is the output:

{"Time":"2019-10-26T16:48:37.809827062+09:00","Action":"run","Package":"example.com","Test":"Test_panic"}
{"Time":"2019-10-26T16:48:37.809976433+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"=== RUN   Test_panic\n"}
{"Time":"2019-10-26T16:48:37.80999731+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"--- FAIL: Test_panic (0.00s)\n"}
{"Time":"2019-10-26T16:48:37.811997085+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"panic: panic [recovered]\n"}
{"Time":"2019-10-26T16:48:37.812050124+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\tpanic: panic\n"}
{"Time":"2019-10-26T16:48:37.812067897+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\n"}
{"Time":"2019-10-26T16:48:37.812082944+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"goroutine 7 [running]:\n"}
{"Time":"2019-10-26T16:48:37.812103579+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"testing.tRunner.func1(0xc00009a100)\n"}
{"Time":"2019-10-26T16:48:37.812119215+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:874 +0x3a3\n"}
{"Time":"2019-10-26T16:48:37.812133424+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"panic(0x50f620, 0x568e00)\n"}
{"Time":"2019-10-26T16:48:37.812149167+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/runtime/panic.go:679 +0x1b2\n"}
{"Time":"2019-10-26T16:48:37.812162786+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"example%2ecom.Test_panic(0xc00009a100)\n"}
{"Time":"2019-10-26T16:48:37.812174836+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/home/me/example.com/example_test.go:6 +0x39\n"}
{"Time":"2019-10-26T16:48:37.812187814+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"testing.tRunner(0xc00009a100, 0x54e1b0)\n"}
{"Time":"2019-10-26T16:48:37.812196648+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:909 +0xc9\n"}
{"Time":"2019-10-26T16:48:37.812204452+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"created by testing.(*T).Run\n"}
{"Time":"2019-10-26T16:48:37.812211803+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:960 +0x350\n"}
{"Time":"2019-10-26T16:48:37.812512011+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"exit status 2\n"}
{"Time":"2019-10-26T16:48:37.812546284+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"FAIL\texample.com\t0.004s\n"}
{"Time":"2019-10-26T16:48:37.812577123+09:00","Action":"fail","Package":"example.com","Test":"Test_panic","Elapsed":0.004}

[dmitshur]

/cc @jayconrod @bcmills

[bcmills]

Possibly related to #27764?

[bcmills]

And almost certainly to #33419.

[ailurarctos]

This issue appears to be fixed since go1.14.1. I think 76a6adc fixed it.

Here is the go test -json . output for the example_test.go (in the first comment) when run with go1.14.1:

{"Time":"2020-05-19T10:14:26.986587778+09:00","Action":"run","Package":"example.com","Test":"Test_panic"}
{"Time":"2020-05-19T10:14:26.986711668+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"=== RUN   Test_panic\n"}
{"Time":"2020-05-19T10:14:26.986727103+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"--- FAIL: Test_panic (0.00s)\n"}
{"Time":"2020-05-19T10:14:26.988913273+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"panic: panic [recovered]\n"}
{"Time":"2020-05-19T10:14:26.988958022+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\tpanic: panic\n"}
{"Time":"2020-05-19T10:14:26.98896551+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\n"}
{"Time":"2020-05-19T10:14:26.988971836+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"goroutine 18 [running]:\n"}
{"Time":"2020-05-19T10:14:26.988980882+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"testing.tRunner.func1.1(0x50ee00, 0x5665c0)\n"}
{"Time":"2020-05-19T10:14:26.988991089+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:941 +0x3d0\n"}
{"Time":"2020-05-19T10:14:26.989001224+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"testing.tRunner.func1(0xc0000d2120)\n"}
{"Time":"2020-05-19T10:14:26.989006155+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:944 +0x3f9\n"}
{"Time":"2020-05-19T10:14:26.989010738+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"panic(0x50ee00, 0x5665c0)\n"}
{"Time":"2020-05-19T10:14:26.989014968+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/runtime/panic.go:967 +0x166\n"}
{"Time":"2020-05-19T10:14:26.989021457+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"example%2ecom.Test_panic(0xc0000d2120)\n"}
{"Time":"2020-05-19T10:14:26.989026123+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/home/me/example.com/example_test.go:6 +0x39\n"}
{"Time":"2020-05-19T10:14:26.989034311+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"testing.tRunner(0xc0000d2120, 0x549220)\n"}
{"Time":"2020-05-19T10:14:26.989038817+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:992 +0xdc\n"}
{"Time":"2020-05-19T10:14:26.989043454+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"created by testing.(*T).Run\n"}
{"Time":"2020-05-19T10:14:26.989047757+09:00","Action":"output","Package":"example.com","Test":"Test_panic","Output":"\t/usr/lib/go/src/testing/testing.go:1043 +0x357\n"}
{"Time":"2020-05-19T10:14:26.989405403+09:00","Action":"fail","Package":"example.com","Test":"Test_panic","Elapsed":0}
{"Time":"2020-05-19T10:14:26.989425466+09:00","Action":"output","Package":"example.com","Output":"FAIL\texample.com\t0.004s\n"}
{"Time":"2020-05-19T10:14:26.989441567+09:00","Action":"fail","Package":"example.com","Elapsed":0.004}

This matches the expected output. In particular there is a "fail" action for both the test and the package.

I tried go1.14.3 and it also works. Closing.