testing: t.Fatal does not fatal tests if defers do not complete

[zwass]

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

go version go1.9.2 darwin/amd64

Does this issue reproduce with the latest release?

Yes.

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/zwass/dev/go"
GORACE=""
GOROOT="/usr/local/Cellar/go/1.9.2/libexec"
GOTOOLDIR="/usr/local/Cellar/go/1.9.2/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/4k/2q3ctn7d5_xb03_zsb3v6lgr0000gn/T/go-build085156185=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"

What did you do?

test_test.go

package test

import (
	"sync"
	"testing"
	"time"
)

func TestTest(t *testing.T) {
	var m sync.Mutex
	defer m.Lock()
	go func() {
		for {
			time.Sleep(1 * time.Second)
		}
	}()

	m.Lock()
	t.Fatal("foobar")
}

What did you expect to see?

go test -v
=== RUN   TestTest
--- FAIL: TestTest (0.00s)
	test_test.go:19: foobar
FAIL
exit status 1
FAIL	test	0.007s

What did you see instead?

go test -v
=== RUN   TestTest
panic: test timed out after 10m 0s

goroutine 17 [running]:
testing.startAlarm.func1()
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:1145 +0xf9
created by time.goFunc
	/usr/local/Cellar/go/1.9.2/libexec/src/time/sleep.go:170 +0x44

goroutine 1 [chan receive]:
testing.(*T).Run(0xc420094000, 0x1135230, 0x8, 0x113d640, 0x10688b6)
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:790 +0x2fc
testing.runTests.func1(0xc420094000)
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:1004 +0x64
testing.tRunner(0xc420094000, 0xc420043de0)
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:746 +0xd0
testing.runTests(0xc42000a060, 0x11db860, 0x1, 0x1, 0xc42004c3b0)
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:1002 +0x2d8
testing.(*M).Run(0xc420043f18, 0xc420043f70)
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:921 +0x111
main.main()
	test/_test/_testmain.go:44 +0xdb

goroutine 6 [semacquire]:
sync.runtime_SemacquireMutex(0xc4200140ec, 0xc420048e00)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/sema.go:71 +0x3d
sync.(*Mutex).Lock(0xc4200140e8)
	/usr/local/Cellar/go/1.9.2/libexec/src/sync/mutex.go:134 +0xee
runtime.Goexit()
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/panic.go:366 +0x147
testing.(*common).FailNow(0xc4200940f0)
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:544 +0x39
testing.(*common).Fatal(0xc4200940f0, 0xc420030788, 0x1, 0x1)
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:582 +0x6f
test.TestTest(0xc4200940f0)
	/Users/zwass/dev/go/src/test/test_test.go:19 +0xdc
testing.tRunner(0xc4200940f0, 0x113d640)
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:746 +0xd0
created by testing.(*T).Run
	/usr/local/Cellar/go/1.9.2/libexec/src/testing/testing.go:789 +0x2de

goroutine 7 [sleep]:
time.Sleep(0x3b9aca00)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/time.go:65 +0x130
test.TestTest.func1()
	/Users/zwass/dev/go/src/test/test_test.go:14 +0x2a
created by test.TestTest
	/Users/zwass/dev/go/src/test/test_test.go:12 +0x78
exit status 2
FAIL	test	600.010s

The above example is obviously broken, but this hanging behavior from the test runner causes quite a confusing experience when there are more subtle issues going on.

It's also worth noting that there is no way to determine from the dumped goroutines what is causing the hang.

From what I can tell, this is due to t.FailNow() using runtime.GoExit() which waits for defers to complete.

The docs for t.FailNow() say the following:

FailNow marks the function as having failed and stops its execution. Execution will continue at the next test or benchmark. FailNow must be called from the goroutine running the test or benchmark function, not from other goroutines created during the test. Calling FailNow does not stop those other goroutines.

[ianlancetaylor]

I'm marking this as a documentation issue. If someone can figure out how to fix it reasonably, that's fine with me. But in practice I think we should just document this and move on.

[gopherbot]

Change https://golang.org/cl/83881 mentions this issue: testing: emphasize that Fatal/FailNow/etc run deferred calls

[rsc]

This is working as intended. You want those deferred calls to run and finish before the test is torn down. If one is buggy and blocks forever, well, sorry. Sent a CL.