Skip to content

fix(checkpoint): book the writer's real outcome when the wait bound expires - #1945

Open
wqymi wants to merge 2 commits into
mainfrom
fix/checkpoint-writer-timeout-followup
Open

fix(checkpoint): book the writer's real outcome when the wait bound expires#1945
wqymi wants to merge 2 commits into
mainfrom
fix/checkpoint-writer-timeout-followup

Conversation

@wqymi

@wqymi wqymi commented Jul 27, 2026

Copy link
Copy Markdown
Collaborator

Follow-up to #1938 (merged). That PR's core fix is correct and is not changed here: waitForWriter still returns a distinct "timeout" when its 300s bound expires with the writer still in flight, and prune's result !== "failure" guard still skips the failure counter. This PR closes two holes that fix left behind.

1. Hitting the bound was completely silent

waitForWriter returned "timeout" with no log, and prune's watcher returned with no log. On main-before-#1938 the operator at least saw checkpoint writer failed — cleared thresholds for retry at +300s — in fact that log line is the entire evidence base #1938 was diagnosed from. After #1938, a writer stuck past 5 minutes produced no record at all.

waitForWriter now logs checkpoint writer wait bound expired — writer still in flight with sessionID and boundMs.

2. The writer's real outcome was booked nowhere

prune's watcher fiber is the only holder of the per-fire accounting, and writerFailures (prune.ts:177) is closure-private to the prune layer, so the checkpoint settle watcher cannot reach it. Once the watcher returned on "timeout" and never re-awaited:

  • a writer that genuinely FAILS past 300s ticked no counter anywhere. MAX_WRITER_FAILURES became unreachable for exactly the slow regime fix(checkpoint): don't count a timed-out writer wait as a writer failure #1938 is about — and fix(checkpoint): don't count a timed-out writer wait as a writer failure #1938's own notes document ~13 sequential LLM round-trips at 20-25s each, so a late failure is the realistic case, not a corner. A permanently-broken-but-slow writer was retried forever with no give-up warning.
  • a post-timeout SUCCESS never cleared the counter. writerFailures is only cleared on an observed success, and resetThresholds does not clear it, so two earlier fast failures left it frozen at 2 and any later fast failure tripped "gave up" for a session whose writers demonstrably work.

The watcher now extends its wait across bound expiries and accounts for the settled result, capped at MAX_WRITER_WAIT_EXTENSIONS (12 × 5min ≈ 1h) so a writer that never settles cannot pin the fiber for the life of the process.

Why extend the wait rather than subscribe to WriterCachePerf

Wiring prune to the WriterCachePerf event (checkpoint.ts:955-961, which already carries status: completed | failed) was the first candidate — it is the only existing cross-layer signal of the writer's real outcome. Rejected as materially riskier for the value:

  • Bus PubSub is InstanceState-scoped (bus/index.ts:107-114, 159-161), so a layer-level subscription in prune's layer would be built outside any Instance context. Subscribing per-fire inside the instance context instead means a subscription lifecycle per checkpoint trigger.
  • subscribe is lazy (Stream.unwrap) and races immediate publishes — history/writer.ts:40-42 documents exactly this hazard — so a correct version has to subscribe before the wait and hand the payload across via a Deferred, plus dedupe against the watcher's own observation for a writer that settles inside the bound.
  • It would add Bus.Service to prune's public layer signature (~25 provider call sites).

Re-entering waitForWriter re-awaits a Deferred we already have a handle to: no new dependency, no new state, no new event plumbing. Two microsecond-wide re-entry windows are documented in the code rather than papered over — (1) the writer settles between our expiry and the re-entry, so the map entry is gone and we get "no-writer" and book nothing (identical to the pre-existing fast-writer race already documented at prune.ts:302-315); (2) a queued writer was drained into a fresh entry in that window, so we book its outcome — still a real outcome for that session.

Tests

