feat(events): a failed step may say when to retry (MODULE_API 1.15.0) #215
@@ -966,6 +966,15 @@ function detailValue(value) {
|
||||
|
||||
export const logKindWord = (kind) => KIND_WORDS[kind] || kind
|
||||
|
||||
// "20:10", in the viewer's own clock. Time only: the log line it sits in carries
|
||||
// its own timestamp, and a retry is at most thirty minutes after it.
|
||||
function clockTime(value) {
|
||||
if (!value) return ''
|
||||
const t = new Date(value)
|
||||
if (Number.isNaN(t.getTime())) return ''
|
||||
return `${String(t.getHours()).padStart(2, '0')}:${String(t.getMinutes()).padStart(2, '0')}`
|
||||
}
|
||||
|
||||
/**
|
||||
* One log line as a sentence.
|
||||
*
|
||||
@@ -992,8 +1001,12 @@ export function describeLogLine(line) {
|
||||
return `${line.phase} finished`
|
||||
case 'step.parked':
|
||||
return `${d.action} is waiting on a human`
|
||||
case 'step.retry':
|
||||
return `${d.action} failed, attempt ${d.attempt} of ${d.of}${d.error ? `: ${d.error}` : ''}`
|
||||
case 'step.retry': {
|
||||
// `retryAt` is on every retry line since MODULE_API 1.15.0; a line written
|
||||
// before it says what it always said.
|
||||
const at = clockTime(d.retryAt)
|
||||
return `${d.action} failed, attempt ${d.attempt} of ${d.of}${at ? `, retrying at ${at}` : ''}${d.error ? `: ${d.error}` : ''}`
|
||||
}
|
||||
case 'step.status':
|
||||
return d.control
|
||||
? `${d.action} → ${d.to}${by} — ${d.control}${d.note || d.reason ? `: ${d.note || d.reason}` : ''}`
|
||||
|
||||
@@ -11,7 +11,10 @@
|
||||
// that the two files can drift, so a test asserts they agree
|
||||
// (client/test/moduleRegistry.test.js) rather than trusting a bump to remember
|
||||
// both.
|
||||
// 1.14.0 — an action param's `multiple` (Rust PLAN_REDESIGNS §12.3): a param
|
||||
// 1.15.0 — a failed step's `retryAfterMs` (Rust PLAN_REDESIGNS §14.3.13): when
|
||||
// to try again. Server-side; the run console's retry line now says when. This
|
||||
// file bumps for the reason at the top.
|
||||
// 1.14.0 —an action param's `multiple` (Rust PLAN_REDESIGNS §12.3): a param
|
||||
// that holds several values, drawn by core's step editor as a multi-select.
|
||||
// Server-side declaration; this file bumps for the reason at the top.
|
||||
// 1.13.0 — the event step editor (Rust PLAN_REDESIGNS §2): event templates, a
|
||||
@@ -88,4 +91,4 @@
|
||||
// but the two halves state ONE version: a module declares a single coreApi range
|
||||
// and is served one chunk, so a client that claimed 1.0.0 while the server
|
||||
// answered 1.1.0 would be two answers to one question.
|
||||
export const MODULE_API_VERSION = '1.14.0'
|
||||
export const MODULE_API_VERSION = '1.15.0'
|
||||
|
||||
@@ -347,6 +347,21 @@ test('the log lines a run produces all render as something', () => {
|
||||
}
|
||||
})
|
||||
|
||||
test('a retry line says when it will run (MODULE_API 1.15.0), and an older line still reads', () => {
|
||||
// Built from local parts so the assertion holds in any timezone the suite runs in.
|
||||
const at = new Date(2026, 9, 15, 20, 10, 0)
|
||||
const text = describeLogLine({
|
||||
kind: 'step.retry',
|
||||
detail: { action: 'rust.dt.start', attempt: 1, of: 3, error: 'not ready yet', retryAt: at.toISOString() },
|
||||
})
|
||||
assert.equal(text, 'rust.dt.start failed, attempt 1 of 3, retrying at 20:10: not ready yet')
|
||||
|
||||
const before = describeLogLine({ kind: 'step.retry', detail: { action: 'core.announce', attempt: 2, of: 3 } })
|
||||
assert.equal(before, 'core.announce failed, attempt 2 of 3')
|
||||
const junk = describeLogLine({ kind: 'step.retry', detail: { action: 'a', attempt: 1, of: 3, retryAt: 'soon' } })
|
||||
assert.equal(junk, 'a failed, attempt 1 of 3', 'an unreadable time is left out, not shown as NaN')
|
||||
})
|
||||
|
||||
// ── The one log line core did not compose (Phase 15) ──────────────────────
|
||||
|
||||
test('a module detail line renders the module keys, not the kind id', () => {
|
||||
|
||||
@@ -1,6 +1,6 @@
|
||||
{
|
||||
"_comment": "Generated event-trigger inventory - the authoritative freeze of CORE's engagement contract (docs/website/ENGAGEMENT.md 4.3). Regenerate with `npm run engagement:manifest` in website/server. A renamed variable, a changed type or a widened ceiling breaks stored templates and rules, so the diff here is the review signal. A module ships its own copy in its bundle; this file never contains one.",
|
||||
"moduleApiVersion": "1.14.0",
|
||||
"moduleApiVersion": "1.15.0",
|
||||
"triggers": [
|
||||
{
|
||||
"id": "event.phase.changed",
|
||||
|
||||
@@ -44,6 +44,38 @@ const MAX_HOLD_SECONDS = 7 * 24 * 60 * 60
|
||||
// rendered half of one would be a second bug on top of the first.
|
||||
const MAX_DETAIL_BYTES = 4096
|
||||
|
||||
// The bounds on a failure's `retryAfterMs`, in milliseconds (MODULE_API 1.15.0,
|
||||
// Rust PLAN_REDESIGNS §14.3.13, D371). One minute to thirty. **Clamped, never
|
||||
// refused**: it is the module's hint about its own verb — "the treasure is still
|
||||
// warming up, try in ten minutes" — not an author's value, so a module that says
|
||||
// five seconds or five hours gets the nearest bound rather than a failed step.
|
||||
// The floor is the flat delay's own default, so no hint can make a retry come
|
||||
// sooner than an unhinted one would on a stock deployment; the ceiling keeps
|
||||
// `MAX_ATTEMPTS` tries of a step inside an hour and a half of the moment the
|
||||
// event was about.
|
||||
const MIN_RETRY_AFTER_MS = 60_000
|
||||
const MAX_RETRY_AFTER_MS = 30 * 60_000
|
||||
|
||||
/**
|
||||
* A failure's `retryAfterMs`, clamped, or null for "use the flat delay".
|
||||
*
|
||||
* A value that is not a number at all is the hint being absent rather than
|
||||
* wrong: it is dropped and logged, the step retries on the flat delay, and
|
||||
* nothing about the failure changes — the same posture as a bad `detail`.
|
||||
*/
|
||||
function safeRetryAfter(value, actionId) {
|
||||
if (value === undefined || value === null) return null
|
||||
const n = typeof value === 'number' ? value : Number.NaN
|
||||
if (!Number.isFinite(n)) {
|
||||
log.warn('event action answered a retryAfterMs that is not a number; using the flat delay', {
|
||||
action: actionId,
|
||||
retryAfterMs: String(value).slice(0, 40),
|
||||
})
|
||||
return null
|
||||
}
|
||||
return Math.min(MAX_RETRY_AFTER_MS, Math.max(MIN_RETRY_AFTER_MS, Math.round(n)))
|
||||
}
|
||||
|
||||
/**
|
||||
* A module's own account of what a successful step actually did.
|
||||
*
|
||||
@@ -127,7 +159,7 @@ function withDeadline(fn, ms, actionId) {
|
||||
|
||||
/**
|
||||
* Turn a raw `perform()` answer into
|
||||
* `{ outcome, error?, holdSeconds?, resources?, participants? }`.
|
||||
* `{ outcome, error?, retryAfterMs?, holdSeconds?, resources?, participants? }`.
|
||||
*
|
||||
* Exported and pure, so the classification rules are testable without a registry,
|
||||
* a database or a clock — which matters because they are the rules that decide
|
||||
@@ -150,10 +182,13 @@ function classify(result, actionId) {
|
||||
// says `retry: false`, and an envelope that forgot to say anything gets the
|
||||
// benefit of the doubt on the transient question but not on the success one.
|
||||
const retry = result.retry !== false
|
||||
return {
|
||||
outcome: retry ? 'retry' : 'terminal',
|
||||
error: result.error ? String(result.error) : `${actionId} refused`,
|
||||
}
|
||||
const error = result.error ? String(result.error) : `${actionId} refused`
|
||||
if (!retry) return { outcome: 'terminal', error }
|
||||
// **When to try again** is the module's to suggest and core's to bound. Read
|
||||
// on the retry shape only: a terminal failure is never attempted again, so a
|
||||
// delay beside `retry: false` describes nothing.
|
||||
const retryAfterMs = safeRetryAfter(result.retryAfterMs, actionId)
|
||||
return retryAfterMs === null ? { outcome: 'retry', error } : { outcome: 'retry', error, retryAfterMs }
|
||||
}
|
||||
|
||||
// ── The two success shapes that are not "finished" ──
|
||||
@@ -250,4 +285,15 @@ async function dispatchStep(step, { run, actor = null, verify = false } = {}) {
|
||||
return classification
|
||||
}
|
||||
|
||||
module.exports = { dispatchStep, classify, withDeadline, safeDetail, OUTCOMES, MAX_HOLD_SECONDS, MAX_DETAIL_BYTES }
|
||||
module.exports = {
|
||||
dispatchStep,
|
||||
classify,
|
||||
withDeadline,
|
||||
safeDetail,
|
||||
safeRetryAfter,
|
||||
OUTCOMES,
|
||||
MAX_HOLD_SECONDS,
|
||||
MAX_DETAIL_BYTES,
|
||||
MIN_RETRY_AFTER_MS,
|
||||
MAX_RETRY_AFTER_MS,
|
||||
}
|
||||
|
||||
@@ -9,7 +9,16 @@
|
||||
// Deliberately separate from PROTOCOL_VERSION (which versions the shard wire and
|
||||
// has nothing to say about a website module) and from any module's own version.
|
||||
|
||||
// 1.14.0 — an action param may hold several values: `multiple: true`, with an
|
||||
// 1.15.0 — a failed step may say when to try again: `{ ok: false, retry: true,
|
||||
// retryAfterMs }` (Rust PLAN_REDESIGNS §14.3.13, D371; docs/website/EVENTS.md §F).
|
||||
// Clamped to one minute–thirty minutes, never refused; absent, the flat
|
||||
// `EVENT_STEP_RETRY_MS` as before. It is one attempt of `EVENT_STEP_MAX_ATTEMPTS`
|
||||
// like any retry, and ignored beside `retry: false`. One optional envelope
|
||||
// member, so minor. Module-uo declares `^1.10.0` and answers none: an envelope
|
||||
// without it is classified exactly as it was. This took 1.15.0 ahead of
|
||||
// STEAM_SIGNIN.md, which had claimed it and moves to the next minor.
|
||||
//
|
||||
// 1.14.0 —an action param may hold several values: `multiple: true`, with an
|
||||
// optional `max` (1–100, 20 if left out), on a `string` or `int` param (Rust
|
||||
// PLAN_REDESIGNS §12.3, D344; docs/website/EVENTS.md §F). The step stores a JSON
|
||||
// array; a bare value is read as a list of one; `required` means at least one;
|
||||
@@ -198,6 +207,6 @@
|
||||
// an admin action a module performs belongs in core's one audit log, the
|
||||
// extension slot needs the user its prefix names, and §2.7 forbids a module
|
||||
// reading core's `APP_BASE_URL` for itself. Additions only, so minor.
|
||||
const MODULE_API_VERSION = '1.14.0'
|
||||
const MODULE_API_VERSION = '1.15.0'
|
||||
|
||||
module.exports = { MODULE_API_VERSION }
|
||||
|
||||
@@ -428,13 +428,28 @@ async function drainStep(run, step, now, carry = {}) {
|
||||
}
|
||||
|
||||
if (result.outcome === 'retry' && step.attempts + 1 < MAX_ATTEMPTS) {
|
||||
await stepsDb.reschedule(step.id, new Date(now.getTime() + RETRY_MS), result.error)
|
||||
// The module's `retryAfterMs` when it gave one (already clamped by the
|
||||
// dispatcher), else the flat delay. **It is still one attempt** of
|
||||
// MAX_ATTEMPTS: a hint changes when, never how many, so a module that answers
|
||||
// "not yet" for ever fails the step on schedule like any other. A run paused
|
||||
// or cancelled in the wait is not picked up — `findDue` reads only running
|
||||
// runs — and the staff Retry on a paused step is unaffected.
|
||||
const delayMs = result.retryAfterMs || RETRY_MS
|
||||
const retryAt = new Date(now.getTime() + delayMs)
|
||||
await stepsDb.reschedule(step.id, retryAt, result.error)
|
||||
await logDb.write({
|
||||
runId: run.id,
|
||||
stepId: step.id,
|
||||
kind: 'step.retry',
|
||||
phase: step.phase,
|
||||
detail: { action: step.action_id, attempt: step.attempts + 1, of: MAX_ATTEMPTS, error: result.error },
|
||||
detail: {
|
||||
action: step.action_id,
|
||||
attempt: step.attempts + 1,
|
||||
of: MAX_ATTEMPTS,
|
||||
error: result.error,
|
||||
retryAt: retryAt.toISOString(),
|
||||
...(result.retryAfterMs ? { retryAfterMs: result.retryAfterMs } : {}),
|
||||
},
|
||||
})
|
||||
// Degraded from the FIRST retry, not from the eventual failure. An event
|
||||
// whose announcements are landing on the second attempt is having trouble
|
||||
|
||||
@@ -112,7 +112,7 @@ test('the version a module declares against satisfies ^1.10.0', () => {
|
||||
// 1.10.0 loading — Module-uo declares exactly `^1.10.0` — and this is the
|
||||
// assertion that says it does. The number itself is pinned in version.js.
|
||||
assert.ok(semver.satisfies(MODULE_API_VERSION, '^1.10.0'), MODULE_API_VERSION)
|
||||
assert.equal(MODULE_API_VERSION, '1.14.0')
|
||||
assert.equal(MODULE_API_VERSION, '1.15.0')
|
||||
})
|
||||
|
||||
test('a module registers actions, budgets, leases and option sources', () => {
|
||||
|
||||
@@ -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' } }
|
||||
|
||||
Reference in New Issue
Block a user