Remove the in-loop no-progress watchdogs that were failing healthy runs - #3447
Conversation
Two 90s bounds ran for the whole model stream — one on silence between engine frames, one on a tool input whose byte count stopped growing — plus a zero-byte restart tripwire. Each inferred a dead stream from the absence of a particular event, and that inference cannot be made on the Anthropic transport: the SDK drops the provider's `ping` keepalives before any consumer sees them (`core/streaming.js`: `if (sse.event === 'ping') continue;`, with no opt-out). A model composing a large tool argument is therefore byte-for-byte indistinguishable from a wedged socket. That is normal operation. Only a tool declared for eager input streaming emits anything while its arguments are generated, so a long file write or a long structured result is a content-silent window sized by the argument. In one production deployment 2 of 27 one-shot analyst runs completed; the guards added for reliability were the thing taking it away. Also removed: the `earliestStartedAt` fallback, which anchored the action-preparation deadline to a start time it never advanced past, and the `Math.min` that let that deadline override a demonstrably live stream. One in-loop bound survives — the pre-first-frame cap on the clamped hosted foreground runtime, where the ~57s platform wall arrives before the engine's 120s abort could. The first real frame releases it, so long first tokens, long thinking, long tool inputs and long outputs are past it by construction. Real failures keep the bounds that key off evidence rather than absence: the engine's own first-event abort, the run-manager backstop outside the stream, per-tool execution timeouts, the chunk budget, and the stale reaper. The trade is explicit: an in-stream wedge after the first frame is now caught by the run budget rather than at 90s, because no clock here could tell it apart from a model writing a large tool call.
|
Here's a visual recap of what changed: Open the full interactive recap |
`runAgentLoop` re-derived the chunk budget from `resolveRunSoftTimeoutMs`, which answers with the generic background chat ceiling (13 min). A background AUTOMATION does not have that budget: its own hard abort minus headroom is 10min - 20s, so the per-tool ceiling came out at 12m55s inside a run that had 9m40s. Every per-tool timeout on that path was therefore unreachable and the chunk boundary won instead — the exact inversion `RUN_TOOL_TIMEOUT_HEADROOM_MS` exists to prevent, reintroduced by guessing at a number the caller already knew. `runAgentLoopWithResume` now passes its resolved `timeoutMs` down as `runSoftTimeoutMs`, and the ceiling is derived from that when present. `0` (local dev, no soft-timeout regime) keeps the existing fallback. Test asserts both halves: the chat ceiling produces a tool ceiling ABOVE an automation's budget, and the automation's own budget produces one below it.
![builder-io-integration[bot]](https://avatars.githubusercontent.com/in/353721?s=60&v=4){kind=small}
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
Follow-up: the tool-timeout ceiling (pushed in 8e208fe)
On the two remaining failure modesI looked at both and did not add fixes for them, because the evidence says they are downstream of what this PR already deletes rather than separate bugs.
Two things I could not establish and am not guessing at:
Both are worth instrumenting rather than patching. |
…runs
CI failed on this branch with every test passing: 12,465 green, one worker
exited unexpectedly, exit 1. Two causes, both mine.
The tests I rewrote left `runAgentLoop` promises pending forever. Their
engine hung on `new Promise(() => {})` and ignored `abortSignal`, so
aborting the controller settled nothing and the vitest worker was torn down
with the fork still live. Added `abortableHangingEngine`, which returns when
the caller aborts, and each of those tests now awaits the run before
restoring timers.
And twelve more tests still pinned the deleted action-preparation
machinery — the zero-byte restart tripwire, the byte-growth deadline, the
stalled-input tracking across snapshots. The first of them hung outright
once nothing was left to checkpoint it, which is what killed the worker.
They assert behaviour this branch deliberately removes, so they go with it.
The five that assert a checkpoint must NOT fire are kept: "keeps a model
stream alive when non-heartbeat events continue", the three
abandoned-zero-byte-id cases, and "keeps assembling a large action input
while bytes keep streaming". Those are exactly the property this branch is
for, and they still hold.
production-agent.spec.ts: 253 passing, no unhandled errors.
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
`stale_run` is the largest terminal outcome on the one-shot automation path — 14 of 27 runs in one production deployment — and the row records nothing about why. `error_detail` is the same fixed sentence for every reap, so a correct reap and a false one are indistinguishable after the fact, and every question worth asking needed a number nobody stored. The reap now records: which of the three stale windows applied, whether the row had a dispatch payload to recover from, time since heartbeat, time since last progress, whether the in-flight grace was in play and for how long, and the run's age measured to its liveness basis rather than to the reap. The field that matters is `hbAheadOfProgress`. A worker that died takes its heartbeat with it, so heartbeat and progress stop together and it reads ~0. A worker still running while the agent loop stops producing keeps heartbeating and it grows without bound — one production run showed the heartbeat 3,000s past the last progress, and nothing recorded that, so nothing could act on it. Those are opposite bugs that look identical in `agent_runs` today. ONE diagnostic write, not two: `diag_stage` holds a single value, so an independent forensics write would have overwritten the recovery outcome that already lands there — trading "did a successor get created" for "why did it die". Both fit on one line, so the recovery outcome keeps its stage name and leading position and the numbers are appended. Numbers, booleans and an enum only — no prompt, no result, no user content — so this obeys the same privacy rule as event properties and log lines, and a test asserts every token matches `key=<number|enum>`. `staleWindowMsForRow` mirrors `backgroundAwareStaleCutoffSql`, which decides the same thing in SQL because it must run inside the conditional UPDATE; a test pins all three cases so the two cannot drift. src/agent, src/app-config, src/jobs: 1,769 passing.
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
Three review findings on this PR, all real.
1. Resumed rounds kept the invocation's budget. `stableOpts` carries the
full `timeoutMs`, but round 2+ runs inside `roundTimeoutMs` — what is
left after earlier rounds spent wall-clock. Clamping a per-tool timeout
against the full window put it above the round containing it, so the
round timer won and the per-tool timeout was unreachable. Each round now
gets its own budget.
2. The main chat handler resolved its soft timeout for `startRun` and then
let the loop re-derive one. An app-configured chunk shorter than the
generic hosted/background ceiling therefore got per-tool timeouts longer
than the chunk containing them. Resolved once, passed to both — the same
inversion `RUN_TOOL_TIMEOUT_HEADROOM_MS` exists to prevent, two call
sites over from the automation case already fixed here.
3. After the first frame the in-loop deadline is infinite on every runtime,
which is the point of this PR. But local dev and self-hosted resolve the
soft timeout to 0, so the run-manager backstop is off and the engine's
first-event bound has already been released: on the direct-provider
engines a socket that wedged after the first frame had nothing left to
catch it. builder-engine already solves this with a two-stage deadline;
`createFirstEventAbortController` now does the same, so anthropic-engine
and ai-sdk-engine get a 14-minute `STREAM_TOTAL_TIMEOUT_MS` on the whole
call once the first frame releases the 120s first-event bound.
This is a total-request bound, not a no-progress bound. It cannot fire on
the healthy content-silent generation this PR exists to protect — the
largest chunk any caller runs inside is the ~13min background soft
timeout — and it does not reintroduce the absence-of-event inference.
Which deadline fired is now reported per stage, so a mid-stream wedge is
no longer described as a connection that never spoke.
The AI SDK path also swallowed a deadline abort as a graceful
`{type:"abort"}` part and fell through to a clean `end_turn`. Not gated
on `sawFirstEvent` any more: the total deadline fires mid-stream by
definition, and a truncated turn reported as a complete one is the
failure mode this repo names first.
Also unblocks CI: the stale-reap forensics query discarded a rejection into
`""`, which reads as "reaped with nothing worth saying" — the exact
ambiguity those forensics exist to remove. An unreadable row now says so.
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
`fireTimeout` recorded `timeoutMessage` before checking whether the composed controller had already been aborted, and `abortFromParent` left the deadline armed. A provider that is slow to settle after a user Stop or a run-budget abort could therefore fire the timer into an already-cancelled request and set `didTimeout()` — which is precisely what anthropic-engine and `classifyProviderError` read to tag a failure `provider_network_error` / retryable. A cancellation would have come back as a resumable provider error and been resumed. The ordering is pre-existing, but it was close to harmless while `markFirstEvent()` cleared the timer outright: nothing was armed after the first frame. Arming a total deadline for the whole stream turned a narrow race into a whole-stream one, so this is the new bound's bug to fix. - a timeout is recorded only when this controller wins the abort race - parent cancellation clears the outstanding deadline - `markFirstEvent()` will not re-arm one on an aborted controller, so a frame still in flight when the Stop lands cannot resurrect the timer Three tests, each verified to fail against the previous logic: cancellation mid-stream while the provider settles, cancellation before the first event, and a frame landing after cancellation.
This comment was marked as outdated.
This comment was marked as outdated.
Sorry, something went wrong.
The custom-agent mention path runs `runAgentLoop` directly inside the same `startRun` chunk and on the same signal as the main loop, but without `runSoftTimeoutMs`. The loop therefore fell back to re-deriving the generic hosted/background ceiling, which can sit above the chunk those nested calls actually run inside — so the per-tool timeout was unreachable and the chunk boundary preempted it. Fourth call site of this same shape in this PR. The recurring fix is a symptom: `runAgentLoop` silently guessing a budget when the caller does not supply one is the boundary, and every in-chunk caller having to remember to pass it is how the next one gets missed. Making the budget non-optional, or having `startRun` hand its resolved budget to the runFn, is the real fix and is too wide for this PR — noted rather than smuggled in. The standalone single-tool helper is unaffected: it has no surrounding chunk, which is what the optional field is for.
There was a problem hiding this comment.
Builder reviewed your changes — looks good ✅
Review Details
Code Review Summary
This incremental review examined the latest custom-agent timeout-budget propagation along with stream timeout/cancellation behavior, resumed-round budgets, and run-store diagnostics. The previously open custom-agent comment was verified fixed and resolved: the resolved enclosing chunk budget now reaches both custom-agent subloops and the primary loop, keeping per-tool ceilings inside the actual run budget. The earlier first-event/total-stream cancellation protections and stale-run forensic coverage remain consistent, and the focused timeout, resume, run-store, run-manager, and production-agent suites passed (410 targeted lifecycle/run-store tests plus 253 production-agent tests).
No new confirmed bugs or regressions were found. This is standard risk because the PR changes shared agent lifecycle and timeout behavior.
🧪 Browser testing: Skipped — PR only modifies backend/config/docs/tests, no UI impact
2 participants
The problem
Two 90s bounds ran for the whole model stream — one on silence between engine frames (
MODEL_STREAM_NO_PROGRESS_TIMEOUT_MS), one on a tool input whose byte count stopped growing (ACTION_PREPARATION_NO_PROGRESS_TIMEOUT_MS) — plus a zero-byte tool-input restart tripwire.Each inferred a dead stream from the absence of a particular event. That inference cannot be made on the Anthropic transport:
The SDK drops the provider's
pingkeepalives before any consumer sees them, with no opt-out —RawMessageStreamEventhas nopingvariant at all. So a model composing a large tool argument is byte-for-byte indistinguishable from a wedged socket.And that is normal operation, not an edge case. Only a tool declared for eager input streaming emits
input_json_deltawhile its arguments are generated. Everything else producestool-input-startand then nothing until the whole blob is ready — for a large file write or a long structured result, that is minutes of legitimate silence.Evidence
In one production deployment, 2 of 27 one-shot analyst runs completed. The dominant terminal states were
stale_runandtruncated, with real progress consistently stopping during the final large tool call. Guards added for reliability were the thing taking it away.Three failure modes in
actionPreparationDeadlineAt()specifically:trackActiveToolInputwas called only when bytes increase, so a frame carrying no new bytes was not progress.earliestStartedAt + 90s— an absolute anchor that never moves. "Slow" became "dead" deterministically at 90,000ms.noProgressDeadlineAt()took theminof that and the model-stream clock, solastModelStreamProgressAtcould be updating on every frame — positive proof nothing was wedged — and it could not save the round.What this removes
MODEL_STREAM_NO_PROGRESS_TIMEOUT_MSand its deadlineACTION_PREPARATION_NO_PROGRESS_TIMEOUT_MS, its deadline, theearliestStartedAtfallback, and theMath.minoverrideACTION_PREPARATION_ZERO_BYTE_RESTART_LIMIT,noteZeroByteToolInputStart,resetZeroByteToolInputRestart)+181 / −315.
What still catches a real wedge
None of these can fire on slow-but-healthy work:
FIRST_STREAM_EVENT_TIMEOUT_MS(120s) — a stream that opens and never speaksOne in-loop bound survives: the pre-first-frame cap on the clamped hosted foreground runtime, where the ~57s platform wall arrives before the engine's 120s abort could. The first real frame releases it, so long first tokens, long thinking, long tool inputs and long outputs are all past it by construction. Off that runtime there is no in-loop deadline at all.
The trade, stated explicitly
model_streamstart/end still suspends the run-manager's 150s backstop, and that suspension used to be justified by the inner watchdog bounding the window. With the watchdog gone, an in-stream wedge after the first frame is caught by the run budget rather than at 90s.That is slower on a genuine mid-stream wedge, and it is the correct direction: no clock in the loop could tell that case apart from a model writing a large tool call. The comment in
types.tswas updated so the old justification does not stand unchallenged.Tests
Five tests asserted the deleted behaviour. They are rewritten to pin the inverse:
src/agent/,src/app-config/,src/jobs/: 1,588 passing. Failures elsewhere incore(client, cli, eject, ingestion) are pre-existing — they fail identically on a clean tree from an unbuilt@agent-native/toolkitand a missingxlsx.Note for reviewers
One implementation detail worth a look:
setTimeout(…, Infinity)is coerced to 1ms by Node, which would have turned "no bound" into the tightest bound there is.nextEngineEventWithNoProgressTimeoutnow awaits the iterator directly when the deadline is not finite.Not included
runToolTimeoutCeilingMsderives from the 780s chat ceiling while a background automation's real budget is 580s (backgroundRunHardTimeoutMs− headroom), so the per-tool timeout is dead code on that path and the chunk boundary wins. Real bug, separate fix.