From 6ad3557b1b4d194a7b1a8eb7f996922b4c25f106 Mon Sep 17 00:00:00 2001 From: Tianyi Cui <53024+tianyicui@users.noreply.github.com> Date: Sun, 27 Sep 2026 16:37:14 +0800 Subject: [PATCH] test(boot): wait on the observed state in two Windows-lane cases `operations.spec.ts` read the profile's run record from a 100 ms timer armed before the refused installation whose repair it observes; a loaded runner reached the repair run after that timer and the case failed with `null` against the recorded run. The observing child now stays in flight until the record appears, and the bounded wait starts at the launcher hand-over rather than at test start. The loader-composition case counts `stdin_read` settlements but reported only the count, so its Windows failures could not say which tier settled which send. The recorded reasons now ride in the assertion message; the threshold and the assertions are unchanged. --- ...ervation-waits-on-observed-state.i18n.yaml | 22 +++++++++ ...-27-observation-waits-on-observed-state.md | 35 ++++++++++++++ ...-observation-waits-on-observed-state.zh.md | 35 ++++++++++++++ .../plugin-manager/tests/operations.spec.ts | 48 +++++++++++++++---- .../tests/loader-composition.spec.ts | 7 ++- 5 files changed, 136 insertions(+), 11 deletions(-) create mode 100644 .agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml create mode 100644 .agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md create mode 100644 .agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md 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 new file mode 100644 index 0000000000..c52ccdc078 --- /dev/null +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.i18n.yaml @@ -0,0 +1,22 @@ +# Bilingual-pair consistency record for 2026-09-27-observation-waits-on-observed-state.md (docs/i18n/README.md): per heading +# section, a hash of its English and Chinese blocks outside code blocks and generated regions. +# After editing either side, bring the other along and re-record with: +# pnpm run verify-translation-pairing --write .agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md +/agent-note-windows-lane-observations-wait-on-the-state-they-read: + en: 8949f81c9d585fc0 + zh: 34e1bdbca1cf2126 +/agent-note-windows-lane-observations-wait-on-the-state-they-read/problem: + en: 270b015afc8de8ac + zh: 65aeb1e270d19a27 +/agent-note-windows-lane-observations-wait-on-the-state-they-read/decision: + en: 479cb25421102304 + zh: 9e23396728001e2c +/agent-note-windows-lane-observations-wait-on-the-state-they-read/alternatives-considered: + en: 00e59c561085e081 + zh: 4f6ac4dfc3259f58 +/agent-note-windows-lane-observations-wait-on-the-state-they-read/consequences: + en: 13db32f9da19d87b + zh: 48081fc7035dea45 +/agent-note-windows-lane-observations-wait-on-the-state-they-read/deferred: + en: 68baa2f8c114d646 + zh: 5ca029c62a288b14 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 new file mode 100644 index 0000000000..4eb4ed92ae --- /dev/null +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.md @@ -0,0 +1,35 @@ +# Agent Note: Windows-lane observations wait on the state they read + +Status: implemented + +English | [中文](2026-09-27-observation-waits-on-observed-state.zh.md) + +## Problem + +Two self-hosted Windows lane cases observed state through a wall-clock window instead of the state they assert on. + +`packages/boot/plugin-manager/tests/operations.spec.ts` armed a 100 ms timer when the case started and read the profile's `run.json` when it fired, to observe the run record while the run was still in flight. The repaired installation it observes runs only after a refused installation, a `pnpm view` lookup, the restoration of the profile files, and a second `launch`, so the timer measured that whole prefix rather than the record write. Under the loaded runner the repair began after the deadline and the case failed with `expected null to deeply equal { pid: 4343, grouped: false }` (PR #4595 `windows node 24 / coverage`, job 108402945554, 2026-09-26; the case took 345 ms, and its sibling single-run cases, which need no such prefix, passed in 113 ms and 116 ms). + +`packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts` counts each send's settlement tier and requires the controlled-prompt fast path, but reported only the count, so a failure could not say which tier settled which send — the one fact that separates a degraded readiness path from a mis-sized window. + +## Decision + +`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. + +## Alternatives considered + +**Raise the fixed timer, or poll for the record from test start.** Rejected: both keep the window anchored before the operation reached the run it observes, so the bound has to cover the whole prefix and grows with whatever the runner does before the repair run — the same mistake at a larger size. Anchoring on the hand-over measures only the state transition being waited for. + +**Wait for the record without a bound.** Rejected: a record the operation never writes would hang the case until the runner's own timeout and report nothing about the record. + +**Record only the settlements that matter, or assert a subset of sends.** Rejected: it weakens what the suite pins — that no send falls back to the silence tier — to make the failure go away. + +## Consequences + +Both plugin-manager record cases now observe the record while the run is in flight on a loaded runner, and a genuinely missing record still fails the same assertion. The bounded wait costs 2 s only when the operation never writes the record. + +## Deferred + +The loader-composition failure of 2026-09-25/26 remains unexplained. On Windows `isStdinWaiting` returns false and `foregroundPgid` returns the shell pid, so `stdin_read` can only come from the controlled-prompt tail; the three failing runs settled one or two of seven sends on that prompt, and their durations (17.5 s, 20.9 s against 4.7 s healthy) match one silence tier per degraded send while every output assertion passed. A fourth run timed out at the case bound. Native Windows reproduction was unavailable for this change (the local guest rejected its guest-operations credentials), so the assertion, the session's readiness path, and the prompt installation are unchanged; the next failure now names the tiers each send settled on. 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 new file mode 100644 index 0000000000..e471e76383 --- /dev/null +++ b/.agents/notes/implemented/testing/2026-09-27-observation-waits-on-observed-state.zh.md @@ -0,0 +1,35 @@ +# Agent Note: Windows lane 的观测等待它所读取的状态 + +Status: implemented + +[English](2026-09-27-observation-waits-on-observed-state.md) | 中文 + +## Problem + +自托管 Windows lane 的两个用例用墙钟窗口观测状态，而不是等待它们真正断言的那个状态。 + +`packages/boot/plugin-manager/tests/operations.spec.ts` 在用例开始时启动一个 100 毫秒定时器，并在它触发时读取 profile 的 `run.json`，以此在该 run 仍在进行时观测 run 记录。它要观测的「修复安装」只有在一次被拒绝的安装、一次 `pnpm view` 查询、profile 文件恢复以及第二次 `launch` 之后才会发生，因此该定时器度量的是这整段前缀，而不是记录写入本身。在负载较高的 runner 上修复安装晚于该截止时刻才开始，用例因而以 `expected null to deeply equal { pid: 4343, grouped: false }` 失败（PR #4595 的 `windows node 24 / coverage`，job 108402945554，2026-09-26；该用例耗时 345 毫秒，而相邻的单 run 用例不需要这段前缀，分别以 113 毫秒和 116 毫秒通过）。 + +`packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts` 统计每次 send 的结算层级并要求受控提示符快路径，但只报告数量，失败时无法说明哪一层级结算了哪一次 send——而这正是区分「就绪路径退化」与「窗口取值不当」的唯一事实。 + +## Decision + +`observingChild` 会保持该 run 在进行中，直到测试读到 run 记录，因此读取不可能与 run 结束竞争；其有界等待从被 mock 的启动器交接处开始，而不是从用例开始处开始：被记录的 run 只是紧随启动之后的一次原子写入，因此等待上界只需覆盖这次写入。`RECORD_WAIT_MS`（2 秒）刻意低于用例预算，于是一条始终没有出现的记录会以指名它的断言报告，而不是以 runner 超时报告。修复安装用例与单 run 用例都通过同一个 `spawned` 钩子交接子进程。 + +loader-composition 的结算层级断言把 `JSON.stringify(settleReasons)` 作为失败信息。阈值与断言本身不变。 + +## Alternatives considered + +**提高固定定时器的时长，或从用例开始处轮询记录。** 不采纳：两者都把窗口锚定在操作尚未到达它所观测的 run 之前，于是上界必须覆盖整段前缀，并随 runner 在修复 run 之前的行为一起增长——同样的错误，只是更大。锚定在交接处则只度量真正要等待的那个状态转换。 + +**无上界地等待记录。** 不采纳：若操作永不写入记录，用例会挂到 runner 自身的超时，且对记录本身不给出任何信息。 + +**只记录关键的那几次结算，或断言 send 的子集。** 不采纳：这会把该套件所固定的内容——任何 send 都不得回退到静默层——削弱成让失败消失。 + +## Consequences + +在负载较高的 runner 上，两个插件管理器记录用例现在都能在该 run 仍在进行时观测到记录，而真正缺失的记录仍会以同一条断言失败。只有在操作始终不写记录时，这段有界等待才会付出 2 秒。 + +## Deferred + +loader-composition 于 2026-09-25/26 的失败仍未解释。在 Windows 上 `isStdinWaiting` 返回 false，`foregroundPgid` 返回 shell 自身的 pid，因此 `stdin_read` 只能来自受控提示符尾部；三次失败运行中七次 send 只有一到两次按该提示符结算，而其耗时（17.5 秒、20.9 秒，对照健康时的 4.7 秒）与「每次退化 send 支付一层静默」相符，同时所有输出断言都通过。第四次运行在用例上界处超时。本次改动无法获得原生 Windows 复现（本机 guest 拒绝其 guest operations 凭据），因此断言、会话的就绪路径与提示符安装均未改动；下一次失败会指明各次 send 结算在哪些层级上。 diff --git a/packages/boot/plugin-manager/tests/operations.spec.ts b/packages/boot/plugin-manager/tests/operations.spec.ts index 41009ec9ed..9a062e8af9 100644 --- a/packages/boot/plugin-manager/tests/operations.spec.ts +++ b/packages/boot/plugin-manager/tests/operations.spec.ts @@ -598,22 +598,50 @@ function runRecord(dir: string): string { return join(dir, '.plugin-manager', 'run.json') } -/** A run that exits after `ms`, reading the profile's run record while it is still running. */ -function observingChild(dir: string, pid: number, ms = 100) { +/** + * The record an operation writes for the run it started, read once the record + * appears. The write follows the run's launch, so a bound this far above one + * atomic file write keeps a missing record reporting as the assertion that + * names it rather than as a runner timeout. + */ +const RECORD_WAIT_MS = 2_000 + +/** + * A run that stays in flight until the test has read the profile's run record, + * so the read observes the run and cannot race its end. `spawned` is the + * mocked launcher's hand-over: the wait for the record starts when the run + * does, not before the operation reached it under a loaded runner. + */ +function observingChild(dir: string, pid: number, waitMs = RECORD_WAIT_MS) { const stdout = new PassThrough() const stderr = new PassThrough() const raw = new EventEmitter() const observed: { record: string | undefined } = { record: undefined } + const spawned = Promise.withResolvers() const done = new Promise((resolve) => { - setTimeout(() => { - observed.record = existsSync(runRecord(dir)) ? readFileSync(runRecord(dir), 'utf8') : undefined + void spawned.promise.then(async () => { + observed.record = await recordedRun(dir, waitMs) stdout.end() stderr.end() raw.emit('exit', 0, null) resolve({ exitCode: 0, failed: false, stdout: '', stderr: '' }) - }, ms) + }) }) - return { child: Object.assign(done, { stdout, stderr, nodeChildProcess: raw, pid }), observed } + return { + child: Object.assign(done, { stdout, stderr, nodeChildProcess: raw, pid }), + observed, + spawned: () => { spawned.resolve(undefined) }, + } +} + +/** The written run record, or undefined once `waitMs` passes without one. */ +async function recordedRun(dir: string, waitMs: number): Promise { + const deadline = Date.now() + waitMs + for (;;) { + if (existsSync(runRecord(dir))) return readFileSync(runRecord(dir), 'utf8') + if (Date.now() >= deadline) return undefined + await new Promise(resolve => setTimeout(resolve, 1)) + } } it.each([8192, 30])('refuses to run while a run recorded by an exited operation is still active (output bound %i)', async (outputBytes) => { @@ -667,8 +695,8 @@ it.each(['not json', 'null', '{"pid":0,"grouped":false}', '{"pid":12,"grouped":" it.each(['cli', 'service'] as const)('records a %s run while it runs and removes the record once it ends', async (execution) => { const { dir, context } = fixture() - const { child, observed } = observingChild(dir, 4242) - command.run.mockImplementationOnce(() => child) + const { child, observed, spawned } = observingChild(dir, 4242) + command.run.mockImplementationOnce(() => { spawned(); return child }) const outcome = await runProfilePnpm(context, ['list'], { execution, outputBytes: 8192 }) expect(outcome.exitCode).toBe(0) expect(JSON.parse(observed.record ?? 'null')).toEqual({ @@ -683,7 +711,9 @@ it('records the install that repairs a refused installation', async () => { const base = command.run.getMockImplementation() as (...call: unknown[]) => Promise & FakeChild const repair = observingChild(dir, 4343) command.run.mockImplementation((...call: unknown[]) => { - return (call[1] as readonly string[]).includes('--config.lockfile=false') ? repair.child : base(...call) + if (!(call[1] as readonly string[]).includes('--config.lockfile=false')) return base(...call) + repair.spawned() + return repair.child }) const outcome = await runProfilePnpm(context, ['add', 'incompatible'], { execution: 'service', outputBytes: 8192 }) expect(outcome.exitCode).toBe(1) 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 8641952fb4..1b43d1efaa 100644 --- a/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts +++ b/packages/shell/tool-pwsh-persistent/tests/loader-composition.spec.ts @@ -198,8 +198,11 @@ 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. - expect(settleReasons.filter(reason => reason === 'stdin_read').length).toBeGreaterThanOrEqual(6) + // 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') }, 120_000) })