Skip to content

test(parse-pool): wait for the idle fault to land, not for 120ms - #651

Open
josephismikhail wants to merge 4 commits into
mainfrom
fix/parse-pool-idle-fault-flake
Open

test(parse-pool): wait for the idle fault to land, not for 120ms#651
josephismikhail wants to merge 4 commits into
mainfrom
fix/parse-pool-idle-fault-flake

Conversation

@josephismikhail

Copy link
Copy Markdown
Contributor

What

takes a worker that faults while IDLE out of the free list is load-flaky. It failed a full-suite run on a busy machine with b2.ts returning nullindistinguishable from the Ix#567 bug it guards, which is the worst way for a flake to present: whoever sees it red next has no reason to suspect the harness.

Reproduction

The fixture throws 20ms after serving the first task; the test slept a flat 120ms waiting for the 'error' event before dispatching two parses.

condition result
idle 0 of 10 runs failed
saturating CPU load 1 of 8 runs failed

Under load the event had not been delivered, so the second parse reached an already-dying worker and resolved null.

Fix

Wait on the condition, not a duration. onError increments respawns and pushes the replacement in the same synchronous handler, so a non-zero count means the pool has finished reacting — including to a fault with no task in flight, which crashedTasks() deliberately does not count because no file was lost.

That distinction is precisely why there was nothing to wait on, and why this adds respawnCount() rather than reusing a counter. It earns its place outside the test as well: a run that quietly respawned a dozen workers looks identical to a healthy one in every other counter the pool exposes.

What I am not claiming

Post-fix loaded runs were 0 of 8. That is not strong evidence — under the observed 1-in-8 rate, zero in eight happens 34% of the time. The argument is structural: the test no longer depends on an event arriving inside a fixed window, so the failure mode is removed rather than made less likely. It also returns as soon as the condition holds, so it is faster than the sleep it replaces.

The test still catches the bug

With the idle.splice in onError deleted — Ix#567 restored — the test fails, hanging until the 20s timeout, which is the "promise never settles" symptom exactly. The poll signal increments after that splice, so it does not depend on the fix being present and cannot mask its absence.

The other five fixed sleeps in this file wait for a parse to be dispatched rather than for an error to be delivered, and none has been observed to fail. Left alone rather than rewritten on speculation.

