Merge pull request #5298 from deepseek-harness/fix/pwsh-settle-diagnosis-20260927

test(pwsh): record a per-send readiness timeline in the loader-composition case
This commit is contained in:
Tianyi Cui authored and GitHub committed 2026-09-28 23:10:24 +08:00
commit dc19d6b7fb
9 files changed
+589 -42

No files matched your search

@@ -6,11 +6,11 @@
en: 5e8c5673a0669d9c
zh: c8442a6186288a2a
/agent-note-a-seen-prompt-marker-keeps-its-own-tail-grace/problem:
en: ac4fb08e3203cee9
zh: 69fcfcb4f8fc0319
en: 906f8707987ff36c
zh: 40430ec1e03ee340
/agent-note-a-seen-prompt-marker-keeps-its-own-tail-grace/decision:
en: 653c74442decb65a
zh: 46f01c45d48b846b
en: a998f5c6abdd68eb
zh: a7cdd13e1e4de6c6
/agent-note-a-seen-prompt-marker-keeps-its-own-tail-grace/alternatives-considered:
en: 21a9a19b76f42758
zh: 30a8f5425b59900d
@@ -18,5 +18,5 @@
en: b58904921286a1db
zh: a696c2954d86c04f
/agent-note-a-seen-prompt-marker-keeps-its-own-tail-grace/testing:
en: 78253191eea198fa
zh: 32bdd6807ddc13a0
en: c741ea002d239ae6
zh: d68846526e63ce51
@@ -6,11 +6,11 @@ English | [中文](2026-09-27-pwsh-prompt-tail-grace.zh.md)
## Problem
Windows sessions on the self-hosted lane settled one or two of seven sends on the controlled prompt and charged the silence tier for the rest (2026-09-25/26, issue #2487). The exact readiness evidence is the controlled prompt's printable tail after the OSC `133;D` marker, and the bound on waiting for it was `idleSilenceMs + handoffGraceMs`. A native Windows probe shows the render arrives as two pty chunks: the marker alone, then the five-byte `dsh> ` 2-28 ms later (56 renders), with nothing printable after any prompt and no terminal queries in the output. The marker is written by the shell's own prompt function and the tail by the same render, so a tail that arrives past the bound means the host stalled that delivery, not that the prompt is absent. The session settled `inferred_idle` anyway, and each such send cost the tool call roughly three seconds.
Windows sessions on the self-hosted lane settled one or two of seven sends on the controlled prompt and charged the silence tier for the rest (2026-09-25/26, issue #2487). The exact readiness evidence is the controlled prompt's printable tail after the OSC `133;D` marker, and the bound on waiting for it was `idleSilenceMs + handoffGraceMs`. A native Windows probe shows the render arrives as two pty chunks: the marker alone, then the five-byte `dsh> ` 2-28 ms later (56 renders under Windows PowerShell 5.1, the same two-chunk render under pwsh 7.6.6), with nothing printable after any prompt and no terminal queries in the output. The marker is written by the shell's own prompt function and the tail by the same render, so a tail that arrives past the bound means the host stalled that delivery, not that the prompt is absent. The session settled `inferred_idle` anyway, and each such send cost the tool call roughly three seconds. The lane's own failures are not that state: the first master run carrying this field (run 36326153388, 2026-09-27 14:30Z) took the same 20.8 s as the run before it (36309006133), so its degraded sends settled at the plain bound with the tolerance inert; the [Windows-lane observation note](../testing/2026-09-27-observation-waits-on-observed-state.md) records the open investigation.
## Decision
`dsh-terminal-bash` gains a validated `promptTailGraceMs` configuration field, default `0`. While a send has seen the prompt marker and its printable tail has not arrived, the silence bound becomes `idleSilenceMs + handoffGraceMs + promptTailGraceMs`; every other bound, wait reason, and code path is unchanged. The [persistent PTY readiness design](../feature/2026-07-16-persistent-pty-sessions.md) owns the tier ladder this bound extends. Zero reproduces the previous bound exactly, so an upgrade changes no deployment's behaviour. The persistent pwsh Loader-composition case sets 5000 ms, because the hosts whose stalls the field is for are exactly the ones that run it, and its assertion (at least six `stdin_read` settlements, no `inferred_idle`) then measures the controlled-prompt path instead of the host's delivery timing. `validateConfig` accepts zero for this field — the one numeric bound whose zero is a documented value — and rejects negative or fractional values.
`dsh-terminal-bash` gains a validated `promptTailGraceMs` configuration field, default `0`. While a send has seen the prompt marker and its printable tail has not arrived, the silence bound becomes `idleSilenceMs + handoffGraceMs + promptTailGraceMs`; every other bound, wait reason, and code path is unchanged. The [persistent PTY readiness design](../feature/2026-07-16-persistent-pty-sessions.md) owns the tier ladder this bound extends. Zero reproduces the previous bound exactly, so an upgrade changes no deployment's behaviour. The persistent pwsh Loader-composition case keeps the default: the self-hosted lane's degraded sends settle at the plain bound with the tolerance present or absent, so a nonzero value there would only lengthen a never-arriving-tail fallback from 3.3 s to 8.3 s per send while reporting a genuinely late tail as a slow pass instead of a named failure. `validateConfig` accepts zero for this field — the one numeric bound whose zero is a documented value — and rejects negative or fractional values.
## Alternatives considered
@@ -28,4 +28,4 @@ A deployment whose console renderer stalls keeps those sends on the exact path b
## Testing
`packages/terminal/terminal-bash/tests/session.spec.ts` pins every state with fake timers: with `promptTailGraceMs` set, a marker whose tail arrives after the plain bound stays pending and then settles `stdin_read`; a marker whose tail never arrives falls back to `inferred_idle` at the extended bound; a tail that arrived and was invalidated by later output keeps the plain bound; and with the field at zero the same delayed delivery settles `inferred_idle`. `packages/terminal/terminal-bash/tests/config.spec.ts` accepts zero and rejects negative or fractional values, and rejects a nonzero tolerance shorter than one `pollIntervalMs`. `packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts` carries the end-to-end evidence on native Windows: with every session's prompt tail withheld for four seconds the case passes with the configured tolerance — nine settles, eight `stdin_read` and the `exit` command's `session_exit`, in 33.4 s and 37.5 s — and fails with the tolerance patched to zero, where two sends settle `inferred_idle` with `promptSeen` true, `promptTextSeen` false, an empty tail and `idleFor` 3312-3316 ms.
`packages/terminal/terminal-bash/tests/session.spec.ts` pins every state with fake timers: with `promptTailGraceMs` set, a marker whose tail arrives after the plain bound stays pending and then settles `stdin_read`; a marker whose tail never arrives falls back to `inferred_idle` at the extended bound; a tail that arrived and was invalidated by later output keeps the plain bound; and with the field at zero the same delayed delivery settles `inferred_idle`. `packages/terminal/terminal-bash/tests/config.spec.ts` accepts zero and rejects negative or fractional values, and rejects a nonzero tolerance shorter than one `pollIntervalMs`. The end-to-end evidence on native Windows came from a guest-patched copy of `packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts` (Windows PowerShell 5.1, 2026-09-27): with every session's prompt tail withheld for four seconds and the tolerance at 5000 ms the case passed — nine settles, eight `stdin_read` and the `exit` command's `session_exit`, in 33.4 s and 37.5 s — and with the tolerance at zero two sends settled `inferred_idle` with `promptSeen` true, `promptTextSeen` false, an empty tail and `idleFor` 3312-3316 ms. The committed case runs with the default and prints a per-send readiness timeline on failure, so that state is named when it occurs rather than inferred from wall time.
@@ -6,11 +6,11 @@ Status: implemented
## Problem
自托管 lane 上的 Windows 会话在七次 send 中只有一到两次按受控提示符结算,其余都要支付静默层(2026-09-25/26,issue #2487)。精确的就绪证据是 OSC `133;D` 标记之后受控提示符的可打印尾部,而等待它的上界是 `idleSilenceMs + handoffGraceMs`。原生 Windows 探测表明该渲染以两个 pty 分块到达:先是标记本身,2–28 毫秒后是 5 字节的 `dsh> `(56 次渲染),任何提示符之后都没有可打印文本,输出中也没有终端查询。标记由 shell 自己的 prompt 函数写出、尾部由同一次渲染写出,因此尾部晚于上界到达意味着宿主机拖慢了这次投递,而不是提示符缺失。会话此前仍会按 `inferred_idle` 结算,每次这样的 send 让工具调用多付约三秒。
自托管 lane 上的 Windows 会话在七次 send 中只有一到两次按受控提示符结算,其余都要支付静默层(2026-09-25/26,issue #2487)。精确的就绪证据是 OSC `133;D` 标记之后受控提示符的可打印尾部,而等待它的上界是 `idleSilenceMs + handoffGraceMs`。原生 Windows 探测表明该渲染以两个 pty 分块到达:先是标记本身,2–28 毫秒后是 5 字节的 `dsh> `(Windows PowerShell 5.1 下 56 次渲染,pwsh 7.6.6 下同样是两分块渲染),任何提示符之后都没有可打印文本,输出中也没有终端查询。标记由 shell 自己的 prompt 函数写出、尾部由同一次渲染写出,因此尾部晚于上界到达意味着宿主机拖慢了这次投递,而不是提示符缺失。会话此前仍会按 `inferred_idle` 结算,每次这样的 send 让工具调用多付约三秒。该 lane 自身的失败不是这种状态:首个带着该字段的 master run(run 36326153388,2026-09-27 14:30Z)与其前一个 run(36309006133)同样耗时 20.8 秒,因此其退化的 send 是在宽限不起作用的情况下按普通上界结算的;[Windows lane 观测笔记](../testing/2026-09-27-observation-waits-on-observed-state.zh.md)记录了这项仍未关闭的调查。
## Decision
`dsh-terminal-bash` 新增一个经过校验的 `promptTailGraceMs` 配置字段,默认 `0`。当某次 send 已看到提示符标记而其可打印尾部尚未到达时,静默上界变为 `idleSilenceMs + handoffGraceMs + promptTailGraceMs`;其他上界、等待原因与代码路径均不变。该上界所扩展的层级阶梯由[持久 PTY 就绪设计](../feature/2026-07-16-persistent-pty-sessions.zh.md)拥有。零精确复现此前的上界,因此升级不改变任何部署的行为。持久 pwsh 的 Loader 组合用例设置 5000 毫秒,因为需要该字段的宿主机正是运行该用例的那些,而其断言(至少六次 `stdin_read` 结算、不含 `inferred_idle`)由此度量受控提示符路径,而不是宿主机的投递时序。`validateConfig` 允许该字段取零——这是唯一一个零为文档化取值的数值上界——并拒绝负数与小数。
`dsh-terminal-bash` 新增一个经过校验的 `promptTailGraceMs` 配置字段,默认 `0`。当某次 send 已看到提示符标记而其可打印尾部尚未到达时,静默上界变为 `idleSilenceMs + handoffGraceMs + promptTailGraceMs`;其他上界、等待原因与代码路径均不变。该上界所扩展的层级阶梯由[持久 PTY 就绪设计](../feature/2026-07-16-persistent-pty-sessions.zh.md)拥有。零精确复现此前的上界,因此升级不改变任何部署的行为。持久 pwsh 的 Loader 组合用例保持默认值:自托管 lane 上退化的 send 无论有没有该宽限都按普通上界结算,因此在那里设置非零值只会把尾部永不到达时的回退从每次 send 3.3 秒拉长到 8.3 秒,并把真正迟到的尾部报告成一次缓慢的通过,而不是一次点名状态的失败。`validateConfig` 允许该字段取零——这是唯一一个零为文档化取值的数值上界——并拒绝负数与小数。
## Alternatives considered
@@ -28,4 +28,4 @@ Status: implemented
## Testing
`packages/terminal/terminal-bash/tests/session.spec.ts` 用假定时器固定每一种状态:设置 `promptTailGraceMs` 时,尾部晚于普通上界到达的标记保持挂起,随后按 `stdin_read` 结算;尾部始终不到时在扩展上界处回落到 `inferred_idle`;尾部已到达但被后续输出失效时保持普通上界;字段为零时,同样的延迟投递按 `inferred_idle` 结算。`packages/terminal/terminal-bash/tests/config.spec.ts` 接受零、拒绝负数或小数,并拒绝非零但短于一个 `pollIntervalMs` 的宽限。`packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts` 承载原生 Windows 上的端到端证据:把每个 session 的提示符尾部扣留四秒时,配置了该宽限后用例通过——九次结算、八次 `stdin_read` 加 `exit` 命令的 `session_exit`,耗时 33.4 秒与 37.5 秒;把该宽限改为零后同一停摆失败,其中两次 send 以 `inferred_idle` 结算,`promptSeen` 为 true、`promptTextSeen` 为 false、尾部为空且 `idleFor` 为 3312–3316 毫秒。
`packages/terminal/terminal-bash/tests/session.spec.ts` 用假定时器固定每一种状态:设置 `promptTailGraceMs` 时,尾部晚于普通上界到达的标记保持挂起,随后按 `stdin_read` 结算;尾部始终不到时在扩展上界处回落到 `inferred_idle`;尾部已到达但被后续输出失效时保持普通上界;字段为零时,同样的延迟投递按 `inferred_idle` 结算。`packages/terminal/terminal-bash/tests/config.spec.ts` 接受零、拒绝负数或小数,并拒绝非零但短于一个 `pollIntervalMs` 的宽限。原生 Windows 上的端到端证据来自 guest 内打过补丁的 `packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts` 副本(Windows PowerShell 5.1,2026-09-27):把每个 session 的提示符尾部扣留四秒且宽限设为 5000 毫秒时用例通过——九次结算、八次 `stdin_read` 加 `exit` 命令的 `session_exit`,耗时 33.4 秒与 37.5 秒;宽限为零时两次 send 以 `inferred_idle` 结算,`promptSeen` 为 true、`promptTextSeen` 为 false、尾部为空且 `idleFor` 为 3312–3316 毫秒。提交的用例以默认值运行,并在失败时打印逐 send 的就绪时间线,因此该状态一旦出现就会被点名,而不是从墙钟时间推断。
@@ -9,8 +9,8 @@
en: 270b015afc8de8ac
zh: 65aeb1e270d19a27
/agent-note-windows-lane-observations-wait-on-the-state-they-read/decision:
en: 479cb25421102304
zh: 9e23396728001e2c
en: 55a0bcab15f38620
zh: 677545442a19c7dc
/agent-note-windows-lane-observations-wait-on-the-state-they-read/alternatives-considered:
en: 00e59c561085e081
zh: 4f6ac4dfc3259f58
@@ -18,5 +18,5 @@
en: 46517270dd3b22b1
zh: 94e300066237cece
/agent-note-windows-lane-observations-wait-on-the-state-they-read/deferred:
en: 18dc81f98375fb04
zh: e30413cd3d201b80
en: 8e182739fdf90baf
zh: 5f93f7b7d9518764
@@ -16,7 +16,7 @@ Two self-hosted Windows lane cases observed state through a wall-clock window in
`observingChild` stays in flight until the test has read the run record, so the read cannot race the run's end, and its bounded wait starts at the mocked launcher's hand-over instead of at test start: the recorded run is one atomic write that follows the launch, so the bound only has to cover that write. `RECORD_WAIT_MS` (2 s) is deliberately below the case budget, so a record that never appears reports as the assertion that names it rather than as a runner timeout. Both the repair-install case and the single-run case hand the child over through the same `spawned` hook.
The loader-composition settle-reason assertion carries `JSON.stringify(settleReasons)` as its failure message. The threshold and the assertions are unchanged.
The loader-composition settle-reason assertions carry the recorded reasons and a per-send readiness timeline in their failure message: every decoded pty chunk with the sanitizer's marker verdict and prompt tail, every foreground poll result, every input write, each send's settle reason and elapsed time, the session's prompt evidence replayed from those chunks, and the host, shell, PSReadLine, and console-host versions. `onTestFailed` prints the same timeline when the runner's budget ends the case before the assertions. The threshold and the assertions are unchanged.
## Alternatives considered
@@ -34,4 +34,6 @@ Both plugin-manager record cases now observe the record while the run is in flig
## Deferred
The loader-composition failure of 2026-09-25/26 is an environment-sensitive readiness window, not a product logic error, and the product now owns a documented tolerance for it: the [prompt tail grace decision](../bug-fix/2026-09-27-pwsh-prompt-tail-grace.md). On Windows `isStdinWaiting` returns false and `foregroundPgid` returns the shell pid, so `stdin_read` can only come from the controlled-prompt tail. A native Windows probe (Windows 11 ARM64 guest, 8 vCPU, with the readiness probe enabled) shows the fast path is deterministic when delivery is normal: every prompt render is the OSC marker alone in one pty chunk followed by a five-byte `dsh> ` chunk 2-28 ms later (56 renders), nothing printable follows any prompt, the output carries no terminal queries, and 21 runs (baseline, six CPU burners, emulated x64, four concurrent pty-heavy instances, and Windows PowerShell 5.1 as the shell) settled all seven sends on the prompt, six `stdin_read` plus the `exit` command's `session_exit`. Withholding each session's prompt tail for four seconds reproduces the reported failure exactly: `expected 4 to be greater than or equal to 6` with `["inferred_idle","stdin_read","stdin_read","stdin_read","stdin_read","session_exit","inferred_idle"]`, the degraded settles carrying `promptSeen` true, `promptTextSeen` false, an empty tail and `idleFor` 3301/3313 ms (exactly the configured bound), 22.1/21.9 s against 17.5/20.9 s in CI, and every output assertion still passing. The CI trigger itself was not reproduced locally, so this case keeps its assertion and supplies `promptTailGraceMs` in its composition: it measures the controlled-prompt path rather than the host's delivery timing, and it still fails when no prompt marker appears at all.
The loader-composition failure on the self-hosted Windows lane (2026-09-25..27, issue #2487) remains open, and its mechanism is not a stalled prompt tail. The master run before the [prompt tail grace](../bug-fix/2026-09-27-pwsh-prompt-tail-grace.md) landed (run 36309006133, 2026-09-27 09:19Z) and the first run carrying it with `promptTailGraceMs: 5000` in this composition (run 36326153388, 14:30Z, reasons `["stdin_read","inferred_idle","inferred_idle","inferred_idle","inferred_idle","session_exit","inferred_idle"]`) both took 20.8 s, so the degraded sends settled at the plain `idleSilenceMs + handoffGraceMs` bound: either no marker was seen, or a marker was seen and its tail was invalidated by later printable text — the two states the tolerance does not cover. The foreground comparison is not a candidate on Windows: `WindowsProcessInspector.foregroundPgid` returns the shell pid unconditionally and `isStdinWaiting` returns false, so `shellPgid` always matches and `stdin_read` can only come from the controlled-prompt tail. The composition therefore keeps the field at its product default of `0`, and the failure message's timeline names the state directly the next time the lane fails; the 2026-09-27 12:51Z run (36320394583) instead hit the 120 s case budget before any assertion, which the same print covers.
Native evidence with pwsh 7.6.6 and PSReadLine 2.4.5 on Windows 11 25H2 (conhost 10.0.26100.1; the probes the tail-grace note cites ran under Windows PowerShell 5.1, the guest's only preinstalled shell): the case settles every send on the prompt at baseline, under eight CPU burners plus disk churn, under emulated x64 Node, under `vitest run --coverage --maxWorkers=1`, and with a 12-row viewport that scrolls from the second command, each prompt arriving as one in-order marker chunk followed by the five-byte tail. With an 8-row, 60-column viewport ConPTY re-emits the stored `133;D` mark inside repaint frames — five markers in one send, one followed by repainted row text (`\x07\e[Hdsh> Write-Output …`) — which leaves a tail that is not a prefix of the controlled prompt; on that console host the real prompt's marker still arrived last and the send settled `stdin_read`. That repaint path is the leading hypothesis for the lane, whose Windows build and console-host version are unknown (the job logs carry neither and the pool has no dispatchable job); the failure message records `os.release()`, `os.version()`, the pwsh and PSReadLine versions, and `conhost.exe`'s file version, and `dsh-subprocess-local` spawns node-pty without `useConptyDll`, so the system console host is the one in play. The pid `0` those probes also exposed on Windows is a separate defect, tracked by issue #5297.
@@ -16,7 +16,7 @@ Status: implemented
`observingChild` 会保持该 run 在进行中,直到测试读到 run 记录,因此读取不可能与 run 结束竞争;其有界等待从被 mock 的启动器交接处开始,而不是从用例开始处开始:被记录的 run 只是紧随启动之后的一次原子写入,因此等待上界只需覆盖这次写入。`RECORD_WAIT_MS`(2 秒)刻意低于用例预算,于是一条始终没有出现的记录会以指名它的断言报告,而不是以 runner 超时报告。修复安装用例与单 run 用例都通过同一个 `spawned` 钩子交接子进程。
loader-composition 的结算层级断言把 `JSON.stringify(settleReasons)` 作为失败信息。阈值与断言本身不变。
loader-composition 的结算层级断言把记录到的结算原因与一份逐 send 的就绪时间线放进失败信息:每个解码后的 pty 分块及 sanitizer 对它的标记判定与提示符尾部、每次前台轮询的结果、每次输入写入、每次 send 的结算原因与耗时、由这些分块回放出的会话提示符证据,以及宿主机、shell、PSReadLine 与控制台宿主的版本。当 runner 预算在断言之前结束用例时,`onTestFailed` 打印同一份时间线。阈值与断言本身不变。
## Alternatives considered
@@ -34,4 +34,6 @@ loader-composition 的结算层级断言把 `JSON.stringify(settleReasons)` 作
## Deferred
loader-composition 于 2026-09-25/26 的失败是一个对投递时序敏感的就绪窗口,而不是 product 逻辑错误;product 现在为它拥有一个文档化的容忍度:[提示符尾部宽限决策](../bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md)。在 Windows 上 `isStdinWaiting` 返回 false、`foregroundPgid` 返回 shell 自身的 pid,因此 `stdin_read` 只能来自受控提示符尾部。原生 Windows 探测(Windows 11 ARM64 guest,8 vCPU,启用就绪探测)表明只要投递正常,快路径就是确定的:每次提示符渲染都是 OSC 标记独占一个 pty 分块,紧随其后的下一个分块是 5 字节的 `dsh> `,间隔 2–28 毫秒(56 次渲染),任何提示符之后都没有可打印文本,输出中也没有终端查询;21 次运行(基线、6 个 CPU burner、模拟 x64、4 个并发 pty 实例、以及以 Windows PowerShell 5.1 作为 shell)全部七次 send 都按提示符结算——六次 `stdin_read` 加 `exit` 命令的 `session_exit`。把每个 session 的提示符尾部扣留 4 秒可以精确复现上报的失败:`expected 4 to be greater than or equal to 6`,`settleReasons` 为 `["inferred_idle","stdin_read","stdin_read","stdin_read","stdin_read","session_exit","inferred_idle"]`,退化的结算带着 `promptSeen` 为 true、`promptTextSeen` 为 false、空尾部与 `idleFor` 3301/3313 毫秒(正是配置的上界),耗时 22.1/21.9 秒对照 CI 的 17.5/20.9 秒,且所有输出断言仍然通过。CI 的触发条件本身未能在本地复现,因此该用例保留其断言并在组合中提供 `promptTailGraceMs`:它度量受控提示符路径而不是宿主机的投递时序,且在完全没有提示符标记时仍然失败。
自托管 Windows lane 上 loader-composition 的失败(2026-09-25..27,issue #2487)仍未关闭,其机制不是提示符尾部停摆。[提示符尾部宽限](../bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md)合入前的 master run(run 36309006133,2026-09-27 09:19Z)与首个带着该字段、且本组合设置了 `promptTailGraceMs: 5000` 的 run(run 36326153388,14:30Z,结算原因为 `["stdin_read","inferred_idle","inferred_idle","inferred_idle","inferred_idle","session_exit","inferred_idle"]`)都耗时 20.8 秒,因此退化的 send 是按普通的 `idleSilenceMs + handoffGraceMs` 上界结算的:要么根本没看到标记,要么看到了标记但其尾部被随后的可打印文本失效——这正是该宽限不覆盖的两种状态。前台比较在 Windows 上不是候选:`WindowsProcessInspector.foregroundPgid` 无条件返回 shell pid、`isStdinWaiting` 返回 false,因此 `shellPgid` 总是匹配,`stdin_read` 只能来自受控提示符尾部。于是该组合把字段保持在 product 默认值 `0`,下一次该 lane 失败时,失败信息里的时间线会直接点名所处的状态;2026-09-27 12:51Z 的 run(36320394583)则是在任何断言之前就撞上 120 秒的用例预算,同一份打印也覆盖这条路径。
在 Windows 11 25H2(conhost 10.0.26100.1)上以 pwsh 7.6.6 与 PSReadLine 2.4.5 取得的原生证据(尾部宽限笔记所引用的探测运行在 Windows PowerShell 5.1 之下,那是 guest 唯一预装的 shell):基线、8 个 CPU burner 加磁盘反复读写、模拟 x64 Node、`vitest run --coverage --maxWorkers=1`、以及从第二条命令起就滚动的 12 行视口下,用例的每次 send 都按提示符结算,每个提示符都是一个按序到达的标记分块紧跟 5 字节尾部。在 8 行 60 列的视口下,ConPTY 会在重绘帧内重新发出已存储的 `133;D` 标记——一次 send 内出现五个标记,其中一个后面紧跟重绘的行文本(`\x07\e[Hdsh> Write-Output …`)——这使尾部不再是受控提示符的前缀;在该控制台宿主上,真正提示符的标记仍然最后到达,因此该 send 仍按 `stdin_read` 结算。这条重绘路径是该 lane 的首要假设,而该 lane 的 Windows 版本与控制台宿主版本未知(job 日志两者都没有,该 pool 也没有可手动触发的 job);失败信息会记录 `os.release()`、`os.version()`、pwsh 与 PSReadLine 版本以及 `conhost.exe` 的文件版本,而 `dsh-subprocess-local` 启动 node-pty 时未设置 `useConptyDll`,因此起作用的是系统控制台宿主。这些探测同时暴露的 Windows 上 pid 为 `0` 的问题是另一个缺陷,由 issue #5297 跟踪。
@@ -1,9 +1,9 @@
import { spawnSync } from 'node:child_process'
import { mkdtemp, realpath, rm, writeFile } from 'node:fs/promises'
import { tmpdir } from 'node:os'
import { release, tmpdir, version } from 'node:os'
import { join } from 'node:path'
import { pathToFileURL } from 'node:url'
import { afterEach, describe, expect, it, vi } from 'vitest'
import { afterEach, describe, expect, it, onTestFailed, vi } from 'vitest'
import { Context } from '@deepseek-ai/cordis'
import Loader from '@deepseek-ai/cordis-plugin-loader'
import Include from '@deepseek-ai/cordis-plugin-include'
@@ -24,16 +24,44 @@ import SystemPrompt from '@deepseek-ai/dsh-system-prompt'
import ToolRegistry from '@deepseek-ai/dsh-tools'
import * as ToolPwshPersistent from '@deepseek-ai/dsh-tool-pwsh-persistent'
import { unsupportedInbox } from '@deepseek-ai/dsh-agent-loop-testkit'
import { ReadinessTimeline, TIMELINE_HEADER } from './readiness-timeline.ts'
const pwshPath = resolvePwshPath()
const hasPwsh = spawnSync(
resolvePwshPath(), ['-NoLogo', '-NoProfile', '-NonInteractive', '-Command', '$true'],
pwshPath, ['-NoLogo', '-NoProfile', '-NonInteractive', '-Command', '$true'],
{ encoding: 'utf8' },
).status === 0
// Shell and console-host versions for a failure message: the Windows console host, not this
// process, decides how the prompt marker and its tail reach the session, and its build on the
// self-hosted pool is unknown.
const HOST_FACTS_COMMAND = [
'"pwsh $($PSVersionTable.PSVersion) PSReadLine $((Get-Module PSReadLine -ListAvailable | Sort-Object Version -Descending | Select-Object -First 1).Version)"',
'if ($env:OS -eq \'Windows_NT\') { "conhost $((Get-Item (Join-Path $env:SystemRoot \'System32\\conhost.exe\')).VersionInfo.FileVersion)" }',
].join('; ')
function hostFacts(): string {
const probe = spawnSync(
pwshPath, ['-NoLogo', '-NoProfile', '-NonInteractive', '-Command', HOST_FACTS_COMMAND],
{ encoding: 'utf8', timeout: 30_000 },
)
const shell = probe.status === 0
? probe.stdout.trim().split(/\r?\n/).join('; ')
: `version probe failed: ${probe.error?.message ?? probe.stderr.trim()}`
return [
`host: ${process.platform} ${process.arch} ${release()} (${version()}); node ${process.version}`,
`shell: ${pwshPath}; ${shell}`,
// dsh-subprocess-local spawns node-pty without useConptyDll, so the system console host,
// not the OpenConsole build node-pty bundles, renders every session.
'conpty: system conhost',
].join('\n')
}
let root: string | undefined
let context: Context | undefined
afterEach(async () => {
vi.restoreAllMocks()
await context?.fiber.dispose()
context = undefined
if (root !== undefined) await rm(root, { recursive: true, force: true })
@@ -100,12 +128,9 @@ describe.skipIf(!hasPwsh)('persistent pwsh through a real cordis.yml Loader comp
// send's wait reason, which pins the controlled-prompt fast path directly
// instead of relying on how long silence would take to settle.
' handoffGraceMs: 300',
// The self-hosted Windows pool stalls the console renderer for seconds (issue 2487): the
// OSC marker reaches the session while the five-byte prompt tail that follows it does not
// arrive until the plain silence bound has passed, and every such send would otherwise
// settle as inferred_idle. The tolerance keeps those sends on the controlled-prompt path
// this case pins, without letting a missing prompt (no marker at all) escape the silence tier.
' promptTailGraceMs: 5000',
// promptTailGraceMs keeps its product default (0): the self-hosted Windows failures of
// 2026-09-25..27 settled at the plain silence bound with the tolerance present and absent
// alike, so it never applied there and would only lengthen a never-arriving-tail fallback.
' scrollbackLines: 20000',
// The first call pays the full pwsh cold-start latency (spawn + .NET +
// PSReadLine + Defender) inside the tool deadline; a 60s bound on the
@@ -153,10 +178,23 @@ describe.skipIf(!hasPwsh)('persistent pwsh through a real cordis.yml Loader comp
const startSend = terminals.startSend.bind(terminals)
// A send that lost the controlled-prompt fast path settles as inferred_idle
// after the silence tier, so recording why every send settled detects that
// regression immediately instead of through accumulated wall-clock.
// regression immediately instead of through accumulated wall-clock. The
// timeline records what the session observed on the way there — every pty
// chunk's prompt verdict, every foreground poll, every write — because the
// reason alone cannot say whether the marker was missing, its tail was
// invalidated by later output, or the foreground comparison failed.
const timeline = new ReadinessTimeline(hostFacts)
timeline.observeSanitizer()
const spawnTerminal = context.subprocess.spawnTerminal.bind(context.subprocess)
vi.spyOn(context.subprocess, 'spawnTerminal').mockImplementation(async (spec) => {
const handle = await spawnTerminal(spec)
timeline.observeTerminal(handle)
return handle
})
const settleReasons: TerminalWaitReason[] = []
vi.spyOn(terminals, 'startSend').mockImplementation((owner, id, request) => {
const operation = startSend(owner, id, request)
timeline.track(operation, request)
void operation.done.then(
(settled) => { settleReasons.push(settled.waitReason) },
// A rejected send is the tool's error path, not a settle reason.
@@ -164,16 +202,25 @@ describe.skipIf(!hasPwsh)('persistent pwsh through a real cordis.yml Loader comp
)
return operation
})
// The runner's timeout never reaches the assertions below; print the timeline
// for that path too, unless a failed assertion already carries it.
onTestFailed(({ task }) => {
if (task.result?.errors?.some(error => error.message?.includes(TIMELINE_HEADER))) return
console.error(timeline.format())
})
const owner = await agent(context, root)
const signal = new AbortController().signal
const execute = (id: string, command: string) => context!.tools.execute({
signal,
callId: ToolCallId(id),
name: 'pwsh',
arguments: { command },
agent: owner,
})
const execute = (id: string, command: string) => {
timeline.label(id)
return context!.tools.execute({
signal,
callId: ToolCallId(id),
name: 'pwsh',
arguments: { command },
agent: owner,
})
}
expect(context.tools.schemas().map(schema => schema.name)).toEqual(['pwsh'])
await execute('state', '$env:KEEP = "loader"; New-Item -ItemType Directory -Force -Path nested | Out-Null; Set-Location nested')
@@ -204,11 +251,17 @@ describe.skipIf(!hasPwsh)('persistent pwsh through a real cordis.yml Loader comp
expect(text(await execute('after-exit', 'Write-Output "$PWD"'))).toBe(root)
// Six commands settle on the controlled prompt; no send may fall back to the
// silence tier, which is the 3.5 s-per-call degradation this suite pins. The
// silence tier, which is the 3.3 s-per-call degradation this suite pins. The
// counts alone do not say which tier settled which send, so every reason the
// run recorded rides in the failure message (2026-09-25 self-hosted Windows
// lane reported one to two stdin_read settlements across three runs).
expect(settleReasons.filter(reason => reason === 'stdin_read').length, JSON.stringify(settleReasons)).toBeGreaterThanOrEqual(6)
expect(settleReasons).not.toContain('inferred_idle')
// run recorded and the per-send timeline ride in the failure message (the
// self-hosted Windows lane reported one to two stdin_read settlements per
// run on 2026-09-25..27, every other send at the plain silence bound). The
// message is built only when an assertion is about to fail: formatting runs
// the host-facts shell probe, which a passing run must not pay for.
const stdinReads = settleReasons.filter(reason => reason === 'stdin_read').length
const degraded = stdinReads < 6 || settleReasons.includes('inferred_idle')
const failure = degraded ? `${JSON.stringify(settleReasons)}\n${timeline.format()}` : ''
expect(stdinReads, failure).toBeGreaterThanOrEqual(6)
expect(settleReasons, failure).not.toContain('inferred_idle')
}, 120_000)
})
@@ -0,0 +1,136 @@
import { Readable } from 'node:stream'
import { afterEach, describe, expect, it, vi } from 'vitest'
import type { SubprocessOutcome, SubprocessTerminalForeground, SubprocessTerminalHandle } from '@deepseek-ai/dsh-subprocess'
import type { TerminalSendOperation, TerminalSendResult } from '@deepseek-ai/dsh-terminal'
import { CONTROLLED_PROMPT, TerminalSanitizer } from '@deepseek-ai/dsh-terminal-bash/src/sanitize.ts'
import { ReadinessTimeline, TIMELINE_HEADER, replayPromptEvidence } from './readiness-timeline.ts'
const MARKER = '\x1b]133;D;0\x07'
afterEach(() => {
vi.restoreAllMocks()
})
interface FakeTerminalState {
foreground: SubprocessTerminalForeground | undefined
inspectError: Error | undefined
}
function fakeTerminal(pid: number): { handle: SubprocessTerminalHandle; state: FakeTerminalState; writes: string[] } {
const state: FakeTerminalState = { foreground: { processGroupId: pid, inputWaiting: false }, inspectError: undefined }
const writes: string[] = []
const handle: SubprocessTerminalHandle = {
pid,
output: new Readable({ read() {} }),
done: new Promise<SubprocessOutcome>(() => {}),
async write(data: string) { writes.push(data) },
async resize() {},
async inspectForeground() {
if (state.inspectError !== undefined) throw state.inspectError
return state.foreground
},
async inspectActivity() { return { state: 'unknown' as const, revision: 0 } },
async signalForeground() { return pid },
async terminate() {},
}
return { handle, state, writes }
}
function fakeSend(): { operation: TerminalSendOperation; settle: (waitReason: TerminalSendResult['waitReason']) => void; reject: () => void } {
const resolvers = Promise.withResolvers<TerminalSendResult>()
const operation: TerminalSendOperation = {
done: resolvers.promise,
cancel: () => false,
readOutput: () => ({ delta: '', truncated: false }),
}
return {
operation,
settle: (waitReason) => { resolvers.resolve({ viewport: '', waitReason, sessionStatus: { kind: 'running' }, truncated: false }) },
reject: () => { resolvers.reject(new Error('inspection failed')) },
}
}
// Let the operation's `done` continuation record the window's end before the next step.
const settled = (): Promise<void> => new Promise(resolve => setTimeout(resolve, 0))
describe('replayPromptEvidence', () => {
it('mirrors the session rule: exact tail, invalidated tail, pending prefix, absent marker', () => {
expect(replayPromptEvidence([{ prompt: true, promptTail: '' }, { prompt: false, promptTail: CONTROLLED_PROMPT }]))
.toEqual({ promptSeen: true, promptTail: CONTROLLED_PROMPT, promptTextSeen: true })
expect(replayPromptEvidence([{ prompt: true, promptTail: '' }, { prompt: false, promptTail: `${CONTROLLED_PROMPT}Write-Output` }]))
.toEqual({ promptSeen: true, promptTail: `${CONTROLLED_PROMPT}\0`, promptTextSeen: false })
expect(replayPromptEvidence([{ prompt: true, promptTail: '' }, { prompt: false, promptTail: 'dsh' }]))
.toEqual({ promptSeen: true, promptTail: 'dsh', promptTextSeen: false })
expect(replayPromptEvidence([{ prompt: false, promptTail: undefined }, { prompt: false, promptTail: 'dsh> ' }]))
.toEqual({ promptSeen: false, promptTail: '', promptTextSeen: false })
// A later marker restarts the tail, as the session's onData does.
expect(replayPromptEvidence([
{ prompt: true, promptTail: 'stale text' },
{ prompt: true, promptTail: '' },
{ prompt: false, promptTail: CONTROLLED_PROMPT },
])).toEqual({ promptSeen: true, promptTail: CONTROLLED_PROMPT, promptTextSeen: true })
})
})
describe('ReadinessTimeline', () => {
it('keeps sends that hand over within one millisecond apart and replays from the input write only', async () => {
const timeline = new ReadinessTimeline(() => 'host: fake')
timeline.observeSanitizer()
const terminal = fakeTerminal(4242)
timeline.observeTerminal(terminal.handle)
const sanitizer = new TerminalSanitizer(1024)
// Send A: input write, a cursor-position query answered by the emulator (a reply write that
// must not reset the evidence), then the marker and tail, then the settling poll.
timeline.label('a')
const a = fakeSend()
timeline.track(a.operation, { text: 'echo a', submit: true })
await terminal.handle.write('echo a\r')
sanitizer.push('a-output\r\n\x1b[6n')
await terminal.handle.write('\x1b[1;1R')
sanitizer.push(MARKER)
sanitizer.push(CONTROLLED_PROMPT)
await terminal.handle.inspectForeground()
a.settle('stdin_read')
await settled()
// Send B starts in the same millisecond as A's settle and never sees a marker.
timeline.label('b')
const b = fakeSend()
timeline.track(b.operation, { text: 'echo b', submit: true })
await terminal.handle.write('echo b\r')
sanitizer.push('b-output\r\n')
terminal.state.inspectError = new Error('snapshot unreadable')
await expect(terminal.handle.inspectForeground()).rejects.toThrow('snapshot unreadable')
b.reject()
await settled()
const text = timeline.format()
expect(text.startsWith(`${TIMELINE_HEADER}\nhost: fake\n`)).toBe(true)
const [, windowA = '', windowB = ''] = text.split(/^(?=#\d )/m)
expect(windowA).toMatch(/^#1 a \(from \+\d+ ms\) → stdin_read after \d+ ms\n/)
expect(windowA).toContain('write s0 7 units (input)')
expect(windowA).toContain('write s0 6 units (reply)')
expect(windowA).toContain('replayed evidence at settle: promptSeen=true promptTail="dsh> " promptTextSeen=true')
expect(windowA).not.toContain('b-output')
expect(windowB).toMatch(/^#2 b \(from \+\d+ ms\) → rejected after \d+ ms\n/)
expect(windowB).toContain('polls 1')
expect(windowB).toContain('threw snapshot unreadable')
expect(windowB).toContain('replayed evidence at settle: promptSeen=false promptTail="" promptTextSeen=false')
expect(windowB).not.toContain('a-output')
})
it('shows every marker-bearing chunk, bounds the rest, and escapes control bytes', () => {
const timeline = new ReadinessTimeline()
timeline.observeSanitizer()
const sanitizer = new TerminalSanitizer(1024)
for (let line = 1; line <= 30; line += 1) sanitizer.push(`${line}\r\n`)
sanitizer.push(`\x1b[H\x1b[K${MARKER}`)
sanitizer.push(CONTROLLED_PROMPT)
const text = timeline.format()
expect(text).toContain('chunks 32 (1 with a prompt marker)')
expect(text).toContain('… 24 chunks elided …')
expect(text).toContain('marker=YES tail="" "\\e[H\\e[K\\e]133;D;0\\x07"')
expect(text).not.toMatch(/[\x00-\x08\x0b-\x1f]/)
})
})
@@ -0,0 +1,354 @@
/**
* Per-send readiness timeline for the persistent pwsh Loader-composition case: every
* decoded pty chunk as the session's sanitizer saw it, every foreground poll result,
* every input write, and how each send settled, formatted for a failure message so a
* lost controlled-prompt fast path names the state that lost it.
*/
import type { SubprocessTerminalForeground, SubprocessTerminalHandle } from '@deepseek-ai/dsh-subprocess'
import type { TerminalSendOperation, TerminalSendRequest, TerminalWaitReason } from '@deepseek-ai/dsh-terminal'
import { CONTROLLED_PROMPT, TerminalSanitizer } from '@deepseek-ai/dsh-terminal-bash/src/sanitize.ts'
import type { SanitizedChunk } from '@deepseek-ai/dsh-terminal-bash/src/sanitize.ts'
import { vi } from 'vitest'
/** First line of the formatted timeline; a failure message carrying it needs no second print. */
export const TIMELINE_HEADER = 'readiness timeline (ms since the case started; s<n> = terminal session in spawn order)'
interface ChunkEvent {
kind: 'chunk'
seq: number
at: number
session: number
units: number
sample: string
prompt: boolean
promptTail: string | undefined
textLength: number
}
interface PollEvent {
kind: 'poll'
seq: number
at: number
session: number
foreground: string
}
interface WriteEvent {
kind: 'write'
seq: number
at: number
session: number
units: number
/** Whether the bytes are the tracked send's own input; other writes are terminal-protocol replies. */
input: boolean
}
interface SpawnEvent {
kind: 'spawn'
seq: number
at: number
session: number
pid: number
}
type TimelineEvent = ChunkEvent | PollEvent | WriteEvent | SpawnEvent
/** An event before the timeline stamps its sequence number and time. */
type RecordedEvent = {
[K in TimelineEvent['kind']]: Omit<Extract<TimelineEvent, { kind: K }>, 'seq' | 'at'>
}[TimelineEvent['kind']]
interface SendWindow {
label: string
/** The exact bytes the session writes for this send; a matching write is the evidence reset. */
input: string
startedAt: number
startSeq: number
settledAt: number | undefined
endSeq: number | undefined
outcome: TerminalWaitReason | 'rejected' | 'pending'
}
/** Replayed prompt evidence for one send window. */
export interface PromptEvidence {
promptSeen: boolean
promptTail: string
promptTextSeen: boolean
}
/** A chunk as the replay needs it: the sanitizer's verdict for one decoded pty chunk. */
export interface ReplayChunk {
prompt: boolean
promptTail: string | undefined
}
const SAMPLE_UNITS = 100
const SHOWN_HEAD_CHUNKS = 2
const SHOWN_TAIL_CHUNKS = 6
function escapeControl(text: string): string {
return text.replace(/[\\\x00-\x1f\x7f]/g, (char) => {
switch (char) {
case '\\': return '\\\\'
case '\n': return '\\n'
case '\r': return '\\r'
case '\x1b': return '\\e'
default: return `\\x${char.charCodeAt(0).toString(16).padStart(2, '0')}`
}
})
}
function sample(text: string): string {
if (text.length <= 2 * SAMPLE_UNITS) return escapeControl(text)
return `${escapeControl(text.slice(0, SAMPLE_UNITS))}…(+${text.length - 2 * SAMPLE_UNITS} units)…${escapeControl(text.slice(-SAMPLE_UNITS))}`
}
const TAIL_UNITS = 24
/** Quote an already-escaped sample. */
function quoted(escaped: string): string {
return `"${escaped}"`
}
/** The session keeps at most one unit past the controlled prompt, so a short prefix names the tail. */
function tail(text: string | undefined): string {
if (text === undefined) return '-'
if (text.length <= TAIL_UNITS) return quoted(escapeControl(text))
return `"${escapeControl(text.slice(0, TAIL_UNITS))}…(+${text.length - TAIL_UNITS} units)"`
}
/**
* The session's own prompt-tail rule replayed over one window's chunks: a marker starts an
* empty tail, later printable text extends it up to one unit past the controlled prompt, and
* the exact prompt text is the fast-path evidence. Mirrors `LocalPtySession.onData`.
* @param chunks - the sanitizer verdicts since the send's input write, in delivery order.
* @returns The evidence the session holds after the last chunk.
*/
export function replayPromptEvidence(chunks: readonly ReplayChunk[]): PromptEvidence {
let promptSeen = false
let promptTail = ''
for (const chunk of chunks) {
if (chunk.prompt) {
promptSeen = true
promptTail = ''
}
if (promptSeen && chunk.promptTail !== undefined) {
const remaining = Math.max(0, CONTROLLED_PROMPT.length + 1 - promptTail.length)
promptTail += chunk.promptTail.slice(0, remaining)
if (chunk.promptTail.length > remaining) promptTail = `${CONTROLLED_PROMPT}\0`
}
}
return { promptSeen, promptTail, promptTextSeen: promptTail === CONTROLLED_PROMPT }
}
/**
* Records one Loader-composition case's terminal traffic and formats it per send. Sessions are
* sequential in that case (a fresh terminal spawns only after the previous shell exited), so a
* sanitizer is attributed to the most recently spawned terminal on its first chunk.
*/
export class ReadinessTimeline {
private readonly origin = performance.now()
private hostFactsText: string | undefined
private seq = 0
/**
* @param hostFacts - host, shell, and console facts for the header; evaluated once, on the
* first `format()` call, so a passing case never pays for a shell probe.
*/
constructor(private readonly hostFacts: () => string = () => '') {}
private readonly events: TimelineEvent[] = []
private readonly sends: SendWindow[] = []
private readonly sanitizers = new WeakMap<TerminalSanitizer, number>()
private spawnCount = 0
private currentLabel: string | undefined
private labelUses = 0
private now(): number {
return Math.round(performance.now() - this.origin)
}
private push(event: RecordedEvent): void {
this.events.push({ ...event, seq: this.seq, at: this.now() })
this.seq += 1
}
/** Spy on every sanitizer's `push` so each decoded chunk is recorded with its prompt verdict. */
observeSanitizer(): void {
// oxlint-disable-next-line typescript/unbound-method -- the spy body re-binds it to each sanitizer through `call`.
const original = TerminalSanitizer.prototype.push
const record = (sanitizer: TerminalSanitizer, chunk: string, result: SanitizedChunk): void => {
this.recordChunk(sanitizer, chunk, result)
}
vi.spyOn(TerminalSanitizer.prototype, 'push').mockImplementation(function (this: TerminalSanitizer, chunk: string): SanitizedChunk {
const result = original.call(this, chunk)
record(this, chunk, result)
return result
})
}
private recordChunk(sanitizer: TerminalSanitizer, chunk: string, result: SanitizedChunk): void {
let session = this.sanitizers.get(sanitizer)
if (session === undefined) {
session = Math.max(0, this.spawnCount - 1)
this.sanitizers.set(sanitizer, session)
}
this.push({
kind: 'chunk',
session,
units: chunk.length,
sample: sample(chunk),
prompt: result.prompt,
promptTail: result.promptTail,
textLength: result.text.length,
})
}
/**
* Wrap one spawned terminal so its writes and foreground polls are recorded.
* @param handle - the provider handle the session will drive.
*/
observeTerminal(handle: SubprocessTerminalHandle): void {
const session = this.spawnCount
this.spawnCount += 1
this.push({ kind: 'spawn', session, pid: handle.pid })
const inspectForeground = handle.inspectForeground.bind(handle)
vi.spyOn(handle, 'inspectForeground').mockImplementation(async (): Promise<SubprocessTerminalForeground | undefined> => {
let foreground: SubprocessTerminalForeground | undefined
try {
foreground = await inspectForeground()
} catch (error: unknown) {
// A throwing inspection rejects the send; the window records what it threw.
this.push({ kind: 'poll', session, foreground: `threw ${error instanceof Error ? error.message : String(error)}` })
throw error
}
this.push({ kind: 'poll', session, foreground: foreground === undefined ? 'undefined' : JSON.stringify(foreground) })
return foreground
})
const write = handle.write.bind(handle)
vi.spyOn(handle, 'write').mockImplementation(async (data: string): Promise<void> => {
const active = this.sends.at(-1)
const input = active !== undefined && active.endSeq === undefined && data === active.input
this.push({ kind: 'write', session, units: data.length, input })
await write(data)
})
}
/**
* Name every send tracked until the next label; a second send under one label reads `label/2`.
* @param label - the tool call id the sends belong to.
*/
label(label: string): void {
this.currentLabel = label
this.labelUses = 0
}
/**
* Open a send window and close it when the operation settles or rejects. Windows are bounded
* by event sequence numbers, so two sends that hand over within one millisecond keep their
* own events; the millisecond stamps are for display only.
* @param operation - the send returned by `terminals.startSend`.
* @param request - the request that send carries; its bytes identify the input write.
*/
track(operation: TerminalSendOperation, request: TerminalSendRequest): void {
this.labelUses += 1
const label = this.currentLabel === undefined
? `send#${this.sends.length + 1}`
: this.labelUses === 1 ? this.currentLabel : `${this.currentLabel}/${this.labelUses}`
const window: SendWindow = {
label,
input: `${request.text}${request.submit ? '\r' : ''}`,
startedAt: this.now(),
startSeq: this.seq,
settledAt: undefined,
endSeq: undefined,
outcome: 'pending',
}
this.sends.push(window)
const close = (outcome: SendWindow['outcome']): void => {
window.settledAt = this.now()
window.endSeq = this.seq
window.outcome = outcome
}
void operation.done.then((settled) => { close(settled.waitReason) }, () => { close('rejected') })
}
/**
* Render every send window plus the traffic between windows (startup, restarts, late output).
* @returns Multi-line text bounded per window: every prompt-bearing chunk, the first and last
* chunks, poll totals by foreground value, and the replayed prompt evidence.
*/
format(): string {
this.hostFactsText ??= this.hostFacts()
const lines: string[] = [TIMELINE_HEADER, ...this.hostFactsText.length > 0 ? [this.hostFactsText] : []]
let cursor = 0
let cursorAt = 0
const windows: { title: string; from: number; fromAt: number; to: number; send: SendWindow | undefined }[] = []
this.sends.forEach((send, index) => {
if (send.startSeq > cursor) {
windows.push({ title: index === 0 ? 'before the first send' : 'between sends', from: cursor, fromAt: cursorAt, to: send.startSeq, send: undefined })
}
const to = send.endSeq ?? this.seq
windows.push({ title: `#${index + 1} ${send.label}`, from: send.startSeq, fromAt: send.startedAt, to, send })
cursor = to
cursorAt = send.settledAt ?? this.now()
})
windows.push({ title: 'after the last send', from: cursor, fromAt: cursorAt, to: this.seq, send: undefined })
for (const window of windows) {
const events = this.events.filter(event => event.seq >= window.from && event.seq < window.to)
if (window.send === undefined && events.length === 0) continue
lines.push(...this.formatWindow(window.title, window.fromAt, window.send, events))
}
return lines.join('\n')
}
private formatWindow(title: string, from: number, send: SendWindow | undefined, events: TimelineEvent[]): string[] {
const lines: string[] = []
const outcome = send === undefined
? ''
: send.settledAt === undefined
? ` → still pending after ${this.now() - send.startedAt} ms`
: ` → ${send.outcome} after ${send.settledAt - send.startedAt} ms`
lines.push(`${title} (from +${from} ms)${outcome}`)
for (const event of events) {
if (event.kind === 'spawn') lines.push(` +${event.at} spawn s${event.session} pid ${event.pid}`)
if (event.kind === 'write') lines.push(` +${event.at} write s${event.session} ${event.units} units (${event.input ? 'input' : 'reply'})`)
}
const polls = events.filter((event): event is PollEvent => event.kind === 'poll')
if (polls.length > 0) {
const byForeground = new Map<string, number>()
for (const poll of polls) byForeground.set(poll.foreground, (byForeground.get(poll.foreground) ?? 0) + 1)
const summary = [...byForeground].map(([foreground, count]) => `${foreground} ×${count}`).join(', ')
lines.push(` polls ${polls.length} (+${polls[0]?.at}…+${polls[polls.length - 1]?.at}): ${summary}`)
}
const chunks = events.filter((event): event is ChunkEvent => event.kind === 'chunk')
if (chunks.length > 0) {
const markers = chunks.filter(chunk => chunk.prompt).length
lines.push(` chunks ${chunks.length} (${markers} with a prompt marker)`)
const shown = new Set<ChunkEvent>()
chunks.slice(0, SHOWN_HEAD_CHUNKS).forEach(chunk => shown.add(chunk))
chunks.slice(-SHOWN_TAIL_CHUNKS).forEach(chunk => shown.add(chunk))
chunks.filter(chunk => chunk.prompt).forEach(chunk => shown.add(chunk))
let elided = 0
for (const chunk of chunks) {
if (!shown.has(chunk)) {
elided += 1
continue
}
if (elided > 0) {
lines.push(` … ${elided} chunks elided …`)
elided = 0
}
lines.push(` +${chunk.at} s${chunk.session} ${chunk.units}u text=${chunk.textLength} marker=${chunk.prompt ? 'YES' : 'no'} tail=${tail(chunk.promptTail)} ${quoted(chunk.sample)}`)
}
if (send !== undefined) {
// Readiness evidence resets at the send's input write; terminal-protocol replies the
// emulator writes back do not reset it, so the replay starts at the last input write.
const lastInput = events.filter((event): event is WriteEvent => event.kind === 'write' && event.input).at(-1)
const evidence = replayPromptEvidence(chunks.filter(chunk => lastInput === undefined || chunk.seq > lastInput.seq))
lines.push(` replayed evidence at settle: promptSeen=${evidence.promptSeen} promptTail=${tail(evidence.promptTail)} promptTextSeen=${evidence.promptTextSeen}`)
}
}
return lines
}
}