From a7917a7a90b8c45f1504a0eb045ad0296d5d1333 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 6 Aug 2026 04:02:12 +0000 Subject: [PATCH] fix(service-automation): the degrade REGISTRATION logs its cause as meta, message stays one line (#5660) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `AutomationEngine.registerDegradedConnector` interpolated the caller-supplied `reason` into its own warn: this.logger.warn(`Connector registered DEGRADED: ${name} (origin: ${origin}) - ${reason}`); That text is not ours. The only caller — `degradeConnectorInstance` — passes `ConnectorUpstreamUnavailableError.message`, constructed by a third-party provider factory (ADR-0097 invites people to write them; the spec constrains the `code`, never the text), so an upstream SDK's multi-line failure landed inside the message verbatim. `ObjectLogger.write()` emits one ` …` head per call, so a message carrying newlines becomes several physical lines and only the first is a record. This is the fourth seam of the family #5048, #5575 and #5636 closed, and what makes it worth its own fix is ORDER, not severity: it fires BEFORE both of #5636's records, and it fires on the DEFAULT branch — #5636's warn sits in a catch (reached only when the husk itself fails to parse), this one runs when that try SUCCEEDS, i.e. on every first degrade of every instance. So after #5636 the ordinary cold-boot degrade still spilled. The downstream is #5636's, measured there: warn goes to stdout, `serve`'s boot-quiet window wraps `process.stdout.write` only, a cold boot reaches this seam inside that window (`materializeDeclaredConnectors(ctx, { fatal: true })` degrades rather than throwing), and `BootLogCapture.offer()` DROPS any physical line `classifyBootLogLine` finds no level head on. `registerDegradedConnector` takes an optional `cause?: unknown` after the defaulted `origin`, so every pre-existing call shape still compiles (a new test is one). The message is now self-sufficient and newline-free by construction (`name` is `^[a-z_][a-z0-9_]*$`, `origin` is an enum) and the facts travel in `warn`'s meta: - `degradedReason` — always present, the text this registration STORED on the husk. Named past `ObjectLogger`'s substring redactor (#5573). - the thrown value's own rendering (`error` or `issues`, via `describeThrownForLog`) — only when a cause was supplied. It describes the FAILURE where `degradedReason` describes the REGISTRATION; the two coincide for today's single caller but the record's shape does not depend on that. Deliberately unchanged: `reason`, and therefore the descriptor's `degradedReason` — what `GET /connectors` shows and what a `connector_action` refusal quotes — stays verbatim, newlines included (#5636 made the same call one layer up), pinned from both sides. And `describeThrownForLog` is NOT widened: `ConnectorUpstreamUnavailableError`'s own nested `cause` is now carried here but still not rendered, which a test states rather than glosses over — widening it changes a helper four seams share. The reverse verification predicted the plain red direction and measured a narrower loss than #5636's: a ZodError dump opens on a bare `[` so its one retained line held no facts, whereas here the reason's first line survives and the `cause:`/`hint:` lines — the address refused and the thing to check — are what the buffer drops. 3 lines in, 1 retained, 2 dropped. --- .changeset/degraded-register-cause.md | 66 +++ .../src/degraded-register-cause.test.ts | 415 ++++++++++++++++++ .../services/service-automation/src/engine.ts | 69 ++- .../services/service-automation/src/plugin.ts | 19 +- 4 files changed, 566 insertions(+), 3 deletions(-) create mode 100644 .changeset/degraded-register-cause.md create mode 100644 packages/services/service-automation/src/degraded-register-cause.test.ts diff --git a/.changeset/degraded-register-cause.md b/.changeset/degraded-register-cause.md new file mode 100644 index 0000000000..811a25bb34 --- /dev/null +++ b/.changeset/degraded-register-cause.md @@ -0,0 +1,66 @@ +--- +"@objectstack/service-automation": patch +--- + +fix(service-automation): 降级注册那条 warn 不再插值 provider 的 reason,cause 走结构化 meta (#5660) + +## 接缝 + +`AutomationEngine.registerDegradedConnector` 自己那条记录: + +```ts +this.logger.warn(`Connector registered DEGRADED: ${parsed.name} (origin: ${origin}) — ${reason}`); +``` + +`reason` 不是我们的文本 —— 唯一调用点(`plugin.ts` 的 `degradeConnectorInstance`)传进来的是 +`ConnectorUpstreamUnavailableError.message`,由**第三方 provider factory** 构造(ADR-0097 明确 +邀请第三方去写;spec 只约束 `code`,不约束文本),所以上游 SDK 的多行失败会原样落进 message。 +`ObjectLogger.write()` 每次调用只打一个 ` ` 头,带换行的 message 就变成若干物理行, +只有第一行是记录。 + +这是 #5048(flow 绑定)、#5575(`reconcileDeclaredConnectors` 的 `fail()`)、#5636 +(`degradeConnectorInstance` 的两条)之后同族的**第四条**,在另一个文件、另一个方法、另一份 +契约里,所以是单独一单。它值得单独修的理由是**顺序**,不是严重度: + +- 它**先**发生 —— `degradeConnectorInstance` 先调 `engine.registerDegradedConnector(…)`, + 之后才打自己那两条; +- 它在**默认分支**上 —— #5636 那条 `warn` 在 `catch` 里(husk 自己 parse 失败才走到), + 这条在同一个 `try` **成功**时打,也就是每个实例首次降级都打。 + +即:#5636 落地之后,常见的冷启动降级路径上仍然留着一条会溢出的 warn。 + +## 危害(与 #5636 同一条下游,机制已实测) + +`ObjectLogger` 把 `warn` 送 stdout;`serve` 的启动静默窗口只包了 `process.stdout.write`; +冷启动会走到这个接缝 —— `materializeDeclaredConnectors(ctx, { fatal: true })` 遇到上游不可达是 +**降级**、不是抛错 —— 而窗口此时正开着。`BootLogCapture.offer()` 只在 `classifyBootLogLine` +能在物理行上找到级别头时才保留该行,所以插值 message 的每条续行是被**直接丢弃**的。 + +本单新测试按 `pretty`(CLI 实际用的格式)实测了旧形状的代价,并且刻意报告了一个**比 #5636 更窄** +的结论:#5636 的载荷是 `ZodError.message`(首行只有一个 `[`),唯一被留下的那行不含任何事实; +这里的载荷是 provider 的散文,**首行会活下来**,丢掉的是它后面的 `cause:` / `hint:` 两行 —— +也就是「连哪个地址被拒」和「该去查什么」。3 行进,1 行留,2 行丢。 + +## 改法(#5660 分诊 A 路) + +`registerDegradedConnector` 签名末尾加可选 `cause?: unknown`(在有默认值的 `origin` 之后, +所以既有调用形状全部照旧编译 —— 新测试里就有一个两参调用在钉这件事)。message 变成单行自足 +(name / origin / 这个状态的后果与后续动作),事实走 `warn(message, meta?)` 的第二参: + +- `degradedReason` —— **恒定存在**,是这次注册**存进** husk 的那段文本。字段名照 #5573 挑过: + `ObjectLogger` 按 `password`/`token`/`secret`/`key` 子串递归脱敏,这个名字一个都不含; +- 抛出值自身的渲染(`error` 或 `issues`,经同包 `describeThrownForLog`)—— 仅当调用点传了 + `cause` 时出现。它描述的是**失败**,`degradedReason` 描述的是**注册**;今天唯一的调用点从 + 前者派生后者所以两者重合,但记录形状不依赖这个巧合,将来传摘要的调用点也不会静默丢信息。 + +唯一调用点顺手把 `info.cause` 传了进来(该字段 #5636 已经存在)。 + +## 刻意没做的两件事 + +- **`reason` / `degradedReason` 一字不动**。`GET /connectors` 展示的、`connector_action` 被拒时 + 引用的那段文本仍逐字保留 provider 自己的 message,换行包含在内 —— 它是人透过 JSON 读的,不经 + 按行切分的消费者(#5636 在上一层做了同样的判断)。测试从两个方向钉住了这个分离。 +- **没有扩 `describeThrownForLog`**。`ConnectorUpstreamUnavailableError` 自带一个 `cause` + (底层 connect 错误),把**抛出值本身**一路带过来才使渲染它成为可能;但该 helper 目前只读 + `.message` / `.issues`,所以嵌套 cause 今天还不会出现在记录里。这一点被一条测试如实钉住, + 而不是含混带过 —— 扩宽它是改四个接缝共用的 helper,不是这个接缝该顺手做的决定。 diff --git a/packages/services/service-automation/src/degraded-register-cause.test.ts b/packages/services/service-automation/src/degraded-register-cause.test.ts new file mode 100644 index 0000000000..2f248a85f3 --- /dev/null +++ b/packages/services/service-automation/src/degraded-register-cause.test.ts @@ -0,0 +1,415 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// Regression: #5660 — `AutomationEngine.registerDegradedConnector`'s own `warn` +// must not interpolate the provider's `reason` into its log message. +// +// This is the FOURTH seam of the family #5048 (flow binding), #5575 +// (`reconcileDeclaredConnectors`'s `fail()`) and #5636 (`degradeConnectorInstance`'s +// two records) closed, and it lives in a different file, in a different method, +// with a different contract — hence its own issue and its own test file. +// +// Two properties make it the one most worth pinning, and both are about ORDER, +// not severity: +// +// • It fires FIRST. `degradeConnectorInstance` calls +// `engine.registerDegradedConnector(husk, info.reason, 'declarative')` and +// only then logs its own records, so this `warn` precedes both of #5636's. +// • It fires on the DEFAULT branch. #5636's `warn` is in a `catch` — reached +// only when the husk itself fails to parse. This one is on that `try` +// SUCCEEDING, i.e. on every first degrade of every instance. +// +// So after #5636 the common cold-boot degrade still spilled a multi-line +// provider message onto stdout. +// +// ## The downstream, same mechanism as #5636 (which measured it) +// +// `ObjectLogger` routes `warn` to **stdout**; `serve`'s boot-quiet window wraps +// `process.stdout.write` only; a cold boot reaches this seam inside that window +// because `materializeDeclaredConnectors(ctx, { fatal: true })` DEGRADES rather +// than throwing when an upstream is unreachable. `BootLogCapture.offer()` keeps +// a physical line only when `classifyBootLogLine` finds a ` ` head on +// it, so every continuation line of an interpolated message is DROPPED — not +// merely mangled. cloud#971's original shape. +// +// ## Reachability (why the issue is a `finding`) +// +// Every `ConnectorUpstreamUnavailableError` message under `packages/connectors/*` +// is single-line text we wrote. But the class takes whatever message a factory +// hands it, and ADR-0097 explicitly invites third parties to write provider +// factories; the spec constrains the `code`, never the text. The first factory +// that forwards an SDK's multi-line failure lands here. +// +// ## What this change deliberately does NOT touch +// +// `reason` — stored as the husk's `degradedReason`, surfaced by `GET /connectors` +// and quoted by a `connector_action` refusal — stays VERBATIM, newlines included. +// It is read by a human through JSON, not split by a line-oriented consumer. +// #5636 made the same call one layer up; the tests below pin it from both sides, +// so a future "let's normalize the reason too" cannot pass unnoticed. + +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { LiteKernel, ObjectLogger } from '@objectstack/core'; +import type { Connector, ConnectorProviderFactory } from '@objectstack/spec/integration'; +import { ConnectorSchema, ConnectorUpstreamUnavailableError } from '@objectstack/spec/integration'; +import { AutomationServicePlugin } from './plugin.js'; +import { AutomationEngine } from './engine.js'; + +afterEach(() => { + vi.restoreAllMocks(); +}); + +// ── fixtures ─────────────────────────────────────────────────────────────── + +/** + * What an SDK-wrapping provider factory throws when its upstream is down and it + * forwards the driver's own multi-line text. + */ +const MULTILINE_UPSTREAM = [ + "connector 'gh_mcp' could not reach its MCP server", + ' cause: connect ECONNREFUSED 127.0.0.1:8931', + ' hint: is the MCP server running?', +].join('\n'); + +/** The two facts that live on the CONTINUATION lines of the old shape. */ +const CAUSE_LINE_FACT = 'ECONNREFUSED 127.0.0.1:8931'; +const HINT_LINE_FACT = 'is the MCP server running?'; + +/** A provider-bound declarative entry, as `registerApp` stores it. */ +function providerConnector(name: string) { + return { name, label: name, type: 'api', provider: 'fake', providerConfig: {} }; +} + +/** A factory that is always down, throwing the #3017 marker error. */ +function downFactory(message: string, cause?: unknown): ConnectorProviderFactory { + return () => { + throw new ConnectorUpstreamUnavailableError(message, { cause }); + }; +} + +/** + * The action-less husk `buildDegradedHuskDef` produces, for the direct-call + * tests below (which exercise the engine method without a plugin around it). + */ +function huskDef(name: string): Connector { + return { + name, + label: name, + type: 'api', + status: 'error', + enabled: true, + authentication: { type: 'none' }, + connectionTimeoutMs: 30000, + requestTimeoutMs: 30000, + actions: [], + } as Connector; +} + +/** + * Boot a kernel with a declared connector set and a provider factory. Boot must + * NOT throw on an unreachable upstream — `{ fatal: true }` degrades (#3017) — + * which is exactly what puts this seam inside `serve`'s boot-quiet window. + */ +async function bootDegraded(declared: unknown[], factory: ConnectorProviderFactory, logger?: unknown) { + const kernel = new LiteKernel({ logger: logger ?? { level: 'silent' } } as never); + kernel.use(new AutomationServicePlugin()); + kernel.use({ + name: 'test.harness', + type: 'standard' as const, + version: '1.0.0', + dependencies: ['com.objectstack.service-automation'], + async init(ctx: any) { + ctx.registerService('objectql', { + registry: { listItems: (t: string) => (t === 'connector' ? declared : []) }, + }); + ctx.getService('automation').registerConnectorProvider('fake', factory); + }, + async start() {}, + } as never); + await kernel.bootstrap(); + return { kernel, engine: kernel.getService('automation') as AutomationEngine }; +} + +/** Capture everything written to one std stream while `fn` runs, split to lines. */ +async function captureStream( + which: 'stdout' | 'stderr', + fn: () => Promise | void, +): Promise { + const chunks: string[] = []; + const spy = vi.spyOn(process[which], 'write').mockImplementation(((c: string | Uint8Array) => { + chunks.push(String(c)); + return true; + }) as never); + try { + await fn(); + } finally { + spy.mockRestore(); + } + return chunks.join('').split('\n').filter((l) => l.length > 0); +} + +/** + * `ObjectLogger`'s `pretty`/`text` record head — the same predicate + * `classifyBootLogLine` applies in `packages/cli/src/utils/boot-log-capture.ts`. + * Re-stated rather than imported: this package must not depend on + * `@objectstack/cli`, and the predicate is the general one every line-based + * consumer keys off, the CLI's boot buffer being the strictest example. + */ +const RECORD_HEAD = /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z(?: \|)? (DEBUG|INFO|WARN|ERROR|FATAL)\b/; + +/** `classifyBootLogLine`'s verdict, reduced to retained-or-dropped. */ +function classifyLine(raw: string): string | null { + const line = raw.replace(/\u001B\[[0-9;]*m/g, '').trim(); + if (!line) return null; + if (line.startsWith('{')) { + try { + const rec = JSON.parse(line) as { level?: unknown; time?: unknown }; + return typeof rec.time === 'string' && typeof rec.level === 'string' ? String(rec.level) : null; + } catch { + return null; + } + } + const m = RECORD_HEAD.exec(line); + return m ? m[1].toLowerCase() : null; +} + +const REGISTER_PREFIX = 'Connector registered DEGRADED'; + +interface DegradeRecord { + level: string; + msg: string; + degradedReason?: unknown; + error?: unknown; + issues?: Array>; +} + +// ── the seam, end to end through a cold boot ─────────────────────────────── + +describe('#5660 — the degrade REGISTRATION is one record, cause in meta', () => { + it('a multi-line provider reason never reaches the log message', async () => { + const lines = await captureStream('stdout', async () => { + const { kernel } = await bootDegraded( + [providerConnector('gh_mcp')], + downFactory(MULTILINE_UPSTREAM), + { level: 'warn', format: 'json' }, + ); + await kernel.shutdown(); + }); + + const mine = lines.filter((l) => l.includes(REGISTER_PREFIX)); + expect(mine, 'the registration announced itself exactly once').toHaveLength(1); + const record = JSON.parse(mine[0]) as DegradeRecord; + + expect(record.level).toBe('warn'); + // Pre-fix this message carried the reason's three lines, so the record + // became three physical lines of which two had no level head. + expect(record.msg).not.toContain('\n'); + expect(record.msg).toContain('gh_mcp'); + expect(record.msg).toContain('origin: declarative'); + // Self-sufficient without the reason: what the state costs and what + // happens next, so the message alone is a usable record. + expect(record.msg).toContain('no actions and no handlers'); + expect(record.msg).toContain('#3017'); + // …and none of the foreign text is in it. + expect(record.msg).not.toContain(CAUSE_LINE_FACT); + expect(record.msg).not.toContain(HINT_LINE_FACT); + + // The facts, in fields a log query can filter on. `degradedReason` is + // what the registration STORED; `error` is the thrown value's own + // rendering (`describeThrownForLog`, not a validation rejection here). + expect(record.degradedReason).toBe(MULTILINE_UPSTREAM); + expect(record.error).toBe(MULTILINE_UPSTREAM); + expect(record.issues).toBeUndefined(); + + // Nothing anywhere on stdout for the boot buffer to drop. + for (const line of lines) { + expect(classifyLine(line), line).not.toBeNull(); + } + }); + + it('renders as a single head-bearing line in `pretty` too', async () => { + // `pretty` is what the CLI gets (the kernel builds the logger from a + // bare `{ level }`), so it is the format the boot buffer actually reads. + const lines = await captureStream('stdout', async () => { + const { kernel } = await bootDegraded( + [providerConnector('gh_mcp')], + downFactory(MULTILINE_UPSTREAM), + { level: 'warn', format: 'pretty' }, + ); + await kernel.shutdown(); + }); + + const mine = lines.filter((l) => l.includes(REGISTER_PREFIX)); + expect(mine).toHaveLength(1); + expect(mine[0]).toMatch(RECORD_HEAD); + expect(mine[0]).toContain('WARN'); + // The cause survives on that one line — newlines escaped by the meta's + // JSON.stringify, which is the whole point of moving it out of `msg`. + expect(mine[0]).toContain(CAUSE_LINE_FACT); + expect(mine[0]).toContain(HINT_LINE_FACT); + for (const line of lines) { + expect(classifyLine(line), line).not.toBeNull(); + } + }); + + it('calls warn(message, meta) — `warn` has no Error slot', async () => { + // Checked against the `Logger` contract rather than assumed: + // `warn(message, meta?)` has no `Error` parameter (only `error`/`fatal` + // do), so the cause belongs in argument TWO here. + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + const { kernel } = await bootDegraded( + [providerConnector('gh_mcp')], + downFactory(MULTILINE_UPSTREAM), + ); + + const call = warn.mock.calls.find((c) => String(c[0]).includes(REGISTER_PREFIX)); + expect(call, 'the seam logged at warn level').toBeDefined(); + expect(call).toHaveLength(2); + const [message, meta] = call as [string, Record]; + expect(message).not.toContain('\n'); + expect(meta.degradedReason).toBe(MULTILINE_UPSTREAM); + expect(meta.error).toBe(MULTILINE_UPSTREAM); + + await kernel.shutdown(); + }); + + it('leaves the API-facing `degradedReason` verbatim, newlines included', async () => { + // The other direction of the same contract: moving the cause out of the + // log MESSAGE must not reshape what `GET /connectors` shows or what a + // `connector_action` refusal quotes. + const { kernel, engine } = await bootDegraded( + [providerConnector('gh_mcp')], + downFactory(MULTILINE_UPSTREAM), + ); + + const desc = engine.getConnectorDescriptors().find((d) => d.name === 'gh_mcp'); + expect(desc?.state).toBe('degraded'); + expect(desc?.degradedReason).toBe(MULTILINE_UPSTREAM); + expect(engine.getConnectorDegradedReason('gh_mcp')).toBe(MULTILINE_UPSTREAM); + + await kernel.shutdown(); + }); + + it("the error's own nested `cause` is carried, not yet rendered", async () => { + // Honest scope statement, pinned so nobody reads more into A-route than + // it delivers. `ConnectorUpstreamUnavailableError` takes a `cause` (the + // underlying connect error) and forwarding the THROWN VALUE is what + // makes rendering it possible at all — but `describeThrownForLog` reads + // `.message` / `.issues` only, so the nested cause does not appear in + // the record today. Widening that is a change to the shared helper, + // used by four seams; it is not this seam's call to make. + const warn = vi.spyOn(ObjectLogger.prototype, 'warn'); + const { kernel } = await bootDegraded( + [providerConnector('gh_mcp')], + downFactory('upstream down', new Error('connect ECONNREFUSED 127.0.0.1:8931')), + ); + + const call = warn.mock.calls.find((c) => String(c[0]).includes(REGISTER_PREFIX)); + const [, meta] = call as [string, Record]; + expect(meta.error).toBe('upstream down'); + expect(JSON.stringify(meta)).not.toContain('ECONNREFUSED'); + + await kernel.shutdown(); + }); +}); + +// ── the optional parameter, from both sides ──────────────────────────────── + +describe('#5660 — `cause` is optional and the record stays useful without it', () => { + it('a two-argument call still reports the reason, in meta', async () => { + // Non-breaking by construction: `cause` sits after the defaulted + // `origin`, so every pre-existing call shape still compiles — this test + // IS one (def + reason only). The record must still carry the fact an + // operator came for, so `degradedReason` is unconditional. + const engine = new AutomationEngine(new ObjectLogger({ level: 'warn', format: 'json' })); + + const lines = await captureStream('stdout', () => { + engine.registerDegradedConnector(huskDef('gh_mcp'), MULTILINE_UPSTREAM); + }); + + expect(lines).toHaveLength(1); + const record = JSON.parse(lines[0]) as DegradeRecord; + expect(record.msg).not.toContain('\n'); + expect(record.msg).toContain('origin: declarative'); + expect(record.degradedReason).toBe(MULTILINE_UPSTREAM); + // No thrown value was supplied, so no rendering of one is invented. + expect(record.error).toBeUndefined(); + expect(record.issues).toBeUndefined(); + // The husk registered, reason verbatim. + expect(engine.getConnectorDegradedReason('gh_mcp')).toBe(MULTILINE_UPSTREAM); + }); + + it('a validation rejection as `cause` renders as `issues`, on one line', async () => { + // The other branch of `describeThrownForLog`, reachable by any future + // caller whose failure is a schema rejection: a `ZodError.message` is a + // multi-line JSON dump opening on a bare `[`, so this is the shape that + // cost cloud#971 an rc line. It must stay one physical line, and the + // rejected key names must survive `ObjectLogger`'s substring redactor + // (#5573 — which is why the flattened field is `unrecognized`, not + // `keys`). + const rejected = ConnectorSchema.safeParse({ name: 'gh_mcp', nope: true }); + expect(rejected.success, 'fixture must actually be rejected').toBe(false); + const zodError = (rejected as { error: unknown }).error; + expect(String((zodError as Error).message)).toContain('\n'); + + const engine = new AutomationEngine(new ObjectLogger({ level: 'warn', format: 'json' })); + const lines = await captureStream('stdout', () => { + engine.registerDegradedConnector(huskDef('gh_mcp'), 'husk def rejected', 'declarative', zodError); + }); + + expect(lines).toHaveLength(1); + const record = JSON.parse(lines[0]) as DegradeRecord; + expect(record.msg).not.toContain('\n'); + expect(record.degradedReason).toBe('husk def rejected'); + expect(Array.isArray(record.issues)).toBe(true); + expect(record.issues!.length).toBeGreaterThan(0); + expect(record.error).toBeUndefined(); + expect(JSON.stringify(record.issues)).not.toContain('REDACTED'); + }); +}); + +// ── reverse verification, direction predicted before running ─────────────── + +describe('#5660 — what the interpolated rendering cost, measured', () => { + it('the pre-fix shape puts the cause and the hint on lines the buffer drops', async () => { + // Predicted BEFORE running, and it is the plain red direction — but the + // claim is NARROWER than #5636's, deliberately, because the payload is + // different. A ZodError dump opens on a bare `[`, so there the ONE + // retained line held no facts at all. Here the reason's FIRST line is + // ordinary prose and does survive on the head line; what is lost is + // every line after it — the `cause:` and `hint:` lines, i.e. the address + // to connect to and the thing to check. So: OLD → 3 physical lines, 1 + // classifies, 2 dropped, and the survivor names the failure without + // saying anything actionable. NEW → 1 line, classifies, carries both. + // Reporting "every fact is lost" here would have been the tidier story + // and the wrong one. + const log = new ObjectLogger({ level: 'warn', format: 'pretty' }); + + const before = await captureStream('stdout', () => { + log.warn(`Connector registered DEGRADED: gh_mcp (origin: declarative) — ${MULTILINE_UPSTREAM}`); + }); + expect(before, 'one call, three physical lines').toHaveLength(3); + const beforeKept = before.filter((l) => classifyLine(l) !== null); + expect(beforeKept).toHaveLength(1); + expect(beforeKept[0]).toContain('could not reach its MCP server'); + expect(beforeKept[0]).not.toContain(CAUSE_LINE_FACT); + expect(beforeKept[0]).not.toContain(HINT_LINE_FACT); + // The dropped lines are where the actionable detail was. + const beforeDropped = before.filter((l) => classifyLine(l) === null); + expect(beforeDropped).toHaveLength(2); + expect(beforeDropped.join('\n')).toContain(CAUSE_LINE_FACT); + expect(beforeDropped.join('\n')).toContain(HINT_LINE_FACT); + + const after = await captureStream('stdout', () => { + log.warn( + 'Connector registered DEGRADED: gh_mcp (origin: declarative) — no actions and no handlers ' + + 'until its upstream is reachable; a connector_action dispatching to it fails with the stored ' + + 'reason, and the materializer retries with backoff (#3017).', + { degradedReason: MULTILINE_UPSTREAM, error: MULTILINE_UPSTREAM }, + ); + }); + expect(after).toHaveLength(1); + expect(classifyLine(after[0])).toBe('warn'); + expect(after[0]).toContain(CAUSE_LINE_FACT); + expect(after[0]).toContain(HINT_LINE_FACT); + }); +}); diff --git a/packages/services/service-automation/src/engine.ts b/packages/services/service-automation/src/engine.ts index 6ea0cc46c6..5069c3a281 100644 --- a/packages/services/service-automation/src/engine.ts +++ b/packages/services/service-automation/src/engine.ts @@ -177,6 +177,10 @@ const FLOW_NODE_UNKNOWN_KEY_GUIDANCE: Record> = { import { runIsUnscopedUserMode, flowTouchesData } from './runtime-identity.js'; import { isGuardRefusal } from './guard-refusal.js'; import { summarizeRun, formatRunSummaryLine } from './run-summary.js'; +// #5660 — the degrade registration reports a FOREIGN failure (a third-party +// provider factory's text), so it renders it as structured `meta` rather than +// interpolating it into the log message. See ./thrown-cause-diagnostics.ts. +import { describeThrownForLog } from './thrown-cause-diagnostics.js'; // ─── Node Executor Interface (Plugin Extension Point) ─────────────── @@ -1710,12 +1714,73 @@ export class AutomationEngine implements IAutomationService { * than "unknown connector". The materializer retries and replaces this * registration via {@link registerConnector} once the upstream is back. * Same cross-origin collision rule as {@link registerConnector} (ADR-0097 §4). + * + * #5660 — this record's message used to end in `— ${reason}`, and `reason` + * is not ours: the only caller passes `ConnectorUpstreamUnavailableError`'s + * message, constructed by a third-party provider factory (ADR-0097 invites + * people to write them; the spec defines the error class and says nothing + * about its text), so an upstream SDK's multi-line failure landed inside the + * message verbatim. `ObjectLogger.write()` emits one ` …` head + * per call, so a message carrying newlines becomes several physical lines + * and only the first is a record. This is the seam of that family (#5048, + * #5575, #5636) that fires **first and on the default branch** — every + * successful husk registration, i.e. every first degrade — and it fires at + * cold boot inside `serve`'s boot-quiet window, which wraps + * `process.stdout.write` (where `warn` goes) and whose `BootLogCapture` + * *drops* any physical line `classifyBootLogLine` finds no level head on. + * So the continuation lines were not merely hard to parse, they were gone. + * + * The message is now self-sufficient and newline-free by construction + * (`name` is `^[a-z_][a-z0-9_]*$` per {@link ConnectorSchema}, `origin` is + * an enum), and the facts travel in the logger's `meta`: + * + * - `degradedReason` — always present: the text this registration STORED + * on the husk. Named for the field it mirrors, and deliberately not + * `reason`/`cause`/`key`-flavoured: `ObjectLogger` redacts recursively + * by substring over `password`/`token`/`secret`/`key` (#5573), and this + * name matches none of them, so the operator's one fact survives. + * - the thrown value's own rendering (`error` or `issues`, via + * {@link describeThrownForLog}) — present only when the caller supplied + * `cause`. It is a fact about the FAILURE, where `degradedReason` is a + * fact about the REGISTRATION; today's single caller derives one from + * the other, so the two coincide, but the record's shape does not + * depend on that and a caller that summarizes is not silently lossy. + * Note `describeThrownForLog` renders the thrown value's own `.message` + * only — `ConnectorUpstreamUnavailableError.cause` (the underlying + * connect error) is carried here but not yet rendered; widening that + * rendering is a change to the shared helper, not to this seam. + * + * `reason` itself — and therefore `degradedReason` on the descriptor, what + * `GET /connectors` shows and what a `connector_action` refusal quotes — is + * unchanged, verbatim, newlines included. It is read by a human through + * JSON, not by a line splitter (#5636 made the same call at the caller). + * + * @param reason operator-facing text stored as the husk's `degradedReason`. + * Kept verbatim; never interpolated into a log message. + * @param origin how the connector reached the engine (ADR-0097 §4). + * @param cause the thrown value behind the degrade, for the log record's + * structured `meta`. Optional — a caller with no thrown value in hand + * still gets `degradedReason` in the record. */ - registerDegradedConnector(def: Connector, reason: string, origin: ConnectorOrigin = 'declarative'): void { + registerDegradedConnector( + def: Connector, + reason: string, + origin: ConnectorOrigin = 'declarative', + cause?: unknown, + ): void { const parsed = ConnectorSchema.parse(def); this.assertSameOriginOrFree(parsed.name, origin); this.connectors.set(parsed.name, { def: parsed, handlers: {}, origin, state: 'degraded', degradedReason: reason }); - this.logger.warn(`Connector registered DEGRADED: ${parsed.name} (origin: ${origin}) — ${reason}`); + // `warn(message, meta?)` per the `Logger` contract — no `Error` slot + // below `error`, so the cause belongs in argument TWO here. + this.logger.warn( + `Connector registered DEGRADED: ${parsed.name} (origin: ${origin}) — no actions and no handlers ` + + `until its upstream is reachable; a connector_action dispatching to it fails with the stored ` + + `reason, and the materializer retries with backoff (#3017).`, + cause === undefined + ? { degradedReason: reason } + : { degradedReason: reason, ...describeThrownForLog(cause) }, + ); } /** Enforce the ADR-0097 §4 two-sources-of-truth rule; warn on same-origin replace. */ diff --git a/packages/services/service-automation/src/plugin.ts b/packages/services/service-automation/src/plugin.ts index fe69164d04..f8c2cdb05d 100644 --- a/packages/services/service-automation/src/plugin.ts +++ b/packages/services/service-automation/src/plugin.ts @@ -1304,6 +1304,12 @@ export class AutomationServicePlugin implements Plugin { * Measured on a 13-line interpolated ZodError dump: 1 line retained (the * head line, ending at Zod's `[`) and 12 dropped outright. That is cloud#971 * in its original form, not merely a hard-to-parse record. + * + * #5660 — there is a THIRD record on this path, and it is the one that fires + * first and on the default branch: `registerDegradedConnector`'s own `warn`, + * inside the engine, on the `try` above SUCCEEDING. It carried the same + * interpolated `reason`; the fix lives in `engine.ts` and is why `info.cause` + * is now forwarded into that call as well. */ private degradeConnectorInstance( engine: AutomationEngine, @@ -1319,7 +1325,11 @@ export class AutomationServicePlugin implements Plugin { * provider's own message, kept verbatim for human readers. */ reason: string; - /** The thrown value, for the log record's structured `meta` (#5636). */ + /** + * The thrown value, for the structured `meta` of every record on + * this path — the two here (#5636) and the engine's own degrade + * registration `warn` (#5660), which this hands it to. + */ cause: unknown; }, ): void { @@ -1329,10 +1339,17 @@ export class AutomationServicePlugin implements Plugin { if (!info.hasLive) { try { + // #5660 — `cause` is passed too, for the engine's OWN record. + // That `warn` fires on the success path of this call (every + // first degrade), before either record below, and it used to + // interpolate `reason` into its message; the engine now renders + // the thrown value as `meta`. `reason` still travels separately + // because it is what the husk STORES (`degradedReason`). engine.registerDegradedConnector( this.buildDegradedHuskDef(info.name, info.entry), info.reason, 'declarative', + info.cause, ); } catch (err) { // Can't even register the husk (e.g. the entry's def no longer