testing: "panic: Log in goroutine after Test..." is unreliable due to lack of synchronization on t.done

[Groxx]

Go version

go1.22.3 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/stevenl/Library/Caches/go-build'
GOENV='/Users/stevenl/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/stevenl/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/stevenl/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/Users/stevenl/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.3.darwin-arm64'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/stevenl/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.3.darwin-arm64/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.3'
GCCGO='gccgo'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/stevenl/go/src/github.com/uber/cadence/go.mod'
GOWORK='/Users/stevenl/go/src/github.com/uber/cadence/go.work'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/zp/sqm92pj94sq7whfh1rl3yjd00000gn/T/go-build780465693=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

/*
❯ cat testlogger_test.go
*/
package testlogger

import (
    "fmt"
    "testing"
    "time"
)

func TestMain(m *testing.M) {
    m.Run()
    time.Sleep(100 * time.Millisecond) // also sometimes works without testmain, but more consistent with next test
}

func TestABefore(t *testing.T) {
    go func() {
        t.Logf("sleeping")
        time.Sleep(10 * time.Millisecond)
        t.Logf("too late")
        fmt.Println("goroutine done") // prove it ran
    }()
    time.Sleep(time.Millisecond)
}

func TestZLater(t *testing.T) {
    t.Logf("another test")
    time.Sleep(time.Second) // make sure the process hangs around long enough
}

/*
❯ go test -count 1 -v -race ./...
=== RUN   TestABefore
    testlogger_test.go:15: sleeping
--- PASS: TestABefore (0.00s)
=== RUN   TestZLater
    testlogger_test.go:24: another test
goroutine done
--- PASS: TestZLater (1.00s)
PASS
ok      example.com/testlogger_test.go  1.465s
*/

Despite clearly logging after the test has completed, this test does not reliably fail, depending on other code in the test and elsewhere. And when it does not fail, t.Logf("too late") is silently not logged anywhere.

This is hard to reliably reproduce, but the cause is fairly straightforward: whether it logs or panics is determined by checking t.done inside the test's mutex, but t.done is changed outside the mutex, so that value change may not propagate to the goroutine that produces the faulty log.

Forcing a happens-after relationship reliably causes failure:

/*
❯ cat testlogger_test.go
*/
package testlogger

import (
    "fmt"
    "testing"
    "time"
)

var done = make(chan struct{})

func TestMain(m *testing.M) {
    m.Run()
    close(done)  // happens-after t.done = true
    time.Sleep(100 * time.Millisecond)
}
func TestABefore(t *testing.T) {
    go func() {
        t.Logf("sleeping")
        time.Sleep(10 * time.Millisecond)
        <-done
        t.Logf("too late") // now also happens-after t.done = true
        fmt.Println("goroutine done")
    }()
    time.Sleep(time.Millisecond)
}

func TestZLater(t *testing.T) {
    t.Logf("another test")
    time.Sleep(time.Second)
}

/*
❯ go test -count 1 -v -race ./...
=== RUN   TestABefore
    testlogger_test.go:17: sleeping
--- PASS: TestABefore (0.00s)
PASS
panic: Log in goroutine after TestABefore has completed: too late

goroutine 35 [running]:
testing.(*common).logDepth(0x14000410820, {0x14000133f70, 0x8}, 0x3)
    /Users/stevenl/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.3.darwin-arm64/src/testing/testing.go:1028 +0x3d0
testing.(*common).log(...)
    /Users/stevenl/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.3.darwin-arm64/src/testing/testing.go:1010
testing.(*common).Logf(0x14000410820, {0x1006c4df4?, 0x0?}, {0x0?, 0x0?, 0x0?})
    /Users/stevenl/go/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.3.darwin-arm64/src/testing/testing.go:1061 +0x5c
example.com/testlogger.TestABefore.func1()
    /Users/stevenl/go/src/example.com/testlogger/testlogger_test.go:19 +0x6c
created by example.com/testlogger.TestABefore in goroutine 34
    /Users/stevenl/go/src/example.com/testlogger/testlogger_test.go:16 +0x5c
FAIL    example.com/testlogger  0.331s
FAIL
*/

As much as I am fond of this race-detecting trick, and appreciate the issues it catches: https://github.com/golang/go/blob/master/src/testing/testing.go#L1675-L1677

        // Do not lock t.done to allow race detector to detect race in case
        // the user does not appropriately synchronize a goroutine.
        t.done = true

I feel like this log-failure-flakiness is an unintended consequence. Maybe the race-detecting access could be moved to a different field, rather than one that has a rather significant impact on behavior?

It's also strange to me that this doesn't seem to be (reliably) catching this race - is that happening inside t.checkRaces(), so this all races later than the check? I'm not familiar with this part of race-detection: https://github.com/golang/go/blob/master/src/testing/testing.go#L1548C1-L1549C1

What did you see happen?

❯ go test -count 1 -v  ./...
...
PASS
ok      example.com/testlogger_test.go  1.465s

Tests pass and the too-late log is not caught nor is its output sent to stdout/stderr.

What did you expect to see?

panic: Log in goroutine after TestABefore has completed: too late

should be produced reliably, as long as the test clearly finishes before the log occurs (as seen from a real-world observer, i.e. me). And it should not require outside-of-test synchronization to behave reliably.

Proof-of-concept fix

67796

[mknyszek]

CC @adonovan @neild via https://dev.golang.org/owners

[Groxx]

Added a proof-of-concept fix over in https://github.com/golang/go/pull/67796

[gopherbot]

Change https://go.dev/cl/590055 mentions this issue: testing: fix racy t.done usage by adding a separate race-canary field