feat(events): a failed step may say when to retry (MODULE_API 1.15.0)
All checks were successful
PR Checks / bot-tests (pull_request) Successful in 48s
PR Checks / client-build (pull_request) Successful in 59s
PR Checks / server-tests (pull_request) Successful in 6m6s

A module's perform() may answer { ok: false, retry: true, retryAfterMs }
and the runner waits that long instead of the flat EVENT_STEP_RETRY_MS
(Rust PLAN_REDESIGNS §14.3.13, D371). Dangerous Treasures' warm-up is the
first user.

- dispatch.classify reads it on the retry shape only, clamped to 60 000 to
  1 800 000 ms; a value that is not a number is dropped and logged, and the
  step retries on the flat delay.
- It is one attempt of EVENT_STEP_MAX_ATTEMPTS and degrades the run like any
  retry. A run paused or cancelled in the wait is not picked up.
- Every step.retry log line now carries retryAt (and retryAfterMs when
  hinted); the run console reads "retrying at 20:10".
- MODULE_API 1.15.0, additions only; the engagement manifest is regenerated.
  Module-uo (^1.10.0) answers none of it and is unaffected.
- Test harness: resourcesDb.finishedRunsWithNothingLeft was never stubbed in
  eventRunner.test.js, so a tick that reached the cleanup sweep with a
  terminal run waited on the dead pool.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01E14m6SuuY6i1vASFeGDBeY
This commit is contained in:
2026-10-15 02:39:43 -05:00
parent a981b2b854
commit 769794d183
9 changed files with 229 additions and 17 deletions

View File

