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..c611d412f --- /dev/null +++ b/docs/research/2026-10-27-subagent-live-update-amplification/README.md @@ -0,0 +1,262 @@ +# 子代理事件日志放大:定位、竞品对照与修复方案 + +- 日期: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 落盘 | 写入触发 | 单个工具结果上限 | 子代理历史 | +| --- | --- | --- | --- | --- | --- | --- | +| 类型级 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. **流式增量永不进入持久化层**。要么在类型上把「可重放」与「仅实时」做成互斥类型(`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 进了父会话、写侧没有上限。所以修复必须同时补这三层,只改其中一层都会留下复发路径。 + +--- + +## 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`) + +投影是**显式 allowlist**,不是 `{...record}` 打补丁:runner 的未知字段、chain 展开后的巨型 task、身份/路径字段都必须各自有边界。 + +```ts +function liveRecord(record) { + return { + 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 合并,并按本次 update 自身的总数重算省略数:合并只能找回「曾经收到过」的记录,永远补不回「从未发布过」的尾部,所以不能清零;重算为 0 时也必须显式写回 `undefined`,否则外层展开会把旧计数留下来重复计算。 + +**② 合流节流**:`LIVE_UPDATE_INTERVAL_MS = 100`(与既有 `BASH_UPDATE_THROTTLE_MS` 一致)。 + +- **所有**更新(含 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`。 +- 全部 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`)。 + +**④ 通用 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* 一节,说明「最终结果上限」与「直播上限」是两套独立的边界。 + +### 3.3 修复后(同一复现脚本) + +| 子会话规模 | 修复前 | 修复后 | 降幅 | +| --- | --- | --- | --- | +| 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(共享 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²)。 + +--- + +## 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 生成)。 +- 状态机的**终态**语义不变:每个任务最终都会到达 completed/failed/aborted,并在调用返回前刷出。 +- **变化**:短于 100 ms 的状态跃迁(典型如瞬时完成的测试替身)可能不出现在 wire 上。真实子代理是秒级,不受影响;这是消除 parallel 下 O(N²) 的必要代价。 +- 直播期间的 `activeText` 从最多 50k 字符变为 2k 尾部,工具入参/输出也从完整值变为尾部:这是**刻意的可见降级**(progress 是可合并快照,不是完整事件历史)。 +- 可观测契约变化:`StepSubagentDetails.results[].messages` 从「全量」变为「终态限量」并新增可选 `messagesTruncated`;直播字段变为有界尾部。消费方(TUI 展开、历史渲染、web 子代理卡片)只用最后一个 assistant 文本或状态字段,已逐一核对。 +- 定时器在返回前关闭(`closeEmitter`),调用返回后的迟到回调不再发布;`onUpdate` 抛错不再从定时器逃逸成未捕获异常,而是按「dispatch 错误优先」的顺序在调用路径上抛出。 +- `mapWithConcurrency` 改为等待所有 worker 结束(`allSettled`)再返回,避免 fail-fast 提前返回后仍有 lane 对着已关闭的 emitter 继续工作。 + +### 4.3 测试与验证 + +新增(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 个并行任务的批量调用:发布次数 ≤ `耗时/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`; + - 单条消息超预算且无 `activeText` 时,仍从完整 transcript 回填可渲染文本; + - 400 KB 最终答复在展示投影里被压到 ≤ 50,000 字符; + - 60 个任务各带 300 KB 答复:终态 details ≤ 256 KiB + O(tasks)(覆盖「预算耗尽后 allowance 为 0」这条路径); + - 调用返回后的迟到回调不再发布; + - `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` 全量(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` 干净。 + +### 4.4 风险与回滚 + +| 风险 | 控件 | +| --- | --- | +| 直播更新过少导致 UI 卡顿感 | 100 ms 与 bash 既有节流一致,token 计数 10 Hz 足够;终态由返回前的 flush 保证 | +| 终态 `messages` 裁剪影响历史渲染 | 渲染优先 `activeText`;`sessionId`/`sessionFile` 指向子进程完整 transcript | +| 兜底误伤正常流式工具 | 阈值 256 KiB,远高于 bash 的 50 KiB;新增测试锁定「未超限原样透传」 | +| 合流定时器泄漏/迟到投递 | 返回前 `closeEmitter` + `flushEmit`(在 dispatch 之外,dispatch 错误优先);`unref()` | +| 后续 web 分支合并冲突 | 改动集中在 `emit` 与 dispatch 外层(`try/finally`);web 分支改的是 `runOne` 内部与 `sessionId` 传递,冲突面小 | + +回滚:分支上三个 commit(初版 + 两轮评审修正),逐个 `git revert` 即恢复原行为,无数据迁移、无配置项。 + +### 4.5 后续(未纳入本 PR) + +1. **终态回显放大**:一次调用的终态 details 会被约 5 类事件各带一份(≈5 × 100 KiB)。要压缩需要改消息级事件形状,与本次「最小爆炸半径」目标冲突,建议单独立项。 +2. **内存队列仍无界**:`agent-loop` 的 update promise 数组与 `output-guard` 的 stdout promise 串都没有上限。本 PR 只降低了增长速度,慢读者场景需要单独做背压或队列上限。 +3. **wire 兜底丢弃非文本 content**:超限的 update 只保留 text part,图片预览会丢;终态不受影响。第三方工具若在小体积 update 里带图需要另行处理。 +4. **web SSE 兜底**:web 分支的 SSE 直接转发 session event,未经过 `toJsonEvent`。当前源头已收敛,但建议在该分支 rebase 后补一条同等的回归测试。 +5. **类型级约束**:成熟实现的做法是给会话事件加 `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/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..0250cb953 100644 --- a/packages/coding-agent/docs/rpc.md +++ b/packages/coding-agent/docs/rpc.md @@ -1052,7 +1052,14 @@ 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 +`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 diff --git a/packages/coding-agent/docs/tool-output-retention.md b/packages/coding-agent/docs/tool-output-retention.md index d253a8b75..3972e2006 100644 --- a/packages/coding-agent/docs/tool-output-retention.md +++ b/packages/coding-agent/docs/tool-output-retention.md @@ -33,3 +33,45 @@ 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. The bound is +`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). 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, 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 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 +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..e0c6ca270 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 { @@ -225,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 { @@ -752,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 3d1a26f39..cd9b1146f 100644 --- a/packages/coding-agent/src/features/subagent/execute.ts +++ b/packages/coding-agent/src/features/subagent/execute.ts @@ -48,6 +48,65 @@ import { import { truncateText } from "./lane-events.ts"; import type { StepSubagentLaneRuntime } from "./lane-lifecycle.ts"; +/** + * 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. 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. 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; +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; +/** 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 details embedded in the tool 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_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; task: string; @@ -152,6 +211,254 @@ function buildDetails( }; } +/** + * 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) 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)}`; +} + +/** + * 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 { + agent: clipMiddle(record.agent, LIVE_IDENTIFIER_CHARS), + agentSource: record.agentSource, + task: clipMiddle(record.task, LIVE_TASK_CHARS), + status: record.status, + exitCode: record.exitCode, + messages: [], + stderr: tailChars(record.stderr, LIVE_STDERR_CHARS) ?? "", + usage: cloneUsage(record.usage), + ...(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: 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: 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: 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), + }; +} + +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) ?? ""), + }; +} + +/** 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 { + if (value === undefined) return true; + 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); + // 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 }; + 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 = serializedBytes(messages[index]) + 1; + if (bytes + size > budget) break; + bytes += size; + kept.push(messages[index]); + } + return { + messages: kept.reverse() as StepSubagentRunResult["messages"], + truncated: kept.length < messages.length, + }; +} + +/** + * Final record projection. + * + * 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) => { + 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. + const textAllowance = Math.min(FINAL_TEXT_CHARS, Math.max(0, Math.floor(budget.remaining / 4))); + 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); + const messages = take(budget, bounded.messages) ? bounded.messages : []; + + // 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 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; + + return { + agent: clipMiddle(record.agent, FINAL_IDENTIFIER_CHARS), + agentSource: record.agentSource, + task, + 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) }), + ...(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 }), + ...(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 } : {}), + }; + }); +} + async function mapWithConcurrency( items: readonly T[], concurrency: number, @@ -166,7 +473,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; } @@ -396,22 +707,80 @@ export async function runPreparedSubagent( duration_ms: Math.max(0, Date.now() - (createdAt[index] ?? Date.now())), }); }; + 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 (closed || !onUpdate) return; + lastPublishAt = Date.now(); + const live = liveDetails(mode, discovery, scope, records); + 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 every update into the next tick. + * + * 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 => { - onUpdate?.( - makeToolResult( - buildDetails( - mode, - discovery, - scope, - records.map((record) => ({ - ...record, - messages: [...record.messages], - usage: cloneUsage(record.usage), - })), - ), - resultDetailsText(buildDetails(mode, discovery, scope, records)), - ), - ); + if (closed || !onUpdate || pendingPublish) return; + const wait = LIVE_UPDATE_INTERVAL_MS - (Date.now() - lastPublishAt); + if (wait <= 0) { + publishSafely(mode); + return; + } + pendingPublish = setTimeout(() => { + pendingPublish = undefined; + publishSafely(mode); + }, wait); + pendingPublish.unref?.(); + }; + + /** 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; + } + if (!closed && onUpdate) publishSafely(mode); + closeEmitter(); + if (publishError !== undefined) { + const error = publishError; + publishError = undefined; + throw error instanceof Error ? error : new Error(String(error)); + } }; const runOne = async ( @@ -551,36 +920,55 @@ 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); - 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); + } 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; + } + 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..fa1ab1939 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,41 @@ 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. + */ +export function rosterFields( + previous: StepSubagentDetails, + next: StepSubagentDetails, +): Pick { + // 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 { results: merged, omittedResults: omitted === 0 ? undefined : omitted }; +} + +/** 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 +290,10 @@ 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. + ...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 7a0f85dde..b41d88f37 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,15 @@ 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; + // 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}/${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 +277,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 +294,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/src/modes/json-event.ts b/packages/coding-agent/src/modes/json-event.ts index 067d8877f..b2933b42a 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,89 @@ 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; + +/** 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; + +function isTextPart(value: unknown): value is { type: "text"; text: string } { + if (!value || typeof value !== "object") return false; + const part = value as { type?: unknown; text?: string }; + return part.type === "text" && typeof part.text === "string"; +} + +function serializedBytes(value: unknown): number { + return Buffer.byteLength(JSON.stringify(value), "utf8"); +} + +/** + * Keep a live update under the wire budget. + * + * The budget applies to the *serialized* event, envelope included, because that + * is what the host writes. Measuring the raw text instead would under-count: + * a control character or a lone surrogate becomes a six-byte JSON escape, so a + * 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; + const content: unknown[] = Array.isArray(event.partialResult?.content) ? event.partialResult.content : []; + const text = content + .filter(isTextPart) + .map((part) => part.text) + .join("\n"); + + const candidate = (tail: string): JsonAgentSessionEvent => ({ + type: "tool_execution_update", + // 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: [ + { + type: "text", + text: tail.length > 0 ? `${tail}\n${TRUNCATED_MARKER}` : TRUNCATED_MARKER, + }, + ], + details: undefined, + }, + }); + + // 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.length <= 1 ? "" : kept.slice(-Math.floor(kept.length / 2)); + bounded = candidate(kept); + } + 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/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 new file mode 100644 index 000000000..08664cfb5 --- /dev/null +++ b/packages/coding-agent/test/json-event-live-update-budget.test.ts @@ -0,0 +1,115 @@ +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. + * + * 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 { + return { + type: "tool_execution_update", + toolCallId: "call_1", + toolName: "subagent", + args: { agent: "general" }, + partialResult, + }; +} + +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 by serialized size, not raw characters", () => { + const big = "x".repeat(4 * 1024 * 1024); + 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. + 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 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); + // 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("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.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", () => { + 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/step-subagent-events.test.ts b/packages/coding-agent/test/step-subagent-events.test.ts index eadf36904..d420ea73b 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; @@ -1020,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-background-tui.test.ts b/packages/coding-agent/test/subagent-background-tui.test.ts index 560975793..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"; @@ -140,6 +142,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"); @@ -238,3 +243,89 @@ 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"); + } +}); + +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); +}); 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-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 new file mode 100644 index 000000000..2df8b6ac0 --- /dev/null +++ b/packages/coding-agent/test/subagent-live-update-budget.test.ts @@ -0,0 +1,349 @@ +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 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; + +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; + /** Rendered text of the partial result, as a UI would read it. */ + text: string; +} + +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[] = options.sink ?? []; + const startedAt = Date.now(); + const result = (await tools.get("subagent")!.execute( + "call", + 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 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, + activeText: "y".repeat(50_000), + activeTool: "run_command", + activeToolArgs: "z".repeat(20_000), + activeToolOutput: "w".repeat(20_000), + lastEvent: "message_update", + }); + if (index % 40 === 0) await new Promise((resolve) => setTimeout(resolve, 5)); + } + return { ...idle, messages, exitCode: 0, stopReason: "stop" }; + }); + + expect(updates.length).toBeGreaterThan(1); + 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); + } + expect(updates.reduce((sum, update) => sum + update.bytes, 0)).toBeLessThan(2 * 1024 * 1024); + expect(result.details?.results[0]?.status).toBe("completed"); +}); + +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 and status changes coalesce into one publish per interval", 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); + // A short-lived status may never reach the wire; the terminal state always does. + expect(updates.at(-1)?.details?.results[0]?.status).toBe("completed"); +}); + +test("a large parallel batch publishes at the tick rate, not once per status change", async () => { + const tasks = 200; + const seen: Captured[] = []; + 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" }); + // 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 elapsedMs = Date.now() - startedAt; + + // 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); + // 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)); + const { result } = await run({ agent: "general", task: "inspect" }, async () => ({ + ...idle, + messages, + exitCode: 0, + stopReason: "stop", + })); + const record = result.details?.results[0]; + const kept = record?.messages ?? []; + expect(kept.length).toBeGreaterThan(0); + expect(kept.length).toBeLessThan(messages.length); + 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 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("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, + activeText: "q".repeat(400_000), + exitCode: 0, + stopReason: "stop", + })); + const record = result.details?.results[0]; + // 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" }); +}); + +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 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..53f1c5f03 --- /dev/null +++ b/packages/coding-agent/test/subagent-live-update-rpc.test.ts @@ -0,0 +1,180 @@ +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[] = []; +// 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. +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(50_000); + expect(stats.logBytes).toBeLessThan(1024 * 1024); + expect(stats.largestUpdate).toBeLessThan(64 * 1024); +});