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

dlsniper · 2020-02-28T13:39:06Z

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.

The text was updated successfully, but these errors were encountered:

bcmills · 2020-02-28T18:36:20Z

Does go test -json exhibit the same problem?

dlsniper · 2020-03-04T09:20:08Z

Yes

dlsniper · 2020-03-04T09:21:42Z

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 · 2020-03-04T22:25:09Z

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 · 2020-03-04T22:31:20Z

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

dmitshur · 2020-03-04T22:34:09Z

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 · 2020-03-04T22:34:19Z

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 · 2020-03-05T16:24:20Z

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 · 2020-03-05T21:23:48Z

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

grasparv · 2020-03-06T09:19:15Z

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 · 2020-03-09T14:01:07Z

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

…r panicking/exiting tests 'go test -json' should report that a test failed if the test binary did not exit normally with status 0. This covers panics, non-zero exits, and abnormal terminations. These tests don't print a final result when run with -test.v (which is used by 'go test -json'). The final result should be "PASS" or "FAIL" on a line by itself. 'go test' prints "FAIL" in this case, but includes error information. test2json was changed in CL 192104 to report that a test passed if it does not report a final status. This caused 'go test -json' to report that a test passed after a panic or non-zero exit. With this change, test2json treats "FAIL" with error information the same as "FAIL" on a line by itself. This is intended to be a minimal fix for backporting, but it will likely be replaced by a complete solution for #29062. Fixes #37671 Updates #37555 Updates #29062 Updates #31969 Change-Id: Icb67bcd36bed97e6a8d51f4d14bf71f73c83ac3d Reviewed-on: https://go-review.googlesource.com/c/go/+/222243 Run-TryBot: Jay Conrod <jayconrod@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Bryan C. Mills <bcmills@google.com> (cherry picked from commit 5ea58c6) Reviewed-on: https://go-review.googlesource.com/c/go/+/222658 Run-TryBot: Dmitri Shuralyov <dmitshur@golang.org> Reviewed-by: Jay Conrod <jayconrod@google.com>

grasparv · 2020-03-10T12:12:53Z

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

bcmills · 2020-03-10T14:37:23Z

@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 · 2020-03-10T14:40:34Z

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

grasparv · 2020-03-10T15:08:41Z

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 · 2020-03-10T15:20:47Z

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 · 2020-03-10T15:46:19Z

Thanks for the reply.

dnephin · 2020-04-11T22:40:35Z

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

Oppodelldog · 2020-05-13T19:39:19Z

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

zolotov · 2020-07-06T20:36:36Z

@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 · 2020-07-08T17:17:57Z

@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 · 2020-07-09T10:10:57Z

@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.

bcmills changed the title ~~go tool test2json fails to report tests with panics as failed~~ cmd/test2json: tests that panic are marked as passing Feb 28, 2020

bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Feb 28, 2020

bcmills added this to the Backlog milestone Feb 28, 2020

ianlancetaylor modified the milestones: Backlog, Go1.14.1 Mar 4, 2020

ianlancetaylor added the release-blocker label Mar 4, 2020

dmitshur changed the title ~~cmd/test2json: tests that panic are marked as passing~~ cmd/go: tests that panic or exit are marked as passing when -json flag is used Mar 4, 2020

jayconrod self-assigned this Mar 4, 2020

dmitshur modified the milestones: Go1.14.1, Go1.15 Mar 4, 2020

This was referenced Mar 4, 2020

cmd/go: tests that panic or exit are marked as passing when -json flag is used [1.14 backport] #37671

Closed

cmd/go: tests that panic or exit are marked as passing when -json flag is used [1.15 backport] #37672

Closed

jayconrod added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Mar 5, 2020

gopherbot closed this as completed in 5ea58c6 Mar 6, 2020

jayconrod mentioned this issue Apr 3, 2020

cmd/go: go test -json sends pass event for a test that panics #38226

Closed

dnephin mentioned this issue Apr 11, 2020

go/test2json: panic in goroutine results in missing Action=Fail TestEvent #38382

Closed

firelizzard18 mentioned this issue Jul 9, 2021

proposal: go/test: add a package to facilitate test tooling #47101

Closed

golang locked and limited conversation to collaborators Jul 9, 2021

gopherbot added the FrozenDueToAge label Jul 9, 2021

rsc unassigned jayconrod Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

dlsniper commented Feb 28, 2020

bcmills commented Feb 28, 2020

dlsniper commented Mar 4, 2020

dlsniper commented Mar 4, 2020

dmitshur commented Mar 4, 2020

bcmills commented Mar 4, 2020

dmitshur commented Mar 4, 2020

gopherbot commented Mar 4, 2020 •

edited by dmitshur

jayconrod commented Mar 5, 2020

gopherbot commented Mar 5, 2020

grasparv commented Mar 6, 2020 •

edited

gopherbot commented Mar 9, 2020

grasparv commented Mar 10, 2020 •

edited

bcmills commented Mar 10, 2020

jayconrod commented Mar 10, 2020

grasparv commented Mar 10, 2020 •

edited

jayconrod commented Mar 10, 2020

grasparv commented Mar 10, 2020

dnephin commented Apr 11, 2020

Oppodelldog commented May 13, 2020

zolotov commented Jul 6, 2020 •

edited

jayconrod commented Jul 8, 2020

zolotov commented Jul 9, 2020

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

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

Comments

dlsniper commented Feb 28, 2020

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

bcmills commented Feb 28, 2020

dlsniper commented Mar 4, 2020

dlsniper commented Mar 4, 2020

dmitshur commented Mar 4, 2020

bcmills commented Mar 4, 2020

dmitshur commented Mar 4, 2020

gopherbot commented Mar 4, 2020 • edited by dmitshur

jayconrod commented Mar 5, 2020

gopherbot commented Mar 5, 2020

grasparv commented Mar 6, 2020 • edited

gopherbot commented Mar 9, 2020

grasparv commented Mar 10, 2020 • edited

bcmills commented Mar 10, 2020

jayconrod commented Mar 10, 2020

grasparv commented Mar 10, 2020 • edited

jayconrod commented Mar 10, 2020

grasparv commented Mar 10, 2020

dnephin commented Apr 11, 2020

Oppodelldog commented May 13, 2020

zolotov commented Jul 6, 2020 • edited

jayconrod commented Jul 8, 2020

zolotov commented Jul 9, 2020

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

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

gopherbot commented Mar 4, 2020 •

edited by dmitshur

grasparv commented Mar 6, 2020 •

edited

grasparv commented Mar 10, 2020 •

edited

grasparv commented Mar 10, 2020 •

edited

zolotov commented Jul 6, 2020 •

edited