testing: T.Cleanup is not invoked when -timeout=N is exceeded

[dprotaso]

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

$ go version
go version go1.15.3 darwin/amd64

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/dprotasowski/Library/Caches/go-build"
GOENV="/Users/dprotasowski/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/dprotasowski/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/dprotasowski/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.15.3/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.15.3/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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=/var/folders/qn/bxc0sm8j5dgcx260_4r3vr7w0000gn/T/go-build588412775=/tmp/go-build -gno-record-gcc-switches -fno-common

What did you do?

Create a test that sleeps for 2s - https://play.golang.org/p/dxQO9DFI6b1

func TestHelloWorld(t *testing.T) {
	t.Cleanup(func() {
		fmt.Println("cleanup")
	})
	time.Sleep(2 * time.Second)
}

func TestMain(m *testing.M) {
	code := m.Run()
        fmt.Println("TestMain cleanup")
        os.Exit(code)
}

Invoke the test with a 1 second timeout

$ go test -v -timeout 1s .

What did you expect to see?

1. Cleanup function registered in TestHelloWorld is invoked.
2. m.Run() returns and TestMain code continues to execute

What did you see instead?

The test timed out but did not invoke fmt.Println("cleanup") nor it it invoke fmt.Println("TestMain cleanup")

[davecheney]

I believe this is because -timeout is implemented in the parent to command and kills the tests binary, not the current test being executed.

[ianlancetaylor]

It's true that the parent has a backup timeout, but that's not quite what is happening here. The timeout in the test works by calling panic, and there is no step that runs the Cleanup functions of the tests that are running at the point where that panic occurs.

There are other ways to stop the test without running the cleanups, such as go func() { panic(0) }(). The Go language doesn't provide a mechanism that can infallibly run a cleanup. And of course no such mechanism is possible in the general case, as the process might be killed by some external program. If your cleanup absolutely must be run in all possible cases, you need to use some mechanism involving a separate process; the t.Cleanup method cannot suffice.

[dprotaso]

And of course no such mechanism is possible in the general case, as the process might be killed by some external program

Yeah that's why I linked #41891 to this issue. I think it's a best effort so I wouldn't expect SIGTERM to cleanup.

There are other ways to stop the test without running the cleanups, such as go func() { panic(0) }(). The Go language doesn't provide a mechanism that can infallibly run a cleanup

Internally do goroutines track the parent routine that spawned them?

[ianlancetaylor]

Internally do goroutines track the parent routine that spawned them?

Yes, in the sense that a stack trace prints out where a goroutine was created. But in general goroutines don't have names or identifiers.