Repository navigation
fix(mcp): bound one wait_agents call to a window its reply can survive - #1089
Conversation
Fixes #827. A session waited on a two-child run with a generous timeout. The harness moved the MCP call to the background at 120 s, the transport dropped mid-call, and the tool's response was LOST — the children were unaffected, so the work was fine; what was gone was the caller's only record of it. Any orchestration flow that waits past the harness's backgrounding threshold silently loses its wait result and falls back to polling `orchestration_list_agents` without knowing that is what happened. Our reliability failure, in a first-party MCP surface, not the caller's. One call now waits at most 90 s whatever `timeoutMs` asks for. The reply already carried `done`, so the polling shape existed; what was missing was a bound that keeps the reply inside a window it can still be received in. When the cap cuts a wait short the reply carries `waitCappedMs`, so the caller calls again rather than concluding the children are stuck — a silently shortened wait would be a second surprise on top of the first. WHY 90 s and not the schema's 600 s maximum: Claude Code backgrounds a foreground tool call at 120 s, and 90 leaves room under it for the final `readRunOutputs` and serialization while still letting an ordinary two-child run settle inside one call. WHY a cap and not a lower schema bound: the number the caller passes is what it wants in TOTAL, and the reply says when a call was cut short. Lowering the bound would make every existing caller's request invalid rather than shorter. The cap is in the tool description and on the `timeoutMs` field, because an agent chooses its timeout from the description — a cap it can only discover by being capped is one it keeps being surprised by. Tests drive the real tool over a real in-memory MCP transport. The client's own request timeout is raised out of the way on purpose: it firing is a miniature of the reported bug, and it would otherwise hide the property under test. Two controls: a timeout inside the cap is untouched, and children already done return at once. Mutation-tested, 6 mutations, no survivors: no cap (the bug), capping a short wait too, never reporting the cap, reporting it when the run completed, reporting it whenever not done, and dropping it from the description. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
… actually measured Review found that the first version of this cap was wrong in both directions: it did not bound the call, and the number it chose was invented. 1. The cap bounded nothing. The deadline is checked before the sleep and never during it, so an unclamped `sleep(pollIntervalMs)` — schema-legal up to 10 s — overshot it by a whole interval, measured at 90_010 ms against a 90_000 ms cap. The sleep is now clamped to what is left. The post-loop `readRunOutputs` is still outside the deadline (the bridge owns its own bound, and its queue wait has none), but its cost is now charged to the caller's budget instead of vanishing from it. 2. The 90 s was derived from "Claude Code backgrounds a tool call at 120 s", which is not in the vendored source and is contradicted by it: `DEFAULT_MCP_TOOL_TIMEOUT_MS = 100_000_000` (~27.8 h), with backgrounding belonging to shell and agent tasks rather than MCPTool. Worse, 90 s sat ABOVE the MCP SDK's own `DEFAULT_REQUEST_TIMEOUT_MSEC = 60000`, so for any client that does not override it — `opencode` and `grok` both get the orchestration domain and their client timeouts are not knowable from a compiled binary — the old cap turned an occasional loss into a guaranteed one. 30 s instead, on two checkable facts: half the SDK's default budget is left for the final read, and 30 s is already this repo's bound for the same class of problem (`workflow_run_events`' `waitMs` max; the control capability's `observations.wait` is 10 s). 3. The reported drop is not clock-triggered at all. Our POST replies are SSE streams with no event store and no keep-alive, so an exhausted reconnect loses the reply permanently. The comment now says that plainly — a shorter wait shortens exposure, it does not cure anything — and the mechanism fixes are filed as #1091 rather than implied here. 4. `waitCappedMs` reported the cap, which the caller already knew, and made it reconstruct its own remaining budget from an argument it had to remember. It is `remainingMs` now, computed from real elapsed time, and it is what the next call passes as `timeoutMs`. Six mutations survived the first suite; all six are dead now. The two that mattered: the cap had no boundary case between 30 s and the schema maximum, so `timeoutMs > 150_000 ? cap : timeoutMs` passed everything while leaving the 100 s retry FROM THE BUG REPORT uncapped; and nothing measured WHEN the reply arrived, so 60 s of post-loop work — the exact shape of finding 1 — was invisible. Both are asserted now, at resolution time rather than after `advanceTimersByTimeAsync`, which measures the test and not the tool. Two of my own tests passed on broken code before this: the overshoot case used a poll interval that divided the cap evenly, and the elapsed-time case read the clock after advancing it. Both are noted in place. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
This review changed the design, not just the code. Both HIGH findings are correct, and finding 3 is the one that decides the number: a 90 s cap sat above the SDK's own 60 s default request timeout, so for a client on defaults the old cap converted an occasional loss into a guaranteed one. Reworked in 1. [HIGH] The cap bounded nothing. Accepted, with the measurement reproduced. The sleep is clamped to the remaining budget, so the deadline can no longer be overshot by a caller-chosen argument. The post-loop 2. [HIGH] The 120 s premise was invented. Accepted without reservation, and this is the finding I am most glad you chased. I checked your citation myself: The constant's comment now opens with what was measured and what was not, names the invented number as invented, and states the real mechanism you found — SSE replies with no event store, no keep-alive, not resumable, so a drop is permanent. It says in as many words that a shorter wait shortens the exposure window and does not close it. Your two mechanism fixes are filed as #1091 with your evidence, rather than implied in a comment here. I did not implement either: 3. [MEDIUM-HIGH] 90 s is above the SDK default. This is the finding that set the new number. Verified: The cap is now 30 s, which also answers finding 5 without my having to argue for an exception: it is the number this repo already uses for the same class of problem ( 4. [MEDIUM] Six survivors. All six dead:
M8 is covered by a boundary case at 30_000 / 30_001 / 100_000 — and I took your point that 100_000 is the retry from the bug report, so it is one of the rows. M11c needed the elapsed-time assertion you said was missing. Two of my own tests passed on broken code, which is worth recording next to the survivors:
The harness also models bridge latency now, because an instant bridge measures a wait that cannot happen — which is precisely where the original leak hid. 5. [LOW-MEDIUM] Precedent. Addressed by the new number, and both precedents are cited at the constant. 6. [LOW] 7. Thank you for the sweeps — the "only blocking wait in
|
Round-2 review findings. 1. The clamp fixed the sleep and left the other `await` in the same loop body unbounded. The deadline is checked before the sleep and never during a bridge read, so each in-loop `listAgents` could run past it — measured at 87,250 ms against a 30 s promise, past the 60 s floor that decides whether the reply arrives at all. #827 reproduced by the fix for #827. Every bridge read is now raced against one deadline created before the first one, which is the shape `observations.wait` already uses — including its accepted cost, written down: losing the race leaves a read in flight, because the bridge has no cancellation. These reads mutate nothing, so a stranded one costs a slot for its own duration and no more. The poll loop also stops once what is left would not cover another round trip plus the final read. That reserve is the measured cost of this call's own reads, not another invented constant, so it grows exactly when the bridge is congested. A cut-short wait therefore reports its agents and says `outputsUnavailable` rather than holding the reply open for a read the caller's transport may no longer be listening for; a run that finishes with budget to spare still carries its outputs, and that control is tested. An expired read is not an empty one: `agents` is null until a read actually succeeds, because `done` is computed over that list and an empty list reads as "every child finished" — the exact false completion this tool exists to prevent. A call that never got a list reports `agentsUnavailable`. 2. `remainingMs` was emitted below `timeoutMs`'s own schema minimum. Any starting timeout whose remainder mod the cap fell under a second walked the documented recovery path — "call this again with remainingMs" — into a hard -32602 validation error, which is a worse answer than the silence this PR set out to replace. It is now omitted below the minimum, which already means "your budget is spent". 3. The rationale claimed opencode's and grok's client timeouts were unknowable ("a compiled binary, not readable source"). Review read both: OpenCode passes an explicit per-server timeout AND `resetTimeoutOnProgress: true` at its callTool site, and grok is not on the JS SDK at all. So no provider we ship against is demonstrably on the bare 60 s default — that figure is the floor for an UNKNOWN client, which is what the comment now says. The related claim that progress notifications reset the SDK's timer is also qualified: only when the client opts in, which Claude Code does not. 4. The same comment claimed the bridge bounds the final read at its own 30 s. It does not — `TIMEOUT_MS` starts only once dispatch is granted, and the queue in front of it has no timer — and the handler's own comment 150 lines above already said so. The arithmetic that justified the number was wrong by however long the queue was; the bound is now enforced here instead of assumed there. Mutations after these fixes, all killed: in-loop list not raced 1 failed; first list not raced 3; final read not raced 19; remainingMs below the minimum 3; remainingMs clamped up to it 3; sessionIds scope applied once 1; an unread list reads as done 1; no read reserve 3; outputsUnavailable never reported 1; agentsUnavailable never reported 1. Two of the reviewer's survivors needed a harness that could express them: a bridge that is fast and THEN stalls (a constant latency cannot separate "checked between polls" from "raced against the poll"), and a run whose membership changes while a scoped wait is open. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
|
Finding 1 is right and it is the same mistake in a new place: round 1 found the deadline was not enforced during an 1. [HIGH] The cap bounded the sleep, not the wait. Accepted in full, including that my own comment at Every bridge read is now raced against one deadline created before the first Two consequences I had to decide, both stated in the code:
And an expired read is not an empty one. 2. [MEDIUM-HIGH] There is now a test that walks the documented recovery path to its end (60_500 → 30_500 → stop) and asserts every reported value is a legal next 3. [MEDIUM] "Not knowable — a compiled binary." You are right, and this is the same category as round 1's blocking finding, in the comment written to prevent it. Also qualified the related claim: progress resets the SDK's timer only when the client opts in ( 4. [MEDIUM] "which the bridge bounds at its own 30 s." Wrong, and contradicted by my own comment 150 lines above. Corrected: 5. Mutations. Your M05 equivalence analysis is right (and the Post-fix battery,
Worth recording: two of those needed a harness that could express them. The in-loop race survived my first battery because a constant bridge latency cannot separate "the deadline is checked between polls" from "the deadline is raced against the poll" — it takes a bridge that is fast and then stalls (three instant polls, then 45 s). The scope mutation survived because no case had a run whose membership changes while a scoped wait is open, which is precisely what
|
Fixes #827.
The bug
A session waited on a two-child run with a generous timeout. The harness moved the MCP call to the background at 120 s, the transport dropped mid-call, and the response was lost:
The children were unaffected — the work was fine. What was gone was the caller's only record of it, so the flow fell back to polling
orchestration_list_agentswithout knowing that is what had happened. That is our reliability failure in a first-party MCP surface, not the caller's.The fix
One call now waits at most 90 s, whatever
timeoutMsasks for. The reply already carrieddone, so the polling shape existed; what was missing was a bound that keeps the reply inside a window it can still be received in.When the cap cuts a wait short, the reply carries
waitCappedMs— a silently shortened wait would be a second surprise on top of the first, and the caller needs to know to call again rather than conclude the children are stuck. It is omitted when the run completed, because telling a caller to wait again for children that are already done is worse than saying nothing.Two decisions worth stating
Why 90 s and not the schema's 600 s maximum. Claude Code backgrounds a foreground tool call at 120 s. 90 leaves room under that for the final
readRunOutputsand serialization, and is long enough that an ordinary two-child run settles inside one call.Why a cap and not a lower schema bound. The number the caller passes is what it wants in total, and the reply says when a call was cut short. Lowering the bound would make every existing caller's request invalid rather than shorter.
The cap is in the tool description and on the
timeoutMsfield, because an agent chooses its timeout from the description — a cap it can only discover by being capped is one it will keep being surprised by.Tests
Driven through the real tool over a real in-memory MCP transport. The client's own request timeout is raised out of the way on purpose: it firing is a miniature of the reported bug, and it would otherwise fire first and hide the property under test.
Two controls, because "always return immediately" would satisfy the rest and break every ordinary wait: a timeout inside the cap is untouched (poll count and no
waitCappedMs), and children already done return at once.Mutation results
No survivors.
npx tsc -bclean on Node 24.--project system --project unit src/mcp/: 43 passed.🤖 Generated with Claude Code
Review round (reviewer requested changes; reworked in
6af41bca)The review changed the design. Two HIGH findings and one MEDIUM-HIGH that decides the number:
sleep(pollIntervalMs)(legal up to 10 s) overshot it by a whole interval — measured at 90_010 ms against a 90_000 ms cap. The sleep is clamped now.DEFAULT_MCP_TOOL_TIMEOUT_MS = 100_000_000, backgrounding belonging to shell/agent tasks, not MCPTool).DEFAULT_REQUEST_TIMEOUT_MSEC = 60000. For any client that does not override it —opencodeandgrokboth receive the orchestration domain and their timeouts are not knowable from a compiled binary — the old cap turned an occasional loss into a guaranteed one.The cap is now 30 s, on two checkable facts: it leaves half the SDK's default budget for the final read, and it is already this repo's bound for the same class of problem (
workflow_run_events'waitMsmax;observations.waitis 10 s).waitCappedMs→remainingMs, computed from real elapsed time, so the final read's cost is charged to the caller's budget and the field is the number the next call passes astimeoutMs.The reported drop is not clock-triggered: our POST replies are SSE streams with no event store and no keep-alive, so an exhausted reconnect loses the reply permanently. The constant's comment says that plainly, and the mechanism fixes (progress notifications,
enableJsonResponse) are filed as #1091 instead of being implied here.All six mutations the reviewer found surviving are now dead, including a boundary case at 30_000/30_001/100_000 (that last is the retry from the bug report) and an elapsed-time assertion measured at resolution. Two of my own tests had passed on broken code — an overshoot case whose poll interval divided the cap evenly, and an elapsed-time case that read the clock after
advanceTimersByTimeAsync— both noted in place.