Skip to content

test(server): deflake reach_rank hook race and the #1008 not-ready window (#224, #227) - #234

Merged
dborup merged 2 commits into
masterfrom
codex/issue-224-227-race-flakes
Oct 5, 2026
Merged

dborup merged 2 commits into
masterfrom
codex/issue-224-227-race-flakes

Conversation

@dborup-agent

Copy link
Copy Markdown
Collaborator

Relates to #224, #227

Two -race test flakes in cmd/server. Both are fixed in the test design, one commit per issue. The only production change is a nil func field that startBackgroundIndexBuilds checks once per Load(); it is unset outside the #227 test.

#224: reach_rank hook written while a previous test's refresh reads it

Cause. The race report (reproduced under load) shows the reader is a singleflight refresh created by getDegreeSnapshot in TestReachRank_ExpiredSnapshotAlwaysRefreshes, already finished when the next test writes onDegreeSnapshotLoad. The two accesses never overlap in time; they lack a happens-before edge. This is how it happens:

  • The test hammers an expired snapshot from 16 goroutines.
  • A caller that read the expired snapshot just before the refresh published can register one more refresh before the callers return.
  • That refresh runs after the test, finds the snapshot cleared by resetReachState's cleanup (degreeSnap = nil), and calls the hook.
  • Nobody receives its result, so nothing orders it before the next test's write.

Fix (test only). At the end of the test, awaitDegreeRefresh joins the "degree" singleflight key once more and receives the result.

  • Every refresh a caller registered is registered before wg.Wait returns, so this join either waits for it or, with none left, runs one that returns the fresh snapshot without a load.
  • The receive orders that refresh before the test returns.

Why not an atomic or per-server hook. Either would silence the race report. But the leftover refresh would still run after the test and call the next test's hook: an atomic hook would be the next test's load counter, which is what RefreshHonoursBackoffAfterQueuedFailure asserts on. Making the test wait fixes the cause, and it is the smallest change: one helper, no production change.

#227: the Kpa-clawbot#1008 503 test races the background subpath index build

Cause. The test asserted the not-ready window right after Load(). The background build of the 6-transmission fixture can finish first, and then the handler answers 200.

Fix.

  • PacketStore gets subpathBuildGate func(), nil in production. startBackgroundIndexBuilds reads it before starting the subpath builder goroutine, which calls it first when it is set.
  • The test sets the gate before Load(), waits until the build is held, and asserts the 503 (status, Retry-After: 5, body). It then releases the gate, waits for WaitIndexesReady, and asserts 200.
  • A t.Cleanup releases the gate if an assertion fails, so the builder is never stranded.

Why a per-store field, not a package variable. Many tests call Load(), and their background builders would read a package variable while this test writes it: the #224 pattern again. A field set before Load() is ordered by the go statement, and other stores never read it.

Production cost and behaviour. One nil check per Load(), outside any request or ingest path. The gate is never set outside the test, and readiness behaviour (flags, 503, ready channel) is unchanged.

Failure rate under load

The load was a second process looping the full cmd/server -race test binary (on tmpfs), on a 4-core host with load average 3–8.

Run Before After
#224: the two tests as separate processes, -count=1 (the race detector reports a race once per process) 5/200 with a race report 0/200
#224: go test -race -count=200 -run 'TestReachRank' — 0 race reports in 3 runs (the first exited FAIL on the deadline flake below; the other two passed)
#227: -count=600 in one process 55/600, 49/600 (status = 200, want 503) 0/600, 0/600
#227: go test -race -count=200 -run TestIssue1008_HandlerReturns503WhileSubpathIndexLoading — ok, 0/200

Mutants

Mutant Result
#224: the awaitDegreeRefresh call removed the race comes back: 4/200 processes with a race report
#227: production ignores the gate the test fails deterministically, 20/20 ("build never started")
#227: the test sets no gate the flake comes back: 2/600 (at a lower load average, ~3)

Also seen, not fixed here

