diff --git a/apps/mcp/scripts/first-load-timeline.mjs b/apps/mcp/scripts/first-load-timeline.mjs index b02c3acd..c7f4ccbd 100644 --- a/apps/mcp/scripts/first-load-timeline.mjs +++ b/apps/mcp/scripts/first-load-timeline.mjs @@ -25,13 +25,17 @@ const lines = file => readFileSync(file, 'utf8').split('\n').filter(line => line /** Records before the first window's start that still belong to it (discovery right before sending). */ const LEAD_MS = 2_000; -/** One normalized entry: when, what kind, and the fields worth printing. */ +/** + * One normalized entry: when, what kind, and the fields worth printing. An application record's own `at` is when it + * happened. Railway's `timestamp` is when Railway collected the line, in batches, so it is only the fallback: preferring + * it reorders records and moves them out of the window they belong to. + */ function normalize(raw) { const time = Date.parse(raw.timestamp ?? '') || raw.at; if (typeof raw.message === 'string' && raw.message.startsWith('{')) { try { const record = JSON.parse(raw.message); return {...record, at: record.at ?? time}; } catch { /* plain text line */ } } - if (raw.event) return {...raw, at: time}; + if (raw.event) return {...raw, at: typeof raw.at === 'number' ? raw.at : time}; const path = raw.path ?? raw.attributes?.path; if (path !== undefined) return {event: 'edge', at: time, ...raw}; return undefined; diff --git a/apps/mcp/test/first-load-timeline.test.ts b/apps/mcp/test/first-load-timeline.test.ts new file mode 100644 index 00000000..0f92dafa --- /dev/null +++ b/apps/mcp/test/first-load-timeline.test.ts @@ -0,0 +1,56 @@ +import assert from 'node:assert/strict'; +import {test} from 'node:test'; +import {execFileSync} from 'node:child_process'; +import {mkdtempSync, rmSync, writeFileSync} from 'node:fs'; +import {tmpdir} from 'node:os'; +import {join} from 'node:path'; +import {fileURLToPath} from 'node:url'; + +const script = fileURLToPath(new URL('../scripts/first-load-timeline.mjs', import.meta.url)); +const at = (iso: string) => Date.parse(iso); + +function timeline(trials: object[], log: object[]) { + const dir = mkdtempSync(join(tmpdir(), 'first-load-timeline-')); + try { + const jsonl = (rows: object[]) => rows.map(row => JSON.stringify(row)).join('\n') + '\n'; + writeFileSync(join(dir, 'trials.jsonl'), jsonl(trials)); + writeFileSync(join(dir, 'app.jsonl'), jsonl(log)); + return execFileSync(process.execPath, [script, join(dir, 'trials.jsonl'), join(dir, 'app.jsonl')], {encoding: 'utf8'}); + } finally { + rmSync(dir, {recursive: true, force: true}); + } +} + +const trial = {host: 'claude', deploy: 'fresh', card: 'closed', label: 'order', first: 'card', retry: 'n-a', + start: '2026-10-30T12:00:10.000Z', end: '2026-10-30T12:00:20.000Z'}; + +// `railway logs --deployment --json` lifts a JSON record's fields to the top level and adds its own `timestamp`, which is +// when Railway collected the line, in batches. The record's own `at` is when it happened. +test('a Railway record is placed by its own time, not the batch timestamp Railway added', () => { + const out = timeline([trial], [ + {event: 'mcp.rpc', rpc: 'resources/read', rid: 'r3', at: at('2026-10-30T12:00:19.500Z'), timestamp: '2026-10-30T12:00:20.400Z', message: ''}, + {event: 'mcp.rpc', rpc: 'tools/list', rid: 'r1', at: at('2026-10-30T12:00:11.000Z'), timestamp: '2026-10-30T12:00:20.500Z', message: ''}, + {event: 'mcp.rpc', rpc: 'tools/call', rid: 'r2', at: at('2026-10-30T12:00:15.000Z'), timestamp: '2026-10-30T12:00:20.100Z', message: ''}, + ]); + const lines = out.split('\n').filter(line => /^\s*\+[\d.]+s → /.test(line)); + assert.deepEqual(lines.map(line => line.trim()), [ + '+1.00s → tools/list [r1]', + '+5.00s → tools/call [r2]', + '+9.50s → resources/read [r3]', + ]); + assert.doesNotMatch(out, /no card read was observed/); +}); + +test('a Railway line without its own time falls back to the batch timestamp', () => { + const out = timeline([trial], [ + {event: 'startup', timestamp: '2026-10-30T12:00:12.000Z', message: ''}, + ]); + assert.match(out, /\+2\.00s · startup/); +}); + +test('a record wrapped in a Railway message keeps its own time', () => { + const out = timeline([trial], [ + {timestamp: '2026-10-30T12:00:25.000Z', message: JSON.stringify({event: 'mcp.rpc', rpc: 'tools/call', rid: 'w1', at: at('2026-10-30T12:00:13.000Z')})}, + ]); + assert.match(out, /\+3\.00s → tools\/call \[w1\]/); +});