flaky: session-persistence GC test races the async audit capture (~25% under load)

[TerrysPOV]

Uncovered while fixing the settings.cache cluster of #304. Filing separately because it is a distinct defect that the crash was masking, and it is not fully resolved.

Symptom

src/__tests__/session-persistence-integration.test.ts → "GC tick drops on-disk expired entries while leaving live in-memory buckets intact" fails intermittently:

650 |       expect(lost).toBeDefined();
error: expect(received).toBeDefined()

Measured rate: 0/12 failures on an idle machine, 2/8 on a busy one. Load-sensitive, not deterministic.

Root cause (partially addressed)

The test drove a GC pass and then sampled the captured audit array with a bare events.find(...):

await plugin._runGCTickForTests();
const gcAudit = events.find((e) => e.event === "mcp_session_gc");
const lost = events.find((e) => e.event === "mcp_session_lost_on_restart" && ...);

Audits reach that array asynchronously — _audit() (src/plugins/mcp-multiplexer/session-persistence.ts:114) calls getMcpBridge().audit(), and the test's capture wrapper pushes on that call. Awaiting the GC tick does not guarantee the audit has landed, so the sample races.

Confirmed by instrumenting: on a failing run the event is eventually present (["mcp_session_lost_on_restart","ttl_expired","pty-stale"]) — the assertion just ran too early.

The rest of the file already uses a polling waitForAudit helper for exactly this reason; the GC assertions were the ones that didn't.

What was done

The #304 cluster-1 PR converts both GC lookups to awaited polling, adding a waitForAuditMatch predicate variant (the existing helper matches on event name only, and lost needs to match on reason + ptyId too).

What remains

That removed a genuine race and reduced the failure rate, but did not eliminate it under load — still ~2/8 with other work running on the machine. The remaining suspicion is the 2000ms polling budget being exceeded under contention, but that is not proven.

Options, roughly in order of preference:

1. Give the GC path a deterministic completion signal — have _runGCTickForTests() resolve only after its audits have been dispatched, so no polling is needed at all. Best fix; removes the timing assumption rather than widening it.
2. Raise the polling budget for this assertion specifically. Cheap, but keeps a wall-clock assumption in a test that will run on shared CI runners.
3. Make the audit capture synchronous in tests.

Why it matters

#304 widens the CI test scope toward the full suite. A test that fails ~25% of the time under load turns CI red at random once this file is in scope, which is exactly the failure mode #304 exists to remove. This should be closed before src/__tests__/ is added to the CI path list.

Related: #304 (test hygiene), #324 (no typecheck step).

[TerrysPOV]

Second instance of the same class, worth tracking here since it is already in CI scope.

src/__tests__/session-manager.test.ts → "session-id collision rotation > gives up after one retry if the collision persists" also fails intermittently under load. Observed just now in a widened-scope run: 1370 pass, 1 fail, that test.

History: #321 raised sessionCollisionDetectMs from 300ms to 2000ms in three tests in that file to address exactly this, and it did help (10/10 in isolation afterwards). But review of #321 flagged — correctly — that the window is not the only race: detectSessionIdCollision (src/bus/session-manager.ts:421-435) also depends on the marker chunk arriving via proc.onData before proc.onExit fires, and no window size fixes that ordering. The #321 comment was softened to say so rather than claim the raise was a complete fix.

Today confirms the raise was not sufficient. Unlike the GC test in this issue, this one is already inside the CI test path list (src/bus), so it can turn CI red on main at random today.

Same remedy shape as option 1 above: give the detector a deterministic completion signal instead of racing a wall-clock bound.

[TerrysPOV]

Update from the #304 cluster-1 work — the audit race was not the residual cause. Recording the negative result so the next person does not re-run it.

What I did beyond the original fix: converted every positive events.find(...) in the file to awaited polling, not just the two GC ones — old lines 449, 508, 562, 571. Only one bare find remains, the negative assertion at what is now line 533, and it is documented as sound because the awaited lookup above it is emitted by the same load pass.

Result: flake rate unchanged. 2/8 before, 3/8 after.

But the failure moved:

before:  error: expect(received).toBeDefined()     <- the audit-timing race
after:   error: expect(received).toBe(expected)    <- something else

So the race I identified was real and is now closed; a second, independent defect sits underneath it in the same test (runtime GC > GC tick drops on-disk expired entries...). The surviving toBe assertions are the GC counts (scanned 2 / kept 1 / dropped 1) and the surviving-entry check (entries[0].ptyId === "pty-live").

Ruled out, checked rather than assumed:

• Background GC timer racing the manual tick — no. That test sets gcTickMs: 0 ("manual drive"), as do all 8 construction sites in the file.
• Audit dispatch timing — no, per the above.

Remaining suspicion, unverified: a race between the test's writeFileSync of the stale entry and the GC pass reading it, which would make scanned 1 instead of 2. That would fit a toBe failure and would be untouched by anything done so far. Someone should capture the actual received-vs-expected values before acting — I did not, and guessing twice already cost me.

Option 1 from the issue body (give _runGCTickForTests() a deterministic completion signal) still looks right, and would likely cover both mechanisms.