TestReachRank_ExpiredSnapshotAlwaysRefreshes has a second, separate flake under load: round N: expired snapshot never refreshed. One round exceeds the test's 3 s per-round deadline. It appeared before the fix too, in 1/200 processes; it also appeared in 1 of 200 iterations of one acceptance run, and in 3/200 processes of the #224 mutant run. It is not a race report, and it is not touched here. A follow-up issue is proposed in the report.

Checks

  • cd cmd/server && go test -race -count=1 -timeout 20m ./... (TMPDIR on tmpfs, unloaded): ok (665 s), 0 race reports.
  • go vet passes. gofmt -l flags index_ready_1008.go and index_ready_1008_test.go, but only for their existing doc-comment lists, which are unformatted on master too; the new hunks are formatted.
  • cmd/server stays read-only. No new map[string]interface{}. Fork guards are unchanged: deploy.yml 9, release-fast-path.yml 1.

🤖 Generated with Claude Code

dborup and others added 2 commits October 4, 2026 13:10
…224)

TestReachRank_ExpiredSnapshotAlwaysRefreshes hammers the expired
snapshot from 16 goroutines. A caller that read the expired snapshot
just before the refresh published can register one more singleflight
refresh before the callers return. That refresh runs after the test,
finds the snapshot cleared by resetReachState's cleanup, and calls
onDegreeSnapshotLoad with no happens-before edge to the next test,
which swaps the hook: the -race report in
TestReach Rank_RefreshHonoursBackoffAfterQueuedFailure.

