Skip to content

fix(service-automation): 降级版挂起态读取器的 warn cause 移出 message,改走 meta (#6230) - #6297

Merged
hotlong merged 1 commit into
mainfrom
claude/issue-6230-degraded-load-log-meta
Aug 7, 2026
Merged

fix(service-automation): 降级版挂起态读取器的 warn cause 移出 message,改走 meta (#6230)#6297
hotlong merged 1 commit into
mainfrom
claude/issue-6230-degraded-load-log-meta

Conversation

@hotlong

@hotlong hotlong commented Aug 7, 2026

Copy link
Copy Markdown
Contributor

Fixes #6230

前提复核(先做的事)

issue 正文按 1549605f6 写的是 :2931。本次在 origin/main dbe92a7e1按内容定位,方法定义仍在 engine.ts:2931(#6228 昨日的改动落在同文件更靠后的 :3036,没有推动这一段),logger.warn:2935,文本逐字一致:

`[automation] failed to load suspended run '${runId}' from durable store: ${(err as Error).message}`

前提成立,行号也没漂。 (err as Error).message 来自 loadSuspendedRunStrict 底下的数据源驱动,与 #5912 是同一个 thrown 值 —— 我们不控制它有几行。

顺带复核了正文的三条断言,均成立:

  1. 危害多一档:ObjectLogger.write()isErrorLevel 分流,warnstdout(packages/core/src/logger.ts:341-343);BootLogCapture.offer() 对每个物理行先跑 isBootDiagnostic,拿不到级别头就 return —— 丢弃,不是降级保留(packages/cli/src/utils/boot-log-capture.ts)。
  2. boot 期真实可达:plugin.ts start()rearmSuspendedWaitTimers → 对 overdue 运行 engine.resume(run.runId)(builtin/wait-node.ts)→ resume() 先跑 refuseGatedResumeresolveEffectiveSuspension这个降级版读取器
  3. warn 是第二参:Logger 契约 warn(message, meta?)(packages/spec/src/contracts/logger.ts:29),与 error(message, error?, meta?) 不同 —— warn 没有 Error 槽。这是照抄 PR fix(service-automation): resumeInternal 存储不可达的日志 cause 移出 message,改走 meta (#5912) #6228 唯一会抄错的地方,单独一条用例钉住。

危害(实测,不是推演)

反向验证跑出来的两个读数:

  • 一个三行 better-sqlite3 驱动错误把这条告警切成 3 个物理行,只有第 1 行带 WARN 头;
  • 这 3 行过 boot-quiet 过滤后只留下 1 行 —— 而留下的那一行恰恰不含任何驱动事实。后 2 行被 offer() 直接丢弃。

第二个读数就是本单相对 #5912 多出来的那一档:#5912error/stderr,被误读;这条是 warn/stdout,被误读 + boot 期被丢弃

改法(同族第七次套既定模板,零新词汇)

复用同包 thrown-cause-diagnostics.tsdescribeThrownForLog(engine.ts 已有该 import):

  • message 单行自足,cause 走 warn(message, meta?)第二参;
  • 未新增任何 meta 字段名:直接用 helper 自己的 error / issues,天然不含 key/token/secret/password 子串(finding(core): ObjectLogger 的脱敏表按子串匹配,一个叫 keys 的普通字段会被整块换成 ***REDACTED*** #5573);
  • 补上后果句(issue 正文判为同一改动的自然范围,分诊评论采纳):原文本只说「读失败」,没说读失败被翻译成了什么。新文本写明这条 best-effort 读降级为 null,调用方(resume gate、screen 取数)看到的与「本来就没有这个挂起运行」完全一样,而运行本身未被触碰、仍停在原处;并指明严格读会报 STORE_UNAVAILABLE 而不降级。

刻意不动的一处(已钉上回归测试)

级别仍是 warn#4632 的判据,这是一个刻意的功能性降级读取器 —— 它的 JSDoc 写明服务于「只需要 best-effort 答案」的顺带读取方,真正需要区分「存储挂了」与「运行没了」的 resumeInternal 用的是严格版。上调到 error 会在整个故障期间对每次 gate 查询报警,正是 #4632 明确警告的镜像误用。the level is not raised 一条用例钉住(同时断言 stderr 为空)。

⛔ 未扩面:resumeInternal(#6228 已治)与返回值信封字段一行未动。

反向验证 —— 方向先声明,再跑

预判:还原被删的拼接肢(cause 塞回 message、去掉 meta 第二参)⇒ 7 条拼接/行数/丢弃/参数槽钉转红;2 条保持绿 —— the level is not raised(还原不改级别)与 still degrades to null(还原不改行为),后者不动正是它们存在的意义,不是漏测。

实跑,与预判逐条相符(7 红 2 绿):

× the driver's multi-line failure never reaches the log message
    AssertionError: expected '[automation] failed to load suspended…' not to contain '\n'
× stays one physical line in `pretty`, the format `os dev` / `os serve` default to
    AssertionError: expected [ …(3) ] to have a length of 1 but got 3
× survives `serve`'s boot-quiet filter whole — the drop this seam's level exposes it to
    AssertionError: nothing this seam emitted is dropped: expected [ Array(1) ] to deeply equal [ …(3) ]
× hands the cause to warn(message, meta) — the second slot, not the third
    AssertionError: the seam logged at warn level: expected undefined to be defined
× renders a single-line driver failure in exactly the same shape — the fix is unconditional
    AssertionError: expected undefined to be 'connection refused'
× emits exactly one clean record per stream, and the driver text is in neither message
× both records survive the boot-quiet filter — the boot path this is reachable from
✓ the level is not raised — a best-effort read degrading is #4632 FUNCTIONAL, not durability
✓ still degrades to null — the fix is to the record, not to the behaviour

Tests  7 failed | 2 passed (9)

1 → 3 是危害本身的读数;Array(1) vs …(3)丢弃的读数 —— 3 行进过滤器,1 行出来。

测试

新增 packages/services/service-automation/src/degraded-suspended-run-load-log-cause.test.ts(9 例)。断言在真实 ObjectLogger 的真实字节上读(#5662 / #5661 / #5737 / #5912 的先例):spy 只用在「参数槽本身就是待验事实」的那一条。

三点与 PR #6228 不同,都是本单形态决定的:

  1. 抓的是 stdout,不是 stderr。fix(service-automation): resumeInternal 存储不可达的日志 cause 移出 message,改走 meta (#5912) #6228 靠「只抓 stderr」把它的接缝与本条 warn 隔开;本单反过来。主路径走 getSuspendedScreen() —— 到这个降级读取器最干净的公开入口,一次调用一条记录,所以物理行计数是这一条记录自己的读数。
  2. boot-quiet 丢弃语义钉住了(issue 说「若可低成本钉住则钉」)。bootFilterRetains() 就地复述 classifyBootLogLine + isBootDiagnostic 的判据 —— 本包不能依赖 @objectstack/cli,而这个判据本来就是所有按行消费者共用的那个。这样「丢弃」是被量到的,不是在正文里描述的。
  3. 多一组「同一次失败的两条记录」用例:resume() 同时走两个 catch,现在 stdout 一条干净 warn、stderr 一条干净 error,两条都过 boot 过滤。这是 finding(service-automation): engine.ts 的 resumeInternal 把驱动错误插进 message —— #5737 修完后,这条 resume 路径上仅剩的一处外来 cause 拼接 #5912finding(service-automation): engine.ts 的 loadSuspendedRun 把驱动错误插进 warn 的 message —— 与 #5912 同文件、同一次失败的另一半,且这条会被 boot 缓冲丢弃 #6230 单独任何一单都取不到的整条路径读数。

未引入任何新的 fake ObjectQL engine(用的是手写 SuspendedRunStore,delete(runId) 是该 store 契约、不是 IDataEngine),因此不涉及 assertEngineDeleteDispatch;pnpm check:engine-double-contract 仍绿。

pnpm --filter @objectstack/service-automation test
  Test Files  68 passed (68)
       Tests  806 passed (806)          # 67/797 -> +1 文件 / +9 例

pnpm --filter @objectstack/service-automation build          ✓ DTS Build success
npx tsc --noEmit -p tsconfig.json  ⇒ 5 errors(3 nested-region-parity.test.ts + 2 engine.test.ts)
  —— 与 check-type-check-coverage.mjs 的 DEBT 台账 errors: 5 逐条吻合,本 PR 新增文件贡献 0

pnpm check:durability-log-level      ✓ 24 durability-critical catch seam(s), all loud
                                     ✓ read-seam invention: 64 seam(s), none invents an unreported empty answer
pnpm check:startup-registry-verdict  ✓ 40 seam(s), none recording a contradictable verdict
pnpm check:engine-double-contract    ✓ 77 pinned, 133 DEBT, 2 exempt
pnpm check:resume-authority-declared ✓ 6/6
pnpm check:error-code-casing         ✓ 3122 file(s), ADR-0112
pnpm check:empty-changeset           ✓ 1 declaring changeset(s) added
pnpm check:nul-bytes                 ✓ OK (5963 tracked text file(s), no raw ASCII control bytes)

一个过程中的教训(已在代码里结构性堵掉)

写 boot 过滤器的 SGR 剥离时,编辑工具把源码里的一个 backslash-u001B 形式的转义物化成了真实的 0x1B 控制字节 —— 正是在「写关于控制字符的代码」时发生的那个事故形态(#4890 / PR #5140)。自扫(grep -naP '[\x00-\x08\x0b\x0c\x0e-\x1f\x7f]')当场抓到并修掉了。修法不是把转义再写一遍,而是换一种写不出控制字节的写法:

const SGR = new RegExp(`${String.fromCharCode(0x1b)}\\[[0-9;]*m`, 'g');

check:nul-bytes 现在绿,自扫也绿。

Changeset

changeset(@objectstack/service-automation: patch),不走 skip-changeset:与 PR #6228 同型判断 —— 这不是纯测试 / 纯 workflow 改动,而是运维可见的日志形状变更(按记录末尾驱动文本字面量 grep 这条记录的查询,需要改成读记录的 error 字段)。同族前六单无一例外都写了 changeset。

顺带发现(未在本 PR 修,已另开单)

同文件还有三处完全同形logger.warn 拼接,分别在 forgetSuspendedRun / cancelRun / listSuspendedRunsDurable。它们在其它方法、其它分支上,分诊评论已把本单范围钉死在 loadSuspendedRun 一处,故按 Prime Directive #10 / objectstack#4949 单开为 observation-class finding,未在此 PR 顺手扩面 —— 见下方评论里的 issue 号。


Generated by Claude Code

)

`engine.ts` 的 `loadSuspendedRun`(`loadSuspendedRunStrict` 的降级版读取器)在
catch 里把数据源驱动自己的失败文本插进了 `logger.warn` 的 message。
`ObjectLogger.write()` 一次调用只加一个「时间戳 + 级别」记录头,message 里的
换行把一条记录切成多个物理行,后几行无级别无时间戳。

这条比 #5912(PR #6228)那条多一层危害:`warn` 走 stdout,`serve` 的 boot-quiet
窗口只包了 `process.stdout.write`,`BootLogCapture.offer()` 仅保留带级别头的
物理行 —— 无头续行被直接丢弃,不只是被误读;且 boot 期真实可达
(plugin.ts start() -> rearmSuspendedWaitTimers -> engine.resume -> gate)。

实测:三行 better-sqlite3 驱动错误把这条告警切成 3 个物理行,过 boot 缓冲过滤
后只剩 1 行,而留下的那行不含任何驱动事实。

改法与同族前六单一致,零新词汇:message 单行自足并补上后果句(读失败被翻译成
null,调用方看到的与「本来就没有这个挂起运行」完全一样),cause 走 `Logger`
契约 `warn(message, meta?)` 的第二参 —— 与 `error` 的第三参不同,warn 没有
Error 槽。级别刻意仍是 `warn`:这是功能性降级(#4632),上调才是镜像误用。

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_015a5qkLzpGXhLL2F5gvJ7dD
@vercel

vercel Bot commented Aug 7, 2026

Copy link
Copy Markdown

The latest updates on your projects. Learn more about Vercel for GitHub.

1 Skipped Deployment
Project Deployment Actions Updated (UTC)
objectstack Ignored Ignored Aug 7, 2026 1:24pm

Request Review

@github-actions github-actions Bot added the size/m label Aug 7, 2026
@github-actions

github-actions Bot commented Aug 7, 2026

Copy link
Copy Markdown
Contributor

📓 Docs Drift Check

This PR changes 1 package(s): @objectstack/service-automation.

5 hand-written doc(s) reference the affected code and may need an implementation-accuracy re-verification:

  • content/docs/automation/flows.mdx (via @objectstack/service-automation)
  • content/docs/kernel/services-checklist.mdx (via @objectstack/service-automation)
  • content/docs/plugins/packages.mdx (via @objectstack/service-automation)
  • content/docs/releases/implementation-status.mdx (via @objectstack/service-automation)
  • content/docs/releases/v9.mdx (via @objectstack/service-automation)

Advisory only. To re-verify, run the docs-accuracy-audit workflow scoped to these files:
node scripts/docs-audit/affected-docs.mjs origin/main → pass the list as args.docs.

hotlong commented Aug 7, 2026

Copy link
Copy Markdown
Contributor Author

顺带发现的 issue 号

正文最后一节提到的三处同形拼接,已单开为 #6299(observation-class,finding 标签、pm:queue、未指派 —— 按 objectstack#4949 的分级交 PM 定级)。

开单前按 objectstack#4949 做了检索(关键字 + 方法名 + 文件路径,is:open),仅命中 #6230 本身,无孪生单。

⚠️ 单里特意写了一条给接手人的警告:那三条不能把本 PR 的模板套三遍。message 拼接那一半三条共通,级别那一半不是 —— forgetSuspendedRunstore.delete() 失败发生在 this.suspendedRuns.delete() 之后,挂起态没被消费却已离开热缓存,看起来更像 #4632耐久性形态,与本 PR「功能性降级、warn 正确」的判定不同,必须逐条重判。


Generated by Claude Code

@hotlong
hotlong marked this pull request as ready for review August 7, 2026 13:28
@hotlong
hotlong enabled auto-merge August 7, 2026 13:29
@hotlong
hotlong added this pull request to the merge queue Aug 7, 2026
Merged via the queue into main with commit 6517448 Aug 7, 2026
24 checks passed
@hotlong
hotlong deleted the claude/issue-6230-degraded-load-log-meta branch August 7, 2026 13:48
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

documentation Improvements or additions to documentation size/m tests tooling

Projects

None yet

2 participants