race detector가 틀렸거나, 제가 ack가 보장해 주는 걸 잘못 이해하고 있는 걸까요? pushgate라는 작은 서비스인데, 제 모바일 앱의 푸시 알림용 디바이스 토큰에 붙은 HMAC 서명을 검사해요. 호출하는 쪽이 unbuffered 채널로 Request를 보내면 worker가 Result를 채우고, 그다음 ack 채널로 ID를 보내요. 호출하는 쪽은 ack를 받은 뒤에만 Result를 읽어요. 테스트는 일부러 time.Sleep 없이 이렇게 썼어요. time.After를 쓴 select는 테스트가 멈췄을 때 죽게 하려는 용도일 뿐이에요.
그냥 go test는 항상 초록불이에요. 오늘 릴리스 태그 달기 전에 go test -race -count=200 ./...를 돌렸어요. 30~40번에 한 번쯤 WARNING: DATA RACE가 뜨는데, 테스트 goroutine에서 읽기, worker goroutine에서 쓰기로 나와요. worker 쪽은 verify.go를 가리키고, 테스트 쪽은 verify_test.go의 t.Logf 줄을 가리켜요. TestWorkerRejectsBadSig에서 더 자주 나오는 것 같은데 확실하진 않아요.
해 본 것들:
- ack 채널을 buffered로 바꿈: race가 더 자주 떠서 원래대로 되돌림
-cpu 1: race가 사라지는데 이건 믿음이 안 가요- 예전 Result는 필드가 두 개였고, 지난주에 감사 로그용으로 타임스탬프를 추가했어요. 이게 왜 문제가 되는지 모르겠어요
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)
}
}
더 자주 실패하는 테스트:
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은 두 채널을 모두 평범한 make(chan ...)로 만들고, worker를 시작하고, Request를 보낸 다음, ack와 time.After(2 * time.Second)를 select하고 res를 반환해요. https://go.dev/ref/mem 을 읽어 봤는데도 순서가 어디서 깨지는지 모르겠어요. struct 안의 포인터가 detector한테서 뭔가를 가리고 있는 걸까요?
영어에서 번역·원문 보기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?
