From 71fc5d5d14c5a14e2fe1c47db1d35511769e8c30 Mon Sep 17 00:00:00 2001 From: Claude Code Date: Thu, 6 Aug 2026 02:57:09 +0000 Subject: [PATCH 1/2] fix(service-automation): route the three startup seams' causes to structured meta (#5661) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `registerRunObject` (warn), the boot `probe()` (error) and the wait-timer re-arm (error) each interpolated a FOREIGN error's text into the log MESSAGE. They are the fourth instalment of the family #5048 / #5575 / #5636 closed, and were out of all three scopes. `ObjectLogger.write()` emits one timestamp+level record head per call, so a message carrying newlines becomes several physical lines of which only the first is attributable. The two `error` seams exist precisely to be read — #4632 raised them so an operator could find them — and the `warn` one runs in `init()`, inside `serve`'s boot-quiet window, where `BootLogCapture.offer()` DROPS a head-less line rather than merely mangling it. All three now log a newline-free, self-sufficient message and hand the cause to `describeThrownForLog`, in the slot the `Logger` contract names: `warn`'s second argument, `error`'s third. #4632's required consequence-and-fix text stays in the first line; only the trailing interpolation is replaced by a pointer to the meta. `check:durability-log-level` stays green (24 seams; neither `error` demoted). Tests: new `plugin-startup-log-cause.test.ts` (13 cases) reads real bytes off a real `ObjectLogger` per the #5662 precedent, pinning per seam that a multi-line cause reaches meta and not the message, the argument slot, and that a cause-less boot writes zero bytes; two closing cases render the old and new shapes side by side and measure the difference. The #4420 probe case in `plugin-suspended-run-wiring.test.ts` is re-judged rather than re-spelled: it now asserts both directions, since a message-only assertion would also pass if the cause were dropped entirely. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01BWS4heBoAitLmzCLhcYdbK --- .changeset/plugin-startup-log-cause.md | 54 ++ .../src/plugin-startup-log-cause.test.ts | 530 ++++++++++++++++++ .../src/plugin-suspended-run-wiring.test.ts | 45 +- .../services/service-automation/src/plugin.ts | 46 +- 4 files changed, 667 insertions(+), 8 deletions(-) create mode 100644 .changeset/plugin-startup-log-cause.md create mode 100644 packages/services/service-automation/src/plugin-startup-log-cause.test.ts diff --git a/.changeset/plugin-startup-log-cause.md b/.changeset/plugin-startup-log-cause.md new file mode 100644 index 0000000000..e221abf84a --- /dev/null +++ b/.changeset/plugin-startup-log-cause.md @@ -0,0 +1,54 @@ +--- +"@objectstack/service-automation": patch +--- + +fix(service-automation): 启动路径三条日志改用结构化 `meta`,message 保持单行 (#5661) + +## 接缝 + +`AutomationServicePlugin` 里还有三处把**外来**错误的文本插进日志 message —— 与 +#5048(flow 绑定)、#5575(`reconcileDeclaredConnectors` 的 `fail()`)、#5636 +(`degradeConnectorInstance`)同一类,是那三单范围之外的第四组: + +- **`registerRunObject`**(`warn`):`err` 来自内核服务注册表(`ctx.getService('manifest')` + 或 `manifest.register()` 的解析拒绝),文本不是我们的。 +- **启动 probe**(`error`):`err` 来自 `candidate.probe()`,即**数据源驱动**抛出的错误。 +- **重启后 wait-timer 重新挂载**(`error`):`err` 是从 `rearmSuspendedWaitTimers` 逃出来 + 的任何东西。 + +## 为什么后两条尤其值得改 + +它们的**存在理由**就是可读性。代码自己写明后果 —— 「suspended runs will NOT survive a +restart」「every wait/approval paused before this restart will hang indefinitely」—— 并被 +#4632 特意定为 `error` 级,好让运维能找到。而 `ObjectLogger.write()` 一次调用只加一个 +「时间戳 + 级别」记录头,所以带换行的 message 会变成多个物理行、只有第一行有头:文件 sink +把其余行当成独立记录存,采集端读成无法归属的碎片,`grep ERROR` 只捞到那条不含任何事实的 +头行。这个 plugin 里最响的耐久性告警,恰好是最可能以读不懂的形态抵达的那一条。 + +第一条的危害是另一种,并且是测出来的:`warn` 走 **stdout**,正是 `serve` 启动静默窗口包住 +的那条流,而 `BootLogCapture.offer()` 只在该物理行上找得到级别头时才保留它 —— 所以续行是 +被**直接丢弃**,不只是难解析。`registerRunObject` 在 `init()` 里跑,正处于窗口开着的时候。 + +## 改法(零新词汇) + +三处都复用同包 `thrown-cause-diagnostics.ts` 的 `describeThrownForLog`:message 是不含换行 +的自足句子,cause 走 logger 的结构化 meta。参数位按 `Logger` 契约区分 —— +`warn(message, meta?)` 没有 `Error` 位,cause 在**第二**参;`error(message, error?, meta?)` +的 cause 在**第三**参(第二参塞原始 error 会让记录额外附带堆栈)。#4632 要求的「后果 + 修 +法」仍然完整留在 message 的第一行里,只是末尾的 `: ${err.message}` / `Cause: ${err.message}` +换成了指向 meta 的一句话。 + +`pnpm check:durability-log-level` 仍绿:24 个耐久性接缝,三处 `error` 未降级、未改成 rethrow。 + +## 测试 + +新增 `plugin-startup-log-cause.test.ts`:13 个用例全部让真 `ObjectLogger` 写真字节再读回来 +(照 #5662 的先例 —— spy 只能证明接缝**调用**了什么,证明不了按行消费者会**看到**什么,而 +后者才是 cloud#971 付掉一整条 rc 线的那一半)。三条接缝各自钉住「多行 cause 不进 message、 +进结构化 meta」、参数位、以及无 cause 时输出零字节;末尾两个用例把插值形态与结构化形态并排 +渲染、量出差别(`warn` 侧:一次调用多个物理行、启动缓冲只留下止于 Zod `[` 的那一行;`error` +侧:一条记录散成三个碎片,后两行无记录头)。 + +`plugin-suspended-run-wiring.test.ts` 里那条 #4420 的 probe 用例做了重新裁决而不是重新拼写: +它原来断言驱动文本出现在 message 里,现在双向断言 —— message 里**没有**、meta 里**有**。 +单向的断言在 cause 被整个丢掉时也会通过。 diff --git a/packages/services/service-automation/src/plugin-startup-log-cause.test.ts b/packages/services/service-automation/src/plugin-startup-log-cause.test.ts new file mode 100644 index 0000000000..d4c6d07927 --- /dev/null +++ b/packages/services/service-automation/src/plugin-startup-log-cause.test.ts @@ -0,0 +1,530 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// Regression: #5661 — the three STARTUP seams of `AutomationServicePlugin` that +// still interpolated a FOREIGN error's text into the log MESSAGE. +// +// They are the fourth instalment of the family #5048 (flow binding, PR #5572), +// #5575 (`reconcileDeclaredConnectors`'s `fail()`, PR #5639) and #5636 +// (`degradeConnectorInstance`, PR #5662) closed, and were out of all three +// scopes: +// +// 1. `registerRunObject` — `warn`, cause from the kernel service registry; +// 2. the boot `probe()` — `error`, cause from the DATASOURCE DRIVER; +// 3. the wait-timer re-arm — `error`, cause from whatever escapes +// `rearmSuspendedWaitTimers`. +// +// ## Why 2 and 3 are the worst possible records to shred +// +// Unlike the flow-bind seams, these two exist *because* somebody has to read +// them. Their own comments state the consequence — "suspended runs will NOT +// survive a restart", "every wait/approval paused before this restart will hang +// indefinitely" — and they were deliberately raised to `error` by #4632 so an +// operator can find them. `ObjectLogger.write()` emits one +// ` ` record per call, so a message carrying newlines +// becomes several physical lines of which only the first has a level head: +// a file sink stores the rest as their own records, a shipper reads them as +// unattributable fragments, and `grep ERROR` returns the one line that holds no +// facts. The loudest durability warning in this plugin was the one most likely +// to arrive unreadable. +// +// Seam 1 has the *other* harm, and it is measured rather than assumed at the +// bottom of this file: `warn` goes to **stdout**, which is the stream `serve`'s +// boot-quiet window wraps, and `BootLogCapture.offer()` retains a physical line +// only when `classifyBootLogLine` finds a level head on it — so a continuation +// line there is DROPPED, not merely mangled. `registerRunObject` runs in +// `init()`, i.e. squarely inside that window. +// +// ## The fix +// +// Identical to the three prior instalments, zero new vocabulary: a static, +// newline-free message plus `describeThrownForLog(err)` in the logger's +// structured slot. Which slot depends on the level, per the `Logger` contract +// (`packages/spec/src/contracts/logger.ts`): `warn(message, meta?)` takes it +// SECOND, `error(message, error?, meta?)` takes it THIRD — the second slot +// would ship the thrown value's stack on the record (#5575). +// +// Every assertion below reads REAL BYTES off a REAL `ObjectLogger`, per the +// #5662 precedent: a spy proves what the seam *called*, not what a downstream +// line-splitter would *see*, and it was the latter that cost cloud#971 a +// release line. The spies appear only where the argument SLOT is the fact under +// test. + +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { ObjectLogger } from '@objectstack/core'; +import { AutomationServicePlugin } from './plugin.js'; +import type { SuspendedRunStoreEngine } from './suspended-run-store.js'; + +// ── the one injected seam, and why ───────────────────────────────────────── + +/** + * `rearmSuspendedWaitTimers` catches every failure it MODELS — the `store.list()` + * read, each overdue `resume()`, each `job.schedule()` — and reports them on its + * own `[wait]` records. So the plugin's `catch` around it is a net for what that + * function did *not* model, and no fixture built out of a real store and a real + * job service can reach it. That is a fact about the seam, not a gap in the + * test: it is defensive code whose log record still has to be correct the day + * something does escape. + * + * Rather than pretend otherwise with a fake that could never occur, the call is + * replaced — and only that call, the rest of the module is the real one — so the + * plugin's own `catch`, its own message and the real logger are all exercised + * against a thrown value we choose. + */ +const rearm = vi.hoisted(() => ({ thrown: undefined as unknown })); + +vi.mock('./builtin/index.js', async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + rearmSuspendedWaitTimers: async ( + ...args: Parameters + ) => { + if (rearm.thrown !== undefined) throw rearm.thrown; + return actual.rearmSuspendedWaitTimers(...args); + }, + }; +}); + +afterEach(() => { + rearm.thrown = undefined; + vi.restoreAllMocks(); +}); + +// ── fixtures ─────────────────────────────────────────────────────────────── + +/** + * What a database driver's failure looks like when it is not one line. Postgres + * (`error: … \n detail: … \n hint: …`) and better-sqlite3 wrappers both do + * this; the in-repo drivers happen to be single-line today, which is why #5661 + * is a `finding` and not an outage report. + */ +const MULTILINE_DRIVER = [ + 'SQLITE_ERROR: no such table: sys_automation_run', + ' at Database.prepare (better-sqlite3/lib/methods/wrappers.js:5:21)', + ' hint: run `os migrate` for this datasource, or set OS_SKIP_SCHEMA_SYNC=0', +].join('\n'); + +/** A job/scheduler failure with an embedded stack-shaped tail. */ +const MULTILINE_JOB = [ + "job service refused to schedule 'flow-wait:run_1:pause'", + ' cause: queue backend unreachable (ECONNREFUSED 127.0.0.1:6379)', + ' hint: is the queue running?', +].join('\n'); + +/** + * A `ZodError`-shaped rejection, duck-typed exactly as `describeThrownForLog` + * recognizes it. `manifest.register()` parses what it is handed, and its + * `.message` is a pretty-printed dump of `issues` whose FIRST line is the single + * character `[`. + */ +function zodLikeRejection(): Error { + const issues = [ + { code: 'unrecognized_keys', keys: ['defaultDatasource'], path: [], message: "Unrecognized key: 'defaultDatasource'" }, + { code: 'invalid_type', path: ['objects', 0, 'fields'], message: 'Invalid input: expected object' }, + ]; + const err = new Error(JSON.stringify(issues, null, 2)) as Error & { issues: unknown }; + err.issues = issues; + return err; +} + +/** + * Stands in for the `sys_automation_run` table, plus the `registry` the boot flow + * pull reads (without it, `syncFlowsFromObjectQL` emits its own — already + * #5048-correct — `warn`, which is noise in every capture below). + * + * `failProbe` fails ONLY the probe-shaped read: `ObjectStoreSuspendedRunStore` + * probes with `{ where: {}, limit: 1 }` and lists with + * `{ where: { status: 'paused' }, limit: 1000 }`. A real missing table fails + * both, and the second failure is reported by a DIFFERENT seam — `wait-node.ts`'s + * `[wait] … re-arm ABORTED … Cause: ${err.message}`, which still interpolates + * (out of this issue's scope, filed separately). Narrowing the fixture to the + * probe keeps these assertions about the seam they name instead of measuring + * someone else's record. + */ +function fakeDataEngine(opts: { failProbe?: string } = {}) { + const rows = new Map(); + const engine: SuspendedRunStoreEngine & { rows: Map; registry: unknown } = { + rows, + registry: { listItems: () => [] }, + async find(_object, options?: any) { + const isProbe = options?.limit === 1 && Object.keys(options?.where ?? {}).length === 0; + if (opts.failProbe && isProbe) throw new Error(opts.failProbe); + return []; + }, + async insert(_object, data) { rows.set(String(data.id), { ...data }); return data; }, + async update(_object, data) { rows.set(String(data.id), { ...data }); return data; }, + async delete() { return true; }, + }; + return engine; +} + +/** + * An `objectql` service that satisfies the boot flow pull and nothing else: no + * `find`/`insert`, so no durable store is built and the probe seam never runs. + * Used by the seam-1 cases, whose subject is `init()`. + */ +function registryOnlyObjectql() { + return { registry: { listItems: () => [] } }; +} + +/** A `manifest` service whose `register()` rejects what it is handed. */ +function rejectingManifest(thrown: unknown) { + return { register() { throw thrown; } }; +} + +/** A `manifest` service that accepts everything. */ +function acceptingManifest() { + const registered: any[] = []; + return { registered, register(m: any) { registered.push(m); } }; +} + +/** The slice of `PluginContext` this plugin's startup path touches. */ +function pluginCtx(services: Map, logger: ObjectLogger): any { + return { + logger, + getService(name: string) { + if (services.has(name)) return services.get(name); + throw new Error(`Service '${name}' not registered`); + }, + registerService(name: string, svc: unknown) { services.set(name, svc); }, + hook() {}, + async trigger() {}, + }; +} + +/** Capture everything written to one std stream while `fn` runs, split to lines. */ +async function captureStream(which: 'stdout' | 'stderr', fn: () => Promise): Promise { + const chunks: string[] = []; + const spy = vi.spyOn(process[which], 'write').mockImplementation(((c: string | Uint8Array) => { + chunks.push(String(c)); + return true; + }) as never); + try { + await fn(); + } finally { + spy.mockRestore(); + } + return chunks.join('').split('\n').filter((l) => l.length > 0); +} + +/** + * Run the plugin's full `init()` + `start()` against a real `ObjectLogger`. + * + * `level` doubles as the noise filter: at `'warn'` the plugin's many `info` + * lines never reach stdout, so a stdout capture contains the seam under test and + * nothing else; at `'error'` the same holds for stderr. + */ +async function bootPlugin(opts: { + manifest?: unknown; + objectql?: unknown; + level: 'warn' | 'error'; + format?: 'json' | 'pretty'; +}): Promise { + const services = new Map(); + if (opts.manifest) services.set('manifest', opts.manifest); + services.set('objectql', opts.objectql ?? registryOnlyObjectql()); + const logger = new ObjectLogger({ level: opts.level, format: opts.format ?? 'json' }); + const ctx = pluginCtx(services, logger); + const plugin = new AutomationServicePlugin(); + await plugin.init(ctx); + await plugin.start(ctx); +} + +/** + * `ObjectLogger`'s `pretty`/`text` record head — the same predicate + * `classifyBootLogLine` applies in `packages/cli/src/utils/boot-log-capture.ts`. + * Re-stated rather than imported: this package must not depend on + * `@objectstack/cli`, and the predicate is the general one every line-based + * consumer keys off, the CLI's buffer being the strictest example. + */ +const RECORD_HEAD = /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z(?: \|)? (DEBUG|INFO|WARN|ERROR|FATAL)\b/; + +/** + * `classifyBootLogLine`'s verdict, reduced to what matters here: a line either + * carries an `ObjectLogger` level head (retained by `BootLogCapture.offer()`) or + * it does not (dropped). + */ +function classifyLine(raw: string): string | null { + const line = raw.replace(/\u001B\[[0-9;]*m/g, '').trim(); + if (!line) return null; + if (line.startsWith('{')) { + try { + const rec = JSON.parse(line) as { level?: unknown; time?: unknown }; + return typeof rec.time === 'string' && typeof rec.level === 'string' ? String(rec.level) : null; + } catch { + return null; + } + } + const m = RECORD_HEAD.exec(line); + return m ? m[1].toLowerCase() : null; +} + +const MANIFEST_PREFIX = '[Automation] manifest service unavailable'; +const PROBE_PREFIX = '[Automation] sys_automation_run could not be read at startup'; +const REARM_PREFIX = '[Automation] suspended wait-timer re-arm FAILED after restart'; + +// ── seam 1: registerRunObject (`warn` → stdout, inside the boot window) ───── + +describe('#5661 — the manifest-unavailable warning is ONE stdout record', () => { + it('a rejection dump becomes structured issues, never a message spill', async () => { + const lines = await captureStream('stdout', () => + bootPlugin({ manifest: rejectingManifest(zodLikeRejection()), level: 'warn' }), + ); + + const mine = lines.filter((l) => l.includes(MANIFEST_PREFIX)); + expect(mine, 'reported exactly once').toHaveLength(1); + // Pre-fix this single call produced 12 physical lines, 11 of them + // head-less — see the reverse-verification block at the bottom. + expect(lines, 'nothing else reached stdout at warn level').toHaveLength(1); + + const record = JSON.parse(mine[0]) as { + level: string; + msg: string; + issues?: Array>; + error?: string; + }; + expect(record.level).toBe('warn'); + expect(record.msg).not.toContain('\n'); + expect(record.msg).toContain('sys_automation_run not registered yet'); + // The facts a reader came for, and the #5573 redaction trap avoided: + // Zod names the offending keys in a field called `keys`, and `'keys'` + // contains `'key'` — `ObjectLogger`'s substring redactor would blank it. + expect(record.error, 'a validation rejection populates `issues`, not `error`').toBeUndefined(); + expect(record.issues?.some((i) => i.path === '(root)')).toBe(true); + expect(record.issues?.some((i) => i.path === 'objects[0].fields')).toBe(true); + expect(JSON.stringify(record.issues)).toContain('defaultDatasource'); + expect(JSON.stringify(record.issues)).not.toContain('REDACTED'); + }); + + it('a plain multi-line rejection keeps its full text, on one line', async () => { + const lines = await captureStream('stdout', () => + bootPlugin({ + manifest: rejectingManifest(new Error(MULTILINE_DRIVER)), + level: 'warn', + format: 'pretty', + }), + ); + + expect(lines).toHaveLength(1); + expect(lines[0]).toMatch(RECORD_HEAD); + expect(classifyLine(lines[0]), 'the boot buffer keeps it').toBe('warn'); + // Newlines survive as `\n` escapes inside the JSON-serialized meta, so + // every fact is on the retained line. + expect(lines[0]).toContain('no such table: sys_automation_run'); + expect(lines[0]).toContain('run `os migrate` for this datasource'); + }); + + it('calls warn(message, meta) — `warn` has no Error slot', async () => { + // Verified against the contract rather than assumed: `Logger.warn` is + // `warn(message, meta?)`, so the cause belongs in argument TWO here even + // though both `error` seams below must use argument THREE. + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + await bootPlugin({ manifest: rejectingManifest(zodLikeRejection()), level: 'warn' }); + + const call = warn.mock.calls.find((c) => String(c[0]).includes(MANIFEST_PREFIX)); + expect(call, 'the seam logged at warn level').toBeDefined(); + expect(call).toHaveLength(2); + const [message, meta] = call as [string, Record]; + expect(message).not.toContain('\n'); + expect(Array.isArray(meta.issues)).toBe(true); + }); + + it('says nothing when the manifest service accepts the object', async () => { + // The no-cause direction: a working composition must not gain a byte. + const lines = await captureStream('stdout', () => + bootPlugin({ manifest: acceptingManifest(), level: 'warn' }), + ); + expect(lines).toEqual([]); + }); +}); + +// ── seam 2: the boot probe (`error` → stderr) ────────────────────────────── + +describe('#5661 — the startup probe error is ONE stderr record', () => { + it("the driver's multi-line failure never reaches the log message", async () => { + const lines = await captureStream('stderr', () => + bootPlugin({ + manifest: acceptingManifest(), + objectql: fakeDataEngine({ failProbe: MULTILINE_DRIVER }), + level: 'error', + }), + ); + + const mine = lines.filter((l) => l.includes(PROBE_PREFIX)); + expect(mine, 'reported exactly once').toHaveLength(1); + expect(lines, 'one call, one physical line').toHaveLength(1); + + const record = JSON.parse(lines[0]) as { level: string; msg: string; error?: string; issues?: unknown }; + expect(record.level).toBe('error'); + expect(record.msg).not.toContain('\n'); + // #4632 demands both of these IN the record's own first line, and moving + // the cause out must not cost either one. + expect(record.msg, 'the consequence').toContain('suspended runs will NOT survive a restart'); + expect(record.msg, 'the fix').toContain('Check that schema sync ran for this datasource'); + // Not a validation rejection → `error`, and the whole driver text + // survives, its newlines escaped by the logger's JSON.stringify. + expect(record.issues).toBeUndefined(); + expect(record.error).toBe(MULTILINE_DRIVER); + }); + + it("calls error(message, undefined, meta) — the contract's third slot", async () => { + const error = vi.spyOn(ObjectLogger.prototype, 'error'); + await bootPlugin({ + manifest: acceptingManifest(), + objectql: fakeDataEngine({ failProbe: MULTILINE_DRIVER }), + level: 'error', + }); + + const call = error.mock.calls.find((c) => String(c[0]).includes(PROBE_PREFIX)); + expect(call, 'the seam logged at error level').toBeDefined(); + const [message, errorSlot, meta] = call as [string, unknown, Record]; + expect(message).not.toContain('\n'); + // The second slot stays empty on purpose: a raw `Error` there ships its + // stack into the record (#5575). + expect(errorSlot).toBeUndefined(); + expect(meta.error).toBe(MULTILINE_DRIVER); + }); + + it('a readable table produces no error bytes at all', async () => { + const lines = await captureStream('stderr', () => + bootPlugin({ manifest: acceptingManifest(), objectql: fakeDataEngine(), level: 'error' }), + ); + expect(lines).toEqual([]); + }); +}); + +// ── seam 3: the wait-timer re-arm (`error` → stderr) ─────────────────────── + +describe('#5661 — the wait-timer re-arm error is ONE stderr record', () => { + it('the escaping cause goes to meta, the consequence stays in the message', async () => { + rearm.thrown = new Error(MULTILINE_JOB); + const lines = await captureStream('stderr', () => + bootPlugin({ manifest: acceptingManifest(), objectql: fakeDataEngine(), level: 'error' }), + ); + + const mine = lines.filter((l) => l.includes(REARM_PREFIX)); + expect(mine, 'reported exactly once').toHaveLength(1); + expect(lines, 'one call, one physical line').toHaveLength(1); + + const record = JSON.parse(lines[0]) as { level: string; msg: string; error?: string }; + expect(record.level).toBe('error'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the consequence').toContain('will hang indefinitely instead of resuming'); + expect(record.msg, 'the fix').toContain('resumed manually via the automation resume API'); + // The message used to end `Cause: `; it now points at the meta. + expect(record.msg).not.toContain('ECONNREFUSED'); + expect(record.error).toBe(MULTILINE_JOB); + }); + + it("calls error(message, undefined, meta) — the contract's third slot", async () => { + rearm.thrown = new Error(MULTILINE_JOB); + const error = vi.spyOn(ObjectLogger.prototype, 'error'); + await bootPlugin({ manifest: acceptingManifest(), objectql: fakeDataEngine(), level: 'error' }); + + const call = error.mock.calls.find((c) => String(c[0]).includes(REARM_PREFIX)); + expect(call, 'the seam logged at error level').toBeDefined(); + const [message, errorSlot, meta] = call as [string, unknown, Record]; + expect(message).not.toContain('\n'); + expect(errorSlot).toBeUndefined(); + expect(meta.error).toBe(MULTILINE_JOB); + }); + + it('still reports at `error`, so check:durability-log-level keeps its seam', async () => { + // `rearmSuspendedWaitTimers` is in `DURABILITY_CRITICAL_CALLEES`: this + // catch must not drop below `error` and must not start rethrowing. + rearm.thrown = new Error(MULTILINE_JOB); + const err = vi.spyOn(ObjectLogger.prototype, 'error'); + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + await expect( + bootPlugin({ manifest: acceptingManifest(), objectql: fakeDataEngine(), level: 'error' }), + ).resolves.toBeUndefined(); + expect(err.mock.calls.some((c) => String(c[0]).includes(REARM_PREFIX))).toBe(true); + expect(warn.mock.calls.some((c) => String(c[0]).includes(REARM_PREFIX))).toBe(false); + }); + + it('a clean re-arm produces no error bytes at all', async () => { + const lines = await captureStream('stderr', () => + bootPlugin({ manifest: acceptingManifest(), objectql: fakeDataEngine(), level: 'error' }), + ); + expect(lines).toEqual([]); + }); +}); + +// ── reverse verification, direction predicted before running ─────────────── + +describe('#5661 — what the interpolated rendering cost, measured', () => { + it('the pre-fix `warn` shape loses its every fact to the boot buffer', async () => { + // Predicted BEFORE running, and it is the plain red direction: rendering + // the OLD shape — the cause spliced into the message — must produce MANY + // physical lines of which exactly ONE classifies, so a boot-quiet window + // retains that one and drops the rest. `registerRunObject` runs in + // `init()`, which is inside that window, and `warn` goes to the stdout + // the window wraps. + const dump = zodLikeRejection().message; + expect(dump.split('\n').length, 'fixture must be multi-line').toBeGreaterThan(1); + expect(dump.split('\n')[0].trim(), "…and open with Zod's `[`").toBe('['); + + const log = new ObjectLogger({ level: 'warn', format: 'pretty' }); + + const before = await captureStream('stdout', async () => { + log.warn( + `[Automation] manifest service unavailable; sys_automation_run not registered yet: ${dump}`, + ); + }); + expect(before.length, 'one call, many physical lines').toBeGreaterThan(1); + const kept = before.filter((l) => classifyLine(l) !== null); + expect(kept, 'exactly one line survives the buffer').toHaveLength(1); + expect(kept[0].trimEnd().endsWith('['), 'and it stops at the bracket').toBe(true); + expect(kept[0]).not.toContain('defaultDatasource'); + expect(before.length - kept.length, 'lines the buffer drops').toBeGreaterThan(1); + + const after = await captureStream('stdout', async () => { + log.warn('[Automation] manifest service unavailable; sys_automation_run not registered yet.', { + issues: [{ code: 'unrecognized_keys', path: '(root)', unrecognized: ['defaultDatasource'] }], + }); + }); + expect(after).toHaveLength(1); + expect(classifyLine(after[0])).toBe('warn'); + expect(after[0]).toContain('defaultDatasource'); + }); + + it('the pre-fix `error` shapes split one durability alarm into fragments', async () => { + // Same prediction on the stderr side, where nothing buffers: the record + // is not dropped, it is MIS-READ. The continuation lines carry no level + // and no timestamp, so a file sink stores them as their own records and a + // `grep ERROR` returns the one line that holds no facts — which for these + // two seams is the line an operator is grepping for in the first place. + const log = new ObjectLogger({ level: 'error', format: 'pretty' }); + + const beforeProbe = await captureStream('stderr', async () => { + log.error( + `[Automation] sys_automation_run could not be read at startup — if this persists, suspended runs will NOT ` + + `survive a restart. Check that schema sync ran for this datasource: ${MULTILINE_DRIVER}`, + ); + }); + expect(beforeProbe, 'three physical lines from one call').toHaveLength(3); + expect(beforeProbe.filter((l) => classifyLine(l) !== null)).toHaveLength(1); + expect(beforeProbe[1]).not.toMatch(RECORD_HEAD); + expect(beforeProbe[1]).toContain('better-sqlite3'); + + const afterProbe = await captureStream('stderr', async () => { + log.error( + `[Automation] sys_automation_run could not be read at startup — if this persists, suspended runs will NOT ` + + `survive a restart. Check that schema sync ran for this datasource; the driver's own failure is in this record's meta.`, + undefined, + { error: MULTILINE_DRIVER }, + ); + }); + expect(afterProbe).toHaveLength(1); + expect(afterProbe[0]).toMatch(RECORD_HEAD); + expect(afterProbe[0]).toContain('better-sqlite3'); + + const beforeRearm = await captureStream('stderr', async () => { + log.error(`[Automation] suspended wait-timer re-arm FAILED after restart. Cause: ${MULTILINE_JOB}`); + }); + expect(beforeRearm).toHaveLength(3); + expect(beforeRearm.filter((l) => classifyLine(l) !== null)).toHaveLength(1); + expect(beforeRearm[2]).toContain('is the queue running?'); + expect(beforeRearm[2]).not.toMatch(RECORD_HEAD); + }); +}); diff --git a/packages/services/service-automation/src/plugin-suspended-run-wiring.test.ts b/packages/services/service-automation/src/plugin-suspended-run-wiring.test.ts index f35f38c271..2730042922 100644 --- a/packages/services/service-automation/src/plugin-suspended-run-wiring.test.ts +++ b/packages/services/service-automation/src/plugin-suspended-run-wiring.test.ts @@ -51,12 +51,31 @@ function recordingManifest() { return { registered, register(m: any) { registered.push(m); } }; } -type LogLine = { level: string; msg: string }; +type LogLine = { level: string; msg: string; meta?: Record }; +/** + * #5661 — the sink now keeps `meta` as well as the message. + * + * It used to record `String(msg)` only, which was enough while every cause was + * interpolated INTO the message. Once the probe seam moved its cause to the + * logger's structured argument, a message-only sink could no longer tell "the + * cause was reported in meta" from "the cause was lost" — both read as an + * absent match. The two levels take it in different slots, per the `Logger` + * contract: `warn(message, meta?)` and `error(message, error?, meta?)`. + */ function capturingLogger(sink: LogLine[]): any { - const log = (level: string) => (msg: any) => sink.push({ level, msg: String(msg) }); + const metaLevel = (level: string) => (msg: any, meta?: Record) => + sink.push({ level, msg: String(msg), meta }); + const errorLike = (level: string) => + (msg: any, errorOrMeta?: unknown, meta?: Record) => + sink.push({ + level, + msg: String(msg), + meta: meta ?? (errorOrMeta instanceof Error ? undefined : (errorOrMeta as any)), + }); return { - info: log('info'), warn: log('warn'), error: log('error'), debug: log('debug'), + info: metaLevel('info'), warn: metaLevel('warn'), + error: errorLike('error'), debug: metaLevel('debug'), child() { return capturingLogger(sink); }, }; } @@ -151,6 +170,16 @@ async function runLifecycle(opts: { manifest, logs, engine: services.get('automation') as AutomationEngine, errors: () => logs.filter(l => l.level === 'error').map(l => l.msg).join('\n'), + /** + * One `error` record, picked by a prefix of its message (#5661). + * + * Needed because an unreadable table trips TWO seams — this plugin's + * boot probe and, further down, `wait-node.ts`'s own `[wait] … re-arm + * ABORTED` record, which still interpolates its cause. Asserting over + * the joined text cannot tell which seam a match came from. + */ + errorRecord: (prefix: string) => + logs.find(l => l.level === 'error' && l.msg.startsWith(prefix)), registeredObjects: () => manifest.registered.flatMap(m => m.objects ?? []).map((o: any) => o.name), }; @@ -207,7 +236,15 @@ describe('durable suspended-run wiring (#4420)', () => { const h = await runLifecycle({ manifestPhase: 'init', data }); expect(h.errors()).toMatch(/could not be read at startup/); - expect(h.errors()).toMatch(/no such table: sys_automation_run/); + // #5661 — the driver's text is still reported, but through the logger's + // structured slot rather than spliced into the message. Asserted in BOTH + // directions on the probe's OWN record: a message-only assertion would + // keep passing if the cause were dropped entirely. + const probe = h.errorRecord('[Automation] sys_automation_run could not be read at startup'); + expect(probe, 'the probe reported').toBeDefined(); + expect(probe!.msg).not.toContain('\n'); + expect(probe!.msg).not.toMatch(/no such table: sys_automation_run/); + expect(probe!.meta?.error).toBe('no such table: sys_automation_run'); expect((h.engine as any).store, 'store still attached').toBeTruthy(); }); diff --git a/packages/services/service-automation/src/plugin.ts b/packages/services/service-automation/src/plugin.ts index 434563e6f3..fe69164d04 100644 --- a/packages/services/service-automation/src/plugin.ts +++ b/packages/services/service-automation/src/plugin.ts @@ -450,8 +450,16 @@ export class AutomationServicePlugin implements Plugin { }); return true; } catch (err) { + // #5661 — `err` is the kernel registry's, not ours, so its text must + // not be interpolated into the MESSAGE. This one is `warn` → stdout, + // which is the stream `serve`'s boot-quiet window wraps: a + // continuation line here is DROPPED by `BootLogCapture.offer()`, not + // merely mangled (#5636 measured 13 lines in, 1 retained). `warn`'s + // SECOND argument is `meta` — the `Logger` contract has no `Error` + // slot below `error`. See ./thrown-cause-diagnostics.ts. ctx.logger.warn( - `[Automation] manifest service unavailable; sys_automation_run not registered yet: ${(err as Error).message}`, + '[Automation] manifest service unavailable; sys_automation_run not registered yet.', + describeThrownForLog(err), ); return false; } @@ -588,9 +596,21 @@ export class AutomationServicePlugin implements Plugin { try { await candidate.probe(); } catch (err) { + // #5661 — this record exists to be READ: it states the + // durability consequence and the fix (#4632), and `err` + // comes out of the DATASOURCE DRIVER, whose multi-line + // failures are ordinary in the ecosystem. Interpolating + // it split one `error` into N fragments of which only the + // first carries a level head, so a file sink stored the + // rest as their own records and `grep ERROR` returned the + // line holding no facts. Third argument, per + // `error(message, error?, meta?)` — the second would ship + // the driver's stack on top (#5575). ctx.logger.error( `[Automation] sys_automation_run could not be read at startup — if this persists, suspended runs will NOT ` + - `survive a restart. Check that schema sync ran for this datasource: ${(err as Error).message}`, + `survive a restart. Check that schema sync ran for this datasource; the driver's own failure is in this record's meta.`, + undefined, + describeThrownForLog(err), ); } durableStore = candidate; @@ -928,11 +948,29 @@ export class AutomationServicePlugin implements Plugin { // ever resume on its own. To everyone waiting on one, that is // indistinguishable from the #4420 loss this store exists to // prevent — so it is reported at `error`, not `warn`. + // + // #5661 — and precisely because this is the record an operator + // greps for, a foreign text does not go into the MESSAGE. + // `Cause: ${err.message}` made the loudest durability warning in + // this plugin the one most likely to arrive as unattributable + // fragments. Third argument, per `error(message, error?, meta?)`. + // See ./thrown-cause-diagnostics.ts. + // + // On WHOSE text that is: `rearmSuspendedWaitTimers` catches every + // failure it models — the store read, each overdue `resume()`, + // each `job.schedule()` — and reports them on its own `[wait]` + // records. So this catch is the net for what that function did + // NOT model, and the message's "job-service error" is a guess at + // the likeliest culprit rather than a guarantee. All the more + // reason to hand the value over structurally instead of splicing + // a shape we cannot predict into a line-oriented record. ctx.logger.error( `[Automation] suspended wait-timer re-arm FAILED after restart — suspended runs are still persisted in ` + `sys_automation_run, but their timers were NOT re-armed: every wait/approval paused before this restart ` + - `will hang indefinitely instead of resuming. Fix the job-service error below and restart to re-attempt the ` + - `re-arm; runs can also be resumed manually via the automation resume API. Cause: ${(err as Error).message}`, + `will hang indefinitely instead of resuming. Fix the job-service error in this record's meta and restart ` + + `to re-attempt the re-arm; runs can also be resumed manually via the automation resume API.`, + undefined, + describeThrownForLog(err), ); } } From d408e34c11650f3bd2b4ee53f22efed3d4210735 Mon Sep 17 00:00:00 2001 From: Claude Code Date: Thu, 6 Aug 2026 03:13:21 +0000 Subject: [PATCH 2/2] test(service-automation): drop the new fake engine's unused delete so check:engine-double-contract passes (#5661) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `check:engine-double-contract` (a lint-job gate, not eslint) pinned the new `plugin-startup-log-cause.test.ts`: its `fakeDataEngine` declared a bare `async delete() { return true; }`, and an engine double whose delete does not route through `assertEngineDeleteDispatch` may accept a call the real `ObjectQL.delete` refuses — how #4434 shipped a dead REST route with a green suite. Removed the method instead of pinning it, and the choice is measured to the ledger's own standard rather than assumed. An `appendFileSync` marker as the first statement of that `delete` printed 0 times over this file's suite; the control — the same injection in `find` — printed 11 times in the same run, so the silence is evidence, not a broken probe. These seams drive `probe()`, `list()` and the boot flow pull only; nothing deletes a suspended run. `SuspendedRunStoreEngine` declares `delete?` optional, so omitting it is the faithful shape. Pinning would have certified a method that models nothing, and whose body was loose in a second way the pin does not address: it answered success while removing no row. A future case that needs deletion writes a real one and the gate requires the predicate then; the store also warns when the engine has no `delete()`, which the byte-exact assertions here would surface at once. The reasoning is recorded on the fixture so the next reader does not re-derive it. check:engine-double-contract: OK — 27 pinned, 65 in the DEBT ledger, 1 exempt (the shrink-only baseline is untouched — no entry added, none lowered). Package suite: 63 files / 754 tests passed. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01BWS4heBoAitLmzCLhcYdbK --- .../src/plugin-startup-log-cause.test.ts | 25 ++++++++++++++++++- 1 file changed, 24 insertions(+), 1 deletion(-) diff --git a/packages/services/service-automation/src/plugin-startup-log-cause.test.ts b/packages/services/service-automation/src/plugin-startup-log-cause.test.ts index d4c6d07927..1f115545c2 100644 --- a/packages/services/service-automation/src/plugin-startup-log-cause.test.ts +++ b/packages/services/service-automation/src/plugin-startup-log-cause.test.ts @@ -140,6 +140,30 @@ function zodLikeRejection(): Error { * (out of this issue's scope, filed separately). Narrowing the fixture to the * probe keeps these assertions about the seam they name instead of measuring * someone else's record. + * + * ## No `delete` on purpose (#4550 / #5629) + * + * `SuspendedRunStoreEngine` declares `delete?` optional, and this double omits + * it. `check:engine-double-contract` flagged an earlier draft that carried a + * bare `async delete() { return true; }`: an engine double whose `delete` does + * not route through `assertEngineDeleteDispatch` may accept a call the real + * `ObjectQL.delete` refuses, which is how #4434 shipped a dead REST route with + * its suite green. + * + * Removing it was the right remedy here rather than pinning it, and the reason + * is measured, not assumed — the ledger's own standard. Injecting an + * `appendFileSync` marker as the first statement of that `delete` and running + * this file printed it **0** times; the control, the same injection in `find`, + * printed **11** times in the same run, so the silence is evidence and not a + * broken probe. Nothing here deletes a suspended run: these seams exercise + * `probe()`, `list()` and the boot flow pull only. So the method modelled + * nothing — and its body was the second kind of looseness besides, answering + * success while removing no row. A pin would have certified that. + * + * A future case that does need deletion writes a real one and + * `check:engine-double-contract` will require the predicate then; and the store + * itself warns when the engine has no `delete()`, which the byte-exact + * assertions below would surface immediately. */ function fakeDataEngine(opts: { failProbe?: string } = {}) { const rows = new Map(); @@ -153,7 +177,6 @@ function fakeDataEngine(opts: { failProbe?: string } = {}) { }, async insert(_object, data) { rows.set(String(data.id), { ...data }); return data; }, async update(_object, data) { rows.set(String(data.id), { ...data }); return data; }, - async delete() { return true; }, }; return engine; }