Repository: go
Issue: testing: "panic: Log in goroutine after Test..." is unreliable due to lack of synchronization on t.done
Labels: NeedsInvestigation,BugReport

### Go version

go1.22.3 darwin/arm64

### Output of `go env` in your module/workspace:

```shell
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?

```go
/*
❯ 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:
```go
/*
❯ 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
```go
		// 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