testing/synctest: unexpected data race after synctest.Wait

[terinjokes]

Go version

go version go1.25rc1 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/terin/.cache/go-build'
GOCACHEPROG=''
GODEBUG=''
GOENV='/home/terin/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFIPS140='off'
GOFLAGS=''
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build2428105469=/tmp/go-build -gno-record-gcc-switches'
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMOD='/home/terin/Development/github.com/cloudflare/certinel/go.mod'
GOMODCACHE='/home/terin/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/home/terin/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/home/terin/sdk/go1.25rc1'
GOSUMDB='sum.golang.org'
GOTELEMETRY='local'
GOTELEMETRYDIR='/home/terin/.config/go/telemetry'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/home/terin/sdk/go1.25rc1/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.25rc1'
GOWORK=''
PKG_CONFIG='pkg-config'

What did you do?

I've written a test using testing/synctest that I expected to be free of data races. https://go.dev/play/p/FKlttCmxPIz?v=gotip

What did you see happen?

WARNING: DATA RACE
Write at 0x00c000124430 by goroutine 10:
  github.com/cloudflare/certinel/ticker.TestTickerSync.func1.1()
      /home/terin/Development/github.com/cloudflare/certinel/ticker/ticker_go125_test.go:20 +0x72

Previous read at 0x00c000124430 by goroutine 9:
  github.com/cloudflare/certinel/ticker.TestTickerSync.func1()
      /home/terin/Development/github.com/cloudflare/certinel/ticker/ticker_go125_test.go:30 +0x191
  testing.tRunner()
      /home/terin/sdk/go1.25rc1/src/testing/testing.go:1931 +0x21c
  testing.testingSynctestTest.gowrap1()
      /home/terin/sdk/go1.25rc1/src/testing/testing.go:2043 +0x44

What did you expect to see?

No data race as the read of variable errWatcher happened after synctest.Wait and the goroutine that writes to it was (to my current understanding) durably blocked.

[seankhliao]

I believe the race detector report is correct. There is nothing that establishes a ordering between the assignment to the error and the subsequent read, see synchronization for what are considered valid events that do so.
synctest.Wait is not a synchronization primitive.

[terinjokes]

At GopherCon EU @neild gave a presentation on synctest. Part of the presentation was synctest.Wait working in conjunction with the race detector to make it easier to write tests like the one I wrote in Play.

Certainly possible I misunderstood the slide, but if I recall correctly it was writing to a value in a goroutine and then reading it after a synctest.Wait. Thst seems pretty similar to what I've done.

[neild]

Hm, there's something strange here. If I reduce the test to this, I see a data race on the indicated lines:

func Test(t *testing.T) {
        synctest.Test(t, func(t *testing.T) {
                var v bool
                go func() {
                        time.Sleep(2 * time.Minute)
                        v = true // data race: write
                }()
                time.Sleep(30 * time.Second)
                synctest.Wait()
                _ = v // data race: previous read
                synctest.Wait()
                time.Sleep(90 * time.Second)
        })
}

That doesn't seem correct, since there are synctest.Wait calls before and after the supposedly racy read.

I'm not sure what's going on yet, but unless I'm missing something there's a bug in the interaction between Wait and the race detector.

[seankhliao]

my understanding was that there was no synchronization between the read/write so the race is expected.
to synchronize, you'd have to put the Wait after the 2min sleep in the goroutine

[neild]

Ah, no, I was missing something (and @seankhliao is right).

synctest.Wait waits for the bubble to become durably blocked, and then creates a happens-before relationship with all activity up to that point in time and the Wait call.

For the reduced case I gave, the Wait calls establish that the _ = v read happens before the time.Sleep call, but nothing establishes the ordering of the v = true write.

In the original example (https://go.dev/play/p/FKlttCmxPIz?v=gotip), a similar problem exists: Nothing establishes the ordering of the write to errWatcher.

[neild]

I do still feel like something isn't behaving quite as it should here, though. The Wait calls in the reduced test are clearly describing a non-racy sequence of events where the read at 30s happens before the write at 120s.

[terinjokes]

There may be a race between the write and the second read in my example.

Putting that aside, why is a race reported between the read and the writes in the reduced example? My mental model is that the first read should have been sequenced and established with the existing synctest.Waits before the deadline was slept to?

[seankhliao]

The read happens after 30s, but may be delayed arbitrarily far into the future, e.g. due to resource starvation, such that it happens in parallel with the write. This usually doesn't happen, but it is a valid sequence of events.