fix(logs): show emission time for replayed log lines, not render time

Log lines were timestamped at RENDER time (new Date() in the client),
so replayed buffer lines — the init replay and the /live backlog seed —
all showed page-open time instead of when each line was actually
produced. Root cause: emission time was captured NOWHERE in the log
path. The audit log file (pipeline logLine) and the in-memory logBuffer
both stored bare strings, and the client invented a timestamp at paint.

Thread a real emission timestamp end-to-end:
- server.js broadcast('log'): stamp data.ts = Date.now() once, at
  emission. logBuffer changes from string[] to {ts,msg}[]; the ts rides
  the live SSE event, the buffer, and (via pipeline) the on-disk log.
- server.js publicLogBuffer(): filter on .msg, return {ts,msg}[].
- server.js parseLogLine() + hydrateLogBufferFromFile(): recover ts from
  the on-disk '[<ISO>] <msg>' format; legacy bare lines → ts:null.
- server.js sanitizeForPublic(): forward ts on public 'log' events.
- audit/pipeline.js logLine(): prefix each persisted line with [<ISO>]
  so emission time survives a server restart / reloaded saved run.
- admin.html: _logEntryFields() normalizes string|{ts,msg};
  _buildLogEntry(msg,cat,tsMs) renders the emission time (null → BLANK,
  never a misleading now); appendLog uses Date.now() only for direct
  live string calls; appendLogBatch + SSE 'log' use the stored ts.
- live.html: appendLog shape-sniffs {ts,msg} buffer/SSE entries (object
  with msg but no tag/cat/status), unwraps to the string-classify path,
  and renders the stored emission ts (null → blank); structured live
  lifecycle objects still stamp now. SSE 'log' case forwards ts.

Lines whose emission time is genuinely unknown (older on-disk runs
written before this change) render a BLANK time rather than a fake one.

Test: admin-log-batch.test.js extended (15) — replayed {ts,msg} renders
its emission time, bare string → blank, live string → current time, live
{ts,msg} SSE → server ts. Adversarial review: SHIP (8/8 risks verified
safe — buffer-shape readers, public API consumers, live shape-sniff,
disk-format parse, no double-prefix, XSS intact, ms-epoch formatting).

Author: Sentinel-Bluebuilder

admin.html

