diff --git a/.changeset/wait-node-log-cause-meta.md b/.changeset/wait-node-log-cause-meta.md new file mode 100644 index 0000000000..fe43953639 --- /dev/null +++ b/.changeset/wait-node-log-cause-meta.md @@ -0,0 +1,30 @@ +--- +"@objectstack/service-automation": patch +--- + +fix(service-automation): `wait` 节点的五条日志不再把外来 cause 拼进 message,改走 meta (#5737) + +`builtin/wait-node.ts` 里有五处记录把**我们不控制文本**的失败原因(数据源驱动、 +job 服务、`engine.resume()` 的错误信封)直接插进日志 message。`ObjectLogger.write()` +一次调用只加一个「时间戳 + 级别」记录头,所以 message 里的换行会把**一条**记录变成 +多个物理行,后面几行既无级别也无时间戳。在 `pretty` / `text` 格式(`os dev` / `os serve` +的默认)下,文件 sink 会把它们当成独立记录存,日志采集器读成无主碎片,而 +`grep ERROR` 只捞得到不含任何事实的那一行 —— 恰恰是运维正在找的那条。 + +五处现在都改成:**message 单行自足**,外来 cause 交给 logger 的结构化参数位 —— +按 `Logger` 契约(`packages/spec/src/contracts/logger.ts`)选位置,`warn(message, meta?)` +用第二参,`error(message, error?, meta?)` 用**第三**参(第二参留空,否则每条记录都 +会带上整个栈)。与 #5048 / #5575 / #5636 / #5661 完全同一套修法,零新词汇。 + +对运维可见的变化(日志形状,非行为): + +- 这五条记录各自恒为**一个**物理行,不论日志格式; +- 原因文本从 `msg` 末尾的 `Cause: …` 移到记录的 `error` 字段(`meta`),多行驱动错误 + 由 `JSON.stringify` 转义换行后完整保留 —— 一个字节都不丢; +- 消息里原本指向拼接文本的「the cause below」措辞改为指向记录的 meta; +- 级别一律不变。其中三处是 #4632 明确定为 `error` 的耐久性诊断 + (`rearmSuspendedWaitTimers` 的 store 不可列、overdue 运行叫不醒、唤醒 job 没排上), + 仍是 `error`,`pnpm check:durability-log-level` 照旧覆盖;「无 job 服务」那条声明式 + 缺失仍是 `warn`。 + +按 `Cause:` 字面量 grep 这五条记录的日志查询需要改成读记录的 `error` 字段。 diff --git a/packages/services/service-automation/src/builtin/wait-node-log-cause.test.ts b/packages/services/service-automation/src/builtin/wait-node-log-cause.test.ts new file mode 100644 index 0000000000..052968a954 --- /dev/null +++ b/packages/services/service-automation/src/builtin/wait-node-log-cause.test.ts @@ -0,0 +1,524 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// Regression: #5737 — the FIVE seams of `builtin/wait-node.ts` that interpolated +// a FOREIGN cause into the log MESSAGE. +// +// The fifth instalment of the family #5048 (flow binding, PR #5572), #5575 +// (`reconcileDeclaredConnectors`'s `fail()`, PR #5639), #5636 +// (`degradeConnectorInstance`, PR #5662) and #5661 (`plugin.ts`'s three startup +// seams) closed. This file was outside every one of those scopes: #5661 fixed +// the plugin's own `catch` around `rearmSuspendedWaitTimers`, and these records +// are written INSIDE the function that catch wraps. +// +// 1. the wake-up handler's `STORE_UNAVAILABLE` line — `error`, cause from +// `engine.resume()`'s result ENVELOPE (`AutomationResult.error`); +// 2. the arming path's schedule failure — `warn`, cause from the job service; +// 3. the re-arm's unlistable store — `error`, cause from the DATASOURCE DRIVER; +// 4. an overdue run that will not resume — `error`, cause from the resume path; +// 5. a re-arm that could not re-schedule — `error`, cause from the job service. +// +// ## Why 3, 4 and 5 are the worst records in this package to shred +// +// They are `error` because #4632 put them there, and their own text says why: +// "every wait/approval paused before this restart will hang indefinitely". +// `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 and +// `grep ERROR` returns the one line holding no facts. `pretty`/`text` is the +// default format of `os dev` and `os serve`, so that is the shape an operator +// actually reads. cloud#971 survived a whole rc.1 line behind this. +// +// Seam 3 is the one measured on a real cold boot in #5737's issue text, so it +// gets the fullest treatment; seam 1 is worth naming separately because its +// cause is not a thrown value at all — the engine BUILDS that envelope string by +// interpolating the driver's own `message` into it, so a multi-line driver +// reaches this record through a second hop. +// +// ## The fix, and where each cause goes +// +// Identical to the four prior instalments, zero new vocabulary: a static, +// newline-free message plus the cause in the logger's structured slot, whose +// POSITION is set by 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 is +// the `Error` slot and would ship a stack on every record (#5575). +// +// Seam 1 does NOT go through `describeThrownForLog`: `AutomationResult.error` is +// a string the engine already composed, and the helper duck-types `.issues` / +// `.message` off a *thrown* object. It hands `{ error }` directly — the helper's +// own field name, so all five records still report a non-validation cause under +// exactly one key. +// +// Assertions read REAL BYTES off a REAL `ObjectLogger` wherever the question is +// "what would a line-oriented consumer see", per the #5662/#5661 precedent: a +// spy proves what the seam *called*, not what the downstream splitter *sees*, +// and it was the latter that cost cloud#971 a release line. Spies appear only +// where the argument SLOT is itself the fact under test. + +import { describe, it, expect, vi } from 'vitest'; +import { ObjectLogger } from '@objectstack/core'; +import { AutomationEngine } from '../engine.js'; +import { InMemorySuspendedRunStore } from '../suspended-run-store.js'; +import { registerWaitNode, rearmSuspendedWaitTimers } from './wait-node.js'; +import type { IJobService } from '@objectstack/spec/contracts'; + +// ── 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 #5737 + * is a `finding` and not an outage report. Byte-identical to the fixture + * `plugin-startup-log-cause.test.ts` uses, because it is the same accident. + */ +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'); + +function silent(): any { + const l: any = { info() {}, warn() {}, error() {}, debug() {} }; + l.child = () => l; + return l; +} + +const waitFlow = (config: Record) => + ({ + name: 'wait_flow', + label: 'wait_flow', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'pause', type: 'wait', label: 'Wait', config }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'pause' }, + { id: 'e2', source: 'pause', target: 'end' }, + ], + }) as never; + +/** + * Boot one "process" against `store`, parked at a wait node. `logger` is the + * plugin-context logger the node executor and its wake-up handler write to; the + * ENGINE keeps a silent one, so a capture holds the seam under test and nothing + * else. + */ +function bootEngine(store: InMemorySuspendedRunStore, config: Record, ctx?: { logger?: unknown; job?: IJobService }) { + const engine = new AutomationEngine(silent()); + registerWaitNode(engine, { + logger: ctx?.logger ?? silent(), + getService(id: string) { + if (id === 'job' && ctx?.job) return ctx.job; + throw new Error('no service'); + }, + } as any); + engine.setSuspendedRunStore(store); + engine.registerFlow('wait_flow', waitFlow(config)); + return engine; +} + +/** A store that persisted fine and then cannot be read back. */ +function unreadableStore(message: string): any { + return { + async list() { + throw new Error(message); + }, + async save() {}, + async load() { + return null; + }, + async remove() {}, + }; +} + +/** 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); +} + +/** + * `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. + */ +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/; + +/** + * Does this physical line carry a level head at all? + * + * The ANSI introducer below is spelled as a lowercase-u escape sequence, never + * as the control byte itself — AGENTS.md byte discipline, whose harms + * `scripts/check-nul-bytes.mjs` argues. This exact line materialized a raw one + * on first draft, which is the accident that rule exists for. + */ +function classifies(raw: string): boolean { + const line = raw.replace(/\u001B\[[0-9;]*m/g, '').trim(); + if (!line) return false; + if (line.startsWith('{')) { + try { + const rec = JSON.parse(line) as { level?: unknown; time?: unknown }; + return typeof rec.time === 'string' && typeof rec.level === 'string'; + } catch { + return false; + } + } + return RECORD_HEAD.test(line); +} + +type Record_ = { level: string; msg: string; error?: string; issues?: unknown }; + +/** The single JSON record on `lines`, parsed. */ +function soleRecord(lines: string[]): Record_ { + expect(lines, 'one call, one physical line').toHaveLength(1); + return JSON.parse(lines[0]) as Record_; +} + +// ── seam 3: the re-arm's unlistable store (the measured one) ──────────────── + +describe('#5737 — the re-arm ABORTED durability alarm is ONE stderr record', () => { + it("the driver's multi-line failure never reaches the log message", async () => { + const log = new ObjectLogger({ level: 'error', format: 'json' }); + const lines = await captureStream('stderr', async () => { + const rearmed = await rearmSuspendedWaitTimers( + new AutomationEngine(silent()), + unreadableStore(MULTILINE_DRIVER), + undefined, + log, + ); + expect(rearmed).toBe(0); + }); + + const record = soleRecord(lines); + expect(record.level).toBe('error'); + expect(record.msg).not.toContain('\n'); + // #4632 demands the consequence and the fix in the record's own line, and + // moving the cause out must not cost either. + expect(record.msg, 'the consequence').toContain('will hang indefinitely instead of resuming'); + expect(record.msg, 'the runs survived').toContain('still persisted'); + expect(record.msg, 'the fix').toContain('restart to re-attempt the re-arm'); + expect(record.msg, 'the escape hatch').toContain('resume(runId)'); + // 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); + expect(record.msg).not.toContain('no such table'); + }); + + it('stays one physical line in `pretty`, the format `os dev` / `os serve` default to', async () => { + // The JSON case above cannot fail the way #5737 reports, because + // JSON.stringify escapes the newlines either way. This is the format the + // measurement was taken in. + const log = new ObjectLogger({ level: 'error', format: 'pretty' }); + const lines = await captureStream('stderr', async () => { + await rearmSuspendedWaitTimers(new AutomationEngine(silent()), unreadableStore(MULTILINE_DRIVER), undefined, log); + }); + + expect(lines).toHaveLength(1); + expect(lines[0]).toMatch(RECORD_HEAD); + // Every fact is on the one line that a `grep ERROR` returns. + expect(lines[0]).toContain('will hang indefinitely'); + expect(lines[0]).toContain('better-sqlite3'); + expect(lines[0]).toContain('run `os migrate` for this datasource'); + }); + + it("calls error(message, undefined, meta) — the contract's third slot", async () => { + const error = vi.spyOn(ObjectLogger.prototype, 'error'); + const log = new ObjectLogger({ level: 'error', format: 'json' }); + await captureStream('stderr', async () => { + await rearmSuspendedWaitTimers(new AutomationEngine(silent()), unreadableStore(MULTILINE_DRIVER), undefined, log); + }); + + const call = error.mock.calls.find((c) => String(c[0]).includes('re-arm ABORTED')); + 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); + error.mockRestore(); + }); +}); + +// ── seam 4: an overdue run that could not be resumed ──────────────────────── + +describe('#5737 — the OVERDUE run error is ONE stderr record', () => { + it('keeps the consequence in the message and the resume failure in meta', async () => { + const store = new InMemorySuspendedRunStore(); + const first = bootEngine(store, { eventType: 'timer', timerDuration: '1' }); + await first.execute('wait_flow'); + await new Promise((r) => setTimeout(r, 10)); // let the 1ms deadline lapse + + // `resume()` REPORTS machine-state problems in its result rather than + // throwing, so only a genuine fault on the resume path reaches this catch. + const brokenEngine = { + async resume() { + throw new Error(MULTILINE_DRIVER); + }, + } as never; + + const log = new ObjectLogger({ level: 'error', format: 'json' }); + const lines = await captureStream('stderr', async () => { + await rearmSuspendedWaitTimers(brokenEngine, store, undefined, log); + }); + + const record = soleRecord(lines); + expect(record.level).toBe('error'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the consequence').toContain('is OVERDUE and could not be resumed'); + expect(record.msg, 'nothing else will wake it').toContain('nothing will'); + // The old text said "Fix the cause below", which was only true of the + // spliced rendering; it now points at where the cause really is. + expect(record.msg).toContain("record's meta"); + expect(record.msg).not.toContain('below'); + expect(record.error).toBe(MULTILINE_DRIVER); + }); +}); + +// ── seam 5: a re-arm that could not re-schedule ───────────────────────────── + +describe('#5737 — the failed re-schedule error is ONE stderr record', () => { + it("keeps the job service's multi-line failure out of the message", async () => { + const store = new InMemorySuspendedRunStore(); + const config = { eventType: 'timer', timerDuration: 'PT2H' }; + const first = bootEngine(store, config); + expect((await first.execute('wait_flow')).status).toBe('paused'); + + const brokenJob: IJobService = { + async schedule() { + throw new Error(MULTILINE_JOB); + }, + } as never; + + const log = new ObjectLogger({ level: 'error', format: 'json' }); + const lines = await captureStream('stderr', async () => { + const rearmed = await rearmSuspendedWaitTimers(bootEngine(store, config), store, brokenJob, log); + expect(rearmed).toBe(0); + }); + + const record = soleRecord(lines); + expect(record.level).toBe('error'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the consequence').toContain('hang past that deadline'); + expect(record.msg, 'the fix').toContain('restart to re-attempt the re-arm'); + // The persisted deadline STAYS in the message: it is a value this file wrote + // and re-read behind a `Date.parse` guard, not foreign text. + expect(record.msg).toMatch(/deadline of \d{4}-\d{2}-\d{2}T/); + expect(record.error).toBe(MULTILINE_JOB); + expect(record.msg).not.toContain('ECONNREFUSED'); + }); +}); + +// ── seam 1: the wake-up handler's STORE_UNAVAILABLE line ──────────────────── + +describe('#5737 — the timer wake-up STORE_UNAVAILABLE error is ONE stderr record', () => { + /** + * The engine composes this cause as an envelope FIELD, by interpolating the + * driver's own `message` into a sentence (`resumeInternal`'s + * `STORE_UNAVAILABLE` return). So the multi-line text arrives here through a + * second hop, and the fixture is shaped exactly like the real envelope. + */ + const ENVELOPE = `Durable suspended-run store unreachable for run 'run_1' — retry once the store is available: ${MULTILINE_DRIVER}`; + + async function fireWakeUpInto(log: ObjectLogger, envelope: { error?: string }) { + const scheduled: Array<{ handler: () => Promise }> = []; + const job: IJobService = { + async schedule(_name: string, _sched: unknown, handler: any) { + scheduled.push({ handler }); + }, + async cancel() {}, + async trigger() {}, + } as never; + + const store = new InMemorySuspendedRunStore(); + const engine = bootEngine(store, { eventType: 'timer', timerDuration: 'PT2H' }, { logger: log, job }); + expect((await engine.execute('wait_flow')).status).toBe('paused'); + expect(scheduled).toHaveLength(1); + + // The wake-up fires into an unreachable store — the branch that must keep + // the job armed (#5529) and report at `error` (#4632). + engine.resume = async () => ({ success: false, code: 'STORE_UNAVAILABLE', ...envelope }) as never; + await scheduled[0].handler(); + } + + it("routes the resume envelope's reason to meta, not into the message", async () => { + const log = new ObjectLogger({ level: 'error', format: 'json' }); + const lines = await captureStream('stderr', () => fireWakeUpInto(log, { error: ENVELOPE })); + + const record = soleRecord(lines); + expect(record.level).toBe('error'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'why the job was kept').toContain('left ARMED on purpose'); + expect(record.msg, 'both remedies').toMatch(/trigger\('flow-wait:/); + expect(record.msg).toMatch(/resume\('/); + expect(record.error).toBe(ENVELOPE); + expect(record.msg).not.toContain('better-sqlite3'); + }); + + it('falls back to a named default when the envelope carries no reason', async () => { + // `AutomationResult.error` is optional. `describeThrownForLog` is NOT used + // here precisely because it would render the literal string `"undefined"` + // into the record for this case. + const log = new ObjectLogger({ level: 'error', format: 'json' }); + const lines = await captureStream('stderr', () => fireWakeUpInto(log, {})); + + const record = soleRecord(lines); + expect(record.error).toBe('store unavailable'); + }); + + it("calls error(message, undefined, meta) — the contract's third slot", async () => { + const error = vi.spyOn(ObjectLogger.prototype, 'error'); + const log = new ObjectLogger({ level: 'error', format: 'json' }); + await captureStream('stderr', () => fireWakeUpInto(log, { error: ENVELOPE })); + + const call = error.mock.calls.find((c) => String(c[0]).includes('timer wake-up')); + 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(ENVELOPE); + error.mockRestore(); + }); +}); + +// ── seam 2: the arming path's schedule failure (`warn` → stdout) ──────────── + +describe('#5737 — the arming-path schedule warning is ONE stdout record', () => { + async function armAgainstBrokenJob(log: ObjectLogger): Promise { + const brokenJob: IJobService = { + async schedule() { + throw new Error(MULTILINE_JOB); + }, + async cancel() {}, + } as never; + const store = new InMemorySuspendedRunStore(); + const engine = bootEngine(store, { eventType: 'timer', timerDuration: 'PT2H' }, { logger: log, job: brokenJob }); + // Degrade-don't-crash: the run still suspends, only auto-resume is lost. + expect((await engine.execute('wait_flow')).status).toBe('paused'); + } + + it('the job failure goes to meta and the record survives the boot buffer', async () => { + // `warn` goes to STDOUT — the stream `serve`'s boot-quiet window wraps, where + // a head-less continuation line is DROPPED outright rather than merely + // mis-read. Measured in `pretty`, that window's own format. + const log = new ObjectLogger({ level: 'warn', format: 'pretty' }); + const lines = await captureStream('stdout', () => armAgainstBrokenJob(log)); + + expect(lines, 'one call, one physical line').toHaveLength(1); + expect(classifies(lines[0]), 'the boot buffer keeps it').toBe(true); + expect(lines[0]).toContain('failed to schedule timer resume'); + expect(lines[0]).toContain('resume it via resume(runId)'); + expect(lines[0]).toContain('is the queue running?'); + }); + + 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 every `error` seam in this file must use argument THREE. + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + const log = new ObjectLogger({ level: 'warn', format: 'json' }); + await captureStream('stdout', () => armAgainstBrokenJob(log)); + + const call = warn.mock.calls.find((c) => String(c[0]).includes('failed to schedule timer resume')); + 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(meta.error).toBe(MULTILINE_JOB); + warn.mockRestore(); + }); +}); + +// ── the no-cause direction ───────────────────────────────────────────────── + +describe('#5737 — a healthy path gains no bytes', () => { + it('a clean re-arm writes nothing at either level', async () => { + const store = new InMemorySuspendedRunStore(); + const config = { eventType: 'timer', timerDuration: 'PT2H' }; + await bootEngine(store, config).execute('wait_flow'); + + const okJob: IJobService = { async schedule() {}, async cancel() {} } as never; + const log = new ObjectLogger({ level: 'warn', format: 'json' }); + + const err = await captureStream('stderr', async () => { + const out = await captureStream('stdout', async () => { + expect(await rearmSuspendedWaitTimers(bootEngine(store, config), store, okJob, log)).toBe(1); + }); + expect(out).toEqual([]); + }); + expect(err).toEqual([]); + }); +}); + +// ── reverse verification, direction predicted before running ─────────────── + +describe('#5737 — what the interpolated rendering cost, measured', () => { + it('the pre-fix `error` shape splits one durability alarm into three fragments', async () => { + // Predicted BEFORE running, and it is the plain red direction: rendering the + // OLD shape — the cause spliced into the message — must produce SEVERAL + // physical lines of which exactly ONE carries a level head, so `grep ERROR` + // returns the line that holds none of the facts. `error` goes to stderr, + // which nothing buffers, so the record is not dropped — it is MIS-READ, and + // a file sink stores the continuation lines as records of their own. + expect(MULTILINE_DRIVER.split('\n'), 'fixture must be multi-line').toHaveLength(3); + const log = new ObjectLogger({ level: 'error', format: 'pretty' }); + + const before = await captureStream('stderr', async () => { + log.error( + `[wait] suspended wait-timer re-arm ABORTED — the suspended-run store could not be listed, so NO timer was ` + + `re-armed. Cause: ${MULTILINE_DRIVER}`, + ); + }); + expect(before, 'three physical lines from one call').toHaveLength(3); + expect(before.filter(classifies), 'only the first classifies').toHaveLength(1); + expect(before[0]).not.toContain('better-sqlite3'); + expect(before[1]).toContain('better-sqlite3'); + expect(before[1]).not.toMatch(RECORD_HEAD); + + // …and the shape this PR ships, through the REAL seam rather than a + // hand-written call: one line, head intact, every fact on it. + const after = await captureStream('stderr', async () => { + await rearmSuspendedWaitTimers(new AutomationEngine(silent()), unreadableStore(MULTILINE_DRIVER), undefined, log); + }); + expect(after).toHaveLength(1); + expect(after.filter(classifies)).toHaveLength(1); + expect(after[0]).toContain('better-sqlite3'); + }); + + it('the pre-fix `warn` shape loses its facts to the boot buffer entirely', async () => { + // Same prediction on the stdout side, where the harm is strictly worse: + // `BootLogCapture.offer()` RETAINS a physical line only when it classifies, + // so the continuation lines are not merely unattributed — they are gone. + const log = new ObjectLogger({ level: 'warn', format: 'pretty' }); + + const before = await captureStream('stdout', async () => { + log.warn(`[wait] node 'pause': failed to schedule timer resume (${MULTILINE_JOB}); suspending without auto-resume`); + }); + expect(before.length, 'one call, many physical lines').toBeGreaterThan(1); + const kept = before.filter(classifies); + expect(kept, 'exactly one line survives the buffer').toHaveLength(1); + expect(kept[0]).not.toContain('ECONNREFUSED'); + expect(before.length - kept.length, 'lines the buffer drops').toBeGreaterThan(0); + }); +}); diff --git a/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts b/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts index 00f794ba11..903d9df857 100644 --- a/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts +++ b/packages/services/service-automation/src/builtin/wait-node-rearm-log-level.test.ts @@ -22,12 +22,24 @@ import { InMemorySuspendedRunStore } from '../suspended-run-store.js'; import { registerWaitNode, rearmSuspendedWaitTimers } from './wait-node.js'; import type { IJobService } from '@objectstack/spec/contracts'; -type Line = { level: 'info' | 'warn' | 'error'; msg: string }; - +type Line = { level: 'info' | 'warn' | 'error'; msg: string; meta?: Record }; + +/** + * Captures the `Logger` contract's slots separately, because #5737 moved every + * foreign cause on this path out of the MESSAGE and into the structured one: + * `warn(message, meta?)` carries it second, `error(message, error?, meta?)` + * third. The level assertions below are unchanged — what this file pins is + * #4632, and a cause that moved slots is still a cause that was reported. + */ function capturingLogger() { const lines: Line[] = []; - const at = (level: Line['level']) => (msg: string) => void lines.push({ level, msg: String(msg) }); - const logger: any = { info: at('info'), warn: at('warn'), error: at('error'), debug() {} }; + const logger: any = { + info: (msg: string) => void lines.push({ level: 'info', msg: String(msg) }), + warn: (msg: string, meta?: Record) => void lines.push({ level: 'warn', msg: String(msg), meta }), + error: (msg: string, _error?: unknown, meta?: Record) => + void lines.push({ level: 'error', msg: String(msg), meta }), + debug() {}, + }; logger.child = () => logger; return { logger, @@ -35,6 +47,13 @@ function capturingLogger() { text(level: Line['level']) { return lines.filter((l) => l.level === level).map((l) => l.msg).join('\n'); }, + /** The `error` field of each record's meta at `level` — where the cause lives now. */ + causes(level: Line['level']) { + return lines + .filter((l) => l.level === level) + .map((l) => String((l.meta as { error?: unknown } | undefined)?.error ?? '')) + .join('\n'); + }, }; } @@ -103,7 +122,10 @@ describe('rearmSuspendedWaitTimers — durability degradations are errors (#4632 // FIX — both the repair and the manual escape hatch. expect(cap.text('error')).toMatch(/restart to re-attempt/); expect(cap.text('error')).toMatch(/resume\(runId\)/); - expect(cap.text('error')).toContain('no such table: sys_automation_run'); + // CAUSE — reported, but in the record's meta since #5737, not spliced into + // the message where a multi-line driver error would shred the record. + expect(cap.causes('error')).toContain('no such table: sys_automation_run'); + expect(cap.text('error')).not.toContain('no such table: sys_automation_run'); // The level is the point: this must not be discoverable only at warn. expect(cap.text('warn')).toBe(''); }); @@ -128,7 +150,8 @@ describe('rearmSuspendedWaitTimers — durability degradations are errors (#4632 expect(cap.text('error')).toMatch(/could NOT be re-scheduled/); expect(cap.text('error')).toMatch(/hang past that deadline/); expect(cap.text('error')).toMatch(/resume\('/); - expect(cap.text('error')).toContain('scheduler backend unreachable'); + expect(cap.causes('error')).toContain('scheduler backend unreachable'); + expect(cap.text('error')).not.toContain('scheduler backend unreachable'); // The run itself is untouched — persisted, and still resumable by hand. expect(await store.list()).toHaveLength(1); }); @@ -156,7 +179,8 @@ describe('rearmSuspendedWaitTimers — durability degradations are errors (#4632 expect(cap.text('error')).toMatch(/is OVERDUE and could not be resumed/); expect(cap.text('error')).toMatch(/nothing will\s+wake it again/); expect(cap.text('error')).toMatch(/resume\('/); - expect(cap.text('error')).toContain('datasource connection lost mid-resume'); + expect(cap.causes('error')).toContain('datasource connection lost mid-resume'); + expect(cap.text('error')).not.toContain('datasource connection lost mid-resume'); }); }); diff --git a/packages/services/service-automation/src/builtin/wait-node.test.ts b/packages/services/service-automation/src/builtin/wait-node.test.ts index 6132f41ed4..397a10755b 100644 --- a/packages/services/service-automation/src/builtin/wait-node.test.ts +++ b/packages/services/service-automation/src/builtin/wait-node.test.ts @@ -300,12 +300,18 @@ describe('wait timer one-shot vs. a shot that never consumed the pause (#5529)', /** A logger that keeps its `error` lines so the diagnostic can be asserted. */ function capturingLogger() { const errors: string[] = []; + // Since #5737 the cause is in the record's meta — `error(message, error?, + // meta?)`, the `Logger` contract's third slot — so this captures it too. + const causes: string[] = []; const logger = { info() {}, warn() {}, debug() {}, - error(msg: string) { errors.push(msg); }, + error(msg: string, _error?: unknown, meta?: Record) { + errors.push(msg); + causes.push(String((meta as { error?: unknown } | undefined)?.error ?? '')); + }, child() { return logger; }, } as any; - return { logger, errors }; + return { logger, errors, causes }; } /** @@ -352,14 +358,14 @@ describe('wait timer one-shot vs. a shot that never consumed the pause (#5529)', e2.setSuspendedRunStore(broken as any); e2.registerFlow('wait_flow', waitFlow(config)); - const { logger, errors } = capturingLogger(); + const { logger, errors, causes } = capturingLogger(); const job = boot2.ctx.getService('job') as IJobService; // The deadline is +24h, so the re-arm re-schedules rather than resuming now. expect(await rearmSuspendedWaitTimers(e2, broken as any, job, logger)).toBe(1); expect(boot2.scheduled).toHaveLength(1); expect(boot2.cancelled).toEqual([]); - return { paused, inner, boot2, ran, errors, jobName: `flow-wait:${paused.runId}:pause` }; + return { paused, inner, boot2, ran, errors, causes, jobName: `flow-wait:${paused.runId}:pause` }; } it('re-arm path: a STORE_UNAVAILABLE shot leaves the one-shot ARMED', async () => { @@ -378,7 +384,7 @@ describe('wait timer one-shot vs. a shot that never consumed the pause (#5529)', }); it('re-arm path: the failed shot is reported at error, naming the job and the run', async () => { - const { paused, boot2, errors, jobName } = await coldBootWithBrokenLoad(); + const { paused, boot2, errors, causes, jobName } = await coldBootWithBrokenLoad(); await boot2.scheduled[0].handler({ jobId: jobName }); // Previously silent: the callback discarded the result without a single line. @@ -389,7 +395,11 @@ describe('wait timer one-shot vs. a shot that never consumed the pause (#5529)', expect(errors[0]).toMatch(/left ARMED on purpose/); expect(errors[0]).toMatch(new RegExp(`trigger\\('${jobName}'\\)`)); expect(errors[0]).toMatch(new RegExp(`resume\\('${paused.runId}'\\)`)); - expect(errors[0]).toContain('connection refused'); + // The resume envelope's reason still reaches the record — in its meta since + // #5737, because the engine composes that envelope by interpolating the + // driver's own message into it and a driver's message can be multi-line. + expect(causes[0]).toContain('connection refused'); + expect(errors[0]).not.toContain('connection refused'); }); it('re-arm path: a shot that DOES resume still disarms the one-shot (unchanged)', async () => { diff --git a/packages/services/service-automation/src/builtin/wait-node.ts b/packages/services/service-automation/src/builtin/wait-node.ts index 366e8e9d8a..fb1b80b1f4 100644 --- a/packages/services/service-automation/src/builtin/wait-node.ts +++ b/packages/services/service-automation/src/builtin/wait-node.ts @@ -4,6 +4,7 @@ import type { PluginContext } from '@objectstack/core'; import { defineActionDescriptor } from '@objectstack/spec/automation'; import type { IJobService } from '@objectstack/spec/contracts'; import type { AutomationEngine, SuspendedRunStore } from '../engine.js'; +import { describeThrownForLog, type ThrownCauseMeta } from '../thrown-cause-diagnostics.js'; /** * The one-shot wake-up job's name for a timer `wait` pause — and, by @@ -21,6 +22,14 @@ function waitTimerJobName(runId: string, nodeId: string): string { * the wake-up fires and the pause survives it (#5529) — and the same level * {@link RearmLogger} requires for the re-arm path's degradations (#4632), * which is why that one extends this. + * + * The variadic tail is the `Logger` contract's own + * (`packages/spec/src/contracts/logger.ts`): `error(message, error?, meta?)`. + * A foreign cause therefore belongs in argument **three**, never two — the + * second slot is the `Error` slot, and putting a raw error there ships its whole + * stack on every record (#5575). #5737 moved all five of this file's causes out + * of the message into that third slot; the spy cases in + * `wait-node-log-cause.test.ts` are what hold the positions. */ interface WaitTimerLogger { error(msg: string, ...args: unknown[]): void; @@ -89,13 +98,30 @@ function makeWaitTimerJobHandler( const result = await engine.resume(runId); if (result?.code === 'STORE_UNAVAILABLE') { keepArmed = true; + // #5737 — the cause goes to `meta`, never into the message. This one is + // NOT a thrown value and so does NOT go through `describeThrownForLog`: + // `AutomationResult.error` is a STRING the engine already composed + // (`spec/contracts/automation-service.ts`), and the helper duck-types + // `.issues` / `.message` off a thrown object — on a string it has nothing + // to read, and on `undefined` it would render the literal `"undefined"` + // in place of the default below. The FIELD NAME is the helper's own + // (`ThrownCauseMeta.error`), so every seam in this package still reports + // a non-validation cause under exactly one key. + // + // Reachable as multi-line today: the engine builds this envelope by + // interpolating the driver's own `message` into it (engine.ts, the + // `STORE_UNAVAILABLE` return of `resumeInternal`). + const cause: ThrownCauseMeta = { error: result.error ?? 'store unavailable' }; logger.error( `[wait] timer wake-up '${jobName}' fired but could NOT resume run '${runId}': the durable suspended-run store was ` + `unreachable, so the pause was never consumed — the run is STILL parked at its wait node, now past its deadline, ` + `and this one-shot has already had its single shot, so nothing will wake it on its own. The job is left ARMED on ` + `purpose (its 'sys_job' row stays active) so the stuck run stays visible and the wake-up re-firable: once the ` + `store is reachable, re-fire it with the job service's trigger('${jobName}'), or resume the run directly via ` + - `resume('${runId}') — a process restart also picks it up as overdue. Cause: ${result.error ?? 'store unavailable'}`, + `resume('${runId}') — a process restart also picks it up as overdue. The resume envelope's own reason is in ` + + `this record's meta.`, + undefined, + cause, ); } } finally { @@ -212,9 +238,16 @@ export function registerWaitNode(engine: AutomationEngine, ctx: PluginContext): ); return { success: true, suspend: true, correlation: jobName, output }; } catch (err) { + // #5737 — `warn(message, meta?)`: the `Logger` contract has no + // `Error` slot below `error`, so the job service's own failure goes + // in argument TWO. Unlike the three `error` seams below this one is + // not a durability degradation (the run still suspends; only + // auto-resume is lost), which is why it stays `warn` — see the + // #4632 note on the `no job service` branch in the re-arm pass. ctx.logger.warn( - `[wait] node '${node.id}': failed to schedule timer resume (${(err as Error)?.message ?? err}); ` + - `suspending without auto-resume (resume it via resume(runId))`, + `[wait] node '${node.id}': failed to schedule timer resume — suspending without auto-resume ` + + `(resume it via resume(runId)). The job service's own failure is in this record's meta.`, + describeThrownForLog(err), ); } } else if (!job) { @@ -316,11 +349,18 @@ export async function rearmSuspendedWaitTimers( // re-arms NOTHING, so every run persisted before this restart stays paused // forever while the process reports a clean boot. The rows survived; the // promise that they would resume did not. + // #5737 — third argument, per `error(message, error?, meta?)`. NOT the + // second: a raw `Error` there ships its stack on the record (#5575). This is + // the seam #5737 measured — a database driver's multi-line failure spliced + // into this message split the loudest durability alarm in this file into + // three physical lines, of which only the first carried ` ERROR`. logger.error( `[wait] suspended wait-timer re-arm ABORTED — the suspended-run store could not be listed, so NO timer was re-armed: ` + `every wait/approval paused before this restart will hang indefinitely instead of resuming. The runs themselves are ` + - `still persisted. Fix the store/datasource error and restart to re-attempt the re-arm, or resume them via ` + - `resume(runId). Cause: ${(err as Error)?.message ?? err}`, + `still persisted. Fix the store/datasource failure in this record's meta and restart to re-attempt the re-arm, or ` + + `resume them via resume(runId).`, + undefined, + describeThrownForLog(err), ); return 0; } @@ -340,10 +380,15 @@ export async function rearmSuspendedWaitTimers( } catch (err) { // #4632 — this run's deadline already passed, so nothing else will ever // wake it: it is persisted, overdue, and now unreachable. + // #5737 — cause to `meta`'s slot (third), message stays one line. The + // text said "the cause below", which was only ever true of the spliced + // rendering; it now names where the cause actually is. logger.error( `[wait] suspended run '${run.runId}' is OVERDUE and could not be resumed — it stays persisted but nothing will ` + - `wake it again (its deadline has already passed, so no timer will be re-armed for it). Fix the cause below and ` + - `restart, or resume it directly via resume('${run.runId}'). Cause: ${(err as Error)?.message ?? err}`, + `wake it again (its deadline has already passed, so no timer will be re-armed for it). Fix the cause in this ` + + `record's meta and restart, or resume it directly via resume('${run.runId}').`, + undefined, + describeThrownForLog(err), ); } continue; @@ -380,11 +425,16 @@ export async function rearmSuspendedWaitTimers( // #4632 — the run is persisted and waiting, but its wake-up job was never // scheduled: it will sit at its wait node past its deadline with nothing // to resume it. + // #5737 — same as the two `error` seams above: third slot, one-line + // message. `${wakeAt}` stays in the message on purpose — it is a deadline + // THIS file persisted and re-read (`typeof === 'string'` + a non-NaN + // `Date.parse` two branches up), not foreign text. logger.error( `[wait] suspended run '${run.runId}' could NOT be re-scheduled — it stays persisted with a deadline of ${wakeAt}, ` + `but no job was armed to wake it, so it will hang past that deadline instead of resuming. Fix the job-service ` + - `error below and restart to re-attempt the re-arm, or resume it via resume('${run.runId}'). ` + - `Cause: ${(err as Error)?.message ?? err}`, + `failure in this record's meta and restart to re-attempt the re-arm, or resume it via resume('${run.runId}').`, + undefined, + describeThrownForLog(err), ); } } 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 1f115545c2..50dee75279 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 @@ -136,10 +136,11 @@ function zodLikeRejection(): Error { * 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. + * `[wait] … re-arm ABORTED …`, which #5737 has since brought into this same + * shape (one-line message, cause in meta) and pinned in + * `builtin/wait-node-log-cause.test.ts`. So the narrowing no longer dodges a + * shredded record, only a second seam's record: the counts below are per-seam + * (`toHaveLength(1)`), and this keeps them measuring the seam they name. * * ## No `delete` on purpose (#4550 / #5629) *