From f1dc75f845ec07a711f07bd3fbc238ecb332259a Mon Sep 17 00:00:00 2001 From: Julius Olsson Date: Sun, 20 Sep 2026 09:33:52 -0700 Subject: [PATCH 1/3] fix(mcp): bound one wait_agents call to a window its reply can survive MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- src/mcp/runtime/createBuiltInMcpServer.ts | 39 ++++- src/mcp/runtime/waitAgentsCap.system.test.ts | 143 +++++++++++++++++++ 2 files changed, 178 insertions(+), 4 deletions(-) create mode 100644 src/mcp/runtime/waitAgentsCap.system.test.ts diff --git a/src/mcp/runtime/createBuiltInMcpServer.ts b/src/mcp/runtime/createBuiltInMcpServer.ts index 9333da498..ebcea7ae4 100644 --- a/src/mcp/runtime/createBuiltInMcpServer.ts +++ b/src/mcp/runtime/createBuiltInMcpServer.ts @@ -1276,11 +1276,12 @@ function orchestrationCreateAgentCallKey( { title: 'Wait For Orchestration Agents', description: - 'Waits for all matching orchestration-created child agents to leave active states, then returns their statuses and latest outputs. Outputs are byte-capped per message/agent and share a cross-agent total budget; over-budget agents degrade to status summaries with short excerpts and truncated=true. To recover a truncated agent, re-read it with orchestration_read_agent and explicit larger caps, or use agent_transcript_read_file on its transcript.', + `Waits for all matching orchestration-created child agents to leave active states, then returns their statuses and latest outputs. ONE CALL WAITS AT MOST ${WAIT_AGENTS_MAX_WAIT_MS / 1000} SECONDS whatever timeoutMs asks for; when it is cut short the reply carries done=false and waitCappedMs, and you call this again to keep waiting. Outputs are byte-capped per message/agent and share a cross-agent total budget; over-budget agents degrade to status summaries with short excerpts and truncated=true. To recover a truncated agent, re-read it with orchestration_read_agent and explicit larger caps, or use agent_transcript_read_file on its transcript.`, inputSchema: { runId: z.string().optional(), sessionIds: z.array(z.string()).optional(), - timeoutMs: z.number().int().min(1000).max(600000).default(30000), + timeoutMs: z.number().int().min(1000).max(600000).default(30000) + .describe(`How long you want to wait. One call waits at most ${WAIT_AGENTS_MAX_WAIT_MS / 1000} s; a larger value returns done=false with waitCappedMs, to be called again.`), pollIntervalMs: z.number().int().min(250).max(10000).default(1000), maxMessagesPerAgent: z.number().int().min(1).max(100).optional(), maxCharsPerMessage: z.number().int().min(50).max(100_000).optional(), @@ -1297,7 +1298,19 @@ function orchestrationCreateAgentCallKey( message: 'Agent Code orchestration services are not available.', }) } - const deadline = Date.now() + args.timeoutMs + // WHY one call never waits the full requested timeout (#827): a harness + // that backgrounds a foreground tool call — Claude Code does it at + // 120 s — drops the MCP transport mid-call, and the reply is LOST. The + // children are unaffected, so the work is fine; what is gone is the + // caller's only record of it, and the flow falls back to polling + // `orchestration_list_agents` with no idea that is what happened. + // + // The reply already carried `done`, so the polling shape existed. This + // keeps the reply inside a window it can still be received in, and says + // `waitCappedMs` so the caller knows to call again rather than + // concluding the children are stuck. + const cappedTimeoutMs = Math.min(args.timeoutMs, WAIT_AGENTS_MAX_WAIT_MS) + const deadline = Date.now() + cappedTimeoutMs let agents = await bridge.listAgents({ parentSessionId: scope.sessionId, runId: args.runId }) if (args.sessionIds && args.sessionIds.length > 0) { const wanted = new Set(args.sessionIds) @@ -1330,11 +1343,16 @@ function orchestrationCreateAgentCallKey( args.maxTotalChars, JSON.stringify(agents).length, ) + const done = !agents.some(agent => isOrchestrationAgentActive(agent.lifecycleState)) return toolText({ ok: true, - done: !agents.some(agent => isOrchestrationAgentActive(agent.lifecycleState)), + done, agents, outputs: bounded.outputs, + // Only when the cap actually cut the wait short AND there is still + // something to wait for. Reporting it on a completed run would tell + // the caller to call again for children that are already done. + ...(!done && cappedTimeoutMs < args.timeoutMs ? { waitCappedMs: cappedTimeoutMs } : {}), ...(bounded.truncated ? { truncated: true } : {}), }) }, @@ -1395,6 +1413,19 @@ function orchestrationCreateAgentCallKey( ) } +// WHY 90 s and not the schema's 600 s maximum (#827): a foreground MCP tool +// call has to return while its transport is still listening. Claude Code +// backgrounds one at 120 s and the reply is then lost outright — the reported +// failure. 90 s leaves room under that threshold for the final +// `readRunOutputs` and serialization, and is long enough that an ordinary +// two-child run settles well inside one call. +// +// It is a CAP, not a new maximum: `timeoutMs` still accepts up to 600 s +// because the number the caller passes is what it wants in total, and the +// reply says when a call was cut short. Lowering the schema bound instead +// would make every existing caller's request invalid rather than shorter. +const WAIT_AGENTS_MAX_WAIT_MS = 90_000 + // Cross-agent total budget for read_run_outputs / wait_agents (#373). // // WHY this lives in the tool handler and not in the renderer or bridge: the diff --git a/src/mcp/runtime/waitAgentsCap.system.test.ts b/src/mcp/runtime/waitAgentsCap.system.test.ts new file mode 100644 index 000000000..7fa33a230 --- /dev/null +++ b/src/mcp/runtime/waitAgentsCap.system.test.ts @@ -0,0 +1,143 @@ +import { Client } from '@modelcontextprotocol/sdk/client/index.js' +import { InMemoryTransport } from '@modelcontextprotocol/sdk/inMemory.js' +import { describe, expect, it, vi } from 'vitest' + +import { createBuiltInMcpServer } from '@mcp/runtime/createBuiltInMcpServer.js' + +// #827. A Claude 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: +// +// MCP server "agent_code" transport dropped mid-call; response for tool +// "orchestration_wait_agents" was lost +// +// The children were unaffected; a retry with 100 s returned normally. So any +// orchestration flow that waits past the harness's backgrounding threshold +// silently loses its wait result and has to fall back to polling +// `orchestration_list_agents` — a reliability failure in a first-party MCP +// surface, caused by us and not by the caller. +// +// The response already carried `done`, so the shape for polling existed. What +// was missing was a server-side bound that keeps the reply inside the window +// the caller can still receive it in. + +function child(lifecycleState: string) { + return { sessionId: 'child-1', kind: 'claude', cwd: '/repo', title: 'Child', lifecycleState, messageCount: 0 } +} + +async function callWait(args: Record, lifecycleState = 'running') { + const listAgents = vi.fn(async () => [child(lifecycleState)]) + const server = createBuiltInMcpServer( + { sessionId: 'parent', cwd: '/repo', domains: ['orchestration'] }, + { + orchestrationBridge: { + listAgents, + readRunOutputs: vi.fn(async () => []), + } as never, + }, + ) + const client = new Client({ name: 'wait-cap-test', version: '0.0.0' }) + const [clientTransport, serverTransport] = InMemoryTransport.createLinkedPair() + try { + await server.connect(serverTransport) + await client.connect(clientTransport) + const startedAt = Date.now() + // The CLIENT's own request timeout is raised out of the way on purpose: + // this suite is about the SERVER bounding its wait, and under fake timers + // the client's default 60 s would fire first and hide that. (It firing is + // itself a miniature of the reported bug — a transport that stops + // listening while the tool is still working.) + const result = await client.callTool( + { name: 'orchestration_wait_agents', arguments: args }, + undefined, + { timeout: 10_000_000 }, + ) + const elapsedMs = Date.now() - startedAt + const text = (result.content as Array<{ text: string }>)[0]!.text + return { payload: JSON.parse(text) as Record, elapsedMs, listAgents } + } finally { + await client.close() + await server.close() + } +} + +describe('orchestration_wait_agents stays inside the window its reply can survive (#827)', () => { + it('caps a long wait and says it capped, so the caller polls instead of losing the reply', async () => { + vi.useFakeTimers() + try { + // The reported call: a generous timeout on children that never settle. + const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 1_000 }) + await vi.advanceTimersByTimeAsync(600_000) + const { payload } = await pending + + // It returned, rather than running the full ten minutes into a transport + // that is no longer listening. + expect(payload.done).toBe(false) + // And it SAYS the wait was shortened. A silently short wait is a second + // surprise on top of the first: the caller asked for ten minutes. + expect(payload.waitCappedMs).toBe(90_000) + } finally { + vi.useRealTimers() + } + }) + + it('polls only up to the cap, never for the timeout the caller asked for', async () => { + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 1_000 }) + await vi.advanceTimersByTimeAsync(600_000) + const { listAgents } = await pending + + // One read before the loop, then one per poll inside the cap. Anything + // near 600 means the cap did not bound the loop. + expect(listAgents.mock.calls.length).toBeLessThanOrEqual(92) + expect(listAgents.mock.calls.length).toBeGreaterThan(80) + } finally { + vi.useRealTimers() + } + }) + + it('leaves a timeout inside the cap exactly as it was', async () => { + // The control. "Always return immediately" would satisfy the two above and + // break every ordinary wait. + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs: 30_000, pollIntervalMs: 1_000 }) + await vi.advanceTimersByTimeAsync(30_000) + const { payload, listAgents } = await pending + + expect(payload.done).toBe(false) + // No cap was applied, so the field is absent rather than reported as 0. + expect(payload).not.toHaveProperty('waitCappedMs') + expect(listAgents.mock.calls.length).toBeGreaterThan(25) + expect(listAgents.mock.calls.length).toBeLessThanOrEqual(32) + } finally { + vi.useRealTimers() + } + }) + + it('returns at once when the children are already done, whatever the timeout', async () => { + const { payload, elapsedMs } = await callWait({ timeoutMs: 600_000 }, 'completed') + + expect(payload.done).toBe(true) + expect(payload).not.toHaveProperty('waitCappedMs') + expect(elapsedMs).toBeLessThan(5_000) + }) + + it('tells the caller about the cap in the tool description, not only in the reply', async () => { + // An agent reads the description before it chooses a timeout. A cap it can + // only discover by being capped is a cap it will keep being surprised by. + const server = createBuiltInMcpServer({ sessionId: 'parent', cwd: '/repo', domains: ['orchestration'] }) + const client = new Client({ name: 'wait-cap-doc-test', version: '0.0.0' }) + const [clientTransport, serverTransport] = InMemoryTransport.createLinkedPair() + try { + await server.connect(serverTransport) + await client.connect(clientTransport) + const tool = (await client.listTools()).tools.find(item => item.name === 'orchestration_wait_agents') + expect(tool?.description).toContain('90') + } finally { + await client.close() + await server.close() + } + }) +}) From 6af41bcabebe87fb2ea99ddbc40ae008ff9c4f24 Mon Sep 17 00:00:00 2001 From: Julius Olsson Date: Sun, 20 Sep 2026 10:20:57 -0700 Subject: [PATCH 2/3] fix(orchestration): bound the whole wait at 30 s, on a number that is actually measured MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- src/mcp/runtime/createBuiltInMcpServer.ts | 99 +++++++--- src/mcp/runtime/waitAgentsCap.system.test.ts | 179 ++++++++++++++++--- 2 files changed, 234 insertions(+), 44 deletions(-) diff --git a/src/mcp/runtime/createBuiltInMcpServer.ts b/src/mcp/runtime/createBuiltInMcpServer.ts index ebcea7ae4..e4cd6549c 100644 --- a/src/mcp/runtime/createBuiltInMcpServer.ts +++ b/src/mcp/runtime/createBuiltInMcpServer.ts @@ -1276,12 +1276,12 @@ function orchestrationCreateAgentCallKey( { title: 'Wait For Orchestration Agents', description: - `Waits for all matching orchestration-created child agents to leave active states, then returns their statuses and latest outputs. ONE CALL WAITS AT MOST ${WAIT_AGENTS_MAX_WAIT_MS / 1000} SECONDS whatever timeoutMs asks for; when it is cut short the reply carries done=false and waitCappedMs, and you call this again to keep waiting. Outputs are byte-capped per message/agent and share a cross-agent total budget; over-budget agents degrade to status summaries with short excerpts and truncated=true. To recover a truncated agent, re-read it with orchestration_read_agent and explicit larger caps, or use agent_transcript_read_file on its transcript.`, + `Waits for all matching orchestration-created child agents to leave active states, then returns their statuses and latest outputs. ONE CALL STOPS WAITING AFTER ${WAIT_AGENTS_MAX_WAIT_MS / 1000} SECONDS whatever timeoutMs asks for, then reads outputs once and replies; when it is cut short the reply carries done=false and remainingMs, and you call this again with remainingMs to keep waiting. Outputs are byte-capped per message/agent and share a cross-agent total budget; over-budget agents degrade to status summaries with short excerpts and truncated=true. To recover a truncated agent, re-read it with orchestration_read_agent and explicit larger caps, or use agent_transcript_read_file on its transcript.`, inputSchema: { runId: z.string().optional(), sessionIds: z.array(z.string()).optional(), timeoutMs: z.number().int().min(1000).max(600000).default(30000) - .describe(`How long you want to wait. One call waits at most ${WAIT_AGENTS_MAX_WAIT_MS / 1000} s; a larger value returns done=false with waitCappedMs, to be called again.`), + .describe(`How long you want to wait in total. One call stops waiting after ${WAIT_AGENTS_MAX_WAIT_MS / 1000} s; a larger value returns done=false with remainingMs, which is what you pass to the next call.`), pollIntervalMs: z.number().int().min(250).max(10000).default(1000), maxMessagesPerAgent: z.number().int().min(1).max(100).optional(), maxCharsPerMessage: z.number().int().min(50).max(100_000).optional(), @@ -1298,26 +1298,39 @@ function orchestrationCreateAgentCallKey( message: 'Agent Code orchestration services are not available.', }) } - // WHY one call never waits the full requested timeout (#827): a harness - // that backgrounds a foreground tool call — Claude Code does it at - // 120 s — drops the MCP transport mid-call, and the reply is LOST. The - // children are unaffected, so the work is fine; what is gone is the - // caller's only record of it, and the flow falls back to polling - // `orchestration_list_agents` with no idea that is what happened. + // WHY one call never waits the full requested timeout (#827): a + // foreground MCP tool call whose transport stops listening loses its + // reply outright. The children are unaffected, so the work is fine; what + // is gone is the caller's only record of it, and the flow falls back to + // polling `orchestration_list_agents` with no idea that is what + // happened. See WAIT_AGENTS_MAX_WAIT_MS for which numbers here are + // measured and which hazard this does NOT close. // // The reply already carried `done`, so the polling shape existed. This // keeps the reply inside a window it can still be received in, and says - // `waitCappedMs` so the caller knows to call again rather than - // concluding the children are stuck. + // `remainingMs` so the caller knows to call again — with a budget it does + // not have to compute — rather than concluding the children are stuck. + const startedAt = Date.now() const cappedTimeoutMs = Math.min(args.timeoutMs, WAIT_AGENTS_MAX_WAIT_MS) - const deadline = Date.now() + cappedTimeoutMs + // Before the first `listAgents`, deliberately: that call is a round trip + // through the bridge, which serializes every orchestration request + // app-wide behind one in-flight slot. Starting the clock after it would + // let an unbounded queue wait be added to the cap rather than spent + // inside it. + const deadline = startedAt + cappedTimeoutMs let agents = await bridge.listAgents({ parentSessionId: scope.sessionId, runId: args.runId }) if (args.sessionIds && args.sessionIds.length > 0) { const wanted = new Set(args.sessionIds) agents = agents.filter(agent => wanted.has(agent.sessionId)) } while (Date.now() < deadline && agents.some(agent => isOrchestrationAgentActive(agent.lifecycleState))) { - await sleep(args.pollIntervalMs) + // Clamped to what is LEFT, not the raw interval. `pollIntervalMs` is + // schema-legal up to 10 s, so an unclamped sleep let one call overshoot + // the cap by a whole interval — the deadline is checked before the + // sleep, never during it. Measured at 90_010 ms against a 90_000 ms + // cap before this clamp existed; a promise that is off by an argument + // the caller chooses is not a promise. + await sleep(Math.min(args.pollIntervalMs, Math.max(0, deadline - Date.now()))) agents = await bridge.listAgents({ parentSessionId: scope.sessionId, runId: args.runId }) if (args.sessionIds && args.sessionIds.length > 0) { const wanted = new Set(args.sessionIds) @@ -1352,7 +1365,16 @@ function orchestrationCreateAgentCallKey( // Only when the cap actually cut the wait short AND there is still // something to wait for. Reporting it on a completed run would tell // the caller to call again for children that are already done. - ...(!done && cappedTimeoutMs < args.timeoutMs ? { waitCappedMs: cappedTimeoutMs } : {}), + // + // The caller's UNSPENT budget, not the cap. Reporting the cap made the + // caller reconstruct "how much of what I asked for is left" from an + // argument it had to remember; `remainingMs` is the number it passes + // straight back as the next `timeoutMs`. It is computed from real + // elapsed time rather than from the cap, so the final read's cost is + // charged to the caller's budget instead of quietly vanishing from it. + ...(!done && cappedTimeoutMs < args.timeoutMs + ? { remainingMs: Math.max(0, args.timeoutMs - (Date.now() - startedAt)) } + : {}), ...(bounded.truncated ? { truncated: true } : {}), }) }, @@ -1413,18 +1435,55 @@ function orchestrationCreateAgentCallKey( ) } -// WHY 90 s and not the schema's 600 s maximum (#827): a foreground MCP tool -// call has to return while its transport is still listening. Claude Code -// backgrounds one at 120 s and the reply is then lost outright — the reported -// failure. 90 s leaves room under that threshold for the final -// `readRunOutputs` and serialization, and is long enough that an ordinary -// two-child run settles well inside one call. +// WHY 30 s and not the schema's 600 s maximum (#827): a foreground MCP tool +// call has to return while its transport is still listening. +// +// WHAT IS MEASURED, and what is not. The first version of this cap was 90 s, +// justified by "Claude Code backgrounds a tool call at 120 s". Review could +// not find that threshold anywhere, and the vendored source says the opposite: +// `vendor/claude-code-src/full/services/mcp/client.ts:211` sets +// `DEFAULT_MCP_TOOL_TIMEOUT_MS = 100_000_000` (~27.8 h) and passes it at the +// `callTool` site; backgrounding there belongs to shell and agent tasks, not +// to MCPTool. So that number was invented, and a cap derived from it was a +// guess wearing a fact's clothing. +// +// These are the numbers that are real, each checked in the tree: +// +// - `@modelcontextprotocol/sdk` … /shared/protocol.js:8 — +// `DEFAULT_REQUEST_TIMEOUT_MSEC = 60000`, applied as +// `options?.timeout ?? DEFAULT_REQUEST_TIMEOUT_MSEC`. ANY client that does +// not override it kills the request at 60 s. This is the binding +// constraint, and the 90 s cap sat ABOVE it: the old cap turned an +// occasional loss into a guaranteed one for such a client. Claude Code +// overrides (above) and Codex uses 300 s +// (`vendor/codex-src/codex-rs/codex-mcp/src/rmcp_client.rs`), but +// `opencode` and `grok` also receive the `orchestration` domain and their +// client timeouts are NOT known — a compiled binary, not readable source. +// So the cap has to assume the default. +// - This repo already bounds its other long-poll at 30 s +// (`workflow_run_events`' `waitMs: …max(30_000)`), and the control +// capability `observations.wait` at 10 s. 30 s is the house number for +// "a tool call that blocks while a transport listens". +// +// 30 s therefore leaves half the SDK's default budget for the final +// `readRunOutputs` round trip, which the bridge bounds at its own 30 s +// (`OrchestrationBridge` TIMEOUT_MS). +// +// WHAT THIS DOES NOT FIX, stated so nobody mistakes the cap for a cure: the +// reported drop is not clock-triggered. Our POST replies are SSE streams +// (`BuiltInMcpHttpHost` builds `StreamableHTTPServerTransport` with no +// `eventStore` and no `enableJsonResponse`), that stream carries ZERO bytes +// for the whole call, and with no event store it is not resumable — so when a +// client's SSE reconnects are exhausted the reply is gone for good. A shorter +// wait shortens the exposure window; it does not close it. The mechanism fixes +// are progress notifications (the SDK resets its request timer on progress) or +// `enableJsonResponse: true`, neither verified here — see #1091. // // It is a CAP, not a new maximum: `timeoutMs` still accepts up to 600 s // because the number the caller passes is what it wants in total, and the // reply says when a call was cut short. Lowering the schema bound instead // would make every existing caller's request invalid rather than shorter. -const WAIT_AGENTS_MAX_WAIT_MS = 90_000 +const WAIT_AGENTS_MAX_WAIT_MS = 30_000 // Cross-agent total budget for read_run_outputs / wait_agents (#373). // diff --git a/src/mcp/runtime/waitAgentsCap.system.test.ts b/src/mcp/runtime/waitAgentsCap.system.test.ts index 7fa33a230..5520211fd 100644 --- a/src/mcp/runtime/waitAgentsCap.system.test.ts +++ b/src/mcp/runtime/waitAgentsCap.system.test.ts @@ -4,35 +4,52 @@ import { describe, expect, it, vi } from 'vitest' import { createBuiltInMcpServer } from '@mcp/runtime/createBuiltInMcpServer.js' -// #827. A Claude 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: -// -// MCP server "agent_code" transport dropped mid-call; response for tool -// "orchestration_wait_agents" was lost -// -// The children were unaffected; a retry with 100 s returned normally. So any -// orchestration flow that waits past the harness's backgrounding threshold -// silently loses its wait result and has to fall back to polling -// `orchestration_list_agents` — a reliability failure in a first-party MCP -// surface, caused by us and not by the caller. +// #827. A Claude session waited on a two-child run with a generous timeout, +// the transport dropped mid-call, and the tool's response was LOST. The +// children were unaffected; a retry with 100 s returned normally. So any +// orchestration flow that waits long enough silently loses its wait result and +// falls back to polling `orchestration_list_agents` — a reliability failure in +// a first-party MCP surface, caused by us and not by the caller. // // The response already carried `done`, so the shape for polling existed. What // was missing was a server-side bound that keeps the reply inside the window // the caller can still receive it in. +// +// The ERROR TEXT quoted in #827 is a paraphrase, and the "120 s backgrounding +// threshold" the first version of this suite was written against does not +// exist in the vendored harness source. The bound these tests hold the tool to +// is the one that is real and checkable: the MCP SDK's own +// `DEFAULT_REQUEST_TIMEOUT_MSEC = 60000`, which every client that does not +// override it applies. See WAIT_AGENTS_MAX_WAIT_MS for the full accounting. function child(lifecycleState: string) { return { sessionId: 'child-1', kind: 'claude', cwd: '/repo', title: 'Child', lifecycleState, messageCount: 0 } } -async function callWait(args: Record, lifecycleState = 'running') { - const listAgents = vi.fn(async () => [child(lifecycleState)]) +async function callWait( + args: Record, + lifecycleState = 'running', + // Bridge latency is not a detail here: every one of these calls is a round + // trip that `OrchestrationBridge` serializes behind ONE in-flight slot and + // bounds at 30 s of its own. A harness with an instant bridge measures a + // wait that cannot happen, and it is exactly where the first version of the + // cap leaked — the post-loop read was outside the deadline entirely. + latency: { listMs?: number; readMs?: number } = {}, +) { + const listAgents = vi.fn(async () => { + if (latency.listMs) await new Promise(resolve => setTimeout(resolve, latency.listMs)) + return [child(lifecycleState)] + }) + const readRunOutputs = vi.fn(async () => { + if (latency.readMs) await new Promise(resolve => setTimeout(resolve, latency.readMs)) + return [] + }) const server = createBuiltInMcpServer( { sessionId: 'parent', cwd: '/repo', domains: ['orchestration'] }, { orchestrationBridge: { listAgents, - readRunOutputs: vi.fn(async () => []), + readRunOutputs, } as never, }, ) @@ -54,7 +71,7 @@ async function callWait(args: Record, lifecycleState = 'running ) const elapsedMs = Date.now() - startedAt const text = (result.content as Array<{ text: string }>)[0]!.text - return { payload: JSON.parse(text) as Record, elapsedMs, listAgents } + return { payload: JSON.parse(text) as Record, elapsedMs, listAgents, readRunOutputs } } finally { await client.close() await server.close() @@ -73,9 +90,12 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv // It returned, rather than running the full ten minutes into a transport // that is no longer listening. expect(payload.done).toBe(false) - // And it SAYS the wait was shortened. A silently short wait is a second - // surprise on top of the first: the caller asked for ten minutes. - expect(payload.waitCappedMs).toBe(90_000) + // And it SAYS the wait was shortened, in the form the caller can act on: + // its own UNSPENT budget, which is what the next call passes as + // timeoutMs. Reporting the cap instead made the caller reconstruct this + // from an argument it had to remember. + expect(payload.remainingMs).toBe(570_000) + expect(payload).not.toHaveProperty('waitCappedMs') } finally { vi.useRealTimers() } @@ -90,8 +110,8 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv // One read before the loop, then one per poll inside the cap. Anything // near 600 means the cap did not bound the loop. - expect(listAgents.mock.calls.length).toBeLessThanOrEqual(92) - expect(listAgents.mock.calls.length).toBeGreaterThan(80) + expect(listAgents.mock.calls.length).toBeLessThanOrEqual(32) + expect(listAgents.mock.calls.length).toBeGreaterThan(25) } finally { vi.useRealTimers() } @@ -108,7 +128,7 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv expect(payload.done).toBe(false) // No cap was applied, so the field is absent rather than reported as 0. - expect(payload).not.toHaveProperty('waitCappedMs') + expect(payload).not.toHaveProperty('remainingMs') expect(listAgents.mock.calls.length).toBeGreaterThan(25) expect(listAgents.mock.calls.length).toBeLessThanOrEqual(32) } finally { @@ -116,11 +136,111 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv } }) + it.each([ + { timeoutMs: 30_000, capped: false }, + { timeoutMs: 30_001, capped: true }, + { timeoutMs: 100_000, capped: true }, + ])('applies the cap on the right side of the boundary: timeoutMs=$timeoutMs', async ({ timeoutMs, capped }) => { + // Without a case between the cap and the schema maximum, a predicate like + // `timeoutMs > 150_000 ? cap : timeoutMs` passes the whole suite — and + // leaves the 100 s retry FROM THE BUG REPORT ITSELF uncapped. 30_001 is + // the boundary; 100_000 is the reported call. + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs, pollIntervalMs: 1_000 }) + await vi.advanceTimersByTimeAsync(timeoutMs) + const { payload, listAgents } = await pending + + expect(payload.done).toBe(false) + expect(Object.hasOwn(payload, 'remainingMs')).toBe(capped) + // Polls prove the WAIT was bounded, not only that a field was set. + expect(listAgents.mock.calls.length).toBeLessThanOrEqual(32) + } finally { + vi.useRealTimers() + } + }) + + it.each([ + // Capped: 7 s does not divide 30 s, so an unclamped sleep lands at 35 s. + { timeoutMs: 600_000, pollIntervalMs: 7_000, bound: 30_000 }, + // NOT capped, and the sharper case: the overshoot breaks the caller's OWN + // timeout. 25 s asked for, 30 s spent, and no cap was even involved. + { timeoutMs: 25_000, pollIntervalMs: 10_000, bound: 25_000 }, + ])('stops waiting exactly when it said it would: timeoutMs=$timeoutMs poll=$pollIntervalMs', async ({ timeoutMs, pollIntervalMs, bound }) => { + // The deadline is checked before the sleep, never during it, so an + // unclamped `sleep(pollIntervalMs)` overshoots by up to a whole interval — + // measured at 90_010 ms against the first version's 90_000 ms cap. A bound + // a caller-chosen argument can exceed is not a bound. + // + // The intervals are chosen NOT to divide the deadline. An earlier version + // of this test used 10 s against a 30 s cap, where clamped and unclamped + // land on the same tick — it passed on the broken code and proved nothing. + vi.useFakeTimers() + try { + // Measured AT RESOLUTION, inside the harness: `advanceTimersByTimeAsync` + // moves the clock the full span whatever the tool did, so reading the + // clock afterwards measures the test, not the tool. + const pending = callWait({ timeoutMs, pollIntervalMs }) + await vi.advanceTimersByTimeAsync(600_000) + const { elapsedMs } = await pending + + expect(elapsedMs).toBe(bound) + } finally { + vi.useRealTimers() + } + }) + + it('charges a slow final read to the caller\'s budget instead of losing it', async () => { + // The sharpest hole the first version had: nothing measured WHEN the reply + // arrived. The loop was capped and then an unbounded `readRunOutputs` ran + // after it — 60 s of post-loop work was invisible to every assertion, and + // that is the exact shape of the bug this tool is supposed to be fixing. + // + // The read itself cannot be cancelled from here (the bridge owns its own + // 30 s bound), so what is asserted is that its cost is ACCOUNTED FOR: the + // wait stops at the cap, and `remainingMs` is computed from real elapsed + // time, so the seconds the read spent come out of the caller's budget + // rather than quietly vanishing from it. + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 1_000 }, 'running', { readMs: 20_000 }) + await vi.advanceTimersByTimeAsync(600_000) + const { payload, elapsedMs } = await pending + + expect(elapsedMs).toBe(50_000) + expect(payload.remainingMs).toBe(550_000) + // Still well inside the SDK's 60 s default request timeout, which is the + // bound that actually decides whether this reply arrives. + expect(elapsedMs).toBeLessThan(60_000) + } finally { + vi.useRealTimers() + } + }) + + it('starts the clock before the first listAgents, not after it', async () => { + // That call is a round trip through a bridge that serializes every + // orchestration request behind one in-flight slot, so its queue wait has + // no bound. Starting the deadline after it would ADD that wait to the cap + // rather than spend it inside the cap — which is how a 30 s promise + // becomes a 60 s call on a busy app. + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 1_000 }, 'running', { listMs: 10_000 }) + await vi.advanceTimersByTimeAsync(600_000) + const { elapsedMs } = await pending + + // The first list costs 10 s of the 30 s cap; it does not extend it. + expect(elapsedMs).toBeLessThanOrEqual(40_000) + } finally { + vi.useRealTimers() + } + }) + it('returns at once when the children are already done, whatever the timeout', async () => { const { payload, elapsedMs } = await callWait({ timeoutMs: 600_000 }, 'completed') expect(payload.done).toBe(true) - expect(payload).not.toHaveProperty('waitCappedMs') + expect(payload).not.toHaveProperty('remainingMs') expect(elapsedMs).toBeLessThan(5_000) }) @@ -134,7 +254,18 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv await server.connect(serverTransport) await client.connect(clientTransport) const tool = (await client.listTools()).tools.find(item => item.name === 'orchestration_wait_agents') - expect(tool?.description).toContain('90') + // The number AND the instruction. `toContain('30')` alone was close to a + // free assertion — the old description said "90" and a mutant that + // changed the unit to MINUTES passed it. What an agent needs from this + // text is the bound, the unit, and what to do when it is hit. + expect(tool?.description).toContain('30 SECONDS') + expect(tool?.description).toMatch(/remainingMs/) + expect(tool?.description).toMatch(/call this again/i) + // The field description is a separate surface and was argued for + // separately in this PR: an agent choosing a timeout reads the SCHEMA. + const timeoutField = (tool?.inputSchema.properties as Record).timeoutMs + expect(timeoutField?.description).toContain('30 s') + expect(timeoutField?.description).toContain('remainingMs') } finally { await client.close() await server.close() From c863776c7f78a12a662fc548888e3b3331789a54 Mon Sep 17 00:00:00 2001 From: Julius Olsson Date: Sun, 20 Sep 2026 10:58:31 -0700 Subject: [PATCH 3/3] fix(orchestration): bound the whole call, not the sleeps between polls MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- src/mcp/runtime/createBuiltInMcpServer.ts | 226 +++++++++++----- src/mcp/runtime/waitAgentsCap.system.test.ts | 265 +++++++++++++++++-- 2 files changed, 404 insertions(+), 87 deletions(-) diff --git a/src/mcp/runtime/createBuiltInMcpServer.ts b/src/mcp/runtime/createBuiltInMcpServer.ts index e4cd6549c..b17d598ae 100644 --- a/src/mcp/runtime/createBuiltInMcpServer.ts +++ b/src/mcp/runtime/createBuiltInMcpServer.ts @@ -22,6 +22,7 @@ import { import type { OrchestrationAgentKind, OrchestrationAgentOutput, + OrchestrationAgentRecord, } from '@mcp/shared/orchestrationTypes.js' import { buildOrchestrationBootstrapPrompt } from '@mcp/shared/orchestrationPrompt.js' import type { BuiltInMcpDependencies } from '@mcp/runtime/BuiltInMcpHttpHost.js' @@ -1276,7 +1277,7 @@ function orchestrationCreateAgentCallKey( { title: 'Wait For Orchestration Agents', description: - `Waits for all matching orchestration-created child agents to leave active states, then returns their statuses and latest outputs. ONE CALL STOPS WAITING AFTER ${WAIT_AGENTS_MAX_WAIT_MS / 1000} SECONDS whatever timeoutMs asks for, then reads outputs once and replies; when it is cut short the reply carries done=false and remainingMs, and you call this again with remainingMs to keep waiting. Outputs are byte-capped per message/agent and share a cross-agent total budget; over-budget agents degrade to status summaries with short excerpts and truncated=true. To recover a truncated agent, re-read it with orchestration_read_agent and explicit larger caps, or use agent_transcript_read_file on its transcript.`, + `Waits for all matching orchestration-created child agents to leave active states, then returns their statuses and latest outputs. ONE CALL STOPS WAITING AFTER ${WAIT_AGENTS_MAX_WAIT_MS / 1000} SECONDS whatever timeoutMs asks for, then reads outputs once and replies; when it is cut short the reply carries done=false and, if any of your budget is left, remainingMs — call this again with that value to keep waiting. A cut-short reply can also carry outputsUnavailable=true, meaning the agents are reported but their outputs were not read in time; get them with orchestration_read_run_outputs. Outputs are byte-capped per message/agent and share a cross-agent total budget; over-budget agents degrade to status summaries with short excerpts and truncated=true. To recover a truncated agent, re-read it with orchestration_read_agent and explicit larger caps, or use agent_transcript_read_file on its transcript.`, inputSchema: { runId: z.string().optional(), sessionIds: z.array(z.string()).optional(), @@ -1314,69 +1315,153 @@ function orchestrationCreateAgentCallKey( const cappedTimeoutMs = Math.min(args.timeoutMs, WAIT_AGENTS_MAX_WAIT_MS) // Before the first `listAgents`, deliberately: that call is a round trip // through the bridge, which serializes every orchestration request - // app-wide behind one in-flight slot. Starting the clock after it would - // let an unbounded queue wait be added to the cap rather than spent - // inside it. + // app-wide behind one in-flight slot and puts NO timer on the queue wait + // (the bridge's 30 s `TIMEOUT_MS` starts only once dispatch is granted). + // Starting the clock after it would let that wait be added to the cap + // rather than spent inside it. const deadline = startedAt + cappedTimeoutMs - let agents = await bridge.listAgents({ parentSessionId: scope.sessionId, runId: args.runId }) - if (args.sessionIds && args.sessionIds.length > 0) { + // One deadline for the WHOLE call, raced against every bridge read — + // not a bound on the sleeps between them. + // + // WHY the clamped sleep is not enough (#1089 review, round 2): the loop + // checks the deadline before the sleep and never during an `await`, so + // clamping the sleep alone left each `listAgents` free to run past it. + // Measured, with a bridge under the contention its own comments describe + // ("with 20 orchestrated children it is common for several wait/list + // calls to poll the same parent/run during the same quarter-second"): + // one call took 87,250 ms against a 30 s promise — past the SDK's 60 s + // default request timeout, which is the reported bug reproduced by its + // own fix. + // + // This is the shape `observations.wait` already uses + // (`src/main/control/waits.ts`), including its accepted cost: losing the + // race leaves a read in flight, because the bridge has no cancellation. + // Nothing is retried and nothing is mutated by these reads, so a + // stranded one costs a slot for its own duration and no more. + let expired = false + let stopWaiting!: () => void + const expiry = new Promise(resolve => { + stopWaiting = () => resolve(EXPIRED) + }) + const expiryTimer = setTimeout(() => { expired = true; stopWaiting() }, cappedTimeoutMs) + // The measured cost of a bridge round trip on THIS call, used as the + // reserve the poll loop leaves for the final `readRunOutputs`. A fixed + // reserve would be another invented number; the last read's own duration + // is the only honest estimate available, and it grows automatically + // exactly when the bridge is congested. + let bridgeCostMs = 0 + const withDeadline = async (operation: Promise): Promise => { + const calledAt = Date.now() + const result = await Promise.race([operation, expiry]) + bridgeCostMs = Math.max(bridgeCostMs, Date.now() - calledAt) + return result + } + const scopeAgents = (list: OrchestrationAgentRecord[]): OrchestrationAgentRecord[] => { + if (!args.sessionIds || args.sessionIds.length === 0) return list const wanted = new Set(args.sessionIds) - agents = agents.filter(agent => wanted.has(agent.sessionId)) + return list.filter(agent => wanted.has(agent.sessionId)) } - while (Date.now() < deadline && agents.some(agent => isOrchestrationAgentActive(agent.lifecycleState))) { - // Clamped to what is LEFT, not the raw interval. `pollIntervalMs` is - // schema-legal up to 10 s, so an unclamped sleep let one call overshoot - // the cap by a whole interval — the deadline is checked before the - // sleep, never during it. Measured at 90_010 ms against a 90_000 ms - // cap before this clamp existed; a promise that is off by an argument - // the caller chooses is not a promise. - await sleep(Math.min(args.pollIntervalMs, Math.max(0, deadline - Date.now()))) - agents = await bridge.listAgents({ parentSessionId: scope.sessionId, runId: args.runId }) - if (args.sessionIds && args.sessionIds.length > 0) { - const wanted = new Set(args.sessionIds) - agents = agents.filter(agent => wanted.has(agent.sessionId)) + + try { + // `null` means NO READ SUCCEEDED, which is not the same as "no agents + // matched" and must never be reported as `done`. An empty list from a + // real read still means the run is finished; an empty list because the + // read lost the race means we know nothing. + let agents: OrchestrationAgentRecord[] | null = null + const first = await withDeadline(bridge.listAgents({ parentSessionId: scope.sessionId, runId: args.runId })) + if (first !== EXPIRED) agents = scopeAgents(first) + while ( + !expired + && agents !== null + && agents.some(agent => isOrchestrationAgentActive(agent.lifecycleState)) + // Stop polling once what is left would not cover another round trip + // plus the final read. Without this the loop spends the entire + // budget on polling and the reply's outputs are always the thing + // that gets dropped. + && Date.now() + bridgeCostMs * 2 < deadline + ) { + // Clamped to what is LEFT, not the raw interval. `pollIntervalMs` is + // schema-legal up to 10 s, so an unclamped sleep overshot the cap by + // a whole interval: measured 90_010 ms against a 90_000 ms cap. + await sleep(Math.min(args.pollIntervalMs, Math.max(0, deadline - Date.now()))) + const next = await withDeadline(bridge.listAgents({ parentSessionId: scope.sessionId, runId: args.runId })) + if (next === EXPIRED) break + // The scope is re-applied on EVERY poll, not only the first read: a + // child created after the call started would otherwise join the set + // the caller explicitly named, and its activity would keep a + // `sessionIds` wait running past the agents it asked about. + agents = scopeAgents(next) } + const agentIds = new Set((agents ?? []).map(agent => agent.sessionId)) + const read = agents === null + ? EXPIRED + : await withDeadline(bridge.readRunOutputs({ + parentSessionId: scope.sessionId, + runId: args.runId, + maxMessagesPerAgent: args.maxMessagesPerAgent, + maxCharsPerMessage: args.maxCharsPerMessage, + maxCharsPerAgent: args.maxCharsPerAgent, + })) + const outputs = read === EXPIRED + ? [] + : read.filter(output => agentIds.has(output.agent.sessionId)) + // The `agents` status array below is part of the same tool response, so + // its JSON size is charged against maxTotalChars as reservedChars — + // otherwise wait_agents' real payload would exceed the budget by + // exactly the part the budget was never told about (#510 review). + // Status records carry no message bodies, so this reservation is small + // and proportional to agent count, not output size. + const bounded = boundOutputsToTotalChars( + outputs, + args.maxTotalChars, + JSON.stringify(agents ?? []).length, + ) + // `done` requires a read that actually happened. A list we never got + // is empty, and an empty list otherwise means "the run has finished" — + // the exact shape that tells a parent every child is done while one is + // still working. + const done = agents !== null && !agents.some(agent => isOrchestrationAgentActive(agent.lifecycleState)) + const elapsedMs = Date.now() - startedAt + const remainingMs = Math.max(0, args.timeoutMs - elapsedMs) + return toolText({ + ok: true, + done, + agents: agents ?? [], + outputs: bounded.outputs, + // Only when the cap actually cut the wait short, there is still + // something to wait for, and what is left is a LEGAL next + // `timeoutMs`. Reporting it on a completed run would tell the caller + // to call again for children that are already done. + // + // The caller's UNSPENT budget, not the cap: reporting the cap made + // the caller reconstruct "how much of what I asked for is left" from + // an argument it had to remember. It is computed from real elapsed + // time, so the final read's cost comes out of that budget instead of + // vanishing from it. + // + // WHY the schema minimum is the floor for reporting it (#1089 + // review, round 2): `timeoutMs` is `min(1000)`, and the description + // tells the caller to pass this straight back. A remainder of 500 — + // reachable from any `timeoutMs` whose remainder mod the cap lands + // under a second — then walked the documented recovery path into a + // hard `-32602` validation error. Omitting it says the same thing + // the `timeoutMs <= cap` case already says: your budget is spent. + ...(!done && cappedTimeoutMs < args.timeoutMs && remainingMs >= MIN_WAIT_AGENTS_TIMEOUT_MS + ? { remainingMs } + : {}), + // The call hit its own deadline with reads still outstanding. Said + // out loud because the reply is PARTIAL: without this a caller + // cannot tell "no outputs, the children produced none" from "no + // outputs, we ran out of time before reading them". + ...(agents === null ? { agentsUnavailable: true } : {}), + ...(read === EXPIRED && agents !== null ? { outputsUnavailable: true } : {}), + ...(bounded.truncated ? { truncated: true } : {}), + }) + } finally { + // Always: an early return or a throw would otherwise leave a 30 s + // timer holding the event loop open after the reply was sent. + clearTimeout(expiryTimer) } - const agentIds = new Set(agents.map(agent => agent.sessionId)) - const outputs = await bridge.readRunOutputs({ - parentSessionId: scope.sessionId, - runId: args.runId, - maxMessagesPerAgent: args.maxMessagesPerAgent, - maxCharsPerMessage: args.maxCharsPerMessage, - maxCharsPerAgent: args.maxCharsPerAgent, - }).then(outputs => outputs.filter(output => agentIds.has(output.agent.sessionId))) - // The `agents` status array below is part of the same tool response, so - // its JSON size is charged against maxTotalChars as reservedChars — - // otherwise wait_agents' real payload would exceed the budget by - // exactly the part the budget was never told about (#510 review). - // Status records carry no message bodies, so this reservation is small - // and proportional to agent count, not output size. - const bounded = boundOutputsToTotalChars( - outputs, - args.maxTotalChars, - JSON.stringify(agents).length, - ) - const done = !agents.some(agent => isOrchestrationAgentActive(agent.lifecycleState)) - return toolText({ - ok: true, - done, - agents, - outputs: bounded.outputs, - // Only when the cap actually cut the wait short AND there is still - // something to wait for. Reporting it on a completed run would tell - // the caller to call again for children that are already done. - // - // The caller's UNSPENT budget, not the cap. Reporting the cap made the - // caller reconstruct "how much of what I asked for is left" from an - // argument it had to remember; `remainingMs` is the number it passes - // straight back as the next `timeoutMs`. It is computed from real - // elapsed time rather than from the cap, so the final read's cost is - // charged to the caller's budget instead of quietly vanishing from it. - ...(!done && cappedTimeoutMs < args.timeoutMs - ? { remainingMs: Math.max(0, args.timeoutMs - (Date.now() - startedAt)) } - : {}), - ...(bounded.truncated ? { truncated: true } : {}), - }) }, ) @@ -1476,8 +1561,11 @@ function orchestrationCreateAgentCallKey( // for the whole call, and with no event store it is not resumable — so when a // client's SSE reconnects are exhausted the reply is gone for good. A shorter // wait shortens the exposure window; it does not close it. The mechanism fixes -// are progress notifications (the SDK resets its request timer on progress) or -// `enableJsonResponse: true`, neither verified here — see #1091. +// are progress notifications or `enableJsonResponse: true`, neither verified +// here — see #1091. Progress extends a client's timer only when that client +// OPTS IN (`resetTimeoutOnProgress`, default false in the SDK): OpenCode does, +// Claude Code does not. So it is a partial mitigation, not the cure it first +// looked like. // // It is a CAP, not a new maximum: `timeoutMs` still accepts up to 600 s // because the number the caller passes is what it wants in total, and the @@ -1485,6 +1573,22 @@ function orchestrationCreateAgentCallKey( // would make every existing caller's request invalid rather than shorter. const WAIT_AGENTS_MAX_WAIT_MS = 30_000 +/** + * The schema's own floor for `timeoutMs`, named once so the handler can refuse + * to hand a caller a `remainingMs` the schema would then reject (#1089 review). + */ +const MIN_WAIT_AGENTS_TIMEOUT_MS = 1_000 + +/** + * "This read lost the race against the call's deadline." + * + * A unique symbol rather than null/undefined because a bridge read can + * legitimately resolve to an empty array, and the difference between "no + * agents" and "we never found out" is what decides whether the reply may say + * `done`. + */ +const EXPIRED = Symbol('wait-agents-expired') + // Cross-agent total budget for read_run_outputs / wait_agents (#373). // // WHY this lives in the tool handler and not in the renderer or bridge: the diff --git a/src/mcp/runtime/waitAgentsCap.system.test.ts b/src/mcp/runtime/waitAgentsCap.system.test.ts index 5520211fd..0f9c5dbdb 100644 --- a/src/mcp/runtime/waitAgentsCap.system.test.ts +++ b/src/mcp/runtime/waitAgentsCap.system.test.ts @@ -22,8 +22,8 @@ import { createBuiltInMcpServer } from '@mcp/runtime/createBuiltInMcpServer.js' // `DEFAULT_REQUEST_TIMEOUT_MSEC = 60000`, which every client that does not // override it applies. See WAIT_AGENTS_MAX_WAIT_MS for the full accounting. -function child(lifecycleState: string) { - return { sessionId: 'child-1', kind: 'claude', cwd: '/repo', title: 'Child', lifecycleState, messageCount: 0 } +function child(lifecycleState: string, sessionId = 'child-1') { + return { sessionId, kind: 'claude', cwd: '/repo', title: 'Child', lifecycleState, messageCount: 0 } } async function callWait( @@ -34,10 +34,20 @@ async function callWait( // bounds at 30 s of its own. A harness with an instant bridge measures a // wait that cannot happen, and it is exactly where the first version of the // cap leaked — the post-loop read was outside the deadline entirely. - latency: { listMs?: number; readMs?: number } = {}, + // `listMs` may be a per-call list: a bridge that is fast and then stalls is + // the case that separates "the deadline is checked between polls" from "the + // deadline is raced against the poll", and a constant latency cannot express + // it. The last entry repeats. + latency: { listMs?: number | number[]; readMs?: number } = {}, ) { + let listCall = 0 const listAgents = vi.fn(async () => { - if (latency.listMs) await new Promise(resolve => setTimeout(resolve, latency.listMs)) + const schedule = latency.listMs + const delay = Array.isArray(schedule) + ? schedule[Math.min(listCall, schedule.length - 1)] ?? 0 + : schedule ?? 0 + listCall += 1 + if (delay) await new Promise(resolve => setTimeout(resolve, delay)) return [child(lifecycleState)] }) const readRunOutputs = vi.fn(async () => { @@ -137,14 +147,24 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv }) it.each([ - { timeoutMs: 30_000, capped: false }, - { timeoutMs: 30_001, capped: true }, - { timeoutMs: 100_000, capped: true }, - ])('applies the cap on the right side of the boundary: timeoutMs=$timeoutMs', async ({ timeoutMs, capped }) => { - // Without a case between the cap and the schema maximum, a predicate like + // Inside the cap: nothing was cut short, so nothing to report. + { timeoutMs: 30_000, remainingMs: undefined }, + // Cut short, but the remainder is 1 ms — BELOW the schema's own + // `min(1000)` for timeoutMs. Reporting it walked the documented recovery + // path ("call this again with remainingMs") straight into an MCP -32602 + // validation error, which is a worse answer than the silence this PR set + // out to replace. Omitted means what it means everywhere else here: your + // budget is spent. + { timeoutMs: 30_001, remainingMs: undefined }, + { timeoutMs: 30_500, remainingMs: undefined }, + // Legal remainder: reported, and it is exactly what the next call passes. + { timeoutMs: 31_000, remainingMs: 1_000 }, + // The retry from the bug report itself. + { timeoutMs: 100_000, remainingMs: 70_000 }, + ])('reports a remainder only when it is a legal next timeoutMs: $timeoutMs', async ({ timeoutMs, remainingMs }) => { + // Without cases between the cap and the schema maximum, a predicate like // `timeoutMs > 150_000 ? cap : timeoutMs` passes the whole suite — and - // leaves the 100 s retry FROM THE BUG REPORT ITSELF uncapped. 30_001 is - // the boundary; 100_000 is the reported call. + // leaves the 100 s retry FROM THE BUG REPORT uncapped. vi.useFakeTimers() try { const pending = callWait({ timeoutMs, pollIntervalMs: 1_000 }) @@ -152,7 +172,7 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv const { payload, listAgents } = await pending expect(payload.done).toBe(false) - expect(Object.hasOwn(payload, 'remainingMs')).toBe(capped) + expect(payload.remainingMs).toBe(remainingMs) // Polls prove the WAIT was bounded, not only that a field was set. expect(listAgents.mock.calls.length).toBeLessThanOrEqual(32) } finally { @@ -160,6 +180,33 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv } }) + it('walks its own documented recovery path to the end', async () => { + // The instruction in the tool description is "call this again with + // remainingMs". A caller that follows it literally must never be handed a + // value the schema then rejects — and it was: any starting timeout whose + // remainder mod the cap fell under a second ended the loop on a -32602. + vi.useFakeTimers() + try { + let timeoutMs = 60_500 + const seen: number[] = [] + for (let call = 0; call < 5; call += 1) { + const pending = callWait({ timeoutMs, pollIntervalMs: 1_000 }) + await vi.advanceTimersByTimeAsync(timeoutMs) + const { payload } = await pending + const next = payload.remainingMs as number | undefined + if (next === undefined) break + expect(next).toBeGreaterThanOrEqual(1_000) + seen.push(next) + timeoutMs = next + } + // 60_500 → 30_500 → (500, illegal) so the chain stops honestly rather + // than handing over a value that cannot be sent. + expect(seen).toEqual([30_500]) + } finally { + vi.useRealTimers() + } + }) + it.each([ // Capped: 7 s does not divide 30 s, so an unclamped sleep lands at 35 s. { timeoutMs: 600_000, pollIntervalMs: 7_000, bound: 30_000 }, @@ -190,33 +237,138 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv } }) - it('charges a slow final read to the caller\'s budget instead of losing it', async () => { - // The sharpest hole the first version had: nothing measured WHEN the reply - // arrived. The loop was capped and then an unbounded `readRunOutputs` ran - // after it — 60 s of post-loop work was invisible to every assertion, and - // that is the exact shape of the bug this tool is supposed to be fixing. + it('drops the outputs rather than the reply when the final read would run past the cap', async () => { + // The sharpest hole round 1 left: nothing measured WHEN the reply arrived. + // The loop was capped and then an unbounded `readRunOutputs` ran after it, + // so 20 s of post-loop work was invisible to every assertion — the exact + // shape of the bug this tool exists to prevent. // - // The read itself cannot be cancelled from here (the bridge owns its own - // 30 s bound), so what is asserted is that its cost is ACCOUNTED FOR: the - // wait stops at the cap, and `remainingMs` is computed from real elapsed - // time, so the seconds the read spent come out of the caller's budget - // rather than quietly vanishing from it. + // A cut-short wait now returns its agents at the cap and SAYS the outputs + // are missing, rather than holding the reply open for a read the caller's + // transport may not still be listening for. The caller can read them with + // `orchestration_read_run_outputs` on a fresh budget; it cannot recover a + // reply that was dropped in flight. vi.useFakeTimers() try { const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 1_000 }, 'running', { readMs: 20_000 }) await vi.advanceTimersByTimeAsync(600_000) const { payload, elapsedMs } = await pending - expect(elapsedMs).toBe(50_000) - expect(payload.remainingMs).toBe(550_000) - // Still well inside the SDK's 60 s default request timeout, which is the - // bound that actually decides whether this reply arrives. + expect(elapsedMs).toBe(30_000) + expect(payload.outputsUnavailable).toBe(true) + expect(payload.outputs).toEqual([]) + // The agents it DID read are still reported, and so is the remainder. + expect((payload.agents as unknown[]).length).toBe(1) + expect(payload.remainingMs).toBe(570_000) + // Well inside the 60 s floor that decides whether this reply arrives. expect(elapsedMs).toBeLessThan(60_000) } finally { vi.useRealTimers() } }) + it('returns the outputs when the run finishes with budget to spare', async () => { + // The control for the case above. "Always drop the outputs" would satisfy + // it and gut the tool: the reply that matters most — the run finished — is + // the one that must carry them. + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 1_000 }, 'completed', { readMs: 5_000 }) + await vi.advanceTimersByTimeAsync(600_000) + const { payload, elapsedMs } = await pending + + expect(payload.done).toBe(true) + expect(payload).not.toHaveProperty('outputsUnavailable') + expect(elapsedMs).toBe(5_000) + } finally { + vi.useRealTimers() + } + }) + + it.each([ + // Each row is the measured end of the call, and each is EARLIER than the + // 30 s cap on purpose: the loop stops once what is left would not cover + // another round trip plus the final read. The reserve is the measured cost + // of this call's own bridge reads, not an invented constant, so it grows + // exactly when the bridge is congested — which is when it matters. + { listMs: 5_000, elapsed: 20_750 }, + // One round trip costs two thirds of the budget: there is no second poll + // to be had, so the call does not pretend otherwise. + { listMs: 20_000, elapsed: 20_000 }, + // The round-2 measurement: this was 58,250 ms before the reads were raced. + { listMs: 29_000, elapsed: 29_000 }, + ])('bounds a poll whose listAgents takes $listMs ms, not just the sleep between polls', async ({ listMs, elapsed }) => { + // Round 2's blocking finding, measured: the deadline is checked before the + // sleep and never during an `await`, so clamping the SLEEP left every + // in-loop `listAgents` free to run past it. With a bridge under the + // contention its own comments describe — one in-flight slot for every + // orchestration request app-wide, no timer on the queue wait — one call + // was 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. + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 250 }, 'running', { listMs }) + await vi.advanceTimersByTimeAsync(600_000) + const { elapsedMs } = await pending + + expect(elapsedMs).toBe(elapsed) + // The invariant the exact numbers above are instances of. + expect(elapsedMs).toBeLessThanOrEqual(30_000) + } finally { + vi.useRealTimers() + } + }) + + it('cuts off a poll that stalls AFTER the bridge looked healthy', async () => { + // The reserve the loop keeps for the final read is the measured cost of + // this call's own reads, so a bridge that is fast and then stalls gets + // into the loop with almost no reserve — and that is exactly when + // contention arrives, since `MAX_ACTIVE_RENDERER_REQUESTS = 1` serializes + // every orchestration request app-wide behind one slot with no timer on + // the queue. + // + // Three instant polls, then a 45 s stall. Checking the deadline BETWEEN + // polls cannot help here: the stall happens inside the `await`. Only + // racing the read against the deadline can, and without the race this + // returns at 45,750 ms — past the 60 s floor once a slow final read is + // added, which is the 87 s call round 2 measured. + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 250 }, 'running', { listMs: [0, 0, 0, 45_000] }) + await vi.advanceTimersByTimeAsync(600_000) + const { payload, elapsedMs } = await pending + + expect(elapsedMs).toBe(30_000) + // And what it reports is what it actually knows: the last good read. + expect(payload.done).toBe(false) + } finally { + vi.useRealTimers() + } + }) + + it('never reports done when it could not read the agents at all', async () => { + // The dangerous shape, and the reason an expired read is not just "no + // agents": `done` is computed over the list, so an EMPTY list reads as + // "every child finished". A list that was never read must therefore be + // distinguishable from a list that came back empty — otherwise a call that + // ran out of time reports exactly the false completion this whole tool is + // about. + vi.useFakeTimers() + try { + const pending = callWait({ timeoutMs: 600_000, pollIntervalMs: 250 }, 'running', { listMs: 40_000 }) + await vi.advanceTimersByTimeAsync(600_000) + const { payload, elapsedMs } = await pending + + expect(elapsedMs).toBe(30_000) + expect(payload.done).toBe(false) + expect(payload.agentsUnavailable).toBe(true) + expect(payload.agents).toEqual([]) + } finally { + vi.useRealTimers() + } + }) + it('starts the clock before the first listAgents, not after it', async () => { // That call is a round trip through a bridge that serializes every // orchestration request behind one in-flight slot, so its queue wait has @@ -236,6 +388,67 @@ describe('orchestration_wait_agents stays inside the window its reply can surviv } }) + it('keeps the sessionIds scope on every poll, not only the first read', async () => { + // A `sessionIds` wait is a question about NAMED children. The filter used + // to be re-applied each iteration and a reviewer's mutation that dropped + // the in-loop copy survived the whole suite, because no case had a run + // whose membership CHANGES while the wait is open. + // + // It does change: `create_agent` can add a child to the same run at any + // time. With the scope applied only once, that newcomer joins the set the + // caller explicitly named, and its activity keeps the wait open long past + // the children the caller asked about — reported, eventually, as those + // children's result. + vi.useFakeTimers() + try { + // The named child is still working, so the wait actually polls — the + // first read alone would never reach the in-loop filter. + let roster = [child('running', 'asked-about')] + const listAgents = vi.fn(async () => roster) + const server = createBuiltInMcpServer( + { sessionId: 'parent', cwd: '/repo', domains: ['orchestration'] }, + { orchestrationBridge: { listAgents, readRunOutputs: vi.fn(async () => []) } as never }, + ) + const client = new Client({ name: 'wait-scope-test', version: '0.0.0' }) + const [clientTransport, serverTransport] = InMemoryTransport.createLinkedPair() + try { + await server.connect(serverTransport) + await client.connect(clientTransport) + const startedAt = Date.now() + // Measured AT RESOLUTION: `advanceTimersByTimeAsync` moves the clock + // the full span whatever the tool did, so reading it afterwards + // measures the test rather than the tool. (This is the third time that + // has caught me in this file; it is why the shared harness does it.) + let resolvedAt = 0 + const pending = client.callTool( + { name: 'orchestration_wait_agents', arguments: { timeoutMs: 600_000, pollIntervalMs: 1_000, sessionIds: ['asked-about'] } }, + undefined, + { timeout: 10_000_000 }, + ).then(result => { resolvedAt = Date.now(); return result }) + // The named child finishes, and a stranger joins the same run at the + // same moment — exactly what create_agent does while a wait is open. + await vi.advanceTimersByTimeAsync(2_000) + roster = [child('completed', 'asked-about'), child('running', 'newcomer')] + await vi.advanceTimersByTimeAsync(600_000) + const result = await pending + const elapsedMs = resolvedAt - startedAt + const payload = JSON.parse((result.content as Array<{ text: string }>)[0]!.text) as Record + + // The wait ends when the NAMED child finishes. With the scope applied + // only to the first read, the newcomer's activity keeps it open to the + // cap and the caller waits 30 s for an agent it never asked about. + expect(payload.done).toBe(true) + expect((payload.agents as Array<{ sessionId: string }>).map(agent => agent.sessionId)).toEqual(['asked-about']) + expect(elapsedMs).toBeLessThan(4_000) + } finally { + await client.close() + await server.close() + } + } finally { + vi.useRealTimers() + } + }) + it('returns at once when the children are already done, whatever the timeout', async () => { const { payload, elapsedMs } = await callWait({ timeoutMs: 600_000 }, 'completed')