diff --git a/.changeset/name-shaped-log-splice-sweep.md b/.changeset/name-shaped-log-splice-sweep.md new file mode 100644 index 0000000000..6b51c9e2ac --- /dev/null +++ b/.changeset/name-shaped-log-splice-sweep.md @@ -0,0 +1,41 @@ +--- +'@objectstack/service-automation': patch +--- + +fix(service-automation): the five NAME-shaped log splices stop interpolating foreign identifiers into log messages (#6654) + +The tail #6499 reported but did not fix and #6587 deliberately excluded: five +`service-automation` log records still spliced **names/identifiers** that +originate outside the engine's control and are not schema-constrained to reject +newlines. `ObjectLogger.write()` adds one ` ` head per call, so a +newline in any of them turns 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 — the same downstream damage as +the closed thrown-text class, reached through a different door. + +All five now log a single-line message carrying only controlled facts, with the +foreign identifier(s) in the logger's structured slot: + +- the **re-entrancy guard** — the caller's record id → `recordId`; +- the **refused resume** — the caller's resume-signal keys → `rejected`; +- the **screen-input refusal** — the user-submitted keys, which reach the + message via `validateScreenInputs`' `Unknown screen field "…"` findings → + `issues` (the message now states the issue COUNT); +- **`warnUnknownNodeTypes`** — the flow's unknown node type names and the + registered vocabulary → `unknownTypes` / `knownTypes`; +- the **unclaimed branch label** (#4414) — the computed, potentially + record-derived branch label and the out-edge labels → `branchLabel` / + `outEdges`. + +**No level changes**: every one of the five is #4632-FUNCTIONAL and stays +`warn`. Behaviour is unchanged at all five sites, and the caller-facing refusal +ENVELOPES (`INVALID_SIGNAL`, `INVALID_SCREEN_INPUT`) are untouched — they still +name the offending variables and fields, because an envelope is not a log +record. + +Operator-visible: each message keeps its lead phrase so existing greps still +match — `re-entered for the same record`, `signal writes engine-internal`, +`violates its declared field contract`, `no registered executor or descriptor` +(load-bearing: tests and log filters count per-flow findings by it), and +`no out-edge carries that label`. Anything keyed on the spliced identifier +inside those messages must read the structured field instead. diff --git a/packages/services/service-automation/src/builtin/decision-branch-routing.test.ts b/packages/services/service-automation/src/builtin/decision-branch-routing.test.ts index 0ff421bafc..ae6edf032d 100644 --- a/packages/services/service-automation/src/builtin/decision-branch-routing.test.ts +++ b/packages/services/service-automation/src/builtin/decision-branch-routing.test.ts @@ -18,12 +18,16 @@ import { registerLogicNodes } from './logic-nodes.js'; * The consequence shipped in `examples/app-crm` — see the first block below. */ -const warnings: string[] = []; +/** One captured `warn` call — message AND structured meta (#6654 moved the + * computed branch label and the out-edge labels into the meta slot). */ +type CapturedWarn = { msg: string; meta?: Record }; + +const warnings: CapturedWarn[] = []; function createTestLogger(): any { return { info: () => {}, - warn: (msg: string) => { warnings.push(String(msg)); }, + warn: (msg: string, meta?: Record) => { warnings.push({ msg: String(msg), meta }); }, error: () => {}, debug: () => {}, child: () => createTestLogger(), @@ -196,10 +200,19 @@ describe('decision branch routing (#4414)', () => { })); await run({ status: 'converted' }); + // #6654 — the computed branch label is potentially record-derived and + // the edge labels are flow-author metadata, so both moved out of the + // message into the structured slot. The #4414 fact under test is + // unchanged: the unclaimed selection is REPORTED, naming the computed + // branch and every out-edge label. expect(warnings.some((w) => - w.includes("selected branch 'Yes — already converted'") - && w.includes("'Yes'") && w.includes("'No'") - && w.includes('#4414'), + w.msg.includes('no out-edge carries that label') + && w.msg.includes('#4414') + && w.meta?.branchLabel === 'Yes — already converted' + && (w.meta?.outEdges as Array<{ label: string | null }>) + .map((e) => e.label).includes('Yes') + && (w.meta?.outEdges as Array<{ label: string | null }>) + .map((e) => e.label).includes('No'), )).toBe(true); // Behaviour is unchanged (a run mid-flight must not die on it) — but it // is no longer invisible. 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 index 3e45338a12..f6b939d2ed 100644 --- a/packages/services/service-automation/src/engine-residual-log-cause.test.ts +++ b/packages/services/service-automation/src/engine-residual-log-cause.test.ts @@ -175,7 +175,21 @@ async function captureBoth(fn: () => Promise | void): Promise<{ stdout: st return { stdout: split(out), stderr: split(err) }; } -type Rec = { level: string; msg: string; error?: string; issues?: unknown; source?: string; visibleWhen?: string }; +type Rec = { + level: string; + msg: string; + error?: string; + issues?: unknown; + source?: string; + visibleWhen?: string; + // #6654 — the name-splice sweep's structured slots. + recordId?: string; + rejected?: string[]; + unknownTypes?: string[]; + knownTypes?: string[]; + branchLabel?: string; + outEdges?: Array<{ id: string; label: string | null }>; +}; /** * The ONE JSON record on `lines` whose message carries `marker` — asserting @@ -714,3 +728,297 @@ describe("#6587 — activateFlowTrigger's trigger-fired-run callback: the Automa spy.mockRestore(); }); }); + +// ═══ #6654 — the five NAME-shaped splices (the weaker class #6499 reported) ═ + +// Unlike sites 1–14 above, nothing here throws and no envelope is involved: +// these five sites interpolated NAMES/IDENTIFIERS that originate outside the +// engine's control — a caller's record id, a resume signal's variable names, +// user-submitted screen keys, flow-author node type names, a computed branch +// label plus edge labels — none of which is schema-constrained against +// newlines. The fixtures below put a newline INTO the identifier to prove the +// family contract: the message stays one physical line carrying only +// controlled facts, the foreign identifier rides the structured meta slot, +// the level is unchanged (option A changes none), and behaviour is unchanged. + +describe("#6654 site 1 — the re-entrancy guard: the caller's record id rides meta", () => { + /** A record id only a caller could produce — carrying a newline. */ + const NL_RECORD_ID = 'case-1\nSECOND LINE'; + + /** Register a self-retriggering flow; returns the inner skip observation. */ + function armLoop(engine: AutomationEngine): { sawGuardSkip: () => boolean } { + let skipped = false; + engine.registerNodeExecutor({ + type: 'self_retrigger', + async execute() { + // Re-fire the SAME flow for the SAME record (the loop shape). + const r = await engine.execute('looping_flow', { + record: { id: NL_RECORD_ID }, + object: 'crm_case', + event: 'record-after-update', + } as unknown as AutomationContext); + if ((r.output as { reason?: string } | undefined)?.reason === 'reentrancy_loop_guard') skipped = true; + return { success: true }; + }, + } as NodeExecutor); + engine.registerFlow('looping_flow', { + name: 'looping_flow', + label: 'Looping', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'loop', type: 'self_retrigger', label: 'Loop' }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'loop' }, + { id: 'e2', source: 'loop', target: 'end' }, + ], + }); + return { sawGuardSkip: () => skipped }; + } + + it("stays `warn`, one stdout line; the record id never reaches the message", async () => { + const engine = new AutomationEngine(jsonLogger()); + const loop = armLoop(engine); + + let res: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + res = await engine.execute('looping_flow', { + record: { id: NL_RECORD_ID }, + object: 'crm_case', + event: 'record-after-update', + } as unknown as AutomationContext); + }); + + // Behaviour unchanged: the outer run completes, the inner re-fire is + // skipped with the guard's envelope. + expect(res.success).toBe(true); + expect(loop.sawGuardSkip()).toBe(true); + + const record = soleRecordWith(streams.stdout, 're-entered for the same record'); + expect(record.level).toBe('warn'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the record id never reaches the message').not.toContain('SECOND LINE'); + expect(record.msg, 'the flow-name correlation stays').toContain("'looping_flow'"); + expect(record.recordId, "the caller's id, whole, newline intact").toBe(NL_RECORD_ID); + assertSilent(streams.stderr, 're-entered for the same record', 'stderr'); + }); + + it('stays one physical line in `pretty`, with the id escaped onto the greppable line', async () => { + const engine = new AutomationEngine(new ObjectLogger({ level: 'warn', format: 'pretty' })); + armLoop(engine); + // Seal AFTER registering, so the vocabulary-never-sealed warning + // (#4792) cannot add a second stdout line to this count. + engine.sealNodeTypeVocabulary(); + + const streams = await captureBoth(async () => { + await engine.execute('looping_flow', { + record: { id: NL_RECORD_ID }, + object: 'crm_case', + event: 'record-after-update', + } as unknown as AutomationContext); + }); + + expect(streams.stdout).toHaveLength(1); + expect(streams.stdout[0]).toMatch(RECORD_HEAD); + expect(streams.stdout[0]).toContain('re-entered for the same record'); + // JSON.stringify escapes the newline, so the id survives ON this line. + expect(streams.stdout[0]).toContain('SECOND LINE'); + }); +}); + +describe("#6654 site 2 — refused resume: the signal's rejected variable names ride meta", () => { + it("stays `warn`, one stdout line; the caller's names never reach the message; the refusal envelope still names them", async () => { + const engine = new AutomationEngine(jsonLogger()); + engine.registerNodeExecutor(pauser()); + engine.registerFlow('pause_flow', PAUSE_FLOW); + const paused = await engine.execute('pause_flow'); + expect(paused.status).toBe('paused'); + + const evilName = '$evil\nname'; + let res: { success?: boolean; code?: string; error?: string } = {}; + const streams = await captureBoth(async () => { + res = await engine.resume(paused.runId!, { variables: { [evilName]: 1 } }); + }); + + // Behaviour unchanged: refused as a whole, envelope code intact, and + // the ENVELOPE (caller-facing refusal text, not a log record — the + // class ruled elsewhere) still names the variables. + expect(res.success).toBe(false); + expect(res.code).toBe('INVALID_SIGNAL'); + expect(res.error).toContain('may not set engine-internal variables'); + + const record = soleRecordWith(streams.stdout, 'signal writes engine-internal'); + expect(record.level).toBe('warn'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the rejected name never reaches the message').not.toContain('$evil'); + expect(record.msg, 'the run correlation stays').toContain(`'${paused.runId}'`); + expect(record.rejected, 'the rejected names, whole, newline intact').toEqual([evilName]); + assertSilent(streams.stderr, 'signal writes engine-internal', 'stderr'); + + // The pause stayed live: the legitimate continuation still lands. + const retry = await engine.resume(paused.runId!, { variables: { ok: 1 } }); + expect(retry.success).toBe(true); + }); +}); + +describe('#6654 site 3 — screen-input refusal: the user-submitted keys ride meta', () => { + it("stays `warn`, one stdout line; the submitted key never reaches the message; the refusal envelope keeps the summary", async () => { + const parked: SuspendedRun = { + runId: 'run_scr2', + flowName: 'onboard2', + 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 }], + } as SuspendedRun['screen'], + }; + const engine = new AutomationEngine(jsonLogger(), workingStore({ + async load(runId) { return runId === 'run_scr2' ? parked : null; }, + })); + // The real `screen` executor, for site 11's reason: since #5561 step + // two the public gate reads the pause's authority off the suspended + // node's descriptor, and with no `screen` registered the resume is + // refused fail-closed before this seam is reached. + registerScreenNodes(engine, { logger: jsonLogger(), getService() { return undefined; } } as never); + engine.registerFlow('onboard2', { + name: 'onboard2', + 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' }, + ], + }); + + const evilKey = 'evil\nkey'; + let res: { success?: boolean; code?: string; error?: string } = {}; + const streams = await captureBoth(async () => { + res = await engine.resume('run_scr2', { variables: { full_name: 'ok', [evilKey]: 1 } }); + }); + + // Behaviour unchanged: refused with the same code, and the ENVELOPE + // (caller-facing refusal text, not a log record — the class ruled + // elsewhere) still carries the per-field summary. + expect(res.success).toBe(false); + expect(res.code).toBe('INVALID_SCREEN_INPUT'); + expect(res.error).toContain('Unknown screen field'); + + const record = soleRecordWith(streams.stdout, 'violates its declared field contract'); + expect(record.level).toBe('warn'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the submitted key never reaches the message').not.toContain('evil'); + expect(record.msg, 'the controlled count stays in the message').toContain('1 issue(s)'); + const issues = record.issues as Array<{ field: string; code: string; message: string }>; + expect(issues).toHaveLength(1); + expect(issues[0].field, "the caller's key, whole, newline intact").toBe(evilKey); + expect(issues[0].code).toBe('unknown_field'); + expect(issues[0].message).toContain('Unknown screen field'); + assertSilent(streams.stderr, 'violates its declared field contract', 'stderr'); + }); +}); + +describe("#6654 site 4 — warnUnknownNodeTypes: the flow's type names ride meta", () => { + it("stays `warn`, one stdout line; the counted lead phrase survives; the names ride meta", async () => { + const engine = new AutomationEngine(jsonLogger()); + engine.sealNodeTypeVocabulary(); // close the vocabulary FIRST — registration validates inline + + const nlType = 'mys\ntery'; + let registered = false; + const streams = await captureBoth(() => { + engine.registerFlow('typo_flow', { + name: 'typo_flow', + label: 'Typo', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'mid', type: nlType, label: 'Mid' }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'mid' }, + { id: 'e2', source: 'mid', target: 'end' }, + ], + }); + registered = true; + }); + + // Behaviour unchanged: the warning is advisory — the flow registers. + expect(registered).toBe(true); + + // The lead phrase is load-bearing: tests and log filters count + // per-flow findings by this exact substring. + const record = soleRecordWith(streams.stdout, 'no registered executor or descriptor'); + expect(record.level).toBe('warn'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the type name never reaches the message').not.toContain('mys'); + expect(record.msg, 'the flow-name correlation stays').toContain("'typo_flow'"); + expect(record.unknownTypes, 'the unknown names, whole, newline intact').toEqual([nlType]); + expect(record.knownTypes, 'the vocabulary the audit judged against').toContain('start'); + assertSilent(streams.stderr, 'no registered executor or descriptor', 'stderr'); + }); +}); + +describe('#6654 site 5 — unclaimed branch label: the computed label and the edge labels ride meta', () => { + it("stays `warn`, one stdout line; label and edge labels never reach the message; traversal still fans out", async () => { + const nlBranch = 'sneaky\nbranch'; + const engine = new AutomationEngine(jsonLogger()); + let endReached = false; + engine.registerNodeExecutor({ + type: 'chooser', + async execute() { return { success: true, branchLabel: nlBranch }; }, + } as NodeExecutor); + engine.registerNodeExecutor({ + type: 'probe', + async execute() { endReached = true; return { success: true }; }, + } as NodeExecutor); + engine.registerFlow('branchy', { + name: 'branchy', + label: 'Branchy', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'choose', type: 'chooser', label: 'Choose' }, + { id: 'after', type: 'probe', label: 'After' }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'choose' }, + { id: 'e2', source: 'choose', target: 'after', label: 'approved' }, + { id: 'e3', source: 'after', target: 'end' }, + ], + }); + + let res: { success?: boolean } = {}; + const streams = await captureBoth(async () => { + res = await engine.execute('branchy'); + }); + + // Behaviour unchanged (#4414): the unclaimed selection is IGNORED, + // every out-edge is evaluated, and the run completes. + expect(res.success).toBe(true); + expect(endReached).toBe(true); + + const record = soleRecordWith(streams.stdout, 'no out-edge carries that label'); + expect(record.level).toBe('warn'); + expect(record.msg).not.toContain('\n'); + expect(record.msg, 'the computed label never reaches the message').not.toContain('sneaky'); + expect(record.msg, 'the edge labels never reach the message').not.toContain('approved'); + expect(record.msg, 'the node correlation stays').toContain("'choose'"); + expect(record.branchLabel, 'the computed label, whole, newline intact').toBe(nlBranch); + expect(record.outEdges, 'each out-edge id with its label').toEqual([{ id: 'e2', label: 'approved' }]); + assertSilent(streams.stderr, 'no out-edge carries that label', 'stderr'); + }); +}); diff --git a/packages/services/service-automation/src/engine.test.ts b/packages/services/service-automation/src/engine.test.ts index a5fa545009..b57473a411 100644 --- a/packages/services/service-automation/src/engine.test.ts +++ b/packages/services/service-automation/src/engine.test.ts @@ -2435,11 +2435,14 @@ describe('AutomationEngine - Execution Status', () => { // ─── ADR-0018: Action Descriptor Registry & Open Node Types ────────── describe('Action Descriptor Registry (ADR-0018)', () => { - /** Logger that records warn() messages so we can assert soft-validation. */ - function createCapturingLogger(warnings: string[]) { + /** One captured `warn` call: its message AND its structured meta. */ + type CapturedWarn = { msg: string; meta?: Record }; + + /** Logger that records warn() calls so we can assert soft-validation. */ + function createCapturingLogger(warnings: CapturedWarn[]) { const logger: any = { info: () => {}, - warn: (msg: string) => warnings.push(msg), + warn: (msg: string, meta?: Record) => warnings.push({ msg: String(msg), meta }), error: () => {}, debug: () => {}, child: () => logger, @@ -2447,6 +2450,21 @@ describe('Action Descriptor Registry (ADR-0018)', () => { return logger; } + /** + * Whether a captured warning REPORTS the node type `t`. + * + * #6654 — the unknown type names are flow-author metadata with no + * newline constraint, so `warnUnknownNodeTypes` moved them out of the + * message into the structured `unknownTypes` slot. What these tests are + * about is unchanged (was the type reported, once), so they read the slot + * the finding now lives in; that the MESSAGE no longer carries it is + * pinned in `engine-residual-log-cause.test.ts`'s #6654 site 4. + */ + function reportsType(w: CapturedWarn, t: string): boolean { + const unknown = (w.meta?.unknownTypes ?? []) as string[]; + return w.msg.includes(t) || unknown.includes(t); + } + const baseFlow = (type: string) => ({ name: 'plugin_node_flow', label: 'Plugin Node Flow', @@ -2463,7 +2481,7 @@ describe('Action Descriptor Registry (ADR-0018)', () => { }); it('accepts a flow whose node type is a plugin-registered executor (the core bug fix)', () => { - const warnings: string[] = []; + const warnings: CapturedWarn[] = []; const engine = new AutomationEngine(createCapturingLogger(warnings)); // A brand-new, non-built-in node type — previously rejected by the @@ -2475,11 +2493,11 @@ describe('Action Descriptor Registry (ADR-0018)', () => { expect(() => engine.registerFlow('plugin_node_flow', baseFlow('send_sms'))).not.toThrow(); // No "unknown node type" warning for a registered executor. - expect(warnings.some(w => w.includes('send_sms'))).toBe(false); + expect(warnings.some(w => reportsType(w, 'send_sms'))).toBe(false); }); it('registers the flow and reports the unknown type once the vocabulary is sealed (#4771)', () => { - const warnings: string[] = []; + const warnings: CapturedWarn[] = []; const engine = new AutomationEngine(createCapturingLogger(warnings)); // Soft-fail per ADR-0018: register but warn (a temporarily-absent @@ -2487,28 +2505,28 @@ describe('Action Descriptor Registry (ADR-0018)', () => { // to the moment the vocabulary can no longer grow — during boot an // unknown type means "no plugin has registered it YET" (#4771). expect(() => engine.registerFlow('plugin_node_flow', baseFlow('not_a_real_type'))).not.toThrow(); - expect(warnings.some(w => w.includes('not_a_real_type'))).toBe(false); + expect(warnings.some(w => reportsType(w, 'not_a_real_type'))).toBe(false); const audit = engine.sealNodeTypeVocabulary(); expect(audit).toEqual([ expect.objectContaining({ flowName: 'plugin_node_flow', unknownTypes: ['not_a_real_type'] }), ]); - expect(warnings.some(w => w.includes('not_a_real_type'))).toBe(true); + expect(warnings.some(w => reportsType(w, 'not_a_real_type'))).toBe(true); }); it('warns INLINE for a flow registered after the vocabulary is sealed (#4771)', () => { - const warnings: string[] = []; + const warnings: CapturedWarn[] = []; const engine = new AutomationEngine(createCapturingLogger(warnings)); // Post-boot registration (Studio publish / dev reload) is judged against // a complete vocabulary, so the assertion is true and immediate. engine.sealNodeTypeVocabulary(); engine.registerFlow('plugin_node_flow', baseFlow('not_a_real_type')); - expect(warnings.filter(w => w.includes('not_a_real_type'))).toHaveLength(1); + expect(warnings.filter(w => reportsType(w, 'not_a_real_type'))).toHaveLength(1); }); it('does not warn for the structural start/end node types', () => { - const warnings: string[] = []; + const warnings: CapturedWarn[] = []; const engine = new AutomationEngine(createCapturingLogger(warnings)); engine.registerFlow('struct_only', { name: 'struct_only', @@ -2521,11 +2539,11 @@ describe('Action Descriptor Registry (ADR-0018)', () => { edges: [{ id: 'e1', source: 'start', target: 'end' }], }); engine.sealNodeTypeVocabulary(); - expect(warnings.filter(w => w.includes('no registered executor'))).toHaveLength(0); + expect(warnings.filter(w => w.msg.includes('no registered executor'))).toHaveLength(0); }); it('stays quiet about a DISABLED flow — a flow that cannot run cannot fail (#4771)', () => { - const warnings: string[] = []; + const warnings: CapturedWarn[] = []; const engine = new AutomationEngine(createCapturingLogger(warnings)); // `status: 'obsolete'` unbinds the flow and guards execute(), so @@ -2533,21 +2551,21 @@ describe('Action Descriptor Registry (ADR-0018)', () => { // this check was moved to stop making. engine.registerFlow('retired_flow', { ...baseFlow('not_a_real_type'), status: 'obsolete' }); expect(engine.sealNodeTypeVocabulary()).toEqual([]); - expect(warnings.filter(w => w.includes('not_a_real_type'))).toHaveLength(0); + expect(warnings.filter(w => reportsType(w, 'not_a_real_type'))).toHaveLength(0); }); it('seals idempotently — a second seal never re-reports the same finding (#4771)', () => { - const warnings: string[] = []; + const warnings: CapturedWarn[] = []; const engine = new AutomationEngine(createCapturingLogger(warnings)); engine.registerFlow('plugin_node_flow', baseFlow('not_a_real_type')); expect(engine.sealNodeTypeVocabulary()).toHaveLength(1); expect(engine.sealNodeTypeVocabulary()).toHaveLength(1); // still reports as STATE… - expect(warnings.filter(w => w.includes('not_a_real_type'))).toHaveLength(1); // …but warns once + expect(warnings.filter(w => reportsType(w, 'not_a_real_type'))).toHaveLength(1); // …but warns once }); it('says nothing about a type a plugin registered AFTER the flow (the #4771 false alarm)', () => { - const warnings: string[] = []; + const warnings: CapturedWarn[] = []; const engine = new AutomationEngine(createCapturingLogger(warnings)); // Exactly the showcase cold-boot order: flows are pulled first, the @@ -2557,7 +2575,7 @@ describe('Action Descriptor Registry (ADR-0018)', () => { engine.registerNodeExecutor({ type: 'approval', async execute() { return { success: true }; } }); expect(engine.sealNodeTypeVocabulary()).toEqual([]); - expect(warnings.filter(w => w.includes('approval'))).toHaveLength(0); + expect(warnings.filter(w => reportsType(w, 'approval'))).toHaveLength(0); }); it('publishes a descriptor into the registry when an executor declares one', () => { diff --git a/packages/services/service-automation/src/engine.ts b/packages/services/service-automation/src/engine.ts index 82efdef6fc..353e91e838 100644 --- a/packages/services/service-automation/src/engine.ts +++ b/packages/services/service-automation/src/engine.ts @@ -2743,9 +2743,17 @@ export class AutomationEngine implements IAutomationService { const guardRecordId = (context?.record as { id?: unknown } | undefined)?.id; const reentryKey = guardRecordId != null ? `${flowName}::${String(guardRecordId)}` : undefined; if (reentryKey && this.activeRecordFlows.has(reentryKey)) { + // #6654 — the record id is CALLER data (nothing schema-constrains + // it against newlines), so it rides the logger's structured slot, + // never the message; see `forgetSuspendedRun`'s catch for the full + // mechanism (#6299). #4632: FUNCTIONAL — stays `warn` (the run is + // deliberately skipped and the caller reads the skip envelope). this.logger.warn( - `[automation] flow '${flowName}' re-entered for the same record '${String(guardRecordId)}' while still running — breaking self-trigger loop. ` + - `Its start condition did not suppress the re-fire; if it guards on a boolean field (e.g. \`is_escalated != true\`), note booleans persist as 0/1 on SQLite/libsql and CEL \`1 != true\` is true.`, + `[automation] flow '${flowName}' re-entered for the same record while still running — breaking ` + + `self-trigger loop; the triggering record's id is in this record's meta. Its start condition ` + + `did not suppress the re-fire; if it guards on a boolean field (e.g. \`is_escalated != true\`), ` + + `note booleans persist as 0/1 on SQLite/libsql and CEL \`1 != true\` is true.`, + { recordId: String(guardRecordId) }, ); return { success: true, output: { skipped: true, reason: 'reentrancy_loop_guard' } }; } @@ -3455,9 +3463,18 @@ export class AutomationEngine implements IAutomationService { const variables = new Map(Object.entries(run.variables)); const rejected = applyResumeSignal(variables, signal, run.nodeId); if (rejected.length) { + // #6654 — the rejected names are the CALLER's resume-signal + // keys (nothing constrains them against newlines), so they + // ride the structured slot, never the message; see + // `forgetSuspendedRun`'s catch for the full mechanism (#6299). + // The returned INVALID_SIGNAL envelope below is caller-facing + // refusal text, not a log record — it keeps naming the + // variables (the envelope class is ruled elsewhere). + // #4632: FUNCTIONAL — stays `warn`. this.logger.warn( `[automation] refused resume of run '${runId}': signal writes engine-internal ` + - `variable(s) ${rejected.join(', ')}`, + `variable(s) — the rejected names are in this record's meta.`, + { rejected }, ); return { success: false, @@ -3688,9 +3705,19 @@ export class AutomationEngine implements IAutomationService { const declared = declaredScreenFieldNames(fields); const summary = issues.map((i) => i.message).join('; '); + // #6654 — the issue messages embed USER-SUBMITTED keys + // (`validateScreenInputs`' `Unknown screen field "…"`, + // screen-input-contract.ts), which nothing constrains against + // newlines, so the findings ride the structured slot, never the + // message; see `forgetSuspendedRun`'s catch for the full mechanism + // (#6299). The returned INVALID_SCREEN_INPUT envelope below is + // caller-facing refusal text, not a log record — it keeps the summary + // (the envelope class is ruled elsewhere). #4632: FUNCTIONAL — stays + // `warn`. this.logger.warn( `[automation] refused resume of run '${runId}': screen '${run.nodeId}' input violates its declared ` + - `field contract — ${summary}`, + `field contract — ${issues.length} issue(s); the field-level findings are in this record's meta.`, + { issues }, ); return { success: false, @@ -4299,11 +4326,19 @@ export class AutomationEngine implements IAutomationService { /** One warning per flow, shared by the boot audit and the post-seal path. */ private warnUnknownNodeTypes(entry: UnknownNodeTypeAuditEntry): void { + // #6654 — the unknown type names are FLOW-AUTHOR metadata and the + // registered vocabulary is plugin-supplied (neither is + // schema-constrained against newlines), so both lists ride the + // structured slot, never the message; see `forgetSuspendedRun`'s + // catch for the full mechanism (#6299). The "no registered executor + // or descriptor" phrase is load-bearing — tests and log filters count + // per-flow findings by it. #4632: FUNCTIONAL — stays `warn`. this.logger.warn( - `Flow '${entry.flowName}' references node type(s) with no registered executor or descriptor: ` + - `${entry.unknownTypes.join(', ')}. Every plugin has started, so nothing will register them now — ` + - `these nodes fail at execution time with NO_EXECUTOR. Install/enable the plugin that contributes them. ` + - `Registered types: ${entry.knownTypes.join(', ') || '(none)'}`, + `Flow '${entry.flowName}' references node type(s) with no registered executor or descriptor — ` + + `the unknown type names and the registered vocabulary are in this record's meta. Every plugin ` + + `has started, so nothing will register them now — these nodes fail at execution time with ` + + `NO_EXECUTOR. Install/enable the plugin that contributes them.`, + { unknownTypes: entry.unknownTypes, knownTypes: entry.knownTypes }, ); } @@ -4986,17 +5021,25 @@ export class AutomationEngine implements IAutomationService { // #4414 — do not fall back silently. The node computed a branch // and no out-edge claims it, so every out-edge is about to be // considered: the guard the author wrote is not guarding. - const declared = allOutEdges - .map(e => (e.label ? `'${e.label}'` : `(unlabelled ${e.id})`)) - .join(', '); + // + // #6654 — the computed branch label is potentially + // RECORD-DERIVED and the edge labels are FLOW-AUTHOR metadata + // (neither is schema-constrained against newlines), so both + // ride the structured slot, never the message; see + // `forgetSuspendedRun`'s catch for the full mechanism (#6299). + // #4632: FUNCTIONAL — stays `warn`. this.logger.warn( // `flow.name` is absent on the synthetic view `runRegion` builds. - `Flow '${flow.name ?? '(region)'}' node '${node.id}' (${node.type}) selected branch ` + - `'${branchLabel}', but no out-edge carries that label — out-edge labels are ` + - `[${declared || 'none'}]. The branch selection is IGNORED and every out-edge is ` + + `Flow '${flow.name ?? '(region)'}' node '${node.id}' (${node.type}) selected a branch, ` + + `but no out-edge carries that label — the computed branch and the out-edge labels are ` + + `in this record's meta. The branch selection is IGNORED and every out-edge is ` + `evaluated instead, so unconditional siblings run regardless of the decision. ` + `Make an out-edge's \`label\` match the branch, or mark the fallback edge ` + `\`isDefault: true\`. (#4414)`, + { + branchLabel, + outEdges: allOutEdges.map(e => ({ id: e.id, label: e.label ?? null })), + }, ); } } diff --git a/packages/services/service-automation/src/nested-region-parity.test.ts b/packages/services/service-automation/src/nested-region-parity.test.ts index 9fe551323d..4236bf9b6b 100644 --- a/packages/services/service-automation/src/nested-region-parity.test.ts +++ b/packages/services/service-automation/src/nested-region-parity.test.ts @@ -27,11 +27,12 @@ function silentLogger() { return { info() {}, warn() {}, error() {}, debug() {}, child() { return silentLogger(); } } as any; } -/** A logger that records `warn` lines, for the soft-fail validators. */ -function recordingLogger(sink: string[]) { +/** A logger that records `warn` calls — message AND structured meta, since + * #6654 moved the soft-fail validators' identifiers into the meta slot. */ +function recordingLogger(sink: Array<{ msg: string; meta?: Record }>) { const l: any = { info() {}, error() {}, debug() {}, - warn(msg: string) { sink.push(String(msg)); }, + warn(msg: string, meta?: Record) { sink.push({ msg: String(msg), meta }); }, child() { return l; }, }; return l; @@ -294,7 +295,7 @@ describe('#4389 — registration validators cover region graphs', () => { const unknownNode = [{ id: 'x', type: 'no_such_node_type', label: 'X' }]; const warningsFor = (nested: boolean) => { - const warnings: string[] = []; + const warnings: Array<{ msg: string; meta?: Record }> = []; const engine = new AutomationEngine(recordingLogger(warnings)); registerLoopNode(engine, ctx()); engine.registerFlow('sweep', flowWith(nested, unknownNode)); @@ -303,7 +304,7 @@ describe('#4389 — registration validators cover region graphs', () => { // is unchanged: the audit walks ADR-0031 regions exactly as the // registration-time check did. engine.sealNodeTypeVocabulary(); - return warnings.filter(w => w.includes('no registered executor')); + return warnings.filter(w => w.msg.includes('no registered executor')); }; it('warns about an unknown node type at the top level (unchanged)', () => { @@ -313,7 +314,11 @@ describe('#4389 — registration validators cover region graphs', () => { it('warns about the SAME type inside a loop body', () => { const warnings = warningsFor(true); expect(warnings).toHaveLength(1); - expect(warnings[0]).toContain('no_such_node_type'); + // #6654 — the type name is flow-author metadata with no newline + // constraint, so it rides the structured slot instead of the message. + // The region-coverage fact under test is unchanged: the audit found + // THIS type inside the loop body. + expect(warnings[0].meta?.unknownTypes).toContain('no_such_node_type'); }); });