awaitDegreeRefresh joins the "degree" key once more at the end of the
test and receives its result: it waits for any refresh still in flight
(or runs one that returns the fresh snapshot without a load), which
orders that refresh before the test returns. Test-only: an atomic or
per-server hook would hide the report but still let the leftover
refresh call the next test's hook.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
 503 test (#227)

TestIssue1008_HandlerReturns503WhileSubpathIndexLoading checked the
not-ready window right after Load(), racing the background subpath
index build of a 6-transmission fixture; under CPU load the build won
and the handler answered 200.

PacketStore gets subpathBuildGate, a func field that is nil in
production. startBackgroundIndexBuilds reads it before starting the
subpath builder goroutine, which calls it first when it is set. The test
sets it before Load() to block the build, asserts the 503, then releases
it, waits for WaitIndexesReady and asserts 200. A per-store field rather
than a package variable: background builds of other tests' stores never
read it, so it cannot race the way #224's package hook did. Production
cost is one nil check per Load(); readiness behaviour is unchanged.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@dborup-agent

Copy link
Copy Markdown
Collaborator Author

Rapport — CS-pve-agent3 PR#234 #224+#227 — head 7862f67

Status: Both flakes were reproduced under load and fixed in the test design. The fixes are 7faca593 (#224, test only) and 7862f67a (#227, a per-store gate that is nil in production). Under load both now run with 0 failures, and the mutants bring each flake back. CI is green. The PR stays a draft.

Evidence tags: [T] test or run output, [K] checked in code, diff or CI log, [A] assessment or inference.

Load for all "under load" numbers: a second process looping the full cmd/server -race test binary on tmpfs, on a 4-core host with load average 3–8. [T]

Failure rate, before and after

Issue Run Before After
#224 the two tests as 200 separate processes, -count=1, because the race detector reports a race once per process 5/200 with a DATA RACE report [T] 0/200 [T]
#224 go test -race -count=200 -run 'TestReachRank' — 3 runs, 0 race reports [T]. Run 1 exited FAIL on the separate deadline flake (see Residuals); runs 2 and 3 passed [T]
#227 -count=600 in one process 55/600 and 49/600 (status = 200, want 503) [T] 0/600 and 0/600 [T]
#227 go test -race -count=200 -run TestIssue1008_HandlerReturns503WhileSubpathIndexLoading — ok, 0/200 [T]

Design and reasons

#224.

  • Cause. The race report shows the reader is a singleflight refresh created by getDegreeSnapshot in TestReachRank_ExpiredSnapshotAlwaysRefreshes, already finished when the next test writes the hook. So the two accesses lack a happens-before edge; they do not overlap in time. [T]
    • A caller that read the expired snapshot just before the refresh published can register one more refresh before the 16 callers return.
    • That refresh runs after the test, finds degreeSnap == nil (cleared by resetReachState's t.Cleanup), and calls onDegreeSnapshotLoad. Nobody receives its result. [K][A]
  • Fix (test only). At the end of the test, awaitDegreeRefresh joins the "degree" key once more and receives the result. [K]
    • Every refresh a caller registered is registered before wg.Wait returns, so this join either waits for it or, with none left, runs one that returns the fresh snapshot without a load.
    • The receive orders it before the test returns.
  • Why this one. It removes the cause with one helper and no production change. An atomic or per-server hook would silence the report, but the leftover refresh would still run after the test and call the next test's hook (for example its load counter). [A]

#227.

  • Fix. [K]
    • PacketStore.subpathBuildGate func() is nil in production. startBackgroundIndexBuilds reads it before starting the subpath builder goroutine, which calls it first when it is set.
    • The test sets the gate before Load(), waits until the build is held, and asserts the 503 (status, Retry-After: 5, body). It then releases the gate, waits for WaitIndexesReady, and asserts 200.
    • A t.Cleanup releases the gate if an assertion fails.
  • Why a per-store field. A package variable would be read by the background builders of every other test's Load() while this test writes it, which is reach_rank tests: onDegreeSnapshotLoad written while a previous test's singleflight refresh still reads it (-race flake) #224's pattern again. A field set before Load() is ordered by the go statement. [A]
  • Production cost. One nil check per Load(), outside request and ingest paths. Readiness behaviour (flags, 503, ready channel) is unchanged. [K]

Mutants

Mutant Result
#224: the awaitDegreeRefresh call removed the race comes back: 4/200 processes with a DATA RACE report, under load [T]
#227: production ignores the gate (_ = gate) fails deterministically, 20/20 ("background subpath index build never started") [T]
#227: the test sets no gate the flake comes back: 2/600 status = 200, want 503 (at load average ~3, lower than in the "before" runs) [T]

Other checks

  • [T] cd cmd/server && go test -race -count=1 -timeout 20m ./... (TMPDIR on tmpfs, unloaded): ok (665 s), 0 race reports.
  • [T] go vet passes.
  • [T] gofmt -l flags index_ready_1008.go and index_ready_1008_test.go, but only for their existing doc-comment lists, which are unformatted on master too; the new hunks are formatted.
  • [K] cmd/server stays read-only. No new map[string]interface{}. Fork guards are unchanged (deploy.yml 9, release-fast-path.yml 1). Two commits, one per issue.

CI (run 37206392371, head 7862f67a)

Job Result
Go Build & Test pass [T]; 0 DATA RACE lines in its log [K]
Playwright E2E Tests pass [T]
Build & Publish Docker Image pass [T]; local image build only, no push [K]
Release Artifacts / Deploy Staging / Publish Badges & Summary skipped (PR) [T]

Residuals

@dborup

dborup commented Oct 5, 2026

Copy link
Copy Markdown
Owner

Review — CS-MacBook PR#234 race-flakes — head 7862f67

Dom: APPROVE med nits

Evidence tags: [T] run or test output, [A] assessment or inference, [K] checked in code, diff, CI or git.

Scope: independent read-only review. Head 7862f67a was the same before and after the review (git ls-remote). The merged tree is git merge-tree --write-tree of origin/master (aff158c7) and the head: tree 5a2b2308. Its cmd/server differs from master only in the four PR files. [K]

Findings

# Severity Finding
F1 nit awaitDegreeRefresh runs only on the success path of TestReachRank_ExpiredSnapshotAlwaysRefreshes. A t.Fatalf inside the round loop skips it, so a failing run can leave the same stray refresh behind and add a second, misleading race report in the next test. Registering the join with t.Cleanup would also cover failures (Cleanup is LIFO, so it runs before resetReachState's clear). [K][A]
F2 nit, out of scope TestIssue1008_PathHopIndexReadyFalseImmediatelyAfterLoad has the same race class as #227: it asserts "not ready" right after Load(), and the path-hop builder can win. The PR gate covers only the subpath builder. Seen once on master under heavy load: 1 failure in 900 runs. The subpath sibling had 0 in 900. Candidate follow-up issue. [T]
F3 nit store.subpathBuildGate = func() { close(building); <-release } closes building unguarded. That is fine while Load() runs the builder once (it does: one call site, store.go:1158), but a second Load() on the same store would panic on a double close. [K]
F4 note only The #224 commit message misspells the test name ("TestReach Rank_…"). Not fixed here, as instructed.
F5 info gofmt -l lists index_ready_1008.go and index_ready_1008_test.go, but the same files are listed on master. The gofmt -d hunks are at lines 55–72 and 219+ of the .go file and 2–14 of the test. None overlap the PR hunks. reach_rank_test.go and store.go are clean. go vet ./... passes. [T]

No blocking finding.

Answers to points 1–5

1. #224

  • Analysis holds. [T][K]
    • The race report on master, run 64 of 250, names the write at reach_rank_test.go:969 in TestReachRank_RefreshHonoursBackoffAfterQueuedFailure.
    • The previous read is reach_rank.go:311, the hook call inside refreshDegreeSnapshot's singleflight function. That goroutine was created from getDegreeSnapshot (reach_rank.go:254) in a goroutine of TestReachRank_ExpiredSnapshotAlwaysRefreshes (reach_rank_test.go:947). It is a finished reader with no happens-before edge to the write, not an overlapping read.
    • The log of that same run shows degree snapshot rebuild failed: reach rank begin: sql: database is closed. That is the leftover refresh loading after the earlier test's DB was closed, which fits the "leftover flight after cleanup" story.
  • The join removes the cause, including several late refreshes. [T][A]
    • singleflight allows one in-flight call per key. Every DoChan a caller made is registered before the callers return from wg.Wait. At the end of the test there is therefore at most one flight, running or not yet started. The test's DoChan either joins it or starts a new one.
    • A flight that already finished is ordered before the join through the group mutex: its map delete happens before its hook read is observed by the join's lock. That mutex chain is why earlier flights are covered too.
    • I checked this with a scratch-only counter (not part of the PR) in the production function. Under load, 200 iterations of the test showed running > 0 right after the join in 0 of 200. A late flight was present just before the join in about 3 % of iterations: 2 running at sampling, plus 4 that started between sampling and the join. The join covered every one of them.
  • The join cannot hang. [T][A]
    • With no refresh left, the new flight sees the fresh snapshot (TTL 60 s, just published) and returns without touching the hook. This was the common case: 194 of 200 iterations.
    • A flight that does load is bounded by reachDegreeQueryTimeout, and the helper has its own 10 s t.Fatal guard.
  • No production change for reach_rank tests: onDegreeSnapshotLoad written while a previous test's singleflight refresh still reads it (-race flake) #224. The diff of reach_rank.go is empty; the PR touches reach_rank_test.go only. [K]

2. #227

  • Ordering. [K][A]
    • gate := s.subpathBuildGate is read in the goroutine that calls Load(), before the go statement. The test writes the field in the same goroutine before Load(). Nothing writes the field afterwards, so there is no race window.
    • The field is referenced in only four places: the declaration, the read, the call, and the test.
    • A read inside the goroutine would be just as safe in this suite. The pre-go read is the more robust choice.
    • Only Load() calls startBackgroundIndexBuilds. The chunk-loader path uses markIndexesReadySync and never touches the gate.
  • Production cost and behaviour. [K]
    • It is one nil check per Load(), outside request and ingest paths.
    • The ready flags, the 503 and Retry-After handling, and the ready channel are unchanged. The diff adds a field, a read and a conditional call, nothing else.
    • The gate runs before the builder takes s.mu, so a held gate holds no lock.
    • The full suite passes on the merged tree, including the other TestIssue1008_* and distance_lazy_build_149 tests (see Tests).
  • t.Cleanup on assert failure. [T]
    • Mutant: the 503 assertion changed to expect 418. The test fails fast (--- FAIL … 0.04s), and the log then shows [startup] index build complete: subpath. That line means the builder was released and finished, so nothing is stranded and nothing hangs.
    • If Load() fails before the gate is reached, no gate runs and the release is a no-op.

3. Reproduction

My host differs from the author's: macOS arm64 with 10 cores, and other builds running on it. The ambient load was uncontrolled, so I added 16 CPU burner loops for the heavy-load rows. Both load levels always ran alongside three looping full-suite -race binaries of cmd/server. Binaries were compiled once with -race. "PR" means the merged tree and "master" means aff158c7. Variants were interleaved. [T]

Issue Load master PR (merged tree)
#224, separate processes, -count=1 (only the two tests) three full-suite loops, load avg ~11–22 1/250 with DATA RACE 0/250
#224, same + 16 burners, load avg up to ~180 4/150 0/150
#227, -count=300 per round, one process three full-suite loops, no burners, 6 rounds 1/1800 0/1800
#227, same + 16 burners, 3 rounds 12/900 (status = 200, want 503) 0/900

4. Mutants [T]

Mutant Result
#224: PR with the awaitDegreeRefresh call removed (race pattern restored) 6/150 with DATA RACE, same signature as master, under heavy load; master in the same batch had 4/150
#227: production ignores the gate (_ = gate) 20/20 fail: "background subpath index build never started"
#227: PR with the test set back to master's version (no gate) 7/900 status = 200, want 503 under heavy load; 5 in 1800 under lighter load
#227: wrong expected status fails fast and the builder is released (point 2)

5. Rules [K]

  • cmd/server stays read-only: the PR adds no write path. The diff is four files, three of them tests or comments plus one small store.go field.
  • New map[string]interface{} in the diff: 0.
  • Fork guards: deploy.yml 9 and release-fast-path.yml 1 (github.repository == 'Kpa-clawbot/CoreScope'), identical on master and head. No workflow file changed.
  • Closing keywords in the diff, the commit messages, or the PR description: none. (Only the neutral (#224) and (#227) suffixes.)
  • Commit author and committer on both commits: dborup <kontakt@meshview.dk>. The Co-Authored-By trailers are Claude noreply addresses. The reach_rank tests: onDegreeSnapshotLoad written while a previous test's singleflight refresh still reads it (-race flake) #224 commit-message typo is noted in F4.

Tests

  • cd cmd/server && go test -race -count=1 -timeout 20m ./... on the merged tree (aff158c7 + PR head): ok in 387.6 s, exit 0, 0 DATA RACE lines. [T]
  • Master's full-suite binary, looped three ways as load, ended every iteration with exit 0 (5 iterations). [T]

Not verified

  • I did not run the Playwright or Docker CI jobs; I only read the PR report's claim that CI is green. [K]
  • Linux amd64 and a 4-core host: my runs are macOS arm64 only, so the absolute flake rates differ from the author's.
  • The statistical gap for reach_rank tests: onDegreeSnapshotLoad written while a previous test's singleflight refresh still reads it (-race flake) #224 at the lighter load is small (1/250 vs 0/250). A first 100-process batch used a counting script with a bash-3.2 bug (declare -A), so I discarded it and report only the rerun. The mechanism evidence (the counter, the mutant with the same signature, the heavy-load rows) carries the conclusion, not that row alone.
  • I did not audit every other cmd/server test for refresh flights that outlive their test. The full-suite runs (merged tree once, master five times under load) showed none.
  • Go toolchain used here is 1.26.3 while go.mod says 1.22. The CI toolchain was not checked.
  • The awaitDegreeRefresh happens-before argument through the singleflight group mutex is reasoning plus the 0/250 and 0/150 results. I did not read the race detector's model beyond that.

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.

2 participants