testing: stack unavailable when a parallel test times out

[mvdan]

Please answer these questions before submitting your issue. Thanks!

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

go version devel +a2bd5c5 Thu Nov 24 03:48:45 2016 +0000 linux/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/mvdan/go"
GORACE=""
GOROOT="/home/mvdan/tip"
GOTOOLDIR="/home/mvdan/tip/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build553187312=/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?

Ran go test -short -timeout 1s with a new test case that I knew was going to loop forever and time out (trying to fix it).

What did you expect to see?

The go test timeout being hit and the panic with a useful stack trace shown.

What did you see instead?

panic: test timed out after 1s

goroutine 177 [running]:
testing.startAlarm.func1()
        /home/mvdan/tip/src/testing/testing.go:1041 +0xf9
created by time.goFunc
        /home/mvdan/tip/src/time/sleep.go:170 +0x44

goroutine 1 [chan receive]:
testing.tRunner.func1(0xc4200860e0)
        /home/mvdan/tip/src/testing/testing.go:655 +0x17e
testing.tRunner(0xc4200860e0, 0xc420039db8)
        /home/mvdan/tip/src/testing/testing.go:681 +0x149
testing.runTests(0xc4200cc180, 0x6bb720, 0x12, 0x12, 0x10)
        /home/mvdan/tip/src/testing/testing.go:906 +0x29d
testing.(*M).Run(0xc42003af20, 0x0)
        /home/mvdan/tip/src/testing/testing.go:841 +0xfc
github.com/mvdan/sh/syntax.TestMain(0xc420039f20)
        /home/mvdan/go/src/github.com/mvdan/sh/syntax/parser_test.go:66 +0x5d
main.main()
        github.com/mvdan/sh/syntax/_test/_testmain.go:82 +0xf7

goroutine 9 [chan receive]:
testing.(*T).Run(0xc4200862a0, 0xc420162bc8, 0x3, 0xc4201647e0, 0x0)
        /home/mvdan/tip/src/testing/testing.go:717 +0x2f1
github.com/mvdan/sh/syntax.TestParseErrBash(0xc4200862a0)
        /home/mvdan/go/src/github.com/mvdan/sh/syntax/parser_test.go:752 +0x23f
testing.tRunner(0xc4200862a0, 0x5d1ad8)
        /home/mvdan/tip/src/testing/testing.go:679 +0x13f
created by testing.(*T).Run
        /home/mvdan/tip/src/testing/testing.go:716 +0x2c7

goroutine 10 [chan receive]:
testing.runTests.func1.1(0xc4200860e0)
        /home/mvdan/tip/src/testing/testing.go:905 +0x47
created by testing.runTests.func1
        /home/mvdan/tip/src/testing/testing.go:905 +0xaf

goroutine 170 [running]:
        goroutine running on other thread; stack unavailable
created by testing.(*T).Run
        /home/mvdan/tip/src/testing/testing.go:716 +0x2c7
FAIL    github.com/mvdan/sh/syntax      1.015s

Note that this doesn't happen all the time. It happens often, though - about half of the times I run go test.

I don't know if this is by design. I can see the cause - the use of t.Parallel() - but I don't think its use should have this inconvenient.

[mvdan]

For the sake of completeness, this is what the stack trace looks when it happens to be alright:

goroutine 170 [runnable]:
github.com/mvdan/sh/syntax.(*parser).wordPart(0xc420106000, 0x6a0fc0, 0xc427443a88)
        /home/mvdan/go/src/github.com/mvdan/sh/syntax/parser.go:537 +0x2041
[...]
github.com/mvdan/sh/syntax.checkError.func1(0xc42015ddc0)
        /home/mvdan/go/src/github.com/mvdan/sh/syntax/parser_test.go:731 +0xb4
testing.tRunner(0xc42015ddc0, 0xc4201647e0)
        /home/mvdan/tip/src/testing/testing.go:679 +0x13f
created by testing.(*T).Run
        /home/mvdan/tip/src/testing/testing.go:716 +0x2c7
FAIL    github.com/mvdan/sh/syntax      1.011s

[quentinmit]

I have a vague memory that setting GOTRACEBACK=crash might cause the omitted backtraces to be printed. But now I can't find any docs that say it.

[minux]

That's right (setting GOTRACEBACK=crash will print all backtraces) but I agree this is not documented because it doesn't work on all platforms. (More detailed explanations: with GOTRACEBACK=crash, because it's going to crash anyway, the runtime can send signals to each thread and ask it to dump stack trace. But this implementation obviously don't work on systems without async signals.)

[quentinmit]

Maybe the testing package should automatically set GOTRACEBACK=crash?

[mvdan]

Frustratingly, this happens 100% of the time when I do:

go test -short -timeout 1s -parallel 1 -run TestThatHangs

Surely this one is fixable? If -parallel 1 is given, I would assume that everything gets run on the main thread and this doesn't happen at all.

[josharian]

If -parallel 1 is given, I would assume that everything gets run on the main thread and this doesn't happen at all.

Running tests involves a fair amount of machinery. Running everything on the main thread is a hard enough problem that testing.M was introduced in large part to enable it. So the fix here is going to have to be general, not particular to the value of -parallel.

[mvdan]

For future reference, I ended up opening #19280 for forcing parallel tests to run sequentially.

[rsc]

Duplicate of #13161.