@@ -30,7 +30,7 @@ const assert = require('node:assert/strict')
const registries = require('../src/modules/registries')
const runner = require('../src/utils/eventRunner')
const { classify } = require('../src/events/dispatch')
const { classify, MIN_RETRY_AFTER_MS, MAX_RETRY_AFTER_MS } = require('../src/events/dispatch')
const runsDb = require('../src/model/events/eventRuns.db')
const stepsDb = require('../src/model/events/eventRunSteps.db')
const logDb = require('../src/model/events/eventRunLog.db')
@@ -181,6 +181,10 @@ function installStubs() {
// sweep has its own file — answering with nothing is what keeps every `tick()`
// here measuring the runner rather than a teardown.
resourcesDb.runsNeedingCleanup = async () => []
// Its 1.11.0 sibling, which was never stubbed: a tick that reached the sweep
// with a terminal run in the store asked the dead pool and waited out its
// acquire timeout on every call.
resourcesDb.finishedRunsWithNothingLeft = async () => []
runsDb.setCleanupStatus = async (id, to, from = null) => {
const r = store.runs.get(id)
@@ -901,6 +905,113 @@ test('a transient failure retries on a flat backoff with the same idempotency ke
assert.equal(new Set(scripted['test.flaky'].calls.map((c) => c.idempotencyKey)).size, 1)
})
// ── §F: a failure's retryAfterMs (MODULE_API 1.15.0, Rust PLAN_REDESIGNS §14.3.13) ──
const retryLine = (id) => store.log.find((l) => l.runId === id && l.kind === 'step.retry')
test('retryAfterMs: the module says when, and the step waits that long instead of the flat delay', async () => {
register([scriptedAction('test.warming')])
scripted['test.warming'] = {
calls: [],
answers: [{ ok: false, retry: true, retryAfterMs: 10 * 60_000, error: 'not ready yet' }],
answer: { ok: true },
}
const id = seedRun([{ key: 'main', label: 'Main', steps: [step('test.warming', {}, 'skip')] }])
await runner.tick(T0)
assert.equal(stepsOf(id)[0].status, 'pending')
assert.equal(stepsOf(id)[0].due_at.getTime(), later(10 * 60_000).getTime())
assert.equal(retryLine(id).detail.retryAt, later(10 * 60_000).toISOString())
assert.equal(retryLine(id).detail.retryAfterMs, 10 * 60_000)
assert.equal(run(id).health, 'degraded', 'a hinted retry degrades the run as any retry does')
await runner.tick(later(runner.RETRY_MS))
assert.equal(scripted['test.warming'].calls.length, 1, 'the flat delay passing is not the hinted one')
await runner.tick(later(10 * 60_000))
assert.equal(scripted['test.warming'].calls.length, 2)
assert.equal(stepsOf(id)[0].status, 'done')
})
test('retryAfterMs: an unhinted retry line still says when', async () => {
register([scriptedAction('test.flaky')])
scripted['test.flaky'] = { calls: [], answer: { ok: false, retry: true, error: 'relay is down' } }
const id = seedRun([{ key: 'main', label: 'Main', steps: [step('test.flaky', {}, 'skip')] }])
await runner.tick(T0)
assert.equal(retryLine(id).detail.retryAt, later(runner.RETRY_MS).toISOString())
assert.equal('retryAfterMs' in retryLine(id).detail, false)
})
test('retryAfterMs: it is one attempt, so a module that never gets ready fails on schedule', async () => {
register([scriptedAction('test.warming')])
scripted['test.warming'] = {
calls: [],
answer: { ok: false, retry: true, retryAfterMs: 30 * 60_000, error: 'not ready yet' },
}
const id = seedRun([{ key: 'main', label: 'Main', steps: [step('test.warming', {}, 'skip')] }])
await runner.tick(T0)
await runner.tick(later(30 * 60_000))
assert.equal(stepsOf(id)[0].attempts, 2)
await runner.tick(later(60 * 60_000))
assert.equal(stepsOf(id)[0].attempts, runner.MAX_ATTEMPTS)
assert.equal(stepsOf(id)[0].status, 'failed', 'a hint changes when, never how many')
assert.equal(run(id).status, 'completed')
})
test('retryAfterMs: a run paused in the wait does not retry', async () => {
register([scriptedAction('test.warming')])
scripted['test.warming'] = {
calls: [],
answer: { ok: false, retry: true, retryAfterMs: 5 * 60_000, error: 'not ready yet' },
}
const id = seedRun([{ key: 'main', label: 'Main', steps: [step('test.warming', {}, 'skip')] }])
await runner.tick(T0)
await runsDb.transition(id, ['running'], 'paused', { clearClaim: true })
await runner.tick(later(6 * 60_000))
assert.equal(scripted['test.warming'].calls.length, 1, 'paused means nothing is dispatched')
assert.equal(stepsOf(id)[0].status, 'pending', 'the step is still there for a resume or a staff Retry')
})
test('retryAfterMs: a run cancelled in the wait does not retry', async () => {
register([scriptedAction('test.warming')])
scripted['test.warming'] = {
calls: [],
answer: { ok: false, retry: true, retryAfterMs: 5 * 60_000, error: 'not ready yet' },
}
const id = seedRun([{ key: 'main', label: 'Main', steps: [step('test.warming', {}, 'skip')] }])
await runner.tick(T0)
await runsDb.transition(id, ['running'], 'cancelled', { clearClaim: true })
await stepsDb.cancelPending(id)
await runner.tick(later(6 * 60_000))
assert.equal(scripted['test.warming'].calls.length, 1)
assert.equal(stepsOf(id)[0].status, 'cancelled')
})
test('classify: retryAfterMs is clamped to one minute–thirty minutes, and only on the retry shape', () => {
const at = (v) => classify({ ok: false, retry: true, retryAfterMs: v }, 'a').retryAfterMs
assert.equal(at(10 * 60_000), 10 * 60_000)
assert.equal(at(5_000), MIN_RETRY_AFTER_MS, 'too soon is the floor, not a refusal')
assert.equal(at(0), MIN_RETRY_AFTER_MS)
assert.equal(at(-1), MIN_RETRY_AFTER_MS)
assert.equal(at(5 * 60 * 60_000), MAX_RETRY_AFTER_MS, 'too late is the ceiling, not a refusal')
assert.equal(at(90_000.6), 90_001, 'whole milliseconds')
assert.equal(at(undefined), undefined, 'absent: the flat delay')
assert.equal(at(null), undefined)
assert.equal(at('600000'), undefined, 'a string is not a hint; the flat delay, and the failure is unchanged')
assert.equal(at(Number.NaN), undefined)
assert.equal(at(Infinity), undefined)
assert.equal(classify({ ok: false, retry: true, retryAfterMs: 'soon' }, 'a').outcome, 'retry')
assert.equal(classify({ ok: false, retryAfterMs: 120_000 }, 'a').retryAfterMs, 120_000, 'retry defaults on, so the hint is read')
const terminal = classify({ ok: false, retry: false, retryAfterMs: 120_000 }, 'a')
assert.equal(terminal.outcome, 'terminal')
assert.equal('retryAfterMs' in terminal, false, 'a terminal failure is never tried again, so a delay means nothing')
assert.equal('retryAfterMs' in classify({ ok: true, retryAfterMs: 120_000 }, 'a'), false)
})
test('on_failure: pause stops the run and the tick never picks it up again', async () => {
register([scriptedAction('test.bad'), scriptedAction('test.after')])
scripted['test.bad'] = { calls: [], answer: { ok: false, retry: false, error: 'the world is half changed' } }