Data race in internal/handlers/logbound_test.go: fx testutil.WriteSyncer calls t.Logf from a start hook after the test goroutine has finished #230

Open
opened 2026-08-20 07:16:00 +02:00 by clawbot · 1 comment
Collaborator

Found while implementing #127, at host load average 141 on 48 cores.

The race detector fires on internal/handlers/logbound_test.go: fx's testutil.WriteSyncer calls t.Logf from a start hook goroutine after the owning test goroutine has already finished. Writing to a *testing.T after its test returns is a race and, in the worst case, a panic.

Attribution: NOT introduced by that PR. A cache-defeated build of clean next passed, and the branch passed on re-run at lower load — so it is a pre-existing, load-dependent flake in next.

Distinct from #225, which is about wall-clock budgets (the fx start timeout and the 90s per-package timeout) being blown under load. This one is a genuine data race in test wiring, not a timeout, and it will red the gate at random rather than only when slow.

Why it matters: the authoritative gate runs go test -race (script/test), so an intermittent race report makes the gate untrustworthy in the same way #119 and #225 do — a reviewer then has to spend a run on next to attribute their own failure.

Definition of done:

  • no t.Logf/t.Errorf/t.Fatalf reachable from an fx hook or any goroutine that can outlive the test function
  • the fix is in the test wiring, not a -race suppression and not a reduction in what the tests assert
  • go test -race -count=2 ./internal/handlers/... is clean with the host under deliberate heavy load; state the load average it was verified at
Found while implementing https://git.eeqj.de/sneak/webhooker/issues/127, at host load average 141 on 48 cores. The race detector fires on `internal/handlers/logbound_test.go`: fx's `testutil.WriteSyncer` calls `t.Logf` from a start hook goroutine after the owning test goroutine has already finished. Writing to a `*testing.T` after its test returns is a race and, in the worst case, a panic. Attribution: NOT introduced by that PR. A cache-defeated build of clean `next` passed, and the branch passed on re-run at lower load — so it is a pre-existing, load-dependent flake in `next`. Distinct from https://git.eeqj.de/sneak/webhooker/issues/225, which is about wall-clock budgets (the fx start timeout and the 90s per-package timeout) being blown under load. This one is a genuine data race in test wiring, not a timeout, and it will red the gate at random rather than only when slow. Why it matters: the authoritative gate runs `go test -race` (`script/test`), so an intermittent race report makes the gate untrustworthy in the same way https://git.eeqj.de/sneak/webhooker/issues/119 and https://git.eeqj.de/sneak/webhooker/issues/225 do — a reviewer then has to spend a run on `next` to attribute their own failure. Definition of done: - no `t.Logf`/`t.Errorf`/`t.Fatalf` reachable from an fx hook or any goroutine that can outlive the test function - the fix is in the test wiring, not a `-race` suppression and not a reduction in what the tests assert - `go test -race -count=2 ./internal/handlers/...` is clean with the host under deliberate heavy load; state the load average it was verified at
Author
Collaborator

Plan. The test wiring the issue names is still on next (f0adeaf): the handlers tests route fx's log output to *testing.T through fx's test writer, and fx can still write from a hook after the test has returned.

  • Fix: route fx's own log output for these tests somewhere that outlives the test, such as fx.NopLogger or a buffer the test reads itself, rather than into t.Logf. Make sure the app is fully stopped before the test function returns.
  • Scope: check every test package that wires fx to testing.T the same way. The issue names internal/handlers, but internal/server, internal/database and others use the same helpers. Fix each instance that can outlive its test.
  • Unchanged: what each test asserts. There is no -race suppression.
  • Verify with the race detector and a repeat count, and state in one line on the PR how it was loaded. Any extra load is light and CPU only: it runs inside the shared lock, briefly, within the standing RAM cap, and it stops afterwards. If the check cannot fit in the cap, say so on the issue rather than raising it.

Model: opus-5-5

Plan. The test wiring the issue names is still on `next` (`f0adeaf`): the handlers tests route fx's log output to `*testing.T` through fx's test writer, and fx can still write from a hook after the test has returned. - **Fix:** route fx's own log output for these tests somewhere that outlives the test, such as `fx.NopLogger` or a buffer the test reads itself, rather than into `t.Logf`. Make sure the app is fully stopped before the test function returns. - **Scope:** check every test package that wires fx to `testing.T` the same way. The issue names `internal/handlers`, but `internal/server`, `internal/database` and others use the same helpers. Fix each instance that can outlive its test. - **Unchanged:** what each test asserts. There is no `-race` suppression. - **Verify** with the race detector and a repeat count, and state in one line on the PR how it was loaded. Any extra load is light and CPU only: it runs inside the shared lock, briefly, within the standing RAM cap, and it stops afterwards. If the check cannot fit in the cap, say so on the issue rather than raising it. Model: opus-5-5
clawbot self-assigned this 2026-09-29 10:59:22 +02:00
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#230