testing: nested t.Fatalf hides errors

[scubed2]

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

go version
go version go1.8 linux/amd64

Does this issue reproduce with the latest release?

(Untested)

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

go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/scubed/go"
GORACE=""
GOROOT="/nix/store/5428ij3ln77vam6cacnljc1f75f214fs-go-1.8/share/go"
GOTOOLDIR="/nix/store/5428ij3ln77vam6cacnljc1f75f214fs-go-1.8/share/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build180482905=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

I'm not sure how to put a test in the playground.
If someone could point out how to do that, I will.

nested.go
-------------
package nested
-------------
nested_test.go
-------------
package nested

import (
"testing"
)

func TestNested(t *testing.T) {
outer := t
t.Run("sub", func(t *testing.T) {
outer.Fatalf("Nope")
})
}
-------------
Note that renaming t to outer is just for emphasis.

What did you expect to see?

While it's not immediately obvious to me what should happen in this case, it should at least:

1. Print out the string passed to Fatalf (in this case, "Nope")
2. If this is invalid, say that it is calling Fatalf from the wrong scope, so people know what the actual problem is.

This came up when debugging a test that was using gomock incorrectly. I ended up spending time tracking down this instead of fixing the test.

What did you see instead?

It gives a not very helpful stacktrace.

go test nested_test.go
panic: test executed panic(nil) or runtime.Goexit

goroutine 6 [running]:
testing.tRunner.func1(0xc420076750)
/nix/store/5428ij3ln77vam6cacnljc1f75f214fs-go-1.8/share/go/src/testing/testing.go:622 +0x29d
runtime.Goexit()
/nix/store/5428ij3ln77vam6cacnljc1f75f214fs-go-1.8/share/go/src/runtime/panic.go:366 +0x153
testing.(*common).FailNow(0xc4200765b0)
/nix/store/5428ij3ln77vam6cacnljc1f75f214fs-go-1.8/share/go/src/testing/testing.go:486 +0x39
testing.(*common).Fatalf(0xc4200765b0, 0x5393ee, 0x4, 0x0, 0x0, 0x0)
/nix/store/5428ij3ln77vam6cacnljc1f75f214fs-go-1.8/share/go/src/testing/testing.go:530 +0x83
command-line-arguments.TestNested.func1(0xc420076750)
/dev/shm/a/nested_test.go:10 +0x5c
testing.tRunner(0xc420076750, 0xc42000eea0)
/nix/store/5428ij3ln77vam6cacnljc1f75f214fs-go-1.8/share/go/src/testing/testing.go:657 +0x96
created by testing.(*T).Run
/nix/store/5428ij3ln77vam6cacnljc1f75f214fs-go-1.8/share/go/src/testing/testing.go:697 +0x2ca
FAIL command-line-arguments 0.004s

[agnivade]

Tested on 1.9 and master. Fails on both.

Simplified the code to use different variables. It's much more clear here -

package nested

import (
	"testing"
)

func TestNested(tt *testing.T) {
        // tt.Fatalf("Nope") // This works as expected
	tt.Run("sub", func(t *testing.T) {
		tt.Fatalf("Nope")
	})
}

Just save this to a file and run go test. It gives a panic.

[creichlin]

This behavior is triggered because t.Run creates a new goroutine and t.Fatalf calls t.FailNow from that new goroutine which will try to exit the current test by exiting the current goroutine. This is documented in the Run and FailNow method. It should be possible to fix because Run is blocking and while it's blocked a proper error message could be printed before panicking.
I'm not sure though if such a thing is worth fixing, i would say it's rather unlikely to happen and at least it panics so you see that there is something wrong. The added complexity might out-weight the benefit.

[namusyaka]

Actually, I think this is a corner case, but the current behavior is not intuitive.

For example, I guess we can fix the issue with such a change.

diff --git src/testing/testing.go src/testing/testing.go
index f56dbf8f6d..6bd03b703b 100644
--- src/testing/testing.go
+++ src/testing/testing.go
@@ -733,7 +733,7 @@ func tRunner(t *T, fn func(t *T)) {
                t.duration += time.Since(t.start)
                // If the test panicked, print any test output before dying.
                err := recover()
-               if !t.finished && err == nil {
+               if (t.parent != nil && !t.parent.finished) && !t.finished && err == nil {
                        err = fmt.Errorf("test executed panic(nil) or runtime.Goexit")
                }
                if err != nil {

and then, got:

=== RUN   TestNested
=== RUN   TestNested/sub
--- FAIL: TestNested (0.00s)
	main_test.go:10: Nope
    --- PASS: TestNested/sub (0.00s)
FAIL

What do you think? I can send a CL if you hope.

[gopherbot]

Change https://golang.org/cl/87835 mentions this issue: testing: don't overwrite error unless parent of subtest is finished

[namusyaka]

I've rethink this issue, and then I strongly thought that this problem should be fixed. Anyway, I will send the CL to do this discussion productively, then I decided to wait for go-1.11 development cycle.
Thanks.

[gopherbot]

Change https://golang.org/cl/97635 mentions this issue: testing: gracefully handle subtest failing parent’s T

[mpvl]

@namusyaka I agree that the current behavior is undesirable. Thanks for the CL. It comes close to a fix, but has some remaining issues. I've created another CL which I believe comes to a good compromise. It treats calling FailNow on a parent as an error, but will still handle it gracefully without panicking.

If we decide in the future that this is not an error, we need to handle the case of parallel subtests calling FailNow on a parent concurrently. This will be very tricky to get right.