The file remains out of the CI path list for this reason.

[TerrysPOV]

Correction: the diagnosis in this issue's body is WRONG. Retracting it.

A review pass disproved the stated mechanism, and I verified all of it against source before writing this. The audit chain is fully synchronous — there is no race to fix.

• _audit (src/plugins/mcp-multiplexer/session-persistence.ts:114) is a one-line direct call: getMcpBridge().audit(event, payload);
• the test's own capture wrapper pushes synchronously: bridge.audit = (event, payload) => { events.push(...); orig(...); }
• garbageCollect() emits mcp_session_gc before its promise resolves, and mcp_session_lost_on_restart inside the loadAll() it awaits

By the time the awaited call returns, both events are already in events. A bare events.find(...) after it cannot race.

That also explains the negative result I posted earlier: converting every lookup to awaited polling left the flake rate unchanged (2/8 → 3/8) because there was never a race to remove. I built a waitForAuditMatch helper on an unverified mechanism; it has been reverted from the #304 cluster-1 PR, which now contains only the fixture consolidation.

The actual failure

The reviewer captured the received value I failed to:

(fail) runtime GC > GC tick drops on-disk expired entries...
  at session-persistence-integration.test.ts:665   Received: 1

Line 665 is expect(gcAudit?.payload.scanned).toBe(2). Note what this means:

• waitForAudit returned without timing out, and toBeDefined() passed — the audit was present and on time
• the sanity check expect(before?.entries).toHaveLength(2) passed immediately before the tick — 2 entries were genuinely on disk
• yet GC reported scanned: 1

So it is a wrong payload, not a missing event: something rewrites alpha.json between the test's manual writeFileSync of the stale entry and the GC pass reading it. A file/GC state race, not an audit-delivery race. Polling can never fix this — a poll that finds the event returns instantly with the wrong payload.

Revised remedy

Option 1 from the original body (give _runGCTickForTests() a deterministic completion signal) may still help, but the investigation should start from who else writes alpha.json during that window — likely the live pty-live session's own record()/touch() path, whose write could land between the append and the tick and clobber the manual entry.

Ruled out and verified: background GC timer (gcTickMs: 0 at all 8 construction sites in the file), and audit-delivery timing (above).

The title of this issue is also now inaccurate — it says "races the async audit capture". Happy to rename it if that helps whoever picks it up.

[TerrysPOV]

Third instance, and the second already inside CI scope.

Observed during #304 cluster-2 gate runs:

