Skip to content

Commit 229d29e

Browse files
os-zhuangclaude
andauthored
fix(automation): keep a wait timer's one-shot armed when the shot never consumed the pause (#5529) (#5549)
`engine.resume()` reports failure by RETURNING a code, not by throwing, so the timer callback's unconditional `finally` could not tell a shot that consumed the pause from one that missed. On `STORE_UNAVAILABLE` — the durable suspended-run store unreadable, which per #4420 must never read as "no such run" — the pause survived but its only wake-up job cancelled itself, so nothing woke that run until the next process start's overdue re-arm. The one-shot now settles on the return code: `STORE_UNAVAILABLE` keeps the job armed and reports the degradation at `error` (the path was previously silent); success, `RESUME_IN_PROGRESS`, machine-state failures and thrown errors cancel exactly as before. Measured, not assumed: a `once` schedule is a single `setTimeout` in `IntervalJobAdapter`, so surviving is not a retry. It keeps the `sys_job` row `active` with its deadline and keeps the registration `trigger()`-able, which is a no-restart remedy the log line names; a cancel destroys both. Both arming sites now share one handler so they cannot drift, the same reason `waitTimerJobName` is one declaration. Separate from #5512's `onSuspensionReleased`, which answers the RUN-side question. Claude-Session: https://claude.ai/code/session_01BWS4heBoAitLmzCLhcYdbK Co-authored-by: Claude <noreply@anthropic.com>
1 parent c637387 commit 229d29e

3 files changed

Lines changed: 391 additions & 39 deletions

File tree

Lines changed: 46 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,46 @@
1+
---
2+
"@objectstack/service-automation": patch
3+
---
4+
5+
fix(automation): a wait node's timer wake-up no longer disarms itself when the store outage means it never woke the run (#5529)
6+
7+
A timer `wait` arms one job to wake its run. That job used to disarm itself in an
8+
unconditional `finally` — and `AutomationEngine.resume()` reports failure by
9+
**returning** a code rather than throwing, so "this shot consumed the pause" and
10+
"this shot missed" were indistinguishable to that `finally`. Both were cancelled.
11+
12+
On `STORE_UNAVAILABLE` that was a durability hole. The durable suspended-run
13+
store being unreadable does **not** mean the run is gone (#4420 draws exactly
14+
that line): the pause was never consumed, the run is still parked at its wait
15+
node, and its row is still there — but the one job that was ever going to wake it
16+
had just retired itself. Nothing then woke that run until the next process start,
17+
where `rearmSuspendedWaitTimers` picks it up as overdue. A store that wobbled for
18+
the one moment the deadline landed, plus no restart, meant a run parked forever.
19+
20+
The one-shot now settles on the resume's return code:
21+
22+
- **`STORE_UNAVAILABLE`** — the job stays armed, and the degradation is reported
23+
at `error` (this path was previously silent — the result was discarded without
24+
even a `warn`). The line names the job, the run, and both remedies.
25+
- **everything else** — cancelled exactly as before: success consumed the pause,
26+
`RESUME_IN_PROGRESS` means a concurrent resume is consuming it, a machine-state
27+
failure means there is no pause left to serve, and a thrown error is not a
28+
store outage.
29+
30+
Keeping the job armed is **not** self-healing, and the log line says so rather
31+
than implying a retry: a `once` schedule is a single `setTimeout`, so it never
32+
re-fires on its own. What survival buys is the two things `cancel` destroys — the
33+
`sys_job` row stays `active` with its deadline (true, here: the run really is
34+
still waiting) instead of flipping to `active: false` and reading as "this
35+
wake-up is done", and the registration stays in the job service, so
36+
`trigger('flow-wait:<runId>:<nodeId>')` re-fires that wake-up once the store is
37+
back **without a restart**. After a cancel, `trigger` reports the job as not
38+
found and a restart is the only path left.
39+
40+
Both sites that arm this job — the wait node's own arming path and the cold-boot
41+
re-arm — now share one handler, so they cannot drift, the same reason the job's
42+
name is a single declaration. This is separate from the `onSuspensionReleased`
43+
teardown added in #5512 and does not replace it: that one fires when the **run**
44+
leaves the node, this one when the **job** has had its single shot.
45+
46+
No authoring surface changes; no flow needs editing.

