Go: cmd/go: tests that panic or exit are marked as passing when -json flag is used

[dlsniper]

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

$ go version
go version go1.14 windows/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

set GO111MODULE=on

set GOARCH=amd64

set GOBIN=

set GOCACHE=C:\Users\florin\AppData\Local\go-build

set GOENV=C:\Users\florin\AppData\Roaming\go\env

set GOEXE=.exe

set GOFLAGS=

set GOHOSTARCH=amd64

set GOHOSTOS=windows

set GOINSECURE=

set GONOPROXY=

set GONOSUMDB=

set GOOS=windows

set GOPATH=D:\go

set GOPRIVATE=

set GOPROXY=direct

set GOROOT=C:\go-distros\go1.14

set GOSUMDB=sum.golang.org

set GOTMPDIR=

set GOTOOLDIR=C:\go-distros\go1.14\pkg\tool\windows_amd64

set GCCGO=gccgo

set AR=ar

set CC=gcc

set CXX=g++

set CGO_ENABLED=1

set GOMOD=D:\GoLandProjects\awesomeProject26\go.mod

set CGO_CFLAGS=-g -O2

set CGO_CPPFLAGS=

set CGO_CXXFLAGS=-g -O2

set CGO_FFLAGS=-g -O2

set CGO_LDFLAGS=-g -O2

set PKG_CONFIG=pkg-config

set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=C:\Users\florin\AppData\Local\Temp\go-build954171622=/tmp/go-build -gno-record-gcc-switches

What did you do?

• take the code from here: https://play.golang.org/p/sM_HbzDzmXn
• run the following commands:

go test -c -coverpkg=./... -covermode=atomic -o mytests.exe awesomeProject26
go tool test2json -t ./mytests.exe -test.v -test.coverprofile cov.out

What did you expect to see?

I would expect to see that TestName2 fails since there's a panic there.
See the output here: https://play.golang.org/p/-9xQPOYa5iN

What did you see instead?

Test is marked as pass in the resulting json:

{
    "Time":"2020-02-28T15:26:08.7281772+02:00",
    "Action":"pass",
    "Test":"TestName2",
    "Elapsed":0.286
}

The test position doesn't seem to matter, if it's the first, the last, or in the middle of the test suite.

This is confirmed to happen both on Windows and Ubuntu.

[bcmills]

Does go test -json exhibit the same problem?

[dlsniper]

Yes

[dlsniper]

To give more context. This behavior was working in Go 1.13 and previous releases and was broken in Go 1.14.
In turn, this breaks GoLand and potentially other test runners that rely on this feature. See the original report here: https://youtrack.jetbrains.com/issue/GO-8876

[dmitshur]

Thank you for reporting.

I can reproduce this 1.14 regression with go test -json. It affects tests that fail due to panic and non-zero exit code.

$ cd $(mktemp -d)
$ go mod init issue37555.test
$ echo 'package main_test

import (
    "os"
    "testing"
)

func TestPanic(t *testing.T) {
    panic("not okay")
}

func TestExit(t *testing.T) {
    os.Exit(1)
}' > main_test.go

$ go1.13.8 test -run=TestPanic -json | tail -1
{"Time":"2020-03-04T17:23:17.682923-05:00","Action":"fail","Package":"issue37555.test","Test":"TestPanic","Elapsed":0.077}
$ go1.13.8 test -run=TestExit -json | tail -1
{"Time":"2020-03-04T17:23:38.263876-05:00","Action":"fail","Package":"issue37555.test","Test":"TestExit","Elapsed":0.078}

$ go1.14 test -run=TestPanic -json | tail -1
{"Time":"2020-03-04T17:24:22.480484-05:00","Action":"pass","Package":"issue37555.test","Test":"TestPanic","Elapsed":0.083}
$ go1.14 test -run=TestExit -json | tail -1 
{"Time":"2020-03-04T17:24:47.673458-05:00","Action":"pass","Package":"issue37555.test","Test":"TestExit","Elapsed":0.078}

/cc @jayconrod @matloob

[bcmills]

Given the reliance of test2json on -test.v, this is likely a side-effect of #24929.

[dmitshur]

This reproduces on tip as well. I'll change this issue to Go 1.15 milestone, and ask @gopherbot to please backport this to Go 1.14. Based on information so far, this looks like a serious bug that likely doesn't have a viable workaround.

[gopherbot]

Backport issue(s) opened: #37671 (for 1.14), #37672 (for 1.15).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

[jayconrod]

I think this was triggered by CL 192104. test2json started failing open instead of failing closed.

If the test binary fails for any reason (exits non-zero, fails to run), go test is supposed to add a message to stdout. But test2json doesn't understand the message that go test writes.

Will have a CL soon.

[gopherbot]

Change https://golang.org/cl/222243 mentions this issue: cmd/go: make go test -json report failures for panicking/exiting tests

[grasparv]

I've seen this issue before too since I maintain a testrunner tool that uses the "-json" functionality (https://github.com/grasparv/testie) - did not have time to to report it though at the time it happened and forgot about it.