prune.test.ts gains the two cases that pin the prune-side consequence #1938 is actually about. #1938's test only asserted waitForWriter's return value, but its thesis is "the failure counter must not tick" — which lives in prune. Both reuse the existing makeRetryHarness:

  • timeouts never tick the counter, and a late success clears itfailure, failure, timeout, timeout, success then a re-cross with three more failures. Reads 6 enqueues; would read 5 if a post-timeout success did not clear the counter.
  • a late failure is still counted, so the cap stays reachabletimeout, failure × 3. Reads 3 enqueues then stops at the cap; would read 1 if the watcher still gave up at the bound (thresholds never cleared → fire 2 never enqueues).

The waitForWriter timeout test is tightened: it now pins the bound (still pending at 4 minutes, so shrinking 300s to 1s — reintroducing the bug in a new shape — fails) and asserts isWriterRunning is still true after the expiry, which is the property that makes "timeout" honest rather than a renamed failure. That replaces expect(result).not.toBe("failure"), which was dead — implied by the toBe("timeout") on the line above.

Verification

bun typecheck → exit 0 (12/12 tasks).

Scoped run (bun test --timeout 120000) of prune, checkpoint-writer-wait-timeout, checkpoint-drain19 pass / 0 fail (77 expects), against a pristine baseline of the identical command at this branch point → 15 pass / 0 fail (61 expects; the delta is the 4 new cases below). Only these three suites were run on purpose: a live-model suite was running concurrently on the same box, and concurrent full runs starve each other badly enough to make pass counts meaningless.

Two claims in this PR were previously asserted from reading the code only. Both are now closed.

1. The late-arriving writer outcome — PROVEN (deterministic, TestClock)

checkpoint-writer-wait-timeout.test.ts gains two cases that drive the real service: a writer is left in flight past the 5-minute bound (caller gets "timeout", isWriterRunning still true), the wait is then re-entered exactly as prune.ts:338-349 does, and only then does the writer settle. A late success reports "success" and a late failure reports "failure".

The witness is waitForWriter's own return on the re-entered wait — which is the only surface prune ever learns the outcome from, so it is the right one. Mechanism, now pinned rather than assumed: prune re-enters at bound expiry, i.e. while the writer is by definition unsettled, so the writers-map entry is still present and the fiber parks on the same Deferred. Because it is already parked when the writer settles, the settle watcher's later writers.delete (checkpoint.ts:939) cannot strip the outcome from it. A fresh call after settlement would return "no-writer" — so this witness exists only for an already-blocked re-entry, which is precisely the shape prune uses.

What is still NOT directly observable, stated honestly:

  • writerFailures is closure-private to the prune layer. It is covered only through its consequence — booking a failure clears crossed, so the next fire re-enqueues (enqueueCount). That consequence is public and is pinned in both directions, but nothing reads the counter itself.
  • No single test spans both layers. The prune cases stub waitForWriter; the new checkpoint cases drive the real one. That prune calls waitForWriter in the extension loop is still established by reading the code, not by one integrated test. Closing that would need a real 5-minute writer or a timeoutMs parameter on waitForWriter (the bound is currently the hardcoded Effect.timeout(300_000)), and neither was judged worth it here.

2. The ~1-hour cap — it exists, and its boundary is now tested

MAX_WRITER_WAIT_EXTENSIONS = 12 at prune.ts:32. It is easy to miss: it lives in prune.ts rather than checkpoint.ts, and is expressed as a count of 300_000 ms extensions — the strings 60 * 60, 3600 and HOUR appear nowhere near it. It is not config-overridable (unlike max_writer_failures). The loop makes one initial call plus at most 12 re-entries, so 13 waitForWriter calls ≈ 65 min.

Both sides of that boundary are now pinned in prune.test.ts, and the stub's leftover queue length counts the calls exactly:

  • 12 extensions, still inside the cap — 12 × timeout then failure: the queue drains to 0 (the 13th call happened) and the failure is booked, so the next fire enqueues (2, not 1).
  • the 13th extension, past the cap — 13 × timeout then failure: the trailing failure is still queued (never reached), nothing is booked, crossed stays set, and the next fire does not enqueue.

Revert probes (each restored afterwards; git diff --name-only src/ → 0 files)