Verification

  • 13 pool tests pass; full suite 1791 (3 known Windows symlink failures, unrelated, pass on CI's windows-2022)
  • typecheck and lint clean
  • mutation-tested as above

🤖 Generated with Claude Code

https://claude.ai/code/session_01B5bkc5oUL4SapwDE13UgHt

Found by running the full suite on a loaded machine: `takes a worker that
faults while IDLE out of the free list` failed with `b2.ts` coming back null.
That is indistinguishable from the bug the test guards (Ix#567), which is the
worst way for a flake to present -- the next person to see it red has no
reason to suspect the harness.

It is the wait. The fixture throws 20ms after serving the first task, and the
test slept a flat 120ms for the 'error' to be delivered before dispatching
two parses. Measured:

  idle    0 of 10 runs failed
  loaded  1 of 8  runs failed   (saturating CPU load)

Under load the event had not arrived, so the second parse reached a worker
that was already dying and resolved null.

The fix waits on the condition instead of a duration. `onError` increments
`respawns` and pushes the replacement in the same synchronous handler, so a
non-zero count means the pool has finished reacting -- including to a fault
with no task in flight, which `crashedTasks()` deliberately does not count
because no file was lost. That distinction is why there was nothing to wait
on, and why this adds `respawnCount()` rather than reusing an existing
counter. It earns its place outside the test too: a run that quietly
respawned a dozen workers is identical to a healthy one in every other
counter the pool exposes.

Two things worth stating precisely, because a weaker claim is the honest one:

The post-fix loaded runs were 0 of 8. That is NOT strong evidence on its own
-- under the observed 1-in-8 rate, zero in eight happens 34% of the time. The
argument is structural: the test no longer depends on an event arriving
inside a fixed window, so the failure mode is removed rather than made less
likely. It returns as soon as the condition holds, so it is also faster than
the sleep it replaces on an idle machine.

And the test still catches what it was written for. With the `idle.splice`
in `onError` deleted -- the Ix#567 bug restored -- it fails, hanging until the
20s timeout, which is the "promise never settles" symptom exactly. The poll
signal is incremented AFTER that splice, so it does not depend on the fix
being present and cannot mask its absence.

The other five fixed sleeps in this file wait for a parse to be dispatched
rather than for an error to be delivered, and none has been observed to fail;
they are left alone rather than rewritten on speculation.

13 pool tests pass; full suite 1791; typecheck and lint clean.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01B5bkc5oUL4SapwDE13UgHt
@josephismikhail

Copy link
Copy Markdown
Contributor Author

Now reproduced on CI, not just locally

Test (windows-2022 · node 22) on PR #649 (4d8046b) failed with exactly this:

AssertionError: expected [ { filePath: 'a2.ts' }, null ] to deeply equal [ { filePath: 'a2.ts' }, …(1) ]
-   { "filePath": "b2.ts" },
+   null,
 ❯ src/cli/__tests__/parse-pool.test.ts:137:18

run 34179642182 — same test, same assertion, same line.

#649 does not touch parse-pool.test.ts. Its diff is ingest-files.test.ts, ingestion-loader.test.ts, ingestion-loader.ts. So this is not that PR's regression — it is this flake, and the windows-2022 runner is loaded enough to hit it.

That upgrades the evidence here in two ways:

  1. The failure mode is real on CI, not an artifact of my synthetic load. A green history simply means the runner usually delivers the 'error' inside 120ms.
  2. It manifests as b2.ts → null, which is the Ix#567 signature. Anyone triaging that red on an unrelated PR would start by suspecting their own change, which is the cost this fix removes.

Merging this first would clear #649's red without touching #649.

josephismikhail and others added 3 commits September 7, 2026 20:05
…ing monotonic

Review of #651 found the fix was half a fix, and that the counter it added
did not mean what its own doc said.

The counter first. `respawnCount()` returned `respawns`, which `onResult`
sets to zero on EVERY successful round trip -- deliberately, since the cap is
a budget against a worker dying deterministically, not a lifetime quota. So
it is a streak, not a tally: a run that lost a dozen workers, each
replacement then parsing a file, ends reporting zero. The doc I wrote claimed
the opposite ("a run that quietly respawned a dozen workers looks identical
to a healthy one in every other counter") and would have been read as a
diagnostic that is silently blind. There is now a separate `respawnsTotal`
that nothing resets, and `respawnCount()` returns that; `respawns` keeps its
budget role and says so.

That also mattered for the wait. Polling a value any completed parse resets
is edge-triggered state read as a level -- safe in this test only because the
pool is quiescent, and a trap for the next person who copies the pattern.

The second half of the race is the bigger one. `IDLE_FAULT` counted with a
per-thread `let served = 0`, so the REPLACEMENT armed its own fault 20ms
after serving `a2.ts` -- and `b2.ts` is posted only once the parent has
received a2's result and re-drained. Miss that 20ms window on a busy machine
and the replacement dies with `b2.ts` in flight, which `onError` resolves to
null. Same `b2.ts === null` signature, same test, from the harness rather
than the pool. Waiting properly for the FIRST fault did nothing about it, so
the previous claim that the failure mode was "removed rather than made less
likely" was true of one window and not the other.

The fixture now arms at most once per pool, claiming a marker file before
scheduling the throw so a thread starting while the timer is pending sees it
taken. A file because the arming has to be visible across threads, which
share nothing else here.

And the test pins it: `respawnCount()` must be exactly 1 at the end. A
replacement that armed its own fault would make it 2, so the once-per-pool
contract is asserted rather than assumed.

Evidence, and it is stronger than last time:

  loaded, before the fix   1 of 8 failed
  loaded, both fixes       0 of 20 failed

0 of 20 is not proof either -- under the observed 1-in-8 rate it happens
about 7% of the time -- but it is no longer the 34% that 0 of 8 was. The
structural argument is what carries it, and it now covers both windows
rather than one.

The test still fails against Ix#567 restored, re-verified after the fixture
change: deleting the `idle.splice` in `onError` hangs it to the 20s timeout.

13 pool tests; full suite 1791; typecheck and lint clean.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01B5bkc5oUL4SapwDE13UgHt
…eck pinned nothing

Second review round on #651, and the medium is one I earned: last round I
added `expect(pool.respawnCount()).toBe(1)` and wrote in the commit message
that it "asserted rather than assumed" the once-per-pool contract. It does
not. The replacement's fault is a 20ms timer armed when it serves `a2.ts`,
and a2 -> b2 -> `Promise.all` -> the assertion all finish in a few
milliseconds, so the timer has not fired and the count still reads 1. The
reviewer reverted the fixture to per-thread arming and the assertion passed
5 runs out of 5.

Which is the same mistake as the thing being fixed: I asserted a guard was
load-bearing without restoring the bug to see it fire.

The fix is to assert on what is synchronous. Arming happens in the same tick
as the serve; only the throw is delayed. The fixture now appends its
`threadId` to the marker as it arms, and the test reads that file back and
requires exactly one line. A replacement that armed its own fault appends a
second line immediately, with no timer to wait for.

Mutation-tested this time, in both directions the regression can take:

  (a) guard dropped, every worker arms      failed 3 of 3
  (b) reverted to per-thread arming         failed 3 of 3

The `respawnCount()` check is kept but demoted in the comment to what it
actually is -- a cheap check that no extra worker died during the two
parses -- and is no longer presented as the guard.

Three smaller corrections:

`respawns`'s new doc said "Remaining respawn BUDGET", which inverts it:
`onError` increments toward `MAX_RESPAWNS`, so the field is what has been
CONSUMED since the last success -- 0 is a full budget, 16 is exhausted.
Anyone writing `if (this.respawns > 0)` for headroom from that description
gets the cap backwards.

The `respawnCount()` doc cited a `windows-2022` failure. That observation is
real -- Actions run 34179642182 took down `Test (windows-2022 - node 22)` on
an unrelated PR at `parse-pool.test.ts:137` -- but it was recorded only in a
PR comment, which does not survive into the repo, and the sentence let it
read as a second measurement of the 1-in-8 rate. The run is cited in the
source now, and it is labelled as the single observation it is.

And a stale one-line doc was left stacked above the new fixture's JSDoc,
still describing the per-thread behaviour that was just removed.

13 pool tests; full suite 1791; typecheck and lint clean. Ix#567 restored
still hangs the test to its timeout.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01B5bkc5oUL4SapwDE13UgHt
… passing the check

Third review round on #651. Three findings, all low, no medium -- and one of
them is a residual race this PR had claimed more credit for closing than it
had earned.

The fixture replies to `first.ts` and then throws on a timer. 'message' and
'error' reach the parent on different channels, so a parent descheduled
across both can take the 'error' first, find `first.ts` still in `active` and
resolve it null -- failing that assertion with the same signature this test
exists to distinguish from Ix#567. At 20ms the margin was the same order as
the scheduling delays that caused the original flake in the first place. It
is 250ms now.

Being exact about what that is and is not: it does NOT remove the ordering
dependency. It cannot. The worker has no way to learn that its reply was
consumed, and a fault raised while a task IS in flight never leaves a stale
entry in `idle` -- which is the entire bug. So the premise requires an idle
fault, an idle fault requires a delay, and the delay can only be made
implausible to miss rather than impossible. The comment says that rather than
implying the window is gone.

Second: `readFileSync(...).trim().split("\n")` returns `[""]` for an empty
file, so ZERO armings satisfied `toHaveLength(1)`. The marker assertion is
the load-bearing contract check from last round, and it would have gone inert
the moment anyone pre-created the marker -- which is the obvious fix for its
ENOENT path, so this was a trap laid for the next person. `.filter(Boolean)`
now, with the reason recorded.

Third: `respawnCount()`'s doc had grown to twenty lines of incident forensics
in production source -- a local failure rate, an Actions run id, and
`parse-pool.test.ts:137`, a line number this very PR moves. It keeps the
mechanism, which is what a reader of the pool needs: why it is not
`respawns`, and that it is a level rather than an edge. The forensics live in
the PR body, which already has them.

All three mutations re-run after these edits:

  guard dropped, every worker arms       failed 3 of 3
  reverted to per-thread arming          failed 3 of 3
  Ix#567 restored (`idle.splice` gone)   fails

The last one now fails with an assertion naming `b2.ts` instead of hanging to
the 20s timeout, which is a better failure as well as a faster one.

13 pool tests; full suite 1791; typecheck and lint clean.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01B5bkc5oUL4SapwDE13UgHt
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.

1 participant