From 25ec347152e196c4c49a5ffa9a1047016f7dbc3b Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 10 Sep 2026 22:09:27 +0000 Subject: [PATCH 1/3] fix(service-automation): guard the two initial-execution completion history writes (#16274) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `execute()` and `executeWithoutRetry()` called `recordLog({ status: 'completed' })` from inside the `try` whose `catch` exists for node failures, so a throw out of a history write on a run that had already finished was handled as though a node had thrown. Measured on the unpatched tree, and sharper than the report assumed: the false `failed` is handed to `retryExecution` by the strategy branch, whose loop reads `result.success` and re-executes the whole flow — `1 + maxRetries` runs of every node for one logical success, unattended, with one `failed` history row per attempt. Controls: the same flow on healthy sinks runs the node once; a genuine node failure runs it `1 + maxRetries` times. Guarded at each call site in the shape the resume path already landed: report the swallowed failure once at `error` with its consequence and fix, recompute the summary with the same pure function. No `catch` arm's meaning is widened. Claude-Session: https://claude.ai/code/session_01ToDPcx9AESFubJkDiFMtKW Co-authored-by: Claude --- .../16274-initial-completion-history-guard.md | 23 ++ .../services/service-automation/src/engine.ts | 189 +++++++-- .../initial-completion-history-throw.test.ts | 380 ++++++++++++++++++ 3 files changed, 565 insertions(+), 27 deletions(-) create mode 100644 .changeset/16274-initial-completion-history-guard.md create mode 100644 packages/services/service-automation/src/initial-completion-history-throw.test.ts diff --git a/.changeset/16274-initial-completion-history-guard.md b/.changeset/16274-initial-completion-history-guard.md new file mode 100644 index 00000000000..874bf9769af --- /dev/null +++ b/.changeset/16274-initial-completion-history-guard.md @@ -0,0 +1,23 @@ +--- +"@objectstack/service-automation": patch +--- + +A run whose nodes all succeeded is no longer answered `failed` — or, under `errorHandling.strategy: 'retry'`, RE-EXECUTED — because its terminal run-history write threw (#16274) + +`AutomationEngine.execute()` and `executeWithoutRetry()` each called `recordLog({ status: 'completed' })` from inside the `try` whose `catch` exists for **node** failures, so a throw out of a history write on a run that had already finished successfully was handled as though a node had thrown. This is the initial-execution half of the pattern fixed on the resume path in 17.4.0; that fix deliberately scoped these two sites out. + +**The consequence was measured, and it is a double run, not just a mislabelled one.** `execute()`'s node-failure arm ends at the retry strategy branch, which hands the false `failed` result to the retry loop; the loop reads `result.success` and therefore re-enters `executeWithoutRetry()` — the whole flow, every node, again. Driven with `maxRetries: 2`: a flow whose node always succeeded ran it **three** times and wrote three `failed` rows, unattended, inside one `execute()` call, with the node's side effects repeated each time. Controls on the same instrument: the identical flow on healthy sinks runs the node once, and a genuine node failure runs it three times (retry working correctly). + +**What can throw there is a host surface, not in-repo code** — which is why it could not be reproduced from inside the package and why the package owed the fix: + +- the run-summary line `logger.info(line, meta)`, on by default (`runSummaryLog: 'info'`) and calling a **host-injected** `Logger`. This one needs no store at all. +- `store.recordTerminal(record)` throwing **synchronously**, before it returns a promise — the `void write.catch(...)` beneath that call only ever sees a returned promise's rejection. Both stores shipped in this package are `async` methods and cannot do it, but `SuspendedRunStore` is an exported interface whose `recordTerminal` is optional, so a host store is unconstrained. (A store returning a non-thenable escapes identically: `write.catch` is then itself a synchronous `TypeError`.) + +On that second variant the old code did not even answer `failed`: the node-failure arm's own `recordLog({ status: 'failed' })` threw again out of the same store and escaped `execute()` entirely — a rejected promise where `AutomationResult` is declared. + +What changes: + +- **Each completion-path history write is guarded at its own call site**, restoring the invariant that call's own documentation states: a history write must never block or break the run that produced it. The caller is told the truth — `success: true`, no `status`, the flow's `successMessage`, and a `summary` recomputed by the same pure function `recordLog` runs first — the node runs exactly once, and one `completed` row is recorded rather than `1 + maxRetries` `failed` ones. +- **The swallowed failure is reported once per run at `error`**, with the consequence and the fix in the first line: the run completed, its terminal history row never landed, nothing retries it, and the run must not be re-run. The thrown text rides the structured slot. + +⛔ No `catch` arm's meaning is widened: a genuine node failure still reaches the node-failure arm, is still recorded `failed`, still carries the node's own text, and is still retried the full `1 + maxRetries` times. diff --git a/packages/services/service-automation/src/engine.ts b/packages/services/service-automation/src/engine.ts index 7f77362b873..8223765305a 100644 --- a/packages/services/service-automation/src/engine.ts +++ b/packages/services/service-automation/src/engine.ts @@ -4865,19 +4865,108 @@ export class AutomationEngine implements IAutomationService { const durationMs = Date.now() - startTime; - // Record execution log - const logged = this.recordLog({ - id: runId, - flowName, - flowVersion: flow.version, - status: 'completed', - startedAt, - completedAt: new Date().toISOString(), - durationMs, - trigger: buildRunTrigger(context), - steps, - output, - }, context); + // [#16274] THE RUN IS OVER AND IT SUCCEEDED. Everything from here + // to the return is BOOKKEEPING ABOUT that fact, and the `catch` + // below this `try` exists for NODE failures — so a throw out of the + // history write was handled as though a node had thrown: the arm + // recorded a `failed` row carrying the history driver's own text as + // the run's error and answered `status: 'failed'` for a run whose + // every node succeeded. This is the guard PR #16273 landed on + // {@link resumeInternal}'s completion path, now on the two + // INITIAL-execution paths that card deliberately scoped out — this + // one and {@link executeWithoutRetry}'s. + // + // ⚠️ MEASURED, and sharper than the report assumed: under + // `errorHandling.strategy: 'retry'` that false `failed` is handed + // to {@link retryExecution} by the strategy branch in the catch + // below, whose loop reads `result.success` — so it RE-EXECUTES a + // flow that already finished. `1 + maxRetries` runs of every node, + // unattended, inside this one call, with the side effects repeated + // each time and one `failed` history row per attempt. That is the + // DOUBLE RUN #15944 was graded sharp for, reached here with no + // operator action at all, where #15944's needed an operator to + // restore and resume. + // + // Two statements inside `recordLog` reach that catch on the + // terminal path, and neither is hypothetical: + // + // 1. the run-summary line `this.logger.info(line, meta)` — on by + // default (`runSummaryLog: 'info'`) and calling a + // HOST-INJECTED `Logger`, so it needs no store at all; + // 2. `store.recordTerminal(record)` throwing SYNCHRONOUSLY — the + // `void write.catch(...)` beneath that call only ever sees a + // returned promise's rejection (both shipped stores are + // `async` and cannot; `SuspendedRunStore` is an exported + // interface with an optional `recordTerminal`, so a host store + // is unconstrained, and one returning a non-thenable makes + // `write.catch` itself a synchronous `TypeError`). On THAT + // variant the unguarded code did not even answer `failed`: the + // catch arm's own `recordLog({ status: 'failed' })` threw again + // out of the same store and escaped `execute()` entirely, + // rejecting a promise `AutomationResult` is declared for. + // + // The guard restores the invariant `recordLog`'s own doc states — + // "a history write must NEVER block or break the run that produced + // it" — which that call was relied upon to keep and did not. + // + // ⛔ NOT a widening of anything: no exit gains a status it did not + // have, the node-failure arm below is untouched (a genuine node + // throw still lands there, still records `failed`, still retries), + // and the failure is REPORTED rather than swallowed — see the + // catch. + let logged: ExecutionLogEntry | undefined; + try { + logged = this.recordLog({ + id: runId, + flowName, + flowVersion: flow.version, + status: 'completed', + startedAt, + completedAt: new Date().toISOString(), + durationMs, + trigger: buildRunTrigger(context), + steps, + output, + }, context); + } catch (bookkeeping) { + // #4632 verdict: DURABILITY, so `error` — the caller is told + // the truthful thing (the run completed), which is exactly + // what makes the rest invisible from the outside: the terminal + // history row never landed, nothing retries it, and no + // envelope carries a word about it. Consequence and fix in the + // first line, per AGENTS.md. Said ONCE per run, not once per + // failed write. + // + // ⚠️ The level is the precedent's (#16273, #15555) and is NOT + // a #13398-class raise: that ruling forbids raising a site to + // `error` where doing so means GROWING `error?` onto a + // published sink that lacks it, and this sink — `Logger` from + // `@objectstack/spec/contracts` — declares `error(message, + // error?, meta?)` as a REQUIRED member (only `fatal?`, + // `child?` and `withTrace?` are optional). Nothing is widened, + // which is also why the two precedents on this same sink could + // land `error`. + // + // THIRD argument per `error(message, error?, meta?)`; the + // `Error` slot stays empty on purpose (#5575), and the thrown + // text goes to the structured slot rather than into the + // message (#6499). + this.logger.error( + `[Automation] run '${runId}' of flow '${flowName}' COMPLETED successfully but its ` + + `run-history bookkeeping threw, so its terminal history row never landed — nothing ` + + `retries it, the caller is told the run succeeded, and after the next restart this ` + + `run is invisible to the Runs surfaces while the approvals sweeps read it as ` + + `never-finished. The run itself is COMPLETE and must NOT be re-run or retried. Fix ` + + `the history failure in this record's meta.`, + undefined, + describeThrownForLog(bookkeeping), + ); + } + // [#16274] Recomputed when the guard above had to abandon + // `recordLog`: the same pure function of the same steps that + // `recordLog`'s own first statement runs, so the two spellings + // cannot disagree. Same shape as `resumeInternal`'s (#15944). + const summary = logged?.summary ?? summarizeRun(steps); return { success: true, @@ -4908,7 +4997,7 @@ export class AutomationEngine implements IAutomationService { // #4354 — hand the counts back synchronously so a caller // (a `subflow` roll-up, a runtime test asserting the sweep wrote // something) never has to re-read the run to learn what it did. - summary: logged.summary, + summary, }; } catch (err: unknown) { // A node asked to suspend the run (ADR-0019 durable pause). Snapshot @@ -10154,18 +10243,64 @@ export class AutomationEngine implements IAutomationService { } const durationMs = Date.now() - startTime; - const logged = this.recordLog({ - id: runId, - flowName, - flowVersion: flow.version, - status: 'completed', - startedAt, - completedAt: new Date().toISOString(), - durationMs, - trigger: buildRunTrigger(context), - steps, - output, - }, context); + // [#16274] The SECOND initial-execution instance of the guard + // above in `execute()` — the retry path's own completion site, and + // the one where the consequence was measured worst. This method IS + // a retry attempt (it is only ever reached from + // {@link retryExecution}), so a `failed` answer here does not just + // mislead a caller: it is read by the loop that drives this method, + // which re-enters it for the next attempt. An attempt whose every + // node SUCCEEDED and whose only failure was its own history write + // therefore burned the rest of the budget re-running the flow, + // `1 + maxRetries` times in total, each attempt writing one more + // `failed` row for work that had already completed. + // + // ⚠️ Fixing `execute()` alone would NOT have closed that: a flow + // under `strategy: 'retry'` whose attempt 2 completes leaves + // through THIS exit and never crosses `execute()`'s again — the + // seventh instance of this method's documented drift from + // `execute()` (#9378, #9415, #9414, #9510, #9704, #9889 before it), + // and the same chokepoint discipline applies: one shape, both + // attempt paths. + // + // The reachable statements, the invariant and the #13398 reading + // are all stated at the `execute()` site; this is the same guard, + // not a second design. + let logged: ExecutionLogEntry | undefined; + try { + logged = this.recordLog({ + id: runId, + flowName, + flowVersion: flow.version, + status: 'completed', + startedAt, + completedAt: new Date().toISOString(), + durationMs, + trigger: buildRunTrigger(context), + steps, + output, + }, context); + } catch (bookkeeping) { + // #4632 verdict: DURABILITY, so `error` — see the `execute()` + // site for why this is outside #13398's class. The message + // names the ATTEMPT, because the run id an operator finds in + // the Runs surfaces is this attempt's own and not the failed + // attempt's. Said ONCE per run, not once per failed write. + this.logger.error( + `[Automation] run '${runId}' of flow '${flowName}' COMPLETED successfully on a RETRY ` + + `attempt but its run-history bookkeeping threw, so its terminal history row never ` + + `landed — nothing retries it, the caller is told the run succeeded, and after the next ` + + `restart this run is invisible to the Runs surfaces while the approvals sweeps read it ` + + `as never-finished. The run itself is COMPLETE and must NOT be re-run or retried. Fix ` + + `the history failure in this record's meta.`, + undefined, + describeThrownForLog(bookkeeping), + ); + } + // [#16274] The same recomputation as the `execute()` site's: one + // pure function of the same steps, so the abandoned `recordLog` + // costs the caller no counts. + const summary = logged?.summary ?? summarizeRun(steps); // #4354 — a retried run reports its own attempt's counts, not the // failed one's: `retryExecution` returns THIS result on success. @@ -10175,7 +10310,7 @@ export class AutomationEngine implements IAutomationService { // The author's completion text has to be produced here as well, or // `successMessage` would be a function of which attempt happened to // work — the same route-dependent shape the fix is removing. - return { success: true, output, durationMs, successMessage: flow.successMessage, summary: logged.summary }; + return { success: true, output, durationMs, successMessage: flow.successMessage, summary }; } catch (err: unknown) { // [#9510] A node asked to suspend the run (ADR-0019 durable pause) // — here, on a RETRY attempt, the only way this method is ever diff --git a/packages/services/service-automation/src/initial-completion-history-throw.test.ts b/packages/services/service-automation/src/initial-completion-history-throw.test.ts new file mode 100644 index 00000000000..488651a7ba0 --- /dev/null +++ b/packages/services/service-automation/src/initial-completion-history-throw.test.ts @@ -0,0 +1,380 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * #16274 — a run whose nodes ALL succeeded must not be answered `failed`, and + * above all must not be RE-EXECUTED, because its terminal HISTORY write threw. + * + * The initial-execution half of the pattern #15944 reported on the resume path. + * `execute()` and `executeWithoutRetry()` each called `this.recordLog({ status: + * 'completed' })` from INSIDE the same `try` whose `catch` exists for node + * failures, so a throw out of a history write on a run that finished + * successfully was handled as though a node had thrown. + * + * ## ⚠️ The consequence, MEASURED on the unpatched tree rather than assumed + * + * The card filed this as the milder half of #15944 — "a completed run answered + * `failed`" — and flagged ONE question as worth driving first: whether the + * retry path can then re-attempt a run that already completed. It can, and + * that makes this the same DOUBLE RUN #15944 was graded sharp for: + * + * - `execute()`'s node-failure arm ends at a strategy branch that hands a + * `failed` result to {@link AutomationEngine.retryExecution}; + * - that loop reads `result.success`, so it re-enters + * `executeWithoutRetry()` — the whole flow, every node, again; + * - each attempt completes, throws in the same history write, is read as one + * more failure, and the loop burns the whole budget. + * + * Driven on `origin/main` with `maxRetries: 2`: the node ran **three** times + * for one logical success, and three `failed` rows were written. The controls + * below are what make that a reading — the same flow on healthy sinks runs the + * node ONCE, and a genuine node failure runs it three times (retry working + * correctly). Nothing external is needed to reach it: no store at all, just a + * host-injected `Logger` whose `info` throws on the run-summary line that is on + * by default (`runSummaryLog: 'info'`). + * + * On the store variant the unpatched code did not even answer `failed`: the + * catch arm's own `recordLog({ status: 'failed' })` threw again out of the same + * store and escaped `execute()` entirely — a REJECTED promise where + * `AutomationResult` is declared, and the reason that variant's node count is + * 1 (the strategy branch is never reached), which is not safety. + * + * ## What can throw out of `recordLog` + * + * Neither statement is an in-repo surface, which is why this cannot be + * reproduced without doubles and why it must be fixed — the package promises + * hosts it will not do this, in `recordLog`'s own doc comment: *"Best-effort + + * fire-and-forget: a history write must NEVER block or break the run that + * produced it."* + * + * 1. `store.recordTerminal(record)` throwing SYNCHRONOUSLY — the + * `void write.catch(...)` beneath that call only ever sees a RETURNED + * PROMISE's rejection. Both shipped stores are `async` and cannot; + * `SuspendedRunStore` is an exported interface whose `recordTerminal` is + * optional, so a host store is unconstrained. (A store returning a + * non-thenable escapes identically: `write.catch` is then itself a + * synchronous `TypeError`.) + * 2. The run-summary line `this.logger.info(line, meta)` — default-on and + * calling a HOST-INJECTED `Logger`. + * + * ## What this file pins + * + * 1. Both initial-execution paths answer the TRUTH for a completed run: + * `success: true`, no `status` discriminator, the author's + * `successMessage`, and a `summary` recomputed by the same pure function + * `recordLog` runs first. + * 2. **The sharp one: the node runs EXACTLY ONCE under + * `errorHandling.strategy: 'retry'`** — the assertion the defect actually + * fails, and the one the `maxRetries` control grades. + * 3. The store variant RETURNS rather than rejecting. + * 4. The swallowed failure stays loud: `error`, once per run, consequence and + * fix in the first line, the driver's text in the structured slot. + * 5. Controls, so every pin is a reading and not a constant: retry still + * retries a GENUINE node failure the full `1 + maxRetries` times; a + * genuine node failure is still answered `status: 'failed'` with the + * node's own text; and a completed run on healthy sinks logs no `error` + * and lands its row. + * + * ## Deliberately NOT here + * + * ⛔ `resumeInternal`'s completion site is PR #16273's and is untouched — + * `completed-run-history-throw.test.ts` owns it. ⛔ Nothing here widens a + * `catch` arm's meaning, and ⛔ nothing here bears on + * `restoreConsumedSuspension` or `inspectStrandedRequests` (#15358). + * + * ⛔ The FAILURE-arm `recordLog` on these two paths is a different site with a + * different consequence (a genuine node failure plus a throwing store makes + * `execute()` reject) and is NOT pinned here — it is reported separately rather + * than fixed or frozen under this card. + */ + +import { describe, it, expect } from 'vitest'; + +import { AutomationEngine } from './engine.js'; +import { InMemorySuspendedRunStore } from './suspended-run-store.js'; +import type { AutomationContext, AutomationResult } from '@objectstack/spec/contracts'; +import { defineActionDescriptor } from '@objectstack/spec/automation'; + +/** The history failures. Distinct text from the node's, so neither can stand in for the other. */ +const TERMINAL_WRITE_FAILURE = 'run-history driver refused the terminal row'; +const SUMMARY_LOG_FAILURE = 'log transport rejected the run-summary line'; +/** The node failure used ONLY by the controls, where a `failed` answer is correct. */ +const NODE_FAILURE = 'work blew up'; + +const MAX_RETRIES = 2; + +const plain = (type: string) => defineActionDescriptor({ type, version: '1.0.0', name: type }); +const ctx = { event: 'test', record: { id: 'rec_1' } } as unknown as AutomationContext; + +interface LoggedError { message: string; errorSlot: unknown; meta: unknown } + +/** + * Records `error` calls positionally (the `Logger` contract is + * `error(message, error?, meta?)`) and can be armed to throw from `info`. + */ +function recorder(opts: { infoThrows?: string } = {}) { + const errors: LoggedError[] = []; + return { + errors, + logger: { + // Armed at exactly ONE call: the run-summary line `recordLog` + // writes for a COMPLETED terminal run, the statement inside the + // window. The engine also logs `info` while registering executors + // and while running, and the FAILED row's own summary line is an + // `info` too — throwing from those would measure other seams. + info(_msg: string, meta?: { status?: string }) { + if (opts.infoThrows && meta?.status === 'completed') throw new Error(opts.infoThrows); + }, + warn() {}, + debug() {}, + error(message: string, errorSlot?: unknown, meta?: unknown) { + errors.push({ message, errorSlot, meta }); + }, + } as never, + }; +} + +/** A durable store whose terminal write throws SYNCHRONOUSLY, before any promise exists. */ +class SyncThrowTerminalStore extends InMemorySuspendedRunStore { + override recordTerminal(): Promise { + throw new Error(TERMINAL_WRITE_FAILURE); + } +} + +/** start → work → end. `work` SUCCEEDS unless the harness is told otherwise. */ +function flowDefinition(retry: boolean) { + return { + name: retry ? 'retry_flow' : 'plain_flow', + label: 'F', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'work', type: 'work', label: 'Work' }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'work' }, + { id: 'e2', source: 'work', target: 'end' }, + ], + ...(retry ? { errorHandling: { strategy: 'retry', maxRetries: MAX_RETRIES, backoffMs: 0 } } : {}), + successMessage: 'author success text', + errorMessage: 'author failure text', + }; +} + +function boot(opts: { + retry: boolean; + store?: InMemorySuspendedRunStore; + infoThrows?: string; + nodeThrows?: boolean; +}) { + const { errors, logger } = recorder({ infoThrows: opts.infoThrows }); + const engine = new AutomationEngine(logger, opts.store); + /** How many times the node's executor actually ran — the double-run instrument. */ + const calls = { work: 0 }; + engine.registerNodeExecutor({ + type: 'work', + descriptor: plain('work'), + async execute() { + calls.work++; + if (opts.nodeThrows) throw new Error(NODE_FAILURE); + return { success: true, output: { ok: true } }; + }, + } as never); + const definition = flowDefinition(opts.retry); + engine.registerFlow(definition.name, definition as never); + return { engine, calls, errors, flowName: definition.name }; +} + +/** + * Execute, recording WHICH WAY the call ended. On the pre-guard tree the + * completion path could make `execute()` REJECT outright (the catch arm's own + * `recordLog` throws again out of the same store), so a plain `await` would + * fail with a stack trace instead of producing a reading. + */ +async function executeOutcome(engine: AutomationEngine, flowName: string) { + return engine.execute(flowName, ctx).then( + (result: AutomationResult) => ({ kind: 'returned' as const, result, thrown: undefined as unknown }), + (err: unknown) => ({ kind: 'threw' as const, result: undefined, thrown: err }), + ); +} + +describe('#16274 — a completed run must not be failed, and never re-run, by its own history write', () => { + it('PIN 1 — `execute()`, terminal write throws SYNCHRONOUSLY, every node succeeded: the run is answered SUCCESS', async () => { + const store = new SyncThrowTerminalStore(); + const { engine, calls, errors, flowName } = boot({ retry: false, store }); + + const outcome = await executeOutcome(engine, flowName); + + // ── The reproduction. Before the guard this REJECTED: the completion + // write threw, the node-failure arm took it, and the arm's own + // `recordLog({ status: 'failed' })` threw again out of the same store. + expect(outcome.kind, 'a history write must never break the run that produced it').toBe('returned'); + expect(outcome.result?.success, 'every node succeeded').toBe(true); + expect(outcome.result?.status, 'a completed run is not `failed`').toBeUndefined(); + expect(outcome.result?.error, 'the run did not fail').toBeUndefined(); + // The run's real answer survives the lost bookkeeping. + expect(outcome.result?.successMessage).toBe('author success text'); + expect(outcome.result?.summary, 'the summary survives the lost history row').toBeDefined(); + expect(calls.work).toBe(1); + + // The in-memory run history tells the truth too: one `completed` row, + // not a `failed` one carrying the driver's text as the run's error. + const rows = await engine.listRuns(flowName, { limit: 10 }); + expect(rows.map(r => r.status)).toEqual(['completed']); + + // ── The secondary failure was REAL, not simulated away: no durable + // history row landed. That is the loss PIN 5 reports. + expect(await store.loadTerminal(rows[0]!.id), 'the history row genuinely did not land').toBeFalsy(); + expect(errors.length, 'and it was reported, once').toBe(1); + }); + + it('PIN 2 — `execute()`, the run-summary log line throws with NO store attached: same answer', async () => { + // The second reachable statement in the same window, and the one that + // needs no store at all — the host-injected `Logger`'s `info`, default-on. + const { engine, calls, errors, flowName } = boot({ retry: false, infoThrows: SUMMARY_LOG_FAILURE }); + + const outcome = await executeOutcome(engine, flowName); + + expect(outcome.kind).toBe('returned'); + expect(outcome.result?.success).toBe(true); + expect(outcome.result?.status).toBeUndefined(); + expect(outcome.result?.error).toBeUndefined(); + expect(outcome.result?.summary).toBeDefined(); + expect(calls.work).toBe(1); + expect((await engine.listRuns(flowName, { limit: 10 })).map(r => r.status)).toEqual(['completed']); + expect(errors.length).toBe(1); + expect(errors[0]?.message).toContain(rowIdOf(await engine.listRuns(flowName, { limit: 10 }))); + }); + + it('PIN 3 — THE SHARP ONE: under `strategy: retry`, the node runs EXACTLY ONCE', async () => { + // Unpatched, with `maxRetries: 2`: three executions of a flow that had + // already finished, three `failed` rows, and the node's side effects + // three times — unattended, inside this one call. `execute()`'s arm + // hands the false `failed` to `retryExecution`, whose loop reads + // `result.success`. + const { engine, calls, errors, flowName } = boot({ retry: true, infoThrows: SUMMARY_LOG_FAILURE }); + + const outcome = await executeOutcome(engine, flowName); + + expect(calls.work, 'a completed run is NEVER re-attempted').toBe(1); + expect(outcome.kind).toBe('returned'); + expect(outcome.result?.success, 'the attempt that completed is the answer').toBe(true); + expect(outcome.result?.status).toBeUndefined(); + expect(outcome.result?.successMessage).toBe('author success text'); + expect(outcome.result?.summary).toBeDefined(); + // One row for one run — not 1 + maxRetries rows for one logical success. + expect((await engine.listRuns(flowName, { limit: 10 })).map(r => r.status)).toEqual(['completed']); + expect(errors.length, 'one run, one report').toBe(1); + }); + + it('PIN 4 — `strategy: retry` + a synchronously throwing store: RETURNS, does not reject, runs once', async () => { + const store = new SyncThrowTerminalStore(); + const { engine, calls, errors, flowName } = boot({ retry: true, store }); + + const outcome = await executeOutcome(engine, flowName); + + expect(outcome.kind, 'the declared contract is a result, not an exception').toBe('returned'); + expect(outcome.result?.success).toBe(true); + expect(calls.work).toBe(1); + expect(errors.length).toBe(1); + }); + + it('PIN 5 — the swallowed history failure is loud: `error`, naming the run, the loss and the fix', async () => { + // ⛔ The guard must not trade a false `failed` for a silent failure. + // AGENTS.md "Degradation log levels": the terminal history row claims + // to persist and did not while every caller reads a healthy completed + // run — the judgment question answers YES, so `error`, with the + // consequence and the fix in the first line. + // + // ⚠️ And NOT a #13398-class raise: `Logger` from + // `@objectstack/spec/contracts` declares `error` as a REQUIRED member, + // so nothing is grown onto a published sink that lacks it. + const { engine, errors, flowName } = boot({ retry: false, store: new SyncThrowTerminalStore() }); + + await executeOutcome(engine, flowName); + const runId = rowIdOf(await engine.listRuns(flowName, { limit: 10 })); + + expect(errors.length, 'said ONCE per run, not once per failed write').toBe(1); + const line = errors[0]!; + expect(line.message).toContain(runId); + expect(line.message, 'the consequence: the run COMPLETED and its history row did not land') + .toMatch(/completed/i); + expect(line.message, 'and that it must not be re-run — the harm this card measured') + .toMatch(/must NOT be re-run/); + expect(line.message, 'the fix is the history failure in the meta').toMatch(/history/i); + // THIRD argument per `error(message, error?, meta?)` — the driver text + // goes to the structured slot, never into the message (#6499), and the + // `Error` slot stays empty on purpose (#5575). + expect(line.errorSlot).toBeUndefined(); + expect(JSON.stringify(line.meta)).toContain(TERMINAL_WRITE_FAILURE); + expect(line.message).not.toContain(TERMINAL_WRITE_FAILURE); + }); + + it('CONTROL — retry still retries a GENUINE node failure the full `1 + maxRetries` times', async () => { + // ⛔ The guard must narrow nothing, and this is what grades PIN 3: the + // same flow, the same policy, the same counter — a node that really + // fails still burns the whole budget. Without this control PIN 3's `1` + // could be a broken retry loop rather than a guarded history write. + const { engine, calls, errors, flowName } = boot({ + retry: true, + store: new InMemorySuspendedRunStore(), + nodeThrows: true, + }); + + const outcome = await executeOutcome(engine, flowName); + + expect(calls.work, 'attempt 1 plus every retry').toBe(1 + MAX_RETRIES); + expect(outcome.result?.success).toBe(false); + expect(outcome.result?.status, "the producer's lifecycle verdict (#9378)").toBe('failed'); + expect(outcome.result?.error).toContain(NODE_FAILURE); + expect(outcome.result?.errorMessage).toBe('author failure text'); + expect(errors, 'no history write failed ⇒ nothing to report').toEqual([]); + }); + + it('CONTROL — a GENUINE node failure is still answered `failed` with the NODE\'s own text', async () => { + // The completion-side sink is broken in exactly the way PIN 2 breaks + // it, and the node fails anyway: the node-failure arm must still be + // reached and must still say so. This is the arm the guard is often + // mistaken for widening. + const { engine, calls, errors, flowName } = boot({ + retry: false, + infoThrows: SUMMARY_LOG_FAILURE, + nodeThrows: true, + }); + + const outcome = await executeOutcome(engine, flowName); + + expect(outcome.kind).toBe('returned'); + expect(outcome.result?.success).toBe(false); + expect(outcome.result?.status).toBe('failed'); + expect(outcome.result?.error, "the NODE's text, never the history sink's").toContain(NODE_FAILURE); + expect(calls.work).toBe(1); + expect((await engine.listRuns(flowName, { limit: 10 })).map(r => r.status)).toEqual(['failed']); + expect(errors, 'the completed-path guard never fired — the run never completed').toEqual([]); + }); + + it('CONTROL — a completed run on HEALTHY sinks logs no error and lands its history row', async () => { + // The reverse control for PIN 5. If this logged too, PIN 5 would be + // measuring "the engine logs on every completed run". + const store = new InMemorySuspendedRunStore(); + const { engine, calls, errors, flowName } = boot({ retry: true, store }); + + const outcome = await executeOutcome(engine, flowName); + + expect(outcome.result?.success).toBe(true); + expect(outcome.result?.summary).toBeDefined(); + expect(calls.work).toBe(1); + expect(errors, 'no secondary failure ⇒ nothing to report').toEqual([]); + + // `recordTerminal` is fire-and-forget — let the microtask land. + await new Promise(r => setTimeout(r, 0)); + const runId = rowIdOf(await engine.listRuns(flowName, { limit: 10 })); + expect((await store.loadTerminal(runId))?.status, 'the healthy path still persists').toBe('completed'); + }); +}); + +/** The single run's id, asserted to be single so a pin can never read the wrong row. */ +function rowIdOf(rows: Array<{ id: string }>): string { + expect(rows.length, 'exactly one run').toBe(1); + return rows[0]!.id; +} From de6ece0ccf5d54f07956ef5bb0bc0a0841c4aa15 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 10 Sep 2026 22:27:42 +0000 Subject: [PATCH 2/3] chore(gates): teach check:durability-log-level the run-history seam (#16274) AGENTS.md's rule for this gate: "it cannot discover a new seam, only stop known ones from regressing; found a new one, add it to DURABILITY_CRITICAL_CALLEES in the same PR that fixes it." `recordLog` is that seam. Measured: the population goes 29 -> 33 catch seams, the four newly covered are this card's two guards plus the two the resume path already landed, all four are judged LOUD, and the gate stays green with zero unrecognised constructs. The empty shrink-only baseline stays empty. Claude-Session: https://claude.ai/code/session_01ToDPcx9AESFubJkDiFMtKW Co-authored-by: Claude --- scripts/check-durability-degradation-log-level.mjs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/scripts/check-durability-degradation-log-level.mjs b/scripts/check-durability-degradation-log-level.mjs index 87a4b617834..86378520a1e 100644 --- a/scripts/check-durability-degradation-log-level.mjs +++ b/scripts/check-durability-degradation-log-level.mjs @@ -293,6 +293,10 @@ const READ_INVENTION_BASELINE_PATH = join( * is a design call, and it is deliberately not taken here. */ const DURABILITY_CRITICAL_CALLEES = new Map([ + [ + 'recordLog', + "A run's TERMINAL history row was never written — the run itself finished and the caller was told so, so the result envelope, the HTTP status and every counter read clean while `sys_automation_run` simply has no row for it. Nothing retries the write: after the next restart the run is invisible to the Runs surfaces, `inspectStrandedRequests` reads \"no suspension + no terminal row\" as a STRANDED request and `releasePendingForTerminalRuns` reads the same hole as still-alive. The engine states the invariant this entry protects in `recordLog`'s own doc — a history write must NEVER block or break the run that produced it — so the `catch` that keeps the run alive is also the only place the loss can be reported, and a `warn` there is the one level at which an operator is never told (#15944 on the resume path, #16274 on the two initial-execution paths, where the unreported version additionally re-ran the whole flow under `errorHandling.strategy: 'retry'`).", + ], [ 'tryInsert', "A seeder's insert was refused and the helper answered `null` — the row is simply absent while the seeding pass moves on and its per-boot summary still reads clean. This is the shape #12981 was filed over: the RBAC catalog seeders swallowed refused writes in `catch { return null; }`, and a boot logged \"RBAC catalog seeded\" at `info` over zero landed rows, on a deployed plane, for weeks (#12923). The helper answers its CALLER, which reports the refusal through the #12923 accumulator; what this entry holds is that no caller may re-swallow that answer in a quiet `catch`.", From 18b177466154e1a4ac78cf5ebaa435e56d35f973 Mon Sep 17 00:00:00 2001 From: Claude Date: Thu, 10 Sep 2026 22:55:20 +0000 Subject: [PATCH 3/3] chore(gates): carry `recordLog` into the swallow-family census copy (#16274) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `measure-durability-swallow-family.mjs` keeps a deliberate by-value copy of the gate's `DURABILITY_CRITICAL_CALLEES` under `origin: 'gate-vocabulary'`, and its `--self-test=gated` reddens on drift — which it did, naming `recordLog` as "declared by the gate, missing from the copy". Its own remedy text: a name the gate gained belongs in the copy. check:swallow-census-controls: 21 copied gate-vocabulary names now match the gate's declaration, exit 0. Claude-Session: https://claude.ai/code/session_01ToDPcx9AESFubJkDiFMtKW Co-authored-by: Claude --- scripts/measure-durability-swallow-family.mjs | 1 + 1 file changed, 1 insertion(+) diff --git a/scripts/measure-durability-swallow-family.mjs b/scripts/measure-durability-swallow-family.mjs index b6c8913bf44..71349512c5c 100644 --- a/scripts/measure-durability-swallow-family.mjs +++ b/scripts/measure-durability-swallow-family.mjs @@ -328,6 +328,7 @@ const WRITE_SHAPED_CALLEES = new Map([ ['deleteMetaItemFromLoader', 'gate-vocabulary'], ['persistPackageCommitRow', 'gate-vocabulary'], ['persistSeedTenancyReceiptRow', 'gate-vocabulary'], + ['recordLog', 'gate-vocabulary'], ['runWideningAlters', 'gate-vocabulary'], ]);