testing/synctest: race when logging in goroutine in bubble #76615
Description
Go version
go version go1.26-devel_29d43df8ab Tue Oct 21 14:49:13 2025 -0700 linux/amd64
Output of go env in your module/workspace:
AR='ar'
CC='gcc'
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_ENABLED='1'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
CXX='g++'
GCCGO='gccgo'
GO111MODULE=''
GOAMD64='v1'
GOARCH='amd64'
GOAUTH='netrc'
GOBIN=''
GOCACHE='/home/rogpeppe/.cache/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/home/rogpeppe/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build77024818=/tmp/go-build -gno-record-gcc-switches'
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMOD='/dev/null'
GOMODCACHE='/home/rogpeppe/src/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/home/rogpeppe/src/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/home/rogpeppe/go'
GOSUMDB='sum.golang.org'
GOTELEMETRY='on'
GOTELEMETRYDIR='/home/rogpeppe/.config/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/home/rogpeppe/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.26-devel_29d43df8ab Tue Oct 21 14:49:13 2025 -0700'
GOWORK=''
PKG_CONFIG='pkg-config'What did you do?
I ran this testscript:
exec go test -race -count 100
-- go.mod --
module test
go 1.25
-- main_test.go --
package main
import (
"testing"
"testing/synctest"
)
func TestSyncTestLogging(t *testing.T) {
synctest.Test(t, func(t *testing.T) {
go func() {
t.Logf("hello")
}()
})
}
What did you see happen?
> exec go test -race -count 100
[stdout]
==================
WARNING: DATA RACE
Write at 0x00c0001b44d3 by goroutine 90:
testing.tRunner.func1()
/home/rogpeppe/go/src/testing/testing.go:2016 +0x904
runtime.deferreturn()
/home/rogpeppe/go/src/runtime/panic.go:663 +0x5d
testing.testingSynctestTest.gowrap1()
/home/rogpeppe/go/src/testing/testing.go:2143 +0x38
Previous read at 0x00c0001b44d3 by goroutine 91:
testing.(*common).destination()
/home/rogpeppe/go/src/testing/testing.go:1058 +0x96
testing.(*common).log()
/home/rogpeppe/go/src/testing/testing.go:1036 +0xbe
testing.(*common).Logf()
/home/rogpeppe/go/src/testing/testing.go:1200 +0x8e
test.TestSyncTestLogging.func1.1()
$WORK/main_test.go:11 +0x44
Goroutine 90 (running) created at:
testing/synctest.testingSynctestTest()
/home/rogpeppe/go/src/testing/testing.go:2143 +0x5fc
testing/synctest.Test.func1()
/home/rogpeppe/go/src/testing/synctest/synctest.go:291 +0x44
Goroutine 91 (running) created at:
test.TestSyncTestLogging.func1()
$WORK/main_test.go:10 +0x8a
testing.tRunner()
/home/rogpeppe/go/src/testing/testing.go:2029 +0x21c
testing.testingSynctestTest.gowrap1()
/home/rogpeppe/go/src/testing/testing.go:2143 +0x38
==================
--- FAIL: TestSyncTestLogging (0.00s)
main_test.go:11: hello
testing.go:1712: race detected during execution of test
FAIL
exit status 1
FAIL test 0.024s
[exit status 1]
FAIL: x.txtar:1: unexpected command failure
What did you expect to see?
A passing test. From my understanding of synctest, it waits for all goroutines in the bubble to exit
before completion. That means that the t.Logf call must have completed before the test completes,
so we should be able to consider this code to behave similarly to putting a t.Logf inside a Cleanup:
it runs after the test function has returned but before the test has fully stopped.
This definitely doesn't seem to be working as intended, because some of the synctest
examples themselves contain t.Log calls without any subsequent synchronization.