diff --git a/.changeset/try-catch-failed-attempt-steps.md b/.changeset/try-catch-failed-attempt-steps.md new file mode 100644 index 0000000000..fc07f84816 --- /dev/null +++ b/.changeset/try-catch-failed-attempt-steps.md @@ -0,0 +1,65 @@ +--- +"@objectstack/service-automation": minor +--- + +feat(service-automation): a caught `try_catch` failure now records what failed, how many attempts ran, and which node threw (#7546) + +A caught failure used to leave **no forensic trace**. The whole run log was: + +``` +[ start, guarded_push (try_catch, success), record_failure (catch) ] +``` + +Nothing carried `regionKind: 'try'`. Nothing carried `status: 'failure'`. The +container's own step read `success`. From the log alone a caught failure was +indistinguishable from a clean run that happened to also touch the catch path — +the only evidence a failure had occurred was the catch region's side effects, +which is nothing at all when the catch is a bare notification, and worse than +nothing when the catch's own write is the thing you are trying to explain. An +operator (or an agent) reading such a log was not merely under-informed: the +most natural reading was that the try region had never run, which points at +"fix" work on a region that was behaving exactly as designed. + +The steps were never missing for a structural reason. A failing node pushes its +own `failure` step into the region's step array *before* it throws, and the +`childSteps` splice that folds region steps into the parent log has existed +since #1479 and works for every region kind that succeeds. The failed attempt's +array was simply dropped on the floor as the region unwound. + +**What changes.** `runRegion()` now hands a failed region's partial steps to the +caller through an opt-in sink before the throw propagates, tagged exactly as a +successful region's are, and `try_catch` accumulates every failed attempt across +the retry ladder and folds them into `childSteps` **ahead of** the steps of +whichever region finally succeeded. So a caught failure's log now contains, in +execution order, each failed try attempt (the throwing node's `failure` step +with its error, plus whatever the attempt got through before it) followed by the +catch handler's steps. The same applies to a ladder that recovers on a retry: +the attempts it burned are recorded rather than erased. + +Where a retry policy is declared, those steps also carry `retryAttempt` — the +zero-based attempt index — so the number of attempts is a **count** in the log +rather than something inferred from elapsed wall time. `retryAttempt` is not new +vocabulary: it has been declared on the spec's `ExecutionStepLogSchema` since +that schema was written, with exactly this meaning, and had no producer anywhere +in the engine until now. + +**What does not change.** The retry and throw semantics of `try_catch` are +untouched: the same number of attempts, the same fall-through to the catch +region, the same node-level outcome. A container that recovers still reports +`success` — giving it a distinct status such as `recovered` was considered as +part of this decision and deliberately not adopted, because the container's +contract is "the error was handled" and the forensic detail belongs in the step +log underneath it, which is what this change delivers. + +**Log volume.** A try region that retries N times now emits up to N times its +body's steps, and a retry ladder nested in a loop multiplies. Durable run +history is unaffected in shape: `compactStepLogForHistory` already caps +persisted steps and already prioritises failures and their container chains, so +the extra records land inside the existing budget rather than growing it. + +Run summaries need no special case and get more accurate. A try node that failed +twice before succeeding folds to `runs: 3, failures: 2` — all three numbers +true, and the same "worst outcome wins, `runs`/`failures` carry the nuance" rule +a loop body has always folded under. Records written by an attempt that then +threw now reach the run's `selected`/`acted` totals instead of vanishing, which +is what those counters are for. diff --git a/docs/qa/platform-checklist/areas/automation.json b/docs/qa/platform-checklist/areas/automation.json index 6d22e8450f..dd88d26011 100644 --- a/docs/qa/platform-checklist/areas/automation.json +++ b/docs/qa/platform-checklist/areas/automation.json @@ -517,10 +517,10 @@ }, { "id": "automation.flow-error-handling", - "title": "A failing node inside try_catch is handled (catch region, $error binding); outside it fails the run loudly", + "title": "A failing node inside try_catch is handled (catch region, $error binding) and the failed attempt is still recorded; outside it fails the run loudly", "since": "v16", "status": "active", - "revision": 1, + "revision": 2, "priority": "P1", "surface": "mixed", "personas": [ @@ -536,7 +536,7 @@ "steps": [ "boot showcase isolated (dogfood §0); sign in as the dev admin", "handled case: POST a showcase_task and PATCH status→'done' — showcase_resilient_sync runs, its try-region http node fails against the unroutable host, retries, then the catch region runs", - "GET /api/v1/automation/showcase_resilient_sync/runs/:runId — record overall status, the try step's status/error/regionKind, the catch step's status/regionKind, and the run duration", + "GET /api/v1/automation/showcase_resilient_sync/runs/:runId — record the overall status, the try_catch container step's own status, EVERY step carrying regionKind='try' (nodeId, status, error, retryAttempt) in log order, the catch step's status/regionKind, and the run duration", "re-read the task over /api/v1/data/showcase_task/:id — sync_status and sync_error", "unhandled case: POST /api/v1/automation a minimal autolaunched probe flow (start → http POST to the same unroutable URL, NOT wrapped in try_catch → end) in the scratch package; trigger it via POST /api/v1/automation//trigger", "GET the probe run: overall status and the run-level error", @@ -545,22 +545,28 @@ ], "acceptance": [ { - "clause": "handled: the run completes (status=completed) — the failure was absorbed by the container, not the run", + "clause": "handled: the run completes (status=completed) — the failure was absorbed by the container, not the run — and the try_catch container's OWN step reads status='success'", "oracle": "api", - "verify": "run detail: status=completed; the http step inside the try region records status=failure with regionKind='try'; the catch-region update_record step records status=success with regionKind='catch'", + "verify": "run detail: status=completed; the step whose nodeType is 'try_catch' carries status='success'. ⛔ That 'success' is BY DESIGN and is never on its own a finding: #7546 weighed giving a recovered container a distinct status (a 'recovered' vocabulary, the card's Option C) and did NOT adopt it — the container's contract is 'the error was handled', and the forensic detail lives in the step log underneath it, which is what the next clause asserts", "evidence": "run-detail read" }, { - "clause": "the caught error binds to $error and lands in data: the task carries sync_status='failed' and a non-empty sync_error message", + "clause": "the failed try attempt is RECORDED, not discarded: every attempt of the try region that failed contributes its steps to the same flat run log, tagged parentNodeId= and regionKind='try', with the throwing node's own step carrying status='failure' and a populated error {code,message} — and all of them ordered BEFORE the catch region's steps. An operator reading the run log alone can therefore answer all three of WHAT failed (the error on the failing step), WHICH node threw (that step's nodeId), and HOW MANY attempts ran (the next clause). Maintainer ruling on #7546, 2026-08-11: 'surface the failed try-region's steps … so an operator can see what failed, how many attempts ran, and which node threw', implemented over the existing #1479 childSteps splice with the retry/throw semantics of try_catch unchanged", "oracle": "api", - "verify": "task read after the run: sync_status='failed', sync_error interpolated from {$error.message}", - "evidence": "task read" + "verify": "in the run detail, the steps carrying regionKind='try' are present and non-empty; the one for the unroutable http node has status='failure' with error.message naming the connection failure; its index in the step array is lower than the catch step's. NOTE the version boundary: this contract begins with #7546 — a run captured against a framework build that predates it will legitimately show NO regionKind='try' step on a caught failure, which is the old behaviour being replaced, not a fresh defect. Record the framework revision with the result", + "evidence": "ordered step-log excerpt showing each regionKind='try' failure step and the following regionKind='catch' step" }, { - "clause": "the retry policy actually ran before the catch: the failure is not instantaneous", + "clause": "the retry ladder is countable from the log, not merely inferable from elapsed time: with a retry policy declared, each try attempt's steps carry a zero-based retryAttempt, so the number of distinct retryAttempt values equals maxRetries+1 when every attempt failed", "oracle": "api", - "verify": "the run/step duration is at least the first backoff delay (>= ~1s per backoffMs:1000), evidencing at least one retry before the catch — note this oracle's weakness (duration, not a retry counter) in the evidence", - "evidence": "durationMs from the run detail" + "verify": "collect retryAttempt across the regionKind='try' steps: for showcase_resilient_sync (retry.maxRetries=3) expect the four values 0,1,2,3, each with status='failure'. Corroborate — do not substitute — with the duration oracle: the run/step duration is at least the first backoff delay (>= ~1s per backoffMs:1000). The duration alone was this item's only retry evidence before #7546 and was explicitly recorded as a weak oracle; the counter is now the primary one and the duration is the cross-check", + "evidence": "retryAttempt values from the run detail + durationMs" + }, + { + "clause": "the caught error binds to $error and lands in data: the task carries sync_status='failed' and a non-empty sync_error message", + "oracle": "api", + "verify": "task read after the run: sync_status='failed', sync_error interpolated from {$error.message}", + "evidence": "task read" }, { "clause": "unhandled: the probe run terminates status=failed with the run-level error populated", @@ -571,7 +577,7 @@ { "clause": "both failures surface in the designer Runs panel: the failed step marked with its error message, catch-body steps nested under the container", "oracle": "screenshot", - "verify": "Runs panel screenshots for both runs — the panel renders run/step errors (string run-level, {code,message} step-level) and nests region steps", + "verify": "Runs panel screenshots for both runs — the panel renders run/step errors (string run-level, {code,message} step-level) and nests region steps; the handled run's panel now also shows the failed try attempts nested under the container alongside the catch body", "evidence": "two Runs panel screenshots" }, { @@ -583,7 +589,9 @@ ], "negative": [ "an unhandled node failure that leaves its run status=completed, or leaves the run-level error empty, is a FAIL — a dead outbound call reporting success is the inert-automation failure shape (#1887)", - "a catch region that runs when the try did NOT fail is a FAIL of the container semantics — check the catch steps are absent from a successful run" + "a catch region that runs when the try did NOT fail is a FAIL of the container semantics — check the catch steps are absent from a successful run", + "a caught failure that leaves NO forensic trace is the FAIL this item's core clause guards, and it is the exact shape #7546 fixed: a run log of only [start, (success), ] — nothing carrying regionKind='try', nothing carrying status='failure' — makes a caught failure indistinguishable from a clean run that merely touched the catch path, so the only evidence of failure is the catch's own side effects. Silence here is a regression of #7546, not a cosmetic gap", + "⛔ the try_catch container step reading status='success' after it caught a failure is NOT a finding — #7546 ruled on exactly that and kept it; re-filing it re-litigates a closed decision" ], "traps": [ "wrong-panel", @@ -592,9 +600,13 @@ "source": [ "examples/app-showcase/src/automation/flows/index.ts (ResilientSyncFlow, ADR-0031 try/catch/retry; canonical retry keys #4661)", "packages/spec/src/automation/control-flow.zod.ts (TryCatchConfigSchema)", - "packages/spec/src/automation/execution.zod.ts (ExecutionStatus 'failed'; step status/error; regionKind)", + "packages/spec/src/automation/execution.zod.ts (ExecutionStatus 'failed'; step status/error; regionKind; retryAttempt — declared since the schema was written, given its first producer by #7546)", + "packages/services/service-automation/src/engine.ts (runRegion's partialSteps sink — the failed attempt's tagged steps handed to the caller before the throw propagates; StepLogEntry.retryAttempt)", + "packages/services/service-automation/src/builtin/try-catch-node.ts (failed attempts accumulated across the retry ladder and folded into childSteps ahead of the surviving region's steps)", + "packages/services/service-automation/src/builtin/try-catch-failed-attempt-steps.test.ts (the #7546 unit pins, including 'a recovered container still reports success')", "objectui packages/app-shell/src/views/metadata-admin/previews/FlowRunsPanel.tsx (run-level string error vs step-level {code,message})", - "packages/runtime/src/route-ledger.ts (POST /automation — automation.create)" + "packages/runtime/src/route-ledger.ts (POST /automation — automation.create)", + "#7546 (maintainer ruling 2026-08-11 — surface the failed try-region's steps; Option C's 'recovered' container status NOT adopted)" ], "history": [ { @@ -602,6 +614,12 @@ "date": "2026-08-07", "change": "initial — splits handled (try_catch) vs unhandled failure into one contrast item with API + panel + log oracles", "ref": "claude/platform-test-checklist-ocwugl" + }, + { + "revision": 2, + "date": "2026-08-11", + "change": "recorded the #7546 ruling. The handled-case clause asserted that the try-region's failing step appears with regionKind='try' — a contract the engine had never promised, so QA run #7516 read a by-design silence as a FAIL. Rather than weaken the clause to match the engine, the ruling implemented it: failed try attempts are now surfaced. The clause set is re-cut accordingly — container 'success' pinned as by-design (Option C's 'recovered' status was considered and rejected), the failed-attempt steps promoted to their own clause with the ordering requirement, and the retry evidence upgraded from the weak duration oracle to a retryAttempt count with duration as cross-check. The negative now names post-#7546 silence as the regression shape and forbids re-filing the container's 'success'", + "ref": "#7546 (ruling 2026-08-11; QA run #7516; #1479 splice plumbing)" } ] }, diff --git a/packages/services/service-automation/src/builtin/try-catch-failed-attempt-steps.test.ts b/packages/services/service-automation/src/builtin/try-catch-failed-attempt-steps.test.ts new file mode 100644 index 0000000000..5130bc8c36 --- /dev/null +++ b/packages/services/service-automation/src/builtin/try-catch-failed-attempt-steps.test.ts @@ -0,0 +1,267 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +import { describe, it, expect, beforeEach } from 'vitest'; +import { AutomationEngine } from '../engine.js'; +import type { NodeExecutor, StepLogEntry } from '../engine.js'; +import { summarizeRun } from '../run-summary.js'; +import { registerTryCatchNode } from './try-catch-node.js'; + +/** + * #7546 — a caught `try_catch` failure used to leave NO forensic trace. + * + * The run log of a caught failure was exactly: + * + * [ start, guarded_push (try_catch, success), record_failure (catch) ] + * + * Nothing carried `regionKind: 'try'`. Nothing carried `status: 'failure'`. + * The container's own step read `success`. From the log alone a caught failure + * was indistinguishable from a clean run that happened to also touch the catch + * path — the only evidence a failure had occurred was the catch's side effects, + * which is nothing at all when the catch is a bare notification, and worse than + * nothing when the catch's own write is the thing you are trying to explain. + * + * The steps were never missing for a structural reason: a failing node pushes + * its own `failure` step into the region's array *before* it throws, and the + * #1479 `childSteps` splice already carries region steps into the parent log. + * The failed attempt's array was simply dropped on the floor as the region + * unwound. These tests pin the three questions the ruling names — WHAT failed, + * HOW MANY attempts ran, WHICH node threw — as answerable from the run log + * alone, plus the semantics that must NOT have moved to get there. + * + * Maintainer ruling, 2026-08-11 (issue #7546): surface the failed try-region's + * steps; the existing #1479 splice plumbing is the vehicle; **retry/throw + * semantics of `try_catch` are unchanged**. Option C's `recovered` container + * status was explicitly NOT adopted — a container that recovers still reports + * `success`, and the test named "a recovered container still reports success" + * below is the pin that keeps it that way. + */ + +function silentLogger(): any { + return { info() {}, warn() {}, error() {}, debug() {}, child() { return silentLogger(); } }; +} +function ctx(): any { + return { logger: silentLogger(), getService() { throw new Error('none'); } }; +} + +describe('#7546 failed try-region attempts surface in the run log', () => { + let engine: AutomationEngine; + let attempts: number; + + beforeEach(() => { + engine = new AutomationEngine(silentLogger()); + attempts = 0; + registerTryCatchNode(engine, ctx()); + + engine.registerNodeExecutor({ + type: 'ok', + async execute() { return { success: true }; }, + } as NodeExecutor); + + // Always fails. + engine.registerNodeExecutor({ + type: 'boom', + async execute() { return { success: false, error: 'kaboom' }; }, + } as NodeExecutor); + + // Fails the first `failTimes` calls, then succeeds. + engine.registerNodeExecutor({ + type: 'flaky', + async execute(node) { + attempts++; + const failTimes = Number((node.config as any)?.failTimes ?? 0); + if (attempts <= failTimes) return { success: false, error: `transient ${attempts}` }; + return { success: true }; + }, + } as NodeExecutor); + + // Writes rows and THEN fails — for the run-summary metrics fold. + engine.registerNodeExecutor({ + type: 'partial_write', + async execute() { + return { success: false, error: 'died mid-write', metrics: { selected: 5, acted: 2 } }; + }, + } as NodeExecutor); + + engine.registerNodeExecutor({ + type: 'handler', + async execute() { return { success: true }; }, + } as NodeExecutor); + }); + + const tcFlow = (tcConfig: Record) => ({ + name: 'tc_flow', + label: 'TryCatch Flow', + type: 'autolaunched' as const, + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'tc', type: 'try_catch', label: 'Guarded', config: tcConfig }, + { id: 'after', type: 'ok', label: 'After' }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'tc' }, + { id: 'e2', source: 'tc', target: 'after' }, + { id: 'e3', source: 'after', target: 'end' }, + ], + }); + + /** Run `tc_flow` and hand back its flat step log. */ + async function runSteps(tcConfig: Record): Promise { + engine.registerFlow('tc_flow', tcFlow(tcConfig)); + await engine.execute('tc_flow'); + const runs = await engine.listRuns('tc_flow'); + return runs[0].steps; + } + + it('records WHAT failed and WHICH node threw — the failing try node appears tagged regionKind=try with its error', async () => { + const steps = await runSteps({ + try: { nodes: [{ id: 't', type: 'boom', label: 'T' }], edges: [] }, + catch: { nodes: [{ id: 'c', type: 'handler', label: 'C' }], edges: [] }, + }); + + const failed = steps.filter(s => s.status === 'failure'); + expect(failed).toHaveLength(1); + expect(failed[0]).toMatchObject({ + nodeId: 't', + nodeType: 'boom', + status: 'failure', + parentNodeId: 'tc', + regionKind: 'try', + }); + // The error rides along — "what failed" is answerable, not just "something did". + expect(failed[0].error?.message).toContain('kaboom'); + + // …and it is ordered BEFORE the catch handler's step, because it happened first. + const failedIdx = steps.findIndex(s => s.nodeId === 't'); + const catchIdx = steps.findIndex(s => s.nodeId === 'c'); + expect(failedIdx).toBeGreaterThan(-1); + expect(catchIdx).toBeGreaterThan(failedIdx); + expect(steps[catchIdx]).toMatchObject({ regionKind: 'catch', status: 'success' }); + }); + + it('records HOW MANY attempts ran — one tagged try step per attempt, indexed by retryAttempt', async () => { + const steps = await runSteps({ + try: { nodes: [{ id: 't', type: 'flaky', label: 'T', config: { failTimes: 99 } }], edges: [] }, + catch: { nodes: [{ id: 'c', type: 'handler', label: 'C' }], edges: [] }, + retry: { maxRetries: 2, backoffMs: 0 }, + }); + + const trySteps = steps.filter(s => s.regionKind === 'try'); + // initial + 2 retries = 3 attempts, every one of them recorded. + expect(trySteps).toHaveLength(3); + expect(trySteps.map(s => s.retryAttempt)).toEqual([0, 1, 2]); + expect(trySteps.every(s => s.status === 'failure')).toBe(true); + expect(trySteps.map(s => s.error?.message)).toEqual([ + expect.stringContaining('transient 1'), + expect.stringContaining('transient 2'), + expect.stringContaining('transient 3'), + ]); + // The engine really did run it three times — the log now agrees with reality. + expect(attempts).toBe(3); + }); + + it('surfaces the whole partial attempt, not only the throwing node', async () => { + // t1 succeeds, t2 throws. Both are part of what the failed attempt DID. + const steps = await runSteps({ + try: { + nodes: [ + { id: 't1', type: 'ok', label: 'T1' }, + { id: 't2', type: 'boom', label: 'T2' }, + ], + edges: [{ id: 'te', source: 't1', target: 't2' }], + }, + catch: { nodes: [{ id: 'c', type: 'handler', label: 'C' }], edges: [] }, + }); + + const trySteps = steps.filter(s => s.regionKind === 'try'); + expect(trySteps.map(s => [s.nodeId, s.status])).toEqual([ + ['t1', 'success'], + ['t2', 'failure'], + ]); + // Every surfaced step still nests under its container, so the Runs panel can + // group them exactly as it groups a successful region's steps. + expect(trySteps.every(s => s.parentNodeId === 'tc')).toBe(true); + }); + + it('surfaces the failed attempts of a ladder that eventually SUCCEEDS, ahead of the successful one', async () => { + const steps = await runSteps({ + try: { nodes: [{ id: 't', type: 'flaky', label: 'T', config: { failTimes: 2 } }], edges: [] }, + retry: { maxRetries: 3, backoffMs: 0 }, + }); + + const trySteps = steps.filter(s => s.regionKind === 'try'); + expect(trySteps.map(s => [s.retryAttempt, s.status])).toEqual([ + [0, 'failure'], + [1, 'failure'], + [2, 'success'], + ]); + // No catch region was declared and none was needed — the ladder recovered. + expect(steps.some(s => s.regionKind === 'catch')).toBe(false); + }); + + it('a recovered container still reports success — the ruling did NOT adopt a new container status', async () => { + const steps = await runSteps({ + try: { nodes: [{ id: 't', type: 'boom', label: 'T' }], edges: [] }, + catch: { nodes: [{ id: 'c', type: 'handler', label: 'C' }], edges: [] }, + }); + + const container = steps.find(s => s.nodeId === 'tc'); + expect(container?.status).toBe('success'); + expect(container?.nodeType).toBe('try_catch'); + // Downstream still ran — the failure was absorbed by the container, not the run. + expect(steps.some(s => s.nodeId === 'after' && s.status === 'success')).toBe(true); + }); + + it('tags no attempt index when no retry policy is declared — presence of retryAttempt is itself the signal', async () => { + const steps = await runSteps({ + try: { nodes: [{ id: 't', type: 'boom', label: 'T' }], edges: [] }, + catch: { nodes: [{ id: 'c', type: 'handler', label: 'C' }], edges: [] }, + }); + + const tryStep = steps.find(s => s.regionKind === 'try'); + expect(tryStep?.status).toBe('failure'); + expect(tryStep?.retryAttempt).toBeUndefined(); + }); + + it('a clean run stays clean — no phantom try-failure steps when nothing failed', async () => { + const steps = await runSteps({ + try: { nodes: [{ id: 't', type: 'ok', label: 'T' }], edges: [] }, + catch: { nodes: [{ id: 'c', type: 'handler', label: 'C' }], edges: [] }, + }); + + expect(steps.filter(s => s.status === 'failure')).toHaveLength(0); + const trySteps = steps.filter(s => s.regionKind === 'try'); + expect(trySteps.map(s => [s.nodeId, s.status])).toEqual([['t', 'success']]); + // The negative the checklist item guards: catch must not run when try succeeds. + expect(steps.some(s => s.regionKind === 'catch')).toBe(false); + }); + + it('the run-summary fold counts retried attempts truthfully and needs no special case (P4)', async () => { + const steps = await runSteps({ + try: { nodes: [{ id: 't', type: 'flaky', label: 'T', config: { failTimes: 2 } }], edges: [] }, + retry: { maxRetries: 3, backoffMs: 0 }, + }); + + const summary = summarizeRun(steps); + const node = summary.nodes.find(n => n.nodeId === 't'); + // The node really did run three times and really did fail twice. `runs` and + // `failures` carry the nuance, exactly as they do for a loop body. + expect(node).toMatchObject({ runs: 3, failures: 2, status: 'failure' }); + // The container is one run, not three, and carries no metrics of its own. + expect(summary.nodes.find(n => n.nodeId === 'tc')).toMatchObject({ runs: 1, failures: 0 }); + }); + + it('a partial write inside an abandoned attempt now reaches the run totals instead of vanishing', async () => { + const steps = await runSteps({ + try: { nodes: [{ id: 't', type: 'partial_write', label: 'T' }], edges: [] }, + catch: { nodes: [{ id: 'c', type: 'handler', label: 'C' }], edges: [] }, + }); + + const summary = summarizeRun(steps); + // Rows the abandoned attempt really did touch (#4354 keeps metrics on a + // failure step); before #7546 the whole step was discarded, so `acted` read + // 0 for a run that had in fact written 2 records. + expect(summary.selected).toBe(5); + expect(summary.acted).toBe(2); + }); +}); diff --git a/packages/services/service-automation/src/builtin/try-catch-node.ts b/packages/services/service-automation/src/builtin/try-catch-node.ts index bf497e402b..c683c3f63e 100644 --- a/packages/services/service-automation/src/builtin/try-catch-node.ts +++ b/packages/services/service-automation/src/builtin/try-catch-node.ts @@ -4,7 +4,7 @@ import type { PluginContext } from '@objectstack/core'; import { defineActionDescriptor, TryCatchConfigSchema } from '@objectstack/spec/automation'; import type { TryCatchConfigParsed } from '@objectstack/spec/automation'; import type { AutomationContext } from '@objectstack/spec/contracts'; -import type { AutomationEngine } from '../engine.js'; +import type { AutomationEngine, StepLogEntry } from '../engine.js'; import { parseNodeConfig } from './parse-config.js'; /** @@ -25,6 +25,16 @@ import { parseNodeConfig } from './parse-config.js'; * - `try` exhausts retries and there is **no** `catch` (or `catch` itself * fails) → the node fails, surfacing to the flow's fault edge / error handling. * + * What the RUN LOG records (#7546) is a separate question from those outcomes, + * and the two must not be conflated. Every **failed** try attempt now + * contributes its steps to `childSteps`, tagged `regionKind: 'try'` (and + * `retryAttempt: ` when a retry policy is declared), ahead of the steps of + * whichever region finally succeeded. So a recovered container still reports + * `success` — that model is unchanged and deliberately so — while the log + * underneath it now answers the three questions it previously could not: WHAT + * failed (the failing node's own `failure` step, with its error), HOW MANY + * attempts ran (count the distinct `retryAttempt` values), and WHICH node threw. + * * This is the low-code-native error model — the same `fault` + exponential- * backoff retry the engine already implements, surfaced as a construct rather * than BPMN boundary events. @@ -95,22 +105,56 @@ export function registerTryCatchNode(engine: AutomationEngine, ctx: PluginContex const useJitter = retry?.jitter === true; // Run the try region, retrying with exponential backoff up to maxRetries. + // + // #7546: every FAILED attempt's steps accumulate here and ride out on + // `childSteps` ahead of whatever ultimately succeeded. Before this, they + // were discarded in the `catch (err)` arm below and a caught failure left + // no forensic trace: the container's own step read `success`, no step + // carried `regionKind: 'try'`, none carried `status: 'failure'`, and the + // only evidence a failure had occurred was the catch region's side + // effects. An operator (or an agent) reading such a log was not merely + // under-informed — the log pointed at the wrong conclusion, namely that + // the try region had never run. + // + // Retry/throw semantics are UNCHANGED by this: the loop still retries the + // same number of times, still falls through to the same catch, and the + // container still reports `success` when it recovers. Only the record of + // what happened changes. let lastError = 'unknown error'; + const failedAttemptSteps: StepLogEntry[] = []; for (let attempt = 0; attempt <= maxRetries; attempt++) { if (attempt > 0) { let delay = Math.min(baseDelay * Math.pow(multiplier, attempt - 1), maxDelay); if (useJitter) delay = delay * (0.5 + Math.random() * 0.5); if (delay > 0) await new Promise(r => setTimeout(r, delay)); } + // Sink for THIS attempt's partial steps, filled by `runRegion` only if + // the attempt throws (#7546). + const attemptSteps: StepLogEntry[] = []; try { // #1479: surface the successful try region's steps. - const trySteps = await engine.runRegion(tryRegion, variables, ctxOrEmpty, { - parentNodeId: node.id, - regionKind: 'try', - }); - return { success: true, output: { attempts: attempt + 1, caught: false }, childSteps: trySteps }; + const trySteps = await engine.runRegion( + tryRegion, + variables, + ctxOrEmpty, + { + parentNodeId: node.id, + regionKind: 'try', + // Only tag the attempt index when a retry ladder is actually + // declared: on a plain `try_catch` every step would carry a + // constant `retryAttempt: 0`, which is noise rather than signal. + ...(maxRetries > 0 ? { retryAttempt: attempt } : {}), + }, + attemptSteps, + ); + return { + success: true, + output: { attempts: attempt + 1, caught: false }, + childSteps: [...failedAttemptSteps, ...trySteps], + }; } catch (err) { lastError = err instanceof Error ? err.message : String(err); + failedAttemptSteps.push(...attemptSteps); } } @@ -126,7 +170,10 @@ export function registerTryCatchNode(engine: AutomationEngine, ctx: PluginContex return { success: true, output: { attempts: maxRetries + 1, caught: true, error: lastError }, - childSteps: catchSteps, + // #7546: the failed attempts come FIRST — they happened first, and + // the run log is ordered. The catch handler's steps read as the + // response to them rather than as the whole story. + childSteps: [...failedAttemptSteps, ...catchSteps], }; } catch (catchErr) { const catchMsg = catchErr instanceof Error ? catchErr.message : String(catchErr); @@ -134,7 +181,12 @@ export function registerTryCatchNode(engine: AutomationEngine, ctx: PluginContex } } - // No catch handler — surface the failure to the flow's fault edge / error handling. + // No catch handler — surface the failure to the flow's fault edge / error + // handling. No `childSteps` here on purpose: the engine splices them only + // on a SUCCESSFUL node result, so attaching them to a failing one would + // be dead weight. That path is not the gap #7546 closes either — an + // unhandled failure already terminates the run `failed` with both + // run-level and step-level errors, which is loud by construction. return { success: false, error: `try_catch '${node.id}': try region failed — ${lastError}` }; }, }); diff --git a/packages/services/service-automation/src/engine.ts b/packages/services/service-automation/src/engine.ts index 400f423545..5f0b4a0d33 100644 --- a/packages/services/service-automation/src/engine.ts +++ b/packages/services/service-automation/src/engine.ts @@ -688,6 +688,21 @@ export interface StepLogEntry { iteration?: number; /** Which region kind the step ran in: `loop-body` | `parallel-branch` | `try` | `catch`. */ regionKind?: string; + /** + * #7546: zero-based `try_catch` attempt this step ran in — `0` is the first + * try, `1` the first retry. Set only on `try`-region steps, and only by a + * container that actually retries, so its presence is itself the signal + * that a retry ladder ran. + * + * Not new vocabulary: `retryAttempt` has been declared on the spec's + * `ExecutionStepLogSchema` since the schema was written, with exactly this + * meaning ("Retry attempt number (0 = first try)") and — until now — no + * producer anywhere in the engine. Surfacing failed attempts (#7546) is + * what finally gives the declared key a writer, which is the direction + * declared-=-enforced asks for: consume the existing declaration rather + * than invent a second spelling beside it. + */ + retryAttempt?: number; /** * #4354: records this step read / wrote, copied from * {@link NodeExecutionResult.metrics}. Folded into the run summary. @@ -5362,9 +5377,27 @@ export class AutomationEngine implements IAutomationService { * so the calling container node can fold them into the parent run log via * `NodeExecutionResult.childSteps`. Tagging only fills fields left undefined, * so when regions nest, each step keeps its **innermost** container's - * `parentNodeId` / `iteration` / `regionKind`. On failure the region throws - * as before (preserving `try_catch` retry semantics); a failed attempt's - * partial steps are not surfaced. + * `parentNodeId` / `iteration` / `regionKind` / `retryAttempt`. + * + * #7546: a region that FAILS still throws — the `try_catch` retry/throw + * semantics are untouched — but its partial steps are no longer discarded. + * They are tagged exactly like a successful region's and handed to the + * caller through the `partialSteps` sink before the throw propagates, so a + * container that recovers from the failure can still fold them into the run + * log. Until this, a caught failure left NO trace at all: the container's + * own step read `success`, nothing carried `regionKind: 'try'`, nothing + * carried `status: 'failure'`, and an operator could not tell what failed, + * how many attempts ran, or which node threw — the only evidence a failure + * had happened was the catch region's side effects. The steps always + * existed (a failing node pushes its own `failure` step into the region's + * array before it throws); they were simply dropped on the floor when the + * region unwound. + * + * A sink rather than a return value because the failure path's contract is + * still "throw": handing the steps back through the exception would either + * change what callers catch or require a bespoke error type, and both are + * larger seams than an out-parameter the two callers that want it opt into. + * Callers that do not pass a sink (`loop`, `parallel`) are unaffected. * * Durable pause (`suspend`) inside a region is not supported in this * iteration — it is converted into a clear error (mirrors the `subflow` @@ -5374,7 +5407,8 @@ export class AutomationEngine implements IAutomationService { region: FlowRegionParsed, variables: Map, context: AutomationContext, - grouping?: { parentNodeId: string; iteration?: number; regionKind?: string }, + grouping?: { parentNodeId: string; iteration?: number; regionKind?: string; retryAttempt?: number }, + partialSteps?: StepLogEntry[], ): Promise { const entryId = findRegionEntry(region); const entry = region.nodes.find(n => n.id === entryId); @@ -5384,28 +5418,39 @@ export class AutomationEngine implements IAutomationService { // A synthetic flow view — executeNode/traverseNext only read `nodes`/`edges`. const subFlow = { nodes: region.nodes, edges: region.edges ?? [] } as unknown as FlowParsed; const regionSteps: StepLogEntry[] = []; - try { - await this.executeNode(entry, subFlow, variables, context, regionSteps); - } catch (err) { - if (isSuspendSignal(err)) { - throw new Error( - `durable pause inside a structured region (node '${err.nodeId}') is not supported`, - ); - } - throw err; - } // Tag this region's steps with their immediate container. Innermost wins: // a step that already carries a `parentNodeId` (set by a nested region) - // is left untouched. - if (grouping) { + // is left untouched. Shared by the success and failure paths (#7546) so + // a failed attempt's steps are indistinguishable in SHAPE from a + // successful one's — they differ only in their own `status`. + const tag = (): void => { + if (!grouping) return; for (const step of regionSteps) { if (step.parentNodeId === undefined) { step.parentNodeId = grouping.parentNodeId; if (grouping.iteration !== undefined) step.iteration = grouping.iteration; if (grouping.regionKind !== undefined) step.regionKind = grouping.regionKind; + if (grouping.retryAttempt !== undefined) step.retryAttempt = grouping.retryAttempt; } } + }; + try { + await this.executeNode(entry, subFlow, variables, context, regionSteps); + } catch (err) { + // #7546: surface what the failed attempt DID get through before + // rethrowing. Tagged first so the caller receives finished records, + // and pushed into the caller's sink rather than returned because + // this path's contract is (still) to throw. + tag(); + partialSteps?.push(...regionSteps); + if (isSuspendSignal(err)) { + throw new Error( + `durable pause inside a structured region (node '${err.nodeId}') is not supported`, + ); + } + throw err; } + tag(); return regionSteps; } diff --git a/packages/services/service-automation/src/run-summary.ts b/packages/services/service-automation/src/run-summary.ts index cc6afe3f7a..b6b13a7169 100644 --- a/packages/services/service-automation/src/run-summary.ts +++ b/packages/services/service-automation/src/run-summary.ts @@ -22,6 +22,25 @@ import type { StepLogEntry } from './engine.js'; * metrics, so nothing is double-counted. Per-node entries fold across * executions: a body node that ran 30 times is ONE entry with `runs: 30`. * + * #7546 added a fourth source of body steps — the FAILED attempts of a + * `try_catch` try region, which used to be discarded — and the fold needs no + * special case for them, which is worth stating because the obvious worry is + * that it does. A try-region node that failed twice before succeeding now folds + * to `runs: 3, failures: 2, status: 'failure'`, and every one of those numbers + * is the truth: the node really did execute three times and really did fail + * twice. That is the same "worst outcome wins, `runs`/`failures` carry the + * nuance" rule a `loop` body has always folded under (see below) — a retry + * ladder is just another way for one node to run more than once. The node-level + * `failure` does NOT propagate to the run, whose status is decided elsewhere + * from the run's own outcome, so a container that recovered still yields a + * completed run. + * + * The `selected` / `acted` metrics get strictly MORE accurate, not less: a node + * that wrote rows and then threw carries its counts on its `failure` step + * (#4354), so a partial write inside an abandoned attempt now reaches the run's + * totals instead of vanishing — and a partial write that really happened is + * exactly what `acted` is supposed to count. + * * `subflow` is the one exception, and it is deliberate: a child run's steps live * in the child's own log, so the `subflow` node reports the child's totals as * its own metrics. The parent therefore answers "what did this run cause",