-race reports DATA RACE even though ack is an unbuffered receive. Is time.After to blame?

Is it possible that the race detector is wrong here, or that I misunderstand what the ack gives me? This is pushgate, a small service that checks HMAC signatures on device tokens for push notifications in my mobile app. The caller sends a Request on an unbuffered channel, the worker fills in a Result, then sends the ID on an ack channel. The caller reads the Result only after receiving the ack. I wrote the tests like this on purpose so there is no time.Sleep. The select with time.After is only there so a stuck test dies.

Plain go test is always green. Today before tagging a release I ran go test -race -count=200 ./.... About one run in 30-40 prints WARNING: DATA RACE, with a read in the test goroutine and a write in the worker goroutine. The worker side points into verify.go, the test side at the t.Logf line in verify_test.go. It seems to come more from TestWorkerRejectsBadSig, but I am not sure.

What I tried:

buffered ack channel: race showed up more often, so I put it back
-cpu 1: race disappears, but I don't trust that
the old Result had two fields, and I added a timestamp last week for audit logs. I don't see why that would matter

The worker:

for r := range in {
	want := sign(secret, r.Token)
	ok := hmac.Equal([]byte(want), []byte(r.Sig))

	r.Result.DeviceID = r.ID
	r.Result.Valid = ok
	ack <- r.ID

	// stamp after the ack so the caller is not kept waiting
	r.Result.Checked = time.Now()
	if verbose {
		log.Printf("checked device=%d valid=%v", r.ID, ok)
	}
}

The test that fails more often:

func TestWorkerRejectsBadSig(t *testing.T) {
	res := runOne(t, 9, "apns-abc123", "deadbeef")
	t.Logf("result for bad sig: %+v", *res)
	if res.Valid {
		t.Fatal("bad signature accepted")
	}
	if res.DeviceID != 9 {
		t.Fatalf("device id %d", res.DeviceID)
	}
}

runOne makes both channels with plain make(chan ...), starts the worker, sends the Request, then selects on ack vs time.After(2 * time.Second) and returns res. I was reading https://go.dev/ref/mem but still don't see where the ordering breaks. Is the pointer inside the struct hiding something from the detector?

The conversation continues 4

Follow the reasoning

Vadim31 Aug Permalink
Found it, and the detector was right)) The problem is my own comment, "stamp after the ack". The ack only orders the writes that happen before it. r.Result.Checked = time.Now() runs after ack <- r.ID, so nothing orders it against the caller's read. t.Logf("%+v", *res) copies the whole struct, including Checked, while the worker may still be writing it.

That also explains the rest:
- With two fields, both were written before the ack, so there was no race. The timestamp I added last week is the first write after the ack.
- -cpu 1 hides it because the worker rarely gets to run in that window.
- The buffered ack makes it worse because the worker never blocks on the send, so it reaches the late write sooner.
- TestWorkerRejectsBadSig fails more often because it is the only test that logs the whole struct. The others read single fields, so they only hit it if they happen to read Checked.
The fix is to move the stamp before the ack:
```
r.Result.DeviceID = r.ID
r.Result.Valid = ok
r.Result.Checked = time.Now()
ack <- r.ID
```
The send happens-before the receive completes, as in the "Channel communication" section of https://go.dev/ref/mem. I ran -race -count=200 again and it came back clean. The log.Printf after the ack is fine because it doesn't touch the Result.
Vadim16 Sept Permalink
Following an earlier reply ↗
Small follow-up for anyone who finds this later. I changed the comment above the send to "everything the caller reads is written before this line", and the stamp now sits right under the other two fields. The wrong comment was what led me astray in the first place.

I also read the race detector article properly this time: https://go.dev/doc/articles/race_detector. It says the detector only reports races that actually happen in that run. So my green plain go test never proved anything, and the clean -count=200 is evidence, not a guarantee. That is why I now keep -race in the pre-release script and not only in my head.

If the audit timestamp must be written after the ack, the worker could send it in a second message, or the caller could take a copy of the Result only after a later sync point. For pushgate I don't need it, so I left it out.

Funny that the same mistake in the Android client would show up as a rare crash in a user's logs, and I'd never reproduce it on my laptop))
Vadim17 Sept Permalink
One more thing for people hitting this: -count=200 and -shuffle=on are both in the testing flags list in the go command docs, and I use them together now. https://pkg.go.dev/cmd/go
tam_ly8 Oct Permalink
Disagree, I don't think the detector is wrong. The write after ack looks like the race to me. Why share the Result pointer at all? Why not send the Result by value through the channel? I admit the audit timestamp makes it a bit awkward.

-race reports DATA RACE even though ack is an unbuffered receive. Is time.After to blame?

The conversation continues 4

Other sides of the same question

HMAC mismatch on one webhook only (the one with accents in the name)

memset before free passes at default flags, fails with OPT=-O2

Same overflow check, different error branch at -O0 vs -O2