From 48ca87a8eda51b836f94e4e0ef814580e4865890 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 8 Aug 2026 04:51:33 +0000 Subject: [PATCH] fix(service-automation): stop splicing uncontrolled thrown text into engine.ts log messages (13 residual seams + 1 self-authored), re-grade run-history persist to error (#6499) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The 13 seams #6499 lists — datasource (persistSuspendedRun, listRuns, getRun, recordLog), plugin-supplied (releaseSuspension, unregisterTrigger, activateFlowTrigger, deactivateFlowTrigger), and engine-internal (resolveRunContext, expandDeclaredLookups, refuseInvalidScreenInput, bubbleToParent x2) — now log a single-line consequence-stating message and hand the cause to the logger's structured slot (describeThrownForLog), the #6299 / PR #6498 pattern. The 14th site (validateFlowExpressions' advisory pass) had the opposite cause — a self-authored newline — and gets the same shape: message one line, the author's expression source in the meta slot. Per-site #4632 verdicts (each pinned by test, since check:durability-log-level grades none of these): recordTerminal's fire-and-forget catch is RAISED warn -> error (terminal history row failed to land while the run reads healthy; the approvals sweeps then misread the hole); persistSuspendedRun stays error (#4460); all other sites stay warn (functional degradations that claim no persistence). Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01USNUyHEr7uaU6MoEWXitei --- .../engine-residual-log-splice-sweep.md | 51 ++ .../src/engine-residual-log-cause.test.ts | 604 ++++++++++++++++++ .../services/service-automation/src/engine.ts | 242 ++++++- .../src/suspended-run-store.test.ts | 15 +- .../src/suspension-release.test.ts | 18 +- 5 files changed, 900 insertions(+), 30 deletions(-) create mode 100644 .changeset/engine-residual-log-splice-sweep.md create mode 100644 packages/services/service-automation/src/engine-residual-log-cause.test.ts diff --git a/.changeset/engine-residual-log-splice-sweep.md b/.changeset/engine-residual-log-splice-sweep.md new file mode 100644 index 0000000000..9858239c98 --- /dev/null +++ b/.changeset/engine-residual-log-splice-sweep.md @@ -0,0 +1,51 @@ +--- +"@objectstack/service-automation": patch +--- + +fix(service-automation): the 13 residual `engine.ts` seams stop splicing uncontrolled thrown text into log messages, plus the one self-authored multi-line message; run-history persist failure is re-graded `error` (#6499) + +#6299 / PR #6498 fixed three `engine.ts` seams and closed with "this file is now +clean"; #6499 is the corrective record: 13 more logger calls in the same file +still interpolated a thrown value's `.message` — a datasource driver's, a +plugin's (trigger / node-executor), or, second-hand via the +`AutomationResult.error` envelope, a failing node's — into the log MESSAGE. +`ObjectLogger.write()` adds one ` ` head per call, so a cause +carrying newlines turned ONE record into several physical lines of which only +the first is greppable, and `serve`'s boot-quiet window drops the headless +continuations outright on the stdout (warn) path. All 13 now log a single-line +message stating the site's own consequence and hand the cause to the logger's +structured slot (`describeThrownForLog`). + +A 14th site with the opposite cause is fixed alongside, argued on its own +terms: `validateFlowExpressions`' advisory schema pass authored a literal +`\n source: …` continuation into a message we control, with the flow +author's (newline-tolerant CEL) expression as the second line. The message now +stays one line; the expression source rides the structured slot (`source`). + +The level was judged per seam (#4632), not batch-copied: + +- **`recordLog`'s fire-and-forget `store.recordTerminal` → RAISED to `error`.** + The write half of the run-history claim: a TERMINAL run's history row failed + to land while the run completed and every caller reads healthy — nothing + retries it, nothing upstream is told. After the next restart the run is + invisible to the Runs surfaces, `inspectStrandedRequests` (#3456) reads + "no suspension + no terminal row" as a STRANDED approval, and + `releasePendingForTerminalRuns` (#4469) reads "no terminal row" as + still-alive, so a finished run's leftover pending approvals are never + auto-released. +- **`persistSuspendedRun` stays `error`** (#4460's raise; #4420 is this exact + seam's accident) — no re-grade, message and slot fixed only. +- **Everything else stays `warn`** (functional): `listRuns` / `getRun` + (observability reads degrading to ring buffer / null — each record now says + the caller cannot tell the degraded answer from a real one), the four + plugin-supplied seams (`releaseSuspension`, `unregisterTrigger`, + `activateFlowTrigger`, `deactivateFlowTrigger`), the grants resolver, lookup + expansion, the screen `visibleWhen` probe, and both `bubbleToParent` + branches. Nothing these degrade claims to be persisted. + +Operator-visible: one record moves from stdout/`WARN` to stderr/`ERROR` +(run-history persist failure), and the reworded messages keep their original +lead phrases (`run-history read failed`, `durable run lookup failed`, +`Failed to bind flow`, `could not resolve grants`, …) so existing greps still +match; alert rules keyed on the trailing `: ` splice need the +structured `error` / `source` / `visibleWhen` fields instead. diff --git a/packages/services/service-automation/src/engine-residual-log-cause.test.ts b/packages/services/service-automation/src/engine-residual-log-cause.test.ts new file mode 100644 index 0000000000..9e1180af93 --- /dev/null +++ b/packages/services/service-automation/src/engine-residual-log-cause.test.ts @@ -0,0 +1,604 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// Regression: #6499 — the 13 residual `engine.ts` seams that still interpolated +// a FOREIGN cause (a caught error's `.message`, or a foreign envelope field) +// into a log MESSAGE after #6299 / PR #6498, plus the separately-argued 14th +// (`validateFlowExpressions`, a self-authored `\n` in a message we control). +// The ninth instalment of the family #5048 / #5575 / #5636 / #5661 / #5737 / +// #5912 / #6230 / #6299 closed. +// +// ## The shared half: the message +// +// `ObjectLogger.write()` (packages/core/src/logger.ts) 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 headless records, `grep WARN`/`grep ERROR` +// returns the one line with no facts on it, and `serve`'s boot-quiet window +// drops the continuations outright on the stdout (warn) path. The thrown value +// at these seams is a datasource driver's, a plugin's, or (second-hand, via the +// `AutomationResult.error` envelope) a failing node's own text, whose line +// count we do not control. cloud#971 is the shape. The fix at every site is the +// family's: the message stays one line, the cause rides the logger's structured +// slot (`describeThrownForLog`), which every Logger implementation serializes +// with JSON.stringify — newlines become `\n` escapes, one physical line. +// +// ## The half that is NOT shared: the level +// +// ⛔ Per #6299's lesson, each seam's #4632 verdict was taken on its own +// consequence path — see the per-site comments in engine.ts. The outcome here: +// +// - `persistSuspendedRun` → **error**, unchanged (#4460's raise; #4420 is +// this exact seam's accident). +// - `recordLog`'s fire-and-forget `store.recordTerminal` → **RAISED to +// error** (durability): a terminal run's history row failed to land while +// the run completed and every caller reads healthy; nothing retries it, +// and after a restart the approvals sweeps read the hole as +// stranded/never-finished. +// - Every other seam (2–3, 5–13) and the 14th → **warn**, unchanged +// (functional): nothing claimed-persisted fails to land; each record now +// states its own degradation out loud. +// +// `check:durability-log-level` grades NONE of these (its callee vocabulary +// does not name `SuspendedRunStore`'s methods and its read-seam scan roots do +// not reach this package), so the level pins below are the only thing holding +// all 14 verdicts. +// +// Assertions read REAL BYTES off a REAL `ObjectLogger` (per the #5662 → #6230 +// precedent: a spy proves what the seam called, not what a line-oriented +// consumer sees). Because the JSON format spreads `meta` into the record, a +// record that carries `error`/`source` proves the meta landed in the RIGHT +// argument slot — a meta passed third to `warn(message, meta?)` is silently +// dropped and the field would be absent. Prototype spies appear only where the +// `error(message, error?, meta?)` slot layout is itself the fact under test. + +import { describe, it, expect, vi } from 'vitest'; +import { ObjectLogger } from '@objectstack/core'; +import { AutomationEngine } from './engine.js'; +import type { NodeExecutor, SuspendedRun, SuspendedRunStore, FlowTrigger } from './engine.js'; +import type { AutomationContext } from '@objectstack/spec/contracts'; + +// ── fixtures ─────────────────────────────────────────────────────────────── + +/** + * What a database driver's failure looks like when it is not one line — + * byte-identical to the fixture the whole family uses + * (`suspended-run-store-consume-log-cause.test.ts` et al.), because it is the + * same accident. In-repo drivers are single-line today, which is why #6499 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 store where everything works except the one method a test breaks. */ +function workingStore(overrides: Partial): SuspendedRunStore { + return { + async save() {}, + async load(): Promise { return null; }, + async delete() {}, + async list(): Promise { return []; }, + ...overrides, + }; +} + +/** A pausing executor; `onRelease` optionally makes its teardown throw. */ +function pauser(onRelease?: () => void): NodeExecutor { + return { + type: 'pauser', + async execute(node) { + return { success: true, suspend: true, correlation: `test-armature:${node.id}` }; + }, + ...(onRelease ? { onSuspensionReleased: onRelease } : {}), + } as NodeExecutor; +} + +const PAUSE_FLOW = { + name: 'pause_flow', + label: 'Pause Flow', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'hold', type: 'pauser', label: 'Hold' }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'hold' }, + { id: 'e2', source: 'hold', target: 'end' }, + ], +}; + +/** The smallest flow that runs to a TERMINAL state. */ +const NOOP_FLOW = { + name: 'noop_flow', + label: 'Noop', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [{ id: 'e1', source: 'start', target: 'end' }], +}; + +/** A record-change-triggered flow, for the three trigger seams. */ +function triggeredFlow(name: string) { + return { + name, + label: name, + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start', config: { objectName: 'task', triggerType: 'record-after-update' } }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [{ id: 'e1', source: 'start', target: 'end' }], + }; +} + +const flush = () => new Promise((r) => setTimeout(r, 20)); + +// ── real-byte capture ────────────────────────────────────────────────────── + +/** Capture BOTH streams — every site's verdict includes a STREAM claim. */ +async function captureBoth(fn: () => Promise | void): Promise<{ stdout: string[]; stderr: string[] }> { + const out: string[] = []; + const err: string[] = []; + const outSpy = vi.spyOn(process.stdout, 'write').mockImplementation(((c: string | Uint8Array) => { + out.push(String(c)); + return true; + }) as never); + const errSpy = vi.spyOn(process.stderr, 'write').mockImplementation(((c: string | Uint8Array) => { + err.push(String(c)); + return true; + }) as never); + try { + await fn(); + } finally { + outSpy.mockRestore(); + errSpy.mockRestore(); + } + const split = (chunks: string[]) => chunks.join('').split('\n').filter((l) => l.length > 0); + return { stdout: split(out), stderr: split(err) }; +} + +type Rec = { level: string; msg: string; error?: string; issues?: unknown; source?: string; visibleWhen?: string }; + +/** + * The ONE JSON record on `lines` whose message carries `marker` — asserting + * both that it exists and that the record occupies exactly one physical line + * (a shredded record's continuation lines would not parse and would not carry + * the marker's level head). + */ +function soleRecordWith(lines: string[], marker: string): Rec { + const hits = lines.filter((l) => l.includes(marker)); + expect(hits, `exactly one physical line carries '${marker}'`).toHaveLength(1); + return JSON.parse(hits[0]) as Rec; +} + +/** Assert `lines` carries NO line mentioning `marker` (stream-silence pin). */ +function assertSilent(lines: string[], marker: string, stream: string): void { + expect(lines.filter((l) => l.includes(marker)), `nothing on ${stream}`).toEqual([]); +} + +function jsonLogger(): ObjectLogger { + return new ObjectLogger({ level: 'warn', format: 'json' }); +} + +/** The pretty-format ` ` head. */ +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/; + +/** The core one-line + cause-in-meta contract every site below re-asserts. */ +function expectOneLineWithCause(record: Rec, level: string): void { + expect(record.level).toBe(level); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'no driver fact leaks into the message').not.toContain('no such table'); + expect(record.msg).not.toContain('better-sqlite3'); + expect(record.error, 'the WHOLE driver text rides the structured slot').toBe(MULTILINE_DRIVER); + expect(record.issues).toBeUndefined(); +} + +// ═══ datasource-driver seam (sites 1–4) ════════════════════════════════════ + +describe('#6499 sites 1–4 — SuspendedRunStore driver seams', () => { + it("site 1: persistSuspendedRun — #4632 DURABILITY, stays `error`, one stderr line, cause in meta", async () => { + const engine = new AutomationEngine(jsonLogger(), workingStore({ + async save() { throw new Error(MULTILINE_DRIVER); }, + })); + engine.registerNodeExecutor(pauser()); + engine.registerFlow('pause_flow', PAUSE_FLOW); + + let paused: { status?: string } = {}; + const streams = await captureBoth(async () => { + paused = await engine.execute('pause_flow'); + }); + + // Behaviour unchanged: the in-memory suspension still parks the run. + expect(paused.status).toBe('paused'); + + const record = soleRecordWith(streams.stderr, 'failed to persist suspended run'); + expectOneLineWithCause(record, 'error'); + expect(record.msg).toContain('NOT be resumable after a restart'); + expect(record.msg).toContain("this record's meta"); + assertSilent(streams.stdout, 'failed to persist', 'stdout'); + }); + + it('site 1: stays one physical line in `pretty`, with every fact on the greppable line', async () => { + const engine = new AutomationEngine(new ObjectLogger({ level: 'warn', format: 'pretty' }), workingStore({ + async save() { throw new Error(MULTILINE_DRIVER); }, + })); + engine.registerNodeExecutor(pauser()); + engine.registerFlow('pause_flow', PAUSE_FLOW); + + const streams = await captureBoth(async () => { await engine.execute('pause_flow'); }); + expect(streams.stderr).toHaveLength(1); + expect(streams.stderr[0]).toMatch(RECORD_HEAD); + expect(streams.stderr[0]).toContain('failed to persist suspended run'); + expect(streams.stderr[0]).toContain('run `os migrate` for this datasource'); + }); + + it('site 1: hands the cause to error(message, error, meta) — meta THIRD, Error slot empty (#5575)', async () => { + const spy = vi.spyOn(ObjectLogger.prototype, 'error'); + const engine = new AutomationEngine(jsonLogger(), workingStore({ + async save() { throw new Error(MULTILINE_DRIVER); }, + })); + engine.registerNodeExecutor(pauser()); + engine.registerFlow('pause_flow', PAUSE_FLOW); + await captureBoth(async () => { await engine.execute('pause_flow'); }); + + const call = spy.mock.calls.find((c) => String(c[0]).includes('failed to persist suspended run')); + expect(call).toBeDefined(); + const [message, errorSlot, meta] = call as unknown as [string, unknown, Record]; + expect(message).not.toContain('\n'); + expect(errorSlot).toBeUndefined(); + expect(meta.error).toBe(MULTILINE_DRIVER); + spy.mockRestore(); + }); + + it("site 2: listRuns — #4632 FUNCTIONAL, stays `warn`, one stdout line, degradation said out loud", async () => { + const engine = new AutomationEngine(jsonLogger(), workingStore({ + async listHistory() { throw new Error(MULTILINE_DRIVER); }, + })); + + let listed: unknown[] = []; + const streams = await captureBoth(async () => { + listed = await engine.listRuns('some_flow'); + }); + + expect(listed).toEqual([]); // behaviour unchanged: degrades to the ring buffer + const record = soleRecordWith(streams.stdout, 'run-history read failed'); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain('DEGRADES to the in-memory ring buffer'); + expect(record.msg).toContain('cannot tell a short list from a complete one'); + assertSilent(streams.stderr, 'run-history read failed', 'stderr'); + }); + + it('site 2: stays one physical line in `pretty`', async () => { + const engine = new AutomationEngine(new ObjectLogger({ level: 'warn', format: 'pretty' }), workingStore({ + async listHistory() { throw new Error(MULTILINE_DRIVER); }, + })); + const streams = await captureBoth(async () => { await engine.listRuns('some_flow'); }); + expect(streams.stdout).toHaveLength(1); + expect(streams.stdout[0]).toMatch(RECORD_HEAD); + expect(streams.stdout[0]).toContain('run `os migrate` for this datasource'); + }); + + it("site 3: getRun — #4632 FUNCTIONAL, stays `warn`; the record admits null is indistinguishable", async () => { + const engine = new AutomationEngine(jsonLogger(), workingStore({ + async loadTerminal() { throw new Error(MULTILINE_DRIVER); }, + })); + + let got: unknown = 'unset'; + const streams = await captureBoth(async () => { + got = await engine.getRun('run_gone'); + }); + + expect(got).toBeNull(); // behaviour unchanged — the #5186 shape is out of #6499's scope + const record = soleRecordWith(streams.stdout, 'durable run lookup failed'); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain('DEGRADES to null'); + expect(record.msg).toContain('cannot tell the two apart'); + assertSilent(streams.stderr, 'durable run lookup failed', 'stderr'); + }); + + it("site 4: recordTerminal — #4632 DURABILITY, RAISED warn→error: the run reads healthy while its history row never landed", async () => { + const engine = new AutomationEngine(jsonLogger(), workingStore({ + async recordTerminal() { throw new Error(MULTILINE_DRIVER); }, + })); + engine.registerFlow('noop_flow', NOOP_FLOW); + + let res: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + res = await engine.execute('noop_flow'); + await flush(); // fire-and-forget .catch() + }); + + expect(res.success).toBe(true); // the run itself is untouched — that is the hazard + const record = soleRecordWith(streams.stderr, 'run-history persist failed'); + expectOneLineWithCause(record, 'error'); + expect(record.msg).toContain('nothing retries the write'); + expect(record.msg).toContain('approvals sweeps read it as never-finished'); + assertSilent(streams.stdout, 'run-history persist failed', 'stdout'); + }); + + it('site 4: hands the cause to error(message, error, meta) — meta THIRD, Error slot empty (#5575)', async () => { + const spy = vi.spyOn(ObjectLogger.prototype, 'error'); + const engine = new AutomationEngine(jsonLogger(), workingStore({ + async recordTerminal() { throw new Error(MULTILINE_DRIVER); }, + })); + engine.registerFlow('noop_flow', NOOP_FLOW); + await captureBoth(async () => { + await engine.execute('noop_flow'); + await flush(); + }); + + const call = spy.mock.calls.find((c) => String(c[0]).includes('run-history persist failed')); + expect(call).toBeDefined(); + const [message, errorSlot, meta] = call as unknown as [string, unknown, Record]; + expect(message).not.toContain('\n'); + expect(errorSlot).toBeUndefined(); + expect(meta.error).toBe(MULTILINE_DRIVER); + spy.mockRestore(); + }); +}); + +// ═══ plugin-supplied code seam (sites 5–8) ═════════════════════════════════ + +describe('#6499 sites 5–8 — plugin-supplied code seams, all #4632 FUNCTIONAL, all stay `warn`', () => { + it("site 5: releaseSuspension — the executor's thrown teardown rides meta; the handle stays in the message", async () => { + const engine = new AutomationEngine(jsonLogger()); + engine.registerNodeExecutor(pauser(() => { throw new Error(MULTILINE_DRIVER); })); + engine.registerFlow('pause_flow', PAUSE_FLOW); + + const paused = await engine.execute('pause_flow'); + let resumed: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + resumed = await engine.resume(paused.runId!); + }); + + expect(resumed.success).toBe(true); // teardown is best-effort — behaviour unchanged + const record = soleRecordWith(streams.stdout, 'failed to release its suspension'); + expectOneLineWithCause(record, 'warn'); + expect(record.msg, 'the operator clean-up handle').toContain('test-armature:hold'); + expect(record.msg).toContain('may still be scheduled'); + assertSilent(streams.stderr, 'failed to release', 'stderr'); + }); + + it("site 6: unregisterTrigger — the trigger's thrown stop() rides meta", async () => { + const engine = new AutomationEngine(jsonLogger()); + const trigger: FlowTrigger = { type: 'record_change', start() {}, stop() { throw new Error(MULTILINE_DRIVER); } }; + engine.registerTrigger(trigger); + engine.registerFlow('rc_unreg', triggeredFlow('rc_unreg')); + + const streams = await captureBoth(() => { engine.unregisterTrigger('record_change'); }); + + const record = soleRecordWith(streams.stdout, 'failed while unregistering the trigger'); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain("stop('rc_unreg')"); + expect(record.msg).toContain('may keep firing until the process restarts'); + assertSilent(streams.stderr, 'unregistering the trigger', 'stderr'); + }); + + it("site 7: activateFlowTrigger — the trigger's thrown start() rides meta; the flow's not-armed state is in the message", async () => { + const engine = new AutomationEngine(jsonLogger()); + const trigger: FlowTrigger = { type: 'record_change', start() { throw new Error(MULTILINE_DRIVER); }, stop() {} }; + engine.registerTrigger(trigger); + + const streams = await captureBoth(() => { engine.registerFlow('rc_bind', triggeredFlow('rc_bind')); }); + + const record = soleRecordWith(streams.stdout, 'Failed to bind flow'); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain("'rc_bind'"); + expect(record.msg).toContain('will NOT fire on this trigger'); + assertSilent(streams.stderr, 'Failed to bind flow', 'stderr'); + }); + + it("site 8: deactivateFlowTrigger — the trigger's thrown stop() rides meta", async () => { + const engine = new AutomationEngine(jsonLogger()); + const trigger: FlowTrigger = { type: 'record_change', start() {}, stop() { throw new Error(MULTILINE_DRIVER); } }; + engine.registerTrigger(trigger); + engine.registerFlow('rc_unbind', triggeredFlow('rc_unbind')); + + const streams = await captureBoth(async () => { await engine.toggleFlow('rc_unbind', false); }); + + const record = soleRecordWith(streams.stdout, 'failed while unbinding the flow'); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain("stop('rc_unbind')"); + assertSilent(streams.stderr, 'unbinding the flow', 'stderr'); + }); +}); + +// ═══ engine-internal, transitively foreign text (sites 9–13) ═══════════════ + +describe('#6499 sites 9–13 — engine-internal seams carrying foreign text, all #4632 FUNCTIONAL, all stay `warn`', () => { + it("site 9: resolveRunContext — the grants resolver's thrown text rides meta; fail-safe stays audible", async () => { + const engine = new AutomationEngine(jsonLogger()); + engine.registerFlow('noop_flow', NOOP_FLOW); + engine.setUserGrantsResolver(() => { throw new Error(MULTILINE_DRIVER); }); + + let res: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + res = await engine.execute('noop_flow', { userId: 'u1' } as AutomationContext); + }); + + expect(res.success).toBe(true); // fail-safe: the run proceeds, un-elevated + const record = soleRecordWith(streams.stdout, 'could not resolve grants'); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain('baseline member permissions (not elevated)'); + assertSilent(streams.stderr, 'could not resolve grants', 'stderr'); + }); + + it("site 10: expandDeclaredLookups — the expander's thrown text rides meta", async () => { + const engine = new AutomationEngine(jsonLogger()); + engine.registerFlow('expand_flow', { + ...NOOP_FLOW, + name: 'expand_flow', + nodes: [ + { id: 'start', type: 'start', label: 'Start', config: { expand: ['owner'] } }, + { id: 'end', type: 'end', label: 'End' }, + ], + }); + engine.setRecordExpander(() => { throw new Error(MULTILINE_DRIVER); }); + + let res: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + res = await engine.execute('expand_flow', { record: { id: 'r1' }, object: 'contact' } as AutomationContext); + }); + + expect(res.success).toBe(true); // expansion must never break the flow it feeds + const record = soleRecordWith(streams.stdout, 'could not expand lookups'); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain('[owner]'); + expect(record.msg).toContain('resolve to the scalar id'); + assertSilent(streams.stderr, 'could not expand lookups', 'stderr'); + }); + + it("site 11: refuseInvalidScreenInput — the author's predicate AND the evaluator's multi-line throw both ride meta", async () => { + // The predicate is metadata-author text and the evaluator's thrown + // message deliberately embeds it (`— source: \`…\``), so BOTH spliced + // pieces were uncontrolled. The broken predicate lives in the STORED + // row (rows at rest are not re-validated), the registered flow is + // clean — which is exactly how such a predicate reaches this seam. + const brokenPredicate = '][ not a predicate\nsecond line'; + const parked: SuspendedRun = { + runId: 'run_scr', + flowName: 'onboard', + nodeId: 'collect', + variables: {}, + steps: [], + context: {} as AutomationContext, + startedAt: new Date().toISOString(), + startTime: Date.now(), + screen: { + nodeId: 'collect', + title: 'Your details', + fields: [{ name: 'full_name', label: 'Full name', type: 'text', required: true, visibleWhen: brokenPredicate }], + } as SuspendedRun['screen'], + }; + const engine = new AutomationEngine(jsonLogger(), workingStore({ + async load(runId) { return runId === 'run_scr' ? parked : null; }, + })); + engine.registerFlow('onboard', { + name: 'onboard', + label: 'Onboard', + type: 'screen', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'collect', type: 'screen', label: 'Your details', config: { title: 'Your details', fields: [] } }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'collect' }, + { id: 'e2', source: 'collect', target: 'end' }, + ], + }); + + let resumed: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + resumed = await engine.resume('run_scr', { variables: {} }); + }); + + expect(resumed.success).toBe(true); // unevaluable ⇒ hidden ⇒ `required` not enforced + const record = soleRecordWith(streams.stdout, 'has a visibleWhen that could not be evaluated'); + expect(record.level).toBe('warn'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the predicate never reaches the message').not.toContain('][ not a predicate'); + expect(record.msg).toContain('`required` is not enforced'); + expect(record.visibleWhen, "the author's predicate, whole").toBe(brokenPredicate); + expect(record.error, "the evaluator's own multi-line throw").toContain('condition'); + expect(record.error).toContain('][ not a predicate'); + assertSilent(streams.stderr, 'visibleWhen', 'stderr'); + }); + + it("site 12: bubbleToParent — the parent's failure ENVELOPE (which carries foreign text verbatim, #5912) rides meta", async () => { + const engine = new AutomationEngine(jsonLogger()); + engine.registerNodeExecutor(pauser()); + engine.registerFlow('pause_flow', PAUSE_FLOW); + const paused = await engine.execute('pause_flow', { $parentRunId: 'run_parent' } as unknown as AutomationContext); + expect(paused.status).toBe('paused'); + + // Route ONLY the parent's resume into a failure envelope carrying the + // driver's text verbatim — the #5912-preserved `AutomationResult.error` + // shape this seam re-splices second-hand. The child's own resume goes + // through the real implementation untouched. + const eng = engine as unknown as { resumeInternal: (runId: string, ...rest: unknown[]) => Promise }; + const real = eng.resumeInternal.bind(engine); + eng.resumeInternal = async (runId: string, ...rest: unknown[]) => + runId === 'run_parent' ? { success: false, error: MULTILINE_DRIVER } : real(runId, ...rest); + + let resumed: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + resumed = await engine.resume(paused.runId!); + }); + + expect(resumed.success).toBe(true); // the child's completion is genuine + const record = soleRecordWith(streams.stdout, "the parent's failure envelope is in this record's meta"); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain("resuming parent 'run_parent'"); + assertSilent(streams.stderr, 'resuming parent', 'stderr'); + }); + + it('site 13: bubbleToParent — a THROWN parent resume rides meta', async () => { + const engine = new AutomationEngine(jsonLogger()); + engine.registerNodeExecutor(pauser()); + engine.registerFlow('pause_flow', PAUSE_FLOW); + const paused = await engine.execute('pause_flow', { $parentRunId: 'run_parent' } as unknown as AutomationContext); + + const eng = engine as unknown as { resumeInternal: (runId: string, ...rest: unknown[]) => Promise }; + const real = eng.resumeInternal.bind(engine); + eng.resumeInternal = async (runId: string, ...rest: unknown[]) => { + if (runId === 'run_parent') throw new Error(MULTILINE_DRIVER); + return real(runId, ...rest); + }; + + let resumed: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + resumed = await engine.resume(paused.runId!); + }); + + expect(resumed.success).toBe(true); // best-effort: never thrown back at the child's resumer + const record = soleRecordWith(streams.stdout, "threw — the thrown failure is in this record's meta"); + expectOneLineWithCause(record, 'warn'); + expect(record.msg).toContain("resuming parent 'run_parent'"); + assertSilent(streams.stderr, 'resuming parent', 'stderr'); + }); +}); + +// ═══ the separately-argued 14th site ═══════════════════════════════════════ + +describe("#6499 site 14 — validateFlowExpressions' advisory pass: a self-authored newline, not a foreign one", () => { + it("the advisory finding stays one line; the author's (possibly multi-line) expression source rides meta", async () => { + // The OPPOSITE cause of sites 1–13: nothing threw and no envelope is + // involved — the old message itself authored `\n source: …`, and + // `issue.source` is the flow AUTHOR's expression, whose line count is + // theirs (CEL is newline-tolerant, as this fixture proves by + // registering cleanly). Level stays `warn` BY #1928's contract: + // advisory, logged-never-thrown, strictly additive to registration. + const engine = new AutomationEngine(jsonLogger()); + engine.setObjectSchemaResolver(() => ({ fields: ['amount', 'status'] })); + const source = 'amout >\n 100'; // near-miss of `amount`, spanning two lines + + let registered = false; + const streams = await captureBoth(() => { + engine.registerFlow('expense_check', { + name: 'expense_check', + label: 'Expense check', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start', config: { objectName: 'expense', condition: source } }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [{ id: 'e1', source: 'start', target: 'end' }], + }); + registered = true; + }); + + expect(registered).toBe(true); // advisory: the flow registers cleanly + const record = soleRecordWith(streams.stdout, "[flow 'expense_check']"); + expect(record.level).toBe('warn'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the did-you-mean finding itself').toContain('did you mean'); + expect(record.msg).toContain('`amount`'); + expect(record.source, "the author's expression, whole, newline intact").toBe(source); + assertSilent(streams.stderr, "[flow 'expense_check']", 'stderr'); + }); +}); diff --git a/packages/services/service-automation/src/engine.ts b/packages/services/service-automation/src/engine.ts index 80092121d0..d4adcef0a4 100644 --- a/packages/services/service-automation/src/engine.ts +++ b/packages/services/service-automation/src/engine.ts @@ -1244,8 +1244,23 @@ export class AutomationEngine implements IAutomationService { try { await this.store.save(run); } catch (err) { + // #6499 — the cause is the datasource DRIVER's own text, so it + // goes to the logger's STRUCTURED slot, never spliced into the + // message; see `forgetSuspendedRun`'s catch below for the full + // mechanism (#6299) — this seam is its nearest twin, on the + // same `SuspendedRunStore` driver. + // + // #4632 verdict: DURABILITY — the level STAYS `error`, where + // #4460 put it: the docblock above argues it (#4420 is this + // exact seam's accident). Third argument per the `Logger` + // contract (`error(message, error?, meta?)`); the `Error` slot + // stays empty on purpose (#5575). this.logger.error( - `[automation] failed to persist suspended run '${run.runId}' to the durable store — it is kept in memory only and will NOT be resumable after a restart: ${(err as Error).message}`, + `[automation] failed to persist suspended run '${run.runId}' to the durable store — it is ` + + `kept in memory only and will NOT be resumable after a restart. Fix the store failure ` + + `in this record's meta.`, + undefined, + describeThrownForLog(err), ); } } @@ -1356,10 +1371,22 @@ export class AutomationEngine implements IAutomationService { reason, }); } catch (err) { + // #6499 — the thrown text is PLUGIN-SUPPLIED (the node executor's + // own teardown), so it goes to the structured slot; see + // `forgetSuspendedRun`'s catch above for the full mechanism + // (#6299). The message keeps the correlation handle — that is the + // thing an operator cleans up by hand. + // + // #4632 verdict: FUNCTIONAL — stays `warn`, per the docblock: the + // run continued and nothing claimed-persisted failed to land; the + // leftover is whatever the node armed on entry (a misleading + // `sys_job` row, not a broken run). `warn(message, meta?)` — meta + // is the SECOND argument; `warn` has no `Error` slot. this.logger.warn( `[automation] run '${run.runId}': '${nodeType}' node '${run.nodeId}' failed to release its suspension ` + - `(reason: ${reason}, correlation: ${run.correlation ?? 'none'}): ${(err as Error)?.message ?? err} — ` + - `the run continued; whatever the node armed on entry may still be scheduled`, + `(reason: ${reason}, correlation: ${run.correlation ?? 'none'}) — the run continued; whatever the ` + + `node armed on entry may still be scheduled. The executor's own failure is in this record's meta.`, + describeThrownForLog(err), ); } } @@ -1555,7 +1582,21 @@ export class AutomationEngine implements IAutomationService { try { this.triggers.get(type)?.stop(name); } catch (err) { - this.logger.warn(`Trigger '${type}' stop('${name}') failed: ${(err as Error).message}`); + // #6499 — the thrown text is PLUGIN-SUPPLIED (`FlowTrigger.stop`), + // so it goes to the structured slot; see `forgetSuspendedRun`'s + // catch above for the full mechanism (#6299). + // + // #4632 verdict: FUNCTIONAL — stays `warn`: nothing + // claimed-persisted is involved. The binding bookkeeping is + // dropped either way; the worst case is the trigger's own + // subscription staying armed, and a fired flow still lands in + // run history visibly, behind execute()'s own guards. + this.logger.warn( + `Trigger '${type}' stop('${name}') failed while unregistering the trigger — the flow is ` + + `unbound anyway; whatever the trigger armed for it may keep firing until the process ` + + `restarts. The trigger's own failure is in this record's meta.`, + describeThrownForLog(err), + ); } this.boundFlowTriggers.delete(name); } @@ -1696,7 +1737,21 @@ export class AutomationEngine implements IAutomationService { this.boundFlowTriggers.set(flowName, resolved.triggerType); this.logger.info(`Flow '${flowName}' bound to trigger '${resolved.triggerType}'`); } catch (err) { - this.logger.warn(`Failed to bind flow '${flowName}' to trigger '${resolved.triggerType}': ${(err as Error).message}`); + // #6499 — plugin-supplied thrown text (`FlowTrigger.start`) to the + // structured slot; see `forgetSuspendedRun`'s catch above for the + // full mechanism (#6299). + // + // #4632 verdict: FUNCTIONAL — stays `warn`: "a trigger is not + // armed" is the rule's own canonical `warn` example. The flow is + // visibly smaller than declared (its runs never appear), and the + // kernel:bootstrapped binding audit re-reports every unbound + // triggered flow. + this.logger.warn( + `Failed to bind flow '${flowName}' to trigger '${resolved.triggerType}' — the flow stays ` + + `registered but will NOT fire on this trigger until the flow or the trigger is ` + + `re-registered. The trigger's own failure is in this record's meta.`, + describeThrownForLog(err), + ); } } @@ -1707,7 +1762,21 @@ export class AutomationEngine implements IAutomationService { try { this.triggers.get(boundType)?.stop(flowName); } catch (err) { - this.logger.warn(`Trigger '${boundType}' stop('${flowName}') failed: ${(err as Error).message}`); + // #6499 — plugin-supplied thrown text (`FlowTrigger.stop`) to the + // structured slot; see `forgetSuspendedRun`'s catch above for the + // full mechanism (#6299). + // + // #4632 verdict: FUNCTIONAL — stays `warn`, same consequence shape + // as `unregisterTrigger`'s stop above: the binding is dropped + // either way, and a subscription the trigger failed to tear down + // fires into execute()'s own disabled/unregistered-flow guards, + // visibly. + this.logger.warn( + `Trigger '${boundType}' stop('${flowName}') failed while unbinding the flow — the binding is ` + + `dropped anyway; whatever the trigger armed for it may keep firing until the process ` + + `restarts. The trigger's own failure is in this record's meta.`, + describeThrownForLog(err), + ); } this.boundFlowTriggers.delete(flowName); } @@ -2357,8 +2426,25 @@ export class AutomationEngine implements IAutomationService { const rows = await this.store.listHistory(flowName, limit); durable = rows.map(r => this.runRecordToLogEntry(r)); } catch (err) { + // #6499 — the datasource driver's text to the structured slot; + // see `forgetSuspendedRun`'s catch above for the full mechanism + // (#6299). `warn(message, meta?)` — meta is the SECOND + // argument; `warn` has no `Error` slot. + // + // #4632 verdict: FUNCTIONAL — stays `warn`, the same reasoning + // as `listSuspendedRunsDurable` below: nothing + // claimed-persisted failed to land — the history rows are + // intact — and this read feeds only the observability Runs + // view, which degrades to the in-memory ring buffer. The + // record says the shortfall out loud (#5186's invented-answer + // shape; its propagation remedy is a return-contract change + // outside #6499). this.logger.warn( - `[Automation] run-history read failed for '${flowName}': ${(err as Error)?.message}`, + `[Automation] run-history read failed for '${flowName}' — the Runs listing DEGRADES to the ` + + `in-memory ring buffer alone, so terminal runs from before the last restart (or evicted ` + + `from the buffer) are missing and the caller cannot tell a short list from a complete ` + + `one. The rows themselves are untouched. Fix the store failure in this record's meta.`, + describeThrownForLog(err), ); } } @@ -2412,8 +2498,26 @@ export class AutomationEngine implements IAutomationService { const rec = await this.store.loadTerminal(runId); if (rec) return this.runRecordToLogEntry(rec); } catch (err) { + // #6499 — driver text to the structured slot; see + // `forgetSuspendedRun`'s catch above for the full mechanism + // (#6299). + // + // #4632 verdict: FUNCTIONAL — stays `warn`. Nothing + // claimed-persisted failed to land: the terminal row, if one + // exists, is intact — this read degrades to `null`. What IS + // wrong is #5186's shape: `null` is also this method's honest + // "no such run", so a caller cannot tell an unreadable store + // from a run that never ran (plugin-approvals' + // `inspectStrandedRequests` counts a THROWN getRun as + // `undetermined` — a distinction this swallow denies it). The + // remedy is propagation, a return-contract change outside + // #6499's scope, so the record says the degradation out loud. this.logger.warn( - `[Automation] durable run lookup failed for '${runId}': ${(err as Error)?.message}`, + `[Automation] durable run lookup failed for '${runId}' — this read DEGRADES to null, so ` + + `the caller sees exactly what it would see if the run had never run and cannot tell ` + + `the two apart. The terminal row, if one exists, is untouched. Fix the store failure ` + + `in this record's meta.`, + describeThrownForLog(err), ); } } @@ -2486,10 +2590,19 @@ export class AutomationEngine implements IAutomationService { // the trigger's (unresolved) identity — the data middleware applies // its baseline member fallback, NOT elevation — and we warn loudly // so the degraded authorization is audible rather than silent. + // + // #6499 — the resolver's thrown text (transitively the + // datasource's) goes to the structured slot; see + // `forgetSuspendedRun`'s catch above for the full mechanism + // (#6299). #4632 verdict: FUNCTIONAL — stays `warn`: the + // degradation is fail-safe as argued above, its symptom is the + // run's own data-op refusals/strips, and nothing + // claimed-persisted failed to land. this.logger.warn( `[runAs] flow '${flow.name}' could not resolve grants for triggering user ` + - `'${runContext.userId}': ${(err as Error)?.message ?? String(err)}. Its data ops fall ` + - `back to baseline member permissions (not elevated).`, + `'${runContext.userId}' — its data ops fall back to baseline member permissions ` + + `(not elevated). The resolver's failure is in this record's meta.`, + describeThrownForLog(err), ); } } @@ -2559,10 +2672,18 @@ export class AutomationEngine implements IAutomationService { } } } catch (err) { + // #6499 — the expander's thrown text (transitively the + // datasource's) goes to the structured slot; see + // `forgetSuspendedRun`'s catch above for the full mechanism + // (#6299). #4632 verdict: FUNCTIONAL — stays `warn`, per the + // docblock: expansion is best-effort enrichment that must never + // break the flow it feeds, and the visible symptom is templates + // rendering the scalar id. this.logger.warn( `[expand] flow '${flow.name}' could not expand lookups [${expandFields.join(', ')}] on ` + - `'${object}#${String(id)}': ${(err as Error)?.message ?? String(err)}. Templates referencing ` + - `these relations resolve to the scalar id.`, + `'${object}#${String(id)}' — templates referencing these relations resolve to the scalar ` + + `id. The expander's failure is in this record's meta.`, + describeThrownForLog(err), ); } } @@ -3446,10 +3567,22 @@ export class AutomationEngine implements IAutomationService { try { return this.evaluateCondition(String(field.visibleWhen), scope); } catch (err) { + // #6499 — BOTH spliced pieces were uncontrolled: the author's + // own `visibleWhen` source (metadata text of any shape) and + // the evaluator's thrown message (`evaluateCondition` composes + // a deliberately multi-line one). Both go to the structured + // slot; see `forgetSuspendedRun`'s catch above for the full + // mechanism (#6299). + // + // #4632 verdict: FUNCTIONAL — stays `warn`: one field's + // `required` is not enforced for one submission, the resume + // caller reads the outcome directly, and nothing + // claimed-persisted is involved. this.logger.warn( `[automation] run '${runId}': screen field '${field.name}' has a visibleWhen that could not be ` + - `evaluated (\`${field.visibleWhen}\`: ${(err as Error)?.message}) — its \`required\` is not ` + - `enforced for this submission`, + `evaluated — its \`required\` is not enforced for this submission. The predicate and the ` + + `evaluator's failure are in this record's meta.`, + { visibleWhen: String(field.visibleWhen), ...describeThrownForLog(err) }, ); return undefined; } @@ -3520,13 +3653,36 @@ export class AutomationEngine implements IAutomationService { : this.buildSubflowResumeSignal(run.context, output); const parentRes = await this.resumeInternal(parentRunId, sig, false, summary); if (!parentRes.success) { + // #6499 — `parentRes.error` is the envelope field that carries + // a failing node's / driver's text VERBATIM (#5912 left it + // that way on purpose), so foreign newlines reach this message + // second-hand; it goes to the structured slot. See + // `forgetSuspendedRun`'s catch above for the full mechanism + // (#6299). + // + // #4632 verdict: FUNCTIONAL — stays `warn`: no false success + // is recorded anywhere — the parent either failed terminally + // (recorded in run history) or stays visibly parked and + // resumable — and the child's own completion, which is what + // its resumer was told, is genuine. this.logger.warn( - `[automation] subflow run '${run.runId}' completed but resuming parent '${parentRunId}' failed: ${parentRes.error}`, + `[automation] subflow run '${run.runId}' completed but resuming parent '${parentRunId}' ` + + `failed — the parent's failure envelope is in this record's meta.`, + { error: parentRes.error ?? 'unknown error' }, ); } } catch (err) { + // #6499 — thrown text to the structured slot; see + // `forgetSuspendedRun`'s catch above for the full mechanism + // (#6299). #4632 verdict: FUNCTIONAL — stays `warn`, the same + // consequence envelope as the branch above: the parent's + // suspension was either consumed with a recorded outcome or + // survives parked and resumable; nothing reads as success that + // is not. this.logger.warn( - `[automation] subflow run '${run.runId}' completed but resuming parent '${parentRunId}' threw: ${(err as Error).message}`, + `[automation] subflow run '${run.runId}' completed but resuming parent '${parentRunId}' ` + + `threw — the thrown failure is in this record's meta.`, + describeThrownForLog(err), ); } } @@ -3838,8 +3994,39 @@ export class AutomationEngine implements IAutomationService { summary: entry.summary, }; void this.store.recordTerminal(record).catch((err) => { - this.logger.warn( - `[Automation] run-history persist failed for '${entry.flowName}': ${(err as Error)?.message}`, + // #6499 — driver text to the structured slot; see + // `forgetSuspendedRun`'s catch above for the full mechanism + // (#6299). + // + // #4632 verdict: DURABILITY — RAISED from `warn` to `error`. + // This is the WRITE half of the run-history claim whose read + // halves (`listRuns` / `getRun` above) stay `warn`: a TERMINAL + // run's history row failed to land while the run itself + // completed and every caller reads healthy — fire-and-forget, + // nothing retries it, nothing upstream is told. After the next + // restart the run is invisible to the Runs surfaces, and the + // approvals sweeps read exactly that hole: `inspectStranded- + // Requests` (#3456) treats "no suspension + no terminal row" + // as a STRANDED request, so a run that actually completed is + // reported as lost, and `releasePendingForTerminalRuns` + // (#4469) treats "no terminal row" as still-alive, so a + // finished run's leftover pending approvals are never + // auto-released. A write that claims to persist did not, while + // the system keeps looking healthy — #4632's judgment question + // answers YES. `check:durability-log-level` cannot see it + // (`SuspendedRunStore.recordTerminal` is not in its callee + // vocabulary), so the level is pinned by a test instead. + // + // THIRD argument per `error(message, error?, meta?)`; the + // `Error` slot stays empty on purpose (#5575). + this.logger.error( + `[Automation] run-history persist failed for terminal run '${entry.id}' of flow ` + + `'${entry.flowName}' — the run finished and reads healthy everywhere, but its history ` + + `row never landed and nothing retries the write, so after the next restart this run is ` + + `invisible to the Runs surfaces and the approvals sweeps read it as never-finished. ` + + `Fix the store failure in this record's meta.`, + undefined, + describeThrownForLog(err), ); }); } @@ -4241,7 +4428,24 @@ export class AutomationEngine implements IAutomationService { if (useSchemaHint && result.errors.length === 0 && schemaHint) { const schemaPass = validateExpression('predicate', raw as string | { dialect?: string; source?: string }, schemaHint); for (const issue of [...schemaPass.errors, ...schemaPass.warnings]) { - this.logger.warn(`[flow '${flowName}'] ${where}: ${issue.message}\n source: \`${issue.source}\``); + // #6499's separately-argued 14th site — the OPPOSITE cause + // of the thrown-text seams: no foreign thrown value is + // involved; this message simply AUTHORED a second physical + // line (`\n source: …`) into a one-record-per-call + // logger, and `issue.source` is the flow AUTHOR's + // expression text, whose line count is theirs (CEL is + // newline-tolerant). Same downstream damage as the family + // (see `forgetSuspendedRun`'s catch, #6299), same fix + // shape: the message stays one line (`issue.message` + // embeds at most identifier names, which cannot carry + // newlines), the source moves to the structured slot. + // + // #4632 verdict: FUNCTIONAL — stays `warn` BY CONTRACT: + // #1928 defines this advisory schema pass as logged-never- + // thrown and strictly additive to registration; a finding + // here must not fail or alarm a flow that registers + // cleanly. + this.logger.warn(`[flow '${flowName}'] ${where}: ${issue.message}`, { source: issue.source }); } } }; diff --git a/packages/services/service-automation/src/suspended-run-store.test.ts b/packages/services/service-automation/src/suspended-run-store.test.ts index 0d84005cad..6c78dce212 100644 --- a/packages/services/service-automation/src/suspended-run-store.test.ts +++ b/packages/services/service-automation/src/suspended-run-store.test.ts @@ -256,11 +256,11 @@ describe('resume failure codes', () => { }); it('logs a failed durable write at ERROR — a pause kept only in memory is data loss in waiting', async () => { - const lines: { level: string; msg: string }[] = []; + const lines: { level: string; msg: string; meta?: Record }[] = []; const logger: any = { info: (m: any) => lines.push({ level: 'info', msg: String(m) }), - warn: (m: any) => lines.push({ level: 'warn', msg: String(m) }), - error: (m: any) => lines.push({ level: 'error', msg: String(m) }), + warn: (m: any, meta?: any) => lines.push({ level: 'warn', msg: String(m), meta }), + error: (m: any, _err?: any, meta?: any) => lines.push({ level: 'error', msg: String(m), meta }), debug: () => {}, child() { return logger; }, }; @@ -270,9 +270,12 @@ describe('resume failure codes', () => { .execute('approval_flow'); expect(paused.status).toBe('paused'); // the run still pauses… - const errs = lines.filter(l => l.level === 'error').map(l => l.msg).join('\n'); - expect(errs).toMatch(/no such table: sys_automation_run/); - expect(errs).toMatch(/NOT be resumable after a restart/); + const rec = lines.find(l => l.level === 'error' && /NOT be resumable after a restart/.test(l.msg)); + expect(rec).toBeTruthy(); + // #6499 — the driver's own text rides the STRUCTURED slot, never the + // message (whose line count must stay ours). + expect(rec!.msg).not.toMatch(/no such table/); + expect(String(rec!.meta?.error)).toMatch(/no such table: sys_automation_run/); }); }); diff --git a/packages/services/service-automation/src/suspension-release.test.ts b/packages/services/service-automation/src/suspension-release.test.ts index 150e36a6a0..8f63ba5493 100644 --- a/packages/services/service-automation/src/suspension-release.test.ts +++ b/packages/services/service-automation/src/suspension-release.test.ts @@ -164,8 +164,13 @@ describe('NodeExecutor.onSuspensionReleased (#5512)', () => { }); it('a teardown that throws is logged and does not fail the continuation', async () => { - const warns: string[] = []; - const loud = new AutomationEngine(silentLogger(warns)); + const warns: Array<{ msg: string; meta?: Record }> = []; + const recordingLogger = { + info() {}, error() {}, debug() {}, + warn(msg: string, meta?: Record) { warns.push({ msg: String(msg), meta }); }, + child() { return recordingLogger; }, + } as any; + const loud = new AutomationEngine(recordingLogger); const ranLoud: string[] = []; loud.registerNodeExecutor(markerExecutor(ranLoud)); loud.registerNodeExecutor({ @@ -180,11 +185,14 @@ describe('NodeExecutor.onSuspensionReleased (#5512)', () => { expect(resumed.success).toBe(true); // the run is what matters — teardown is best-effort expect(ranLoud).toEqual(['after']); - const warn = warns.find((w) => w.includes('failed to release its suspension')); + const warn = warns.find((w) => w.msg.includes('failed to release its suspension')); expect(warn).toBeTruthy(); // The line has to name the handle an operator would clean up by hand. - expect(warn).toContain('test-armature:hold'); - expect(warn).toContain('job service exploded'); + expect(warn!.msg).toContain('test-armature:hold'); + // #6499 — the executor's own text is plugin-supplied, so it rides the + // STRUCTURED slot, never the message (whose line count must stay ours). + expect(warn!.msg).not.toContain('job service exploded'); + expect(warn!.meta?.error).toBe('job service exploded'); }); it('delegates through a deprecated node alias to the canonical executor', async () => {