From fc885edf721dbd0769622c4093a460f8985bbbf5 Mon Sep 17 00:00:00 2001 From: Tianyi Cui <53024+tianyicui@users.noreply.github.com> Date: Mon, 28 Sep 2026 00:12:40 +0800 Subject: [PATCH 1/4] test(pwsh): record a per-send readiness timeline in the loader-composition case The self-hosted Windows lane settles one or two of seven sends on the controlled prompt and the rest at the plain silence bound, and the settle reasons alone cannot say whether the marker was missing, its tail was invalidated by later output, or the foreground comparison failed. The case now records every decoded pty chunk with the sanitizer's marker verdict and prompt tail, every foreground poll, every input write, each send's settle reason and elapsed time, the session's prompt evidence replayed from those chunks, and the host, pwsh, PSReadLine, and console host versions; the settle assertions carry that timeline in their failure message and onTestFailed prints it when the runner's budget ends the case first. promptTailGraceMs returns to the product default: master runs with and without it took the same 20.8 s, so the lane's degraded sends never held the state it covers, and a nonzero value there would only lengthen a never-arriving-tail fallback. --- .../tests/loader-composition.spec.ts | 91 ++++-- .../tests/readiness-timeline.ts | 301 ++++++++++++++++++ 2 files changed, 371 insertions(+), 21 deletions(-) create mode 100644 packages/shell/tool-pwsh-persistent/tests/readiness-timeline.ts diff --git a/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts b/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts index edbf07509c..bfe01a0088 100644 --- a/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts +++ b/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts @@ -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 differs +// between the runners that pass this case and the self-hosted pool that fails it. +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) 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') @@ -206,9 +253,11 @@ describe.skipIf(!hasPwsh)('persistent pwsh through a real cordis.yml Loader comp // 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 // 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). + const failure = (): string => `${JSON.stringify(settleReasons)}\n${timeline.format()}` + expect(settleReasons.filter(reason => reason === 'stdin_read').length, failure()).toBeGreaterThanOrEqual(6) + expect(settleReasons, failure()).not.toContain('inferred_idle') }, 120_000) }) diff --git a/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.ts b/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.ts new file mode 100644 index 0000000000..3255166bfa --- /dev/null +++ b/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.ts @@ -0,0 +1,301 @@ +/** + * 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, 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 = terminal session in spawn order)' + +interface ChunkEvent { + kind: 'chunk' + at: number + session: number + units: number + sample: string + prompt: boolean + promptTail: string | undefined + textLength: number +} + +interface PollEvent { + kind: 'poll' + at: number + session: number + foreground: string +} + +interface WriteEvent { + kind: 'write' + at: number + session: number + units: number +} + +interface SpawnEvent { + kind: 'spawn' + at: number + session: number + pid: number +} + +type TimelineEvent = ChunkEvent | PollEvent | WriteEvent | SpawnEvent + +interface SendWindow { + label: string + startedAt: number + settledAt: number | undefined + outcome: TerminalWaitReason | 'rejected' | 'pending' +} + +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`. + */ +function replayPromptEvidence(chunks: ChunkEvent[]): { promptSeen: boolean; promptTail: string; promptTextSeen: boolean } { + 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. */ +export class ReadinessTimeline { + private readonly origin = performance.now() + private hostFactsText: string | undefined + + /** + * @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() + private sanitizerCount = 0 + private spawnCount = 0 + private currentLabel: string | undefined + private labelUses = 0 + + private now(): number { + return Math.round(performance.now() - this.origin) + } + + /** 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 = this.sanitizerCount + this.sanitizerCount += 1 + this.sanitizers.set(sanitizer, session) + } + this.events.push({ + kind: 'chunk', + at: this.now(), + 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.events.push({ kind: 'spawn', at: this.now(), session, pid: handle.pid }) + const inspectForeground = handle.inspectForeground.bind(handle) + vi.spyOn(handle, 'inspectForeground').mockImplementation(async (): Promise => { + const foreground = await inspectForeground() + this.events.push({ kind: 'poll', at: this.now(), 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 => { + this.events.push({ kind: 'write', at: this.now(), session, units: data.length }) + 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. + * @param operation - the send returned by `terminals.startSend`. + */ + track(operation: TerminalSendOperation): 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, startedAt: this.now(), settledAt: undefined, outcome: 'pending' } + this.sends.push(window) + void operation.done.then( + (settled) => { + window.settledAt = this.now() + window.outcome = settled.waitReason + }, + () => { + window.settledAt = this.now() + window.outcome = '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] : []] + const now = this.now() + let cursor = 0 + const windows: { title: string; from: number; to: number; send: SendWindow | undefined }[] = [] + // A send window spans its start through its settle instant inclusive: the poll that + // settled a send is recorded in the same millisecond as the settle. + this.sends.forEach((send, index) => { + if (send.startedAt > cursor) { + windows.push({ title: index === 0 ? 'before the first send' : 'between sends', from: cursor, to: send.startedAt, send: undefined }) + } + const to = (send.settledAt ?? now) + 1 + windows.push({ title: `#${index + 1} ${send.label}`, from: send.startedAt, to, send }) + cursor = to + }) + windows.push({ title: 'after the last send', from: cursor, to: now + 1, send: undefined }) + for (const window of windows) { + const events = this.events.filter(event => event.at >= window.from && event.at < window.to) + if (window.send === undefined && events.length === 0) continue + lines.push(...this.formatWindow(window.title, window.from, 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`) + } + const polls = events.filter((event): event is PollEvent => event.kind === 'poll') + if (polls.length > 0) { + const byForeground = new Map() + 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() + 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; replay from the last write. + const lastWrite = events.filter(event => event.kind === 'write').at(-1) + const evidence = replayPromptEvidence(chunks.filter(chunk => lastWrite === undefined || chunk.at >= lastWrite.at)) + lines.push(` replayed evidence at settle: promptSeen=${evidence.promptSeen} promptTail=${tail(evidence.promptTail)} promptTextSeen=${evidence.promptTextSeen}`) + } + } + return lines + } +} From f0a7f798a379914e50d556b3dc0c4e3f34e52577 Mon Sep 17 00:00:00 2001 From: Tianyi Cui <53024+tianyicui@users.noreply.github.com> Date: Mon, 28 Sep 2026 00:55:28 +0800 Subject: [PATCH 2/4] docs(notes): correct the pwsh lane record to the observed silence-bound settles The 2026-09-27 14:30Z master run carried the tail grace and took the same 20.8 s as the run before it, so the lane's mechanism is not a stalled prompt tail; the composition keeps the default and the notes record the open investigation, the native pwsh 7.6.6 evidence, the ConPTY repaint re-emission of the 133;D mark as the leading hypothesis, and issue #5297 for the Windows pid 0 side finding. --- .../2026-09-27-pwsh-prompt-tail-grace.i18n.yaml | 12 ++++++------ .../bug-fix/2026-09-27-pwsh-prompt-tail-grace.md | 6 +++--- .../bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md | 6 +++--- ...-27-observation-waits-on-observed-state.i18n.yaml | 8 ++++---- ...2026-09-27-observation-waits-on-observed-state.md | 6 ++++-- ...6-09-27-observation-waits-on-observed-state.zh.md | 6 ++++-- 6 files changed, 24 insertions(+), 20 deletions(-) diff --git a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.i18n.yaml b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.i18n.yaml index af95d9cdf7..1eda5f53ae 100644 --- a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.i18n.yaml +++ b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.i18n.yaml @@ -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: 5c48d66d06c50a09 + zh: 893853d96c26d6e9 /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 diff --git a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.md b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.md index 0aa25795c1..e836ef8088 100644 --- a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.md +++ b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.md @@ -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 turned out not to be 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 that 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. diff --git a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md index feb551d35f..3b3a57b67a 100644 --- a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md +++ b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md @@ -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 的就绪时间线,因此该状态一旦出现就会被点名,而不是从墙钟时间推断。 diff --git a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml index 3e4c2f6895..7fbdbcbcd2 100644 --- a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml @@ -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: 13db32f9da19d87b zh: 48081fc7035dea45 /agent-note-windows-lane-observations-wait-on-the-state-they-read/deferred: - en: 18dc81f98375fb04 - zh: e30413cd3d201b80 + en: e1c0bb4ec03b36a8 + zh: 6b1c2166c53f4e03 diff --git a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md index e0218a4d5f..b4a43d1509 100644 --- a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md @@ -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 @@ -32,4 +32,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 earlier probes had run under Windows PowerShell 5.1 because the guest carries no pwsh 7): 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. diff --git a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md index 079ae65451..809286cdbd 100644 --- a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md @@ -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 @@ -32,4 +32,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 取得的原生证据(此前的探测因 guest 没有 pwsh 7 而运行在 Windows PowerShell 5.1 之下):基线、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 跟踪。 From 51ede0f8c57a72c070c7e0c075f712d028172a55 Mon Sep 17 00:00:00 2001 From: Tianyi Cui <53024+tianyicui@users.noreply.github.com> Date: Mon, 28 Sep 2026 01:22:54 +0800 Subject: [PATCH 3/4] test(pwsh): build the failure message lazily and bound windows by event order Review round 1: the settle assertions build their message only when one is about to fail, so a passing run never pays the host-facts shell probe; send windows are bounded by event sequence numbers instead of milliseconds, so two sends that hand over within one millisecond keep their own events; the replay starts at the send's own input write and ignores the emulator's terminal-protocol replies; a throwing foreground inspection is recorded before the send rejects; a sanitizer is attributed to the most recently spawned terminal, which the class documents as the sequential-session assumption. A unit spec pins the replay rule against the session's evidence states, the window boundaries, the reply/input distinction, and the bounded, escaped rendering. Notes and comments drop change narration and the unverified claim about the pool's build. --- ...026-09-27-pwsh-prompt-tail-grace.i18n.yaml | 4 +- .../2026-09-27-pwsh-prompt-tail-grace.md | 2 +- .../2026-09-27-pwsh-prompt-tail-grace.zh.md | 2 +- ...ervation-waits-on-observed-state.i18n.yaml | 4 +- ...-27-observation-waits-on-observed-state.md | 2 +- ...-observation-waits-on-observed-state.zh.md | 2 +- .../tests/loader-composition.spec.ts | 20 ++- .../tests/readiness-timeline.spec.ts | 143 ++++++++++++++++++ .../tests/readiness-timeline.ts | 133 +++++++++++----- 9 files changed, 256 insertions(+), 56 deletions(-) create mode 100644 packages/shell/tool-pwsh-persistent/tests/readiness-timeline.spec.ts diff --git a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.i18n.yaml b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.i18n.yaml index 1eda5f53ae..d0742687e2 100644 --- a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.i18n.yaml +++ b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.i18n.yaml @@ -6,8 +6,8 @@ en: 5e8c5673a0669d9c zh: c8442a6186288a2a /agent-note-a-seen-prompt-marker-keeps-its-own-tail-grace/problem: - en: 5c48d66d06c50a09 - zh: 893853d96c26d6e9 + en: 906f8707987ff36c + zh: 40430ec1e03ee340 /agent-note-a-seen-prompt-marker-keeps-its-own-tail-grace/decision: en: a998f5c6abdd68eb zh: a7cdd13e1e4de6c6 diff --git a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.md b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.md index e836ef8088..375ba521d5 100644 --- a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.md +++ b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.md @@ -6,7 +6,7 @@ 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 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 turned out not to be 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 that open investigation. +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 diff --git a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md index 3b3a57b67a..511cedf728 100644 --- a/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md +++ b/.agents/notes/implemented/bug-fix/2026-09-27-pwsh-prompt-tail-grace.zh.md @@ -6,7 +6,7 @@ Status: implemented ## Problem -自托管 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)记录了这项仍未关闭的调查。 +自托管 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 diff --git a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml index 7fbdbcbcd2..e444419931 100644 --- a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml @@ -18,5 +18,5 @@ en: 13db32f9da19d87b zh: 48081fc7035dea45 /agent-note-windows-lane-observations-wait-on-the-state-they-read/deferred: - en: e1c0bb4ec03b36a8 - zh: 6b1c2166c53f4e03 + en: 8e182739fdf90baf + zh: 5f93f7b7d9518764 diff --git a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md index b4a43d1509..522358e508 100644 --- a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md @@ -34,4 +34,4 @@ Both plugin-manager record cases now observe the record while the run is in flig 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 earlier probes had run under Windows PowerShell 5.1 because the guest carries no pwsh 7): 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. +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. diff --git a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md index 809286cdbd..9adf17b517 100644 --- a/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md @@ -34,4 +34,4 @@ loader-composition 的结算层级断言把记录到的结算原因与一份逐 自托管 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 取得的原生证据(此前的探测因 guest 没有 pwsh 7 而运行在 Windows PowerShell 5.1 之下):基线、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 跟踪。 +在 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 跟踪。 diff --git a/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts b/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts index bfe01a0088..bd2204aa1f 100644 --- a/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts +++ b/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts @@ -33,8 +33,8 @@ const hasPwsh = spawnSync( ).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 differs -// between the runners that pass this case and the self-hosted pool that fails it. +// 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)" }', @@ -194,7 +194,7 @@ describe.skipIf(!hasPwsh)('persistent pwsh through a real cordis.yml Loader comp const settleReasons: TerminalWaitReason[] = [] vi.spyOn(terminals, 'startSend').mockImplementation((owner, id, request) => { const operation = startSend(owner, id, request) - timeline.track(operation) + 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. @@ -251,13 +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 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). - const failure = (): string => `${JSON.stringify(settleReasons)}\n${timeline.format()}` - expect(settleReasons.filter(reason => reason === 'stdin_read').length, failure()).toBeGreaterThanOrEqual(6) - expect(settleReasons, failure()).not.toContain('inferred_idle') + // 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) }) diff --git a/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.spec.ts b/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.spec.ts new file mode 100644 index 0000000000..153c2c0bd4 --- /dev/null +++ b/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.spec.ts @@ -0,0 +1,143 @@ +import { Readable } from 'node:stream' +import { afterEach, describe, expect, it, vi } from 'vitest' +import type { SubprocessOutcome, 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 FakeTerminal { + handle: SubprocessTerminalHandle + foreground: { processGroupId: number; inputWaiting: boolean } | undefined + inspectError: Error | undefined + writes: string[] +} + +function fakeTerminal(pid: number): FakeTerminal { + const fake: FakeTerminal = { + foreground: { processGroupId: pid, inputWaiting: false }, + inspectError: undefined, + writes: [], + handle: undefined as unknown as SubprocessTerminalHandle, + } + const output = new Readable({ read() {} }) + fake.handle = { + pid, + output, + done: new Promise(() => {}), + async write(data: string) { fake.writes.push(data) }, + async resize() {}, + async inspectForeground() { + if (fake.inspectError !== undefined) throw fake.inspectError + return fake.foreground + }, + async inspectActivity() { return { state: 'unknown' as const, revision: 0 } }, + async signalForeground() { return pid }, + async terminate() {}, + } + return fake +} + +function fakeSend(): { operation: TerminalSendOperation; settle: (waitReason: TerminalSendResult['waitReason']) => void; reject: () => void } { + const resolvers = Promise.withResolvers() + 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 => 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.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]/) + }) +}) diff --git a/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.ts b/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.ts index 3255166bfa..521c0605a0 100644 --- a/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.ts +++ b/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.ts @@ -5,7 +5,7 @@ * lost controlled-prompt fast path names the state that lost it. */ import type { SubprocessTerminalForeground, SubprocessTerminalHandle } from '@deepseek-ai/dsh-subprocess' -import type { TerminalSendOperation, TerminalWaitReason } from '@deepseek-ai/dsh-terminal' +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' @@ -15,6 +15,7 @@ export const TIMELINE_HEADER = 'readiness timeline (ms since the case started; s interface ChunkEvent { kind: 'chunk' + seq: number at: number session: number units: number @@ -26,6 +27,7 @@ interface ChunkEvent { interface PollEvent { kind: 'poll' + seq: number at: number session: number foreground: string @@ -33,13 +35,17 @@ interface PollEvent { 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 @@ -47,13 +53,35 @@ interface SpawnEvent { type TimelineEvent = ChunkEvent | PollEvent | WriteEvent | SpawnEvent +/** An event before the timeline stamps its sequence number and time. */ +type RecordedEvent = { + [K in TimelineEvent['kind']]: Omit, '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 @@ -93,8 +121,10 @@ function tail(text: string | undefined): string { * 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. */ -function replayPromptEvidence(chunks: ChunkEvent[]): { promptSeen: boolean; promptTail: string; promptTextSeen: boolean } { +export function replayPromptEvidence(chunks: readonly ReplayChunk[]): PromptEvidence { let promptSeen = false let promptTail = '' for (const chunk of chunks) { @@ -111,10 +141,15 @@ function replayPromptEvidence(chunks: ChunkEvent[]): { promptSeen: boolean; prom return { promptSeen, promptTail, promptTextSeen: promptTail === CONTROLLED_PROMPT } } -/** Records one Loader-composition case's terminal traffic and formats it per send. */ +/** + * 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 @@ -125,7 +160,6 @@ export class ReadinessTimeline { private readonly events: TimelineEvent[] = [] private readonly sends: SendWindow[] = [] private readonly sanitizers = new WeakMap() - private sanitizerCount = 0 private spawnCount = 0 private currentLabel: string | undefined private labelUses = 0 @@ -134,6 +168,11 @@ export class ReadinessTimeline { 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`. @@ -151,13 +190,11 @@ export class ReadinessTimeline { private recordChunk(sanitizer: TerminalSanitizer, chunk: string, result: SanitizedChunk): void { let session = this.sanitizers.get(sanitizer) if (session === undefined) { - session = this.sanitizerCount - this.sanitizerCount += 1 + session = Math.max(0, this.spawnCount - 1) this.sanitizers.set(sanitizer, session) } - this.events.push({ + this.push({ kind: 'chunk', - at: this.now(), session, units: chunk.length, sample: sample(chunk), @@ -174,16 +211,25 @@ export class ReadinessTimeline { observeTerminal(handle: SubprocessTerminalHandle): void { const session = this.spawnCount this.spawnCount += 1 - this.events.push({ kind: 'spawn', at: this.now(), session, pid: handle.pid }) + this.push({ kind: 'spawn', session, pid: handle.pid }) const inspectForeground = handle.inspectForeground.bind(handle) vi.spyOn(handle, 'inspectForeground').mockImplementation(async (): Promise => { - const foreground = await inspectForeground() - this.events.push({ kind: 'poll', at: this.now(), session, foreground: foreground === undefined ? 'undefined' : JSON.stringify(foreground) }) + 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 => { - this.events.push({ kind: 'write', at: this.now(), session, units: data.length }) + 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) }) } @@ -198,26 +244,33 @@ export class ReadinessTimeline { } /** - * Open a send window and close it when the operation settles or rejects. + * 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): void { + 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, startedAt: this.now(), settledAt: undefined, outcome: 'pending' } + 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) - void operation.done.then( - (settled) => { - window.settledAt = this.now() - window.outcome = settled.waitReason - }, - () => { - window.settledAt = this.now() - window.outcome = 'rejected' - }, - ) + 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') }) } /** @@ -228,24 +281,23 @@ export class ReadinessTimeline { format(): string { this.hostFactsText ??= this.hostFacts() const lines: string[] = [TIMELINE_HEADER, ...this.hostFactsText.length > 0 ? [this.hostFactsText] : []] - const now = this.now() let cursor = 0 - const windows: { title: string; from: number; to: number; send: SendWindow | undefined }[] = [] - // A send window spans its start through its settle instant inclusive: the poll that - // settled a send is recorded in the same millisecond as the settle. + let cursorAt = 0 + const windows: { title: string; from: number; fromAt: number; to: number; send: SendWindow | undefined }[] = [] this.sends.forEach((send, index) => { - if (send.startedAt > cursor) { - windows.push({ title: index === 0 ? 'before the first send' : 'between sends', from: cursor, to: send.startedAt, send: undefined }) + 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.settledAt ?? now) + 1 - windows.push({ title: `#${index + 1} ${send.label}`, from: send.startedAt, to, send }) + 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, to: now + 1, send: undefined }) + 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.at >= window.from && event.at < window.to) + 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.from, window.send, events)) + lines.push(...this.formatWindow(window.title, window.fromAt, window.send, events)) } return lines.join('\n') } @@ -260,7 +312,7 @@ export class ReadinessTimeline { 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`) + 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) { @@ -290,9 +342,10 @@ export class ReadinessTimeline { 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; replay from the last write. - const lastWrite = events.filter(event => event.kind === 'write').at(-1) - const evidence = replayPromptEvidence(chunks.filter(chunk => lastWrite === undefined || chunk.at >= lastWrite.at)) + // 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}`) } } From 0310066b39980c78cb3d93da3ebfcbed8dbb66aa Mon Sep 17 00:00:00 2001 From: Tianyi Cui <53024+tianyicui@users.noreply.github.com> Date: Mon, 28 Sep 2026 01:30:26 +0800 Subject: [PATCH 4/4] test(pwsh): build the fake terminal handle without an unknown cast The unit spec's fake handle is a typed object whose methods read a mutable state record, so the no-new-unknown-casts gate has nothing to reject. --- .../tests/readiness-timeline.spec.ts | 33 ++++++++----------- 1 file changed, 13 insertions(+), 20 deletions(-) diff --git a/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.spec.ts b/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.spec.ts index 153c2c0bd4..2d090b31a0 100644 --- a/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.spec.ts +++ b/packages/shell/tool-pwsh-persistent/tests/readiness-timeline.spec.ts @@ -1,6 +1,6 @@ import { Readable } from 'node:stream' import { afterEach, describe, expect, it, vi } from 'vitest' -import type { SubprocessOutcome, SubprocessTerminalHandle } from '@deepseek-ai/dsh-subprocess' +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' @@ -11,36 +11,29 @@ afterEach(() => { vi.restoreAllMocks() }) -interface FakeTerminal { - handle: SubprocessTerminalHandle - foreground: { processGroupId: number; inputWaiting: boolean } | undefined +interface FakeTerminalState { + foreground: SubprocessTerminalForeground | undefined inspectError: Error | undefined - writes: string[] } -function fakeTerminal(pid: number): FakeTerminal { - const fake: FakeTerminal = { - foreground: { processGroupId: pid, inputWaiting: false }, - inspectError: undefined, - writes: [], - handle: undefined as unknown as SubprocessTerminalHandle, - } - const output = new Readable({ read() {} }) - fake.handle = { +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, + output: new Readable({ read() {} }), done: new Promise(() => {}), - async write(data: string) { fake.writes.push(data) }, + async write(data: string) { writes.push(data) }, async resize() {}, async inspectForeground() { - if (fake.inspectError !== undefined) throw fake.inspectError - return fake.foreground + 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 fake + return { handle, state, writes } } function fakeSend(): { operation: TerminalSendOperation; settle: (waitReason: TerminalSendResult['waitReason']) => void; reject: () => void } { @@ -107,7 +100,7 @@ describe('ReadinessTimeline', () => { timeline.track(b.operation, { text: 'echo b', submit: true }) await terminal.handle.write('echo b\r') sanitizer.push('b-output\r\n') - terminal.inspectError = new Error('snapshot unreadable') + terminal.state.inspectError = new Error('snapshot unreadable') await expect(terminal.handle.inspectForeground()).rejects.toThrow('snapshot unreadable') b.reject() await settled()