From 78bb0cc91fa108cd08372c1159c5e7188878b405 Mon Sep 17 00:00:00 2001 From: Younes Abouelnagah Date: Thu, 5 Nov 2026 10:20:02 -0500 Subject: [PATCH] fix(mcp): place Railway log records by their own time in the first-load timeline `railway logs --deployment --json` lifts each JSON record's fields to the top level and adds `timestamp`, when Railway collected the line in batches. The timeline took that branch and replaced the record's own `at` with Railway's `timestamp`, so records were reordered and some fell outside the trial window they belonged to. On the 30 October evidence, 65 of 98 records were off by more than 50 ms, and up to 13.2 s. No per-trial finding changes. The record's own `at` now wins; `timestamp` remains the fallback for lines without one. A test drives the script with Railway-shaped lines. Co-Authored-By: Claude Opus 5.5 --- apps/mcp/scripts/first-load-timeline.mjs | 8 +++- apps/mcp/test/first-load-timeline.test.ts | 56 +++++++++++++++++++++++ 2 files changed, 62 insertions(+), 2 deletions(-) create mode 100644 apps/mcp/test/first-load-timeline.test.ts 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\]/); +});