(fail) BusCore IPC > re-delivers an immediately-delivered prompt when the IPC send failed (MCP-blip wedge, #252)
 1377 pass  1 fail

src/bus/__tests__/core.test.ts. Evidence it is load-sensitivity and not the cluster-2 change:

• that branch touches only src/event-processor.ts, its test, .github/workflows/test.yml, and the two version files — no src/bus file (git diff --name-only)
• the file passes 6/6 in isolation
• it failed once in a 1378-test run with heavy parallel work on the machine

Running tally of load-sensitive tests found while working #304:

test	file	in CI scope?
session-id collision rotation > gives up after one retry…	src/__tests__/session-manager.test.ts	yes (src/bus… no — root suite, but reached via the gate's wider TEST_ARGS)
BusCore IPC > re-delivers an immediately-delivered prompt…	src/bus/__tests__/core.test.ts	yes
runtime GC > GC tick drops on-disk expired entries…	src/__tests__/session-persistence-integration.test.ts	no (held back deliberately)
MemorySubject — Pass B: perf > …50K-line index reads in <500ms	src/tuner/__tests__/…/memory-subject.test.ts	yes

Two of the four are already in the CI path list. That is the live risk: CI on main can go red at random today, and the natural reading of a red run is "the PR broke it".

Common shape across all four: an assertion whose truth depends on wall-clock timing or on work completing within an unstated window, which holds on an idle machine and not on a busy one. The memory-subject one is explicit about it (expect(elapsed).toBeLessThan(1500)); the others are implicit.

Suggests this issue is really about a class, not the single GC test its title names. Renaming it to something like "load-sensitive tests: assertions that depend on wall-clock timing" would match the evidence better — happy to do that, or split per-test, whichever is easier to action.

[TerrysPOV]

Major correction: most of my evidence was contaminated by my own runaway processes

I have to retract most of what I reported on this issue.

What happened

While reviewing #328, a spawned review agent wrote a load generator to test a flake hypothesis:

for i in $(seq 1 8); do (while :; do :; done) & done
... 10x bun test ...
kill $LOADPIDS      # success path only, no trap

The test loop never completed, so the cleanup never fired. Eight orphaned shells spun at ~217% CPU on an 8-core machine for 3h20m, from 11:28 onward. I accepted that agent's "10 runs under CPU load" finding without asking how it produced the load or whether it cleaned up. They are now killed.

Most of the flake evidence in this thread was gathered while those were running.

Re-measured on a quiet machine, 10 runs each

test	quiet result
src/bus/__tests__/core.test.ts (BusCore IPC #252)	0/10 failed
src/__tests__/session-manager.test.ts (session-id collision)	0/10 failed
src/tuner/.../memory-subject.test.ts (perf bound)	0/10 failed
src/__tests__/session-persistence-integration.test.ts (GC)	4/10 failed

What this means

Three of the four "load-sensitive tests" I catalogued here do not reproduce at all. The comment above listing four instances of a shared class is wrong, and the framing that this issue represents a class of wall-clock-dependent assertions is not supported by clean data. Retracted.

Caveat I cannot fully separate: session-manager.test.ts had its sessionCollisionDetectMs raised 300 -> 2000 in #321, so its 0/10 may reflect that fix working rather than the earlier failures being pure artifact. The other two had no such change, so for those the artifact explanation is the only one standing.

Knock-on: in #329 I scoped the tests-passing gate to PR-touched paths, justifying it by "the CI line is already non-deterministically red". On this evidence that justification was largely wrong — the line was red because of my processes. The scoping decision itself still matches project guidance, but the stated reason does not hold.

What is actually real

session-persistence-integration.test.ts — 4/10 on a quiet machine, worse than the 2/8 I originally reported. This is a genuine defect, not load sensitivity, and it is the only thing this issue should track.

Confirmed diagnosis stands from the earlier correction: the failure is expect(gcAudit?.payload.scanned).toBe(2) receiving 1, with the audit present and on time and 2 entries verifiably on disk one line earlier. A file/GC state race, not audit delivery.

Investigating that now. Suggest this issue be retitled to name that single test rather than a class.

[TerrysPOV]

Measured properly on a quiet machine — worse than reported, and localised

Follow-up to the retraction above. All numbers below are from a machine with no artificial load, my orphaned processes killed, load stable across each sample.

Failure rate

12/20 (60%) — not the 2/8 (~25%) I originally reported. Two independent samples: 4/10, then 8/20. An 8/8 clean streak in between was luck, not conditions.

All failures are in ONE test, at three assertions

Tabulated over 20 runs:

count	line	assertion
8	:635	expect(gcAudit?.payload.scanned).toBe(2)
3	:646	expect(lost).toBeDefined()
1	:627	expect(before?.entries).toHaveLength(2)

All in runtime GC > GC tick drops on-disk expired entries while leaving live in-memory buckets intact.

The :627 failure is the key one

Line 627 is the sanity check before the GC tick runs at all:

writeFileSync(join(persistRoot, "alpha.json"), JSON.stringify({ ..., entries: [liveEntry, stale] }));

// Sanity: file now has 2 entries.
const before = readPersistenceFile(persistRoot, "alpha");
expect(before?.entries).toHaveLength(2);   // <- fails

The test writes the file synchronously and immediately reads back fewer than 2 entries. So the file is already wrong before GC is involved — this is a write race, not a GC defect. The :635 and :646 failures are the same cause observed later (GC scans the clobbered file, so scanned is 1 and no ttl_expired audit fires for pty-stale).

That supersedes the "file/GC state race" phrasing in my earlier comment: the clobber happens between the test's writeFileSync and its own read-back.

Ruled out, verified by reading source

SessionPersistenceStore.record() awaits this._mutate(...) (session-persistence.ts:192) before emitting mcp_session_persisted (:198). So the persist write is durable by the time the test's waitForAudit returns — the persist path is not the racer. My earlier guess that it was is wrong.

What is still unknown

Which writer clobbers the file. SessionPersistenceStore has a per-server write queue (writeQueue, :154) and three mutating methods — record (:173), drop (:207), touch (:232). The test awaits only the record audit. A touch or drop queued by the tool call or the transport close, not awaited by the test, is the obvious candidate but I have not confirmed it: I could not catch the 5% :627 case under instrumentation in 30 runs.

Suggested next step

Have the test await store quiescence before its manual writeFileSync — e.g. expose a test-only "drain the write queue" hook — rather than awaiting a single audit. That addresses all three assertion failures at once, because they share the clobber as root cause.

Retitling suggestion stands: this is one broken test, not a class.

[TerrysPOV]

Small correction to my own correction — session-id collision rotation IS load-sensitive

My retraction above said this test was 0/10 on a quiet machine and therefore an artifact. That was measured at load ~5. It has since failed again during a full-scope run at load ~13.

More precise picture:

condition	gives up after one retry if the collision persists
load ~5 (idle)	0/10 fail
load ~13 (normal parallel work)	fails intermittently
load 217% artificial CPU (my orphaned processes)	failed frequently

So it is genuinely load-sensitive — my artificial load exaggerated the rate but did not invent the behaviour. I over-corrected in saying it did not reproduce; the honest statement is that it reproduces above some load threshold between 5 and 13.

The mechanism previously identified in #321 review still stands as the likely cause: detectSessionIdCollision depends on the marker chunk arriving via proc.onData before proc.onExit fires (src/bus/session-manager.ts:421-435), and no window size fixes that ordering. Raising sessionCollisionDetectMs 300 -> 2000 in #321 reduced but did not eliminate it, exactly as that review predicted.

This one IS already inside the CI path list (src/bus), so it can redden main. BusCore IPC #252 and the memory-subject perf bound remain retracted — those were 0/10 and I have not seen them since.