[go1.14] Panics in a test confuse test2json, test is considered passing

[notnoop]

When a panic occurs in a test background goroutine, gotestsum terminates with exit code 1 but without reporting the panic and without reporting the package name, unlike go test.

go test -json unexpectedly emits a action=pass event for the test and doesn't the result of package name. Justifiably, gotestsum doesn't report the output of a reportedly successful test.

This seems unambiguously a go test issue, and I aim to follow up go test maintainers; though, I'd suggest considering a workaround or noting a caveat in documentation. It has been a bit hard to identify in our case and some peers have advocated for switching back to using go test to avoid similar bugs in future.

Reproduction

With sample file blow:

1. run go test .; echo "exit code: $?" - note the FAIL message, panic and non-zero exit code
2. run `gotestsum .; echo "exit code: $?""

$ go version
go version go1.14 darwin/amd64
$ go test .; echo "exit code: $?"
panic: panicing on a background goroutine

goroutine 19 [running]:
mypkg.Test_PanicInGoroutine.func1()
	/Users/notnoop/go/src/mypkg/my_test.go:9 +0x39
created by mypkg.Test_PanicInGoroutine
	/Users/notnoop/go/src/mypkg/my_test.go:9 +0x35
FAIL	mypkg	0.024s
FAIL
exit code: 1
$ gotestsum .; echo "exit code: $?"

DONE 1 tests in 0.811s
exit code: 1

sample test

package mypkg

import (
	"testing"
	"time"
)

func Test_PanicInGoroutine(t *testing.T) {
	go func() { panic("panicing on a background goroutine") }()
	time.Sleep(10 * time.Millisecond)
}

func Test_AlwaysFail(t *testing.T)    { t.Fatalf("fail here") }
func Test_AlwaysSucceed(t *testing.T) {}

more details

The json output of go test for Test_PanicInGoroutineandTest_AlwaysFails` are included below. I would note two differences:

• Test_PanicInGoroutine has "Action":"pass" entry for the test despite the previous FAIL output.
• Test_PanicInGoroutine does not have a "Action":"{pass|fail}" for the package level.

Test_PanicInGoroutine

`$ go test -json . -run 'Test_PanicInGoroutine'; echo "exit code: $?"`
{"Time":"2020-03-10T16:39:56.06625-04:00","Action":"run","Package":"mypkg","Test":"Test_PanicInGoroutine"}
{"Time":"2020-03-10T16:39:56.066817-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"=== RUN   Test_PanicInGoroutine\n"}
{"Time":"2020-03-10T16:39:56.068326-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"panic: panicing on a background goroutine\n"}
{"Time":"2020-03-10T16:39:56.068345-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"\n"}
{"Time":"2020-03-10T16:39:56.068356-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"goroutine 7 [running]:\n"}
{"Time":"2020-03-10T16:39:56.06836-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"mypkg.Test_PanicInGoroutine.func1()\n"}
{"Time":"2020-03-10T16:39:56.068364-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"\t/Users/notnoop/go/src/mypkg/my_test.go:9 +0x39\n"}
{"Time":"2020-03-10T16:39:56.068367-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"created by mypkg.Test_PanicInGoroutine\n"}
{"Time":"2020-03-10T16:39:56.068379-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"\t/Users/notnoop/go/src/mypkg/my_test.go:9 +0x35\n"}
{"Time":"2020-03-10T16:39:56.068697-04:00","Action":"output","Package":"mypkg","Test":"Test_PanicInGoroutine","Output":"FAIL\tmypkg\t0.022s\n"}
{"Time":"2020-03-10T16:39:56.068726-04:00","Action":"pass","Package":"mypkg","Test":"Test_PanicInGoroutine","Elapsed":0.024}
exit code: 1

AlwaysFails

go test -json -v . -run 'Test_AlwaysFail'; echo "exit code: $?"
{"Time":"2020-03-10T16:40:45.63055-04:00","Action":"run","Package":"mypkg","Test":"Test_AlwaysFail"}
{"Time":"2020-03-10T16:40:45.630831-04:00","Action":"output","Package":"mypkg","Test":"Test_AlwaysFail","Output":"=== RUN   Test_AlwaysFail\n"}
{"Time":"2020-03-10T16:40:45.630847-04:00","Action":"output","Package":"mypkg","Test":"Test_AlwaysFail","Output":"    Test_AlwaysFail: my_test.go:13: fail here\n"}
{"Time":"2020-03-10T16:40:45.631142-04:00","Action":"output","Package":"mypkg","Test":"Test_AlwaysFail","Output":"--- FAIL: Test_AlwaysFail (0.00s)\n"}
{"Time":"2020-03-10T16:40:45.631158-04:00","Action":"fail","Package":"mypkg","Test":"Test_AlwaysFail","Elapsed":0}
{"Time":"2020-03-10T16:40:45.631173-04:00","Action":"output","Package":"mypkg","Output":"FAIL\n"}
{"Time":"2020-03-10T16:40:45.631211-04:00","Action":"output","Package":"mypkg","Output":"FAIL\tmypkg\t0.020s\n"}
{"Time":"2020-03-10T16:40:45.631221-04:00","Action":"fail","Package":"mypkg","Elapsed":0.02}
exit code: 1

[dnephin]

Thanks for the detailed bug report! I haven't been able to get my PR for #66 accepted to fix that issue, so I would like to work around this problem in case it takes a while to get fixed.

For an immediate workaround I would suggest using --format standard-verbose. That format does appear to properly print the output at least, even if the summary is not exactly correct.

I think a potential code change workaround could be:

• if the last line of output is FAIL\t...\n consider the test as failed

I hope this will fix the problem in gotestsum until it can be fixed in the go toolchain.

[dnephin]

I think the problem is any panic in a test. Ex, I added this:

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

and it seems to have the same behaviour.

[dnephin]

Tested with both go1.13 and go1.12 and it seems to work correctly. I think this is a regression in go1.14.

[notnoop]

So good news: This report issue is indeed a regression in 1.14, with a fix targeting 1.14.1. There is a fix already for golang/go@76a6adc .

Sadly, we've encountered another bug with similar symptoms. Prior to upgrading to golang 1.14, we had seen cases no failed tests but exit code 1 with golang 1.12, e.g. https://circleci.com/gh/hashicorp/nomad/41667 and https://circleci.com/gh/hashicorp/nomad/28151 . It happened at a much lower rate. It might be #66 .

I'll close this issue, research the issue we saw in 1.12 by adding more logging and collecting data, and then follow up with a new ticket or comment on #66 .

Thank you so much for your quick follow up!

[dnephin]

There are still some issues like this in go1.14.1. I wrote up #99