From 7963cdac1b19f1f81f3012a96286b704b426b5b8 Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 5 Aug 2026 19:24:44 +0000 Subject: [PATCH] fix(service-automation): report flow-bind failures as structured log meta, not a one-line err.message (#5048) The five flow-bind/read failure seams in AutomationServicePlugin interpolated `err.message` into a single-line `logger.warn`. `registerFlow` parses with the closed (#4001) `FlowSchema`, so an unrecognized key THROWS, and a ZodError's `.message` is a pretty-printed JSON dump of its issue array whose first line is the single character `[`. Two pipeline properties then destroyed the rest: `ObjectLogger.write()` emits one ` ` record per call, so a message carrying newlines spills onto prefix-less lines; and `BootLogCapture.offer()` keeps a line only when `classifyBootLogLine` finds that prefix. A boot with 24 unbindable flows therefore printed 24 warnings that named the flow and then said `[`. cloud#971 survived an entire rc.1 release line behind exactly that unreadability. The seams now log a static, newline-free message and hand the facts to the logger's `meta` argument, which every Logger implementation serializes with JSON.stringify -- newlines in a value become escapes, so the record stays on one physical line, the shape the boot capture retains. New internal module `flow-bind-diagnostics.ts` flattens each Zod issue to `{ code, path, message, unrecognized }`. The key names go in `unrecognized` rather than Zod's own `keys` because ObjectLogger redacts recursively by SUBSTRING and its default list contains `key`: forwarding `err.issues` verbatim renders `"keys":"***REDACTED***"`, losing the one fact the reader came for. The issue list is capped and the cap DECLARED via `issueCount` rather than silently applied. Non-ZodError failures fall back to an `error` string. No public API change; every greppable message prefix is preserved. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01BWS4heBoAitLmzCLhcYdbK --- .../flow-bind-warning-structured-issues.md | 32 ++ .../src/flow-bind-diagnostics.test.ts | 366 ++++++++++++++++++ .../src/flow-bind-diagnostics.ts | 159 ++++++++ .../services/service-automation/src/plugin.ts | 36 +- 4 files changed, 582 insertions(+), 11 deletions(-) create mode 100644 .changeset/flow-bind-warning-structured-issues.md create mode 100644 packages/services/service-automation/src/flow-bind-diagnostics.test.ts create mode 100644 packages/services/service-automation/src/flow-bind-diagnostics.ts diff --git a/.changeset/flow-bind-warning-structured-issues.md b/.changeset/flow-bind-warning-structured-issues.md new file mode 100644 index 0000000000..dc230a7493 --- /dev/null +++ b/.changeset/flow-bind-warning-structured-issues.md @@ -0,0 +1,32 @@ +--- +"@objectstack/service-automation": patch +--- + +fix(service-automation): flow 绑定失败的告警改用结构化 `meta`,不再把 Zod issue 数组塞进单行日志 (#5048) + +`AutomationServicePlugin` 的五个 flow 绑定/读取失败点都把 `err.message` 插进一条 +单行 `logger.warn`。而 `registerFlow` 用 `FlowSchema` 解析,#4001 关闭 metadata +schema 之后未知键是**抛出**而不是被丢弃 —— ZodError 的 `.message` 是 issue 数组的 +多行 JSON dump,第一行就是一个 `[`。 + +两级管线随后把余下内容销毁:`ObjectLogger.write()` 每次调用只写一条 +` ` 记录,带换行的 message 会溢出到没有等级前缀的后续行;而 +`serve` 的启动诊断缓冲(`BootLogCapture.offer()`)只保留 `classifyBootLogLine` +能认出等级前缀的行。于是一次启动里 24 个绑不上的 flow,给出的是 24 条点了名字、 +然后说一个 `[` 的告警 —— cloud#971 能横跨整条 rc.1 发布线没人发现,就是因为这个。 + +现在这些位置改为:message 是不含换行的静态字符串,事实交给 logger 的 `meta` +第二参(仓库里每个 `Logger` 实现都用 `JSON.stringify` 序列化它,值里的换行变成 +`\n` 转义,整条记录稳定占一行,正是启动缓冲会保留的形态)。新增内部模块 +`flow-bind-diagnostics.ts` 把 Zod issue 摊平成 `{ code, path, message, +unrecognized }`:`path` 渲染成 `nodes[0].config.x`,被拒的键名放在 +`unrecognized` 而不是 Zod 原本的 `keys` —— 因为 `ObjectLogger` 的默认脱敏表 +(`['password','token','secret','key']`)按**子串**递归匹配,`keys` 含 `key`, +原样转发 `err.issues` 会渲染成 `"keys":"***REDACTED***"`,恰好丢掉读者唯一需要 +的那个事实。issue 列表有上限,超出时用 `issueCount` **显式声明**总数,而不是静默 +截断。非 ZodError 的失败退回 `error` 字符串分支。 + +无公开 API 变化;日志文本的可 grep 前缀(`cold-boot flow bind: failed to +register`、`flow re-sync: failed to register`、`flow pull from ObjectQL +registry failed`、`flow read from protocol failed`)全部保留。与 #4632 同源: +被截断的诊断比没有诊断更贵。 diff --git a/packages/services/service-automation/src/flow-bind-diagnostics.test.ts b/packages/services/service-automation/src/flow-bind-diagnostics.test.ts new file mode 100644 index 0000000000..292be8f84f --- /dev/null +++ b/packages/services/service-automation/src/flow-bind-diagnostics.test.ts @@ -0,0 +1,366 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// Regression: #5048 — a flow that fails to bind must report WHY, on the line +// that carries the level prefix. +// +// The three `registerFlow` seams in AutomationServicePlugin (boot pull, +// `metadata:reloaded` re-sync, `kernel:ready` cold-boot bind) plus the +// `getMetaItems('flow')` read all rendered their failure by interpolating +// `err.message` into a single-line `logger.warn`. `registerFlow` parses with +// `FlowSchema`, which #4001 closed — an unrecognized key THROWS — and a +// ZodError's `.message` is a pretty-printed JSON dump of its issue array whose +// first line is the single character `[`. +// +// `ObjectLogger` writes one ` ` record per call, so a message +// carrying newlines spills onto lines with no level prefix, and `serve`'s +// boot-diagnostic buffer (packages/cli/src/utils/boot-log-capture.ts) keeps a +// line only when `classifyBootLogLine` finds that prefix. Every continuation +// line was therefore dropped: 24 warnings that named 24 flows and then said +// `[`. That unreadability is what let cloud#971 survive a whole rc.1 line. +// +// These tests pin both halves of the fix: the seams hand the facts to the +// logger's `meta` argument (asserted on the call), and the resulting record +// occupies ONE physical line with the offending key name still in it (asserted +// on real rendered output — which is also what catches `ObjectLogger`'s +// substring redactor eating a field called `keys`). + +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { LiteKernel, ObjectLogger, createLogger } from '@objectstack/core'; +import { FlowSchema } from '@objectstack/spec/automation'; +import { AutomationEngine } from './engine.js'; +import { AutomationServicePlugin } from './plugin.js'; +import { + describeFlowBindError, + formatIssuePath, + MAX_LOGGED_FLOW_BIND_ISSUES, +} from './flow-bind-diagnostics.js'; + +const flush = () => new Promise((r) => setTimeout(r, 0)); + +/** Fire 'metadata:reloaded' the way MetadataPlugin / a Studio publish does. */ +const reload = (kernel: LiteKernel) => (kernel as any).context.trigger('metadata:reloaded', {}); + +afterEach(() => { + vi.restoreAllMocks(); +}); + +// ── fixtures ─────────────────────────────────────────────────────────────── + +/** + * A flow the closed `FlowSchema` (#4001) rejects: `visibleIf` sits at NODE + * level, a sibling of `id`/`type`, so it is an `unrecognized_keys` issue with a + * non-empty path (`nodes[0]`). The same mistake inside `config` would be caught + * later by #4277's descriptor check (a plain Error), which is the other branch + * covered below — so the placement here is deliberate, not incidental. + */ +function flowWithUnknownNodeKey(name: string) { + return { + name, + label: name, + type: 'autolaunched', + nodes: [ + { + id: 'start', + type: 'start', + label: 'Start', + visibleIf: 'status == "done"', + config: { objectName: 'task', triggerType: 'record-after-update' }, + }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [{ id: 'e1', source: 'start', target: 'end' }], + }; +} + +/** A well-formed flow, for the seams that must still bind. */ +function goodFlow(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' }], + }; +} + +/** The protocol's flattened flow view, in the `{ items: [...] }` envelope. */ +function fakeProtocolService(flows: () => unknown[], opts: { throwOnRead?: Error } = {}) { + return { + async getMetaItems(q: { type: string }) { + if (opts.throwOnRead) throw opts.throwOnRead; + return { items: q.type === 'flow' ? flows() : [] }; + }, + }; +} + +async function bootKernel( + flows: () => unknown[], + opts: { throwOnRead?: Error } = {}, +): Promise { + const kernel = new LiteKernel({ logger: { level: 'silent' } } as never); + kernel.use(new AutomationServicePlugin()); + kernel.use({ + name: 'test.harness', + type: 'standard' as const, + version: '1.0.0', + dependencies: [] as string[], + async init(ctx: any) { + ctx.registerService('protocol', fakeProtocolService(flows, opts)); + }, + async start() {}, + } as never); + await kernel.bootstrap(); + return kernel; +} + +/** Every `logger.warn` whose message starts with `prefix`. */ +function warnsMatching(spy: { mock: { calls: unknown[][] } }, prefix: string): unknown[][] { + return spy.mock.calls.filter((c: unknown[]) => String(c[0]).startsWith(prefix)); +} + +// ── the seams ────────────────────────────────────────────────────────────── + +describe('flow-bind failures report their Zod issues structurally (#5048)', () => { + it('cold-boot bind: the message is newline-free and the issues ride in meta', async () => { + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + const kernel = await bootKernel(() => [flowWithUnknownNodeKey('campaign_enrollment')]); + await flush(); + + const calls = warnsMatching(warn, '[Automation] cold-boot flow bind: failed to register'); + expect(calls.length, 'the cold-boot seam warned exactly once').toBe(1); + const [message, meta] = calls[0] as [string, Record]; + + // Half one: the first argument is a single line. Pre-fix it ended in + // `: [` and the rest of the dump followed on prefix-less lines the boot + // capture drops. + expect(message).not.toContain('\n'); + + // Half two: the facts are present, and complete. + expect(meta).toBeTypeOf('object'); + expect(meta.flow).toBe('campaign_enrollment'); + expect(meta.error, 'a validation rejection reports `issues`, not `error`').toBeUndefined(); + const issues = meta.issues as Array>; + expect(Array.isArray(issues)).toBe(true); + expect(issues.length).toBeGreaterThanOrEqual(1); + const unrecognized = issues.find((i) => i.code === 'unrecognized_keys'); + expect(unrecognized, 'the unrecognized_keys issue survived').toBeDefined(); + expect(unrecognized!.unrecognized).toEqual(['visibleIf']); + expect(unrecognized!.path).toBe('nodes[0]'); + expect(String(unrecognized!.message)).toContain('visibleIf'); + + await kernel.shutdown(); + }); + + it('re-sync (metadata:reloaded): same shape at the second seam', async () => { + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + let served: unknown[] = [goodFlow('nightly_digest')]; + const kernel = await bootKernel(() => served); + await flush(); + warn.mockClear(); + + // A Studio publish / dev reload now serves a flow the schema rejects. + served = [flowWithUnknownNodeKey('nightly_digest')]; + await reload(kernel); + await flush(); + + const calls = warnsMatching(warn, '[Automation] flow re-sync: failed to register'); + expect(calls.length, 're-sync warned once for the rejected flow').toBe(1); + const [message, meta] = calls[0] as [string, Record]; + expect(message).not.toContain('\n'); + expect(meta.flow).toBe('nightly_digest'); + expect((meta.issues as unknown[])?.length).toBeGreaterThanOrEqual(1); + + await kernel.shutdown(); + }); + + it('a NON-Zod registration failure falls back to the `error` string, with no `issues`', async () => { + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + let served: unknown[] = [goodFlow('escalate_case')]; + const kernel = await bootKernel(() => served); + await flush(); + + // Not every registerFlow rejection is a ZodError: #4277's descriptor + // check and the DAG/expression validators throw plain Errors, and those + // must still be reported — as a string, not as a phantom empty `issues`. + const engine = kernel.getService('automation'); + vi.spyOn(engine, 'registerFlow').mockImplementation(() => { + throw new Error('Node "start": config key `visibleIf` is not declared by its descriptor'); + }); + warn.mockClear(); + + served = [goodFlow('escalate_case')]; + await reload(kernel); + await flush(); + + const calls = warnsMatching(warn, '[Automation] flow re-sync: failed to register'); + expect(calls.length).toBe(1); + const [message, meta] = calls[0] as [string, Record]; + expect(message).not.toContain('\n'); + expect(meta.flow).toBe('escalate_case'); + expect(meta.issues).toBeUndefined(); + expect(meta.error).toContain('visibleIf'); + + await kernel.shutdown(); + }); + + it('a failed getMetaItems read reports its cause in meta too', async () => { + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + const kernel = await bootKernel(() => [], { throwOnRead: new Error('protocol offline') }); + await flush(); + + const calls = warnsMatching(warn, '[Automation] flow read from protocol failed'); + expect(calls.length).toBeGreaterThanOrEqual(1); + const [message, meta] = calls[0] as [string, Record]; + expect(message).not.toContain('\n'); + expect((meta as { error?: string }).error).toBe('protocol offline'); + + await kernel.shutdown(); + }); + + it('a well-formed flow still binds and warns about nothing', async () => { + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + const kernel = await bootKernel(() => [goodFlow('notify_on_done')]); + await flush(); + + expect(warnsMatching(warn, '[Automation] cold-boot flow bind: failed to register')).toHaveLength(0); + const engine = kernel.getService('automation'); + expect(await engine.getFlow('notify_on_done')).not.toBeNull(); + + await kernel.shutdown(); + }); +}); + +// ── the rendered record ──────────────────────────────────────────────────── + +describe('the rendered warning is ONE line that still names the key (#5048)', () => { + /** Capture what `ObjectLogger` actually writes to stdout. */ + function captureStdout(fn: (log: ObjectLogger) => void): string[] { + const chunks: string[] = []; + const spy = vi + .spyOn(process.stdout, 'write') + .mockImplementation(((c: string | Uint8Array) => { + chunks.push(String(c)); + return true; + }) as never); + try { + fn(createLogger({ level: 'warn', format: 'json' })); + } finally { + spy.mockRestore(); + } + return chunks.join('').split('\n').filter(Boolean); + } + + it('renders on one physical line, with the offending key name intact', () => { + // A real FlowSchema rejection — not a hand-written issue array — so the + // assertion tracks whatever Zod actually produces. + let thrown: unknown; + try { + FlowSchema.parse(flowWithUnknownNodeKey('campaign_enrollment')); + } catch (err) { + thrown = err; + } + expect(thrown, 'FlowSchema must reject the fixture — otherwise this test proves nothing').toBeDefined(); + // The defect's fingerprint: the string form is multi-line and opens with `[`. + expect(String((thrown as Error).message).split('\n').length).toBeGreaterThan(1); + expect(String((thrown as Error).message).split('\n')[0].trim()).toBe('['); + + const lines = captureStdout((log) => { + log.warn('[Automation] cold-boot flow bind: failed to register flow', { + flow: 'campaign_enrollment', + ...describeFlowBindError(thrown), + }); + }); + + expect(lines, 'one warn call must render as exactly one line').toHaveLength(1); + const record = JSON.parse(lines[0]) as Record; + expect(record.msg).toBe('[Automation] cold-boot flow bind: failed to register flow'); + expect(record.flow).toBe('campaign_enrollment'); + // The whole point: the reader can see WHICH key, WHERE. + expect(lines[0]).toContain('visibleIf'); + expect(lines[0]).toContain('nodes[0]'); + // And nothing was eaten by the redactor on the way out. + expect(lines[0]).not.toContain('REDACTED'); + }); + + it('forwarding Zod issues VERBATIM would be redacted — this is why they are re-shaped', () => { + // Evidence for the `unrecognized` naming in flow-bind-diagnostics.ts: + // ObjectLogger redacts recursively by SUBSTRING, and its default list + // includes `key`, which `keys` contains. A `{ issues: err.issues }` meta + // therefore ships `"keys":"***REDACTED***"` — losing the one fact the + // reader came for. Pinned so a future "just pass err.issues" cleanup + // fails loudly instead of silently re-blinding the diagnostic. + const lines = captureStdout((log) => { + log.warn('verbatim', { + issues: [{ code: 'unrecognized_keys', keys: ['visibleIf'], path: ['nodes', 0] }], + }); + }); + expect(lines).toHaveLength(1); + expect(lines[0]).toContain('REDACTED'); + expect(lines[0]).not.toContain('visibleIf'); + }); + + it('a multi-line NON-Zod message still occupies one line (JSON escapes the newlines)', () => { + const lines = captureStdout((log) => { + log.warn('[Automation] flow re-sync: failed to register flow', { + flow: 'f', + ...describeFlowBindError(new Error('line one\nline two\nline three')), + }); + }); + expect(lines).toHaveLength(1); + const record = JSON.parse(lines[0]) as { error?: string }; + expect(record.error).toBe('line one\nline two\nline three'); + }); +}); + +// ── the helper ───────────────────────────────────────────────────────────── + +describe('describeFlowBindError / formatIssuePath', () => { + it('formats paths with array indices, and names the root explicitly', () => { + expect(formatIssuePath([])).toBe('(root)'); + expect(formatIssuePath(undefined)).toBe('(root)'); + expect(formatIssuePath(['nodes', 0])).toBe('nodes[0]'); + expect(formatIssuePath(['nodes', 2, 'config', 'objectName'])).toBe('nodes[2].config.objectName'); + expect(formatIssuePath([0, 'a'])).toBe('[0].a'); + }); + + it('reports `issues` for a ZodError-shaped throw and `error` for anything else', () => { + const zodish = { issues: [{ code: 'invalid_type', path: ['version'], message: 'expected number' }] }; + expect(describeFlowBindError(zodish)).toEqual({ + issues: [{ code: 'invalid_type', path: 'version', message: 'expected number' }], + }); + + expect(describeFlowBindError(new Error('boom'))).toEqual({ error: 'boom' }); + expect(describeFlowBindError('a bare string')).toEqual({ error: 'a bare string' }); + expect(describeFlowBindError(undefined)).toEqual({ error: 'undefined' }); + }); + + it('caps the issue list and DECLARES the cap instead of truncating silently', () => { + const many = { + issues: Array.from({ length: MAX_LOGGED_FLOW_BIND_ISSUES + 7 }, (_, i) => ({ + code: 'unrecognized_keys', + keys: [`k${i}`], + path: ['nodes', i], + message: `Unrecognized key: "k${i}"`, + })), + }; + const meta = describeFlowBindError(many); + expect(meta.issues).toHaveLength(MAX_LOGGED_FLOW_BIND_ISSUES); + expect(meta.issueCount).toBe(MAX_LOGGED_FLOW_BIND_ISSUES + 7); + // Under the cap the count is omitted — no noise when nothing was dropped. + expect(describeFlowBindError({ issues: many.issues.slice(0, 3) }).issueCount).toBeUndefined(); + }); + + it('an empty issues array is still a validation rejection, not an `error` string', () => { + // A ZodError with zero issues should not fall through to the string + // branch and re-render as `"error":"[]"` — the shape decides. + expect(describeFlowBindError({ issues: [], message: '[]' })).toEqual({ issues: [] }); + }); +}); diff --git a/packages/services/service-automation/src/flow-bind-diagnostics.ts b/packages/services/service-automation/src/flow-bind-diagnostics.ts new file mode 100644 index 0000000000..72ba2151c9 --- /dev/null +++ b/packages/services/service-automation/src/flow-bind-diagnostics.ts @@ -0,0 +1,159 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * Structured rendering for the failures the flow-binding seams report (#5048). + * + * ## The defect this exists to prevent + * + * Every flow-bind seam in `AutomationServicePlugin` used to render its failure + * by interpolating `err.message` into a single-line `logger.warn`: + * + * ctx.logger.warn(`[Automation] cold-boot flow bind: failed to register ${def.name}: ${err.message}`); + * + * `registerFlow` parses with `FlowSchema`, and #4001 closed that schema — an + * unrecognized key now **throws** instead of being dropped. A `ZodError`'s + * `.message` is a pretty-printed JSON dump of its `issues` array, so its FIRST + * LINE is the single character `[`. Two properties of the log pipeline then + * conspire to destroy the rest of it: + * + * 1. `ObjectLogger.write()` (packages/core/src/logger.ts) emits one + * ` ` record per call; a message carrying newlines + * becomes several physical lines, and only the first carries the level + * prefix. + * 2. `serve`'s boot-diagnostic buffer (packages/cli/src/utils/boot-log-capture.ts) + * is line-oriented: `BootLogCapture.offer()` keeps a line only when + * `classifyBootLogLine` finds a ` ` head on it. Every + * continuation line of a multi-line message fails that test and is + * dropped outright. + * + * Net effect on a boot where N flows fail to bind: N warnings that name the + * flow and then say `[`. cloud#971 survived an entire rc.1 release line behind + * exactly that — the second defect made the first one invisible. + * + * ## The fix + * + * Never pass structured information through the *string* shape of an error. + * The seams now log a static, newline-free message and hand the facts to the + * logger's `meta` argument, which every `Logger` implementation in this repo + * serializes with `JSON.stringify` — so newlines inside a value become `\n` + * escapes and the whole record stays on ONE physical line, which is exactly + * what the boot capture retains. Same discipline as #4632: a truncated + * diagnostic costs more than no diagnostic. + * + * ## Why the issues are re-shaped rather than forwarded verbatim + * + * Two measured reasons, not taste: + * + * - `ObjectLogger` redacts recursively by substring: its default + * `redact: ['password', 'token', 'secret', 'key']` matches any field whose + * lowercased name *contains* one of them. A Zod `unrecognized_keys` issue + * names the offending keys in a field called `keys`, and `'keys'` contains + * `'key'` — forwarding `err.issues` untouched therefore renders + * `"keys":"***REDACTED***"`, i.e. it loses the one fact the reader came + * for. The field is named `unrecognized` here so the key names survive. + * - A Zod issue can carry the whole rejected `input` on some codes. A boot + * warning must stay bounded; the boot capture drops any line that would + * overflow its budget, which would resurrect the very failure mode above. + * + * So the fields are named deliberately and the list is capped, with the cap + * *declared* in the record (`issueCount`) rather than silently applied. + */ + +/** Cap on how many issues one warning carries — see the module docblock. */ +export const MAX_LOGGED_FLOW_BIND_ISSUES = 20; + +/** One validation issue, flattened to the facts a one-line log record needs. */ +export interface FlowBindIssue { + /** Zod issue code, e.g. `unrecognized_keys` / `invalid_type`. */ + code: string; + /** Dotted path to the offending node, `(root)` for the flow document itself. */ + path: string; + /** Zod's own rendering — already names the expected/received detail. */ + message: string; + /** + * The rejected key names of an `unrecognized_keys` issue. Named + * `unrecognized` rather than `keys` so `ObjectLogger`'s substring redactor + * does not replace it with `***REDACTED***`. + */ + unrecognized?: string[]; +} + +/** The `meta` payload a flow-bind seam attaches to its warning. */ +export interface FlowBindErrorMeta { + /** Present when the failure was a schema/validation rejection. */ + issues?: FlowBindIssue[]; + /** + * Total issue count, present ONLY when it exceeds + * {@link MAX_LOGGED_FLOW_BIND_ISSUES} — i.e. when `issues` is a prefix. + */ + issueCount?: number; + /** Present when the failure was not a validation rejection. */ + error?: string; +} + +/** + * Render a Zod issue path as `nodes[0].config.visibleIf`. + * + * Numeric segments become `[i]` so an array index reads as one, and an empty + * path (the flow document itself — where `unrecognized_keys` on the top-level + * object lands) reads as `(root)` instead of an empty string that would look + * like a missing field. + */ +export function formatIssuePath(path: readonly unknown[] | undefined): string { + if (!path || path.length === 0) return '(root)'; + let out = ''; + for (const seg of path) { + if (typeof seg === 'number') { + out += `[${seg}]`; + } else { + out += out === '' ? String(seg) : `.${String(seg)}`; + } + } + return out; +} + +/** + * Turn a thrown value into the structured `meta` for a flow-bind warning. + * + * A `ZodError` is recognized by duck-typing its `issues` array rather than by + * `instanceof z.ZodError`. That is deliberate: the throw site is + * `FlowSchema.parse` inside `@objectstack/spec`, so the error can be + * constructed by a *different* `zod` module instance than any `instanceof` + * check here would hold (the classic dual-package hazard), and this package + * declares no direct `zod` dependency to check against. The shape IS the + * contract at this seam — `issues` is what we render, so `issues` is what we + * test for. + * + * Exactly one of `issues` / `error` is populated, so a reader never has to + * decide which of two renderings of the same failure to trust. + */ +export function describeFlowBindError(err: unknown): FlowBindErrorMeta { + const raw = (err as { issues?: unknown } | null | undefined)?.issues; + if (Array.isArray(raw)) { + const issues: FlowBindIssue[] = []; + for (const entry of raw.slice(0, MAX_LOGGED_FLOW_BIND_ISSUES)) { + const issue = (entry ?? {}) as { + code?: unknown; + path?: unknown; + message?: unknown; + keys?: unknown; + }; + const flat: FlowBindIssue = { + code: typeof issue.code === 'string' ? issue.code : 'unknown', + path: formatIssuePath(Array.isArray(issue.path) ? issue.path : undefined), + message: typeof issue.message === 'string' ? issue.message : String(entry), + }; + if (Array.isArray(issue.keys)) flat.unrecognized = issue.keys.map((k) => String(k)); + issues.push(flat); + } + return raw.length > MAX_LOGGED_FLOW_BIND_ISSUES + ? { issues, issueCount: raw.length } + : { issues }; + } + + // Not a validation rejection. `String(err.message)` keeps a multi-line + // message intact — the logger's JSON.stringify escapes the newlines, so it + // still occupies one physical line. + const message = (err as { message?: unknown } | null | undefined)?.message; + return { error: message === undefined || message === null ? String(err) : String(message) }; +} diff --git a/packages/services/service-automation/src/plugin.ts b/packages/services/service-automation/src/plugin.ts index dd2755b378..15d193c239 100644 --- a/packages/services/service-automation/src/plugin.ts +++ b/packages/services/service-automation/src/plugin.ts @@ -14,6 +14,7 @@ import { isConnectorUpstreamUnavailable } from '@objectstack/spec/integration'; import { stripReadDecorations } from '@objectstack/spec/kernel'; import { AutomationEngine } from './engine.js'; import type { RunSummaryLogLevel } from './engine.js'; +import { describeFlowBindError } from './flow-bind-diagnostics.js'; import { installBuiltinNodes, rearmSuspendedWaitTimers } from './builtin/index.js'; import { resolveRunDataContext } from './runtime-identity.js'; import { SysAutomationRun } from './sys-automation-run.object.js'; @@ -754,16 +755,22 @@ export class AutomationServicePlugin implements Plugin { this.syncedFlowNames.add(def.name); registered++; } catch (e) { - const msg = e instanceof Error ? e.message : String(e); - ctx.logger.warn(`[Automation] failed to register flow ${def.name}: ${msg}`); + // #5048 — the facts go in `meta`, never interpolated into the + // message: a ZodError's `.message` is a multi-line JSON dump + // whose first line is `[`, and the boot diagnostic buffer keeps + // only the line carrying the level prefix. See + // ./flow-bind-diagnostics.ts. + ctx.logger.warn('[Automation] failed to register flow', { + flow: def.name, + ...describeFlowBindError(e), + }); } } if (registered > 0) { ctx.logger.info(`[Automation] Pulled ${registered} flow(s) from ObjectQL registry`); } } catch (err) { - const msg = err instanceof Error ? err.message : String(err); - ctx.logger.warn(`[Automation] flow pull from ObjectQL registry failed: ${msg}`); + ctx.logger.warn('[Automation] flow pull from ObjectQL registry failed', describeFlowBindError(err)); } // ── ADR-0097: materialize provider-bound declarative connector instances ── @@ -1399,8 +1406,11 @@ export class AutomationServicePlugin implements Plugin { try { raw = await protocol.getMetaItems({ type: 'flow' }); } catch (err) { + // #5048 — structured `meta`, not string interpolation (same reason as + // the register seams below; see ./flow-bind-diagnostics.ts). ctx.logger.warn( - `[Automation] flow read from protocol failed: getMetaItems('flow'): ${(err as Error).message}`, + "[Automation] flow read from protocol failed: getMetaItems('flow')", + describeFlowBindError(err), ); return null; } @@ -1456,9 +1466,11 @@ export class AutomationServicePlugin implements Plugin { this.engine.registerFlow(def.name, def as never); resynced++; } catch (err) { - ctx.logger.warn( - `[Automation] flow re-sync: failed to register ${def.name}: ${(err as Error).message}`, - ); + // #5048 — see ./flow-bind-diagnostics.ts. + ctx.logger.warn('[Automation] flow re-sync: failed to register flow', { + flow: def.name, + ...describeFlowBindError(err), + }); } } @@ -1500,9 +1512,11 @@ export class AutomationServicePlugin implements Plugin { this.syncedFlowNames.add(def.name); bound++; } catch (err) { - ctx.logger.warn( - `[Automation] cold-boot flow bind: failed to register ${def.name}: ${(err as Error).message}`, - ); + // #5048 — see ./flow-bind-diagnostics.ts. + ctx.logger.warn('[Automation] cold-boot flow bind: failed to register flow', { + flow: def.name, + ...describeFlowBindError(err), + }); } } if (bound > 0) {