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

Jump to bottom

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

Closed
ailurarctos opened this issue Oct 26, 2019 · 4 comments
Closed

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

ailurarctos opened this issue Oct 26, 2019 · 4 comments
Labels
FrozenDueToAge GoCommand cmd/go NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@ailurarctos
Copy link

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 dmitshur added GoCommand cmd/go NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Oct 29, 2019
@dmitshur dmitshur changed the title go test -json: package output incorrectly attributed to the last test when a test panics cmd/go: go test -json has package output incorrectly attributed to the last test when a test panics Oct 29, 2019
@dmitshur
Copy link
Contributor

/cc @jayconrod @bcmills

@jayconrod jayconrod added this to the Backlog milestone Nov 25, 2019
@bcmills
Copy link
Contributor

bcmills commented Dec 5, 2019

Possibly related to #27764?

@bcmills
Copy link
Contributor

bcmills commented Dec 5, 2019

And almost certainly to #33419.

@jayconrod jayconrod mentioned this issue Mar 25, 2020
Closed
skudasov pushed a commit to skudasov/go-test-rp that referenced this issue Apr 22, 2020
validate test hierarchy, fail if json report is broken due bug: golan…
d05c116 
…g/go#35180
@ailurarctos
Copy link
Author

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.

@golang golang locked and limited conversation to collaborators May 19, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge GoCommand cmd/go NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
5 participants
@jayconrod @ailurarctos @dmitshur @bcmills @gopherbot