packages/services/service-automation/src/builtin/wait-node.test.ts

Lines changed: 216 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -277,6 +277,222 @@ describe('wait timer teardown when the pause ends another way (#5512)', () => {
277277
});
278278
});
279279

280+
/**
281+
* The other half of "when may the one-shot disarm itself?" (#5529).
282+
*
283+
* #5512 gave the RUN-side question a hook (`onSuspensionReleased` — the pause
284+
* ended, so drop the job). The JOB-side question stayed in the timer callback's
285+
* `finally`, and that `finally` read nothing: `engine.resume()` reports failure
286+
* by RETURNING a code, so a shot that consumed the pause and a shot that missed
287+
* it looked identical, and both were cancelled. On `STORE_UNAVAILABLE` — the
288+
* durable store unreadable, so per #4420 the pause is emphatically NOT gone —
289+
* that cancelled the only thing left that would ever wake the run.
290+
*
291+
* Reachability is not equal across the two sites, and these tests are built to
292+
* say so rather than to look symmetric: `resumeInternal` reads the durable store
293+
* only on a hot-cache MISS, and a run that paused in this process stays cached
294+
* for the life of its suspension. So the end-to-end specimen below is the
295+
* **re-arm** callback (fresh process, empty cache, store consulted for real);
296+
* the arming callback's branch is latent by construction and is pinned at the
297+
* handler level, with the code injected rather than provoked.
298+
*/
299+
describe('wait timer one-shot vs. a shot that never consumed the pause (#5529)', () => {
300+
/** A logger that keeps its `error` lines so the diagnostic can be asserted. */
301+
function capturingLogger() {
302+
const errors: string[] = [];
303+
const logger = {
304+
info() {}, warn() {}, debug() {},
305+
error(msg: string) { errors.push(msg); },
306+
child() { return logger; },
307+
} as any;
308+
return { logger, errors };
309+
}
310+
311+
/**
312+
* A durable store that is fully working except that `load` — the read
313+
* `resumeInternal` makes on a cache miss — is unreachable. Everything else
314+
* delegates, so the underlying rows stay inspectable: that is how these tests
315+
* prove the pause SURVIVED the failed shot instead of assuming it.
316+
*/
317+
function storeWithUnreadableLoad(inner: InMemorySuspendedRunStore) {
318+
return {
319+
inner,
320+
async save(run: any) { return inner.save(run); },
321+
async load(_runId: string): Promise<any> { throw new Error('connection refused'); },
322+
async delete(runId: string) { return inner.delete(runId); },
323+
async list() { return inner.list(); },
324+
};
325+
}
326+
327+
const config = { eventType: 'timer', timerDuration: 'P1D' };
328+
329+
/**
330+
* Suspend a run in "process 1", then cold-boot "process 2" whose durable
331+
* `load` is broken, and let its re-arm pass re-schedule the wake-up. Returns
332+
* the re-armed job so a test can fire it.
333+
*/
334+
async function coldBootWithBrokenLoad() {
335+
const inner = new InMemorySuspendedRunStore();
336+
const boot1 = fakeJobCtx();
337+
const e1 = new AutomationEngine(silentLogger());
338+
e1.registerNodeExecutor(markerExecutor([]));
339+
registerWaitNode(e1, boot1.ctx);
340+
e1.setSuspendedRunStore(inner);
341+
e1.registerFlow('wait_flow', waitFlow(config));
342+
const paused = await e1.execute('wait_flow');
343+
expect(paused.status).toBe('paused');
344+
345+
// Process 2: same durable rows, but the resume-time read fails.
346+
const broken = storeWithUnreadableLoad(inner);
347+
const boot2 = fakeJobCtx();
348+
const ran: string[] = [];
349+
const e2 = new AutomationEngine(silentLogger());
350+
e2.registerNodeExecutor(markerExecutor(ran));
351+
registerWaitNode(e2, boot2.ctx);
352+
e2.setSuspendedRunStore(broken as any);
353+
e2.registerFlow('wait_flow', waitFlow(config));
354+
355+
const { logger, errors } = capturingLogger();
356+
const job = boot2.ctx.getService('job') as IJobService;
357+
// The deadline is +24h, so the re-arm re-schedules rather than resuming now.
358+
expect(await rearmSuspendedWaitTimers(e2, broken as any, job, logger)).toBe(1);
359+
expect(boot2.scheduled).toHaveLength(1);
360+
expect(boot2.cancelled).toEqual([]);
361+
362+
return { paused, inner, boot2, ran, errors, jobName: `flow-wait:${paused.runId}:pause` };
363+
}
364+
365+
it('re-arm path: a STORE_UNAVAILABLE shot leaves the one-shot ARMED', async () => {
366+
const { paused, inner, boot2, ran, jobName } = await coldBootWithBrokenLoad();
367+
368+
// The deadline arrives and the wake-up fires — into an unreachable store.
369+
await boot2.scheduled[0].handler({ jobId: jobName });
370+
371+
// The pause was never consumed: the run is still parked, its row still there.
372+
expect(ran).toEqual([]);
373+
expect((await inner.list()).map((r) => r.runId)).toEqual([paused.runId]);
374+
// …so the job that would wake it MUST survive. This is the regression: the
375+
// unconditional `finally` cancelled here, and nothing would have re-armed
376+
// until the next process start.
377+
expect(boot2.cancelled).toEqual([]);
378+
});
379+
380+
it('re-arm path: the failed shot is reported at error, naming the job and the run', async () => {
381+
const { paused, boot2, errors, jobName } = await coldBootWithBrokenLoad();
382+
await boot2.scheduled[0].handler({ jobId: jobName });
383+
384+
// Previously silent: the callback discarded the result without a single line.
385+
expect(errors).toHaveLength(1);
386+
expect(errors[0]).toContain(jobName);
387+
expect(errors[0]).toContain(paused.runId!);
388+
// Both remedies an operator can act on, and the reason the job was kept.
389+
expect(errors[0]).toMatch(/left ARMED on purpose/);
390+
expect(errors[0]).toMatch(new RegExp(`trigger\\('${jobName}'\\)`));
391+
expect(errors[0]).toMatch(new RegExp(`resume\\('${paused.runId}'\\)`));
392+
expect(errors[0]).toContain('connection refused');
393+
});
394+
395+
it('re-arm path: a shot that DOES resume still disarms the one-shot (unchanged)', async () => {
396+
// Same cold boot, working store — the branch must not have swallowed the
397+
// ordinary teardown along with the failing one.
398+
const inner = new InMemorySuspendedRunStore();
399+
const boot1 = fakeJobCtx();
400+
const e1 = new AutomationEngine(silentLogger());
401+
e1.registerNodeExecutor(markerExecutor([]));
402+
registerWaitNode(e1, boot1.ctx);
403+
e1.setSuspendedRunStore(inner);
404+
e1.registerFlow('wait_flow', waitFlow(config));
405+
const paused = await e1.execute('wait_flow');
406+
407+
const ran: string[] = [];
408+
const boot2 = fakeJobCtx();
409+
const e2 = new AutomationEngine(silentLogger());
410+
e2.registerNodeExecutor(markerExecutor(ran));
411+
registerWaitNode(e2, boot2.ctx);
412+
e2.setSuspendedRunStore(inner);
413+
e2.registerFlow('wait_flow', waitFlow(config));
414+
const { logger, errors } = capturingLogger();
415+
await rearmSuspendedWaitTimers(e2, inner, boot2.ctx.getService('job') as IJobService, logger);
416+
417+
await boot2.scheduled[0].handler({ jobId: boot2.scheduled[0].name });
418+
419+
expect(ran).toEqual(['after']);
420+
expect([...new Set(boot2.cancelled)]).toEqual([`flow-wait:${paused.runId}:pause`]);
421+
expect(errors).toEqual([]);
422+
});
423+
424+
it('arming path: the same handler keeps the job armed on STORE_UNAVAILABLE', async () => {
425+
// The arming callback shares one handler with the re-arm callback, so this
426+
// pins the branch on THAT site too. The code is injected, not provoked: a run
427+
// that paused in this process is in the engine's hot cache, so its own resume
428+
// never reads the durable store and cannot produce STORE_UNAVAILABLE here.
429+
// Fabricating a cache miss to "prove" otherwise would pin a scenario the
430+
// engine does not have — what is verified is the handler's branch, and that
431+
// the arming site routes through it rather than keeping its own `finally`.
432+
const { ctx, scheduled, cancelled } = fakeJobCtx();
433+
const engine = new AutomationEngine(silentLogger());
434+
const ran: string[] = [];
435+
engine.registerNodeExecutor(markerExecutor(ran));
436+
registerWaitNode(engine, ctx);
437+
engine.registerFlow('wait_flow', waitFlow(config));
438+
439+
const paused = await engine.execute('wait_flow');
440+
expect(scheduled).toHaveLength(1);
441+
442+
engine.resume = async () => ({
443+
success: false,
444+
code: 'STORE_UNAVAILABLE',
445+
error: `Durable suspended-run store unreachable for run '${paused.runId}'`,
446+
});
447+
await scheduled[0].handler({ jobId: scheduled[0].name });
448+
449+
expect(cancelled).toEqual([]);
450+
expect(ran).toEqual([]);
451+
});
452+
453+
it('RESUME_IN_PROGRESS still disarms — the other resume owns the pause', async () => {
454+
const { ctx, scheduled, cancelled } = fakeJobCtx();
455+
const engine = new AutomationEngine(silentLogger());
456+
const ran: string[] = [];
457+
let release: () => void = () => {};
458+
const gate = new Promise<void>((r) => { release = r; });
459+
engine.registerNodeExecutor({
460+
type: 'mark',
461+
async execute(node) { ran.push(node.id); await gate; return { success: true }; },
462+
});
463+
registerWaitNode(engine, ctx);
464+
engine.registerFlow('wait_flow', waitFlow(config));
465+
const paused = await engine.execute('wait_flow');
466+
467+
// A concurrent resume claims the pause and parks inside the next node.
468+
const inFlight = engine.resume(paused.runId!);
469+
await new Promise((r) => setTimeout(r, 10));
470+
expect(ran).toEqual(['after']); // it really is mid-flight, holding the guard
471+
472+
// Ignore the release-hook teardown that claim already triggered, so what is
473+
// asserted below can only have come from the timer's own settle step.
474+
cancelled.length = 0;
475+
await scheduled[0].handler({ jobId: scheduled[0].name });
476+
expect(cancelled).toEqual([`flow-wait:${paused.runId}:pause`]);
477+
478+
release();
479+
expect((await inFlight).success).toBe(true);
480+
});
481+
482+
it('a thrown resume still disarms — a throw is not a store outage', async () => {
483+
const { ctx, scheduled, cancelled } = fakeJobCtx();
484+
const engine = new AutomationEngine(silentLogger());
485+
engine.registerNodeExecutor(markerExecutor([]));
486+
registerWaitNode(engine, ctx);
487+
engine.registerFlow('wait_flow', waitFlow(config));
488+
await engine.execute('wait_flow');
489+
490+
engine.resume = async () => { throw new Error('boom'); };
491+
await expect(scheduled[0].handler({ jobId: scheduled[0].name })).rejects.toThrow('boom');
492+
expect(cancelled).toEqual([scheduled[0].name]);
493+
});
494+
});
495+
280496
/**
281497
* The loose `config.*` back door the executor used to read alongside
282498
* `waitEventConfig` graduated into the ADR-0087 D2 conversion layer

0 commit comments

Comments
 (0)