fix(subagent): credit provider-paused time against the wall-clock ceiling - #797
Merged
Conversation
…ling A fork parked by a provider-imposed pause longer than its wall-clock budget was GUARANTEED to die, no matter what the caller did. On 2026-07-31 a /forge run lost 1h49m of work this way: the provider parked the account at 01:16:47Z (HTTP 429, retryAfterMs 6792000, resetsAt 03:10:00Z — a ~113 min pause), the child forked at 02:26:21.307Z inheriting SUBAGENT_DEFAULT_TIMEOUT_MS, and it died at 03:11:21.307Z — exactly dispatch + 2,700,000 ms, 81 seconds AFTER the pause reset. It had spent 43m38s of its 45-minute budget parked and got ~81 seconds of actual working time. The idle watchdog did NOT fire at its 8-minute window, which proves the runtime recognized the pause and correctly extended the idle deadline. The wall clock ignored the very same signal and killed the child anyway. Callers cannot pre-compute a safe timeoutMs because the pause window is unknowable at dispatch; the only escape was timeoutMs: 0 (fully unbounded), which is worse. WHY THIS REVISES A SHIPPED DECISION .afk/plans/subagent-idle-watchdog.md:88 locked the wall-clock as the "un-resettable ceiling", and #672 deliberately built pause-awareness into IdleWatchdog alone so it would NOT touch withTimeout. This is a deliberate revision of that decision, not a gap-fill. It honors the PURPOSE of the invariant — a fork's lifetime must have a guaranteed finite, predictable upper bound — rather than its letter, which made "bound the child's WORKING time" inexpressible. The budget now bounds working time: effective ceiling = timeoutMs + min(provider-parked time, cap) Crediting parked time (rather than asking "is a pause in effect right now?") is load-bearing: in the incident the park ended 81s BEFORE the deadline, so a right-now check grants nothing and the child still dies. Properties preserved: - Only provider-reported pause signals (`paused` w/ resetsAt, `rate_limit` w/ retryAfterMs) grant credit — the same events IdleWatchdog consumes. Child content, tokens, thinking, and tool activity NEVER extend the ceiling, so it remains un-resettable by the child: it cannot author the only moving signal. - Each grant is bounded by the provider's own reported window, never open-ended; an unresumed park stops accruing at its stated end. - Total accumulated extension is capped by SUBAGENT_MAX_PAUSE_EXTENSION_MS (2h — the provider's own maximum subscription park, covering the observed ~113 min with headroom). Once exhausted the ceiling fires as it does today. Worst case with the default budget is 45min + 2h = 2h45m: finite, predictable. - On fire under pause the TimeoutError names the pause context instead of a bare "Operation timed out after 2700000ms". - With no pause events, behaviour and error message are byte-for-byte identical. Pause arithmetic is extracted to a shared pause-window module so the idle watchdog and the ceiling cannot drift apart (all 20 existing idle-watchdog tests pass unchanged). New concerns live in new files, keeping every source file under the 350 LOC limit.
…time Adversarial review of the previous commit found a real defect. A pause was closed only on `resumed`, but `resumed` is emitted ONLY on the OAuth park path (`retry-layer.ts:415,512`) — a transient `rate_limit` NEVER has a matching `resumed`. Such a pause therefore stayed open forever, and because a later signal widens the window by the elapsed gap (`elapsedIntoPause + windowMs`), each new throttle retroactively credited the ordinary WORKING time between throttles: a 5s retry-after seen every 10 min credited the full 10 min, quietly inflating the effective budget toward `timeoutMs + cap`. Finiteness was never at risk (the absolute cap still bound it), but the budget's MEANING was: the whole point is to credit only time the provider actually said it was parked. A pause is now closed as soon as its own reported window has elapsed — checked on every pause signal and at the deadline — so credit can only ever reflect provider-stated park time. Verified: 4 x 5s throttles spread over 40 min now credit 140s (the reported windows incl. slack), not 40 min. Also from the same review: - Floor each grant at MIN_EXTENSION_GRANT_MS (1s). A deadline landing ~1ms after a pause opened would otherwise grant ~1ms at a time and re-arm the timer millions of times across a long park. Never exceeds the remaining cap, so the worst-case bound is unchanged. - `describe()` now reports a stale pause as `expired` rather than `still open`, so the error text cannot misreport a long-dead throttle. Independently re-derived and confirmed by the same review: worst-case total wait is timeoutMs + SUBAGENT_MAX_PAUSE_EXTENSION_MS (2h45m at the default); no child-authored event can grant extension; and the no-pause path is byte-for-byte identical to before.
|
The latest updates on your projects. Learn more about Vercel for GitHub.
|
…cing the runner The 'prints the quota line with its deadline once the binding window is hot' test builds a deadline of exactly Date.now() + 12*60_000 and asserts the rendered footer contains 'resets in 12m'. resetClause() in quota-footer.ts recomputes msLeft against a fresh now captured later, at render time, and formatResetCountdown() floors msRemaining/60_000 to whole minutes. Any wall-clock elapsed time between snapshot and render can push msLeft to 719_999ms, which floors to 11m instead of 12m — an exact-floor boundary assertion racing the test runner's speed. Freeze the clock in this describe block's beforeEach/afterEach so the deadline arithmetic is exact instead of racing the runner. This flake pre-existed on main and is unrelated to this PR's actual changes; the identical fix was already verified green on the sibling PR #793 branch.
Owner
Author
|
Wave 1.5 verification complete. All file-state citations match the reviewed ref content (verified). The B1 absence claim ("PauseAwareCeiling emits zero trace events") is confirmed-absent — the single grep hit was a comment line ( Since there are no cross-agent conflicts and all findings are ≤ medium severity, I'll synthesize inline (the synthesis is mechanical; dispatching a 7th session for 6 low-stakes findings would be overhead without value). Review: PR #797 — pause-aware wall-clock ceiling for forked sub-agentsTarget: SummaryThis revises a deliberately-shipped architectural decision ( The reviewer-critical properties all verify clean:
Findings
Conflicts: none (agents covered disjoint dimensions; no finding dedup needed). Spec-compliance (against stated intent)Stated intent present → assessed. All five asserted guarantees are implemented:
Unmet intent: none. Scope creep: none — the Infinity-vs-1ms guard fix and the 1s grant floor are both called out in the PR body as deliberate, not stealth changes. Epistemic scope
Merge decision: MERGENo critical or high findings. The core invariant — finite, predictable, provider-only-extensible ceiling that fixes a real 1h49m-work-loss incident — is correctly implemented and well-tested, with anti-gaming verified and API changes fully additive. The five findings (two medium coverage/namability gaps, two low, three nit) are non-blocking follow-ups: add a Done — read-only review of PR #797 complete; no files were modified, committed, or pushed. 🤖 Posted by |
…iling grant PauseAwareCeiling granted bounded wall-clock extensions entirely off-observation: the only record that a fork's budget had been moved was the terminal timeout error string. Reconstructing "the child got N extensions totaling Xms across this park" required the error alone — exactly the forensics gap the next incident would need. Add a pause_extension_granted session_phase witness event, emitted fire-and-forget from the handle each time PauseAwareCeiling.onDeadline grants a non-zero extension. The ceiling exposes an onGrant observer (so it stays decoupled from the trace layer and pure/testable); the handle wires a callback that emits the event carrying grantMs, totalGrantedMs, remainingCapMs, grantCount, subagentId, and the pause description. - trace: add pause_extension_granted to SessionPhaseName union + Zod enum + parity-test map (the union<->schema parity test enforces all three move together). - pause-ceiling: new PauseExtensionGrantInfo interface + 3rd ctor param onGrant; invoked after grantedMs/grantCount update, wrapped so an observer fault can never strand the wait. No-pause path still grants nothing, never invokes onGrant (pinned by a new test). - handle: pass the observer, closing over traceWriter + this.id; mirrors the idle_watchdog_fired emit pattern. Tests: +2 unit tests (onGrant invoked with correct details on a grant; onGrant NOT invoked when no pause observed). pause-ceiling 16, session-phase 48, idle-watchdog 20 (unchanged), handle 6 — all green.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The incident
On 2026-07-31 a code-backed
/forgerun lost 1h49m of work. Verified from~/.afk/agent-framework/forge-telemetry.jsonland witness traces:retryAfterMs: 6792000; runtime logsusage_limit_pausewithresetsAt: 2026-07-31T03:10:00.000Z(~113-min account-level pause)forge-rework-2with no explicittimeoutMs→ inheritsSUBAGENT_DEFAULT_TIMEOUT_MS(2,700,000 ms)TimeoutErrorThe idle watchdog consumed the pause signal correctly. The wall clock ignored the very same signal and killed the child anyway. The child had spent 43m38s of its 45-minute budget parked and received roughly 81 seconds of actual working time.
Net effect: a fork parked by a provider-imposed pause longer than its ceiling is guaranteed to die, no matter what the caller does. The only knob bounds wall time, so there was no way to express "bound the child's working time". Callers cannot pre-compute a safe
timeoutMsbecause the pause window is unknowable at dispatch; the only escape wastimeoutMs: 0(fully unbounded), which is worse.The decision this revises
.afk/plans/subagent-idle-watchdog.mdL88 states verbatim:#672 built pause-awareness into a separate
IdleWatchdogspecifically so it would not touchwithTimeout. This PR is a deliberate revision of that shipped architectural decision, not a gap-fill.The revision honors the purpose of the invariant — a fork's lifetime must have a guaranteed finite, predictable upper bound — rather than its letter, which made the actually-desired bound inexpressible. The ceiling remains un-resettable by the child; it is now movable only by the provider.
Design: bounded credit, not a reset
The budget now bounds working time:
Crediting parked time — rather than asking "is a pause in effect right now?" — is load-bearing. In the incident the park ended 81s before the deadline, so a right-now check grants nothing and the child dies exactly as before. My first implementation made precisely that mistake; the incident-replay test caught it.
Guarantees:
paused(withresetsAt) andrate_limit(withretryAfterMs) — the same eventsIdleWatchdogalready consumes, originating in the provider retry layer. Child content, tokens, thinking, tool activity,message,stream_retrygrant nothing. The child cannot author the only signal that moves the ceiling.SUBAGENT_MAX_PAUSE_EXTENSION_MS = 2h.Justification: the OAuth subscription park this defends against is itself bounded (plan doc L64, "subscription park, ≤2h"), and the observed real park was ~113 min (1h53m), which 2h covers with ~7 min of headroom. Choosing the provider's own maximum park means a legitimately parked child survives any pause the provider can impose, while a child parked by anything else is still bounded. Worst-case lifetime at the default budget: 45min + 2h = 2h45m — finite and predictable, reached only when a provider actively reports being parked that entire span.... [pause-aware ceiling: base budget 2700000ms; pause extension granted Nms across K extensions (cap 7200000ms); last provider pause: paused (usage-limit, resetsAt=...)]instead of a bareOperation timed out after 2700000ms.TimeoutError.timeoutMs, same controller-abort semantics. Pinned by an explicit byte-for-byte test against the no-extender path.Shared arithmetic (no duplication)
pausedWindowMs-style logic is extracted intosrc/agent/subagent/pause-window.ts, consumed by bothIdleWatchdogand the new ceiling so the two bounds cannot drift apart.IDLE_WATCHDOG_PAUSE_SLACK_MSis now an alias of the sharedPAUSE_WINDOW_SLACK_MS. All 20 pre-existing idle-watchdog tests pass unchanged.Files
src/agent/timeout.tsTimeoutExtenderseam; consulted only at the deadlinesrc/agent/subagent/pause-window.tssrc/agent/subagent/pause-ceiling.tsPauseAwareCeiling+SUBAGENT_MAX_PAUSE_EXTENSION_MSsrc/agent/subagent/handle.tswithTimeout; feed the streamsrc/agent/subagent/idle-watchdog.tsEvery source file stays under the 350-LOC limit; new concerns went into new files rather than growing existing ones.
Tests
pause-ceiling.test.ts(14),pause-window.test.ts(10),handle.test.ts(+3 wiring):pausedcarryingresetsAtrate_limitcarryingretryAfterMsEXHAUSTEDin the message)resumedbanks the closed pause's credit and stops further accrualrate_limits that never pair withresumeddo not credit working time (see below)paused, and does not extend on ordinary contentAdversarial review caught a real bug (2nd commit)
I dispatched an independent read-only verifier to re-derive finiteness, anti-gaming, no-pause identity, and refactor safety. It confirmed three and found a genuine merge-blocker in my first commit:
A pause was closed only on
resumed— butresumedis emitted only on the OAuth path (retry-layer.ts:415,512); a transientrate_limitnever has one. That pause stayed open forever, and since a later signal widens the window by the elapsed gap, each new throttle retroactively credited the ordinary working time between throttles. A 5s retry-after seen every 10 min credited the full 10 min. Finiteness was never at risk (the cap still bound it) but the budget's meaning was.Fixed in
0053360: a pause self-closes once its reported window elapses. Verified — 4×5s throttles across 40 min now credit 140s (the reported windows), not 40 minutes. Regression test added. The same review also prompted a 1s floor on grants (avoids millions of ~1ms timer re-arms) and anexpiredvsstill opendistinction in the error text.Verification
pnpm lint(tsc --noEmit)pnpm vitest run src/agent/subagent/ src/agent/timeout.test.tspnpm test(full)For reviewers to scrutinize
SubagentHandleImpl.pauseCeilingis per-run instance state, mirroringlastStreamedContent, becauserun()ownswithTimeoutwhile the stream loop lives instreamToFinalMessage.rate_limitwithretryAfterMs: Infinitypreviously passedInfinity > 0intosetTimeout, which Node clamps to 1ms → spurious instant idle-fire. The shared guard now treats it as "no knowable window". Strictly a fix, but it is an observable change in that edge case.retryAfterMs > 2^31-1still clamps insideIdleWatchdog.arm— pre-existing, untouched here.