Merge pull request 'fix(events): carry a module's own account of a successful step' (#197) from fix/events-module-detail into edge

Reviewed-on: #197

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)
   }

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)

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 }

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) }

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') {

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', {