probe result
waitForWriter expiry mapping "timeout""failure" (i.e. undo this PR's core change) checkpoint-writer-wait-timeout 0 pass / 3 fail, all Expected: "timeout" / Received: "failure"
settled mapping status === "success" ? … : "failure" → always "failure" 2 pass / 1 failonly the new late-success case dies (Expected: "success" / Received: "failure"), so it is load-bearing and not implied by the pre-existing test
MAX_WRITER_WAIT_EXTENSIONS 12 → 11 prune 11 pass / 2 fail (Expected: 0 / Received: 1 and Expected: 1 / Received: 2)
MAX_WRITER_WAIT_EXTENSIONS 12 → 13 prune 12 pass / 1 fail (Expected: 1 / Received: 0)

The last two bracket the constant from both sides, so moving it by one in either direction fails a test.

Also

  • Folds fix(checkpoint): don't count a timed-out writer wait as a writer failure #1938's now-stale waitForWriter comment (the 5-min padding is no longer what prevents misclassification — the distinct return value is, and the AgentOutcome → WriterOutcome table was missing timeout) into the current block.
  • checkpoint-align.ts's claim that a degenerate-session LLM rejection increments writerFailures "via the existing path" is now only conditionally true; corrected to state when it is and is not booked.

Deliberately not included

computeBoundary coverage pinning (checkpoint.ts:254-293) — it changes what a checkpoint covers and is a separate, riskier decision.

…xpires

Follow-up to #1938. That PR stopped a merely-slow writer from being booked as
a failure by returning a distinct "timeout" from waitForWriter, which prune's
`result !== "failure"` guard skips. Correct, but it left two holes.

1. Hitting the bound became completely silent. waitForWriter returned and
prune's watcher returned, neither logging — yet the +300s log line is exactly
the evidence #1938 was diagnosed from. waitForWriter now logs
"checkpoint writer wait bound expired — writer still in flight".

2. The real outcome was booked nowhere. prune's watcher fiber is the only
holder of the per-fire accounting and writerFailures is private to the prune
layer, so once the watcher returned on "timeout" a writer that genuinely
FAILED past 300s ticked no counter — making MAX_WRITER_FAILURES unreachable
for exactly the slow regime #1938 is about, so a permanently-broken-but-slow
writer retried forever with no give-up warning. Symmetrically, a writer that
SUCCEEDED past 300s never cleared a counter left at 1-2 by earlier fast
failures, so a later fast failure could trip "gave up" for a session whose
writers demonstrably work.

The watcher now extends its wait across bound expiries and accounts for the
settled result, capped at MAX_WRITER_WAIT_EXTENSIONS (~1h) so a writer that
never settles cannot pin the fiber for the life of the process. Two
microsecond-wide re-entry windows are documented rather than papered over.

Tests: prune.test.ts gains the two cases that pin the prune-side consequence
#1938 is actually about (timeouts never tick the counter and a late success
clears it; a late failure is still counted so the cap stays reachable) — the
existing test only asserted waitForWriter's return value. The timeout test now
also pins the BOUND (still pending at 4 minutes, so shrinking it to 1s fails)
and asserts the writer is still running after the expiry, replacing a dead
`not.toBe("failure")` implied by the line above it.

Also folds the stale 5-min-padding comment into the current block and corrects
checkpoint-align.ts's now-conditional claim about writerFailures.
…ion cap

The bounded wait's late-outcome contract and MAX_WRITER_WAIT_EXTENSIONS were
both asserted only by reading the code. Two gaps are now covered:

- waitForWriter: a writer that settles AFTER the 5-minute bound reports its
  REAL outcome (success / failure) to the re-entered wait, which is the
  only surface prune learns it from. Driven on TestClock against the real
  service, so the seam the prune-side stubs assume is now exercised.
- prune: the extension cap is a boundary, so both sides of it are pinned —
  12 extensions still books the writer's outcome, a 13th abandons the wait.
  The stub's leftover queue counts the waitForWriter calls exactly, so moving
  the constant by one fails a test.
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