But up until now, these tools have had to check for the go test exit code in addition to the json reports (my commit from 11th December last year, https://github.com/grasparv/testie/commit/229695c87d6440484a962933bfaa138b370d5e74). Just recently discovered that my own tool does not present this very clearly either, so had to add a warning about golang being buggy.

[gopherbot]

Change https://golang.org/cl/222658 mentions this issue: [release-branch.go1.14] cmd/go: make go test -json report failures for panicking/exiting tests

[grasparv]

Does this fix cover cases where the (test) code does not compile too?

[bcmills]

@grasparv, if the test does not compile, we should not even make it to the point where we run the test (or the test2json wrapper).

[jayconrod]

@grasparv No, but see #35169 and #23037.

[grasparv]

It will be hard/impossible to differentiate between:

• an old golang version failing with panic bug above
• code did not compile at all
• there were no go files in this directory

... in the test runner after running 'go test -json'.

Should not all output be JSON if you run with -json? And yes, I understand that it is a wrapper that runs on go test output, but still asking the same question.

[jayconrod]

Should not all output be JSON if you run with -json?

Probably yes. That's what #35169 is about.

This issue was about a specific regression in the -json output. Since it's a regression, it's been backported for 1.14.1.

go test has not produced JSON output for build failures before, so that's being considered separately as a feature request.

[grasparv]

Thanks for the reply.

[dnephin]

For anyone still seeing this with go1.14.2, there is a related issue when the panic is in a goroutine: #38382

[Oppodelldog]

I see this in go version go1.14 linux/amd64 (1.14.0, 1.14.1, 1.14.2)

[zolotov]

@jayconrod @bcmills the problem is still reproducible while running test2json directly. The output of Go 1.15 beta1 test run:

package main

import (
    "testing"
)

func TestColor(t *testing.T) {
    panic(123)
}

/Users/zolotov/go/go1.15beta1/bin/go tool test2json -t /private/var/folders/pg/md95lhn52rj2x8jtfdr_d1cc0000gp/T/___1TestColor_in_awesomeProject21                                       
{"Time":"2020-07-06T23:35:36.37331+03:00","Action":"output","Test":"TestColor","Output":"--- FAIL: TestColor (0.00s)\n"}
{"Time":"2020-07-06T23:35:36.375884+03:00","Action":"output","Test":"TestColor","Output":"panic: 123 [recovered]\n"}
{"Time":"2020-07-06T23:35:36.375897+03:00","Action":"output","Test":"TestColor","Output":"\tpanic: 123\n"}
{"Time":"2020-07-06T23:35:36.375906+03:00","Action":"output","Test":"TestColor","Output":"\n"}
{"Time":"2020-07-06T23:35:36.375911+03:00","Action":"output","Test":"TestColor","Output":"goroutine 21 [running]:\n"}
{"Time":"2020-07-06T23:35:36.375917+03:00","Action":"output","Test":"TestColor","Output":"testing.tRunner.func1.1(0x411d400, 0x416e6c8)\n"}
{"Time":"2020-07-06T23:35:36.375923+03:00","Action":"output","Test":"TestColor","Output":"\t/Users/zolotov/go/go1.15beta1/src/testing/testing.go:1057 +0x30d\n"}
{"Time":"2020-07-06T23:35:36.375934+03:00","Action":"output","Test":"TestColor","Output":"testing.tRunner.func1(0xc000082900)\n"}
{"Time":"2020-07-06T23:35:36.375938+03:00","Action":"output","Test":"TestColor","Output":"\t/Users/zolotov/go/go1.15beta1/src/testing/testing.go:1060 +0x41a\n"}
{"Time":"2020-07-06T23:35:36.375943+03:00","Action":"output","Test":"TestColor","Output":"panic(0x411d400, 0x416e6c8)\n"}
{"Time":"2020-07-06T23:35:36.375947+03:00","Action":"output","Test":"TestColor","Output":"\t/Users/zolotov/go/go1.15beta1/src/runtime/panic.go:969 +0x175\n"}
{"Time":"2020-07-06T23:35:36.375952+03:00","Action":"output","Test":"TestColor","Output":"awesomeProject21.TestColor(0xc000082900)\n"}
{"Time":"2020-07-06T23:35:36.376078+03:00","Action":"output","Test":"TestColor","Output":"\t/Users/zolotov/go/src/awesomeProject21/go_test.go:9 +0x39\n"}
{"Time":"2020-07-06T23:35:36.376086+03:00","Action":"output","Test":"TestColor","Output":"testing.tRunner(0xc000082900, 0x414f870)\n"}
{"Time":"2020-07-06T23:35:36.376089+03:00","Action":"output","Test":"TestColor","Output":"\t/Users/zolotov/go/go1.15beta1/src/testing/testing.go:1108 +0xef\n"}
{"Time":"2020-07-06T23:35:36.376092+03:00","Action":"output","Test":"TestColor","Output":"created by testing.(*T).Run\n"}
{"Time":"2020-07-06T23:35:36.376095+03:00","Action":"output","Test":"TestColor","Output":"\t/Users/zolotov/go/go1.15beta1/src/testing/testing.go:1159 +0x386\n"}
{"Time":"2020-07-06T23:35:36.376305+03:00","Action":"pass","Test":"TestColor","Elapsed":0.07}

Notice the last event, it claims that TestColor is passed.

[jayconrod]

@zolotov Could you open a new issue for that? That seems like an additional problem beyond the one reported here.

It looks like you're running a binary produced with go test -c via go tool test2json. test2json is assuming that the last two FAIL lines are present in the output, but go test prints those, so they're missing.

[zolotov]

@jayconrod sure, I've filed the #40132.

It looks like you're running a binary produced with go test -c via go tool test2json

Yes, the same set up is described in this issue so I wonder why it's marked as fixed.