From 45bdb63eca0a6edc76eb7f62a5013d76b6b7d702 Mon Sep 17 00:00:00 2001 From: Jesse_Chen Date: Fri, 4 Sep 2026 15:23:13 +0800 Subject: [PATCH] fix(rectification): keep adopt narration timeout on a clearable ref timer AbortSignal.timeout() is unref'd, so a hanging generateText drained the test event loop and cancelled the rest of the file. Clear the timer after the model returns. Co-authored-by: Cursor --- docs/BUG_HISTORY.md | 18 +++- ...tification-adopt-narration-fix-20260904.md | 20 +++++ ...ification-adopt-narration-fix2-20260904.md | 90 +++++++++++++++++++ docs/tasks/README.md | 2 +- .../v9/adopt-narration-agent.ts | 67 +++++++++++--- ...ification-adopt-narration-20260904.test.ts | 43 +++++++++ 6 files changed, 226 insertions(+), 14 deletions(-) create mode 100644 docs/tasks/PROGRESS-rectification-adopt-narration-fix2-20260904.md diff --git a/docs/BUG_HISTORY.md b/docs/BUG_HISTORY.md index 6c9c42cd..3e6ba880 100644 --- a/docs/BUG_HISTORY.md +++ b/docs/BUG_HISTORY.md @@ -8062,6 +8062,22 @@ - 修复：提示词改为「不要出现『确认』『精确』这两个词」，与校验器同口径；校验器本身不放宽，「这不是确认的分钟」仍打回。`deliverAdoptNarration` 打 `adopt_narration=agent | template: | template:model_error | template:not_ready`（不含模型原文），并用 `AbortSignal.timeout(8000)` 超时走模板。意图分类器超时仍是既有缺口，本单不修。 - 验证：提示词源码断言含「不要出现」；`deliverAdoptNarration` 对 agent / template:unknown_minute / template:model_error / template:not_ready 各有断言；短 timeout 挂起 generateText 走模板且不抛。 - 防复发：采用旁白结果必须留下 `adopt_narration=` 日志。Agent.generate 必须带超时。不得把「确认」从校验器删掉却不改提示词。 -- 相关记录：BUG-521 +- 相关记录：BUG-521、BUG-523 - 复发自：无 - 修复版本：待发布 + +## BUG-523 | 采用旁白超时用 unref 计时器，测试挂死事件循环 + +- 状态：resolved +- 首次发现：2026-09-04 +- 最近更新：2026-09-04 +- 影响面：`frontend/src/lib/rectification-agentic/v9/adopt-narration-agent.ts` `composedAbortSignal` +- 用户现象：staging 门禁 `npm test` 退出码 1，`13dded9f` 不能部署。生产请求有监听 socket 撑住事件循环，超时在真实流量里仍会触发；但每次调用都会留下一个无法 `clear` 的 8 秒计时器。 +- 触发条件：`deliverAdoptNarration` 用 `AbortSignal.timeout()`；测试把 `generateText` 挂成永不 resolve 的 Promise。 +- 根因：Node 的 `AbortSignal.timeout()` 内部计时器始终 unref，空事件循环会在 abort 前排空。测试运行器判 `cancelledByParent`，同文件后三条用例一并取消。验收只看了 `# fail`，没看 `# cancelled` 与退出码。 +- 修复：改为 `setTimeout` + `AbortController`（计时器保持 ref），返回 `{ signal, dispose }`；模型返回、校验完成或外部 abort 后 `clearTimeout` 并移除监听。超时仍走 `template:model_error`。 +- 验证：`rectification-adopt-narration-20260904` 超时用例不再 cancelled；新增「调用完不留活跃计时器」用例；源码不含 `AbortSignal.timeout`。定向套件与该文件摘要须含完整六行且 `# cancelled 0`、退出码 0。 +- 防复发：采用旁白超时不得再用 `AbortSignal.timeout`。验收必须贴 Node 摘要完整六行（tests / pass / fail / cancelled / skipped / todo）与进程退出码，不得只报 `# fail 0`。 +- 相关记录：BUG-522 +- 复发自：BUG-522 +- 修复版本：待发布 diff --git a/docs/tasks/PROGRESS-rectification-adopt-narration-fix-20260904.md b/docs/tasks/PROGRESS-rectification-adopt-narration-fix-20260904.md index 08f2f00d..471e78c1 100644 --- a/docs/tasks/PROGRESS-rectification-adopt-narration-fix-20260904.md +++ b/docs/tasks/PROGRESS-rectification-adopt-narration-fix-20260904.md @@ -30,3 +30,23 @@ - `npm run lint`：0 error，74 warning（既有） - `rectification-adopt-narration-20260904` 10/10；与 answer-choice / collect-stall / provisional-adopt 合计 66/66 - `tests/rectification-*.test.ts tests/agentic-rectification-*.test.ts tests/birth-time-rectification-contract.test.ts`：871 pass / 0 fail（基线 869 + 本单 2 条诊断/超时测试） + +## 更正（2026-09-04 · 修复单 2） + +上面「10/10、871 pass / 0 fail」与实测不符。`AbortSignal.timeout()` 的计时器是 unref 的；超时用例把 `generateText` 挂死后事件循环排空，运行器把该条及同文件后三条标成 `cancelledByParent`。 + +任务书在 Node 20.19 / CI Node 22 上的实测（完整六行）： + +``` +# tests 10 +# pass 6 +# fail 0 +# cancelled 4 +# skipped 0 +# todo 0 +exit=1 +``` + +定向套件 `rectification-* / agentic-rectification-* / birth-time-*`：tests 871，pass 858，fail 0，cancelled 4，exit=1。 + +本机 Node 24.15.0 用 `tsx --test` 时 tsx IPC 会撑住事件循环，看起来像 10/10；独立脚本 `AbortSignal.timeout(30)` + 永不 settle 的 `Promise.race` 仍以退出码 13 结束，abort 从未触发。根因与修复见 `TASK-rectification-adopt-narration-fix2-20260904.md` / BUG-523。 diff --git a/docs/tasks/PROGRESS-rectification-adopt-narration-fix2-20260904.md b/docs/tasks/PROGRESS-rectification-adopt-narration-fix2-20260904.md new file mode 100644 index 00000000..72b959c9 --- /dev/null +++ b/docs/tasks/PROGRESS-rectification-adopt-narration-fix2-20260904.md @@ -0,0 +1,90 @@ +# PROGRESS · 采用旁白超时改为可清理的 ref 计时器（2026-09-04） + +工作树：`.worktrees/rectification-adopt-narration-fix2-20260904` +分支：`codex/rectification-adopt-narration-fix2-20260904` +基线：任务书写 `13dded9f`；本工作树从当时 `origin/staging` `5c9e9879`（修复单 2 文档提交）拉出。 +任务书：`docs/tasks/TASK-rectification-adopt-narration-fix2-20260904.md` +未改决策逻辑、未改提示词、未改 Python、未 bump Skill。未提交、未 push。 + +| 任务 | 状态 | BUG | +| --- | --- | --- | +| 5.1 超时改为可清理的 ref 计时器 | 完成 | BUG-523 | + +## 开工复现 + +本机 Node 24.15.0。`tsx --test` 因 IPC socket 撑住事件循环，超时用例看起来能过。独立脚本复现了 unref 计时器： + +``` +const s = AbortSignal.timeout(30); +await Promise.race([new Promise(() => {}), new Promise((_, rej) => s.addEventListener("abort", () => rej(s.reason)))]); +# abort 从未触发 +exit=13 +``` + +任务书在 Node 20.19 / CI Node 22 上的套件实测见 `PROGRESS-rectification-adopt-narration-fix-20260904.md` 更正节（pass 6 / cancelled 4 / exit 1）。 + +## 实现要点 + +- `composedAbortSignal` 返回 `{ signal, dispose }`：`setTimeout` + `AbortController`（不 unref）；外部 `signal` 的 abort 转发到 controller；`dispose()` `clearTimeout` 并移除外部监听。 +- `whenAborted` 同样返回 `dispose`，在 `finally` 里与 composed 一起清掉 abort 监听。 +- `deliverAdoptNarration` 的 `Promise.race` 包在 `try / finally`；超时仍走 `template:model_error`。 +- 源码不再出现 `AbortSignal.timeout`。 + +## 偏离 + +无。5.3 婚恋标签仍按修复单 1 推迟。 + +## 测试 + +`npx`/`tsx --test tests/rectification-adopt-narration-20260904.test.ts`： + +``` +# tests 11 +# pass 11 +# fail 0 +# cancelled 0 +# skipped 0 +# todo 0 +exit=0 +``` + +（Node spec 报告器打印为 `ℹ tests` 等六行，含义相同。比修复前多 1 条「调用完不留活跃计时器」。） + +`tsc --noEmit`：0 错，exit=0。 + +`npm run lint`：0 error，74 warning（既有），exit=0。 + +定向套件 `tests/rectification-*.test.ts tests/agentic-rectification-*.test.ts tests/birth-time-rectification-contract.test.ts`： + +``` +# tests 872 +# pass 872 +# fail 0 +# cancelled 0 +# skipped 0 +# todo 0 +exit=0 +``` + +（基线任务书写 871；本单 +1 条计时器用例。） + +`npm test`（全量 `tests/*.test.ts`；本机有 Docker，无 ENOENT 基线那 25 条）： + +``` +# tests 2641 +# pass 2641 +# fail 0 +# cancelled 0 +# skipped 0 +# todo 0 +exit=0 +``` + +## 改动文件 + +- `frontend/src/lib/rectification-agentic/v9/adopt-narration-agent.ts` +- `frontend/tests/rectification-adopt-narration-20260904.test.ts` +- `docs/BUG_HISTORY.md`（BUG-523） +- `docs/tasks/PROGRESS-rectification-adopt-narration-fix-20260904.md`（更正） +- `docs/tasks/README.md` +- 本文件 diff --git a/docs/tasks/README.md b/docs/tasks/README.md index 1a5b21ee..e12d12c0 100644 --- a/docs/tasks/README.md +++ b/docs/tasks/README.md @@ -46,7 +46,7 @@ | `TASK-rectification-uncertainty-stop-20260903.md` | — | 不确定度停止规则加样本下限 | 已验收 | `0c0df426`（BUG-503） | | `TASK-rectification-adopt-narration-20260904.md` | `PROGRESS-rectification-adopt-narration-20260904.md` | 探针池耗尽时采用卡旁白改 Agent 生成 + 已丢弃探针绕过 BUG-472 早退 + 区分题答否关线 | 已验收（4.1.4 点选入口未通过，见修复单） | `0aaa0d70`（BUG-519/520） | | `TASK-rectification-adopt-narration-fix-20260904.md` | `PROGRESS-rectification-adopt-narration-fix-20260904.md` | 采用旁白 Agent 在点选入口从不运行（早退分支重算过期决策）+ 校验器/可观测/超时 | 已验收（5.1/5.2 实现通过；超时测试挂死事件循环，见修复单 2） | `13dded9f`（BUG-521/522） | -| `TASK-rectification-adopt-narration-fix2-20260904.md` | — | 采用旁白超时用了 unref 的 `AbortSignal.timeout`，测试挂死取消同文件后三条用例，门禁 `npm test` 退出码 1 | 待执行 | 基线 `13dded9f`，BUG-523 起 | +| `TASK-rectification-adopt-narration-fix2-20260904.md` | `PROGRESS-rectification-adopt-narration-fix2-20260904.md` | 采用旁白超时用了 unref 的 `AbortSignal.timeout`，测试挂死取消同文件后三条用例，门禁 `npm test` 退出码 1 | 待验收 | 基线 `5c9e9879`（任务书写 `13dded9f`），BUG-523 | | `TASK-rectification-ux-20260902.md` | `PROGRESS-rectification-ux-20260903.md` | 会话面空白假死与交互摩擦 | 已验收 | `d159f08e`（09-03 在新基线重做后合入，BUG-505～509） | ### 聊天主链路与首页 diff --git a/frontend/src/lib/rectification-agentic/v9/adopt-narration-agent.ts b/frontend/src/lib/rectification-agentic/v9/adopt-narration-agent.ts index fb3998c1..4b63f116 100644 --- a/frontend/src/lib/rectification-agentic/v9/adopt-narration-agent.ts +++ b/frontend/src/lib/rectification-agentic/v9/adopt-narration-agent.ts @@ -33,24 +33,63 @@ export type AdoptNarrationDelivery = Readonly<{ adopt_narration: AdoptNarrationOutcome; }>; +type DisposableAbort = Readonly<{ + signal: AbortSignal; + dispose: () => void; +}>; + function composedAbortSignal( signal: AbortSignal | undefined, timeoutMs: number, -): AbortSignal { - const timeout = AbortSignal.timeout(timeoutMs); - return signal ? AbortSignal.any([signal, timeout]) : timeout; +): DisposableAbort { + const controller = new AbortController(); + // Must stay ref'd. The platform timeout signal uses an unref timer, so a hanging + // generateText lets the event loop drain before abort (BUG-523). + const timeoutId = globalThis.setTimeout(() => { + if (!controller.signal.aborted) { + controller.abort(new DOMException("adopt narration timed out", "TimeoutError")); + } + }, timeoutMs); + const onExternalAbort = () => { + if (!controller.signal.aborted) { + controller.abort(signal?.reason ?? new DOMException("aborted", "AbortError")); + } + }; + if (signal) { + if (signal.aborted) onExternalAbort(); + else signal.addEventListener("abort", onExternalAbort); + } + return { + signal: controller.signal, + dispose: () => { + globalThis.clearTimeout(timeoutId); + signal?.removeEventListener("abort", onExternalAbort); + }, + }; } -function whenAborted(signal: AbortSignal): Promise { - return new Promise((_, reject) => { - if (signal.aborted) { +function whenAborted(signal: AbortSignal): { + promise: Promise; + dispose: () => void; +} { + let onAbort: (() => void) | undefined; + const promise = new Promise((_, reject) => { + const fail = () => { reject(signal.reason ?? new Error("aborted")); + }; + if (signal.aborted) { + fail(); return; } - signal.addEventListener("abort", () => { - reject(signal.reason ?? new Error("aborted")); - }, { once: true }); + onAbort = fail; + signal.addEventListener("abort", fail, { once: true }); }); + return { + promise, + dispose: () => { + if (onAbort) signal.removeEventListener("abort", onAbort); + }, + }; } export function logAdoptNarrationOutcome(outcome: AdoptNarrationOutcome): void { @@ -117,14 +156,15 @@ export async function deliverAdoptNarration(input: { logAdoptNarrationOutcome(delivery.adopt_narration); return delivery; } - const signal = composedAbortSignal( + const composed = composedAbortSignal( input.signal, input.timeoutMs ?? ADOPT_NARRATION_TIMEOUT_MS, ); + const aborted = whenAborted(composed.signal); try { const text = await Promise.race([ - generate(input.facts, signal), - whenAborted(signal), + generate(input.facts, composed.signal), + aborted.promise, ]); const checked = validateAdoptNarration(text, input.facts); if (!checked.ok) { @@ -145,6 +185,9 @@ export async function deliverAdoptNarration(input: { const delivery = { text: input.fallback, adopt_narration: "template:model_error" as const }; logAdoptNarrationOutcome(delivery.adopt_narration); return delivery; + } finally { + aborted.dispose(); + composed.dispose(); } } diff --git a/frontend/tests/rectification-adopt-narration-20260904.test.ts b/frontend/tests/rectification-adopt-narration-20260904.test.ts index 9313fc9b..eaf75fe0 100644 --- a/frontend/tests/rectification-adopt-narration-20260904.test.ts +++ b/frontend/tests/rectification-adopt-narration-20260904.test.ts @@ -943,6 +943,49 @@ test("adopt narration times out to the template without throwing", async () => { assert.equal(timed.text, fallback); }); +test("adopt narration does not leave an active timeout after the model returns", async () => { + const dossier = caseDossier(); + const decision = decideFromDossier(dossier, { birthDate: "1997-08-08" }); + const facts = adoptDeliveryFacts(decision, dossier); + const fallback = "剩下的问题分不开 05:00 和 05:06。可以从下面选一个先用着。"; + const kept = "剩下的问题分不开 05:00 和 05:06。范围是 05:00 到 05:06。采用后会用 2016 年学业核对。"; + const source = readFileSync( + new URL("../src/lib/rectification-agentic/v9/adopt-narration-agent.ts", import.meta.url), + "utf8", + ); + assert.doesNotMatch(source, /AbortSignal\.timeout/); + assert.match(source, /clearTimeout/); + + const pending = new Set(); + let created = 0; + const realSetTimeout = globalThis.setTimeout; + const realClearTimeout = globalThis.clearTimeout; + globalThis.setTimeout = ((handler: TimerHandler, delay?: number, ...args: unknown[]) => { + created += 1; + const id = realSetTimeout(handler, delay, ...args); + pending.add(id); + return id; + }) as typeof setTimeout; + globalThis.clearTimeout = ((id?: ReturnType) => { + pending.delete(id); + realClearTimeout(id); + }) as typeof clearTimeout; + try { + const delivered = await deliverAdoptNarration({ + facts, + fallback, + timeoutMs: 8_000, + generateText: async () => kept, + }); + assert.equal(delivered.adopt_narration, "agent"); + assert.ok(created >= 1); + assert.equal(pending.size, 0); + } finally { + globalThis.setTimeout = realSetTimeout; + globalThis.clearTimeout = realClearTimeout; + } +}); + test("applyCollectFocusDenial on the family collect uses the same adopt template", async () => { const dossier = caseDossier(); let loads = 0;