fix(test): retain child turn diagnostics when log reads time out

2026-09-09 04:02:35 +00:00 · 2026-09-08 17:27:59 +08:00
parent f7ef7103f3
commit 180bdede47
5 changed files with 52 additions and 13 deletions
@@ -2,5 +2,5 @@
 # side as of the last confirmed-consistent state. Both languages carry equal authority;
 # after editing either side, bring the other along and re-record with:
 #   pnpm run verify-translation-pairing --write packages/test-support/session-snapshot/README.md
-README.md: f1126920969cead7844712ad3b2c7213cce19ed9
-README.zh.md: 65e04f252a13c22351b450da2df44f244d484811
+README.md: 6e88270dc3be31b135534097d30fb2b67a37ebde
+README.zh.md: 57cf86dcda198ac939c6e82c56cd3c9c3b473baa
@@ -88,6 +88,7 @@ A scenario requiring a non-Windows host declares `posixOnly`, which skips its ru

 ### What can go wrong

+- **A child turn wait fails** — `waitForSubagentTurnEnd` identifies the child, requested turn, and deadline even when the first log harvest exceeds that deadline, and retains the underlying failure as the error cause.
 - **A fixture guard rejects the committed files** — orphan scenario dirs, missing files, multiple pins for one header class, duplicate sidecar content, unscrubbed JSONL headers, and malformed pinning headers all fail the suite before comparisons run.
 - **The session harvest needs raw JSONL mode** — snapshot configs set the JSONL backend's `compression: 'none'`; compressed JSONL has no snapshot-harvest path.
 - **Built mode needs current artifacts** — run `pnpm run build` before selecting `DSH_EXAMPLE_MODE=lib`; source mode remains the zero-build path.
@@ -88,6 +88,7 @@ Spill 场景通过真实本地 provider 保存到私有临时根目录。夹具

 ### 可能出什么问题

+- **子会话轮次等待失败**——即使首次日志收集就超过期限，`waitForSubagentTurnEnd` 也会指出子会话、目标轮次与等待期限，并通过错误的 cause 保留底层失败。
 - **fixture 保护拒绝已提交文件**——遗留场景目录、缺失文件、一个 header 类别包含多个 pin、重复的伴随文件内容、未擦除的 JSONL header 与格式错误的 pin header 都会在比较运行前使套件失败。
 - **会话收集需要原始 JSONL mode**——快照配置使用 JSONL 后端的 `compression: 'none'`；压缩 JSONL 没有快照收集路径。
 - **构建 mode 需要当前产物**——选择 `DSH_EXAMPLE_MODE=lib` 前先运行 `pnpm run build`；源 mode 仍是零构建路径。
@@ -67,7 +67,8 @@ const WAIT_POLL_INTERVAL_MS = 10
 * `waitForInboxMessage` waits for inserted inbox text containing a scenario marker.
 * `waitForSubagentTurnEnd` waits until one background child has persisted a
 * closed model-work turn after its own descriptor; child progress has no ACP
- * update to wait on.
+ * update to wait on. Failures identify the child, turn, and deadline even if
+ * the first log read is still pending; the underlying failure is retained as cause.
 * `waitForTitleAfterTurnEnd` additionally waits for a later durable title.
 * `waitForEventAfterTurnEnd` waits until a complete record of the given event
 * type follows the latest closed turn — for scenarios whose asserted state
@@ -608,16 +609,20 @@ async function waitForPersistedChildTurnEnd(
  timeoutMs = DEFAULT_WAIT_TIMEOUT_MS,
  minimumTurn = 1,
 ): Promise<void> {
-  await vi.waitFor(async () => {
-    const log = (await harvestSessionLogs(root))[child]
-    if (log === undefined || !latestTurnIsClosed(log.content)
-      || !hasRequestHeaderAfterDescriptor(log.content)
-      || !hasClosedTurn(log.content, minimumTurn)) {
-      throw new Error(
-        `snapshot-harness: subagent child #${child} did not persist closed turn ${minimumTurn} within ${timeoutMs}ms`,
-      )
-    }
-  }, { interval: WAIT_POLL_INTERVAL_MS, timeout: timeoutMs })
+  const message = `snapshot-harness: subagent child #${child} did not persist closed turn ${minimumTurn} within ${timeoutMs}ms`
+  try {
+    await vi.waitFor(async () => {
+      const log = (await harvestSessionLogs(root))[child]
+      if (log === undefined || !latestTurnIsClosed(log.content)
+        || !hasRequestHeaderAfterDescriptor(log.content)
+        || !hasClosedTurn(log.content, minimumTurn)) {
+        throw new Error(message)
+      }
+    }, { interval: WAIT_POLL_INTERVAL_MS, timeout: timeoutMs })
+  } catch (cause) {
+    // The deadline can precede the first harvest, before the callback names the missing turn.
+    throw new Error(message, { cause })
+  }
 }

 /** Whether a raw session log contains the requested closed turn. */
@@ -1,4 +1,5 @@
 import { mkdir, mkdtemp, readFile, readdir, realpath, rm, symlink, writeFile } from 'node:fs/promises'
+import * as fsPromises from 'node:fs/promises'
 import { once } from 'node:events'
 import { tmpdir } from 'node:os'
 import { delimiter, join, relative, sep } from 'node:path'
@@ -984,6 +985,37 @@ describe('runScenario', () => {
    )).rejects.toThrow(/did not persist goal phase "blocked" within 20ms/)
  })

+  it('identifies the child wait when its first log harvest outlasts the deadline', async () => {
+    const { fixtureFile } = await scenario({})
+    const reading = Promise.withResolvers<undefined>()
+    const release = Promise.withResolvers<undefined>()
+    let pendingRead: Promise<unknown> | undefined
+    const originalReaddir = readdir
+    const spy = vi.spyOn(fsPromises, 'readdir').mockImplementation(async (...args) => {
+      if (pendingRead === undefined && String(args[0]).includes('acp-snap-sessions-')) {
+        const read = release.promise.then(() => originalReaddir(...args))
+        pendingRead = read
+        reading.resolve(undefined)
+        return await read
+      }
+      return await originalReaddir(...args)
+    })
+    const run = runScenario(
+      { steps: [...boot, { op: 'waitForSubagentTurnEnd', child: 2, timeoutMs: 20 }] },
+      { agent: AGENT, mode: 'replay', fixtureFile },
+    )
+    const rejected = expect(run).rejects.toThrow(/subagent child #2 did not persist closed turn 1 within 20ms/)
+    try {
+      await Promise.race([reading.promise, rejected])
+      expect(pendingRead).toBeDefined()
+      await rejected
+    } finally {
+      release.resolve(undefined)
+      await Promise.allSettled([pendingRead, run, rejected])
+      spy.mockRestore()
+    }
+  })
+
  it('waitForSubagentTurnEnd requires a closed child work turn', { timeout: 20_000 }, async () => {
    const closed = await scenario({
      prompt: 'hang-until-cancel',