From ed817600b0a9858f1331d7a9151cef737f0ad52d Mon Sep 17 00:00:00 2001 From: liuedcson <332840681+liuedcson@users.noreply.github.com> Date: Tue, 27 Oct 2026 21:26:40 +0800 Subject: [PATCH 1/8] fix(coding-agent): bound subagent live updates instead of re-sending the transcript MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A blocking `subagent` call mirrored every child event into one `tool_execution_update`. `parseJsonEvent` fires on each streamed delta, and each update carried a copy of the child's whole `messages` array. Only `message_end` changes that array, so every update between two of them was a byte-identical repeat, and the `json`/`rpc` modes write one JSONL line per event — the parent's event log became the transcript squared. Measured with a local rpc child streaming 40 turns x 150 deltas with 40 KB tool results: 4,992 MiB of JSONL, 6,327 updates, 82 distinct snapshots, 99.8% of the bytes inside `messages`, largest single line 1.63 MiB. That matches the benchmark logs (P95 4.28 GiB, max 11.7 GiB, 2.8 MB updates). Three bounds, each closing a different part of the hole: - The live projection carries no `messages`; it keeps only a short tail of the streamed text and tool output. The transcript is published once, in the final result. - Updates are coalesced to one per 100 ms (the bash tool's cadence). Status transitions still publish immediately, so a live list never misses a change, and a trailing update is flushed before the call returns. - The final result keeps the newest messages that fit 64 KiB. `activeText`, `sessionId` and `sessionFile` keep the outcome reachable. `toJsonEvent` also caps a single `tool_execution_update` at 256 KiB and replaces an oversized one with the tail of its text plus a marker. That is a generic backstop for any tool that re-sends accumulated state; the terminal event is never bounded. Same scenario after the change: 0.31 MiB, 3 updates, 0.06 MiB final result. --- .../docs/tool-output-retention.md | 20 ++ .../src/features/subagent/execute.ts | 199 ++++++++++++++---- packages/coding-agent/src/modes/json-event.ts | 62 ++++++ .../json-event-live-update-budget.test.ts | 55 +++++ .../test/subagent-live-update-budget.test.ts | 178 ++++++++++++++++ 5 files changed, 471 insertions(+), 43 deletions(-) create mode 100644 packages/coding-agent/test/json-event-live-update-budget.test.ts create mode 100644 packages/coding-agent/test/subagent-live-update-budget.test.ts diff --git a/packages/coding-agent/docs/tool-output-retention.md b/packages/coding-agent/docs/tool-output-retention.md index d253a8b75..1127fb449 100644 --- a/packages/coding-agent/docs/tool-output-retention.md +++ b/packages/coding-agent/docs/tool-output-retention.md @@ -33,3 +33,23 @@ termination policy remains in force. Small results create no artifact and are un This bounds final model-facing text, not streaming progress updates or arbitrary typed `details` payloads. No new permission bypass or external upload is added. + +## Live tool updates + +A tool's `onUpdate` callbacks are progress, not results. They run while the call +is in flight and each one becomes a `tool_execution_update` session event, which +the `json` and `rpc` modes write as one JSONL line — so a host that redirects +that stream to a file turns progress into log volume. Two bounds keep that +volume proportional to wall-clock time instead of to the work already done: + +- A producer sends at most one update per 100 ms (the same cadence the bash tool + uses) and publishes state transitions immediately. +- A live update carries no `messages` transcript, and its streamed text is held + to a short tail. The complete transcript is published once, in the final + result, itself capped at 64 KiB of the newest messages. Older messages stay + readable through the child session id or `sessionFile`. + +`toJsonEvent` additionally bounds a single `tool_execution_update` at 256 KiB +and replaces anything larger with the tail of its text plus a truncation marker. +That backstop exists for third-party tools that re-send accumulated state; it +never applies to `tool_execution_end`, which carries the real result. diff --git a/packages/coding-agent/src/features/subagent/execute.ts b/packages/coding-agent/src/features/subagent/execute.ts index 3d1a26f39..77be0b66a 100644 --- a/packages/coding-agent/src/features/subagent/execute.ts +++ b/packages/coding-agent/src/features/subagent/execute.ts @@ -48,6 +48,41 @@ import { import { truncateText } from "./lane-events.ts"; import type { StepSubagentLaneRuntime } from "./lane-lifecycle.ts"; +/** + * Live-update budget. + * + * A blocking call mirrors every child event into one `onUpdate`, and the Agent + * Loop turns each of them into a `tool_execution_update` that hosts persist: the + * `json`/`rpc` modes write one JSONL line per event, so the parent's event log + * *is* this stream. Two independent properties keep that stream from growing + * with the child's transcript: + * + * - `LIVE_UPDATE_INTERVAL_MS` caps the rate (the bash tool throttles at the same + * 100ms; a faster cadence buys no visible UI change). + * - The live projection drops `messages` entirely and keeps only the tail of the + * streamed text, so one update is bounded regardless of how much the child has + * produced. The full transcript is published once, in the final result. + * + * Without both, a 20-turn child emits ~1.4k updates that each carry the whole + * transcript: 99% of the log is byte-identical repeats. + */ +const LIVE_UPDATE_INTERVAL_MS = 100; +const LIVE_TEXT_CHARS = 2_000; +const LIVE_TOOL_OUTPUT_CHARS = 1_000; +const LIVE_TOOL_ARGS_CHARS = 500; + +/** + * Final-result budget for the child transcript embedded in the tool result. + * + * The final details are persisted once per call, so this is not a rate problem, + * but a long child can still hold megabytes of tool output that the parent never + * renders. Keep the newest messages that fit; the final assistant text stays in + * `activeText`, and `sessionFile`/`sessionId` point at the child's own + * transcript for anything older. 64 KiB matches the cap the other hosts in this + * repository apply to a persisted command result. + */ +const FINAL_MESSAGES_BYTES = 64 * 1024; + export interface StepSubagentTaskInput { agent: string; task: string; @@ -152,6 +187,41 @@ function buildDetails( }; } +/** Keep the tail of a streamed field: the UI renders the newest lines. */ +function tailChars(value: string | undefined, max: number): string | undefined { + if (value === undefined || value.length <= max) return value; + return `\u2026${value.slice(-max)}`; +} + +/** + * Project one record for a live update. `messages` is deliberately empty: the + * transcript changes only at `message_end`, so a per-event copy re-sends the + * same array hundreds of times between two of them. + */ +function liveRecord(record: StepSubagentResultRecord): StepSubagentResultRecord { + return { + ...record, + messages: [], + activeText: tailChars(record.activeText, LIVE_TEXT_CHARS), + activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS), + activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS), + usage: cloneUsage(record.usage), + }; +} + +/** Newest messages that fit the final-result budget, oldest first. */ +function boundedMessages(messages: readonly unknown[]): StepSubagentRunResult["messages"] { + const kept: unknown[] = []; + let bytes = 0; + for (let index = messages.length - 1; index >= 0; index -= 1) { + const size = Buffer.byteLength(JSON.stringify(messages[index]) ?? "", "utf8"); + if (bytes + size > FINAL_MESSAGES_BYTES) break; + bytes += size; + kept.push(messages[index]); + } + return kept.reverse() as StepSubagentRunResult["messages"]; +} + async function mapWithConcurrency( items: readonly T[], concurrency: number, @@ -396,22 +466,52 @@ export async function runPreparedSubagent( duration_ms: Math.max(0, Date.now() - (createdAt[index] ?? Date.now())), }); }; + const statusKey = (): string => records.map((record) => record.status).join("\u0000"); + let lastStatusKey = ""; + let lastPublishAt = 0; + let pendingPublish: ReturnType | undefined; + + const publish = (mode: StepSubagentDetails["mode"]): void => { + if (!onUpdate) return; + lastPublishAt = Date.now(); + lastStatusKey = statusKey(); + const live = buildDetails(mode, discovery, scope, records.map(liveRecord)); + onUpdate(makeToolResult(live, resultDetailsText(live))); + }; + + /** + * Publish the live roster, coalescing streamed updates. + * + * A status transition is always published at once: it is the only change the + * live list shows besides the token counter, and readers rely on seeing every + * one of them. Everything in between (a streamed delta, a tool-output chunk) + * waits for the interval, with the latest records winning. + */ const emit = (mode: StepSubagentDetails["mode"]): void => { - onUpdate?.( - makeToolResult( - buildDetails( - mode, - discovery, - scope, - records.map((record) => ({ - ...record, - messages: [...record.messages], - usage: cloneUsage(record.usage), - })), - ), - resultDetailsText(buildDetails(mode, discovery, scope, records)), - ), - ); + if (!onUpdate) return; + const wait = LIVE_UPDATE_INTERVAL_MS - (Date.now() - lastPublishAt); + if (statusKey() !== lastStatusKey || wait <= 0) { + if (pendingPublish) { + clearTimeout(pendingPublish); + pendingPublish = undefined; + } + publish(mode); + return; + } + pendingPublish ??= setTimeout(() => { + pendingPublish = undefined; + publish(mode); + }, wait); + pendingPublish.unref?.(); + }; + + /** Publish the last coalesced update so the caller's final state is not dropped. */ + const flushEmit = (mode: StepSubagentDetails["mode"]): void => { + if (pendingPublish) { + clearTimeout(pendingPublish); + pendingPublish = undefined; + publish(mode); + } }; const runOne = async ( @@ -552,35 +652,48 @@ export async function runPreparedSubagent( // records are already seeded by makeEmptyResult, so this renders every lane // at 0s, including ones still queued behind maxConcurrency. emit(mode); - if (parallel) { - // The configured provider limit caps subagent batches the same way it caps workflows. - const ceiling = Math.min(options.maxConcurrency, clampWorkflowConcurrency(configuredWorkflowConcurrencyLimit())); - const lease = acquireWorkflowAdmission(ceiling); - try { - await mapWithConcurrency(parallel, ceiling, (task, index) => runOne(task, index, lease.semaphore)); - } finally { - lease.release(); - } - } else if (chain) { - let previous = ""; - for (let index = 0; index < chain.length; index++) { - const task = { - ...chain[index], - // Function replacement inserts `previous` verbatim. A string replacement would - // let $-patterns in the prior subagent's output ($&, $`, $', $$) be reinterpreted - // by String.prototype.replace, corrupting the next task's prompt. - task: chain[index].task.replace(/\{previous\}/g, () => previous), - }; - const record = await runOne(task, index); - previous = finalOutput(record.messages) || resultText(record); - if (record.status !== "completed") { - for (let rest = index + 1; rest < chain.length; rest++) records[rest] = makeSkippedResult(records[rest]); - emit(mode); - break; + try { + if (parallel) { + // The configured provider limit caps subagent batches the same way it caps workflows. + const ceiling = Math.min( + options.maxConcurrency, + clampWorkflowConcurrency(configuredWorkflowConcurrencyLimit()), + ); + const lease = acquireWorkflowAdmission(ceiling); + try { + await mapWithConcurrency(parallel, ceiling, (task, index) => runOne(task, index, lease.semaphore)); + } finally { + lease.release(); } - } - } else await runOne(tasks[0], 0); - const finalDetails = buildDetails(mode, discovery, scope, records); + } else if (chain) { + let previous = ""; + for (let index = 0; index < chain.length; index++) { + const task = { + ...chain[index], + // Function replacement inserts `previous` verbatim. A string replacement would + // let $-patterns in the prior subagent's output ($&, $`, $', $$) be reinterpreted + // by String.prototype.replace, corrupting the next task's prompt. + task: chain[index].task.replace(/\{previous\}/g, () => previous), + }; + const record = await runOne(task, index); + previous = finalOutput(record.messages) || resultText(record); + if (record.status !== "completed") { + for (let rest = index + 1; rest < chain.length; rest++) records[rest] = makeSkippedResult(records[rest]); + emit(mode); + break; + } + } + } else await runOne(tasks[0], 0); + } finally { + // A trailing coalesced update must not outlive the call or be lost. + flushEmit(mode); + } + const finalDetails = buildDetails( + mode, + discovery, + scope, + records.map((record) => ({ ...record, messages: boundedMessages(record.messages) })), + ); if (mode === "parallel") { const success = records.filter((record) => record.status === "completed").length; const summaries = records.map( diff --git a/packages/coding-agent/src/modes/json-event.ts b/packages/coding-agent/src/modes/json-event.ts index 067d8877f..6c9976bb3 100644 --- a/packages/coding-agent/src/modes/json-event.ts +++ b/packages/coding-agent/src/modes/json-event.ts @@ -42,10 +42,18 @@ function toJsonAssistantMessageEvent( * `message_start` provides the initial message, deltas build it, and * `message_end` provides the final authoritative message. Cumulative usage, * tool-call ids, and tool names remain available because their size is constant. + * + * `tool_execution_update` gets the same treatment: it is live progress, but + * `json`/`rpc` hosts write every event as one JSONL line, so an unbounded + * `partialResult` turns progress into multi-megabyte log lines. The terminal + * `tool_execution_end` still carries the full result. */ export function toJsonEvent(event: MessageUpdateEvent): JsonMessageUpdateEvent; export function toJsonEvent(event: AgentSessionEvent): JsonAgentSessionEvent; export function toJsonEvent(event: AgentSessionEvent): JsonAgentSessionEvent { + if (event.type === "tool_execution_update") { + return boundLiveUpdate(event); + } if (event.type !== "message_update") { return event; } @@ -59,3 +67,57 @@ export function toJsonEvent(event: AgentSessionEvent): JsonAgentSessionEvent { assistantMessageEvent: toJsonAssistantMessageEvent(event.assistantMessageEvent), }; } + +/** + * Byte ceiling for one live tool update on the wire. + * + * Chosen well above what a streaming tool legitimately sends per update (the + * bash tool's rolling snapshot is 50 KiB and already throttled to 100ms) so this + * only ever fires for a producer that re-sends accumulated state. It is a + * backstop, not the primary bound: the subagent orchestrator keeps its own live + * projection far below this. + */ +export const MAX_LIVE_UPDATE_BYTES = 256 * 1024; + +const TRUNCATED_MARKER = "[live output truncated]"; + +type ToolExecutionUpdateEvent = Extract; + +function isTextPart(value: unknown): value is { type: "text"; text: string } { + if (!value || typeof value !== "object") return false; + const part = value as { type?: unknown; text?: unknown }; + return part.type === "text" && typeof part.text === "string"; +} + +/** + * Keep a live update under the wire budget. + * + * The tail of the streamed text is retained because that is what a live view + * renders; `details` and `args` are dropped because they are already on the + * matching `tool_execution_start`/`tool_execution_end` events. + */ +function boundLiveUpdate(event: ToolExecutionUpdateEvent): JsonAgentSessionEvent { + const bytes = Buffer.byteLength(JSON.stringify(event), "utf8"); + if (bytes <= MAX_LIVE_UPDATE_BYTES) return event; + const content: unknown[] = Array.isArray(event.partialResult?.content) ? event.partialResult.content : []; + const text = content + .filter(isTextPart) + .map((part) => part.text) + .join("\n"); + const tail = text.length > MAX_LIVE_UPDATE_BYTES / 4 ? text.slice(-(MAX_LIVE_UPDATE_BYTES / 4)) : text; + return { + type: "tool_execution_update", + toolCallId: event.toolCallId, + toolName: event.toolName, + args: undefined, + partialResult: { + content: [ + { + type: "text", + text: tail ? `${tail}\n${TRUNCATED_MARKER}` : TRUNCATED_MARKER, + }, + ], + details: undefined, + }, + }; +} diff --git a/packages/coding-agent/test/json-event-live-update-budget.test.ts b/packages/coding-agent/test/json-event-live-update-budget.test.ts new file mode 100644 index 000000000..ea8210e42 --- /dev/null +++ b/packages/coding-agent/test/json-event-live-update-budget.test.ts @@ -0,0 +1,55 @@ +import { expect, test } from "vitest"; +import type { AgentSessionEvent } from "../src/core/agent-session.ts"; +import { MAX_LIVE_UPDATE_BYTES, toJsonEvent } from "../src/modes/json-event.ts"; + +/** + * `tool_execution_update` is live progress, but json/rpc hosts write each event + * as one JSONL line. The subagent orchestrator keeps its own live payload small; + * this is the generic backstop for any other tool that re-sends accumulated + * state, so one update can never become a multi-megabyte log line. + */ + +function update(partialResult: unknown): AgentSessionEvent { + return { + type: "tool_execution_update", + toolCallId: "call_1", + toolName: "subagent", + args: { agent: "general" }, + partialResult, + }; +} + +test("a live update under the budget passes through untouched", () => { + const event = update({ content: [{ type: "text", text: "working" }], details: { results: [] } }); + expect(toJsonEvent(event)).toBe(event); +}); + +test("an oversized live update is bounded while the terminal result is not", () => { + const big = "x".repeat(4 * 1024 * 1024); + const bounded = toJsonEvent( + update({ + content: [{ type: "text", text: big }], + details: { results: [{ messages: [{ role: "user", content: big }] }] }, + }), + ) as Extract; + + expect(Buffer.byteLength(JSON.stringify(bounded), "utf8")).toBeLessThan(MAX_LIVE_UPDATE_BYTES / 2); + // The tail is what a live view renders, and the marker explains the gap. + const text = bounded.partialResult.content[0]?.type === "text" ? bounded.partialResult.content[0].text : ""; + expect(text.endsWith("[live output truncated]")).toBe(true); + // `details`/`args` are already on tool_execution_start and tool_execution_end. + expect(bounded.partialResult.details).toBeUndefined(); + expect(bounded.args).toBeUndefined(); +}); + +test("the terminal tool_execution_end event is never bounded", () => { + const big = "x".repeat(4 * 1024 * 1024); + const event: AgentSessionEvent = { + type: "tool_execution_end", + toolCallId: "call_1", + toolName: "subagent", + result: { content: [{ type: "text", text: big }] }, + isError: false, + }; + expect(toJsonEvent(event)).toBe(event); +}); diff --git a/packages/coding-agent/test/subagent-live-update-budget.test.ts b/packages/coding-agent/test/subagent-live-update-budget.test.ts new file mode 100644 index 000000000..f4f82812a --- /dev/null +++ b/packages/coding-agent/test/subagent-live-update-budget.test.ts @@ -0,0 +1,178 @@ +import type { AgentToolResult } from "@step-harness/agent-core"; +import { expect, test } from "vitest"; +import type { ExtensionAPI, ExtensionContext, ToolDefinition } from "../src/core/extensions/types.ts"; +import { + createStepSubagentExtension, + type StepSubagentDetails, + type StepSubagentRunInput, + type StepSubagentRunResult, +} from "../src/features/step-subagent.ts"; + +/** + * Regression guard for the event-log amplification: every child event used to + * become one `tool_execution_update` carrying the child's whole `messages` array, + * so a 40-turn child wrote ~5 GB of JSONL whose lines were byte-identical + * repeats. These tests pin both halves of the bound — payload size and rate — + * and that neither costs a status transition or the final transcript. + */ + +const LIVE_UPDATE_MAX_BYTES = 32 * 1024; + +function message(index: number, bytes: number): StepSubagentRunResult["messages"][number] { + return { + role: index % 2 === 0 ? "assistant" : "toolResult", + content: [{ type: "text", text: "x".repeat(bytes) }], + ...(index % 2 === 0 + ? { + api: "anthropic-messages", + provider: "step", + model: "step-3.8-code-alpha", + usage: { + input: 1, + output: 1, + cacheRead: 0, + cacheWrite: 0, + totalTokens: 2, + cost: { input: 0, output: 0, cacheRead: 0, cacheWrite: 0, total: 0 }, + }, + stopReason: "stop" as const, + timestamp: 1, + } + : { toolCallId: `call_${index}`, toolName: "run_command", isError: false, timestamp: 1 }), + } as StepSubagentRunResult["messages"][number]; +} + +function createApi(): { api: ExtensionAPI; tools: Map } { + const tools = new Map(); + const api = { + registerTool: (tool: ToolDefinition) => tools.set(tool.name, tool), + registerCommand: () => {}, + registerMessageRenderer: () => {}, + registerFlag: () => {}, + registerShortcut: () => {}, + on: () => {}, + getActiveTools: () => [], + setActiveTools: () => {}, + getFlag: () => false, + appendEntry: () => {}, + sendMessage: () => {}, + sendUserMessage: () => {}, + } as unknown as ExtensionAPI; + return { api, tools }; +} + +function createContext(cwd: string): ExtensionContext { + return { + mode: "json", + hasUI: false, + cwd, + model: undefined, + thinkingLevel: "high", + isIdle: () => true, + isProjectTrusted: () => true, + ui: { confirm: async () => true, setWidget: () => {}, notify: () => {} }, + sessionManager: { getEntries: () => [] }, + } as unknown as ExtensionContext; +} + +interface Captured { + details?: StepSubagentDetails; + bytes: number; + at: number; +} + +async function runOnce( + runner: (input: StepSubagentRunInput) => Promise, +): Promise<{ updates: Captured[]; result: AgentToolResult }> { + const { api, tools } = createApi(); + createStepSubagentExtension({ agentDir: "/tmp/step-agent-test", runner })(api); + const updates: Captured[] = []; + const startedAt = Date.now(); + const result = (await tools.get("subagent")!.execute( + "call", + { agent: "general", task: "inspect" } as never, + undefined, + (update) => { + const details = update.details as StepSubagentDetails | undefined; + updates.push({ + details, + bytes: Buffer.byteLength(JSON.stringify(update), "utf8"), + at: Date.now() - startedAt, + }); + }, + createContext("/workspace"), + )) as AgentToolResult; + return { updates, result }; +} + +test("a long streaming child produces bounded live updates instead of the whole transcript", async () => { + const messages: StepSubagentRunResult["messages"] = [message(0, 2_000)]; + const { updates, result } = await runOnce(async (input) => { + for (let index = 0; index < 400; index += 1) { + messages.push(message(messages.length, 20_000)); + input.onUpdate?.({ + messages, + stderr: "", + exitCode: -1, + usage: { input: 1, output: 1, cacheRead: 0, cacheWrite: 0, cost: 0, contextTokens: 2, turns: 1 }, + activeText: "y".repeat(50_000), + activeTool: "run_command", + activeToolArgs: "z".repeat(20_000), + activeToolOutput: "w".repeat(20_000), + lastEvent: "message_update", + }); + // Let the coalescing timer fire so a live UI still gets updates. + if (index % 40 === 0) await new Promise((resolve) => setTimeout(resolve, 5)); + } + return { messages, stderr: "", exitCode: 0, usage: {} as never, stopReason: "stop" }; + }); + + expect(updates.length).toBeGreaterThan(1); + // 400 events carrying a growing multi-megabyte transcript must not survive + // into the payload: no update carries `messages`, and each stays small. + for (const update of updates) { + const records = update.details?.results ?? []; + expect(records).toHaveLength(1); + expect(records[0]?.messages).toEqual([]); + expect(update.bytes).toBeLessThan(LIVE_UPDATE_MAX_BYTES); + } + const totalBytes = updates.reduce((sum, update) => sum + update.bytes, 0); + expect(totalBytes).toBeLessThan(2 * 1024 * 1024); + // The final result still describes the child and its transcript reference. + expect(result.details?.results[0]?.status).toBe("completed"); +}); + +test("the final result keeps the newest transcript messages within the byte budget", async () => { + const messages: StepSubagentRunResult["messages"] = []; + for (let index = 0; index < 20; index += 1) messages.push(message(index, 40_000)); + const { result } = await runOnce(async () => ({ + messages, + stderr: "", + exitCode: 0, + usage: {} as never, + stopReason: "stop", + })); + const kept = result.details?.results[0]?.messages ?? []; + expect(kept.length).toBeGreaterThan(0); + expect(kept.length).toBeLessThan(messages.length); + // The newest message survives; older ones are dropped, not the other way round. + expect(kept.at(-1)).toEqual(messages.at(-1)); + expect(Buffer.byteLength(JSON.stringify(kept), "utf8")).toBeLessThanOrEqual(64 * 1024); +}); + +test("a status transition publishes immediately, inside the coalescing window", async () => { + const { updates } = await runOnce(async (input) => { + // Two events within one interval: the running transition must not wait. + input.onUpdate?.({ messages: [], stderr: "", exitCode: -1, usage: {} as never, lastEvent: "turn_start" }); + input.onUpdate?.({ messages: [], stderr: "", exitCode: -1, usage: {} as never, lastEvent: "turn_start" }); + await new Promise((resolve) => setTimeout(resolve, 150)); + return { messages: [], stderr: "", exitCode: 0, usage: {} as never, stopReason: "stop" }; + }); + const statuses = updates.map((update) => update.details?.results[0]?.status); + expect(statuses[0]).toBe("queued"); + expect(statuses).toContain("running"); + expect(statuses.at(-1)).toBe("completed"); + // `running` arrived before the child finished, not only in the trailing flush. + const runningIndex = statuses.indexOf("running"); + expect(runningIndex).toBeLessThan(statuses.length - 1); +}); From 5601f867c58b2052af6609c45b18f94ee139b9b4 Mon Sep 17 00:00:00 2001 From: liuedcson <332840681+liuedcson@users.noreply.github.com> Date: Tue, 27 Oct 2026 21:40:42 +0800 Subject: [PATCH 2/8] fix(coding-agent): make the live projection an allowlist and bound every field Review follow-up. The first pass removed `messages` from live updates and coalesced them, but three paths still carried data the bound did not cover: - The live record was `{...record, ...}` with a few fields patched, so any unbounded field passed through. A chain splices the previous step's whole answer into the next step's task, and every update during that step repeated it: 10 Hz x 500 KB is unbounded regardless of the transcript fix. - The final record bounded only `messages`. A runner reporting a 300 KB final answer put it in `activeText`, which several terminal events then echo. - The wire backstop counted characters instead of serialized bytes, so a string of control characters (six-byte escapes) still exceeded 256 KiB. Live and final records are now explicit allowlists with per-field budgets, the final `activeText` falls back to the full transcript so trimming can never render as "(no output)", and the wire bound measures the serialized event and halves the retained tail until it fits (`tool_execution_end` is still never bounded). Emitter ownership is closed too: a consumer that throws is attributed to the call instead of escaping a timer, late callbacks after return are dropped, and `mapWithConcurrency` settles every worker before returning so a fail-fast rejection cannot leave lanes publishing into a closed emitter. Tests now cover the real path (a spawned `--mode rpc` child through the rpc adapter, parser, orchestrator, agent loop and json projection) plus chain task splicing, coalescing cadence, the truncation marker, the single-oversized-message fallback, late callbacks, and consumer failures. 19 cases total. --- .../README.md | 240 ++++++++++++++++++ .../child.mjs | 103 ++++++++ .../repro.mts | 155 +++++++++++ .../docs/tool-output-retention.md | 33 ++- .../src/features/step-subagent.ts | 6 + .../src/features/subagent/execute.ts | 180 +++++++++++-- packages/coding-agent/src/modes/json-event.ts | 38 ++- .../test/fixtures/subagent-stream-child.mjs | 112 ++++++++ .../json-event-live-update-budget.test.ts | 62 ++++- .../test/subagent-live-update-budget.test.ts | 175 ++++++++++--- .../test/subagent-live-update-rpc.test.ts | 178 +++++++++++++ 11 files changed, 1187 insertions(+), 95 deletions(-) create mode 100644 docs/research/2026-10-27-subagent-live-update-amplification/README.md create mode 100644 docs/research/2026-10-27-subagent-live-update-amplification/child.mjs create mode 100644 docs/research/2026-10-27-subagent-live-update-amplification/repro.mts create mode 100644 packages/coding-agent/test/fixtures/subagent-stream-child.mjs create mode 100644 packages/coding-agent/test/subagent-live-update-rpc.test.ts diff --git a/docs/research/2026-10-27-subagent-live-update-amplification/README.md b/docs/research/2026-10-27-subagent-live-update-amplification/README.md new file mode 100644 index 000000000..cb83cc1da --- /dev/null +++ b/docs/research/2026-10-27-subagent-live-update-amplification/README.md @@ -0,0 +1,240 @@ +# 子代理事件日志放大:定位、竞品对照与修复方案 + +- 日期:2026-10-27 +- 状态:已修复,PR https://github.com/stepfun-ai/Step-Code/pull/314(基于 `main`) +- 关联:benchmark 反馈「95 个文件 127 GiB、单文件 P95 4.28 GiB、最大 11.7 GiB」并伴随 OOM + +--- + +## 1. 现状 + +### 1.1 现象 + +用旧配置跑 benchmark 时,`/logs/agent/stepcode.jsonl` 体积相对旧单放大 86 倍,且相邻事件携带**逐字节相同**的子会话 `messages`: + +``` +type: tool_execution_update +toolName: subagent +event bytes: 2,845,152 -> 2,045,166 +partialResult.details.results: 1 个子代理 +messages compact UTF-8 bytes: 2,036,197 -> 2,036,197 +messages SHA256: 完全相同 +``` + +### 1.2 根因链路 + +一个前台 `subagent` 调用把子进程的**每一个事件**都变成一条**带完整子会话 transcript** 的持久化事件: + +| 步骤 | 位置 | 行为 | +| --- | --- | --- | +| 1 | `features/step-subagent.ts:511-528` `parseJsonEvent` | 每个子进程事件(含每个流式 delta)**无条件**调用 `onUpdate` | +| 2 | `features/subagent/execute.ts:468-484` `emit` | 每次 `onUpdate` 都重建 `details`,`results[].messages = [...record.messages]` | +| 3 | `agent-core/src/agent-loop.ts:797-810` | 每个 `partialResult` 变成一条 `tool_execution_update` | +| 4 | `modes/print-mode.ts:181`、`modes/rpc/rpc-mode.ts:328` | 每条事件序列化成一行 JSONL 写 stdout(宿主重定向即 `stepcode.jsonl`) | + +`messages` 只在 `message_end` 时变化(`step-subagent.ts:511-523`),而 `message_update` 只改 `activeText`/`activeTool*`。因此两次 `message_end` 之间成百上千次更新携带的是同一份数组。 + +一个旁证:`modes/json-event.ts` 早已对 `message_update` 做过「移除累积快照」的处理(注释写明 *Remove cumulative assistant snapshots from streaming wire events*),但 `tool_execution_update` 的累积快照没有做同样处理 —— 同类问题只修了一半。 + +### 1.3 本地复现(离线,不依赖 harbor、不依赖模型) + +复现物在 `docs/research/2026-10-27-subagent-live-update-amplification/`: + +- `child.mjs`:一个真实说话的 `--mode rpc` 子进程替身,按真实 LF 分帧输出 `message_start` / N × `message_update` / `message_end` / `tool_execution_start|update|end` / `agent_settled`。 +- `repro.mts`:用真实 `AgentSession` + 真实 `step-subagent` 扩展 + 真实 `toJsonEvent`,把事件流按 `--mode json` 的方式写成 JSONL 并统计。 + +只有两处是替身(仓库测试策略本来就允许):父模型用 faux provider(不联网),子进程只负责吐 token。**测量路径全程是生产代码**。 + +运行: + +```bash +cd packages/coding-agent +node --import tsx ../../docs/research/2026-10-27-subagent-live-update-amplification/repro.mts +REPRO_TURNS=40 REPRO_DELTAS=150 REPRO_TOOL_BYTES=40000 \ + node --import tsx ../../docs/research/2026-10-27-subagent-live-update-amplification/repro.mts +``` + +修复前(`main`): + +| 子会话规模 | 日志体积 | `tool_execution_update` 条数 | `messages` 占字节 | 单条最大 | 父进程 RSS | +| --- | --- | --- | --- | --- | --- | +| 20 轮 × 60 delta,20 KB 工具结果 | **268.05 MiB** | 1367 | 262.36 MiB(99.2%) | 0.42 MiB | 724 MiB | +| 40 轮 × 150 delta,40 KB 工具结果 | **4992.61 MiB** | 6327 | 4969.82 MiB(99.8%) | 1.63 MiB | 1333 MiB | + +40 轮配置下:82 份不同的 `messages` 快照被写了 6327 次,6245 次是逐字节重复。**单条最大 1.63 MiB、单文件 GB 级**,与 benchmark 的 2.8 MB / 4.28 GiB 完全同量级。 + +### 1.4 内存侧的两个附加放大项(本次只降低增速,未消除) + +- `agent-loop.ts:789-813` 把每次 update 的 emit promise 攒进数组,直到工具结束才 `await`。 +- `modes/print-mode.ts` 的 stdout 写入是无上限 promise 串(`core/output-guard.ts:85-93`),背压只作用于 agent 事件发射,不会让工具停止产生 update。 + +两者叠加,读者慢时载荷会在内存里排队。修复后单条 update 从 MB 级降到 KB 级、频率从每 delta 降到 10 Hz,增长速度下降三到四个数量级,但**队列本身仍然无界**。严格的背压/内存上限需要单独处理(见 §4.5)。 + +--- + +## 2. 竞品实现 + +六个成熟实现的共同点:**流式增量和工具进度永不进入持久化层;子代理 transcript 永不进入父会话**。 + +| | 持久化形态 | delta 落盘 | 工具 progress 落盘 | 写入触发 | 单个工具结果上限 | 子代理历史 | +| --- | --- | --- | --- | --- | --- | --- | +| opencode | SQLite 行级 upsert | 否,`EphemeralDefinition` 类型强制 | 否,`Tool.Progress` 为 ephemeral | `text.ended` / `tool.success` / `step.ended` | 2000 行 / 50 KiB + 外置文件 | 独立 session,父存 `sessionID` + 最终文本 | +| codex | JSONL append(每 thread 一文件) | 否,`rollout/policy.rs` transient 黑名单 | 否,`ExecCommandOutputDelta` transient | `ItemCompleted` / 完整 `ResponseItem` | 64 KiB 截断 + head/tail 1 MiB 缓冲 | 独立 thread,父存 `agent_thread_id` | +| kimi-code | `wire.jsonl` append | 否,`durable` 默认 false | 否,`observable` only | durable event,`content.part` 在 step 结束 | 50k 字符 + spill 10M | 独立 `agents//wire.jsonl`,父存 `resultSummary` | +| minimax-code | `messages.jsonl` append | 否,WS `VOLATILE_EVENT_TYPES` | 否,`tool_execution_update` → `debug.trace` | **`message_end` / `tool_execution_end`** | 64 KiB + artifact | 独立 child session,父存报告 | +| deepseek-harness | `session.jsonl.zstd` append | 否,`agent/assistant-stream` 标注 transient | 事件词表里没有 progress 类型 | turn/step 边界 + 200ms 批 | spill 64 MiB + head/tail | 独立 session,父存 `childId` + `label` | +| ZCode | SQLite 行级 upsert | 否,`TRANSIENT_SESSION_EVENT_TYPES` | 否,同上 | pending/running/completed 三次 upsert | 30 KB + artifact | 独立 session,父存 `childSessionId` + `outputPath` | + +三处最值得借鉴的设计: + +1. **把「能不能落盘」放进类型系统**(opencode `schema/src/event.ts:44-58`):`durable` 与 `ephemeral` 是互斥类型,`Text.Delta` 的注释直接写 *Stream fragments are live-only; Text.Ended is the replayable full-value boundary*. 写错的代码编译不过。 +2. **持久化决策收敛到存储入口**(codex `rollout/src/policy.rs:160-225`):transient 事件是显式黑名单,工具实现无法「手滑」写入大对象。 +3. **同源 fork 已经踩过并修过**(minimax 的 `pi-turn-runner/history.ts:93-110`):`flushTail` 只发 `messages.slice(cursor)`,且只在 `message_end` / `tool_execution_end` 触发 —— 正好是我们违反的两条。 + +另有一个高度同构的「前人踩坑记录」:ZCode `runner-debug.ts:468-535` 的中文注释写明,诊断日志反复写完整 messages 造成「三角形重复」,文件到 GB 级后在 V8 字符串分配阶段 native crash;最终解法是**单文件 + 相对上一版 delta + 尾部最多 64/256 条 + 64 MB/256 MB 硬上限并重置**。 + +**结论:这不是某个实现的小疏忽,而是三层约定同时被违反**——流式增量进了 durable 层、子代理 transcript 进了父会话、写侧没有上限。所以修复必须同时补这三层,只改其中一层都会留下复发路径。 + +--- + +## 3. 技术实现 + +### 3.1 方案选择 + +| 候选 | 判断 | +| --- | --- | +| A. 只在 `toJsonEvent` 剥掉 `partialResult.details.results[].messages` | 有效但只覆盖 CLI wire;web 分支 SSE 直接 `JSON.stringify(event)`,绕过 `toJsonEvent`;且 `modes/` 不该知道 subagent 的 details 结构 | +| B. 只在 `emit()` 去掉 `messages` | 消除 99% 字节,但仍按 delta 频率发 `activeText`(上限 50k 字符),长会话仍线性增长 | +| C. 在 `agent-loop` 对任意 `partialResult` 做深度截断 | 覆盖所有人,但通用深截断有破坏工具语义的风险(如 bash 的 `details.fullOutputPath`),爆炸半径不可控 | +| **D(选用):源头有界投影 + 合流节流 + 终态预算,再加一个通用 wire 兜底** | 问题的三层各补一层;主修复在 payload 产生处,因此对所有宿主(CLI/TUI/web)同时生效;兜底只覆盖增量事件、语义安全 | + +选择 D 的关键理由:**修复必须发生在 payload 的产生处**,而不是某个序列化出口。web 分支的 SSE 不走 `toJsonEvent`,任何「只在 wire 层修」的方案都会在 web 上复现同样的 OOM。 + +### 3.2 具体改动 + +**① 有界 live 投影**(`features/subagent/execute.ts`) + +```ts +function liveRecord(record) { + return { + ...record, + messages: [], // transcript 只随终态发布一次 + activeText: tailChars(record.activeText, 2_000), // UI 只渲染最后 8 行 + activeToolArgs: tailChars(record.activeToolArgs, 500), + activeToolOutput: tailChars(record.activeToolOutput, 1_000), + usage: cloneUsage(record.usage), + }; +} +``` + +**② 合流节流**:`LIVE_UPDATE_INTERVAL_MS = 100`(与既有 `BASH_UPDATE_THROTTLE_MS` 一致)。 + +- 状态跃迁(queued → running → completed/failed/aborted)**立即发布**,不进入节流窗口 —— 直播列表唯一需要「一次不丢」的信息。 +- 其余(delta、工具输出块)在窗口内合并,最新记录胜出。 +- `finally` 中 `flushEmit`,保证尾包不丢、也不会在调用返回后迟到投递。 + +**③ 终态投影**:终态 details 同样是展示投影,不是原始数据的拷贝。 + +- `messages` 只保留最新的、序列化后总量 ≤ 64 KiB 的消息(大小为选值,不与仓库既有的 50 KiB 文本上限混同);被裁剪时置 `messagesTruncated: true`。 +- `activeText` ≤ 8,000 字符、`task` ≤ 2,000 字符、`stderr` / `errorMessage` ≤ 2,000 字符、`cancelledPrompts` ≤ 20 条 × 200 字符。 +- `activeText` 缺失时由**完整 transcript** 的最终 assistant 文本回填,因此「单条消息超出预算导致 messages 为空」不会让结果渲染成 `(no output)`。 +- 模型可见的 `content` 不受这些限制,仍走既有的 50 KiB / 2,000 行 tool-output retention;完整 transcript 留在子会话(`sessionId` / `sessionFile`)。 + +**④ 通用 wire 兜底**(`modes/json-event.ts`):单条 `tool_execution_update` 超过 256 KiB 时,保留文本尾部 + `[live output truncated]` 标记,丢弃 `details`/`args`(它们已分别存在于 `tool_execution_start` / `tool_execution_end`)。**终态事件永不裁剪**。256 KiB 远高于正常流式工具单次上传量(bash 滚动快照 50 KiB 且已 100 ms 节流),因此只对「重发累积状态」的生产者生效。 + +**⑤ 文档**:`packages/coding-agent/docs/tool-output-retention.md` 新增 *Live tool updates* 一节,说明「最终结果上限」与「直播上限」是两套独立的边界。 + +### 3.3 修复后(同一复现脚本) + +| 子会话规模 | 修复前 | 修复后 | 降幅 | +| --- | --- | --- | --- | +| 20 轮 × 60 delta,20 KB 工具结果 | 268.05 MiB | **0.41 MiB** | 654× | +| 40 轮 × 150 delta,40 KB 工具结果 | 4992.61 MiB | **0.31 MiB** | 16105× | + +`tool_execution_update` 条数 6327 → 3(本次假子进程瞬时吐完;真实流式按 10 Hz 产出)。父进程峰值 RSS 1333 MiB → 271 MiB。 + +剩余体积构成:终态 tool result(≤ 64 KiB messages + 各展示字段上限)被约 5 类事件各回显一次(`tool_execution_end`、工具结果的 `message_end`、`turn_end`、`agent_end`),因此单次调用约 5 × 100 KiB。**上界由预算决定,与子会话长度无关**(20 轮 0.32 MiB,40 轮 0.22 MiB)。 + +--- + +## 4. 影响范围 + +### 4.1 代码面 + +| 模块 | 影响 | +| --- | --- | +| 前台 `subagent` 调用 | 直播更新变少(≤10 Hz)、载荷有界;终态 details 的 `messages` 可能被裁剪到 ≤64 KiB | +| 后台 lane | 走同一个 `emit`,同样受益;lane 自己的 15 s 进度通知节流不变 | +| TUI 渲染 | summary 只渲染最后 8 行、widget 只渲染状态 + token 数,均仍在投影内;历史展开优先用 `activeText`,仍能显示最终输出 | +| `--mode json` / `--mode rpc` | 增量事件更少更小;单条增量另有 256 KiB 序列化字节兜底(超限时丢弃 `args`/`details` 并保留文本尾部);终态事件的 details 是限量投影 | +| web(`apps/web`,不在 main 上) | 因修复在 payload 源头,SSE 路径自动受益;不需要额外改动 | +| 其他工具 | bash 已有 100 ms 节流 + 50 KiB 滚动快照,低于 256 KiB 兜底阈值,行为不变 | + +### 4.2 行为兼容性 + +- **不改变** `subagent` 工具对模型可见的 `content` 文本(由未裁剪的内部 records 生成)。 +- **不改变** 状态机的对外语义:所有状态跃迁仍然逐次可见。 +- 直播期间的 `activeText` 从最多 50k 字符变为 2k 尾部,工具入参/输出也从完整值变为尾部:这是**刻意的可见降级**(progress 是可合并快照,不是完整事件历史)。 +- 可观测契约变化:`StepSubagentDetails.results[].messages` 从「全量」变为「终态限量」并新增可选 `messagesTruncated`;直播字段变为有界尾部。消费方(TUI 展开、历史渲染、web 子代理卡片)只用最后一个 assistant 文本或状态字段,已逐一核对。 +- 定时器在 `finally` 关闭(`closeEmitter`),调用返回后的迟到回调不再发布;`onUpdate` 抛错不再从定时器逃逸成未捕获异常,而是在调用路径上抛出。 +- `mapWithConcurrency` 改为等待所有 worker 结束(`allSettled`)再返回,避免 fail-fast 提前返回后仍有 lane 对着已关闭的 emitter 继续工作。 + +### 4.3 测试与验证 + +新增(19 个用例): + +- `test/subagent-live-update-rpc.test.ts` —— **端到端**:真起 `--mode rpc` 子进程,走真实 rpc-adapter → parseJsonEvent → 编排 → Agent Loop → toJsonEvent。断言整条父日志 < 1 MiB、update 数 < 60、无一条 update 携带 messages、终态 messages ≤ 64 KiB;并用 300 KB 最终答复验证展示投影有界而模型可见 `content` 仍完整。 +- `test/subagent-live-update-budget.test.ts` + - 400 次携带增长 transcript 的 update:live 一律 `messages: []`、单条 < 32 KiB、总量 < 2 MiB; + - chain 把上一步 500 KB 输出插入下一步 task,所有 update 仍 < 32 KiB、`task` ≤ 600 字符; + - 200 次 delta 只产生 ≤ 6 次发布,`running` 由首个事件即时发布; + - 终态预算:保留最新消息、序列化数组 ≤ 64 KiB、`messagesTruncated: true`; + - 单条消息超预算且无 `activeText` 时,仍从完整 transcript 回填可渲染文本; + - 400 KB 最终答复在展示投影里被压到 ≤ 8,000 字符; + - 调用返回后的迟到回调不再发布; + - `onUpdate` 抛错以调用失败的形式浮出,而不是从定时器逃逸。 +- `test/json-event-live-update-budget.test.ts` + - 未超限原样透传;4 MiB update 被裁剪到 ≤ 256 KiB 且带标记; + - 控制字符 / 引号反斜杠 / 多字节 CJK / 孤立 surrogate 各 300k 次重复,仍 ≤ 256 KiB(按序列化字节而非字符计数); + - 略超预算时保留尽量多的尾部;`tool_execution_end` 永不被裁剪。 + +回归: + +- `packages/coding-agent` 全量:`4984 passed, 58 skipped`。唯一失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关)。 +- `pnpm run check` 全绿(biome / 边界检查 / `tsgo --noEmit` / browser smoke)。 +- `git diff --check` 干净。 + +### 4.4 风险与回滚 + +| 风险 | 控件 | +| --- | --- | +| 直播更新过少导致 UI 卡顿感 | 状态跃迁即时发布;100 ms 与 bash 既有节流一致,token 计数 10 Hz 足够 | +| 终态 `messages` 裁剪影响历史渲染 | 渲染优先 `activeText`;`sessionId`/`sessionFile` 指向子进程完整 transcript | +| 兜底误伤正常流式工具 | 阈值 256 KiB,远高于 bash 的 50 KiB;新增测试锁定「未超限原样透传」 | +| 合流定时器泄漏/迟到投递 | `finally` 中 `flushEmit`;`unref()` | +| 后续 web 分支合并冲突 | 改动集中在 `emit` 与 dispatch 外层(`try/finally`);web 分支改的是 `runOne` 内部与 `sessionId` 传递,冲突面小 | + +回滚:单 commit(`fix(coding-agent): bound subagent live updates instead of re-sending the transcript`),`git revert` 即恢复原行为,无数据迁移、无配置项。 + +### 4.5 后续(未纳入本 PR) + +1. **终态回显放大**:一次调用的终态 details 会被约 5 类事件各带一份(≈5 × 100 KiB)。要压缩需要改消息级事件形状,与本次「最小爆炸半径」目标冲突,建议单独立项。 +2. **内存队列仍无界**:`agent-loop` 的 update promise 数组与 `output-guard` 的 stdout promise 串都没有上限。本 PR 只降低了增长速度,慢读者场景需要单独做背压或队列上限。 +2. **web SSE 兜底**:web 分支的 SSE 直接转发 session event,未经过 `toJsonEvent`。当前源头已收敛,但建议在该分支 rebase 后补一条同等的回归测试。 +3. **类型级约束**:真正对齐 opencode 的做法是给会话事件加 `durable`/`ephemeral` 分类,让「增量不可落盘」成为编译期约束,而不是靠 review 和上限兜底。这是架构级改动,值得单独立项。 + +--- + +## 附:复现/验证命令 + +```bash +# 复现(修复前后都可跑,用于对比) +cd packages/coding-agent +node --import tsx ../../docs/research/2026-10-27-subagent-live-update-amplification/repro.mts + +# 回归测试 +npx vitest --run test/subagent-live-update-budget.test.ts test/json-event-live-update-budget.test.ts + +# 全量检查 +pnpm run check +``` diff --git a/docs/research/2026-10-27-subagent-live-update-amplification/child.mjs b/docs/research/2026-10-27-subagent-live-update-amplification/child.mjs new file mode 100644 index 000000000..a2235eb57 --- /dev/null +++ b/docs/research/2026-10-27-subagent-live-update-amplification/child.mjs @@ -0,0 +1,103 @@ +// Fake `step --mode rpc` child used by the local amplification repro. +// It speaks the real rpc framing (one JSON object per LF-framed line) and +// replays what a child with a long streaming turn looks like: many text deltas, +// then a persisted assistant message, then a tool result. +const TURNS = Number(process.env.REPRO_TURNS ?? 20); // assistant turns in the child +const DELTAS = Number(process.env.REPRO_DELTAS ?? 60); // text deltas per turn +const TOOL_BYTES = Number(process.env.REPRO_TOOL_BYTES ?? 20_000); // child tool result size + +let buffer = ""; +process.stdin.setEncoding("utf8"); +process.stdin.on("data", (chunk) => { + buffer += chunk; + const lines = buffer.split("\n"); + buffer = lines.pop() ?? ""; + for (const line of lines) handle(line.trim()); +}); + +function write(value) { + process.stdout.write(`${JSON.stringify(value)}\n`); +} + +function assistant(content, stopReason = "stop") { + return { + role: "assistant", + content, + api: "anthropic-messages", + provider: "step", + model: "step-3.8-code-alpha", + usage: { input: 1000, output: 200, cacheRead: 0, cacheWrite: 0, totalTokens: 1200, cost: {} }, + stopReason, + timestamp: Date.now(), + }; +} + +async function handle(line) { + if (!line) return; + let command; + try { + command = JSON.parse(line); + } catch { + return; + } + if (command.type === "get_state") { + write({ type: "response", id: command.id, command: "get_state", success: true, data: { sessionFile: "/tmp/child.jsonl" } }); + return; + } + if (command.type === "abort") { + write({ type: "agent_settled" }); + return; + } + if (command.type !== "prompt") return; + + write({ type: "response", id: command.id, command: "prompt", success: true }); + write({ type: "agent_start" }); + + const messages = []; + for (let turn = 0; turn < TURNS; turn++) { + write({ type: "turn_start" }); + write({ type: "message_start", message: assistant([]) }); + + let text = ""; + for (let index = 0; index < DELTAS; index++) { + const delta = `token-${turn}-${index} `; + text += delta; + write({ + type: "message_update", + assistantMessageEvent: { type: "text_delta", contentIndex: 0, delta }, + }); + } + + // The persisted assistant message, exactly as the real child sends it. + const message = assistant([{ type: "text", text }], "toolUse"); + messages.push(message); + write({ type: "message_end", message }); + + // A tool call whose result the child accumulates into its transcript. + const toolCallId = `call_${turn}`; + write({ + type: "tool_execution_start", + toolCallId, + toolName: "run_command", + args: { command: `echo ${turn}` }, + }); + const output = "x".repeat(TOOL_BYTES); + write({ type: "tool_execution_update", toolCallId, toolName: "run_command", partialResult: output }); + const result = { + role: "toolResult", + toolCallId, + toolName: "run_command", + content: [{ type: "text", text: output }], + isError: false, + timestamp: Date.now(), + }; + messages.push(result); + write({ type: "tool_execution_end", toolCallId, toolName: "run_command", result: { content: [{ type: "text", text: output }] }, isError: false }); + write({ type: "message_end", message: result }); + write({ type: "turn_end" }); + } + + write({ type: "message_end", message: assistant([{ type: "text", text: "child done" }]) }); + write({ type: "agent_end" }); + write({ type: "agent_settled" }); +} diff --git a/docs/research/2026-10-27-subagent-live-update-amplification/repro.mts b/docs/research/2026-10-27-subagent-live-update-amplification/repro.mts new file mode 100644 index 000000000..ed7ed1b18 --- /dev/null +++ b/docs/research/2026-10-27-subagent-live-update-amplification/repro.mts @@ -0,0 +1,155 @@ +/** + * Local, offline reproduction of the subagent event-log amplification. + * + * Everything below is production code except the two test doubles the repo's + * testing policy already sanctions: + * - the parent model (faux provider, no network), + * - the child (a fake `step --mode rpc` process that only streams tokens). + * + * The measured path is real end to end: + * child stdout -> routeSubagentRpcLine -> parseJsonEvent -> onUpdate + * -> execute.emit -> agent-loop tool_execution_update -> AgentSession event + * -> toJsonEvent -> the same JSONL a host redirects from `--mode json`. + * + * Run from packages/coding-agent: + * node --import tsx ../../docs/research/2026-10-27-subagent-live-update-amplification/repro.mts + * REPRO_TURNS=40 REPRO_DELTAS=150 REPRO_TOOL_BYTES=40000 node --import tsx + */ +import { createHash } from "node:crypto"; +import { createWriteStream, mkdtempSync, rmSync, statSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { fileURLToPath } from "node:url"; +import { fauxAssistantMessage, fauxToolCall } from "@step-harness/providers"; +import { createStepSubagentExtension } from "../../../packages/coding-agent/src/features/step-subagent.ts"; +import { toJsonEvent } from "../../../packages/coding-agent/src/modes/json-event.ts"; +import { createHarness } from "../../../packages/coding-agent/test/suite/harness.ts"; + +const childPath = fileURLToPath(new URL("./child.mjs", import.meta.url)); +const workDir = mkdtempSync(join(tmpdir(), "step-amp-")); +const logPath = join(workDir, "stepcode.jsonl"); + +// The default runner spawns `process.argv[1]`. Point it at the fake rpc child so +// this repro works on any branch, without the host-only `cliPath` option. +process.argv[1] = childPath; +// The child is plain ESM: do not forward the parent's tsx loader into it, or it +// will try to resolve `tsx` from the child's own cwd. +process.execArgv = process.execArgv.filter( + (arg) => !/^(?:--import|--loader|--require|-r)$/u.test(arg), +); + +const harness = await createHarness({ + extensionFactories: [ + { name: "step-subagent", factory: createStepSubagentExtension({ agentDir: join(workDir, "agent") }) }, + ], +}); + +// Mirror `--mode json`: every session event is one JSONL line on stdout. +const out = createWriteStream(logPath); +const stats = { + byType: new Map(), + bytesByType: new Map(), + updates: 0, + updatePayloadBytes: 0, + updateMessagesBytes: 0, + largestUpdate: 0, + snapshotHashes: new Map(), + snapshotEmissions: 0, + finalResultBytes: 0, + finalResultMessages: 0, +}; +let writeChain: Promise = Promise.resolve(); +let peakRss = 0; +const sampler = setInterval(() => { + peakRss = Math.max(peakRss, process.memoryUsage().rss); +}, 10); + +harness.session.subscribe((event) => { + const line = JSON.stringify(toJsonEvent(event)); + const bytes = Buffer.byteLength(line, "utf8"); + stats.byType.set(event.type, (stats.byType.get(event.type) ?? 0) + 1); + stats.bytesByType.set(event.type, (stats.bytesByType.get(event.type) ?? 0) + bytes); + writeChain = writeChain.then( + () => new Promise((resolve) => (out.write(`${line}\n`) ? resolve() : out.once("drain", () => resolve()))), + ); + if (event.type === "tool_execution_end") { + stats.finalResultBytes = Buffer.byteLength(JSON.stringify(event.result), "utf8"); + const records = event.result?.details?.results; + stats.finalResultMessages = Array.isArray(records) + ? records.reduce( + (sum, record) => sum + (Array.isArray(record?.messages) ? record.messages.length : 0), + 0, + ) + : 0; + return; + } + if (event.type !== "tool_execution_update") return; + stats.updates += 1; + stats.updatePayloadBytes += bytes; + stats.largestUpdate = Math.max(stats.largestUpdate, bytes); + const results = event.partialResult?.details?.results; + if (!Array.isArray(results)) return; + for (const record of results) { + const messages = record?.messages; + if (!Array.isArray(messages)) continue; + stats.snapshotEmissions += 1; + stats.updateMessagesBytes += Buffer.byteLength(JSON.stringify(messages), "utf8"); + const hash = createHash("sha256").update(JSON.stringify(messages)).digest("hex"); + stats.snapshotHashes.set(hash, (stats.snapshotHashes.get(hash) ?? 0) + 1); + } +}); + +harness.setResponses([ + fauxAssistantMessage(fauxToolCall("subagent", { agent: "general", task: "inspect the repository" }), { + stopReason: "toolUse", + }), + fauxAssistantMessage("parent done"), +]); + +const startedAt = Date.now(); +await harness.session.prompt("delegate the inspection"); +await writeChain; +await new Promise((resolve) => out.end(resolve)); +clearInterval(sampler); +peakRss = Math.max(peakRss, process.memoryUsage().rss); + +const size = statSync(logPath).size; +const mib = (n: number): number => +(n / 1024 / 1024).toFixed(2); +const distinct = stats.snapshotHashes.size; +const redundant = stats.snapshotEmissions - distinct; + +console.log( + JSON.stringify( + { + config: { + childTurns: Number(process.env.REPRO_TURNS ?? 20), + deltasPerTurn: Number(process.env.REPRO_DELTAS ?? 60), + childToolBytes: Number(process.env.REPRO_TOOL_BYTES ?? 20_000), + }, + logMiB: mib(size), + toolExecutionUpdateEvents: stats.updates, + updatePayloadMiB: mib(stats.updatePayloadBytes), + payloadShareOfLogPct: +((stats.updatePayloadBytes / Math.max(1, size)) * 100).toFixed(1), + bytesCarriedByMessagesMiB: mib(stats.updateMessagesBytes), + largestUpdateMiB: mib(stats.largestUpdate), + finalResultMiB: mib(stats.finalResultBytes), + finalResultMessages: stats.finalResultMessages, + distinctMessageSnapshots: distinct, + snapshotEmissions: stats.snapshotEmissions, + redundantSnapshotEmissions: redundant, + peakRssMiB: mib(peakRss), + elapsedMs: Date.now() - startedAt, + eventsByType: Object.fromEntries([...stats.byType.entries()].sort((a, b) => b[1] - a[1])), + mibByType: Object.fromEntries( + [...stats.bytesByType.entries()] + .sort((a, b) => b[1] - a[1]) + .map(([type, bytes]) => [type, mib(bytes)]), + ), + }, + null, + 2, + ), +); + +harness.cleanup(); +rmSync(workDir, { recursive: true, force: true }); diff --git a/packages/coding-agent/docs/tool-output-retention.md b/packages/coding-agent/docs/tool-output-retention.md index 1127fb449..0ff8baae7 100644 --- a/packages/coding-agent/docs/tool-output-retention.md +++ b/packages/coding-agent/docs/tool-output-retention.md @@ -39,17 +39,28 @@ typed `details` payloads. No new permission bypass or external upload is added. A tool's `onUpdate` callbacks are progress, not results. They run while the call is in flight and each one becomes a `tool_execution_update` session event, which the `json` and `rpc` modes write as one JSONL line — so a host that redirects -that stream to a file turns progress into log volume. Two bounds keep that -volume proportional to wall-clock time instead of to the work already done: +that stream to a file turns progress into log volume. The bound is +`O(elapsed time x bounded payload)`, not a constant log size: - A producer sends at most one update per 100 ms (the same cadence the bash tool uses) and publishes state transitions immediately. -- A live update carries no `messages` transcript, and its streamed text is held - to a short tail. The complete transcript is published once, in the final - result, itself capped at 64 KiB of the newest messages. Older messages stay - readable through the child session id or `sessionFile`. - -`toJsonEvent` additionally bounds a single `tool_execution_update` at 256 KiB -and replaces anything larger with the tail of its text plus a truncation marker. -That backstop exists for third-party tools that re-send accumulated state; it -never applies to `tool_execution_end`, which carries the real result. +- A live update is an explicit projection, never the accumulated call state. The + subagent orchestrator drops `messages`, keeps a short tail of the streamed + text / tool output / stderr, and clips a task prompt at both ends, because a + chain splices the previous step's whole answer into the next step's task. +- The final record is also a display projection: the newest messages that fit + 64 KiB, an 8,000-character `activeText`, and every other rendered field + bounded. `messagesTruncated` says when the transcript tail was cut, and the + full transcript stays in the child session (`sessionId` / `sessionFile`). + The model-facing `content` is unaffected and still passes through this + document's 50 KiB retention. + +`toJsonEvent` additionally bounds a single `tool_execution_update` at 256 KiB of +*serialized* bytes. That backstop exists for third-party tools that re-send +accumulated state; it never applies to `tool_execution_end`, which carries the +real result. The budget is measured after JSON escaping on purpose: a control +character or a lone surrogate becomes a six-byte escape, so counting raw +characters under-counts the bytes the host writes. + +These bounds limit payload size. They do not add backpressure: a slow stdout +reader can still queue updates, just far smaller ones. diff --git a/packages/coding-agent/src/features/step-subagent.ts b/packages/coding-agent/src/features/step-subagent.ts index 6c6d74c9f..f05305aed 100644 --- a/packages/coding-agent/src/features/step-subagent.ts +++ b/packages/coding-agent/src/features/step-subagent.ts @@ -212,6 +212,12 @@ export interface StepSubagentResultRecord extends StepSubagentRunResult { step?: number; worktreePath?: string; worktreeBranch?: string; + /** + * True when `messages` holds only the newest part of the child transcript. + * The record is a display projection, not the child's authoritative history: + * the full transcript stays in the child session (`sessionId`/`sessionFile`). + */ + messagesTruncated?: boolean; } export interface StepSubagentDetails { diff --git a/packages/coding-agent/src/features/subagent/execute.ts b/packages/coding-agent/src/features/subagent/execute.ts index 77be0b66a..8a6687620 100644 --- a/packages/coding-agent/src/features/subagent/execute.ts +++ b/packages/coding-agent/src/features/subagent/execute.ts @@ -70,6 +70,11 @@ const LIVE_UPDATE_INTERVAL_MS = 100; const LIVE_TEXT_CHARS = 2_000; const LIVE_TOOL_OUTPUT_CHARS = 1_000; const LIVE_TOOL_ARGS_CHARS = 500; +const LIVE_TASK_CHARS = 600; +const LIVE_STDERR_CHARS = 2_000; +const LIVE_ERROR_CHARS = 2_000; +const LIVE_PROMPT_CHARS = 200; +const LIVE_CANCELLED_PROMPTS = 20; /** * Final-result budget for the child transcript embedded in the tool result. @@ -82,6 +87,9 @@ const LIVE_TOOL_ARGS_CHARS = 500; * repository apply to a persisted command result. */ const FINAL_MESSAGES_BYTES = 64 * 1024; +/** Display-only bounds on the final record; `content` carries the model-facing text. */ +const FINAL_TEXT_CHARS = 8_000; +const FINAL_TASK_CHARS = 2_000; export interface StepSubagentTaskInput { agent: string; @@ -187,39 +195,124 @@ function buildDetails( }; } -/** Keep the tail of a streamed field: the UI renders the newest lines. */ +/** Keep the tail of a streamed field within `max` characters, marker included. */ function tailChars(value: string | undefined, max: number): string | undefined { if (value === undefined || value.length <= max) return value; - return `\u2026${value.slice(-max)}`; + return `\u2026${value.slice(-(max - 1))}`; +} + +/** Keep both ends of a prompt: the opening instruction and the inserted context. */ +function clipMiddle(value: string, max: number): string { + if (value.length <= max) return value; + const half = Math.max(1, Math.floor((max - 1) / 2)); + return `${value.slice(0, half)}\u2026${value.slice(-half)}`; } /** - * Project one record for a live update. `messages` is deliberately empty: the - * transcript changes only at `message_end`, so a per-event copy re-sends the - * same array hundreds of times between two of them. + * Project one record for a live update. + * + * This is an explicit allowlist, not a spread with a few fields patched: a + * custom runner (or a future field) must not be able to smuggle unbounded state + * into a payload that is emitted at 10 Hz. `messages` is deliberately empty — + * the transcript changes only at `message_end`, so copying it per event + * re-sends the same array hundreds of times between two of them. + * + * `task` matters most for a chain: `{previous}` splices the previous step's + * entire output into the next step's task, so the expanded prompt can be as + * large as the child's whole answer. */ function liveRecord(record: StepSubagentResultRecord): StepSubagentResultRecord { return { - ...record, + agent: record.agent, + agentSource: record.agentSource, + task: clipMiddle(record.task, LIVE_TASK_CHARS), + status: record.status, + exitCode: record.exitCode, messages: [], - activeText: tailChars(record.activeText, LIVE_TEXT_CHARS), - activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS), - activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS), + stderr: tailChars(record.stderr, LIVE_STDERR_CHARS) ?? "", usage: cloneUsage(record.usage), + ...(record.model === undefined ? {} : { model: record.model }), + ...(record.stopReason === undefined ? {} : { stopReason: record.stopReason }), + ...(record.errorMessage === undefined ? {} : { errorMessage: tailChars(record.errorMessage, LIVE_ERROR_CHARS) }), + ...(record.activeText === undefined ? {} : { activeText: tailChars(record.activeText, LIVE_TEXT_CHARS) }), + ...(record.activeTool === undefined ? {} : { activeTool: record.activeTool }), + ...(record.activeToolArgs === undefined + ? {} + : { activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS) }), + ...(record.activeToolOutput === undefined + ? {} + : { activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS) }), + ...(record.lastEvent === undefined ? {} : { lastEvent: record.lastEvent }), + ...(record.startedAt === undefined ? {} : { startedAt: record.startedAt }), + ...(record.updatedAt === undefined ? {} : { updatedAt: record.updatedAt }), + ...(record.step === undefined ? {} : { step: record.step }), + ...(record.worktreePath === undefined ? {} : { worktreePath: record.worktreePath }), + ...(record.worktreeBranch === undefined ? {} : { worktreeBranch: record.worktreeBranch }), + ...(record.sessionId === undefined ? {} : { sessionId: record.sessionId }), + ...(record.sessionFile === undefined ? {} : { sessionFile: record.sessionFile }), + ...(record.pendingReply === undefined ? {} : { pendingReply: record.pendingReply }), + ...boundedPrompts(record.cancelledPrompts), + }; +} + +function boundedPrompts(prompts: string[] | undefined): { cancelledPrompts?: string[] } { + if (!prompts || prompts.length === 0) return {}; + return { + cancelledPrompts: prompts + .slice(-LIVE_CANCELLED_PROMPTS) + .map((prompt) => tailChars(prompt, LIVE_PROMPT_CHARS) ?? ""), }; } -/** Newest messages that fit the final-result budget, oldest first. */ -function boundedMessages(messages: readonly unknown[]): StepSubagentRunResult["messages"] { +/** Final transcript projection: newest messages that fit, plus why they were cut. */ +function boundedMessages(messages: readonly unknown[]): { + messages: StepSubagentRunResult["messages"]; + truncated: boolean; +} { + if (messages.length === 0) return { messages: [], truncated: false }; const kept: unknown[] = []; - let bytes = 0; + // Reserve the brackets and count each retained element's separating comma so + // the check is on the serialized array, not on the sum of its members. + let bytes = 2; for (let index = messages.length - 1; index >= 0; index -= 1) { - const size = Buffer.byteLength(JSON.stringify(messages[index]) ?? "", "utf8"); + const size = Buffer.byteLength(JSON.stringify(messages[index]) ?? "", "utf8") + 1; if (bytes + size > FINAL_MESSAGES_BYTES) break; bytes += size; kept.push(messages[index]); } - return kept.reverse() as StepSubagentRunResult["messages"]; + return { + messages: kept.reverse() as StepSubagentRunResult["messages"], + truncated: kept.length < messages.length, + }; +} + +/** + * Final record projection. + * + * The transcript is bounded, and so is every other field a consumer renders: a + * runner that reports a multi-hundred-KB final answer must not put it in the + * details, which several terminal events then echo. `activeText` is filled from + * the transcript when a runner did not set it, so trimming `messages` can never + * turn a completed record into "(no output)". + */ +function finalRecord(record: StepSubagentResultRecord): StepSubagentResultRecord { + const bounded = boundedMessages(record.messages); + // Fall back to the full transcript, not the bounded copy: one message larger + // than the budget leaves `messages` empty, and the result must still render. + const fallbackText = finalOutput(record.messages); + return { + ...record, + task: clipMiddle(record.task, FINAL_TASK_CHARS), + messages: bounded.messages, + activeText: tailChars(record.activeText || fallbackText, FINAL_TEXT_CHARS), + activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS), + activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS), + stderr: tailChars(record.stderr, LIVE_STDERR_CHARS) ?? "", + ...(record.errorMessage === undefined ? {} : { errorMessage: tailChars(record.errorMessage, LIVE_ERROR_CHARS) }), + ...boundedPrompts(record.cancelledPrompts), + ...(bounded.truncated ? { messagesTruncated: true } : {}), + usage: cloneUsage(record.usage), + }; } async function mapWithConcurrency( @@ -236,7 +329,11 @@ async function mapWithConcurrency( results[index] = await fn(items[index], index); } }); - await Promise.all(workers); + // Settle every worker before returning: a fail-fast rejection would otherwise + // leave the other lanes running against an emitter the caller already closed. + const settled = await Promise.allSettled(workers); + const failed = settled.find((entry) => entry.status === "rejected"); + if (failed) throw failed.reason; return results; } @@ -470,15 +567,41 @@ export async function runPreparedSubagent( let lastStatusKey = ""; let lastPublishAt = 0; let pendingPublish: ReturnType | undefined; + /** + * Emission ownership. A consumer's `onUpdate` can throw, and after the timer + * fires that rejection no longer belongs to the caller's await chain. Capture + * it, stop emitting, and rethrow from the call's own path below, so one + * failing host cannot leave a timer publishing into a dead session. + */ + let closed = false; + let publishError: unknown; + + const closeEmitter = (): void => { + closed = true; + if (pendingPublish) { + clearTimeout(pendingPublish); + pendingPublish = undefined; + } + }; const publish = (mode: StepSubagentDetails["mode"]): void => { - if (!onUpdate) return; + if (closed || !onUpdate) return; lastPublishAt = Date.now(); lastStatusKey = statusKey(); const live = buildDetails(mode, discovery, scope, records.map(liveRecord)); onUpdate(makeToolResult(live, resultDetailsText(live))); }; + /** Run `publish`, attributing a failure to the call instead of the timer. */ + const publishSafely = (mode: StepSubagentDetails["mode"]): void => { + try { + publish(mode); + } catch (error) { + publishError ??= error; + closeEmitter(); + } + }; + /** * Publish the live roster, coalescing streamed updates. * @@ -486,31 +609,39 @@ export async function runPreparedSubagent( * live list shows besides the token counter, and readers rely on seeing every * one of them. Everything in between (a streamed delta, a tool-output chunk) * waits for the interval, with the latest records winning. + * + * Never throws; a consumer failure is surfaced once by `flushEmit`. */ const emit = (mode: StepSubagentDetails["mode"]): void => { - if (!onUpdate) return; + if (closed || !onUpdate) return; const wait = LIVE_UPDATE_INTERVAL_MS - (Date.now() - lastPublishAt); if (statusKey() !== lastStatusKey || wait <= 0) { if (pendingPublish) { clearTimeout(pendingPublish); pendingPublish = undefined; } - publish(mode); + publishSafely(mode); return; } pendingPublish ??= setTimeout(() => { pendingPublish = undefined; - publish(mode); + publishSafely(mode); }, wait); pendingPublish.unref?.(); }; - /** Publish the last coalesced update so the caller's final state is not dropped. */ + /** Publish the last coalesced update, close the emitter, and rethrow a consumer failure. */ const flushEmit = (mode: StepSubagentDetails["mode"]): void => { if (pendingPublish) { clearTimeout(pendingPublish); pendingPublish = undefined; - publish(mode); + publishSafely(mode); + } + closeEmitter(); + if (publishError !== undefined) { + const error = publishError; + publishError = undefined; + throw error instanceof Error ? error : new Error(String(error)); } }; @@ -688,12 +819,7 @@ export async function runPreparedSubagent( // A trailing coalesced update must not outlive the call or be lost. flushEmit(mode); } - const finalDetails = buildDetails( - mode, - discovery, - scope, - records.map((record) => ({ ...record, messages: boundedMessages(record.messages) })), - ); + const finalDetails = buildDetails(mode, discovery, scope, records.map(finalRecord)); if (mode === "parallel") { const success = records.filter((record) => record.status === "completed").length; const summaries = records.map( diff --git a/packages/coding-agent/src/modes/json-event.ts b/packages/coding-agent/src/modes/json-event.ts index 6c9976bb3..baa53f99e 100644 --- a/packages/coding-agent/src/modes/json-event.ts +++ b/packages/coding-agent/src/modes/json-event.ts @@ -85,27 +85,33 @@ type ToolExecutionUpdateEvent = Extract part.text) .join("\n"); - const tail = text.length > MAX_LIVE_UPDATE_BYTES / 4 ? text.slice(-(MAX_LIVE_UPDATE_BYTES / 4)) : text; - return { + + const candidate = (tail: string): JsonAgentSessionEvent => ({ type: "tool_execution_update", toolCallId: event.toolCallId, toolName: event.toolName, @@ -114,10 +120,22 @@ function boundLiveUpdate(event: ToolExecutionUpdateEvent): JsonAgentSessionEvent content: [ { type: "text", - text: tail ? `${tail}\n${TRUNCATED_MARKER}` : TRUNCATED_MARKER, + text: tail.length > 0 ? `${tail}\n${TRUNCATED_MARKER}` : TRUNCATED_MARKER, }, ], details: undefined, }, - }; + }); + + // Halve the retained tail until the whole serialized event fits. Starts at + // the full text so a moderately oversized update keeps as much as it can. + let kept = text; + let bounded = candidate(kept); + while (kept.length > 0 && serializedBytes(bounded) > MAX_LIVE_UPDATE_BYTES) { + kept = kept.slice(-Math.floor(kept.length / 2)); + bounded = candidate(kept); + } + // The envelope alone can still exceed the budget for a pathological id or + // name; the marker-only form is the smallest this function can produce. + return serializedBytes(bounded) <= MAX_LIVE_UPDATE_BYTES ? bounded : candidate(""); } diff --git a/packages/coding-agent/test/fixtures/subagent-stream-child.mjs b/packages/coding-agent/test/fixtures/subagent-stream-child.mjs new file mode 100644 index 000000000..fd7a639d3 --- /dev/null +++ b/packages/coding-agent/test/fixtures/subagent-stream-child.mjs @@ -0,0 +1,112 @@ +// Fake `step --mode rpc` child for the live-update regression tests. +// +// Speaks the real framing (one JSON object per LF-framed line) and streams what +// a long child produces: text deltas, persisted messages, tool progress. Only +// its token stream is synthetic; everything it drives on the parent side is the +// production rpc adapter, parser, orchestration, agent loop and json projection. +const TURNS = Number(process.env.STREAM_TURNS ?? 10); +const DELTAS = Number(process.env.STREAM_DELTAS ?? 40); +const TOOL_BYTES = Number(process.env.STREAM_TOOL_BYTES ?? 20_000); +const DELAY_MS = Number(process.env.STREAM_DELAY_MS ?? 0); +const FINAL_BYTES = Number(process.env.STREAM_FINAL_BYTES ?? 0); + +let buffer = ""; +process.stdin.setEncoding("utf8"); +process.stdin.on("data", (chunk) => { + buffer += chunk; + const lines = buffer.split("\n"); + buffer = lines.pop() ?? ""; + for (const line of lines) void handle(line.trim()); +}); + +const sleep = (ms) => (ms > 0 ? new Promise((resolve) => setTimeout(resolve, ms)) : Promise.resolve()); + +function write(value) { + process.stdout.write(`${JSON.stringify(value)}\n`); +} + +function assistant(content, stopReason = "stop") { + return { + role: "assistant", + content, + api: "anthropic-messages", + provider: "step", + model: "step-3.8-code-alpha", + usage: { input: 100, output: 50, cacheRead: 0, cacheWrite: 0, totalTokens: 150, cost: {} }, + stopReason, + timestamp: Date.now(), + }; +} + +async function handle(line) { + if (!line) return; + let command; + try { + command = JSON.parse(line); + } catch { + return; + } + if (command.type === "get_state") { + write({ + type: "response", + id: command.id, + command: "get_state", + success: true, + data: { sessionFile: "/tmp/stream-child-session.jsonl" }, + }); + return; + } + if (command.type === "abort") { + write({ type: "agent_settled" }); + return; + } + if (command.type !== "prompt") return; + + write({ type: "response", id: command.id, command: "prompt", success: true }); + write({ type: "agent_start" }); + + const messages = []; + for (let turn = 0; turn < TURNS; turn++) { + write({ type: "turn_start" }); + write({ type: "message_start", message: assistant([]) }); + let text = ""; + for (let index = 0; index < DELTAS; index++) { + const delta = `token-${turn}-${index} `; + text += delta; + write({ type: "message_update", assistantMessageEvent: { type: "text_delta", contentIndex: 0, delta } }); + await sleep(DELAY_MS); + } + const message = assistant([{ type: "text", text }], "toolUse"); + messages.push(message); + write({ type: "message_end", message }); + + const toolCallId = `call_${turn}`; + const output = "x".repeat(TOOL_BYTES); + write({ type: "tool_execution_start", toolCallId, toolName: "run_command", args: { command: `echo ${turn}` } }); + write({ type: "tool_execution_update", toolCallId, toolName: "run_command", partialResult: output }); + const result = { + role: "toolResult", + toolCallId, + toolName: "run_command", + content: [{ type: "text", text: output }], + isError: false, + timestamp: Date.now(), + }; + messages.push(result); + write({ + type: "tool_execution_end", + toolCallId, + toolName: "run_command", + result: { content: [{ type: "text", text: output }] }, + isError: false, + }); + write({ type: "message_end", message: result }); + write({ type: "turn_end" }); + await sleep(DELAY_MS); + } + + const finalText = `child finished${FINAL_BYTES > 0 ? ` ${"y".repeat(FINAL_BYTES)}` : ""}`; + write({ type: "message_end", message: assistant([{ type: "text", text: finalText }]) }); + write({ type: "agent_end" }); + write({ type: "agent_settled" }); +} diff --git a/packages/coding-agent/test/json-event-live-update-budget.test.ts b/packages/coding-agent/test/json-event-live-update-budget.test.ts index ea8210e42..00969988c 100644 --- a/packages/coding-agent/test/json-event-live-update-budget.test.ts +++ b/packages/coding-agent/test/json-event-live-update-budget.test.ts @@ -7,6 +7,10 @@ import { MAX_LIVE_UPDATE_BYTES, toJsonEvent } from "../src/modes/json-event.ts"; * as one JSONL line. The subagent orchestrator keeps its own live payload small; * this is the generic backstop for any other tool that re-sends accumulated * state, so one update can never become a multi-megabyte log line. + * + * The budget is on the *serialized* event: a control character or a lone + * surrogate becomes a six-byte JSON escape, so counting raw characters would + * under-count the bytes the host actually writes. */ function update(partialResult: unknown): AgentSessionEvent { @@ -19,29 +23,65 @@ function update(partialResult: unknown): AgentSessionEvent { }; } +function boundedEvent(partialResult: unknown): Extract { + return toJsonEvent(update(partialResult)) as Extract; +} + +function bytesOf(value: unknown): number { + return Buffer.byteLength(JSON.stringify(value), "utf8"); +} + +function textOf(event: Extract): string { + const part = event.partialResult?.content?.[0]; + return part?.type === "text" ? part.text : ""; +} + test("a live update under the budget passes through untouched", () => { const event = update({ content: [{ type: "text", text: "working" }], details: { results: [] } }); expect(toJsonEvent(event)).toBe(event); }); -test("an oversized live update is bounded while the terminal result is not", () => { +test("an oversized live update is bounded by serialized size, not raw characters", () => { const big = "x".repeat(4 * 1024 * 1024); - const bounded = toJsonEvent( - update({ - content: [{ type: "text", text: big }], - details: { results: [{ messages: [{ role: "user", content: big }] }] }, - }), - ) as Extract; - - expect(Buffer.byteLength(JSON.stringify(bounded), "utf8")).toBeLessThan(MAX_LIVE_UPDATE_BYTES / 2); + const bounded = boundedEvent({ + content: [{ type: "text", text: big }], + details: { results: [{ messages: [{ role: "user", content: big }] }] }, + }); + + expect(bytesOf(bounded)).toBeLessThanOrEqual(MAX_LIVE_UPDATE_BYTES); // The tail is what a live view renders, and the marker explains the gap. - const text = bounded.partialResult.content[0]?.type === "text" ? bounded.partialResult.content[0].text : ""; - expect(text.endsWith("[live output truncated]")).toBe(true); + expect(textOf(bounded).endsWith("[live output truncated]")).toBe(true); + expect(textOf(bounded).length).toBeGreaterThan(0); // `details`/`args` are already on tool_execution_start and tool_execution_end. expect(bounded.partialResult.details).toBeUndefined(); expect(bounded.args).toBeUndefined(); }); +test.each([ + ["control characters", "\u0001"], + ["quotes and backslashes", '"\\'], + ["multi-byte CJK", "\u4e2d"], + ["lone surrogate", "\ud800"], +])("an oversized update of %s still respects the byte budget", (_label, unit) => { + const bounded = boundedEvent({ content: [{ type: "text", text: unit.repeat(300_000) }] }); + expect(bytesOf(bounded)).toBeLessThanOrEqual(MAX_LIVE_UPDATE_BYTES); + expect(textOf(bounded)).toContain("[live output truncated]"); +}); + +test("an update just above the budget keeps as much of the tail as fits", () => { + const text = "z".repeat(Math.floor(MAX_LIVE_UPDATE_BYTES * 0.9)); + const bounded = boundedEvent({ content: [{ type: "text", text }] }); + expect(bytesOf(bounded)).toBeLessThanOrEqual(MAX_LIVE_UPDATE_BYTES); + // Far more than the minimum: the halving loop stops at the first fit. + expect(textOf(bounded).length).toBeGreaterThan(text.length / 2); +}); + +test("the envelope alone over budget still produces a minimal valid event", () => { + const bounded = boundedEvent({ content: [{ type: "text", text: "x" }] }); + expect(bounded.type).toBe("tool_execution_update"); + expect(bounded.toolCallId).toBe("call_1"); +}); + test("the terminal tool_execution_end event is never bounded", () => { const big = "x".repeat(4 * 1024 * 1024); const event: AgentSessionEvent = { diff --git a/packages/coding-agent/test/subagent-live-update-budget.test.ts b/packages/coding-agent/test/subagent-live-update-budget.test.ts index f4f82812a..5fee202c1 100644 --- a/packages/coding-agent/test/subagent-live-update-budget.test.ts +++ b/packages/coding-agent/test/subagent-live-update-budget.test.ts @@ -12,8 +12,9 @@ import { * Regression guard for the event-log amplification: every child event used to * become one `tool_execution_update` carrying the child's whole `messages` array, * so a 40-turn child wrote ~5 GB of JSONL whose lines were byte-identical - * repeats. These tests pin both halves of the bound — payload size and rate — - * and that neither costs a status transition or the final transcript. + * repeats. These tests pin the bound on every field a runner controls, the + * coalescing rate, and the emitter's lifecycle; `subagent-live-update-rpc.test.ts` + * covers the same path through a real rpc child. */ const LIVE_UPDATE_MAX_BYTES = 32 * 1024; @@ -79,100 +80,202 @@ interface Captured { details?: StepSubagentDetails; bytes: number; at: number; + /** Rendered text of the partial result, as a UI would read it. */ + text: string; } -async function runOnce( +async function run( + params: Record, runner: (input: StepSubagentRunInput) => Promise, + options: { onUpdateError?: Error; sink?: Captured[] } = {}, ): Promise<{ updates: Captured[]; result: AgentToolResult }> { const { api, tools } = createApi(); createStepSubagentExtension({ agentDir: "/tmp/step-agent-test", runner })(api); - const updates: Captured[] = []; + const updates: Captured[] = options.sink ?? []; const startedAt = Date.now(); const result = (await tools.get("subagent")!.execute( "call", - { agent: "general", task: "inspect" } as never, + params as never, undefined, (update) => { const details = update.details as StepSubagentDetails | undefined; + const text = update.content.find((block) => block.type === "text"); updates.push({ details, bytes: Buffer.byteLength(JSON.stringify(update), "utf8"), at: Date.now() - startedAt, + text: text?.type === "text" ? text.text : "", }); + if (options.onUpdateError) throw options.onUpdateError; }, createContext("/workspace"), )) as AgentToolResult; return { updates, result }; } +const idle: StepSubagentRunResult = { + messages: [], + stderr: "", + exitCode: -1, + usage: { input: 1, output: 1, cacheRead: 0, cacheWrite: 0, cost: 0, contextTokens: 2, turns: 1 }, +}; + test("a long streaming child produces bounded live updates instead of the whole transcript", async () => { const messages: StepSubagentRunResult["messages"] = [message(0, 2_000)]; - const { updates, result } = await runOnce(async (input) => { + const { updates, result } = await run({ agent: "general", task: "inspect" }, async (input) => { for (let index = 0; index < 400; index += 1) { messages.push(message(messages.length, 20_000)); input.onUpdate?.({ + ...idle, messages, - stderr: "", - exitCode: -1, - usage: { input: 1, output: 1, cacheRead: 0, cacheWrite: 0, cost: 0, contextTokens: 2, turns: 1 }, activeText: "y".repeat(50_000), activeTool: "run_command", activeToolArgs: "z".repeat(20_000), activeToolOutput: "w".repeat(20_000), lastEvent: "message_update", }); - // Let the coalescing timer fire so a live UI still gets updates. if (index % 40 === 0) await new Promise((resolve) => setTimeout(resolve, 5)); } - return { messages, stderr: "", exitCode: 0, usage: {} as never, stopReason: "stop" }; + return { ...idle, messages, exitCode: 0, stopReason: "stop" }; }); expect(updates.length).toBeGreaterThan(1); - // 400 events carrying a growing multi-megabyte transcript must not survive - // into the payload: no update carries `messages`, and each stays small. for (const update of updates) { const records = update.details?.results ?? []; expect(records).toHaveLength(1); expect(records[0]?.messages).toEqual([]); expect(update.bytes).toBeLessThan(LIVE_UPDATE_MAX_BYTES); } - const totalBytes = updates.reduce((sum, update) => sum + update.bytes, 0); - expect(totalBytes).toBeLessThan(2 * 1024 * 1024); - // The final result still describes the child and its transcript reference. + expect(updates.reduce((sum, update) => sum + update.bytes, 0)).toBeLessThan(2 * 1024 * 1024); expect(result.details?.results[0]?.status).toBe("completed"); }); -test("the final result keeps the newest transcript messages within the byte budget", async () => { +test("a chain's spliced {previous} prompt stays out of every live update", async () => { + const { updates } = await run( + { + chain: [ + { agent: "general", task: "first" }, + { agent: "general", task: "then {previous}" }, + ], + }, + async (input) => { + // The first step returns a huge answer; the second step's task therefore + // carries it verbatim, and every update during that step would repeat it. + const isSecond = input.task.includes("then "); + input.onUpdate?.({ ...idle, activeText: "working" }); + return { + ...idle, + messages: [message(0, isSecond ? 100 : 500_000)], + exitCode: 0, + stopReason: "stop", + }; + }, + ); + + for (const update of updates) { + expect(update.bytes).toBeLessThan(LIVE_UPDATE_MAX_BYTES); + for (const record of update.details?.results ?? []) { + expect(record.task.length).toBeLessThanOrEqual(600); + } + } + // The second step really did receive the spliced prompt, so the bound above + // is not vacuous. + expect(updates.some((update) => update.details?.results.length === 2)).toBe(true); +}); + +test("streamed deltas coalesce to one publish per interval, but status changes do not wait", async () => { + const seen: Captured[] = []; + const { updates } = await run( + { agent: "general", task: "inspect" }, + async (input) => { + for (let index = 0; index < 200; index += 1) input.onUpdate?.({ ...idle, activeText: `a${index}` }); + // Stay running past one interval so a coalesced publish is observable. + await new Promise((resolve) => setTimeout(resolve, 150)); + return { ...idle, exitCode: 0, stopReason: "stop" }; + }, + { sink: seen }, + ); + + // 200 deltas must not produce 200 publishes: queued, running, at most a + // couple of interval publishes, then completed. + expect(updates.length).toBeLessThanOrEqual(6); + expect(updates.length).toBeGreaterThanOrEqual(3); + const running = updates.filter((update) => update.details?.results[0]?.status === "running"); + // `running` is published by the first event, not deferred to the interval. + expect(running.length).toBeGreaterThanOrEqual(1); + expect(updates.at(-1)?.details?.results[0]?.status).toBe("completed"); +}); + +test("the final result keeps the newest transcript messages and says it truncated", async () => { const messages: StepSubagentRunResult["messages"] = []; for (let index = 0; index < 20; index += 1) messages.push(message(index, 40_000)); - const { result } = await runOnce(async () => ({ + const { result } = await run({ agent: "general", task: "inspect" }, async () => ({ + ...idle, messages, - stderr: "", exitCode: 0, - usage: {} as never, stopReason: "stop", })); - const kept = result.details?.results[0]?.messages ?? []; + const record = result.details?.results[0]; + const kept = record?.messages ?? []; expect(kept.length).toBeGreaterThan(0); expect(kept.length).toBeLessThan(messages.length); - // The newest message survives; older ones are dropped, not the other way round. expect(kept.at(-1)).toEqual(messages.at(-1)); + // Serialized array, brackets and commas included, stays inside the budget. expect(Buffer.byteLength(JSON.stringify(kept), "utf8")).toBeLessThanOrEqual(64 * 1024); + expect(record?.messagesTruncated).toBe(true); }); -test("a status transition publishes immediately, inside the coalescing window", async () => { - const { updates } = await runOnce(async (input) => { - // Two events within one interval: the running transition must not wait. - input.onUpdate?.({ messages: [], stderr: "", exitCode: -1, usage: {} as never, lastEvent: "turn_start" }); - input.onUpdate?.({ messages: [], stderr: "", exitCode: -1, usage: {} as never, lastEvent: "turn_start" }); - await new Promise((resolve) => setTimeout(resolve, 150)); - return { messages: [], stderr: "", exitCode: 0, usage: {} as never, stopReason: "stop" }; +test("a single message larger than the budget still leaves a readable result", async () => { + const { result } = await run({ agent: "general", task: "inspect" }, async () => ({ + ...idle, + // No `activeText` at all: a custom runner that only reports messages. + messages: [message(0, 200_000)], + exitCode: 0, + stopReason: "stop", + })); + const record = result.details?.results[0]; + expect(record?.messages).toEqual([]); + expect(record?.messagesTruncated).toBe(true); + // The fallback keeps the outcome renderable instead of "(no output)". + expect(record?.activeText ?? "").toContain("x"); +}); + +test("a huge final answer is bounded in the display projection", async () => { + const { result } = await run({ agent: "general", task: "inspect" }, async () => ({ + ...idle, + activeText: "q".repeat(400_000), + exitCode: 0, + stopReason: "stop", + })); + const record = result.details?.results[0]; + expect((record?.activeText ?? "").length).toBeLessThanOrEqual(8_000); + // The model-facing text is not the details field. + expect(result.content[0]).toMatchObject({ type: "text" }); +}); + +test("a late child callback after the call returns emits nothing", async () => { + let late: StepSubagentRunInput["onUpdate"]; + const { updates } = await run({ agent: "general", task: "inspect" }, async (input) => { + late = input.onUpdate; + input.onUpdate?.({ ...idle, activeText: "first" }); + return { ...idle, exitCode: 0, stopReason: "stop" }; }); - const statuses = updates.map((update) => update.details?.results[0]?.status); - expect(statuses[0]).toBe("queued"); - expect(statuses).toContain("running"); - expect(statuses.at(-1)).toBe("completed"); - // `running` arrived before the child finished, not only in the trailing flush. - const runningIndex = statuses.indexOf("running"); - expect(runningIndex).toBeLessThan(statuses.length - 1); + const settled = updates.length; + late?.({ ...idle, messages: [message(0, 100_000)], activeText: "late" }); + await new Promise((resolve) => setTimeout(resolve, 150)); + expect(updates.length).toBe(settled); +}); + +test("a consumer that throws on update fails the call instead of escaping a timer", async () => { + const failure = new Error("host went away"); + await expect( + run( + { agent: "general", task: "inspect" }, + async (input) => { + input.onUpdate?.({ ...idle, activeText: "first" }); + return { ...idle, exitCode: 0, stopReason: "stop" }; + }, + { onUpdateError: failure }, + ), + ).rejects.toThrow("host went away"); }); diff --git a/packages/coding-agent/test/subagent-live-update-rpc.test.ts b/packages/coding-agent/test/subagent-live-update-rpc.test.ts new file mode 100644 index 000000000..a753b0161 --- /dev/null +++ b/packages/coding-agent/test/subagent-live-update-rpc.test.ts @@ -0,0 +1,178 @@ +import { mkdtempSync, rmSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; +import { fileURLToPath } from "node:url"; +import { fauxAssistantMessage, fauxToolCall } from "@step-harness/providers"; +import { afterAll, afterEach, expect, test } from "vitest"; +import { createStepSubagentExtension } from "../src/features/step-subagent.ts"; +import { toJsonEvent } from "../src/modes/json-event.ts"; +import { createHarness, type Harness } from "./suite/harness.ts"; + +/** + * End-to-end guard for the log amplification, on the real path. + * + * A real `--mode rpc` child process is spawned through the production rpc + * adapter, parsed by the production event projection, executed by the + * production orchestrator, dispatched by the real Agent Loop, and serialized by + * `toJsonEvent` exactly as `--mode json` does. Only the parent's model is a test + * double (faux provider) and the child's tokens are synthetic. + * + * The regression: every child event used to become one `tool_execution_update` + * carrying the child's whole `messages` array, so the parent's log grew with the + * square of the child's transcript. + */ + +const childPath = fileURLToPath(new URL("./fixtures/subagent-stream-child.mjs", import.meta.url)); +const harnesses: Harness[] = []; +const originalArgv = process.argv; +const originalExecArgv = process.execArgv; +const envBackup = { ...process.env }; +// Keep the shared tool-output retention inside the test's own temp root instead +// of a developer's real agent directory. +const agentRoot = mkdtempSync(join(tmpdir(), "step-subagent-rpc-agent-")); + +afterEach(() => { + for (const key of [ + "STREAM_TURNS", + "STREAM_DELTAS", + "STREAM_TOOL_BYTES", + "STREAM_DELAY_MS", + "STREAM_FINAL_BYTES", + "STEP_CODING_AGENT_DIR", + ]) { + if (envBackup[key] === undefined) delete process.env[key]; + else process.env[key] = envBackup[key]; + } + process.argv = originalArgv; + process.execArgv = originalExecArgv; + while (harnesses.length > 0) harnesses.pop()?.cleanup(); +}); + +afterAll(() => { + rmSync(agentRoot, { recursive: true, force: true }); +}); + +interface RunStats { + logBytes: number; + updateCount: number; + largestUpdate: number; + updatesWithMessages: number; + finalMessagesBytes: number; + /** Model-facing tool result text, which must stay complete. */ + finalText: string; + /** Display-only `activeText` in the details, which must stay bounded. */ + finalActiveTextLength: number; +} + +async function runAgainstRealChild(env: Record): Promise { + Object.assign(process.env, { STEP_CODING_AGENT_DIR: agentRoot, ...env }); + // The default runner spawns `process.argv[1]`; point it at the fake rpc child + // and keep the parent's TS loader out of a plain-ESM child process. + process.argv[1] = childPath; + process.execArgv = process.execArgv.filter((arg) => !/^(?:--import|--loader|--require|-r)$/u.test(arg)); + + const harness = await createHarness({ + extensionFactories: [{ name: "step-subagent", factory: createStepSubagentExtension({ agentDir: agentRoot }) }], + }); + harnesses.push(harness); + + let logBytes = 0; + const stats: RunStats = { + logBytes: 0, + updateCount: 0, + largestUpdate: 0, + updatesWithMessages: 0, + finalMessagesBytes: 0, + finalText: "", + finalActiveTextLength: 0, + }; + harness.session.subscribe((event) => { + const bytes = Buffer.byteLength(JSON.stringify(toJsonEvent(event)), "utf8"); + logBytes += bytes; + if (event.type === "tool_execution_update") { + stats.updateCount += 1; + stats.largestUpdate = Math.max(stats.largestUpdate, bytes); + const results = event.partialResult?.details?.results; + if (Array.isArray(results)) { + for (const record of results) { + if (Array.isArray(record?.messages) && record.messages.length > 0) stats.updatesWithMessages += 1; + } + } + } + if (event.type === "tool_execution_end") { + const content: unknown[] = Array.isArray(event.result?.content) ? event.result.content : []; + stats.finalText = content + .filter( + (part): part is { type: "text"; text: string } => + part !== null && + typeof part === "object" && + (part as { type?: unknown }).type === "text" && + typeof (part as { text?: unknown }).text === "string", + ) + .map((part) => part.text) + .join("\n"); + const records = event.result?.details?.results; + if (Array.isArray(records)) { + stats.finalMessagesBytes = Buffer.byteLength( + JSON.stringify(records.map((record) => record?.messages ?? [])), + "utf8", + ); + stats.finalActiveTextLength = records.reduce( + (sum, record) => sum + (typeof record?.activeText === "string" ? record.activeText.length : 0), + 0, + ); + } + } + }); + stats.logBytes = logBytes; + + harness.setResponses([ + fauxAssistantMessage(fauxToolCall("subagent", { agent: "general", task: "inspect" }), { + stopReason: "toolUse", + }), + fauxAssistantMessage("parent done"), + ]); + await harness.session.prompt("delegate"); + stats.logBytes = logBytes; + return stats; +} + +test("a real rpc child streaming hundreds of events keeps the parent log bounded", async () => { + const stats = await runAgainstRealChild({ + STREAM_TURNS: "10", + STREAM_DELTAS: "40", + STREAM_TOOL_BYTES: "20000", + STREAM_DELAY_MS: "1", + }); + + // 10 turns x (40 deltas + a message_end + two tool events) is over 400 child + // events. Before the fix that was >400 updates each carrying the transcript. + expect(stats.updateCount).toBeGreaterThan(0); + expect(stats.updateCount).toBeLessThan(60); + expect(stats.updatesWithMessages).toBe(0); + // Whole parent log, not just the updates: the transcript is published once. + expect(stats.logBytes).toBeLessThan(1024 * 1024); + expect(stats.finalMessagesBytes).toBeLessThanOrEqual(64 * 1024); +}); + +test("a huge final answer from a real child cannot escape the display budget", async () => { + const stats = await runAgainstRealChild({ + STREAM_TURNS: "2", + STREAM_DELTAS: "5", + STREAM_TOOL_BYTES: "1000", + STREAM_FINAL_BYTES: "300000", + }); + + // A 300 KB answer used to sit in `activeText` and be echoed by every terminal + // event. The model-facing `content` stays complete; only the display copy is + // bounded, so the parent log does not grow with the child's answer. + // Model-facing text goes through the existing tool-result retention, so a + // single 300 KB line becomes a pointer to a saved artifact. Either way the + // answer never enters the event log at full size. + expect(stats.finalText.length).toBeLessThan(100_000); + expect(stats.finalText).toContain("Full output:"); + // The display copy in `details` is bounded by the orchestrator itself. + expect(stats.finalActiveTextLength).toBeLessThanOrEqual(8_000); + expect(stats.logBytes).toBeLessThan(1024 * 1024); + expect(stats.largestUpdate).toBeLessThan(64 * 1024); +}); From d120ee8b509b773919872992bbc29813b8e179e4 Mon Sep 17 00:00:00 2001 From: liuedcson <332840681+liuedcson@users.noreply.github.com> Date: Tue, 27 Oct 2026 22:02:18 +0800 Subject: [PATCH 3/8] fix(coding-agent): coalesce status publishes and close the remaining bounds MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Second review round. Three findings were real: - `boundLiveUpdate` could spin forever. At `kept.length === 1`, `slice(-0)` returns the whole string, so the halving loop never advanced. Truncating the envelope was also missing, so the loop could not converge at all once `toolCallId` alone exceeded the budget. - Status transitions bypassed the coalescing window. Each transition re-sent the whole roster, so a parallel batch was O(tasks^2): 600 tasks wrote 530 MiB of live payload in one call. Every update now shares the 100ms tick, the cadence the bash tool uses, and the final flush still guarantees the terminal state. Measured after the change: 200 tasks, < 60 publishes, < 128 KiB each, < 2 MiB total. - The roster itself was unbounded (`MAX_PARALLEL_TASKS` is 1000). Live records now stop at 48 KiB of serialized bytes and report `omittedResults`; the background lane merges by index so an omitted tail never erases known lanes. Also from review: `finalRecord` was still a spread, so unbounded identity/ path fields could reach the terminal details — it is now bounded too, records share one 256 KiB per-call budget, and `activeText` goes back to 50k characters so Ctrl+O does not silently shrink. The wire cap clips ids, measures serialized bytes, and the dispatch/flush error order keeps the real failure. Contract docs updated (`json.md`, `rpc.md`): oversized updates drop `args`/`details` and keep a text tail, stdout-only, extension handlers unaffected. Three existing tests asserted the old immediate-publish timing; they now wait for one tick, which is the new documented cadence, with the same assertions. --- .../README.md | 70 +++-- packages/coding-agent/docs/json.md | 18 +- packages/coding-agent/docs/rpc.md | 7 + .../docs/tool-output-retention.md | 27 +- .../src/features/step-subagent.ts | 6 + .../src/features/subagent/execute.ts | 241 ++++++++++++------ .../src/features/subagent/lane-lifecycle.ts | 25 +- packages/coding-agent/src/modes/json-event.ts | 30 ++- .../json-event-live-update-budget.test.ts | 34 ++- .../test/step-subagent-events.test.ts | 3 + .../test/subagent-background-tui.test.ts | 3 + .../test/subagent-chain-result.test.ts | 9 +- .../test/subagent-live-update-budget.test.ts | 37 ++- .../test/subagent-live-update-rpc.test.ts | 8 +- 14 files changed, 383 insertions(+), 135 deletions(-) diff --git a/docs/research/2026-10-27-subagent-live-update-amplification/README.md b/docs/research/2026-10-27-subagent-live-update-amplification/README.md index cb83cc1da..2a68396e3 100644 --- a/docs/research/2026-10-27-subagent-live-update-amplification/README.md +++ b/docs/research/2026-10-27-subagent-live-update-amplification/README.md @@ -78,20 +78,20 @@ REPRO_TURNS=40 REPRO_DELTAS=150 REPRO_TOOL_BYTES=40000 \ | | 持久化形态 | delta 落盘 | 工具 progress 落盘 | 写入触发 | 单个工具结果上限 | 子代理历史 | | --- | --- | --- | --- | --- | --- | --- | -| opencode | SQLite 行级 upsert | 否,`EphemeralDefinition` 类型强制 | 否,`Tool.Progress` 为 ephemeral | `text.ended` / `tool.success` / `step.ended` | 2000 行 / 50 KiB + 外置文件 | 独立 session,父存 `sessionID` + 最终文本 | -| codex | JSONL append(每 thread 一文件) | 否,`rollout/policy.rs` transient 黑名单 | 否,`ExecCommandOutputDelta` transient | `ItemCompleted` / 完整 `ResponseItem` | 64 KiB 截断 + head/tail 1 MiB 缓冲 | 独立 thread,父存 `agent_thread_id` | -| kimi-code | `wire.jsonl` append | 否,`durable` 默认 false | 否,`observable` only | durable event,`content.part` 在 step 结束 | 50k 字符 + spill 10M | 独立 `agents//wire.jsonl`,父存 `resultSummary` | -| minimax-code | `messages.jsonl` append | 否,WS `VOLATILE_EVENT_TYPES` | 否,`tool_execution_update` → `debug.trace` | **`message_end` / `tool_execution_end`** | 64 KiB + artifact | 独立 child session,父存报告 | -| deepseek-harness | `session.jsonl.zstd` append | 否,`agent/assistant-stream` 标注 transient | 事件词表里没有 progress 类型 | turn/step 边界 + 200ms 批 | spill 64 MiB + head/tail | 独立 session,父存 `childId` + `label` | -| ZCode | SQLite 行级 upsert | 否,`TRANSIENT_SESSION_EVENT_TYPES` | 否,同上 | pending/running/completed 三次 upsert | 30 KB + artifact | 独立 session,父存 `childSessionId` + `outputPath` | +| 类型级 ephemeral 的事件库 | SQLite 行级 upsert | 否,`ephemeral` 是互斥类型 | 否,progress 事件为 ephemeral | 文本块结束 / 工具结束 / step 结束 | 50 KiB + 外置文件 | 独立 session,父存 session id + 最终文本 | +| 事件策略过滤的 rollout | 每 thread 一个 JSONL | 否,transient 黑名单 | 否,输出 delta 为 transient | 完整 item 完成时 | 64 KiB 截断 + 1 MiB head/tail 缓冲 | 独立 thread,父存 thread id | +| 每 agent 一个事件日志 | `wire.jsonl` append | 否,`durable` 默认 false | 否,`observable` only | durable event,内容块在 step 结束时发 | 50k 字符 + spill 文件 | 独立 agent 日志,父存结果摘要 | +| 消息级 append 日志 | `messages.jsonl` append | 否,WS 层标为 volatile | 否,工具进度只走调试 trace | **message_end / tool_execution_end** | 64 KiB + artifact | 独立 child session,父存报告 | +| 压缩事件日志 | jsonl.zstd append | 否,流式帧标注 transient | 事件词表里没有 progress 类型 | turn/step 边界 + 200ms 批 | spill 64 MiB + head/tail | 独立 session,父存 childId + label | +| SQLite 行级 upsert | message/part 按主键覆盖 | 否,transient 事件类型集合 | 否,同上 | pending/running/completed 三次 upsert | 30 KB + artifact | 独立 session,父存 childSessionId + outputPath | -三处最值得借鉴的设计: +共同点(六个实现全部成立): -1. **把「能不能落盘」放进类型系统**(opencode `schema/src/event.ts:44-58`):`durable` 与 `ephemeral` 是互斥类型,`Text.Delta` 的注释直接写 *Stream fragments are live-only; Text.Ended is the replayable full-value boundary*. 写错的代码编译不过。 -2. **持久化决策收敛到存储入口**(codex `rollout/src/policy.rs:160-225`):transient 事件是显式黑名单,工具实现无法「手滑」写入大对象。 -3. **同源 fork 已经踩过并修过**(minimax 的 `pi-turn-runner/history.ts:93-110`):`flushTail` 只发 `messages.slice(cursor)`,且只在 `message_end` / `tool_execution_end` 触发 —— 正好是我们违反的两条。 - -另有一个高度同构的「前人踩坑记录」:ZCode `runner-debug.ts:468-535` 的中文注释写明,诊断日志反复写完整 messages 造成「三角形重复」,文件到 GB 级后在 V8 字符串分配阶段 native crash;最终解法是**单文件 + 相对上一版 delta + 尾部最多 64/256 条 + 64 MB/256 MB 硬上限并重置**。 +1. **流式增量永不进入持久化层**。要么在类型上把「可重放」与「仅实时」做成互斥类型(`ephemeral` 没有 durable envelope,写错编译不过),要么在存储入口用显式 transient 黑名单过滤(工具实现无法「手滑」写入大对象)。 +2. **持久化点是粗粒度生命周期**:一个内容块、一条完整消息、一次工具调用,绝不是一个 token。 +3. **子代理 transcript 有独立落点**,父会话只保留 id + 摘要 + 输出路径。 +4. **所有可能巨大的写入都有硬边界**:inline 上限(30 KB ~ 64 KiB)、超出外置文件、head/tail 缓冲、单文件上限。 +5. **调试/诊断日志单独治理**:不跟随主会话日志无限放大(其中一处实现记录过「反复写完整 messages → 三角形重复 → GB 级文件 → V8 字符串分配阶段 native crash」,最终改为单文件 + 相对上一版 delta + 尾部保留 + 硬上限重置)。 **结论:这不是某个实现的小疏忽,而是三层约定同时被违反**——流式增量进了 durable 层、子代理 transcript 进了父会话、写侧没有上限。所以修复必须同时补这三层,只改其中一层都会留下复发路径。 @@ -114,33 +114,46 @@ REPRO_TURNS=40 REPRO_DELTAS=150 REPRO_TOOL_BYTES=40000 \ **① 有界 live 投影**(`features/subagent/execute.ts`) +投影是**显式 allowlist**,不是 `{...record}` 打补丁:runner 的未知字段、chain 展开后的巨型 task、身份/路径字段都必须各自有边界。 + ```ts function liveRecord(record) { return { - ...record, - messages: [], // transcript 只随终态发布一次 - activeText: tailChars(record.activeText, 2_000), // UI 只渲染最后 8 行 + agent: clipMiddle(record.agent, 200), + task: clipMiddle(record.task, 600), // chain 会把上一步完整输出插进来 + status: record.status, + messages: [], // transcript 只随终态发布 + stderr: tailChars(record.stderr, 2_000), + activeText: tailChars(record.activeText, 2_000), activeToolArgs: tailChars(record.activeToolArgs, 500), activeToolOutput: tailChars(record.activeToolOutput, 1_000), + // model / sessionId / sessionFile / worktree* / lastEvent 同样有界 usage: cloneUsage(record.usage), }; } ``` +整个 roster 还受一个 **48 KiB / 次**的序列化字节预算约束:超出部分不发送,改为 `omittedResults: N`(`MAX_PARALLEL_TASKS` 允许 1000 个任务,完整 roster 是 O(N))。后台 lane 侧按 index 合并,因此被省略的尾部不会让已存在的 lane 从内存列表里消失。 + **② 合流节流**:`LIVE_UPDATE_INTERVAL_MS = 100`(与既有 `BASH_UPDATE_THROTTLE_MS` 一致)。 -- 状态跃迁(queued → running → completed/failed/aborted)**立即发布**,不进入节流窗口 —— 直播列表唯一需要「一次不丢」的信息。 -- 其余(delta、工具输出块)在窗口内合并,最新记录胜出。 -- `finally` 中 `flushEmit`,保证尾包不丢、也不会在调用返回后迟到投递。 +- **所有**更新(含 queued → running → completed 状态跃迁)都进入同一个 100 ms 窗口,最新记录胜出。 + 最初版本让状态跃迁立即发布,评审实测出后果:parallel 下每个任务 2 次跃迁 × 每次重发整个 roster = **O(N²)**,600 个任务在一次调用里写出 530 MiB。这与本次要消灭的放大是同一类。 +- 代价是状态在列表里最多晚 100 ms,远低于人眼可辨阈值;调用返回前 `flushEmit` 强制刷出终态。 +- `flushEmit` 位于 dispatch 之外:先 flush、再按「dispatch 错误优先」的顺序抛出,因此消费者异常不会覆盖真实失败原因。 **③ 终态投影**:终态 details 同样是展示投影,不是原始数据的拷贝。 - `messages` 只保留最新的、序列化后总量 ≤ 64 KiB 的消息(大小为选值,不与仓库既有的 50 KiB 文本上限混同);被裁剪时置 `messagesTruncated: true`。 -- `activeText` ≤ 8,000 字符、`task` ≤ 2,000 字符、`stderr` / `errorMessage` ≤ 2,000 字符、`cancelledPrompts` ≤ 20 条 × 200 字符。 +- 全部 record 共享一个 **256 KiB / 次调用**的预算,按记录顺序消费;`activeText` 单条 ≤ 50,000 字符(与渲染端一致,不缩小 Ctrl+O 展开视图)、`task` ≤ 2,000 字符、`stderr` / `errorMessage` ≤ 2,000 字符、`cancelledPrompts` ≤ 20 条 × 200 字符。 - `activeText` 缺失时由**完整 transcript** 的最终 assistant 文本回填,因此「单条消息超出预算导致 messages 为空」不会让结果渲染成 `(no output)`。 - 模型可见的 `content` 不受这些限制,仍走既有的 50 KiB / 2,000 行 tool-output retention;完整 transcript 留在子会话(`sessionId` / `sessionFile`)。 -**④ 通用 wire 兜底**(`modes/json-event.ts`):单条 `tool_execution_update` 超过 256 KiB 时,保留文本尾部 + `[live output truncated]` 标记,丢弃 `details`/`args`(它们已分别存在于 `tool_execution_start` / `tool_execution_end`)。**终态事件永不裁剪**。256 KiB 远高于正常流式工具单次上传量(bash 滚动快照 50 KiB 且已 100 ms 节流),因此只对「重发累积状态」的生产者生效。 +**④ 通用 wire 兜底**(`modes/json-event.ts`):单条 `tool_execution_update` 超过 **256 KiB 序列化字节**时,保留文本尾部 + `[live output truncated]` 标记,丢弃 `details`/`args`(它们已分别存在于 `tool_execution_start` / `tool_execution_end`)。**终态事件永不裁剪**。 + +- 上限按**序列化后**的字节计:控制字符与孤立 surrogate 会变成 6 字节转义,按字符数计会低估 6 倍。 +- 循环每轮严格缩短(`>= 1` 时直接清空),并且对 `toolCallId` / `toolName` 也设上限 —— 否则信封本身超限时循环无法收敛(这是评审抓到的死循环)。 +- 契约变更已同步到 `docs/json.md`、`docs/rpc.md`,并注明只影响 stdout 投影、不影响扩展 handler。 **⑤ 文档**:`packages/coding-agent/docs/tool-output-retention.md` 新增 *Live tool updates* 一节,说明「最终结果上限」与「直播上限」是两套独立的边界。 @@ -148,12 +161,14 @@ function liveRecord(record) { | 子会话规模 | 修复前 | 修复后 | 降幅 | | --- | --- | --- | --- | -| 20 轮 × 60 delta,20 KB 工具结果 | 268.05 MiB | **0.41 MiB** | 654× | -| 40 轮 × 150 delta,40 KB 工具结果 | 4992.61 MiB | **0.31 MiB** | 16105× | +| 20 轮 × 60 delta,20 KB 工具结果 | 268.05 MiB | **0.32 MiB** | 837× | +| 40 轮 × 150 delta,40 KB 工具结果 | 4992.61 MiB | **0.22 MiB** | 22693× | `tool_execution_update` 条数 6327 → 3(本次假子进程瞬时吐完;真实流式按 10 Hz 产出)。父进程峰值 RSS 1333 MiB → 271 MiB。 -剩余体积构成:终态 tool result(≤ 64 KiB messages + 各展示字段上限)被约 5 类事件各回显一次(`tool_execution_end`、工具结果的 `message_end`、`turn_end`、`agent_end`),因此单次调用约 5 × 100 KiB。**上界由预算决定,与子会话长度无关**(20 轮 0.32 MiB,40 轮 0.22 MiB)。 +剩余体积构成:终态 tool result(共享 256 KiB 预算)被约 5 类事件各回显一次(`tool_execution_end`、工具结果的 `message_end`、`turn_end`、`agent_end`),因此单次调用约 5 × 100 KiB。**上界由预算决定,与子会话长度无关**(20 轮 0.32 MiB,40 轮 0.22 MiB)。 + +parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB,总量 < 2 MiB;修复前同一场景是 O(N²)。 --- @@ -176,18 +191,19 @@ function liveRecord(record) { - **不改变** 状态机的对外语义:所有状态跃迁仍然逐次可见。 - 直播期间的 `activeText` 从最多 50k 字符变为 2k 尾部,工具入参/输出也从完整值变为尾部:这是**刻意的可见降级**(progress 是可合并快照,不是完整事件历史)。 - 可观测契约变化:`StepSubagentDetails.results[].messages` 从「全量」变为「终态限量」并新增可选 `messagesTruncated`;直播字段变为有界尾部。消费方(TUI 展开、历史渲染、web 子代理卡片)只用最后一个 assistant 文本或状态字段,已逐一核对。 -- 定时器在 `finally` 关闭(`closeEmitter`),调用返回后的迟到回调不再发布;`onUpdate` 抛错不再从定时器逃逸成未捕获异常,而是在调用路径上抛出。 +- 定时器在返回前关闭(`closeEmitter`),调用返回后的迟到回调不再发布;`onUpdate` 抛错不再从定时器逃逸成未捕获异常,而是按「dispatch 错误优先」的顺序在调用路径上抛出。 - `mapWithConcurrency` 改为等待所有 worker 结束(`allSettled`)再返回,避免 fail-fast 提前返回后仍有 lane 对着已关闭的 emitter 继续工作。 ### 4.3 测试与验证 -新增(19 个用例): +新增(21 个用例): - `test/subagent-live-update-rpc.test.ts` —— **端到端**:真起 `--mode rpc` 子进程,走真实 rpc-adapter → parseJsonEvent → 编排 → Agent Loop → toJsonEvent。断言整条父日志 < 1 MiB、update 数 < 60、无一条 update 携带 messages、终态 messages ≤ 64 KiB;并用 300 KB 最终答复验证展示投影有界而模型可见 `content` 仍完整。 - `test/subagent-live-update-budget.test.ts` - 400 次携带增长 transcript 的 update:live 一律 `messages: []`、单条 < 32 KiB、总量 < 2 MiB; - chain 把上一步 500 KB 输出插入下一步 task,所有 update 仍 < 32 KiB、`task` ≤ 600 字符; - - 200 次 delta 只产生 ≤ 6 次发布,`running` 由首个事件即时发布; + - 200 次 delta 只产生 ≤ 6 次发布; + - 200 个并行任务的批量调用:发布 < 60 次、单条 < 128 KiB、总量 < 2 MiB、出现 `omittedResults`; - 终态预算:保留最新消息、序列化数组 ≤ 64 KiB、`messagesTruncated: true`; - 单条消息超预算且无 `activeText` 时,仍从完整 transcript 回填可渲染文本; - 400 KB 最终答复在展示投影里被压到 ≤ 8,000 字符; @@ -214,7 +230,7 @@ function liveRecord(record) { | 合流定时器泄漏/迟到投递 | `finally` 中 `flushEmit`;`unref()` | | 后续 web 分支合并冲突 | 改动集中在 `emit` 与 dispatch 外层(`try/finally`);web 分支改的是 `runOne` 内部与 `sessionId` 传递,冲突面小 | -回滚:单 commit(`fix(coding-agent): bound subagent live updates instead of re-sending the transcript`),`git revert` 即恢复原行为,无数据迁移、无配置项。 +回滚:分支上两个 commit(初版 + 评审修正),`git revert` 两个即恢复原行为,无数据迁移、无配置项。 ### 4.5 后续(未纳入本 PR) diff --git a/packages/coding-agent/docs/json.md b/packages/coding-agent/docs/json.md index fff0229ba..c83300f29 100644 --- a/packages/coding-agent/docs/json.md +++ b/packages/coding-agent/docs/json.md @@ -47,10 +47,26 @@ type AgentEvent = | { type: "message_end"; message: AgentMessage } // Tool execution | { type: "tool_execution_start"; toolCallId: string; toolName: string; args: any } - | { type: "tool_execution_update"; toolCallId: string; toolName: string; args: any; partialResult: any } + // `args`/`details` may be omitted and the text reduced to a tail when one + // update would exceed the wire budget; see "Live tool updates" below. + | { type: "tool_execution_update"; toolCallId: string; toolName: string; args?: any; partialResult: any } | { type: "tool_execution_end"; toolCallId: string; toolName: string; result: any; isError: boolean }; ``` +## Live tool updates + +`tool_execution_update` is progress, and a `json` consumer typically redirects it +to a log, so one update is capped at 256 KiB of serialized bytes. An oversized +update is replaced by the tail of its text plus a `[live output truncated]` +marker, and its `args`/`details` are omitted — both are already on the matching +`tool_execution_start` and `tool_execution_end`. The cap applies only to this +stdout projection: extension handlers see the original event, and terminal +results are never bounded here. Treat an update as a display snapshot that may +be replaced wholesale, not as a complete event history. + +The producer rate is also bounded: the subagent tool publishes at most one +update per 100 ms, and its live roster carries no child transcript. + ## Message Types Base messages from [`packages/providers/src/types.ts`](https://github.com/stepfun-ai/step-harness/blob/main/packages/providers/src/types.ts#L134): diff --git a/packages/coding-agent/docs/rpc.md b/packages/coding-agent/docs/rpc.md index 303f08aa3..0ca664c0f 100644 --- a/packages/coding-agent/docs/rpc.md +++ b/packages/coding-agent/docs/rpc.md @@ -1054,6 +1054,13 @@ When complete: Use `toolCallId` to correlate events. The `partialResult` in `tool_execution_update` contains the accumulated output so far (not just the delta), allowing clients to simply replace their display on each update. +One update is capped at 256 KiB of serialized bytes. An oversized update keeps +only the tail of its text, adds a `[live output truncated]` marker, and omits +`args`/`details`; read those from `tool_execution_start`/`tool_execution_end` +instead, which are never bounded. The cap applies to the stdout projection only, +not to in-process extension handlers. The subagent tool additionally coalesces +updates to at most one per 100 ms and omits a child's transcript from them. + ### queue_update Emitted whenever the pending steering or follow-up queue changes. diff --git a/packages/coding-agent/docs/tool-output-retention.md b/packages/coding-agent/docs/tool-output-retention.md index 0ff8baae7..0b0a8584f 100644 --- a/packages/coding-agent/docs/tool-output-retention.md +++ b/packages/coding-agent/docs/tool-output-retention.md @@ -40,20 +40,27 @@ A tool's `onUpdate` callbacks are progress, not results. They run while the call is in flight and each one becomes a `tool_execution_update` session event, which the `json` and `rpc` modes write as one JSONL line — so a host that redirects that stream to a file turns progress into log volume. The bound is -`O(elapsed time x bounded payload)`, not a constant log size: +`O(elapsed time x bounded payload)`, not a constant log size. Both factors are +bounded: - A producer sends at most one update per 100 ms (the same cadence the bash tool - uses) and publishes state transitions immediately. + uses). Status transitions are coalesced into the same window too: publishing + each one immediately makes a parallel batch quadratic (N transitions times a + roster of N), which is the amplification this bound exists to prevent. The + terminal state is always flushed before the call returns. - A live update is an explicit projection, never the accumulated call state. The subagent orchestrator drops `messages`, keeps a short tail of the streamed - text / tool output / stderr, and clips a task prompt at both ends, because a - chain splices the previous step's whole answer into the next step's task. -- The final record is also a display projection: the newest messages that fit - 64 KiB, an 8,000-character `activeText`, and every other rendered field - bounded. `messagesTruncated` says when the transcript tail was cut, and the - full transcript stays in the child session (`sessionId` / `sessionFile`). - The model-facing `content` is unaffected and still passes through this - document's 50 KiB retention. + text / tool output / stderr, clips every identifier and a task prompt at both + ends, and stops adding records once the roster reaches 48 KiB — reporting the + rest as `omittedResults`. A chain splices the previous step's whole answer + into the next step's task, so a spread would repeat it on every tick. +- The final records are also a display projection sharing one 256 KiB budget: + the newest messages that fit (64 KiB per record), an `activeText` capped at + 50,000 characters (the renderer's own truncation point), and every other + rendered field bounded. `messagesTruncated` says when a transcript tail was + cut, and the full transcript stays in the child session (`sessionId` / + `sessionFile`). The model-facing `content` is unaffected and still passes + through this document's 50 KiB retention. `toJsonEvent` additionally bounds a single `tool_execution_update` at 256 KiB of *serialized* bytes. That backstop exists for third-party tools that re-send diff --git a/packages/coding-agent/src/features/step-subagent.ts b/packages/coding-agent/src/features/step-subagent.ts index f05305aed..90a817572 100644 --- a/packages/coding-agent/src/features/step-subagent.ts +++ b/packages/coding-agent/src/features/step-subagent.ts @@ -231,6 +231,12 @@ export interface StepSubagentDetails { status?: "running" | "completed" | "failed" | "aborted"; startedAt?: number; updatedAt?: number; + /** + * Records left out of this live roster to keep one update bounded. Only set + * while running with a large parallel batch; the final result reports every + * task. Renderers may show it as "+N more". + */ + omittedResults?: number; } export interface StepSubagentExtensionOptions { diff --git a/packages/coding-agent/src/features/subagent/execute.ts b/packages/coding-agent/src/features/subagent/execute.ts index 8a6687620..79b0ff7bb 100644 --- a/packages/coding-agent/src/features/subagent/execute.ts +++ b/packages/coding-agent/src/features/subagent/execute.ts @@ -49,22 +49,27 @@ import { truncateText } from "./lane-events.ts"; import type { StepSubagentLaneRuntime } from "./lane-lifecycle.ts"; /** - * Live-update budget. + * Buffer budget. * * A blocking call mirrors every child event into one `onUpdate`, and the Agent * Loop turns each of them into a `tool_execution_update` that hosts persist: the * `json`/`rpc` modes write one JSONL line per event, so the parent's event log - * *is* this stream. Two independent properties keep that stream from growing - * with the child's transcript: + * *is* this stream. Three properties keep that stream bounded; without them a + * 20-turn child emits ~1.4k updates that each carry the whole transcript, and + * 99% of the log is byte-identical repeats. * - * - `LIVE_UPDATE_INTERVAL_MS` caps the rate (the bash tool throttles at the same - * 100ms; a faster cadence buys no visible UI change). - * - The live projection drops `messages` entirely and keeps only the tail of the - * streamed text, so one update is bounded regardless of how much the child has - * produced. The full transcript is published once, in the final result. - * - * Without both, a 20-turn child emits ~1.4k updates that each carry the whole - * transcript: 99% of the log is byte-identical repeats. + * - `LIVE_UPDATE_INTERVAL_MS` caps the rate. Every event coalesces into the next + * tick — status transitions included — because publishing transitions at once + * makes a parallel batch cost O(tasks^2): N transitions times a roster of N + * records. The terminal state is still guaranteed by the final flush, and a + * 100ms delay is below what a reader can notice (the bash tool throttles at + * the same cadence for the same reason). + * - Each record is an explicit projection with per-field bounds, never the + * accumulated record: a chain splices the previous step's whole answer into + * the next step's task, so a spread would repeat megabytes per tick. + * - The roster itself is bounded by bytes. `MAX_PARALLEL_TASKS` is 1000, so a + * complete roster would still be O(tasks) per tick; records past the budget + * are counted in `omittedResults` instead. */ const LIVE_UPDATE_INTERVAL_MS = 100; const LIVE_TEXT_CHARS = 2_000; @@ -75,20 +80,28 @@ const LIVE_STDERR_CHARS = 2_000; const LIVE_ERROR_CHARS = 2_000; const LIVE_PROMPT_CHARS = 200; const LIVE_CANCELLED_PROMPTS = 20; +/** Identity and path fields are machine-read, so they keep both ends. */ +const LIVE_IDENTIFIER_CHARS = 200; +const LIVE_PATH_CHARS = 500; +/** Per-record transcript allowance inside the shared final budget. */ +const FINAL_MESSAGES_BYTES = 64 * 1024; +/** Serialized budget for one live roster; a renderer only shows a few rows. */ +const LIVE_DETAILS_BYTES = 48 * 1024; /** - * Final-result budget for the child transcript embedded in the tool result. + * Final-result budget for the details embedded in the tool result. * - * The final details are persisted once per call, so this is not a rate problem, - * but a long child can still hold megabytes of tool output that the parent never - * renders. Keep the newest messages that fit; the final assistant text stays in - * `activeText`, and `sessionFile`/`sessionId` point at the child's own - * transcript for anything older. 64 KiB matches the cap the other hosts in this - * repository apply to a persisted command result. + * The final result is persisted once per call, so this is not a rate problem, + * but it is echoed by several terminal events and a long child can hold + * megabytes of tool output the parent never renders. Heavy fields share one + * per-call budget, consumed in record order; status, ids and usage stay complete + * because they are small and machine-read. The final assistant text is kept in + * `activeText` (and therefore still renderable), and `sessionFile`/`sessionId` + * point at the child's own transcript for anything older. */ -const FINAL_MESSAGES_BYTES = 64 * 1024; -/** Display-only bounds on the final record; `content` carries the model-facing text. */ -const FINAL_TEXT_CHARS = 8_000; +const FINAL_DETAILS_BYTES = 256 * 1024; +/** Per-record cap inside the shared final budget; matches the renderer's own truncation. */ +const FINAL_TEXT_CHARS = 50_000; const FINAL_TASK_CHARS = 2_000; export interface StepSubagentTaskInput { @@ -223,7 +236,7 @@ function clipMiddle(value: string, max: number): string { */ function liveRecord(record: StepSubagentResultRecord): StepSubagentResultRecord { return { - agent: record.agent, + agent: clipMiddle(record.agent, LIVE_IDENTIFIER_CHARS), agentSource: record.agentSource, task: clipMiddle(record.task, LIVE_TASK_CHARS), status: record.status, @@ -231,27 +244,28 @@ function liveRecord(record: StepSubagentResultRecord): StepSubagentResultRecord messages: [], stderr: tailChars(record.stderr, LIVE_STDERR_CHARS) ?? "", usage: cloneUsage(record.usage), - ...(record.model === undefined ? {} : { model: record.model }), - ...(record.stopReason === undefined ? {} : { stopReason: record.stopReason }), + ...(record.model === undefined ? {} : { model: clipMiddle(record.model, LIVE_IDENTIFIER_CHARS) }), + ...(record.stopReason === undefined ? {} : { stopReason: clipMiddle(record.stopReason, LIVE_IDENTIFIER_CHARS) }), ...(record.errorMessage === undefined ? {} : { errorMessage: tailChars(record.errorMessage, LIVE_ERROR_CHARS) }), ...(record.activeText === undefined ? {} : { activeText: tailChars(record.activeText, LIVE_TEXT_CHARS) }), - ...(record.activeTool === undefined ? {} : { activeTool: record.activeTool }), + ...(record.activeTool === undefined ? {} : { activeTool: clipMiddle(record.activeTool, LIVE_IDENTIFIER_CHARS) }), ...(record.activeToolArgs === undefined ? {} : { activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS) }), ...(record.activeToolOutput === undefined ? {} : { activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS) }), - ...(record.lastEvent === undefined ? {} : { lastEvent: record.lastEvent }), + ...(record.lastEvent === undefined ? {} : { lastEvent: clipMiddle(record.lastEvent, LIVE_IDENTIFIER_CHARS) }), ...(record.startedAt === undefined ? {} : { startedAt: record.startedAt }), ...(record.updatedAt === undefined ? {} : { updatedAt: record.updatedAt }), ...(record.step === undefined ? {} : { step: record.step }), - ...(record.worktreePath === undefined ? {} : { worktreePath: record.worktreePath }), - ...(record.worktreeBranch === undefined ? {} : { worktreeBranch: record.worktreeBranch }), - ...(record.sessionId === undefined ? {} : { sessionId: record.sessionId }), - ...(record.sessionFile === undefined ? {} : { sessionFile: record.sessionFile }), + ...(record.worktreePath === undefined ? {} : { worktreePath: clipMiddle(record.worktreePath, LIVE_PATH_CHARS) }), + ...(record.worktreeBranch === undefined + ? {} + : { worktreeBranch: clipMiddle(record.worktreeBranch, LIVE_IDENTIFIER_CHARS) }), + ...(record.sessionId === undefined ? {} : { sessionId: clipMiddle(record.sessionId, LIVE_IDENTIFIER_CHARS) }), + ...(record.sessionFile === undefined ? {} : { sessionFile: clipMiddle(record.sessionFile, LIVE_PATH_CHARS) }), ...(record.pendingReply === undefined ? {} : { pendingReply: record.pendingReply }), - ...boundedPrompts(record.cancelledPrompts), }; } @@ -264,19 +278,75 @@ function boundedPrompts(prompts: string[] | undefined): { cancelledPrompts?: str }; } -/** Final transcript projection: newest messages that fit, plus why they were cut. */ -function boundedMessages(messages: readonly unknown[]): { - messages: StepSubagentRunResult["messages"]; - truncated: boolean; +/** Serialized size of a projected record, guarding against values JSON cannot represent. */ +function serializedBytes(value: unknown): number { + try { + return Buffer.byteLength(JSON.stringify(value), "utf8"); + } catch { + // A runner that returns BigInt or a cycle must not crash the projection. + return Number.POSITIVE_INFINITY; + } +} + +interface Budget { + remaining: number; +} + +function take(budget: Budget, value: unknown): boolean { + const size = serializedBytes(value) + 1; + if (size > budget.remaining) return false; + budget.remaining -= size; + return true; +} + +/** + * Bound the live roster by bytes. + * + * `MAX_PARALLEL_TASKS` allows 1000 tasks, and a complete roster would cost + * O(tasks) on every tick. Records that do not fit are counted instead of + * dropped silently; the final result still reports every task. A renderer shows + * a handful of rows anyway, so the tail only matters for counts. + */ +function liveDetails( + mode: StepSubagentDetails["mode"], + discovery: StepAgentDiscoveryResult, + scope: StepAgentScope, + records: readonly StepSubagentResultRecord[], +): StepSubagentDetails { + const budget: Budget = { remaining: LIVE_DETAILS_BYTES }; + const results: StepSubagentResultRecord[] = []; + for (const record of records) { + const projected = liveRecord(record); + // Always include the first record: a roster that reports only a count is + // less useful than one slightly over budget. + if (results.length > 0 && !take(budget, projected)) break; + results.push(projected); + } + const details: StepSubagentDetails = { mode, agentScope: scope, ...discoveryFields(discovery), results }; + const omitted = records.length - results.length; + return omitted > 0 ? { ...details, omittedResults: omitted } : details; +} + +function discoveryFields(discovery: StepAgentDiscoveryResult): { + userAgentsDir: string; + projectAgentsDir: string | null; } { + return { userAgentsDir: discovery.userAgentsDir, projectAgentsDir: discovery.projectAgentsDir }; +} + +/** Final transcript projection: newest messages that fit, plus why they were cut. */ +function boundedMessages( + messages: readonly unknown[], + budget: number, +): { messages: StepSubagentRunResult["messages"]; truncated: boolean } { if (messages.length === 0) return { messages: [], truncated: false }; const kept: unknown[] = []; // Reserve the brackets and count each retained element's separating comma so // the check is on the serialized array, not on the sum of its members. let bytes = 2; for (let index = messages.length - 1; index >= 0; index -= 1) { - const size = Buffer.byteLength(JSON.stringify(messages[index]) ?? "", "utf8") + 1; - if (bytes + size > FINAL_MESSAGES_BYTES) break; + const size = serializedBytes(messages[index]) + 1; + if (bytes + size > budget) break; bytes += size; kept.push(messages[index]); } @@ -295,24 +365,40 @@ function boundedMessages(messages: readonly unknown[]): { * the transcript when a runner did not set it, so trimming `messages` can never * turn a completed record into "(no output)". */ -function finalRecord(record: StepSubagentResultRecord): StepSubagentResultRecord { - const bounded = boundedMessages(record.messages); - // Fall back to the full transcript, not the bounded copy: one message larger - // than the budget leaves `messages` empty, and the result must still render. - const fallbackText = finalOutput(record.messages); - return { - ...record, - task: clipMiddle(record.task, FINAL_TASK_CHARS), - messages: bounded.messages, - activeText: tailChars(record.activeText || fallbackText, FINAL_TEXT_CHARS), - activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS), - activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS), - stderr: tailChars(record.stderr, LIVE_STDERR_CHARS) ?? "", - ...(record.errorMessage === undefined ? {} : { errorMessage: tailChars(record.errorMessage, LIVE_ERROR_CHARS) }), - ...boundedPrompts(record.cancelledPrompts), - ...(bounded.truncated ? { messagesTruncated: true } : {}), - usage: cloneUsage(record.usage), - }; +function finalRecords(records: readonly StepSubagentResultRecord[]): StepSubagentResultRecord[] { + const budget: Budget = { remaining: FINAL_DETAILS_BYTES }; + return records.map((record) => { + // Fall back to the full transcript, not the bounded copy: one message larger + // than the per-record allowance leaves `messages` empty, and the result must + // still render. + const fallbackText = finalOutput(record.messages); + const text = record.activeText || fallbackText; + const textAllowance = Math.min(FINAL_TEXT_CHARS, Math.max(0, Math.floor(budget.remaining / 4))); + const activeText = tailChars(text, textAllowance); + if (activeText !== undefined) take(budget, activeText); + + const messageAllowance = Math.min(FINAL_MESSAGES_BYTES, Math.max(0, budget.remaining)); + const bounded = boundedMessages(record.messages, messageAllowance); + take(budget, bounded.messages); + + const task = clipMiddle(record.task, FINAL_TASK_CHARS); + take(budget, task); + return { + ...record, + task, + messages: bounded.messages, + activeText, + activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS), + activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS), + stderr: tailChars(record.stderr, LIVE_STDERR_CHARS) ?? "", + ...(record.errorMessage === undefined + ? {} + : { errorMessage: tailChars(record.errorMessage, LIVE_ERROR_CHARS) }), + ...boundedPrompts(record.cancelledPrompts), + ...(bounded.truncated ? { messagesTruncated: true } : {}), + usage: cloneUsage(record.usage), + }; + }); } async function mapWithConcurrency( @@ -563,8 +649,6 @@ export async function runPreparedSubagent( duration_ms: Math.max(0, Date.now() - (createdAt[index] ?? Date.now())), }); }; - const statusKey = (): string => records.map((record) => record.status).join("\u0000"); - let lastStatusKey = ""; let lastPublishAt = 0; let pendingPublish: ReturnType | undefined; /** @@ -587,8 +671,7 @@ export async function runPreparedSubagent( const publish = (mode: StepSubagentDetails["mode"]): void => { if (closed || !onUpdate) return; lastPublishAt = Date.now(); - lastStatusKey = statusKey(); - const live = buildDetails(mode, discovery, scope, records.map(liveRecord)); + const live = liveDetails(mode, discovery, scope, records); onUpdate(makeToolResult(live, resultDetailsText(live))); }; @@ -603,27 +686,24 @@ export async function runPreparedSubagent( }; /** - * Publish the live roster, coalescing streamed updates. + * Publish the live roster, coalescing every update into the next tick. * - * A status transition is always published at once: it is the only change the - * live list shows besides the token counter, and readers rely on seeing every - * one of them. Everything in between (a streamed delta, a tool-output chunk) - * waits for the interval, with the latest records winning. + * Status transitions are coalesced too. Publishing each one immediately makes + * a parallel batch quadratic — N transitions, each re-sending a roster of N + * records — which is the same amplification this file exists to remove. The + * trade is at most one interval of latency, the cadence the bash tool already + * uses, and the final flush guarantees the terminal state is never dropped. * * Never throws; a consumer failure is surfaced once by `flushEmit`. */ const emit = (mode: StepSubagentDetails["mode"]): void => { - if (closed || !onUpdate) return; + if (closed || !onUpdate || pendingPublish) return; const wait = LIVE_UPDATE_INTERVAL_MS - (Date.now() - lastPublishAt); - if (statusKey() !== lastStatusKey || wait <= 0) { - if (pendingPublish) { - clearTimeout(pendingPublish); - pendingPublish = undefined; - } + if (wait <= 0) { publishSafely(mode); return; } - pendingPublish ??= setTimeout(() => { + pendingPublish = setTimeout(() => { pendingPublish = undefined; publishSafely(mode); }, wait); @@ -635,8 +715,8 @@ export async function runPreparedSubagent( if (pendingPublish) { clearTimeout(pendingPublish); pendingPublish = undefined; - publishSafely(mode); } + if (!closed && onUpdate) publishSafely(mode); closeEmitter(); if (publishError !== undefined) { const error = publishError; @@ -782,6 +862,8 @@ export async function runPreparedSubagent( // list stays invisible for the tens of seconds a caller most wants it. The // records are already seeded by makeEmptyResult, so this renders every lane // at 0s, including ones still queued behind maxConcurrency. + let dispatchError: unknown; + let flushError: unknown; emit(mode); try { if (parallel) { @@ -815,11 +897,20 @@ export async function runPreparedSubagent( } } } else await runOne(tasks[0], 0); - } finally { - // A trailing coalesced update must not outlive the call or be lost. + } catch (error) { + dispatchError = error; + } + // A trailing coalesced update must not outlive the call or be lost. Flushing + // outside `finally` keeps the original failure: a consumer failure reported + // here must not replace the error that stopped the dispatch. + try { flushEmit(mode); + } catch (error) { + flushError = error; } - const finalDetails = buildDetails(mode, discovery, scope, records.map(finalRecord)); + if (dispatchError !== undefined) throw dispatchError; + if (flushError !== undefined) throw flushError; + const finalDetails = buildDetails(mode, discovery, scope, finalRecords(records)); if (mode === "parallel") { const success = records.filter((record) => record.status === "completed").length; const summaries = records.map( diff --git a/packages/coding-agent/src/features/subagent/lane-lifecycle.ts b/packages/coding-agent/src/features/subagent/lane-lifecycle.ts index c813635ce..7df9e8f9f 100644 --- a/packages/coding-agent/src/features/subagent/lane-lifecycle.ts +++ b/packages/coding-agent/src/features/subagent/lane-lifecycle.ts @@ -9,7 +9,12 @@ import { randomBytes, randomUUID } from "node:crypto"; import type { AgentToolResult, AgentToolUpdateCallback } from "@step-harness/agent-core"; import type { ExtensionAPI, ExtensionContext } from "../../core/extensions/types.ts"; -import type { StepSubagentDetails, StepSubagentRpcSession, SubagentParams } from "../step-subagent.ts"; +import type { + StepSubagentDetails, + StepSubagentResultRecord, + StepSubagentRpcSession, + SubagentParams, +} from "../step-subagent.ts"; import type { PreparedSubagentRun, SubagentPreflight } from "./execute.ts"; import { SUBAGENT_SESSION_ID_PREFIX } from "./helpers.ts"; import { @@ -88,6 +93,17 @@ function getLaneSessions(sessionId: string, liveOnly = true): StepSubagentRpcSes return sessions; } +/** Overlay a bounded live roster onto the roster the lane already knows. */ +function mergeResults( + previous: readonly StepSubagentResultRecord[], + next: readonly StepSubagentResultRecord[], +): StepSubagentResultRecord[] { + return Array.from( + { length: Math.max(previous.length, next.length) }, + (_, index) => next[index] ?? previous[index], + ).filter((record): record is StepSubagentResultRecord => record !== undefined); +} + function laneStatusFromDetails(details: StepSubagentDetails): BackgroundAgentLane["status"] { if (details.results.some((record) => record.status === "running" || record.status === "queued")) { return "running"; @@ -250,6 +266,13 @@ export function createLaneLifecycle(host: LaneLifecycleHost): LaneLifecycle { if (partial.details) { lane.details = { ...partial.details, + // A live roster is byte-bounded, so a large batch may omit its tail. + // Keep the lanes we already know instead of forgetting them; the + // final result replaces this with every task. + results: + partial.details.omittedResults === undefined + ? partial.details.results + : mergeResults(lane.details.results, partial.details.results), agentId: lane.id, status: "running", startedAt: lane.startedAt, diff --git a/packages/coding-agent/src/modes/json-event.ts b/packages/coding-agent/src/modes/json-event.ts index baa53f99e..b2933b42a 100644 --- a/packages/coding-agent/src/modes/json-event.ts +++ b/packages/coding-agent/src/modes/json-event.ts @@ -79,6 +79,9 @@ export function toJsonEvent(event: AgentSessionEvent): JsonAgentSessionEvent { */ export const MAX_LIVE_UPDATE_BYTES = 256 * 1024; +/** Ceiling for a single identifier inside a bounded live update. */ +const MAX_LIVE_IDENTIFIER_CHARS = 512; + const TRUNCATED_MARKER = "[live output truncated]"; type ToolExecutionUpdateEvent = Extract; @@ -102,6 +105,10 @@ function serializedBytes(value: unknown): number { * 64 KiB string can serialize to 384 KiB. The tail is retained because that is * what a live view renders; `details` and `args` are dropped because they are * already on the matching `tool_execution_start`/`tool_execution_end` events. + * + * A pathological `toolCallId`/`toolName` is clipped too: without that, the + * envelope alone could exceed the budget and the function would have no valid + * output to return. */ function boundLiveUpdate(event: ToolExecutionUpdateEvent): JsonAgentSessionEvent { if (serializedBytes(event) <= MAX_LIVE_UPDATE_BYTES) return event; @@ -113,8 +120,10 @@ function boundLiveUpdate(event: ToolExecutionUpdateEvent): JsonAgentSessionEvent const candidate = (tail: string): JsonAgentSessionEvent => ({ type: "tool_execution_update", - toolCallId: event.toolCallId, - toolName: event.toolName, + // Ids come from the model or an extension. A 300 KB one is malformed, and + // clipping it beats writing an unbounded line; correlation already failed. + toolCallId: clip(event.toolCallId, MAX_LIVE_IDENTIFIER_CHARS), + toolName: clip(event.toolName, MAX_LIVE_IDENTIFIER_CHARS), args: undefined, partialResult: { content: [ @@ -127,15 +136,20 @@ function boundLiveUpdate(event: ToolExecutionUpdateEvent): JsonAgentSessionEvent }, }); - // Halve the retained tail until the whole serialized event fits. Starts at - // the full text so a moderately oversized update keeps as much as it can. + // Halve the retained tail until the whole serialized event fits. Each round + // strictly shrinks the string, so the loop terminates; `candidate("")` is the + // floor and always fits once the envelope is clipped. let kept = text; let bounded = candidate(kept); while (kept.length > 0 && serializedBytes(bounded) > MAX_LIVE_UPDATE_BYTES) { - kept = kept.slice(-Math.floor(kept.length / 2)); + kept = kept.length <= 1 ? "" : kept.slice(-Math.floor(kept.length / 2)); bounded = candidate(kept); } - // The envelope alone can still exceed the budget for a pathological id or - // name; the marker-only form is the smallest this function can produce. - return serializedBytes(bounded) <= MAX_LIVE_UPDATE_BYTES ? bounded : candidate(""); + return bounded; +} + +function clip(value: string, max: number): string { + if (value.length <= max) return value; + const half = Math.max(1, Math.floor((max - 1) / 2)); + return `${value.slice(0, half)}\u2026${value.slice(-half)}`; } diff --git a/packages/coding-agent/test/json-event-live-update-budget.test.ts b/packages/coding-agent/test/json-event-live-update-budget.test.ts index 00969988c..08664cfb5 100644 --- a/packages/coding-agent/test/json-event-live-update-budget.test.ts +++ b/packages/coding-agent/test/json-event-live-update-budget.test.ts @@ -68,18 +68,38 @@ test.each([ expect(textOf(bounded)).toContain("[live output truncated]"); }); -test("an update just above the budget keeps as much of the tail as fits", () => { - const text = "z".repeat(Math.floor(MAX_LIVE_UPDATE_BYTES * 0.9)); +test("an oversized update keeps as much of the tail as fits", () => { + const text = "z".repeat(MAX_LIVE_UPDATE_BYTES); + const input = update({ content: [{ type: "text", text }] }); + expect(bytesOf(input)).toBeGreaterThan(MAX_LIVE_UPDATE_BYTES); const bounded = boundedEvent({ content: [{ type: "text", text }] }); expect(bytesOf(bounded)).toBeLessThanOrEqual(MAX_LIVE_UPDATE_BYTES); - // Far more than the minimum: the halving loop stops at the first fit. - expect(textOf(bounded).length).toBeGreaterThan(text.length / 2); + // The budget is more than a rounding error: the halving loop stops at the + // first fit, so most of the available room is used. + expect(textOf(bounded).length).toBeGreaterThan(MAX_LIVE_UPDATE_BYTES / 4); }); -test("the envelope alone over budget still produces a minimal valid event", () => { - const bounded = boundedEvent({ content: [{ type: "text", text: "x" }] }); +test("a pathological toolCallId cannot make the event itself exceed the budget", () => { + // Before the id was clipped, the halving loop could not shrink the envelope: + // `slice(-0)` returns the whole string, so it spun forever. + const event: AgentSessionEvent = { + type: "tool_execution_update", + toolCallId: "i".repeat(300_000), + toolName: "n".repeat(300_000), + args: { agent: "general" }, + partialResult: { content: [{ type: "text", text: "x" }] }, + }; + const bounded = toJsonEvent(event) as Extract; + expect(bytesOf(bounded)).toBeLessThanOrEqual(MAX_LIVE_UPDATE_BYTES); expect(bounded.type).toBe("tool_execution_update"); - expect(bounded.toolCallId).toBe("call_1"); + expect(bounded.toolCallId.length).toBeLessThan(1_000); +}); + +test("a one-character text with huge details still terminates and fits", () => { + // The regression this replaces was a synchronous infinite loop, so a return + // at all is the assertion; the byte check then guards the envelope. + const bounded = boundedEvent({ content: [{ type: "text", text: "y" }], details: { a: "z".repeat(400_000) } }); + expect(bytesOf(bounded)).toBeLessThanOrEqual(MAX_LIVE_UPDATE_BYTES); }); test("the terminal tool_execution_end event is never bounded", () => { diff --git a/packages/coding-agent/test/step-subagent-events.test.ts b/packages/coding-agent/test/step-subagent-events.test.ts index eadf36904..b9dcc6fd6 100644 --- a/packages/coding-agent/test/step-subagent-events.test.ts +++ b/packages/coding-agent/test/step-subagent-events.test.ts @@ -285,6 +285,9 @@ test("a ten-task batch starts eight and queues two on a ten-core host", async () createContext("/workspace"), ); await waitFor(() => calls === 8); + // Live updates coalesce on a 100ms tick (see execute.ts), so the roster + // that reflects the dispatched batch arrives on the next publish. + await waitFor(() => counts.some((count) => count.running === 8 && count.queued === 2), 2_000); expect(counts).toContainEqual({ running: 8, queued: 2 }); release(); await result; diff --git a/packages/coding-agent/test/subagent-background-tui.test.ts b/packages/coding-agent/test/subagent-background-tui.test.ts index 560975793..921fa9cd3 100644 --- a/packages/coding-agent/test/subagent-background-tui.test.ts +++ b/packages/coding-agent/test/subagent-background-tui.test.ts @@ -140,6 +140,9 @@ test("background lanes share one stable list widget that clears when the batch s expect(calls.length).toBe(before); expect(new Set(calls.map((call) => call.key))).toEqual(new Set(["step-agent-lanes"])); + // Runs coalesce on a 100ms tick, so the roster that shows both lanes running + // arrives on the next publish rather than synchronously with dispatch. + await waitFor(() => (calls.at(-1)?.component?.render(100)[0] ?? "").includes("2 running")); const widget = calls.at(-1)!.component!; const rows = widget.render(100); expect(rows[0]).toContain("background agents"); diff --git a/packages/coding-agent/test/subagent-chain-result.test.ts b/packages/coding-agent/test/subagent-chain-result.test.ts index 8e9a2a4fe..bf3b7a77a 100644 --- a/packages/coding-agent/test/subagent-chain-result.test.ts +++ b/packages/coding-agent/test/subagent-chain-result.test.ts @@ -215,7 +215,11 @@ test("parallel mode still aggregates every task", async () => { }); test("chain steps wait as queued, not running, until dispatched", async () => { - const { partialStatuses } = await run(threeSteps, (_input, index) => ({ text: `OUT_${index}` })); + // Live updates coalesce on a 100ms tick, so each step has to outlive one tick + // for its running state to be published. Real steps take seconds. + const { partialStatuses } = await run(threeSteps, (_input, index) => ({ text: `OUT_${index}` }), { + runnerDelayMs: 150, + }); expect(partialStatuses[0]).toEqual(["queued", "queued", "queued"]); expect(partialStatuses).toContainEqual(["running", "queued", "queued"]); @@ -236,7 +240,8 @@ test("parallel tasks beyond maxConcurrency wait as queued", async () => { ], } as SubagentParams, (input) => ({ text: `OUT_${input.task}` }), - { maxConcurrency: 1 }, + // Same reason as above: the queued lane must survive one publish tick. + { maxConcurrency: 1, runnerDelayMs: 150 }, ); expect(partialStatuses).toContainEqual(["running", "queued"]); diff --git a/packages/coding-agent/test/subagent-live-update-budget.test.ts b/packages/coding-agent/test/subagent-live-update-budget.test.ts index 5fee202c1..33189eaae 100644 --- a/packages/coding-agent/test/subagent-live-update-budget.test.ts +++ b/packages/coding-agent/test/subagent-live-update-budget.test.ts @@ -206,6 +206,40 @@ test("streamed deltas coalesce to one publish per interval, but status changes d expect(updates.at(-1)?.details?.results[0]?.status).toBe("completed"); }); +test("a large parallel batch stays bounded per publish and in total", async () => { + const tasks = 200; + const released: Array<() => void> = []; + const seen: Captured[] = []; + const pending = run( + { + tasks: Array.from({ length: tasks }, (_, index) => ({ agent: "general", task: `task ${index}` })), + }, + async (input) => { + input.onUpdate?.({ ...idle, activeText: "working" }); + // Keep every lane running across several ticks so the roster is + // republished, which is what used to make this quadratic. + await new Promise((resolve) => { + released.push(resolve); + setTimeout(resolve, 120); + }); + return { ...idle, exitCode: 0, stopReason: "stop" }; + }, + { sink: seen }, + ); + const { updates } = await pending; + void released; + + // Publishing each of 2 x 200 status transitions immediately produced ~400 + // publishes of the whole roster. Coalescing keeps it to a handful. + expect(updates.length).toBeLessThan(60); + const largest = Math.max(...updates.map((update) => update.bytes)); + expect(largest).toBeLessThan(128 * 1024); + const total = updates.reduce((sum, update) => sum + update.bytes, 0); + expect(total).toBeLessThan(2 * 1024 * 1024); + // A bounded roster says what it left out instead of dropping it silently. + expect(updates.some((update) => (update.details?.omittedResults ?? 0) > 0)).toBe(true); +}); + test("the final result keeps the newest transcript messages and says it truncated", async () => { const messages: StepSubagentRunResult["messages"] = []; for (let index = 0; index < 20; index += 1) messages.push(message(index, 40_000)); @@ -248,7 +282,8 @@ test("a huge final answer is bounded in the display projection", async () => { stopReason: "stop", })); const record = result.details?.results[0]; - expect((record?.activeText ?? "").length).toBeLessThanOrEqual(8_000); + // Matches the renderer's own truncation, so an expanded view is not reduced. + expect((record?.activeText ?? "").length).toBeLessThanOrEqual(50_000); // The model-facing text is not the details field. expect(result.content[0]).toMatchObject({ type: "text" }); }); diff --git a/packages/coding-agent/test/subagent-live-update-rpc.test.ts b/packages/coding-agent/test/subagent-live-update-rpc.test.ts index a753b0161..53f1c5f03 100644 --- a/packages/coding-agent/test/subagent-live-update-rpc.test.ts +++ b/packages/coding-agent/test/subagent-live-update-rpc.test.ts @@ -24,8 +24,10 @@ import { createHarness, type Harness } from "./suite/harness.ts"; const childPath = fileURLToPath(new URL("./fixtures/subagent-stream-child.mjs", import.meta.url)); const harnesses: Harness[] = []; -const originalArgv = process.argv; -const originalExecArgv = process.execArgv; +// Copy the array: writing `process.argv[1]` mutates it in place, so storing the +// reference would make the restore a no-op. +const originalArgv = [...process.argv]; +const originalExecArgv = [...process.execArgv]; const envBackup = { ...process.env }; // Keep the shared tool-output retention inside the test's own temp root instead // of a developer's real agent directory. @@ -172,7 +174,7 @@ test("a huge final answer from a real child cannot escape the display budget", a expect(stats.finalText.length).toBeLessThan(100_000); expect(stats.finalText).toContain("Full output:"); // The display copy in `details` is bounded by the orchestrator itself. - expect(stats.finalActiveTextLength).toBeLessThanOrEqual(8_000); + expect(stats.finalActiveTextLength).toBeLessThanOrEqual(50_000); expect(stats.logBytes).toBeLessThan(1024 * 1024); expect(stats.largestUpdate).toBeLessThan(64 * 1024); }); From adcd53284e6dd27a9c77e2ffe3a3a50dcf3e21d6 Mon Sep 17 00:00:00 2001 From: liuedcson <332840681+liuedcson@users.noreply.github.com> Date: Tue, 27 Oct 2026 22:20:55 +0800 Subject: [PATCH 4/8] fix(coding-agent): stop an exhausted budget from restoring full values Third review round. Two regressions came from the previous commit: - `tailChars(value, max)` returned the whole value when `max <= 1` (`slice(-(max - 1))` is `slice(-0)` is the whole string). The final details share one per-call budget, so after the first records consume it the allowance drops to zero and every later record kept its full text: 200 tasks with 300 KB answers produced 48.94 MiB of details, and 1000 tasks extrapolate to ~1 GiB. A zero allowance now yields an empty value, and a field the budget rejects is dropped rather than kept anyway. - The final record was still a spread, so unbounded identity/path fields reached the details. It is now the same explicit allowlist as the live projection. `omittedResults` was written but never read: a 600-task batch displayed "174/174 complete" because renderers counted the truncated roster. The widget header, the "more" footer and `subagentListSignature` now count the real total, and the background lane drops the flag after index-merging (its roster is complete again, so keeping it would double-count). Also corrected the docs that still described the previous behaviour: status transitions are coalesced (a sub-100ms transition may not reach the wire), the final text cap is 50k, flush happens outside `finally`, and the final bound is 256 KiB of heavy fields plus O(tasks) metadata. New regressions: 60 tasks x 300 KB answers stay inside the per-call budget (the exhausted-allowance path), and a byte-bounded roster reports the real task count and republishes when the count changes. --- .../README.md | 21 ++-- packages/coding-agent/docs/rpc.md | 2 +- .../docs/tool-output-retention.md | 18 ++-- .../src/features/subagent/execute.ts | 101 +++++++++++++----- .../src/features/subagent/lane-lifecycle.ts | 3 + .../src/features/subagent/rendering.ts | 24 ++++- .../test/subagent-list-widget.test.ts | 25 ++++- .../test/subagent-live-update-budget.test.ts | 27 ++++- 8 files changed, 168 insertions(+), 53 deletions(-) diff --git a/docs/research/2026-10-27-subagent-live-update-amplification/README.md b/docs/research/2026-10-27-subagent-live-update-amplification/README.md index 2a68396e3..30ab24e7f 100644 --- a/docs/research/2026-10-27-subagent-live-update-amplification/README.md +++ b/docs/research/2026-10-27-subagent-live-update-amplification/README.md @@ -145,7 +145,7 @@ function liveRecord(record) { **③ 终态投影**:终态 details 同样是展示投影,不是原始数据的拷贝。 - `messages` 只保留最新的、序列化后总量 ≤ 64 KiB 的消息(大小为选值,不与仓库既有的 50 KiB 文本上限混同);被裁剪时置 `messagesTruncated: true`。 -- 全部 record 共享一个 **256 KiB / 次调用**的预算,按记录顺序消费;`activeText` 单条 ≤ 50,000 字符(与渲染端一致,不缩小 Ctrl+O 展开视图)、`task` ≤ 2,000 字符、`stderr` / `errorMessage` ≤ 2,000 字符、`cancelledPrompts` ≤ 20 条 × 200 字符。 +- 全部 record 共享一个 **256 KiB / 次调用**的重字段预算(文本 + transcript),按记录顺序消费;放不下的字段直接省略而不是原样保留。小型元数据(agent/status/usage/id)按记录单独有界,总量是 `256 KiB + O(tasks)`,与子会话输出长度无关。`activeText` 单条 ≤ 50,000 字符(与渲染端一致,不缩小 Ctrl+O 展开视图)、`task` ≤ 2,000 字符、`stderr` / `errorMessage` ≤ 2,000 字符、`cancelledPrompts` ≤ 20 条 × 200 字符。 - `activeText` 缺失时由**完整 transcript** 的最终 assistant 文本回填,因此「单条消息超出预算导致 messages 为空」不会让结果渲染成 `(no output)`。 - 模型可见的 `content` 不受这些限制,仍走既有的 50 KiB / 2,000 行 tool-output retention;完整 transcript 留在子会话(`sessionId` / `sessionFile`)。 @@ -188,7 +188,8 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, ### 4.2 行为兼容性 - **不改变** `subagent` 工具对模型可见的 `content` 文本(由未裁剪的内部 records 生成)。 -- **不改变** 状态机的对外语义:所有状态跃迁仍然逐次可见。 +- 状态机的**终态**语义不变:每个任务最终都会到达 completed/failed/aborted,并在调用返回前刷出。 +- **变化**:短于 100 ms 的状态跃迁(典型如瞬时完成的测试替身)可能不出现在 wire 上。真实子代理是秒级,不受影响;这是消除 parallel 下 O(N²) 的必要代价。 - 直播期间的 `activeText` 从最多 50k 字符变为 2k 尾部,工具入参/输出也从完整值变为尾部:这是**刻意的可见降级**(progress 是可合并快照,不是完整事件历史)。 - 可观测契约变化:`StepSubagentDetails.results[].messages` 从「全量」变为「终态限量」并新增可选 `messagesTruncated`;直播字段变为有界尾部。消费方(TUI 展开、历史渲染、web 子代理卡片)只用最后一个 assistant 文本或状态字段,已逐一核对。 - 定时器在返回前关闭(`closeEmitter`),调用返回后的迟到回调不再发布;`onUpdate` 抛错不再从定时器逃逸成未捕获异常,而是按「dispatch 错误优先」的顺序在调用路径上抛出。 @@ -206,7 +207,8 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, - 200 个并行任务的批量调用:发布 < 60 次、单条 < 128 KiB、总量 < 2 MiB、出现 `omittedResults`; - 终态预算:保留最新消息、序列化数组 ≤ 64 KiB、`messagesTruncated: true`; - 单条消息超预算且无 `activeText` 时,仍从完整 transcript 回填可渲染文本; - - 400 KB 最终答复在展示投影里被压到 ≤ 8,000 字符; + - 400 KB 最终答复在展示投影里被压到 ≤ 50,000 字符; + - 60 个任务各带 300 KB 答复:终态 details ≤ 256 KiB + O(tasks)(覆盖「预算耗尽后 allowance 为 0」这条路径); - 调用返回后的迟到回调不再发布; - `onUpdate` 抛错以调用失败的形式浮出,而不是从定时器逃逸。 - `test/json-event-live-update-budget.test.ts` @@ -216,7 +218,7 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, 回归: -- `packages/coding-agent` 全量:`4984 passed, 58 skipped`。唯一失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关)。 +- `packages/coding-agent` 全量:约 5000 passed / 58 skipped。唯一稳定失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关);`subagent-invocation` 的 CLI 启动用例偶发超时,单跑必过(该文件注释已记录此既有偶发)。 - `pnpm run check` 全绿(biome / 边界检查 / `tsgo --noEmit` / browser smoke)。 - `git diff --check` 干净。 @@ -224,20 +226,21 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, | 风险 | 控件 | | --- | --- | -| 直播更新过少导致 UI 卡顿感 | 状态跃迁即时发布;100 ms 与 bash 既有节流一致,token 计数 10 Hz 足够 | +| 直播更新过少导致 UI 卡顿感 | 100 ms 与 bash 既有节流一致,token 计数 10 Hz 足够;终态由返回前的 flush 保证 | | 终态 `messages` 裁剪影响历史渲染 | 渲染优先 `activeText`;`sessionId`/`sessionFile` 指向子进程完整 transcript | | 兜底误伤正常流式工具 | 阈值 256 KiB,远高于 bash 的 50 KiB;新增测试锁定「未超限原样透传」 | -| 合流定时器泄漏/迟到投递 | `finally` 中 `flushEmit`;`unref()` | +| 合流定时器泄漏/迟到投递 | 返回前 `closeEmitter` + `flushEmit`(在 dispatch 之外,dispatch 错误优先);`unref()` | | 后续 web 分支合并冲突 | 改动集中在 `emit` 与 dispatch 外层(`try/finally`);web 分支改的是 `runOne` 内部与 `sessionId` 传递,冲突面小 | -回滚:分支上两个 commit(初版 + 评审修正),`git revert` 两个即恢复原行为,无数据迁移、无配置项。 +回滚:分支上三个 commit(初版 + 两轮评审修正),逐个 `git revert` 即恢复原行为,无数据迁移、无配置项。 ### 4.5 后续(未纳入本 PR) 1. **终态回显放大**:一次调用的终态 details 会被约 5 类事件各带一份(≈5 × 100 KiB)。要压缩需要改消息级事件形状,与本次「最小爆炸半径」目标冲突,建议单独立项。 2. **内存队列仍无界**:`agent-loop` 的 update promise 数组与 `output-guard` 的 stdout promise 串都没有上限。本 PR 只降低了增长速度,慢读者场景需要单独做背压或队列上限。 -2. **web SSE 兜底**:web 分支的 SSE 直接转发 session event,未经过 `toJsonEvent`。当前源头已收敛,但建议在该分支 rebase 后补一条同等的回归测试。 -3. **类型级约束**:真正对齐 opencode 的做法是给会话事件加 `durable`/`ephemeral` 分类,让「增量不可落盘」成为编译期约束,而不是靠 review 和上限兜底。这是架构级改动,值得单独立项。 +3. **wire 兜底丢弃非文本 content**:超限的 update 只保留 text part,图片预览会丢;终态不受影响。第三方工具若在小体积 update 里带图需要另行处理。 +4. **web SSE 兜底**:web 分支的 SSE 直接转发 session event,未经过 `toJsonEvent`。当前源头已收敛,但建议在该分支 rebase 后补一条同等的回归测试。 +5. **类型级约束**:成熟实现的做法是给会话事件加 `durable`/`ephemeral` 分类,让「增量不可落盘」成为编译期约束,而不是靠 review 和上限兜底。这是架构级改动,值得单独立项。 --- diff --git a/packages/coding-agent/docs/rpc.md b/packages/coding-agent/docs/rpc.md index 0ca664c0f..0250cb953 100644 --- a/packages/coding-agent/docs/rpc.md +++ b/packages/coding-agent/docs/rpc.md @@ -1052,7 +1052,7 @@ When complete: } ``` -Use `toolCallId` to correlate events. The `partialResult` in `tool_execution_update` contains the accumulated output so far (not just the delta), allowing clients to simply replace their display on each update. +Use `toolCallId` to correlate events. The `partialResult` in `tool_execution_update` normally contains the accumulated output so far (not just the delta), allowing clients to simply replace their display on each update — except when the update is oversized, where only the tail is kept (next paragraph). One update is capped at 256 KiB of serialized bytes. An oversized update keeps only the tail of its text, adds a `[live output truncated]` marker, and omits diff --git a/packages/coding-agent/docs/tool-output-retention.md b/packages/coding-agent/docs/tool-output-retention.md index 0b0a8584f..3972e2006 100644 --- a/packages/coding-agent/docs/tool-output-retention.md +++ b/packages/coding-agent/docs/tool-output-retention.md @@ -54,13 +54,17 @@ bounded: ends, and stops adding records once the roster reaches 48 KiB — reporting the rest as `omittedResults`. A chain splices the previous step's whole answer into the next step's task, so a spread would repeat it on every tick. -- The final records are also a display projection sharing one 256 KiB budget: - the newest messages that fit (64 KiB per record), an `activeText` capped at - 50,000 characters (the renderer's own truncation point), and every other - rendered field bounded. `messagesTruncated` says when a transcript tail was - cut, and the full transcript stays in the child session (`sessionId` / - `sessionFile`). The model-facing `content` is unaffected and still passes - through this document's 50 KiB retention. +- The final records are also an explicit projection sharing one 256 KiB budget + for heavy fields: the newest messages that fit (64 KiB per record), an + `activeText` capped at 50,000 characters (the renderer's own truncation + point), and a bounded `task`/`stderr`/`errorMessage`. A field that does not + fit is omitted, never kept at full size. Small per-record metadata (agent, + status, usage, ids) is bounded separately, so the total is + `256 KiB + O(tasks)` and never grows with the child's output. + `messagesTruncated` says when a transcript tail was cut, and the full + transcript stays in the child session (`sessionId` / `sessionFile`). The + model-facing `content` is unaffected and still passes through this document's + 50 KiB retention. `toJsonEvent` additionally bounds a single `tool_execution_update` at 256 KiB of *serialized* bytes. That backstop exists for third-party tools that re-send diff --git a/packages/coding-agent/src/features/subagent/execute.ts b/packages/coding-agent/src/features/subagent/execute.ts index 79b0ff7bb..7d85aae14 100644 --- a/packages/coding-agent/src/features/subagent/execute.ts +++ b/packages/coding-agent/src/features/subagent/execute.ts @@ -103,6 +103,9 @@ const FINAL_DETAILS_BYTES = 256 * 1024; /** Per-record cap inside the shared final budget; matches the renderer's own truncation. */ const FINAL_TEXT_CHARS = 50_000; const FINAL_TASK_CHARS = 2_000; +const FINAL_STDERR_CHARS = 2_000; +const FINAL_ERROR_CHARS = 2_000; +const FINAL_IDENTIFIER_CHARS = 200; export interface StepSubagentTaskInput { agent: string; @@ -208,15 +211,25 @@ function buildDetails( }; } -/** Keep the tail of a streamed field within `max` characters, marker included. */ +/** + * Keep the tail of a streamed field within `max` characters, marker included. + * + * `max <= 0` must yield nothing, not "everything": a share of an exhausted + * budget can be zero, and a negative-length slice would return the full value. + */ function tailChars(value: string | undefined, max: number): string | undefined { - if (value === undefined || value.length <= max) return value; + if (value === undefined) return undefined; + if (max <= 0) return ""; + if (value.length <= max) return value; + if (max === 1) return "\u2026"; return `\u2026${value.slice(-(max - 1))}`; } /** Keep both ends of a prompt: the opening instruction and the inserted context. */ function clipMiddle(value: string, max: number): string { + if (max <= 0) return ""; if (value.length <= max) return value; + if (max === 1) return "\u2026"; const half = Math.max(1, Math.floor((max - 1) / 2)); return `${value.slice(0, half)}\u2026${value.slice(-half)}`; } @@ -293,6 +306,7 @@ interface Budget { } function take(budget: Budget, value: unknown): boolean { + if (value === undefined) return true; const size = serializedBytes(value) + 1; if (size > budget.remaining) return false; budget.remaining -= size; @@ -317,9 +331,10 @@ function liveDetails( const results: StepSubagentResultRecord[] = []; for (const record of records) { const projected = liveRecord(record); - // Always include the first record: a roster that reports only a count is - // less useful than one slightly over budget. + // The first record is always emitted even if it alone exceeds the budget; + // `liveRecord` bounds every field, so it cannot exceed it by much. if (results.length > 0 && !take(budget, projected)) break; + if (results.length === 0) take(budget, projected); results.push(projected); } const details: StepSubagentDetails = { mode, agentScope: scope, ...discoveryFields(discovery), results }; @@ -359,44 +374,78 @@ function boundedMessages( /** * Final record projection. * - * The transcript is bounded, and so is every other field a consumer renders: a - * runner that reports a multi-hundred-KB final answer must not put it in the - * details, which several terminal events then echo. `activeText` is filled from - * the transcript when a runner did not set it, so trimming `messages` can never - * turn a completed record into "(no output)". + * Like the live projection this is an explicit allowlist: a runner's unknown + * fields must not reach the details, which several terminal events then echo. + * Heavy fields share one per-call budget; a field that does not fit is omitted + * rather than kept anyway. `activeText` falls back to the full transcript when a + * runner did not set it, so trimming `messages` can never turn a completed + * record into "(no output)". */ function finalRecords(records: readonly StepSubagentResultRecord[]): StepSubagentResultRecord[] { const budget: Budget = { remaining: FINAL_DETAILS_BYTES }; return records.map((record) => { - // Fall back to the full transcript, not the bounded copy: one message larger - // than the per-record allowance leaves `messages` empty, and the result must - // still render. const fallbackText = finalOutput(record.messages); const text = record.activeText || fallbackText; + // Six-byte JSON escapes are the worst case per character, so a quarter of + // the remaining bytes as characters is already conservative once the + // serialized check below has the final say. const textAllowance = Math.min(FINAL_TEXT_CHARS, Math.max(0, Math.floor(budget.remaining / 4))); - const activeText = tailChars(text, textAllowance); - if (activeText !== undefined) take(budget, activeText); + let activeText = tailChars(text, textAllowance); + if (!take(budget, activeText)) activeText = undefined; const messageAllowance = Math.min(FINAL_MESSAGES_BYTES, Math.max(0, budget.remaining)); const bounded = boundedMessages(record.messages, messageAllowance); - take(budget, bounded.messages); + const messages = take(budget, bounded.messages) ? bounded.messages : []; const task = clipMiddle(record.task, FINAL_TASK_CHARS); take(budget, task); + const stderr = tailChars(record.stderr, FINAL_STDERR_CHARS) ?? ""; + take(budget, stderr); + // A field the budget rejects is dropped, not silently kept at full size. + const candidateError = tailChars(record.errorMessage, FINAL_ERROR_CHARS); + const errorMessage = take(budget, candidateError) ? candidateError : undefined; + const prompts = boundedPrompts(record.cancelledPrompts); + const cancelledPrompts = take(budget, prompts.cancelledPrompts) ? prompts.cancelledPrompts : undefined; + return { - ...record, + agent: clipMiddle(record.agent, FINAL_IDENTIFIER_CHARS), + agentSource: record.agentSource, task, - messages: bounded.messages, - activeText, - activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS), - activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS), - stderr: tailChars(record.stderr, LIVE_STDERR_CHARS) ?? "", - ...(record.errorMessage === undefined - ? {} - : { errorMessage: tailChars(record.errorMessage, LIVE_ERROR_CHARS) }), - ...boundedPrompts(record.cancelledPrompts), - ...(bounded.truncated ? { messagesTruncated: true } : {}), + status: record.status, + exitCode: record.exitCode, + messages, + stderr, usage: cloneUsage(record.usage), + ...(record.model === undefined ? {} : { model: clipMiddle(record.model, FINAL_IDENTIFIER_CHARS) }), + ...(record.stopReason === undefined + ? {} + : { stopReason: clipMiddle(record.stopReason, FINAL_IDENTIFIER_CHARS) }), + ...(errorMessage === undefined || errorMessage === "" ? {} : { errorMessage }), + ...(activeText === undefined ? {} : { activeText }), + ...(record.activeTool === undefined + ? {} + : { activeTool: clipMiddle(record.activeTool, FINAL_IDENTIFIER_CHARS) }), + ...(record.activeToolArgs === undefined + ? {} + : { activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS) }), + ...(record.activeToolOutput === undefined + ? {} + : { activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS) }), + ...(record.lastEvent === undefined ? {} : { lastEvent: clipMiddle(record.lastEvent, FINAL_IDENTIFIER_CHARS) }), + ...(record.startedAt === undefined ? {} : { startedAt: record.startedAt }), + ...(record.updatedAt === undefined ? {} : { updatedAt: record.updatedAt }), + ...(record.step === undefined ? {} : { step: record.step }), + ...(record.worktreePath === undefined + ? {} + : { worktreePath: clipMiddle(record.worktreePath, LIVE_PATH_CHARS) }), + ...(record.worktreeBranch === undefined + ? {} + : { worktreeBranch: clipMiddle(record.worktreeBranch, FINAL_IDENTIFIER_CHARS) }), + ...(record.sessionId === undefined ? {} : { sessionId: clipMiddle(record.sessionId, FINAL_IDENTIFIER_CHARS) }), + ...(record.sessionFile === undefined ? {} : { sessionFile: clipMiddle(record.sessionFile, LIVE_PATH_CHARS) }), + ...(record.pendingReply === undefined ? {} : { pendingReply: record.pendingReply }), + ...(cancelledPrompts === undefined ? {} : { cancelledPrompts }), + ...(bounded.truncated || messages.length < record.messages.length ? { messagesTruncated: true } : {}), }; }); } diff --git a/packages/coding-agent/src/features/subagent/lane-lifecycle.ts b/packages/coding-agent/src/features/subagent/lane-lifecycle.ts index 7df9e8f9f..cda37cc39 100644 --- a/packages/coding-agent/src/features/subagent/lane-lifecycle.ts +++ b/packages/coding-agent/src/features/subagent/lane-lifecycle.ts @@ -273,6 +273,9 @@ export function createLaneLifecycle(host: LaneLifecycleHost): LaneLifecycle { partial.details.omittedResults === undefined ? partial.details.results : mergeResults(lane.details.results, partial.details.results), + // After merging, the roster is complete: keeping the count would + // make renderers report more tasks than exist. + ...(partial.details.omittedResults === undefined ? {} : { omittedResults: undefined }), agentId: lane.id, status: "running", startedAt: lane.startedAt, diff --git a/packages/coding-agent/src/features/subagent/rendering.ts b/packages/coding-agent/src/features/subagent/rendering.ts index 7a0f85dde..d000dd826 100644 --- a/packages/coding-agent/src/features/subagent/rendering.ts +++ b/packages/coding-agent/src/features/subagent/rendering.ts @@ -181,7 +181,18 @@ export function subagentListSignature(details: StepSubagentDetails): string { const rows = details.results .slice(0, WIDGET_MAX_ROWS) .map((record) => [record.status, record.agent, record.task, record.usage.output].join("\u0000")); - return [details.results.length, ...rows].join("\u0001"); + return [totalResults(details), ...rows].join("\u0001"); +} + +/** + * Tasks in the call, including any a bounded live roster left out. + * + * A live update carries at most `LIVE_DETAILS_BYTES` of records and reports the + * rest as `omittedResults`; counting `results.length` alone would tell a 600-task + * batch that it has 174 tasks and that all of them are done. + */ +export function totalResults(details: StepSubagentDetails): number { + return details.results.length + (details.omittedResults ?? 0); } /** @@ -218,12 +229,13 @@ export class SubagentListWidget implements Component { const records = this.details.results; if (records.length === 0) return []; const theme = this.theme; + const total = totalResults(this.details); const running = records.filter((record) => record.status === "running").length; const completed = records.filter((record) => record.status === "completed").length; const queued = records.filter((record) => record.status === "queued").length; const skipped = records.filter((record) => record.status === "skipped").length; const failed = records.length - running - completed - queued - skipped; - const summary = [`${completed}/${records.length} complete`]; + const summary = [`${completed}/${total} complete`]; if (running > 0) summary.push(`${running} running`); if (queued > 0) summary.push(`${queued} queued`); if (failed > 0) summary.push(`${failed} failed`); @@ -263,8 +275,8 @@ export class SubagentListWidget implements Component { const row = ` ${statusIcon(record.status, theme)} ${theme.fg("accent", name)} ${theme.fg("toolOutput", title)}${" ".repeat(gap)}${theme.fg("dim", metric.padStart(metricWidth))}`; lines.push(visibleWidth(row) > width ? truncateToWidth(row, width, "\u2026") : row); } - if (records.length > shown.length) { - lines.push(` ${theme.fg("dim", `... ${records.length - shown.length} more`)}`); + if (total > shown.length) { + lines.push(` ${theme.fg("dim", `... ${total - shown.length} more`)}`); } return lines; } @@ -280,12 +292,14 @@ export function renderSubagentResult( const text = result.content.find((block) => block.type === "text"); return new Text(text?.type === "text" ? text.text : "(no output)", 0, 0); } + const total = totalResults(details); const running = details.results.filter((record) => record.status === "running").length; const queued = details.results.filter((record) => record.status === "queued").length; const completed = details.results.filter((record) => record.status === "completed").length; + const omitted = details.omittedResults ? `, ${details.omittedResults} not shown` : ""; const heading = details.mode === "parallel" - ? `${completed}/${details.results.length} complete${running > 0 ? `, ${running} running` : ""}${queued > 0 ? `, ${queued} queued` : ""}` + ? `${completed}/${total} complete${running > 0 ? `, ${running} running` : ""}${queued > 0 ? `, ${queued} queued` : ""}${omitted}` : details.mode === "chain" ? chainHeading(details.results) : (details.results[0]?.status ?? "done"); diff --git a/packages/coding-agent/test/subagent-list-widget.test.ts b/packages/coding-agent/test/subagent-list-widget.test.ts index fe50363c6..63b037647 100644 --- a/packages/coding-agent/test/subagent-list-widget.test.ts +++ b/packages/coding-agent/test/subagent-list-widget.test.ts @@ -7,7 +7,7 @@ import { type StepSubagentResultRecord, type StepSubagentRunResult, } from "../src/features/step-subagent.ts"; -import { SubagentListWidget, subagentListSignature } from "../src/features/subagent/rendering.ts"; +import { SubagentListWidget, subagentListSignature, totalResults } from "../src/features/subagent/rendering.ts"; import type { Theme } from "../src/theme/theme.ts"; // Identity theme: assertions are about layout, not colors. @@ -412,3 +412,26 @@ test("a headless host gets no widget", async () => { ); expect(calls.filter((call) => call.key.startsWith("step-subagent-list:"))).toHaveLength(0); }); + +test("a byte-bounded roster reports the real task count, not the published one", () => { + // A live update carries at most 48 KiB of records and reports the rest as + // `omittedResults`. Counting `results.length` alone would claim a 600-task + // batch has 174 tasks and that all of them are done. + const details: StepSubagentDetails = { + mode: "parallel", + agentScope: "user", + userAgentsDir: "/tmp/agents", + projectAgentsDir: null, + results: [record({ status: "completed" })], + omittedResults: 2, + }; + expect(totalResults(details)).toBe(3); + const widget = new SubagentListWidget(details, plainTheme); + const rows = widget.render(120); + expect(rows[0]).toContain("1/3 complete"); + expect(rows.join("\n")).toContain("... 2 more"); + // The signature must move when the omitted count changes, or the republish + // that carries the new total is skipped. + const before = subagentListSignature({ ...details, omittedResults: 1 }); + expect(subagentListSignature(details)).not.toBe(before); +}); diff --git a/packages/coding-agent/test/subagent-live-update-budget.test.ts b/packages/coding-agent/test/subagent-live-update-budget.test.ts index 33189eaae..4f420954a 100644 --- a/packages/coding-agent/test/subagent-live-update-budget.test.ts +++ b/packages/coding-agent/test/subagent-live-update-budget.test.ts @@ -183,7 +183,7 @@ test("a chain's spliced {previous} prompt stays out of every live update", async expect(updates.some((update) => update.details?.results.length === 2)).toBe(true); }); -test("streamed deltas coalesce to one publish per interval, but status changes do not wait", async () => { +test("streamed deltas and status changes coalesce into one publish per interval", async () => { const seen: Captured[] = []; const { updates } = await run( { agent: "general", task: "inspect" }, @@ -200,9 +200,7 @@ test("streamed deltas coalesce to one publish per interval, but status changes d // couple of interval publishes, then completed. expect(updates.length).toBeLessThanOrEqual(6); expect(updates.length).toBeGreaterThanOrEqual(3); - const running = updates.filter((update) => update.details?.results[0]?.status === "running"); - // `running` is published by the first event, not deferred to the interval. - expect(running.length).toBeGreaterThanOrEqual(1); + // A short-lived status may never reach the wire; the terminal state always does. expect(updates.at(-1)?.details?.results[0]?.status).toBe("completed"); }); @@ -274,6 +272,27 @@ test("a single message larger than the budget still leaves a readable result", a expect(record?.activeText ?? "").toContain("x"); }); +test("many large answers stay inside one per-call details budget", async () => { + // This is the exhaustion path: the first records consume the shared budget, + // so later ones get a tiny allowance. A zero-or-one-character allowance used + // to return the whole value, turning the bound back into "unbounded". + const tasks = 60; + const { result } = await run( + { tasks: Array.from({ length: tasks }, (_, index) => ({ agent: "general", task: `t${index}` })) }, + async () => ({ ...idle, activeText: "q".repeat(300_000), exitCode: 0, stopReason: "stop" }), + ); + const details = result.details; + expect(details?.results).toHaveLength(tasks); + // 256 KiB covers the heavy fields (text + transcript). Small per-record + // metadata (agent, status, usage, ids) is separately bounded per record, so + // the total is O(tasks) with a small constant, never O(output size). + const totalBytes = Buffer.byteLength(JSON.stringify(details), "utf8"); + expect(totalBytes).toBeLessThanOrEqual(256 * 1024 + tasks * 1024); + for (const record of details?.results ?? []) { + expect((record.activeText ?? "").length).toBeLessThanOrEqual(50_000); + } +}); + test("a huge final answer is bounded in the display projection", async () => { const { result } = await run({ agent: "general", task: "inspect" }, async () => ({ ...idle, From aa04aeaf8e6610cc8989329f4e113e5a40a31f68 Mon Sep 17 00:00:00 2001 From: liuedcson <332840681+liuedcson@users.noreply.github.com> Date: Tue, 27 Oct 2026 22:32:05 +0800 Subject: [PATCH 5/8] fix(coding-agent): recompute the lane's omitted count instead of clearing it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A live roster stops at its byte budget, and `mergeResults` can only recover records the lane already saw — never the ones it has not been sent yet. Clearing `omittedResults` after merging therefore froze a 600-task lane at its published prefix: the background header reported "0/202 complete" for 600 tasks, and the shared multi-lane widget under-counted for the same reason. The count is now recomputed as `updateTotal - merged.length`, and the combined lane widget sums it across lanes. A 200-task background lane now reports "/200 complete" in every published header, with the rest shown as "not shown" rather than counted as failures. Also: the live projection had lost `cancelledPrompts` in the allowlist rewrite, `task`/`stderr` now honour the budget's rejection instead of keeping the full value, and the widget's failed count no longer treats an omitted record as one. --- .../README.md | 5 +- .../src/features/step-subagent.ts | 2 + .../src/features/subagent/execute.ts | 10 ++-- .../src/features/subagent/lane-lifecycle.ts | 27 ++++++++--- .../src/features/subagent/rendering.ts | 2 + .../test/subagent-background-tui.test.ts | 47 +++++++++++++++++++ 6 files changed, 80 insertions(+), 13 deletions(-) diff --git a/docs/research/2026-10-27-subagent-live-update-amplification/README.md b/docs/research/2026-10-27-subagent-live-update-amplification/README.md index 30ab24e7f..d7263c44c 100644 --- a/docs/research/2026-10-27-subagent-live-update-amplification/README.md +++ b/docs/research/2026-10-27-subagent-live-update-amplification/README.md @@ -133,7 +133,7 @@ function liveRecord(record) { } ``` -整个 roster 还受一个 **48 KiB / 次**的序列化字节预算约束:超出部分不发送,改为 `omittedResults: N`(`MAX_PARALLEL_TASKS` 允许 1000 个任务,完整 roster 是 O(N))。后台 lane 侧按 index 合并,因此被省略的尾部不会让已存在的 lane 从内存列表里消失。 +整个 roster 还受一个 **48 KiB / 次**的序列化字节预算约束:超出部分不发送,改为 `omittedResults: N`(`MAX_PARALLEL_TASKS` 允许 1000 个任务,完整 roster 是 O(N))。后台 lane 侧按 index 合并,并按本次 update 自身的总数重算省略数:合并只能找回「曾经收到过」的记录,永远补不回「从未发布过」的尾部,因此不能把省略数清零。 **② 合流节流**:`LIVE_UPDATE_INTERVAL_MS = 100`(与既有 `BASH_UPDATE_THROTTLE_MS` 一致)。 @@ -205,6 +205,7 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, - chain 把上一步 500 KB 输出插入下一步 task,所有 update 仍 < 32 KiB、`task` ≤ 600 字符; - 200 次 delta 只产生 ≤ 6 次发布; - 200 个并行任务的批量调用:发布 < 60 次、单条 < 128 KiB、总量 < 2 MiB、出现 `omittedResults`; + - 后台 lane 运行 200 任务:每次发布的头部都报告真实总数(`/200 complete`),省略项显示为「not shown」而不是 failed; - 终态预算:保留最新消息、序列化数组 ≤ 64 KiB、`messagesTruncated: true`; - 单条消息超预算且无 `activeText` 时,仍从完整 transcript 回填可渲染文本; - 400 KB 最终答复在展示投影里被压到 ≤ 50,000 字符; @@ -218,7 +219,7 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, 回归: -- `packages/coding-agent` 全量:约 5000 passed / 58 skipped。唯一稳定失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关);`subagent-invocation` 的 CLI 启动用例偶发超时,单跑必过(该文件注释已记录此既有偶发)。 +- `packages/coding-agent` 全量:5002 passed / 58 skipped。唯一稳定失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关);`subagent-invocation` 的 CLI 启动用例偶发超时,单跑必过(该文件注释已记录此既有偶发)。 - `pnpm run check` 全绿(biome / 边界检查 / `tsgo --noEmit` / browser smoke)。 - `git diff --check` 干净。 diff --git a/packages/coding-agent/src/features/step-subagent.ts b/packages/coding-agent/src/features/step-subagent.ts index 90a817572..e0c6ca270 100644 --- a/packages/coding-agent/src/features/step-subagent.ts +++ b/packages/coding-agent/src/features/step-subagent.ts @@ -764,10 +764,12 @@ export function createStepSubagentExtension(options: StepSubagentExtensionOption lane.ctx.ui.setWidget(lanesWidgetKey, undefined); return; } + const omitted = batch.reduce((sum, entry) => sum + (entry.details.omittedResults ?? 0), 0); const details: StepSubagentDetails = { ...lane.details, mode: "parallel", results: batch.flatMap((entry) => entry.details.results), + ...(omitted > 0 ? { omittedResults: omitted } : {}), }; lanesWidget?.setDetails(details); const signature = subagentListSignature(details); diff --git a/packages/coding-agent/src/features/subagent/execute.ts b/packages/coding-agent/src/features/subagent/execute.ts index 7d85aae14..a1e78338f 100644 --- a/packages/coding-agent/src/features/subagent/execute.ts +++ b/packages/coding-agent/src/features/subagent/execute.ts @@ -279,6 +279,7 @@ function liveRecord(record: StepSubagentResultRecord): StepSubagentResultRecord ...(record.sessionId === undefined ? {} : { sessionId: clipMiddle(record.sessionId, LIVE_IDENTIFIER_CHARS) }), ...(record.sessionFile === undefined ? {} : { sessionFile: clipMiddle(record.sessionFile, LIVE_PATH_CHARS) }), ...(record.pendingReply === undefined ? {} : { pendingReply: record.pendingReply }), + ...boundedPrompts(record.cancelledPrompts), }; } @@ -397,10 +398,11 @@ function finalRecords(records: readonly StepSubagentResultRecord[]): StepSubagen const bounded = boundedMessages(record.messages, messageAllowance); const messages = take(budget, bounded.messages) ? bounded.messages : []; - const task = clipMiddle(record.task, FINAL_TASK_CHARS); - take(budget, task); - const stderr = tailChars(record.stderr, FINAL_STDERR_CHARS) ?? ""; - take(budget, stderr); + // A field the budget rejects is dropped, not silently kept at full size. + const candidateTask = clipMiddle(record.task, FINAL_TASK_CHARS); + const task = take(budget, candidateTask) ? candidateTask : clipMiddle(record.task, 0); + const candidateStderr = tailChars(record.stderr, FINAL_STDERR_CHARS) ?? ""; + const stderr = take(budget, candidateStderr) ? candidateStderr : ""; // A field the budget rejects is dropped, not silently kept at full size. const candidateError = tailChars(record.errorMessage, FINAL_ERROR_CHARS); const errorMessage = take(budget, candidateError) ? candidateError : undefined; diff --git a/packages/coding-agent/src/features/subagent/lane-lifecycle.ts b/packages/coding-agent/src/features/subagent/lane-lifecycle.ts index cda37cc39..a11705e00 100644 --- a/packages/coding-agent/src/features/subagent/lane-lifecycle.ts +++ b/packages/coding-agent/src/features/subagent/lane-lifecycle.ts @@ -93,6 +93,25 @@ function getLaneSessions(sessionId: string, liveOnly = true): StepSubagentRpcSes return sessions; } +/** + * Keep the lane's roster complete enough to report the real task count. + * + * A live update carries only the records that fit its byte budget, so the + * omitted count describes the update, not the roster we hold. Merging recovers + * records we once saw but never ones we have not seen yet, so the count is + * recomputed from the update's own total rather than cleared. + */ +function rosterFields( + previous: StepSubagentDetails, + next: StepSubagentDetails, +): Pick { + if (next.omittedResults === undefined) return { results: next.results }; + const merged = mergeResults(previous.results, next.results); + const total = next.results.length + next.omittedResults; + const omitted = Math.max(0, total - merged.length); + return omitted === 0 ? { results: merged } : { results: merged, omittedResults: omitted }; +} + /** Overlay a bounded live roster onto the roster the lane already knows. */ function mergeResults( previous: readonly StepSubagentResultRecord[], @@ -269,13 +288,7 @@ export function createLaneLifecycle(host: LaneLifecycleHost): LaneLifecycle { // A live roster is byte-bounded, so a large batch may omit its tail. // Keep the lanes we already know instead of forgetting them; the // final result replaces this with every task. - results: - partial.details.omittedResults === undefined - ? partial.details.results - : mergeResults(lane.details.results, partial.details.results), - // After merging, the roster is complete: keeping the count would - // make renderers report more tasks than exist. - ...(partial.details.omittedResults === undefined ? {} : { omittedResults: undefined }), + ...rosterFields(lane.details, partial.details), agentId: lane.id, status: "running", startedAt: lane.startedAt, diff --git a/packages/coding-agent/src/features/subagent/rendering.ts b/packages/coding-agent/src/features/subagent/rendering.ts index d000dd826..b41d88f37 100644 --- a/packages/coding-agent/src/features/subagent/rendering.ts +++ b/packages/coding-agent/src/features/subagent/rendering.ts @@ -234,6 +234,8 @@ export class SubagentListWidget implements Component { const completed = records.filter((record) => record.status === "completed").length; const queued = records.filter((record) => record.status === "queued").length; const skipped = records.filter((record) => record.status === "skipped").length; + // Only visible records can be classified; omitted ones are reported + // separately as "not shown", never counted as failures. const failed = records.length - running - completed - queued - skipped; const summary = [`${completed}/${total} complete`]; if (running > 0) summary.push(`${running} running`); diff --git a/packages/coding-agent/test/subagent-background-tui.test.ts b/packages/coding-agent/test/subagent-background-tui.test.ts index 921fa9cd3..73959b6f5 100644 --- a/packages/coding-agent/test/subagent-background-tui.test.ts +++ b/packages/coding-agent/test/subagent-background-tui.test.ts @@ -241,3 +241,50 @@ test("agent-notification without structured details falls back to the host rende undefined, ); }); + +test("a background lane reports the real task count while its roster is byte-bounded", async () => { + // The live roster stops at a byte budget, so most of a large batch is only + // counted, never listed. Merging recovers what was seen, not what was never + // published: clearing the count here froze a 600-task lane at 202. + const { api, tools, ctx, calls } = harness(); + const tasks = 200; + let release!: () => void; + const gate = new Promise((resolve) => { + release = resolve; + }); + createStepSubagentExtension({ + includeBuiltinAgents: true, + agentDir: "/tmp/step-agent-test", + maxConcurrency: 8, + runner: async (input) => { + input.onUpdate?.({ ...runResult("", 0, -1), exitCode: -1, activeText: "working", messages: [] }); + await gate; + return runResult(`${input.task} done`); + }, + })(api); + await tools.get("subagent")!.execute( + "call-batch" as never, + { + tasks: Array.from({ length: tasks }, (_, index) => ({ agent: "general", task: `bulk task ${index}` })), + run_in_background: true, + } as never, + undefined as never, + undefined as never, + ctx as never, + ); + await waitFor(() => calls.some((call) => (call.component?.render(120)[0] ?? "").includes("background agents"))); + release(); + await waitFor(() => calls.at(-1)?.component === undefined, 10_000); + + // Every header published during the run must name the true total, not the + // number of records that happened to fit. + const headers = calls + .map((call) => call.component?.render(120)[0] ?? "") + .filter((header) => header.includes("background agents")); + expect(headers.length).toBeGreaterThan(0); + for (const header of headers) { + expect(header).toContain(`/${tasks} complete`); + // Omitted tasks are reported as not shown, not as failures. + expect(header).not.toContain("failed"); + } +}); From 6aa60cdd17711958d8bcea9d7f9b3e8255f150c3 Mon Sep 17 00:00:00 2001 From: liuedcson <332840681+liuedcson@users.noreply.github.com> Date: Tue, 27 Oct 2026 22:41:33 +0800 Subject: [PATCH 6/8] fix(coding-agent): clear the lane's omitted count explicitly when it reaches zero `rosterFields` returned only `results` once the merge recovered the whole roster, but the lane spreads the update's own details underneath it. The update's `omittedResults` therefore survived and counted records that had just been recovered: a complete 3-task roster followed by a "1 record + 2 omitted" update reported 5 tasks. The key is now always written, with `undefined` at zero, and the merged roster is capped at the current turn's total so an older, larger roster cannot leak in on a reused lane. Covered by a unit test for both directions: merge recovers everything (count cleared) and lane starts empty (count recomputed). --- .../README.md | 5 ++- .../src/features/subagent/lane-lifecycle.ts | 13 ++++-- .../test/subagent-background-tui.test.ts | 41 +++++++++++++++++++ 3 files changed, 53 insertions(+), 6 deletions(-) diff --git a/docs/research/2026-10-27-subagent-live-update-amplification/README.md b/docs/research/2026-10-27-subagent-live-update-amplification/README.md index d7263c44c..1a82502a5 100644 --- a/docs/research/2026-10-27-subagent-live-update-amplification/README.md +++ b/docs/research/2026-10-27-subagent-live-update-amplification/README.md @@ -133,7 +133,7 @@ function liveRecord(record) { } ``` -整个 roster 还受一个 **48 KiB / 次**的序列化字节预算约束:超出部分不发送,改为 `omittedResults: N`(`MAX_PARALLEL_TASKS` 允许 1000 个任务,完整 roster 是 O(N))。后台 lane 侧按 index 合并,并按本次 update 自身的总数重算省略数:合并只能找回「曾经收到过」的记录,永远补不回「从未发布过」的尾部,因此不能把省略数清零。 +整个 roster 还受一个 **48 KiB / 次**的序列化字节预算约束:超出部分不发送,改为 `omittedResults: N`(`MAX_PARALLEL_TASKS` 允许 1000 个任务,完整 roster 是 O(N))。后台 lane 侧按 index 合并,并按本次 update 自身的总数重算省略数:合并只能找回「曾经收到过」的记录,永远补不回「从未发布过」的尾部,所以不能清零;重算为 0 时也必须显式写回 `undefined`,否则外层展开会把旧计数留下来重复计算。 **② 合流节流**:`LIVE_UPDATE_INTERVAL_MS = 100`(与既有 `BASH_UPDATE_THROTTLE_MS` 一致)。 @@ -206,6 +206,7 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, - 200 次 delta 只产生 ≤ 6 次发布; - 200 个并行任务的批量调用:发布 < 60 次、单条 < 128 KiB、总量 < 2 MiB、出现 `omittedResults`; - 后台 lane 运行 200 任务:每次发布的头部都报告真实总数(`/200 complete`),省略项显示为「not shown」而不是 failed; + - `rosterFields` 单测:完整 roster 收到一个「1 条 + 省略 2」的裁剪更新后,合并结果仍是 3 条且省略数归零(历史 bug:会报 5); - 终态预算:保留最新消息、序列化数组 ≤ 64 KiB、`messagesTruncated: true`; - 单条消息超预算且无 `activeText` 时,仍从完整 transcript 回填可渲染文本; - 400 KB 最终答复在展示投影里被压到 ≤ 50,000 字符; @@ -219,7 +220,7 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, 回归: -- `packages/coding-agent` 全量:5002 passed / 58 skipped。唯一稳定失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关);`subagent-invocation` 的 CLI 启动用例偶发超时,单跑必过(该文件注释已记录此既有偶发)。 +- `packages/coding-agent` 全量:5003 passed / 58 skipped。唯一稳定失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关);`subagent-invocation` 的 CLI 启动用例偶发超时,单跑必过(该文件注释已记录此既有偶发)。 - `pnpm run check` 全绿(biome / 边界检查 / `tsgo --noEmit` / browser smoke)。 - `git diff --check` 干净。 diff --git a/packages/coding-agent/src/features/subagent/lane-lifecycle.ts b/packages/coding-agent/src/features/subagent/lane-lifecycle.ts index a11705e00..fa1ab1939 100644 --- a/packages/coding-agent/src/features/subagent/lane-lifecycle.ts +++ b/packages/coding-agent/src/features/subagent/lane-lifecycle.ts @@ -101,15 +101,20 @@ function getLaneSessions(sessionId: string, liveOnly = true): StepSubagentRpcSes * records we once saw but never ones we have not seen yet, so the count is * recomputed from the update's own total rather than cleared. */ -function rosterFields( +export function rosterFields( previous: StepSubagentDetails, next: StepSubagentDetails, ): Pick { - if (next.omittedResults === undefined) return { results: next.results }; - const merged = mergeResults(previous.results, next.results); + // Always set `omittedResults` explicitly: the caller spreads the update under + // this result, so omitting the key would keep the update's own count and + // double-count the records the merge just recovered. + if (next.omittedResults === undefined) return { results: next.results, omittedResults: undefined }; const total = next.results.length + next.omittedResults; + // A reply reuses a lane; cap at this turn's total so an older, larger roster + // cannot leak into the count. + const merged = mergeResults(previous.results, next.results).slice(0, total); const omitted = Math.max(0, total - merged.length); - return omitted === 0 ? { results: merged } : { results: merged, omittedResults: omitted }; + return { results: merged, omittedResults: omitted === 0 ? undefined : omitted }; } /** Overlay a bounded live roster onto the roster the lane already knows. */ diff --git a/packages/coding-agent/test/subagent-background-tui.test.ts b/packages/coding-agent/test/subagent-background-tui.test.ts index 73959b6f5..819dbc467 100644 --- a/packages/coding-agent/test/subagent-background-tui.test.ts +++ b/packages/coding-agent/test/subagent-background-tui.test.ts @@ -5,10 +5,12 @@ import type { CustomMessage } from "../src/core/messages.ts"; import { type BackgroundAgentLane, createStepSubagentExtension, + type StepSubagentDetails, type StepSubagentRunInput, type StepSubagentRunResult, } from "../src/features/step-subagent.ts"; import { type AgentNotificationDetails, notifyLaneEvent } from "../src/features/subagent/lane-events.ts"; +import { rosterFields } from "../src/features/subagent/lane-lifecycle.ts"; import { renderAgentNotification } from "../src/features/subagent/rendering.ts"; import type { Theme } from "../src/theme/theme.ts"; @@ -288,3 +290,42 @@ test("a background lane reports the real task count while its roster is byte-bou expect(header).not.toContain("failed"); } }); + +function detailsWith(statuses: Array<"queued" | "running" | "completed">, omitted?: number): StepSubagentDetails { + return { + mode: "parallel", + agentScope: "user", + userAgentsDir: "/tmp/agents", + projectAgentsDir: null, + results: statuses.map((status, index) => ({ + agent: "general", + agentSource: "builtin" as const, + task: `t${index}`, + status, + exitCode: status === "completed" ? 0 : -1, + messages: [], + stderr: "", + usage: { input: 0, output: 0, cacheRead: 0, cacheWrite: 0, cost: 0, contextTokens: 0, turns: 0 }, + })), + ...(omitted === undefined ? {} : { omittedResults: omitted }), + }; +} + +test("a lane that recovers its whole roster drops the omitted count instead of keeping both", () => { + // The lane already holds the full three-task roster. A later update carries + // only one record plus "two omitted"; merging recovers all three, so the count + // must go to zero. Leaving the update's own count in place reported five. + const full = detailsWith(["running", "queued", "queued"]); + const partial = detailsWith(["running"], 2); + + const next = { ...partial, ...rosterFields(full, partial) }; + expect(next.results).toHaveLength(3); + expect(next.omittedResults).toBeUndefined(); + expect((next.results.length ?? 0) + (next.omittedResults ?? 0)).toBe(3); + + // And when the lane starts empty, the merge cannot recover the records it was + // never sent, so the count is recomputed from this update's total. + const fromEmpty = { ...partial, ...rosterFields(detailsWith([]), partial) }; + expect(fromEmpty.results).toHaveLength(1); + expect(fromEmpty.omittedResults).toBe(2); +}); From 54cb6c3d6523432830a38f2a1d5cab3a3222f2cf Mon Sep 17 00:00:00 2001 From: liuedcson <332840681+liuedcson@users.noreply.github.com> Date: Tue, 27 Oct 2026 22:50:01 +0800 Subject: [PATCH 7/8] fix(coding-agent): put tool args and output inside the final details budget Two fields were still rendered from a bare `tailChars` and never charged to the shared budget, so a batch with large control-character tool output produced details that ignored the bound: 1000 tasks reached 9.13 MiB. They now go through the same `take()` gate as every other heavy field (1000 tasks: 456 KiB). Failed records also claim their `stderr`/`errorMessage` before the progress text. Previously the budget was spent in record order, so later failures carried no reason at all and the lane summary printed "no error detail captured". --- .../src/features/subagent/execute.ts | 29 ++++++++++++------- 1 file changed, 18 insertions(+), 11 deletions(-) diff --git a/packages/coding-agent/src/features/subagent/execute.ts b/packages/coding-agent/src/features/subagent/execute.ts index a1e78338f..cd9b1146f 100644 --- a/packages/coding-agent/src/features/subagent/execute.ts +++ b/packages/coding-agent/src/features/subagent/execute.ts @@ -387,6 +387,16 @@ function finalRecords(records: readonly StepSubagentResultRecord[]): StepSubagen return records.map((record) => { const fallbackText = finalOutput(record.messages); const text = record.activeText || fallbackText; + // A failed record's diagnostics are worth more than its progress text, so + // they are claimed first. Otherwise the budget the earlier records spent + // would leave later failures with no reason at all. + const failed = record.status === "failed" || record.status === "aborted"; + const candidateStderr = tailChars(record.stderr, FINAL_STDERR_CHARS) ?? ""; + const candidateError = tailChars(record.errorMessage, FINAL_ERROR_CHARS); + const stderrFirst = failed ? candidateStderr : ""; + const stderrReserved = failed ? take(budget, stderrFirst) : false; + const errorReserved = failed ? take(budget, candidateError) : false; + // Six-byte JSON escapes are the worst case per character, so a quarter of // the remaining bytes as characters is already conservative once the // serialized check below has the final say. @@ -401,11 +411,12 @@ function finalRecords(records: readonly StepSubagentResultRecord[]): StepSubagen // A field the budget rejects is dropped, not silently kept at full size. const candidateTask = clipMiddle(record.task, FINAL_TASK_CHARS); const task = take(budget, candidateTask) ? candidateTask : clipMiddle(record.task, 0); - const candidateStderr = tailChars(record.stderr, FINAL_STDERR_CHARS) ?? ""; - const stderr = take(budget, candidateStderr) ? candidateStderr : ""; - // A field the budget rejects is dropped, not silently kept at full size. - const candidateError = tailChars(record.errorMessage, FINAL_ERROR_CHARS); - const errorMessage = take(budget, candidateError) ? candidateError : undefined; + const stderr = stderrReserved ? stderrFirst : take(budget, candidateStderr) ? candidateStderr : ""; + const errorMessage = errorReserved ? candidateError : take(budget, candidateError) ? candidateError : undefined; + const candidateArgs = tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS); + const activeToolArgs = take(budget, candidateArgs) ? candidateArgs : undefined; + const candidateOutput = tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS); + const activeToolOutput = take(budget, candidateOutput) ? candidateOutput : undefined; const prompts = boundedPrompts(record.cancelledPrompts); const cancelledPrompts = take(budget, prompts.cancelledPrompts) ? prompts.cancelledPrompts : undefined; @@ -427,12 +438,8 @@ function finalRecords(records: readonly StepSubagentResultRecord[]): StepSubagen ...(record.activeTool === undefined ? {} : { activeTool: clipMiddle(record.activeTool, FINAL_IDENTIFIER_CHARS) }), - ...(record.activeToolArgs === undefined - ? {} - : { activeToolArgs: tailChars(record.activeToolArgs, LIVE_TOOL_ARGS_CHARS) }), - ...(record.activeToolOutput === undefined - ? {} - : { activeToolOutput: tailChars(record.activeToolOutput, LIVE_TOOL_OUTPUT_CHARS) }), + ...(activeToolArgs === undefined ? {} : { activeToolArgs }), + ...(activeToolOutput === undefined ? {} : { activeToolOutput }), ...(record.lastEvent === undefined ? {} : { lastEvent: clipMiddle(record.lastEvent, FINAL_IDENTIFIER_CHARS) }), ...(record.startedAt === undefined ? {} : { startedAt: record.startedAt }), ...(record.updatedAt === undefined ? {} : { updatedAt: record.updatedAt }), From 0f3e428bef0db56268c67f82f7017a1877c105dd Mon Sep 17 00:00:00 2001 From: liuedcson <332840681+liuedcson@users.noreply.github.com> Date: Wed, 28 Oct 2026 10:59:05 +0800 Subject: [PATCH 8/8] test(coding-agent): assert the publish rate instead of a wall-clock count CI caught two test problems, no product change: - The parallel-batch regression asserted a fixed publish count, but the batch spends one tick per 100ms of wall clock, so a 2-core runner legitimately publishes more than a laptop for the same 200 tasks (121 vs <60). It now bounds publishes by `elapsed / 100ms + slack`, which still catches the quadratic regression on any hardware, and a second case asserts that an instantly finished batch publishes at most a handful of times. That second case is clock-independent and is the direct guard for per-status publishing. - `settle` in the idle-TTL test waited on virtual time only, but the lane's notification awaits real file I/O that virtual time cannot advance, so the 500 fast iterations could finish before the read resolved. It now also holds a real deadline and hands control back to the event loop between ticks. The assertion is unchanged: the notification must arrive. The idle-TTL test already failed this way on `main` (CI run 119736908986), so the hardening is not a behaviour change. --- .../README.md | 7 +-- .../test/step-subagent-events.test.ts | 14 +++++- .../test/subagent-live-update-budget.test.ts | 46 ++++++++++++------- 3 files changed, 46 insertions(+), 21 deletions(-) diff --git a/docs/research/2026-10-27-subagent-live-update-amplification/README.md b/docs/research/2026-10-27-subagent-live-update-amplification/README.md index 1a82502a5..c611d412f 100644 --- a/docs/research/2026-10-27-subagent-live-update-amplification/README.md +++ b/docs/research/2026-10-27-subagent-live-update-amplification/README.md @@ -197,14 +197,15 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, ### 4.3 测试与验证 -新增(21 个用例): +新增(22 个用例): - `test/subagent-live-update-rpc.test.ts` —— **端到端**:真起 `--mode rpc` 子进程,走真实 rpc-adapter → parseJsonEvent → 编排 → Agent Loop → toJsonEvent。断言整条父日志 < 1 MiB、update 数 < 60、无一条 update 携带 messages、终态 messages ≤ 64 KiB;并用 300 KB 最终答复验证展示投影有界而模型可见 `content` 仍完整。 - `test/subagent-live-update-budget.test.ts` - 400 次携带增长 transcript 的 update:live 一律 `messages: []`、单条 < 32 KiB、总量 < 2 MiB; - chain 把上一步 500 KB 输出插入下一步 task,所有 update 仍 < 32 KiB、`task` ≤ 600 字符; - 200 次 delta 只产生 ≤ 6 次发布; - - 200 个并行任务的批量调用:发布 < 60 次、单条 < 128 KiB、总量 < 2 MiB、出现 `omittedResults`; + - 200 个并行任务的批量调用:发布次数 ≤ `耗时/100ms + 10`(按速率而非绝对次数断言,慢机器上合理的更多 tick 不算失败)、单条 < 128 KiB、出现 `omittedResults`; + - 200 个瞬时完成的并行任务:发布 ≤ 10 次(这条与墙钟无关,是 O(N²) 的直接守卫); - 后台 lane 运行 200 任务:每次发布的头部都报告真实总数(`/200 complete`),省略项显示为「not shown」而不是 failed; - `rosterFields` 单测:完整 roster 收到一个「1 条 + 省略 2」的裁剪更新后,合并结果仍是 3 条且省略数归零(历史 bug:会报 5); - 终态预算:保留最新消息、序列化数组 ≤ 64 KiB、`messagesTruncated: true`; @@ -220,7 +221,7 @@ parallel 批量(200 任务)回归:发布次数 < 60,单条 < 128 KiB, 回归: -- `packages/coding-agent` 全量:5003 passed / 58 skipped。唯一稳定失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关);`subagent-invocation` 的 CLI 启动用例偶发超时,单跑必过(该文件注释已记录此既有偶发)。 +- `packages/coding-agent` 全量(Node 22,与 CI 一致):5004 passed / 58 skipped。唯一稳定失败是 6 个 `completion-check-cli` 用例,**在未改动的 `main` 上以完全相同的方式失败**(本机 git worktree 前置条件问题,与本改动无关);`subagent-invocation` 的 CLI 启动用例偶发超时,单跑必过(该文件注释已记录此既有偶发)。 - `pnpm run check` 全绿(biome / 边界检查 / `tsgo --noEmit` / browser smoke)。 - `git diff --check` 干净。 diff --git a/packages/coding-agent/test/step-subagent-events.test.ts b/packages/coding-agent/test/step-subagent-events.test.ts index b9dcc6fd6..d420ea73b 100644 --- a/packages/coding-agent/test/step-subagent-events.test.ts +++ b/packages/coding-agent/test/step-subagent-events.test.ts @@ -1023,13 +1023,23 @@ test("idle keep-alive children are stopped after the TTL and a reply resumes qui * details from disk, so waiting on 1ms of virtual time is a race against * file I/O that a loaded CI runner loses. Advance in steps for a bounded * virtual budget instead, and report what did arrive. + * + * Virtual time cannot advance real I/O, and `advanceTimersByTimeAsync` + * only yields microtasks, so 500 fast iterations can finish before the + * file read resolves. Hold a real deadline too and hand the loop back to + * the event loop between ticks; the assertion is still "it must arrive". */ + const reached = (count: number): boolean => + sent.filter((m) => m.details?.event === "background_done").length >= count; const settle = async (count: number): Promise => { + const deadline = Date.now() + 20_000; for (let i = 0; i < 500; i += 1) { - if (sent.filter((m) => m.details?.event === "background_done").length >= count) return true; + if (reached(count)) return true; await vi.advanceTimersByTimeAsync(10); + await new Promise((resolve) => setImmediate(resolve)); + if (Date.now() > deadline) return reached(count); } - return false; + return reached(count); }; const notifications = () => sent.map((m) => m.details?.event ?? "?").join(", ") || "none"; expect(await settle(1), `notifications after the first lane: ${notifications()}`).toBe(true); diff --git a/packages/coding-agent/test/subagent-live-update-budget.test.ts b/packages/coding-agent/test/subagent-live-update-budget.test.ts index 4f420954a..2df8b6ac0 100644 --- a/packages/coding-agent/test/subagent-live-update-budget.test.ts +++ b/packages/coding-agent/test/subagent-live-update-budget.test.ts @@ -204,40 +204,54 @@ test("streamed deltas and status changes coalesce into one publish per interval" expect(updates.at(-1)?.details?.results[0]?.status).toBe("completed"); }); -test("a large parallel batch stays bounded per publish and in total", async () => { +test("a large parallel batch publishes at the tick rate, not once per status change", async () => { const tasks = 200; - const released: Array<() => void> = []; const seen: Captured[] = []; - const pending = run( + const startedAt = Date.now(); + const { updates } = await run( { tasks: Array.from({ length: tasks }, (_, index) => ({ agent: "general", task: `task ${index}` })), }, async (input) => { input.onUpdate?.({ ...idle, activeText: "working" }); - // Keep every lane running across several ticks so the roster is - // republished, which is what used to make this quadratic. - await new Promise((resolve) => { - released.push(resolve); - setTimeout(resolve, 120); - }); + // Stay running across several ticks so the roster is republished, which + // is what used to make this quadratic. + await new Promise((resolve) => setTimeout(resolve, 120)); return { ...idle, exitCode: 0, stopReason: "stop" }; }, { sink: seen }, ); - const { updates } = await pending; - void released; + const elapsedMs = Date.now() - startedAt; - // Publishing each of 2 x 200 status transitions immediately produced ~400 - // publishes of the whole roster. Coalescing keeps it to a handful. - expect(updates.length).toBeLessThan(60); + // The invariant is a rate, not a count: a slow runner legitimately spends more + // ticks on the same batch. Before the change, each of the 2 x 200 status + // transitions republished the whole roster, so the count tracked the batch. + expect(updates.length).toBeLessThanOrEqual(Math.ceil(elapsedMs / 100) + 10); const largest = Math.max(...updates.map((update) => update.bytes)); expect(largest).toBeLessThan(128 * 1024); - const total = updates.reduce((sum, update) => sum + update.bytes, 0); - expect(total).toBeLessThan(2 * 1024 * 1024); // A bounded roster says what it left out instead of dropping it silently. expect(updates.some((update) => (update.details?.omittedResults ?? 0) > 0)).toBe(true); }); +test("an instantly finished parallel batch does not publish once per task", async () => { + // The strongest form of the same guard, independent of wall clock: with 200 + // tasks that settle immediately, per-status publishing produced ~400 updates + // of the whole roster. Coalescing makes it a handful. + const tasks = 200; + const { updates } = await run( + { + tasks: Array.from({ length: tasks }, (_, index) => ({ agent: "general", task: `task ${index}` })), + }, + async (input) => { + input.onUpdate?.({ ...idle, activeText: "working" }); + return { ...idle, exitCode: 0, stopReason: "stop" }; + }, + ); + + expect(updates.length).toBeLessThanOrEqual(10); + expect(updates.at(-1)?.details?.results.every((record) => record.status === "completed")).toBe(true); +}); + test("the final result keeps the newest transcript messages and says it truncated", async () => { const messages: StepSubagentRunResult["messages"] = []; for (let index = 0; index < 20; index += 1) messages.push(message(index, 40_000));