@@ -1465,8 +1465,9 @@ <h1 style="margin:0;flex:0 0 auto">SENTINEL NODE TEST</h1>
           if (msg.result) { upsertLocal(msg.result); addSingleRow(msg.result); }
           applyState();
         } else if (msg.type === 'log') {
-          // Live lines carry a server-sent category; prefer it over re-deriving.
-          appendLog(msg.msg, msg.cat);
+          // Live lines carry a server-sent category + emission ts; prefer both
+          // over re-deriving/now.
+          appendLog({ ts: msg.ts, msg: msg.msg }, msg.cat);
         }
       };
       eventSource.onerror = () => {
@@ -2103,21 +2104,35 @@ <h1 style="margin:0;flex:0 0 auto">SENTINEL NODE TEST</h1>
     // trim away — see appendLogBatch for why that mattered.
     const LOG_DOM_MAX = 500;
 
+    // Normalise a log entry to { msg, ts }. Buffer/replay entries arrive as
+    // { ts, msg } (server-stamped emission time); older payloads / direct calls
+    // may be bare strings (ts unknown → null).
+    function _logEntryFields(entry) {
+      if (entry && typeof entry === 'object') {
+        return { msg: String(entry.msg == null ? '' : entry.msg), ts: typeof entry.ts === 'number' ? entry.ts : null };
+      }
+      return { msg: String(entry == null ? '' : entry), ts: null };
+    }
+
     // Build ONE log-entry div — no DOM insertion, no scroll, no reflow. Shared
     // by the live single-line appendLog and the batched init replay so
     // categorization / escaping / linkification stay byte-identical between the
     // two paths.
     // `cat` is the server-sent category for live SSE lines; replayed init buffer
-    // lines arrive as plain strings (no cat), so re-derive via logCategory().
-    function _buildLogEntry(msg, cat) {
+    // lines arrive with no cat, so re-derive via logCategory().
+    // `tsMs` is the EMISSION time in ms — shows WHEN the line was produced, not
+    // when it rendered. null → blank time (genuinely unknown emission time, e.g.
+    // a pre-timestamp line from an older on-disk run); callers pass Date.now()
+    // for lines happening live.
+    function _buildLogEntry(msg, cat, tsMs) {
       const div = document.createElement('div');
       let cls = '';
       if (/⚠|warn|pause|insufficient/i.test(msg)) cls = 'log-warn';
       else if (/✅|complete|✓|success/i.test(msg)) cls = 'log-ok';
       else if (/error|fail|ERR/i.test(msg)) cls = 'log-err';
       div.className = 'log-entry ' + cls;
       div.dataset.cat = cat || logCategory(msg);
-      const ts = new Date().toLocaleTimeString('en-US', { hour12: false });
+      const ts = tsMs != null ? new Date(tsMs).toLocaleTimeString('en-US', { hour12: false }) : '';
       // Escape all five HTML-significant chars (incl. " and ') BEFORE linkifying.
       // Without quote-escaping, an attacker-controlled URL containing a double
       // quote (e.g. from an untrusted node operator's remote_addrs) would break
@@ -2129,10 +2144,14 @@ <h1 style="margin:0;flex:0 0 auto">SENTINEL NODE TEST</h1>
       return div;
     }
 
-    // Live single-line append: one row, one reflow — fine at live cadence.
-    function appendLog(msg, cat) {
+    // Live single-line append: one row, one reflow — fine at live cadence. A
+    // direct string call is a line happening NOW; an object entry carries its
+    // own emission ts.
+    function appendLog(entry, cat) {
       const body = document.getElementById('logBody');
-      body.appendChild(_buildLogEntry(msg, cat));
+      const { msg, ts } = _logEntryFields(entry);
+      const tsMs = (entry && typeof entry === 'object') ? ts : Date.now();
+      body.appendChild(_buildLogEntry(msg, cat, tsMs));
       body.scrollTop = body.scrollHeight;
       if (body.children.length > LOG_DOM_MAX) body.removeChild(body.firstChild);
     }
@@ -2145,12 +2164,16 @@ <h1 style="margin:0;flex:0 0 auto">SENTINEL NODE TEST</h1>
     // appendLog enforces anyway, so the visible result is identical), (b) build
     // them into a single DocumentFragment, and (c) insert + scroll exactly once.
     // One reflow instead of thousands.
-    function appendLogBatch(msgs) {
-      if (!Array.isArray(msgs) || msgs.length === 0) return;
+    function appendLogBatch(entries) {
+      if (!Array.isArray(entries) || entries.length === 0) return;
       const body = document.getElementById('logBody');
-      const tail = msgs.length > LOG_DOM_MAX ? msgs.slice(-LOG_DOM_MAX) : msgs;
+      const tail = entries.length > LOG_DOM_MAX ? entries.slice(-LOG_DOM_MAX) : entries;
       const frag = document.createDocumentFragment();
-      for (const m of tail) frag.appendChild(_buildLogEntry(m));
+      // Replay uses each line's STORED emission ts (null → blank) — never now.
+      for (const e of tail) {
+        const { msg, ts } = _logEntryFields(e);
+        frag.appendChild(_buildLogEntry(msg, undefined, ts));
+      }
       body.appendChild(frag);
       body.scrollTop = body.scrollHeight;
       while (body.children.length > LOG_DOM_MAX) body.removeChild(body.firstChild);

audit/pipeline.js

@@ -603,7 +603,12 @@ export async function runAudit(resume, state, broadcast, preloadedNodes = null,
     auditLogPath = path.join(PROJECT_ROOT, 'results', `audit-${logTs}.log`);
     state.auditLogPath = auditLogPath;
   }
-  const logLine = (msg) => { try { appendFileSync(auditLogPath, msg + '\n', 'utf8'); } catch {} };
+  // Prefix each persisted line with an ISO emission timestamp (`[<ISO>] <msg>`)
+  // so the server can recover WHEN a line was produced when it rehydrates the
+  // log buffer from disk after a restart — see server.js parseLogLine. Written
+  // at logLine-call time, which is ≈ emission (the broadcast tee fires it
+  // synchronously right after the line is emitted).
+  const logLine = (msg) => { try { appendFileSync(auditLogPath, `[${new Date().toISOString()}] ${msg}\n`, 'utf8'); } catch {} };
   if (resume) {
     logLine(`${'='.repeat(32)}`);
     logLine(`RESUMED: ${new Date().toISOString()}`);

live.html

@@ -1387,6 +1387,19 @@ <h1 class="live-page-title">
       const body = document.getElementById('logBody');
       if (!body) return;
 
+      // Buffer/replay + raw 'log' SSE lines arrive as { ts, msg } (server-stamped
+      // emission time). They behave like plain string lines (classify by message
+      // shape) but carry their own time. Distinguish them from the rich
+      // structured lifecycle objects — which always carry tag/cat/status — by
+      // shape, unwrap to the string path, and remember the emission ts.
+      let _emitTs = null;   // emission time in ms, or null = unknown → blank
+      let _haveTs = false;  // entry specified its own time (vs. happening now)
+      if (opts && typeof opts === 'object' && ('msg' in opts) && !('tag' in opts) && !('cat' in opts) && !('status' in opts)) {
+        _emitTs = (typeof opts.ts === 'number') ? opts.ts : null;
+        _haveTs = true;
+        opts = String(opts.msg == null ? '' : opts.msg);
+      }
+
       let o;
       if (typeof opts === 'string') {
         // Derive cat/tag from the message shape so historical/backfilled
@@ -1434,7 +1447,11 @@ <h1 class="live-page-title">
       div.className = 'log-entry ' + cls;
       div.dataset.cat = o.cat || 'sys';
 
-      const ts = new Date().toLocaleTimeString('en-US', { hour12: false });
+      // A normalised { ts, msg } entry uses its STORED emission time (null →
+      // blank, never a misleading now); live structured lifecycle objects are
+      // happening now.
+      const tsMs = _haveTs ? _emitTs : Date.now();
+      const ts = tsMs != null ? new Date(tsMs).toLocaleTimeString('en-US', { hour12: false }) : '';
       const parts = [`<span class="log-time">${ts}</span>`];
 
       // Tag pill
@@ -2340,7 +2357,8 @@ <h1 class="live-page-title">
           break;
         }
         case 'log': {
-          if (d.msg) appendLog(d.msg);
+          // Carry the server's emission ts so the line shows WHEN it happened.
+          if (d.msg) appendLog({ ts: d.ts, msg: d.msg });
           break;
         }
         case 'state': {

server.js

@@ -310,7 +310,7 @@ function classifyLogCategory(msg) {
 // diagnostics are hidden from spectators (the admin dashboard still shows all).
 // Filters the rolling string buffer for the public log endpoints.
 function publicLogBuffer() {
-  return logBuffer.filter(m => classifyLogCategory(m) === 'node');
+  return logBuffer.filter(e => classifyLogCategory(e.msg) === 'node');
 }
 
 // EVENTS persist to a file (separate from per-run runs/test-NNN/audit.log), with
@@ -337,10 +337,15 @@ function appendEventLog(msg) {
 function broadcast(type, data = {}) {
   if (type === 'log' && data.msg) {
     // Tag the live SSE 'log' event with a category so admin/live can filter
-    // without re-deriving it. logBuffer stays an array of strings (the client
-    // re-classifies replayed init lines). Set BEFORE emitter.emit below.
+    // without re-deriving it. Set BEFORE emitter.emit below.
     data.cat = data.cat || classifyLogCategory(data.msg);
-    logBuffer.push(data.msg);
+    // Stamp emission time ONCE, here, so every surface shows WHEN a line was
+    // produced — not when the client rendered/replayed it. The ts rides on the
+    // live SSE event (data.ts), the in-memory buffer ({ts,msg}), and — via the
+    // pipeline's ISO-prefixed logLine — the on-disk audit log, so it survives a
+    // restart too. Buffer entries are {ts,msg} objects; consumers read .msg.
+    if (data.ts == null) data.ts = Date.now();
+    logBuffer.push({ ts: data.ts, msg: data.msg });
     if (logBuffer.length > LOG_BUFFER_MAX) logBuffer.shift();
     if (data.cat === 'events') appendEventLog(data.msg);
   }
@@ -560,13 +565,26 @@ try { state.activeSDK = _rfs(SDK_PREF_FILE, 'utf8').trim() || 'js'; } catch { st
 // boot (after snapshot restore) and on /api/resume so the SSE init replay
 // always carries the in-flight run's full prior log history — not the last
 // few lines, and not a different file's contents.
+// Parse one on-disk audit line back into a {ts,msg} buffer entry. Lines are
+// written as `[<ISO>] <msg>` by audit/pipeline.js logLine. Recover the emission
+// timestamp when the prefix is present; lines from older runs (no prefix) yield
+// ts:null so the client renders a BLANK time rather than a misleading one.
+function parseLogLine(line) {
+  const m = /^\[(\d{4}-\d\d-\d\dT[\d:.]+Z)\]\s([\s\S]*)$/.exec(line);
+  if (m) {
+    const t = Date.parse(m[1]);
+    return { ts: Number.isNaN(t) ? null : t, msg: m[2] };
+  }
+  return { ts: null, msg: line };
+}
+
 function hydrateLogBufferFromFile(filePath) {
   try {
     const txt = _rfs(filePath, 'utf8');
     const lines = txt.split('\n').filter(l => l.trim());
     const tail = lines.slice(-LOG_BUFFER_MAX);
     logBuffer.length = 0;
-    logBuffer.push(...tail);
+    logBuffer.push(...tail.map(parseLogLine));
     return tail.length;
   } catch { return 0; }
 }
@@ -1959,6 +1977,9 @@ function sanitizeForPublic(evt) {
   if (evt.testedAt != null)   safe.testedAt   = evt.testedAt;
   if (evt.msg != null)        safe.msg        = String(evt.msg).slice(0, 400);
   if (evt.cat != null)        safe.cat        = evt.cat;
+  // Emission timestamp — lets /live show WHEN a line was produced, not when it
+  // was rendered (matters for the seeded backlog + reconnect replay).
+  if (evt.ts != null)         safe.ts         = evt.ts;
   if (evt.baselineMbps != null) safe.baselineMbps = evt.baselineMbps;
   if (evt.skipped === true)   safe.skipped    = true;
   if (evt.inPlan === true)    safe.inPlan     = true;

test/admin-log-batch.test.js

@@ -43,7 +43,7 @@ function extractFn(src, name) {
   return src.slice(m.index, j);
 }
 
-const FNS = ['escHtml', 'logCategory', '_logEntryMatches', '_buildLogEntry', 'appendLog', 'appendLogBatch'];
+const FNS = ['escHtml', 'logCategory', '_logEntryMatches', '_logEntryFields', '_buildLogEntry', 'appendLog', 'appendLogBatch'];
 const extracted = FNS.map(n => extractFn(html, n)).join('\n\n');
 
 // ─── Fake DOM ──────────────────────────────────────────────────────────────
@@ -144,6 +144,37 @@ for (let i = 0; i < 600; i++) {
 ok(logBody.children.length === LOG_DOM_MAX,
    `single-line appends trim to ${LOG_DOM_MAX} (got ${logBody.children.length})`);
 
+// ─── 5. Emission-time: replay uses stored ts, never render-time ──────────────
+console.log('[5] replay shows EMISSION time, live shows current time');
+logBody._children = [];
+const T = Date.parse('2026-06-15T08:30:45.000Z');
+const expectedTs = new Date(T).toLocaleTimeString('en-US', { hour12: false });
+vm.runInContext('appendLogBatch(globalThis.__tsEntries)',
+  Object.assign(sandbox, { __tsEntries: [{ ts: T, msg: 'restored line' }] }));
+const tsRow = logBody.children[0].innerHTML;
+ok(tsRow.includes(`<span class="log-time">${expectedTs}</span>`),
+   `replayed { ts, msg } renders its EMISSION time (${expectedTs})`);
+
+// A bare string (unknown emission time) renders a BLANK time, not a fake now.
+logBody._children = [];
+vm.runInContext('appendLogBatch(["legacy bare line"])', sandbox);
+ok(logBody.children[0].innerHTML.includes('<span class="log-time"></span>'),
+   'replayed bare string (no ts) renders a BLANK time, not render-time');
+
+// A direct live string append is happening NOW → non-empty current time.
+logBody._children = [];
+vm.runInContext('appendLog("live line happening now")', sandbox);
+const liveTime = /<span class="log-time">([^<]+)<\/span>/.exec(logBody.children[0].innerHTML);
+ok(liveTime && liveTime[1].trim().length > 0,
+   'live string append stamps the current time (non-blank)');
+
+// A live object entry { ts, msg } (e.g. a 'log' SSE line) uses its server ts.
+logBody._children = [];
+vm.runInContext('appendLog(globalThis.__liveObj)',
+  Object.assign(sandbox, { __liveObj: { ts: T, msg: 'sse live line' } }));
+ok(logBody.children[0].innerHTML.includes(`<span class="log-time">${expectedTs}</span>`),
+   'live { ts, msg } SSE line uses the server emission ts');
+
 console.log(`\n${'='.repeat(60)}\nRESULTS: ${out.pass} passed, ${out.fail} failed (${out.pass + out.fail} total)`);
 if (out.errors.length) for (const e of out.errors) console.log(`  FAIL: ${e}`);
 console.log('='.repeat(60));