From e46842a28c6c0de732493163f4ce36b5eb9debc9 Mon Sep 17 00:00:00 2001 From: wtclaude Date: Tue, 8 Sep 2026 18:48:57 -0500 Subject: [PATCH] fix(events): carry a module's own account of a successful step MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `EVENTS.md` §H told a module the revert contract accepts a `detail` on its envelope. `classify()` reads `ok`, `retry`, `error`, `await`, `holdFor`, `resources` and `participants` — and has never read a `detail`. So a module that answered one was writing into nothing. `module-uo` believed it, twice, since Phase 12b: * `uo.item.grant` answers `{ granted, missed, why }` * `uo.world.save` answers `{ started: true }` The grant is the one that matters. A grant reaches the players a run's participation ledger holds, and **which of them missed out is knowable only to the module and reported nowhere else** — so an operator saw a step marked `done` and never learned four of twelve got nothing. Found writing the integration kit's chapter 5 (`Integration-kit#10`), whose template made the same mistake on §H's authority. ## What this adds `detail` becomes a real, optional member of the two SUCCESS envelopes, beside `resources` and `participants` — on both, because `await: 'human'` is a success and a cue's confirm finishes the step without a second dispatch, so that is the only moment its module could ever have said anything. **Core never interprets it.** `safeDetail()` bounds it and nothing else reads a key out of it, here or in the runner or in the browser. That is the point: a module knows things about its own verb core cannot compute, and it had no other way to say them. * objects only — the column is JSON and the console renders keys, so a bare string has nothing to render under, and core inventing a key would be core interpreting it after all; * 4KB of serialised JSON, dropped rather than truncated, because half a JSON object is not a JSON object; * unserialisable (circular, a throwing `toJSON`) is dropped — reaching the runner would make the log INSERT throw, inside the one write documented never to; * re-parsed rather than passed through, so core holds no live reference into a module's object; * **anything wrong with it is dropped and logged, never a failure.** A step that did what it was asked must not be re-run because its module's commentary was malformed: that is a world write repeated for a log line. The runner writes it as a `step.detail` run-log row, its own kind rather than a field on `resource.recorded` — the grant that forced this ledgers nothing (`reversible: 'none'`) and reports no participants, so it would have had nowhere to ride. ## The renderer, which is half the fix `describeLogLine`'s default returns a kind WORD, so a `step.detail` row falling through would have rendered as the literal string "step.detail" — the channel existing and showing nothing, exactly the failure being fixed. It gets a case that renders whatever keys the module put there, generically: a switch on known keys would be the browser learning one module's vocabulary. uo.item.grant — granted: 8, missed: 4, why: bank full, offline uo.world.save — started: true **`module-uo` needs no change**: the code it already shipped starts working. MODULE_API stays 1.10.0, amended in place — it is still on `edge`. Zero-line route manifest diff; no route added. 2057 server tests, 400 client tests. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_016wDDVXWMDz82WqE1i969r4 --- client/src/lib/eventAuthoring.js | 53 +++++++++++ client/test/eventAuthoring.test.js | 48 ++++++++++ server/src/events/dispatch.js | 73 ++++++++++++++- server/src/model/events/eventRunLog.db.js | 6 ++ server/src/utils/eventRunner.js | 21 +++++ server/test/eventRunner.test.js | 106 ++++++++++++++++++++++ 6 files changed, 306 insertions(+), 1 deletion(-) diff --git a/client/src/lib/eventAuthoring.js b/client/src/lib/eventAuthoring.js index 87c9e32..84c4bed 100644 --- a/client/src/lib/eventAuthoring.js +++ b/client/src/lib/eventAuthoring.js @@ -692,9 +692,46 @@ const KIND_WORDS = { 'step.refused': 'Refused', 'run.budget': 'Caps', 'version.verified': 'Dry run passed', + // Phase 15. "Reported" rather than "Detail": the line is the module talking + // about its own verb, and every other word here names something core did. + 'step.detail': 'Step reported', note: 'Note', } +// How deep and how long a module's own `detail` value is allowed to render. +// The dispatcher already caps the whole object at 4KB, so this is about a line +// staying a line — an operator scanning a run's log should not have one row +// wrap eight times because a module answered with an array of forty names. +const DETAIL_LIST_SHOWN = 5 +const DETAIL_TEXT_MAX = 80 + +/** + * One value out of a module's `detail`, as text. + * + * **Core does not interpret these keys and neither does this.** A module wrote + * the object; the console shows it. That is the whole reason the renderer is + * generic rather than a switch — a switch would be core learning a module's + * vocabulary, which is the thing the module system exists to prevent. + */ +function detailValue(value) { + if (value === null || value === undefined) return '—' + if (Array.isArray(value)) { + const shown = value.slice(0, DETAIL_LIST_SHOWN).map(detailValue).join(', ') + return value.length > DETAIL_LIST_SHOWN + ? `${shown} and ${value.length - DETAIL_LIST_SHOWN} more` + : shown + } + if (typeof value === 'object') { + // A nested object is rendered by its keys rather than as JSON: an operator + // reading a log wants "granted: 8, missed: 4", not a brace. + return Object.entries(value) + .map(([k, v]) => `${k} ${detailValue(v)}`) + .join(', ') + } + const text = String(value) + return text.length > DETAIL_TEXT_MAX ? `${text.slice(0, DETAIL_TEXT_MAX - 1)}…` : text +} + export const logKindWord = (kind) => KIND_WORDS[kind] || kind /** @@ -758,6 +795,22 @@ export function describeLogLine(line) { .join(', ') || 'no caps apply to this run' case 'version.verified': return `Version ${d.version} passed its dry run — scheduled occurrences may start` + // Phase 15. The one line whose body core did not compose: a module may answer + // a successful step with a `detail` object, and this renders whatever keys it + // put there. `action` is core's own and is pulled out to lead the sentence; + // everything after it is the module's. + // + // **Without this case the row would render as the literal string + // "step.detail"**, because the default below is a kind word and not a + // sentence — which would be the reporting channel existing and showing + // nothing, the exact failure it was built to fix. + case 'step.detail': { + const { action, ...rest } = d + const body = Object.entries(rest) + .map(([key, value]) => `${key}: ${detailValue(value)}`) + .join(', ') + return body ? `${action || 'A step'} — ${body}` : `${action || 'A step'} reported nothing` + } default: return logKindWord(line?.kind) } diff --git a/client/test/eventAuthoring.test.js b/client/test/eventAuthoring.test.js index 1c86248..74de846 100644 --- a/client/test/eventAuthoring.test.js +++ b/client/test/eventAuthoring.test.js @@ -347,6 +347,54 @@ test('the log lines a run produces all render as something', () => { } }) +// ── The one log line core did not compose (Phase 15) ────────────────────── + +test('a module detail line renders the module keys, not the kind id', () => { + // The failure this guards is subtle and total: `step.detail` falling to the + // default renders the literal string "step.detail", which is the reporting + // channel existing and showing nothing — exactly what it was built to fix. + const text = describeLogLine({ + kind: 'step.detail', + detail: { action: 'uo.item.grant', granted: 8, missed: 4, why: ['bank full', 'offline'] }, + }) + + assert.ok(!text.includes('step.detail'), `the kind id leaked into the sentence: ${text}`) + assert.match(text, /uo\.item\.grant/) + assert.match(text, /granted: 8/) + assert.match(text, /missed: 4/) + assert.match(text, /bank full/) +}) + +test('a module detail is rendered generically, whatever a module puts in it', () => { + // Core does not interpret these keys and neither does the renderer — a switch + // here would be the browser learning one module vocabulary, which is the thing + // the module system exists to prevent. So an unfamiliar shape still reads. + const text = describeLogLine({ + kind: 'step.detail', + detail: { action: 'rust.wipe.announce', servers: { eu: 3, us: 1 }, dryRun: false, at: null }, + }) + assert.ok(!text.includes('undefined'), text) + assert.ok(!text.includes('[object Object]'), `a nested object rendered as a brace: ${text}`) + assert.match(text, /eu 3/) + assert.match(text, /dryRun: false/, 'false is a value, not an absence') +}) + +test('a long module detail stays one line', () => { + const many = Array.from({ length: 40 }, (_, i) => `player-${i}`) + const text = describeLogLine({ + kind: 'step.detail', + detail: { action: 'uo.item.grant', missed: many, note: 'x'.repeat(500) }, + }) + assert.match(text, /and 35 more/) + assert.ok(text.length < 300, `one row should not wrap eight times: ${text.length} chars`) +}) + +test('a module detail with nothing in it still reads as a sentence', () => { + const text = describeLogLine({ kind: 'step.detail', detail: { action: 'uo.world.save' } }) + assert.ok(text.length > 0) + assert.ok(!text.includes('undefined'), text) +}) + test('every run status has a word, and an unknown one falls through rather than blanking', () => { for (const s of ['scheduled', 'starting', 'running', 'paused', 'ending', 'completed', 'cancelled', 'failed', 'missed']) { assert.ok(runStatusWord(s).length > 0) diff --git a/server/src/events/dispatch.js b/server/src/events/dispatch.js index f1fa8aa..4db6e5e 100644 --- a/server/src/events/dispatch.js +++ b/server/src/events/dispatch.js @@ -36,6 +36,71 @@ const OUTCOMES = ['done', 'parked', 'retry', 'terminal'] // worked. const MAX_HOLD_SECONDS = 7 * 24 * 60 * 60 +// The upper bound on a module's `detail`, in bytes of serialised JSON. It lands +// in `event_run_log.detail` and is read back by the run console, so it is a +// diagnostic line rather than a data channel — a module with more to say than +// this has a table of its own to say it in. Dropped rather than truncated when it +// is over: a truncated JSON object is not a JSON object, and a console that +// rendered half of one would be a second bug on top of the first. +const MAX_DETAIL_BYTES = 4096 + +/** + * A module's own account of what a successful step actually did. + * + * Optional, module-opaque, and **never interpreted by core** — it is carried to + * the run log and rendered, and nothing here or in the runner reads a key out of + * it. That is the whole contract: a module knows things about its own verb that + * core cannot compute and has no other way to say. `uo.item.grant` is the case + * that forced it — a grant reaches the players a run's ledger holds, and *which + * of them missed out* is knowable only to the module and reported nowhere else, + * so an operator saw a step marked `done` and never learned four of twelve got + * nothing. + * + * **Anything wrong with it is dropped and logged, never a failure.** A step that + * did what it was asked must not be re-run because its module's commentary was + * malformed — that would be a world write repeated for a log line. Same posture + * `participants` takes, and for the same reason. + */ +function safeDetail(detail, actionId) { + if (detail === undefined || detail === null) return null + + // Objects only. The column is JSON and the console renders keys, so a bare + // string or a number has nothing to render under — and core inventing a key to + // put it beneath would be core interpreting it after all. + if (typeof detail !== 'object' || Array.isArray(detail)) { + log.warn('action detail is not an object', { action: actionId, type: typeof detail }) + return null + } + + let encoded + try { + encoded = JSON.stringify(detail) + } catch (err) { + // A circular reference, or a `toJSON` that throws. Reaching the runner would + // make the INSERT throw instead, inside the one write that is documented + // never to. + log.warn('action detail could not be serialised', { action: actionId, message: err.message }) + return null + } + if (encoded === undefined) { + log.warn('action detail serialised to nothing', { action: actionId }) + return null + } + if (Buffer.byteLength(encoded, 'utf8') > MAX_DETAIL_BYTES) { + log.warn('action detail is too large', { + action: actionId, + bytes: Buffer.byteLength(encoded, 'utf8'), + max: MAX_DETAIL_BYTES, + }) + return null + } + + // Re-parsed rather than passed through, so what the runner writes is a plain + // JSON value with no getters, no prototype and no live reference into whatever + // the module still holds. + return JSON.parse(encoded) +} + /** * Run `fn()` under a deadline. * @@ -103,6 +168,7 @@ function classify(result, actionId) { error: null, resources: result.resources || [], participants: result.participants || [], + detail: safeDetail(result.detail, actionId), } } @@ -125,6 +191,11 @@ function classify(result, actionId) { holdSeconds, resources: result.resources || [], participants: result.participants || [], + // On the same two success shapes as `resources` and `participants`, and for + // the same reason: `await: 'human'` is a success, and a cue's confirm + // finishes the step without a second dispatch, so this is the only moment + // its module could ever have said anything. + detail: safeDetail(result.detail, actionId), } } @@ -179,4 +250,4 @@ async function dispatchStep(step, { run, actor = null, verify = false } = {}) { return classification } -module.exports = { dispatchStep, classify, withDeadline, OUTCOMES, MAX_HOLD_SECONDS } +module.exports = { dispatchStep, classify, withDeadline, safeDetail, OUTCOMES, MAX_HOLD_SECONDS, MAX_DETAIL_BYTES } diff --git a/server/src/model/events/eventRunLog.db.js b/server/src/model/events/eventRunLog.db.js index 19486a1..c5b4e0d 100644 --- a/server/src/model/events/eventRunLog.db.js +++ b/server/src/model/events/eventRunLog.db.js @@ -65,6 +65,12 @@ const KINDS = [ 'results.published', // the results table was ranked and stamped 'announcement.emitted', // a lifecycle trigger fired, with its id and ceiling 'announcement.enqueued', // a post was linked to this run and queued on the legs + // Phase 15's one, and it is the only kind whose payload core does not compose. + // A module may answer a success envelope with a `detail` object; it is bounded + // and sanitised at the dispatcher and written here verbatim beside the action + // id. Nothing reads a key out of it — it exists because a module knows things + // about its own verb that core cannot compute and had no other way to say. + 'step.detail', // a module's own account of what a successful step did ] const hydrate = (row) => row && { ...row, detail: parseJson(row.detail, null) } diff --git a/server/src/utils/eventRunner.js b/server/src/utils/eventRunner.js index 4ebffe1..fdd1da5 100644 --- a/server/src/utils/eventRunner.js +++ b/server/src/utils/eventRunner.js @@ -361,6 +361,27 @@ async function drainStep(run, step, now, carry = {}) { }, }) } + + // **What the module has to say about it**, which is the third thing a + // success envelope can carry and the only one core does not interpret. + // `resources` is what to undo and `participants` is who took part; this is + // everything else the module knows and core cannot compute — how many of a + // run's players a grant actually reached, whether a save had already started. + // Bounded and sanitised in `dispatch.js`; by here it is a plain JSON object + // or null. + // + // Its own line rather than a field on one of the two above, because a step + // very often has this and neither of those — the grant that forced it + // ledgers nothing (`reversible: 'none'`) and reports no participants. + if (result.detail) { + await logDb.write({ + runId: run.id, + stepId: step.id, + kind: 'step.detail', + phase: step.phase, + detail: { action: step.action_id, ...result.detail }, + }) + } } if (result.outcome === 'parked') { diff --git a/server/test/eventRunner.test.js b/server/test/eventRunner.test.js index 05f6909..5dafc33 100644 --- a/server/test/eventRunner.test.js +++ b/server/test/eventRunner.test.js @@ -1028,6 +1028,112 @@ test('classify: the two success shapes that are not "finished"', () => { assert.ok(classify({ ok: true, holdFor: 1e12 }, 'a').holdSeconds <= 7 * 24 * 60 * 60, 'holdFor is bounded') }) +// ── A module's own account of a successful step (Phase 15) ──────────────── +// +// The third thing a success envelope may carry, and the only one core does not +// interpret. It exists because a module knows things about its own verb that core +// cannot compute and had no other channel for: `uo.item.grant` reaches the players +// a run's ledger holds, and WHICH OF THEM MISSED OUT is reported nowhere else — +// so before this, an operator saw a step marked `done` and never learned that four +// of twelve got nothing. `module-uo` had been answering `detail` since Phase 12b +// on the strength of one sentence in EVENTS.md §H, and core had never read it. + +test('classify: a success may carry a module detail, and it is never interpreted', () => { + assert.equal(classify({ ok: true }, 'a').detail, null, 'absent is null, not undefined') + assert.deepEqual( + classify({ ok: true, detail: { granted: 8, missed: 4 } }, 'a').detail, + { granted: 8, missed: 4 }, + "the keys are the module own and core changes none of them", + ) + // The other success shape. A cue's confirm finishes the step without a second + // dispatch, so this is the only moment its module could ever have said anything. + assert.deepEqual( + classify({ ok: true, await: 'human', detail: { cued: 'britain' } }, 'a').detail, + { cued: 'britain' }, + ) +}) + +test('classify: a bad detail is dropped, and never fails the step', () => { + // A step that did what it was asked must not be re-run because its module's + // commentary was malformed — that would be a world write repeated for a log + // line. Every one of these is `done` with a null detail. + const dropped = [ + { ok: true, detail: 'a string' }, + { ok: true, detail: 42 }, + { ok: true, detail: ['an', 'array'] }, + { ok: true, detail: { big: 'x'.repeat(5000) } }, + ] + for (const envelope of dropped) { + const verdict = classify(envelope, 'a') + assert.equal(verdict.outcome, 'done', 'a bad detail must not change the outcome') + assert.equal(verdict.detail, null) + } + + // A circular object throws inside JSON.stringify. Reaching the runner would + // make the log INSERT throw instead, inside the one write documented never to. + const circular = { ok: true, detail: {} } + circular.detail.self = circular.detail + assert.equal(classify(circular, 'a').outcome, 'done') + assert.equal(classify(circular, 'a').detail, null) +}) + +test("classify: the detail core carries is a copy, not the module object", () => { + const live = { granted: 8 } + const carried = classify({ ok: true, detail: live }, 'a').detail + live.granted = 999 + assert.equal(carried.granted, 8, 'core must not hold a live reference into a module') +}) + +test('a module detail reaches the run log as its own line', async () => { + register([scriptedAction('test.grant')]) + scripted['test.grant'] = { + calls: [], + answer: { ok: true, detail: { granted: 8, missed: 4, why: ['bank full'] } }, + } + + const id = seedRun([{ key: 'main', label: 'Main', steps: [step('test.grant')] }]) + await runner.tick(T0) + + assert.equal(stepsOf(id)[0].status, 'done') + + const line = store.log.find((l) => l.runId === id && l.kind === 'step.detail') + assert.ok(line, 'the module said something and the run has no record of it') + assert.equal(line.detail.action, 'test.grant', "core's own key leads the line") + assert.equal(line.detail.granted, 8) + assert.equal(line.detail.missed, 4) + assert.deepEqual(line.detail.why, ['bank full']) + assert.equal(line.stepId, stepsOf(id)[0].id) +}) + +test('a step that says nothing writes no detail line', async () => { + // Its own line rather than a field on `resource.recorded`, so a run whose steps + // are all quiet must not gain a row per step saying so. + register([scriptedAction('test.quiet')]) + + const id = seedRun([{ key: 'main', label: 'Main', steps: [step('test.quiet')] }]) + await runner.tick(T0) + + assert.equal(stepsOf(id)[0].status, 'done') + assert.equal(kinds(id).filter((k) => k === 'step.detail').length, 0) +}) + +test('a failed step reports no detail, however much it says', async () => { + // `detail` rides the SUCCESS shapes only. A failure's channel is `error`, and + // an action that answered both would otherwise get two bites at the log for a + // step that did not happen. + register([scriptedAction('test.refuse')]) + scripted['test.refuse'] = { + calls: [], + answer: { ok: false, retry: false, error: 'no', detail: { tried: 3 } }, + } + + const id = seedRun([{ key: 'main', label: 'Main', steps: [step('test.refuse', {}, 'skip')] }]) + await runner.tick(T0) + + assert.equal(stepsOf(id)[0].status, 'failed') + assert.equal(kinds(id).filter((k) => k === 'step.detail').length, 0) +}) + test('an action that throws is a transient failure, not a crashed tick', async () => { register([ scriptedAction('test.thrower', { -- 2.49.1