Skip to content

Fix flaky -race tests: dispatcher shutdown-error normalization, deterministic ingest drain asserts, signallive gate log-buffer sync#143

Merged
MaxGhenis merged 2 commits into
mainfrom
fix/flaky-race-shutdown-and-drain
Jul 21, 2026
Merged

Fix flaky -race tests: dispatcher shutdown-error normalization, deterministic ingest drain asserts, signallive gate log-buffer sync#143
MaxGhenis merged 2 commits into
mainfrom
fix/flaky-race-shutdown-and-drain

Conversation

@MaxGhenis

@MaxGhenis MaxGhenis commented Jul 19, 2026

Copy link
Copy Markdown
Owner

Fixes the three flaky -race tests that intermittently fail CI on unrelated PRs (observed on run 29658833081, attempt 1, a Swift-only diff). The third (#147, internal/signallive, hit on W4-A's run 2026-07-19) reproduces reliably once its temp-dir trigger is seeded — see below. Closes #147.

1. TestLegacyPrimaryStackStillStartsLegacyProjector — data race on the test's log buffer

What the trace shows. The race is write/write between two sibling runner goroutines, not goroutine-vs-test: goroutine 2248 (projector, v2stack.go:366, finished) logged its expected "V2 legacy projector stopped" for the nil-legacy sentinel, and goroutine 2247 (dispatcher, v2stack.go:350, running) also logged an error at v2stack.go:353. Both wrote to the test's bytes.Buffer through one zerolog logger. WaitGroup.Done()Done() creates no happens-before between siblings and the buffer has no lock, so any second logging runner is a data race.

Why the dispatcher logged at all. MessageService.Run starts with RecoverExpiredLeases and loops through reconcileStoreFailedDue/DispatchDue. When stop()'s cancel lands mid-query, modernc.org/sqlite surfaces a driver interrupt that does not satisfy errors.Is(err, context.Canceled), so the runner's is-canceled filter let it through and the dispatcher logged a spurious shutdown error. DispatchDue already guards exactly this class in its lease path ("Shutdown can race the lease transaction…"); the fix extends the same normalization to Run's three call sites: once ctx is canceled, Run returns ctx.Err(). The existing regression test (TestDispatchDueCanceledContextIsCleanStopNotLeaseFault) only exercised the pre-canceled path, where database/sql short-circuits with bare context.Canceled before reaching the driver — the mid-query interrupt was the untested gap.

Was there a production drain gap in v2Stack.Stop()? No. Stop() cancels, then runWG.Wait() joins every runner goroutine Start spawned (worker, dispatcher, projector/notifier — each Done() in a defer after its final log write), and only then closes the store. Goroutine lifetimes and shutdown ordering are correct. The real production defect found instead: on shutdown, a cancel racing an in-flight dispatcher query made Run exit with a non-Canceled error — logging a scary V2 message dispatcher stopped at error level on clean shutdowns, and misleading anything supervising Run's exit value. That's fixed at the source in dispatch.go.

Harness hardening. The two tests that capture logs now wrap the buffer in zerolog.SyncWriter (cmd/v2stack_test.go), so any future legitimately-concurrent runner logging can't race the buffer regardless. The projector's nil-legacy log line stays deterministic: Projector.Run validates deps before checking ctx, so the assertion the test exists for is unaffected.

2. TestWhatsAppReactionDeltasApplySwitchRemoveAndOrphanThroughWorker — counters used as durability barriers

CI failed at whatsappdecoder_test.go:623 with unprocessed frames = 1, want 0. The test waits for ReactionsOrphaned == 1, then one-shot asserts the inbox is drained. But countOrphanReaction bumps the atomic counter mid-apply (worker.go:636) while MarkInboxProcessed commits only at the end of the pass (worker.go:697) — the counter is a progress signal, not a durability barrier, and under -race parallel load the one-shot read lands in that gap. (This is specific to the orphan path: Projected, Quarantined, and the reaction-apply counters all increment after their durable writes commit, so the test's other counter-then-read asserts — and the similar one in google_echo_e2e_test.go — are ordered correctly; audited each one.)

While shaking the fix at -count=5 locally, a second latent flake in the same test reproduced at line 566: assertWorkerChangeClosed was a non-blocking select on the captured Changes() channel, but the worker closes it only after the drain pass that advanced the counter the test just waited on.

Both asserts now wait for the condition they actually mean instead of snapshotting it, keeping their discriminating power (a genuinely stuck frame or missing broadcast still fails, at the 10s deadline):

  • i01AssertNoPending polls Unprocessed() until empty (same cadence as i01WaitFor, and the same pattern the test itself already used for the stale-add wait) — covers both call sites.
  • assertWorkerChangeClosed blocks with a deadline; its two other call sites follow a synchronous drain(), where blocking is a no-op.

3. TestSignalCLIVersionGateFailsOpenWithWarning — tmp-sweep goroutine vs. the test's log read (#147)

What the trace shows. The write is sweepLegacyLibsignalTemp logging “Removed libsignal temp dirs…” (tmpdir.go:130) on the tracked goroutine maybeSweepTmp spawns from the receive loop (client.go:1884); the read is the test body's log.String() (gate_test.go:263) against the same unsynchronized bytes.Buffer. The test waits only on the receiveCalls atomic before reading, and nothing joins the sweeper first. #147's hypothesis pointed at the version-gate warning, but that write is ordered: it happens before the receive stub bumps receiveCalls, which the test observes before reading. The sweeper has no such edge.

Why CI reddens intermittently. The sweep only logs when it removes ≥1 stale libsignal* dir from the runner's temp dir — and removing them burns the trigger, so a racing run goes green on the next attempt. Redness is a function of runner temp-dir state, which is why -count=3 sometimes reproduces and sometimes doesn't.

Why not zerolog.SyncWriter this time. Section 1's harness hardening used SyncWriter because those v2stack tests read their buffers after stop() joins every runner — only writers were concurrent. Here the read itself races a live writer, and bytes.Buffer.String() bypasses any writer-side lock. The fix is a test-local syncBuffer whose Write and String share one mutex (internal/signallive/gate_test.go only; no production code touched).

Verification was seeded, not just repeated. Plain -count=N goes green whenever the temp dir happens to be clean, so the repro harness plants stale (2020-mtime) libsignal-seed-* dirs into a private TMPDIR before every single -race run, forcing the sweep down its logging path: 30/30 races before the fix, 0/50 after (plus 0/20 re-run on this branch).

Verification

  • GOWORK=off go test -race -count=50 -run TestLegacyPrimaryStackStillStartsLegacyProjector ./cmd/ — ok
  • GOWORK=off go test -race -count=50 -run TestWhatsAppReactionDeltasApplySwitchRemoveAndOrphanThroughWorker ./internal/ingest/ — ok (plus 10× alongside TestWorkerChanges*)
  • GOWORK=off go test -race -count=3 -run TestDispatchDue ./internal/messaging/ — ok (existing shutdown regression test still green with the new normalization)
  • Seeded harness (stale libsignal* dirs planted per run): 30/30 races pre-fix → 0/50 post-fix; 0/20 on this branch
  • GOWORK=off go test -race -count=50 -run TestSignalCLIVersionGateFailsOpenWithWarning ./internal/signallive/ — ok
  • GOWORK=off go test -race ./... twice — both exit 0, no race warnings, all packages ok (re-run with all three fixes on the branch)

🤖 Generated with Claude Code

… ingest drain asserts deterministic

TestLegacyPrimaryStackStillStartsLegacyProjector raced because two v2Stack
runner goroutines wrote to the test's unsynchronized bytes.Buffer: the
projector logged its nil-legacy sentinel, and the dispatcher also logged on
shutdown because a cancellation racing an in-flight query surfaces as a
driver interrupt rather than context.Canceled. Sibling runners have no
happens-before between them, so two writers is a data race. Normalize
MessageService.Run to return ctx.Err() when canceled (matching DispatchDue's
existing lease-path guard) and give the test buffers zerolog.SyncWriter.
v2Stack.Stop() itself has no drain gap: it joins every runner before closing
the store.

TestWhatsAppReactionDeltasApplySwitchRemoveAndOrphanThroughWorker used
worker counters as durability barriers, but the orphan counter advances
before MarkInboxProcessed commits and the change broadcast fires after the
drain pass. Poll the inbox drain in i01AssertNoPending and block with a
deadline in assertWorkerChangeClosed instead of snapshotting.

Verified: each test 50x under -race; full go test -race ./... twice, clean.

Co-Authored-By: Claude Fable 5 <[email protected]>
@MaxGhenis

Copy link
Copy Markdown
Owner Author

Third flaky -race instance surfaced 2026-07-19 (reddened an unrelated PR's Go Race job): internal/signallive.TestSignalCLIVersionGateFailsOpenWithWarning (subtest malformed_output) — a real data race, reproduces reliably in isolation:

GOWORK=off go test -race -count=3 -run TestSignalCLIVersionGateFailsOpenWithWarning ./internal/signallive/

A goroutine (the version-gate probe/warn path) writes a shared buffer/logger the test then reads. Same class as the v2stack logger race this PR already fixes — likely wants the same treatment (join the gate goroutine before asserting, or a mutex/zerolog.SyncWriter around the warn sink). Flagging so it can ride along here rather than reappear on the next unrelated PR.

…uffer against the tmp-sweep goroutine

TestSignalCLIVersionGateFailsOpenWithWarning raced because the bridge's
receive loop calls maybeSweepTmp, which spawns a tracked goroutine that
sweeps stale signal-cli temp dirs and logs through the bridge logger
whenever it removes any — a concurrent Write into the test's
unsynchronized bytes.Buffer while the test body reads log.String(). The
test waits only on the receiveCalls atomic before reading, and nothing
joins the sweeper first. Whether the sweep logs at all depends on
machine temp-dir state, and a racing run deletes the stale dirs that
triggered it — burning the trigger for the next run — hence
intermittent CI redness on unrelated PRs (issue #147) rather than a
reliable failure. The version-gate warning itself was never the racer:
it is written before the receive stub bumps receiveCalls, which the
test observes before reading.

Unlike the v2stack fix, zerolog.SyncWriter is not enough here: it
serializes writers only, and this race is write-vs-read (the v2stack
tests read their buffers after stop() joins every runner; this test
reads while the sweeper is live). Give the test a syncBuffer whose
Write and String share one mutex.

Verified: seeded-repro harness (stale libsignal* dirs planted in a
private TMPDIR before each -race run, forcing the sweep to log) raced
30/30 before the fix and 0/50 after; the issue's -count=50 repro is
clean; full go test -race ./... twice, clean.

Closes #147.

Co-Authored-By: Claude Fable 5 <[email protected]>
@MaxGhenis MaxGhenis changed the title Fix flaky -race tests: dispatcher shutdown-error normalization + deterministic ingest drain asserts Fix flaky -race tests: dispatcher shutdown-error normalization, deterministic ingest drain asserts, signallive gate log-buffer sync Jul 21, 2026
@MaxGhenis
MaxGhenis merged commit 099e00b into main Jul 21, 2026
5 checks passed
@MaxGhenis
MaxGhenis deleted the fix/flaky-race-shutdown-and-drain branch July 21, 2026 08:21
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Flaky -race: TestSignalCLIVersionGateFailsOpenWithWarning (signallive) — third race, not in #143

1 participant