proposal: testing: flush test output on timeout, panic or abort

[matttproud]

I propose having package test flush test case log output upon panic — e.g., in case of test execution timeout. This is distinct from #23213 and #24929, which themselves ask for real-time streaming of output. I couldn't care less whether the output is realtime; I just want to see what has been logged with (*testing.T).Log() & Co irrespective of test case outcome.

Boilerplate below:

What version of Go are you using?

go version go1.10.1 linux/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using?

go env
GOARCH="amd64"
GOBIN=""
GOCACHE="REDACTED"
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="REDACTED"
GORACE=""
GOROOT="REDACTED"
GOTMPDIR=""
GOTOOLDIR="REDACTED"
GCCGO="gccgo"
CC="clang"
CXX="REDACTED"
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"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build354931168=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Ran this test (simplification of real code):

package timeout_test

import (
	"fmt"
	"os"
	"testing"
)

func TestTimeoutNoLog(t *testing.T) {
	t.Log("This is the log message that is never seen.")
	fmt.Fprintln(os.Stdout, "This is the STDOUT message everyone sees.")
	fmt.Fprintln(os.Stderr, "This is the STDERR message everyone sees.")
	select {}  // Time out!
}

and ran it with

go test timeout_test.go -timeout 5ms

What did you expect to see?

In short, This is the log message that is never seen. appears in the output.

$ go test timeout_test.go -test.timeout 5ms
This is the STDOUT message everyone sees.
This is the STDERR message everyone sees.
This is the log message that is never seen.
panic: test timed out after 5ms
goroutine 17 [running]:
testing.(*M).startAlarm.func1()
        /usr/lib/REDACTED/src/testing/testing.go:1255 +0xfc
created by time.goFunc
        /usr/lib/REDACTED/src/time/sleep.go:172 +0x44
goroutine 1 [chan receive]:
testing.(*T).Run(0xc4200b00f0, 0x52f823, 0x10, 0x536530, 0x4669d6)
        /usr/lib/REDACTED/src/testing/testing.go:825 +0x301
testing.runTests.func1(0xc4200b0000)
        /usr/lib/REDACTED/src/testing/testing.go:1065 +0x64
testing.tRunner(0xc4200b0000, 0xc42005bdf8)
        /usr/lib/REDACTED/src/testing/testing.go:777 +0xd0
testing.runTests(0xc42000a060, 0x5d3150, 0x1, 0x1, 0x40ee69)
        /usr/lib/REDACTED/src/testing/testing.go:1063 +0x2c4
testing.(*M).Run(0xc4200ac000, 0x0)
        /usr/lib/REDACTED/src/testing/testing.go:980 +0x171
main.main()
        _testmain.go:42 +0x151
goroutine 6 [select (no cases)]:
command-line-arguments.TestTimeoutNoLog(0xc4200b00f0)
        /tmp/a/shit_test.go:13 +0x125
testing.tRunner(0xc4200b00f0, 0x536530)
        /usr/lib/REDACTED/src/testing/testing.go:777 +0xd0
created by testing.(*T).Run
        /usr/lib/REDACTED/src/testing/testing.go:824 +0x2e0
FAIL    command-line-arguments  0.018s

What did you see instead?

Note the absence of This is the log message that is never seen.

$ go test timeout_test.go -test.timeout 5ms
This is the STDOUT message everyone sees.
This is the STDERR message everyone sees.
panic: test timed out after 5ms
goroutine 17 [running]:
testing.(*M).startAlarm.func1()
        /usr/lib/REDACTED/src/testing/testing.go:1255 +0xfc
created by time.goFunc
        /usr/lib/REDACTED/src/time/sleep.go:172 +0x44
goroutine 1 [chan receive]:
testing.(*T).Run(0xc4200b00f0, 0x52f823, 0x10, 0x536530, 0x4669d6)
        /usr/lib/REDACTED/src/testing/testing.go:825 +0x301
testing.runTests.func1(0xc4200b0000)
        /usr/lib/REDACTED/src/testing/testing.go:1065 +0x64
testing.tRunner(0xc4200b0000, 0xc42005bdf8)
        /usr/lib/REDACTED/src/testing/testing.go:777 +0xd0
testing.runTests(0xc42000a060, 0x5d3150, 0x1, 0x1, 0x40ee69)
        /usr/lib/REDACTED/src/testing/testing.go:1063 +0x2c4
testing.(*M).Run(0xc4200ac000, 0x0)
        /usr/lib/REDACTED/src/testing/testing.go:980 +0x171
main.main()
        _testmain.go:42 +0x151
goroutine 6 [select (no cases)]:
command-line-arguments.TestTimeoutNoLog(0xc4200b00f0)
        /tmp/a/shit_test.go:13 +0x125
testing.tRunner(0xc4200b00f0, 0x536530)
        /usr/lib/REDACTED/src/testing/testing.go:777 +0xd0
created by testing.(*T).Run
        /usr/lib/REDACTED/src/testing/testing.go:824 +0x2e0
FAIL    command-line-arguments  0.018s

[mvdan]

/cc @rogpeppe

[rsc]

We had two CLs related to this in mid-2017. https://go-review.googlesource.com/44352 added code to show in-progress tests on SIGINT, and then https://go-review.googlesource.com/48370 rolled that back, because some tests wanted to handle SIGINT themselves.

Timeout, panic, and abort are different from SIGINT, so handling those might not run into the same problem, but worth being aware of.

Catching these aborts and printing after the fact requires reaching into the runtime quite a bit, which is easy to cause its own instability. If we did #24929 instead, then there'd be no need for this proposal, since there would be nothing to flush. It might more worth spending more attention on that one instead.

[rsc]

We'll try #24929 in Go 1.12, so let's close this one.