diff --git a/client/src/lib/eventAuthoring.js b/client/src/lib/eventAuthoring.js index 2867eb3..c7b34d0 100644 --- a/client/src/lib/eventAuthoring.js +++ b/client/src/lib/eventAuthoring.js @@ -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}` : ''}` diff --git a/client/src/modules/version.js b/client/src/modules/version.js index 15f1ecd..46a7bed 100644 --- a/client/src/modules/version.js +++ b/client/src/modules/version.js @@ -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' diff --git a/client/test/eventAuthoring.test.js b/client/test/eventAuthoring.test.js index 74de846..d362ed6 100644 --- a/client/test/eventAuthoring.test.js +++ b/client/test/eventAuthoring.test.js @@ -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', () => { diff --git a/server/engagement-triggers.json b/server/engagement-triggers.json index 430f963..6061a63 100644 --- a/server/engagement-triggers.json +++ b/server/engagement-triggers.json @@ -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", diff --git a/server/src/events/dispatch.js b/server/src/events/dispatch.js index 4db6e5e..2ccd10f 100644 --- a/server/src/events/dispatch.js +++ b/server/src/events/dispatch.js @@ -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, +} diff --git a/server/src/modules/version.js b/server/src/modules/version.js index 0b1110f..cc0e435 100644 --- a/server/src/modules/version.js +++ b/server/src/modules/version.js @@ -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 } diff --git a/server/src/utils/eventRunner.js b/server/src/utils/eventRunner.js index fdd1da5..bdb640f 100644 --- a/server/src/utils/eventRunner.js +++ b/server/src/utils/eventRunner.js @@ -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 diff --git a/server/test/eventModuleContract.test.js b/server/test/eventModuleContract.test.js index 68f5e3c..aa7747a 100644 --- a/server/test/eventModuleContract.test.js +++ b/server/test/eventModuleContract.test.js @@ -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', () => { diff --git a/server/test/eventRunner.test.js b/server/test/eventRunner.test.js index 5dafc33..9a762b1 100644 --- a/server/test/eventRunner.test.js +++ b/server/test/eventRunner.test.js @@ -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' } }