Skip to content

Commit 216b066

Browse files
claude[bot]claude
andauthored
fix(service-automation): a completed run is no longer answered failed — or re-executed under strategy: retry — by its own history write (#17565)
* fix(service-automation): guard the two initial-execution completion history writes (#16274) `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 <noreply@anthropic.com> * 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 <noreply@anthropic.com> * chore(gates): carry `recordLog` into the swallow-family census copy (#16274) `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 <noreply@anthropic.com> --------- Co-authored-by: Claude <noreply@anthropic.com>
1 parent d8a833d commit 216b066

5 files changed

Lines changed: 570 additions & 27 deletions

File tree

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
---
2+
"@objectstack/service-automation": patch
3+
---
4+
5+
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)
6+
7+
`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.
8+
9+
**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).
10+
11+
**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:
12+
13+
- 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.
14+
- `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`.)
15+
16+
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.
17+
18+
What changes:
19+
20+
- **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.
21+
- **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.
22+
23+
⛔ 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.

‎packages/services/service-automation/src/engine.ts‎

Lines changed: 162 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -4865,19 +4865,108 @@ export class AutomationEngine implements IAutomationService {
48654865

48664866
const durationMs = Date.now() - startTime;
48674867

4868-
// Record execution log
4869-
const logged = this.recordLog({
4870-
id: runId,
4871-
flowName,
4872-
flowVersion: flow.version,
4873-
status: 'completed',
4874-
startedAt,
4875-
completedAt: new Date().toISOString(),
4876-
durationMs,
4877-
trigger: buildRunTrigger(context),
4878-
steps,
4879-
output,
4880-
}, context);
4868+
// [#16274] THE RUN IS OVER AND IT SUCCEEDED. Everything from here
4869+
// to the return is BOOKKEEPING ABOUT that fact, and the `catch`
4870+
// below this `try` exists for NODE failures — so a throw out of the
4871+
// history write was handled as though a node had thrown: the arm
4872+
// recorded a `failed` row carrying the history driver's own text as
4873+
// the run's error and answered `status: 'failed'` for a run whose
4874+
// every node succeeded. This is the guard PR #16273 landed on
4875+
// {@link resumeInternal}'s completion path, now on the two
4876+
// INITIAL-execution paths that card deliberately scoped out — this
4877+
// one and {@link executeWithoutRetry}'s.
4878+
//
4879+
// ⚠️ MEASURED, and sharper than the report assumed: under
4880+
// `errorHandling.strategy: 'retry'` that false `failed` is handed
4881+
// to {@link retryExecution} by the strategy branch in the catch
4882+
// below, whose loop reads `result.success` — so it RE-EXECUTES a
4883+
// flow that already finished. `1 + maxRetries` runs of every node,
4884+
// unattended, inside this one call, with the side effects repeated
4885+
// each time and one `failed` history row per attempt. That is the
4886+
// DOUBLE RUN #15944 was graded sharp for, reached here with no
4887+
// operator action at all, where #15944's needed an operator to
4888+
// restore and resume.
4889+
//
4890+
// Two statements inside `recordLog` reach that catch on the
4891+
// terminal path, and neither is hypothetical:
4892+
//
4893+
// 1. the run-summary line `this.logger.info(line, meta)` — on by
4894+
// default (`runSummaryLog: 'info'`) and calling a
4895+
// HOST-INJECTED `Logger`, so it needs no store at all;
4896+
// 2. `store.recordTerminal(record)` throwing SYNCHRONOUSLY — the
4897+
// `void write.catch(...)` beneath that call only ever sees a
4898+
// returned promise's rejection (both shipped stores are
4899+
// `async` and cannot; `SuspendedRunStore` is an exported
4900+
// interface with an optional `recordTerminal`, so a host store
4901+
// is unconstrained, and one returning a non-thenable makes
4902+
// `write.catch` itself a synchronous `TypeError`). On THAT
4903+
// variant the unguarded code did not even answer `failed`: the
4904+
// catch arm's own `recordLog({ status: 'failed' })` threw again
4905+
// out of the same store and escaped `execute()` entirely,
4906+
// rejecting a promise `AutomationResult` is declared for.
4907+
//
4908+
// The guard restores the invariant `recordLog`'s own doc states —
4909+
// "a history write must NEVER block or break the run that produced
4910+
// it" — which that call was relied upon to keep and did not.
4911+
//
4912+
// ⛔ NOT a widening of anything: no exit gains a status it did not
4913+
// have, the node-failure arm below is untouched (a genuine node
4914+
// throw still lands there, still records `failed`, still retries),
4915+
// and the failure is REPORTED rather than swallowed — see the
4916+
// catch.
4917+
let logged: ExecutionLogEntry | undefined;
4918+
try {
4919+
logged = this.recordLog({
4920+
id: runId,
4921+
flowName,
4922+
flowVersion: flow.version,
4923+
status: 'completed',
4924+
startedAt,
4925+
completedAt: new Date().toISOString(),
4926+
durationMs,
4927+
trigger: buildRunTrigger(context),
4928+
steps,
4929+
output,
4930+
}, context);
4931+
} catch (bookkeeping) {
4932+
// #4632 verdict: DURABILITY, so `error` — the caller is told
4933+
// the truthful thing (the run completed), which is exactly
4934+
// what makes the rest invisible from the outside: the terminal
4935+
// history row never landed, nothing retries it, and no
4936+
// envelope carries a word about it. Consequence and fix in the
4937+
// first line, per AGENTS.md. Said ONCE per run, not once per
4938+
// failed write.
4939+
//
4940+
// ⚠️ The level is the precedent's (#16273, #15555) and is NOT
4941+
// a #13398-class raise: that ruling forbids raising a site to
4942+
// `error` where doing so means GROWING `error?` onto a
4943+
// published sink that lacks it, and this sink — `Logger` from
4944+
// `@objectstack/spec/contracts` — declares `error(message,
4945+
// error?, meta?)` as a REQUIRED member (only `fatal?`,
4946+
// `child?` and `withTrace?` are optional). Nothing is widened,
4947+
// which is also why the two precedents on this same sink could
4948+
// land `error`.
4949+
//
4950+
// THIRD argument per `error(message, error?, meta?)`; the
4951+
// `Error` slot stays empty on purpose (#5575), and the thrown
4952+
// text goes to the structured slot rather than into the
4953+
// message (#6499).
4954+
this.logger.error(
4955+
`[Automation] run '${runId}' of flow '${flowName}' COMPLETED successfully but its ` +
4956+
`run-history bookkeeping threw, so its terminal history row never landed — nothing ` +
4957+
`retries it, the caller is told the run succeeded, and after the next restart this ` +
4958+
`run is invisible to the Runs surfaces while the approvals sweeps read it as ` +
4959+
`never-finished. The run itself is COMPLETE and must NOT be re-run or retried. Fix ` +
4960+
`the history failure in this record's meta.`,
4961+
undefined,
4962+
describeThrownForLog(bookkeeping),
4963+
);
4964+
}
4965+
// [#16274] Recomputed when the guard above had to abandon
4966+
// `recordLog`: the same pure function of the same steps that
4967+
// `recordLog`'s own first statement runs, so the two spellings
4968+
// cannot disagree. Same shape as `resumeInternal`'s (#15944).
4969+
const summary = logged?.summary ?? summarizeRun(steps);
48814970

48824971
return {
48834972
success: true,
@@ -4908,7 +4997,7 @@ export class AutomationEngine implements IAutomationService {
49084997
// #4354 — hand the counts back synchronously so a caller
49094998
// (a `subflow` roll-up, a runtime test asserting the sweep wrote
49104999
// something) never has to re-read the run to learn what it did.
4911-
summary: logged.summary,
5000+
summary,
49125001
};
49135002
} catch (err: unknown) {
49145003
// A node asked to suspend the run (ADR-0019 durable pause). Snapshot
@@ -10154,18 +10243,64 @@ export class AutomationEngine implements IAutomationService {
1015410243
}
1015510244

1015610245
const durationMs = Date.now() - startTime;
10157-
const logged = this.recordLog({
10158-
id: runId,
10159-
flowName,
10160-
flowVersion: flow.version,
10161-
status: 'completed',
10162-
startedAt,
10163-
completedAt: new Date().toISOString(),
10164-
durationMs,
10165-
trigger: buildRunTrigger(context),
10166-
steps,
10167-
output,
10168-
}, context);
10246+
// [#16274] The SECOND initial-execution instance of the guard
10247+
// above in `execute()` — the retry path's own completion site, and
10248+
// the one where the consequence was measured worst. This method IS
10249+
// a retry attempt (it is only ever reached from
10250+
// {@link retryExecution}), so a `failed` answer here does not just
10251+
// mislead a caller: it is read by the loop that drives this method,
10252+
// which re-enters it for the next attempt. An attempt whose every
10253+
// node SUCCEEDED and whose only failure was its own history write
10254+
// therefore burned the rest of the budget re-running the flow,
10255+
// `1 + maxRetries` times in total, each attempt writing one more
10256+
// `failed` row for work that had already completed.
10257+
//
10258+
// ⚠️ Fixing `execute()` alone would NOT have closed that: a flow
10259+
// under `strategy: 'retry'` whose attempt 2 completes leaves
10260+
// through THIS exit and never crosses `execute()`'s again — the
10261+
// seventh instance of this method's documented drift from
10262+
// `execute()` (#9378, #9415, #9414, #9510, #9704, #9889 before it),
10263+
// and the same chokepoint discipline applies: one shape, both
10264+
// attempt paths.
10265+
//
10266+
// The reachable statements, the invariant and the #13398 reading
10267+
// are all stated at the `execute()` site; this is the same guard,
10268+
// not a second design.
10269+
let logged: ExecutionLogEntry | undefined;
10270+
try {
10271+
logged = this.recordLog({
10272+
id: runId,
10273+
flowName,
10274+
flowVersion: flow.version,
10275+
status: 'completed',
10276+
startedAt,
10277+
completedAt: new Date().toISOString(),
10278+
durationMs,
10279+
trigger: buildRunTrigger(context),
10280+
steps,
10281+
output,
10282+
}, context);
10283+
} catch (bookkeeping) {
10284+
// #4632 verdict: DURABILITY, so `error` — see the `execute()`
10285+
// site for why this is outside #13398's class. The message
10286+
// names the ATTEMPT, because the run id an operator finds in
10287+
// the Runs surfaces is this attempt's own and not the failed
10288+
// attempt's. Said ONCE per run, not once per failed write.
10289+
this.logger.error(
10290+
`[Automation] run '${runId}' of flow '${flowName}' COMPLETED successfully on a RETRY ` +
10291+
`attempt but its run-history bookkeeping threw, so its terminal history row never ` +
10292+
`landed — nothing retries it, the caller is told the run succeeded, and after the next ` +
10293+
`restart this run is invisible to the Runs surfaces while the approvals sweeps read it ` +
10294+
`as never-finished. The run itself is COMPLETE and must NOT be re-run or retried. Fix ` +
10295+
`the history failure in this record's meta.`,
10296+
undefined,
10297+
describeThrownForLog(bookkeeping),
10298+
);
10299+
}
10300+
// [#16274] The same recomputation as the `execute()` site's: one
10301+
// pure function of the same steps, so the abandoned `recordLog`
10302+
// costs the caller no counts.
10303+
const summary = logged?.summary ?? summarizeRun(steps);
1016910304

1017010305
// #4354 — a retried run reports its own attempt's counts, not the
1017110306
// failed one's: `retryExecution` returns THIS result on success.
@@ -10175,7 +10310,7 @@ export class AutomationEngine implements IAutomationService {
1017510310
// The author's completion text has to be produced here as well, or
1017610311
// `successMessage` would be a function of which attempt happened to
1017710312
// work — the same route-dependent shape the fix is removing.
10178-
return { success: true, output, durationMs, successMessage: flow.successMessage, summary: logged.summary };
10313+
return { success: true, output, durationMs, successMessage: flow.successMessage, summary };
1017910314
} catch (err: unknown) {
1018010315
// [#9510] A node asked to suspend the run (ADR-0019 durable pause)
1018110316
// — here, on a RETRY attempt, the only way this method is ever

0 commit comments

Comments
 (0)