Skip to content

Commit 06017ed

Browse files
claude[bot]claudeos-sales
authored
fix(automation): stop logging the degraded "child run is gone" warning on the healthy subflow up-bubble (#14827)
* wip(#14392): pin the up-bubble log branch — carried over a container restart Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01AUF1NoViznQK32gqpK8wS8 * chore(changeset): patch for the subflow up-bubble logging correction Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01AUF1NoViznQK32gqpK8wS8 --------- Co-authored-by: Claude <noreply@anthropic.com> Co-authored-by: os-sales <sales@objectstack.ai>
1 parent 7ad3d4e commit 06017ed

3 files changed

Lines changed: 170 additions & 1 deletion

File tree

Lines changed: 42 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,42 @@
1+
---
2+
"@objectstack/service-automation": patch
3+
---
4+
5+
fix(automation): the healthy subflow up-bubble no longer logs the degraded "child run is gone" warning
6+
7+
Every successful subflow completion logged, at `warn`:
8+
9+
```
10+
[automation] run 'R' is paused at subflow node 'N' but child run 'C' is gone — continuing without child output
11+
```
12+
13+
Both halves of that sentence were false on this path. The child had not gone
14+
anywhere — it had *completed*, which is the normal outcome — and the parent was
15+
continuing **with** the child's output, not without it: the very signal the
16+
engine was holding when it wrote the line already carried it.
17+
18+
The cause is that the branch keyed off a suspension lookup. A parent parked at a
19+
`subflow` node correlates to its child as `subflow:CHILDID`, and on resume the
20+
engine calls `loadSuspendedRun(CHILDID)`. That finds only **SUSPENDED** runs, so
21+
a child that finished has no suspension to find, and the miss fell through to an
22+
`else` written for the genuinely degraded case. The lookup answers "is the child
23+
still parked", which on the up-bubble is a question about nothing: the child is
24+
supposed to be finished there.
25+
26+
The branch now asks the fact the message is actually about — whether the incoming
27+
resume signal already carries the child's output, which is what the engine's own
28+
`buildSubflowResumeSignal` mints when a completed child bubbles into its parent.
29+
When it does, the run continues from the subflow node with a `debug` line naming
30+
the carried output. When there is no child run **and** no carried output, the
31+
degraded case is real and keeps its existing sentence at its existing level.
32+
33+
The engine-built marker is part of the test, not decoration: `output` is a
34+
caller-writable field and on this node a caller's signal is delegated down to the
35+
child, so matching on shape alone would let a caller's own bag silence a genuine
36+
degraded warning. Only the engine can mint that marker.
37+
38+
No behaviour changes: both branches continue the parent exactly as before, no log
39+
call site changes level, and the degraded sentence is untouched. This is a
40+
logging correctness fix — an ordinary outcome had been reported as a fault on
41+
every healthy subflow completion, which is the cry-wolf shape that trains an
42+
operator to skip the line on the one occasion it means what it says.

‎packages/services/service-automation/src/builtin/screen-resume-signal-less.test.ts‎

Lines changed: 74 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,28 @@ import { installBuiltinNodes } from './index.js';
3030
function silentLogger() {
3131
return { info() {}, warn() {}, error() {}, debug() {}, child() { return silentLogger(); } } as any;
3232
}
33+
34+
/**
35+
* A logger that RECORDS what it was told, level included — the engine's own
36+
* sink for the tests that pin a log branch. `silentLogger` discards, so a
37+
* branch can only be pinned on absence against something that keeps the calls
38+
* (#14392).
39+
*/
40+
function recordingLogger(sink: Array<{ level: string; message: string }>) {
41+
const rec = (level: string) => (message: unknown) => { sink.push({ level, message: String(message) }); };
42+
const self: any = {
43+
info: rec('info'), warn: rec('warn'), error: rec('error'), debug: rec('debug'),
44+
child() { return self; },
45+
};
46+
return self;
47+
}
48+
49+
/**
50+
* The degraded up-bubble sentence, verbatim (#14392). Asserted by CONTENT and
51+
* not by "some warn fired": the card is that this exact sentence described the
52+
* healthy path.
53+
*/
54+
const DEGRADED_SENTENCE = 'is gone — continuing without child output';
3355
function ctx() {
3456
return { logger: silentLogger(), getService() { return undefined; } } as any;
3557
}
@@ -165,9 +187,12 @@ describe('signal-less resume of a pause that declares no contract proceeds (#136
165187
describe("engine-built continuation stays exempt — the flag is the ONLY exemption (#13648 negative control)", () => {
166188
let engine: AutomationEngine;
167189
let captured: unknown[];
190+
/** #14392 — the engine's log records, so the up-bubble branch is pinnable. */
191+
let records: Array<{ level: string; message: string }>;
168192

169193
beforeEach(() => {
170-
engine = new AutomationEngine(silentLogger());
194+
records = [];
195+
engine = new AutomationEngine(recordingLogger(records));
171196
installBuiltinNodes(engine, ctx());
172197
captured = [];
173198
// Copies the screen-collected `kind` into the child's declared output.
@@ -241,6 +266,54 @@ describe("engine-built continuation stays exempt — the flag is the ONLY exempt
241266
expect(childRes.status).toBeUndefined();
242267
expect(captured).toEqual([{ result: 'escalate' }]);
243268
expect(engine.listSuspendedRuns()).toHaveLength(0);
269+
270+
// [#14392] Pinned on the BRANCH, not on the sentence. This IS the
271+
// engine-built up-bubble: `captured` one line up is the child's output
272+
// arriving in the parent, so the parent continued *with* it. The
273+
// degraded line claims the opposite and must be absent — it used to
274+
// fire here on every healthy subflow completion, because the parent's
275+
// `subflow:` correlation is looked up with `loadSuspendedRun` and a
276+
// COMPLETED child has no suspension to find.
277+
expect(records.filter((r) => r.message.includes(DEGRADED_SENTENCE))).toEqual([]);
278+
// Not silent by accident either: the healthy continuation says what it
279+
// is, once, at `debug` — never `warn`.
280+
const bubbled = records.filter((r) => r.message.includes('engine-built up-bubble signal'));
281+
expect(bubbled).toHaveLength(1);
282+
expect(bubbled[0].level).toBe('debug');
283+
expect(bubbled[0].message).toContain(child.runId);
284+
});
285+
286+
it('[#14392 positive control] the degraded line still fires when the child run is gone AND nothing carries its output', async () => {
287+
const started = await engine.execute('parent', {} as any);
288+
const parentRunId = started.runId!;
289+
const child = engine.listSuspendedRuns().find((r) => r.flowName === 'child')!;
290+
291+
// Make the child GENUINELY gone without bubbling anything up:
292+
// `cancelRun` consumes the child's continuation only, leaving this
293+
// parent parked on a `subflow:` correlation that now dangles.
294+
expect(await engine.cancelRun(child.runId, 'abandoned')).toBe(true);
295+
records.length = 0;
296+
297+
// A CALLER's signal this time — not the engine's — so nothing carries
298+
// the child's output. `kind` satisfies the child's screen, which the
299+
// parent surfaces as its own.
300+
const res = await engine.resume(parentRunId, { variables: { kind: 'escalate' } });
301+
302+
const degraded = records.filter((r) => r.message.includes(DEGRADED_SENTENCE));
303+
expect(degraded).toHaveLength(1);
304+
// The level does NOT move (#13398-class): this branch keeps `warn`.
305+
expect(degraded[0].level).toBe('warn');
306+
expect(degraded[0].message).toContain(child.runId);
307+
expect(degraded[0].message).toContain(parentRunId);
308+
// ...and no debug up-bubble line, since there was no up-bubble.
309+
expect(records.filter((r) => r.message.includes('engine-built up-bubble signal'))).toEqual([]);
310+
311+
// Behaviour unchanged: the branch still CONTINUES the parent, which is
312+
// the whole point of the `else` — downstream ran, with no subflow
313+
// output to map into `subResult`.
314+
expect(res.success).toBe(true);
315+
expect(captured).toEqual([undefined]);
316+
expect(await engine.hasSuspendedRun(parentRunId)).toBe(false);
244317
});
245318

246319
it("a signal-less resume of the CHILD is still refused — the flag exempts the engine's signal, not the run", async () => {

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

Lines changed: 54 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1037,6 +1037,31 @@ function engineBuilt(signal: ResumeSignal): ResumeSignal {
10371037
return Object.assign(signal, { [ENGINE_BUILT_SIGNAL]: true });
10381038
}
10391039

1040+
/**
1041+
* Whether an incoming resume signal ALREADY carries a completed subflow
1042+
* child's output — the engine-built up-bubble, i.e. the signal
1043+
* `bubbleToParent` builds with `buildSubflowResumeSignal` when a delegated
1044+
* child finishes and continues its parent.
1045+
*
1046+
* The discriminator for the up-bubble's log branch, and deliberately NOT "is
1047+
* the child run still there". On the up-bubble the child has COMPLETED, so its
1048+
* suspension is already consumed and the `loadSuspendedRun` miss on the
1049+
* parent's `subflow:` correlation says nothing about whether the parent
1050+
* continues with the child's output — it only says the child is not SUSPENDED.
1051+
* Branching on a second run lookup would move that same confusion one call
1052+
* over; this asks the fact the message is actually about.
1053+
*
1054+
* The engine-built marker is load-bearing, not decoration: `output` is a
1055+
* caller-writable field, and on this node the caller's signal is delegated
1056+
* DOWN to the child, so shape alone would let a caller's own bag silence the
1057+
* genuine degraded warning. Only the engine can mint the symbol.
1058+
*/
1059+
function carriesSubflowChildOutput(signal: ResumeSignal): boolean {
1060+
if ((signal as Record<symbol, unknown>)[ENGINE_BUILT_SIGNAL] !== true) return false;
1061+
const output = signal.output;
1062+
return typeof output === 'object' && output !== null && 'output' in output;
1063+
}
1064+
10401065
/**
10411066
* Variable names the flow engine owns: `$runId`, `$flowName`, `$flowLabel`,
10421067
* `$record`, `$error`, `$parentRunId`, `$parentMapNode`, `$parentOutputVariable`,
@@ -5155,7 +5180,36 @@ export class AutomationEngine implements IAutomationService {
51555180
// #4354 — down-delegation is the other way a child's work
51565181
// lands under a parent step written at suspend time.
51575182
this.creditChildRun(run.steps, run.nodeId, childRes.summary);
5183+
} else if (carriesSubflowChildOutput(signal)) {
5184+
// The engine-built UP-BUBBLE — the HEALTHY path, and the
5185+
// one this `else` used to describe as a degradation. The
5186+
// child COMPLETED and `bubbleToParent` resumed this run
5187+
// with the child's mapped output, so the miss above is the
5188+
// SUSPENSION lookup missing (a completed run has no
5189+
// suspension), not the child having disappeared, and the
5190+
// parent continues *with* the child's output — which is
5191+
// what the old sentence denied outright.
5192+
//
5193+
// `debug`, for the same reason as the lost-advance-claim
5194+
// record further down: an ordinary outcome logged at `warn`
5195+
// on every healthy subflow completion is the cry-wolf
5196+
// shape — the operator who reads "child run is gone" on
5197+
// each one stops reading the line, and the one time it
5198+
// means what it says is the time it is ignored. Nothing
5199+
// else moves: this branch continues the parent exactly as
5200+
// before, and the degraded branch below keeps its text and
5201+
// its level.
5202+
this.logger.debug(
5203+
`[automation] run '${runId}' continues from subflow node '${run.nodeId}' with the output of ` +
5204+
`completed child run '${childRunId}' — carried on the engine-built up-bubble signal ` +
5205+
`(the child's suspension is consumed, which is why it is not loadable here).`,
5206+
);
51585207
} else {
5208+
// The genuinely degraded case, and the only one the
5209+
// sentence below was ever true of: nothing suspended under
5210+
// the child id AND no carried output, so this run really
5211+
// does continue without the child's output. #4632 verdict:
5212+
// FUNCTIONAL — stays `warn`.
51595213
this.logger.warn(
51605214
`[automation] run '${runId}' is paused at subflow node '${run.nodeId}' but child run '${childRunId}' ` +
51615215
`is gone — continuing without child output`,

0 commit comments

Comments
 (0)