feat(mcp): bounded first-load diagnostics experiment for #335

apps/mcp/README.md

@@ -95,11 +95,74 @@ The Worker takes the variables in the table below as Wrangler `vars` or secrets,
 | `MCP_ALLOWED_ORIGINS` | Comma-separated allowed browser origin hostnames. A configured list replaces defaults; an explicitly empty list permits no Origin header value. Requests without Origin remain supported. |
 | `MCP_RESPONSE_MODE` | `json` for modern MCP final-answer-only responses; otherwise SSE, which supports client-requested progress notifications. Older-host compatibility responses may use SSE. |
 | `ANSARI_RELEASE` | Optional safe release identifier, embedded in served HTML and health/log records. |
+| `MCP_VIEW_DIAGNOSTICS_ORIGIN` | Set only on a deployment being diagnosed: its own public origin, such as `https://ansari-mcp-development.up.railway.app`. The card may then connect to that one origin and reports its start-up milestones to `POST /diag/view`; this changes the card's bytes, address and permissions. Unset, the card, its address and its closed permissions are unchanged and the route does not exist. A value that is not a bare `https` origin (`http` only for localhost) stops startup. Implies `MCP_LOG_LEVEL=debug`. See [First-load diagnosis](#first-load-diagnosis). |
+| `MCP_LOG_LEVEL` | `info` (default) or `debug`. `debug` also writes the first-load measurement records; set it only on a deployment being measured. Any other value, or `info` together with `MCP_VIEW_DIAGNOSTICS_ORIGIN`, stops startup. |
 
 `POST /mcp` serves stateless MCP requests through Hono and the official MCP request handler. Modern requests need no initialization; older hosts can use the handler’s stateless compatibility path. No MCP session IDs, session map, expiry timer or replay store are retained. `GET /mcp` and `DELETE /mcp` return 405. `/health` exposes the release. The HTML is supplied by the hosting target (read from `dist/` at Node start, bundled into the Worker), revision-stamped and fingerprinted once before the first request is served: the release is stamped first, so equal final bytes have equal identities and a release change legitimately changes the hash. Each request creates its own lightweight MCP server using that prepared view; resource bytes and identity stay fixed until restart. No demo, font server, alternative renderer or historical resource is served. Tool calls have a fresh 60-second budget; timeout yields a safe error and leaves subsequent calls usable. The same lifetime signal aborts the upstream fetch and response-body read when the request ends or the budget expires.
 
 Closing a request server releases its budget even if it was never connected to a transport. On SIGINT or SIGTERM the listener stops accepting requests, closes MCP handlers and HTTP connections, and exits; unfinished calls are interrupted, including older-host SSE calls. Fetch cancellation does not guarantee that the remote backend has stopped processing. Caller-disconnect propagation depends on the host transport; the local Workers runtime does not establish immediate upstream cancellation from a client disconnect. Actual fetch cancellation at the request deadline is covered on both hosting targets.
 
+## First-load diagnosis
+
+A bounded experiment for issue #335, not a permanent observability design. In Claude web and ChatGPT web the host's
+own error replaced the card on first load and one Retry recovered it; the card's own failure texts never appeared, so
+the host gave up before the card showed anything. The aim is to locate the first missing step between the card read,
+the card's start, the host handshake, tool-result arrival and the first rendered answer, where that step can be
+observed at all. After the trials, this is removed or narrowed to what proved useful.
+
+**Log levels.** Every record carries a `level`. `error`: `mcp.error` and `source.error`, by error name and code only.
+`warn`: rejected or rate-limited card reports. `info`: the operational records (`startup`, `mcp.request` with the HTTP
+method, `source.start`, `source.complete`). `debug`: the measurement records below, written only with
+`MCP_LOG_LEVEL=debug`. At `info` the server neither inspects nor wraps an exchange, and it writes the records of a
+deployment without this experiment, plus a level on each and error
+names and codes; dropping the `debug` lines from a measured deployment leaves the same records.
+
+**Server records, while measuring.** Each `/mcp` exchange also writes `mcp.rpc` and `mcp.response` lines joined by
+`rid`. The request is inspected from a copy, alongside the handler and up to 64 KiB actually read, so inspection never holds up
+or alters the exchange; a larger body is recorded as `oversize`. The request line names the JSON-RPC method; for a card
+read, the address read and whether it is the one this instance serves (`uriCurrent`); for the handshake, the client's
+name, version and protocol; for a tool call, the tool name. The response line has the HTTP status, bytes, time to
+headers and total time, and `stream`: whether this side's response stream was `drained`, `cancelled` or `failed`. That
+is not proof the host received or rendered it. Responses up to 64 KiB are decoded as JSON-RPC for an error code; a
+stale card read is `-32602` inside an HTTP 200. At start, `view.prepared` records the served card's address, size,
+whether it is a diagnostic card and its connect origins. Handler errors are logged by name and code. These records hold
+no question, answer or other parameter value. A closed-card trial still needs these records: set
+`MCP_LOG_LEVEL=debug` and leave `MCP_VIEW_DIAGNOSTICS_ORIGIN` unset.
+
+**Card reports, diagnostic card only.** With `MCP_VIEW_DIAGNOSTICS_ORIGIN` set, the served card carries an
+`ansari-diagnostics` address in its head, may connect to that one origin, and changes bytes, address and permissions.
+Compare its trials with the closed card's rather than assuming they behave the same. An early script, which runs
+before the bundle is parsed, records errors, unhandled rejections, content-policy violations and when the host's
+messages arrive (first message, tool input, tool result, cancellation, teardown request), by method name only. The
+stack's hooks add font loading, host-context delivery, how starting ended and the first rendered answer or problem. The
+early script reports by itself at `load`, at `pagehide` and after 15 s without a start, so a bundle that never runs is
+still reported; the bundle adds reports when the card is ready, fails, or renders its first answer or problem. Each
+report is an `[ansari-view]` console line and a beacon to `POST /diag/view`. The route accepts only the fixed report
+shape, at most 8 KiB and 120 reports a minute per instance, and logs `view.report` (level `debug`) with `clientAuthored: true`: the
+shape limits what is logged, but anyone who can reach the route can send a report. Report fields are milestones,
+enumerated failures and error names; the stack still prints a callback's own error to the console, as before. One
+violation is expected on every load: zod's `new Function('')` capability probe under the card's `script-src`, which it
+catches. The closed card's early script does nothing.
+
+**Trials.** Use the deployment for nothing else while a trial runs. Run one trial per new conversation, with the
+deployment live for hours (`aged`) and right after a redeploy (`fresh`), and with the diagnostic and the closed card.
+The trial script records the deployment's release and the first attempt and Retry as separate windows:
+
+```sh
+bash scripts/first-load-trial.sh https://ansari-mcp-development.up.railway.app claude aged diagnostic
+# Railway: deployment and edge HTTP logs covering the trials, then one timeline per trial.
+railway logs --deployment --json --since 1h > test-results/first-load/app.jsonl
+railway logs --http --json --since 1h > test-results/first-load/edge.jsonl
+node scripts/first-load-timeline.mjs test-results/first-load/trials.jsonl test-results/first-load/app.jsonl test-results/first-load/edge.jsonl
+```
+
+Records are attributed to an attempt by time only; neither `rid` nor a card's id links to the host's attempt. The
+timeline lists what was observed in each window and flags windows with more than one MCP client, overlapping trials or
+another release as ambiguous. A finding such as "no host message observed by its last report" says only that. Two
+controlled cases have known answers: a stale card read (`resources/read` of an earlier address, answered `-32602`) and
+a bundle that fails before it runs (covered by the browser checks: a `load` report without `main` and with the
+`SyntaxError`).
+
 ## Workspace and container
 
 This package lives at `apps/mcp` and is named `ansari-mcp`. The root `pnpm-lock.yaml` and `pnpm-workspace.yaml` are the only install inputs. `pnpm mcp <script>` targets this app. Shared TypeScript and lint tools use the workspace catalog; no application-local lockfile or standalone workspace is maintained.

apps/mcp/scripts/first-load-timeline.mjs

@@ -0,0 +1,111 @@
+#!/usr/bin/env node
+// Joins first-load trials (scripts/first-load-trial.sh) with the server's logs, one timeline per trial (#335).
+//
+// Usage: node scripts/first-load-timeline.mjs <trials.jsonl> <log.jsonl>...
+// Each log file holds JSON lines in any of three forms: the application's own records (`event`, with `at`),
+// Railway deployment logs (`railway logs --deployment --json`: `timestamp` and the record in `message`), or Railway
+// edge HTTP logs (`railway logs --http --json`: `timestamp`, path, status, duration and bytes).
+//
+// The server writes the records read here only while measuring (`MCP_LOG_LEVEL=debug`, which a diagnostic card
+// implies); their `level` is `debug`. Without them a window shows only edge and operational lines.
+//
+// Records are attributed to a trial by time only: neither a server `rid` nor a card id links to the host's attempt.
+// The timeline therefore says what was observed in each window, flags windows whose traffic may not be the trial's,
+// and never claims that something did not happen anywhere.
+import {readFileSync} from 'node:fs';
+
+const [trialsFile, ...logFiles] = process.argv.slice(2);
+if (!trialsFile || logFiles.length === 0) {
+  console.error('usage: node scripts/first-load-timeline.mjs <trials.jsonl> <log.jsonl>...');
+  process.exit(2);
+}
+const lines = file => readFileSync(file, 'utf8').split('\n').filter(line => line.trim()).flatMap(line => {
+  try { return [JSON.parse(line)]; } catch { return []; }
+});
+/** 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. */
+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};
+  const path = raw.path ?? raw.attributes?.path;
+  if (path !== undefined) return {event: 'edge', at: time, ...raw};
+  return undefined;
+}
+const entries = logFiles.flatMap(lines).map(normalize).filter(entry => entry && typeof entry.at === 'number').sort((a, b) => a.at - b.at);
+const trials = lines(trialsFile);
+
+function describe(entry, zero) {
+  const t = `+${((entry.at - zero) / 1000).toFixed(2)}s`.padStart(9);
+  switch (entry.event) {
+    case 'mcp.rpc': return `${t} → ${entry.rpc}${entry.uri ? ` ${entry.uri}${entry.uriCurrent === false ? ' (NOT CURRENT)' : ''}` : ''}${entry.client ? ` client=${entry.client}/${entry.clientVersion}` : ''} [${entry.rid}]`;
+    case 'mcp.response': return `${t} ← ${entry.rpc} ${entry.status} stream=${entry.stream} ${entry.bytes}B headers=${entry.headersMs}ms total=${entry.ms}ms${entry.errorCode === undefined ? '' : ` error=${entry.errorCode}`} [${entry.rid}]`;
+    case 'view.report': return `${t} ◆ card ${entry.view} ${entry.reason}${entry.failure ? ` failure=${entry.failure}` : ''} host=${entry.host ?? '?'} origin=${entry.origin} marks=${JSON.stringify(entry.marks)}${entry.errors?.length ? ` errors=${JSON.stringify(entry.errors)}` : ''}`;
+    case 'view.prepared': return `${t} ◇ serving ${entry.uri} ${entry.bytes}B diagnostics=${entry.diagnostics}`;
+    case 'edge': {
+      const pick = ['method', 'path', 'httpStatus', 'totalDuration', 'responseTime', 'txBytes', 'rxBytes', 'clientUa', 'responseDetails'];
+      return `${t} ▸ edge ${pick.map(key => entry[key] ?? entry.attributes?.[key]).filter(value => value !== undefined).join(' ')}`;
+    }
+    default: return `${t} · ${entry.event}${entry.rpc ? ` ${entry.rpc}` : ''}${entry.name ? ` ${entry.name}` : ''}${entry.code !== undefined ? ` code=${entry.code}` : ''}`;
+  }
+}
+
+/** What one attempt's window shows. Each finding is an observation in that window, not a claim about the host. */
+function findings(window, card) {
+  const out = [];
+  const reads = window.filter(entry => entry.event === 'mcp.rpc' && entry.rpc === 'resources/read');
+  const readEnds = window.filter(entry => entry.event === 'mcp.response' && entry.rpc === 'resources/read');
+  if (reads.length === 0) out.push('no card read was observed at the server in this window');
+  if (reads.some(entry => entry.uriCurrent === false)) out.push('a card address that is not the one this instance serves was read');
+  for (const end of readEnds) if (end.stream !== 'drained') out.push(`a card read stream was ${end.stream} after ${end.ms}ms and ${end.bytes}B`);
+  for (const end of readEnds) if (end.errorCode !== undefined) out.push(`a card read answered JSON-RPC error ${end.errorCode}`);
+  const slow = readEnds.filter(end => end.ms > 2_000);
+  if (slow.length) out.push(`card read streams slower than 2s on this side: ${slow.map(end => `${end.ms}ms`).join(', ')}`);
+  const cards = new Map();
+  for (const entry of window.filter(item => item.event === 'view.report')) cards.set(entry.view, entry);
+  if (card === 'diagnostic') out.push(`${cards.size} card instance(s) reported in this window${cards.size === 0 ? ' (none observed: a card may not have run, or its report did not arrive)' : ''}`);
+  for (const [id, last] of cards) {
+    const m = last.marks ?? {};
+    if (m.main === undefined) out.push(`card ${id}: the bundle had not evaluated by its last report (${last.reason})`);
+    if (m.teardownRequested !== undefined && m.ready === undefined) out.push(`card ${id}: the host asked for teardown before the card was ready, as of its last report`);
+    if (last.failure) out.push(`card ${id}: start failed (${last.failure})`);
+    if (m.ready !== undefined && m.script !== undefined && m.ready - m.script > 3_000) out.push(`card ${id}: ${Math.round(m.ready - m.script)}ms from script start to ready`);
+    if (m.hostMessage === undefined) out.push(`card ${id}: no host message observed by its last report (${last.reason})`);
+  }
+  return out;
+}
+
+/** Signs that a window holds traffic other than this trial's, so its records cannot be attributed with confidence. */
+function ambiguity(window, trial) {
+  const out = [];
+  const clients = new Set(window.filter(entry => entry.event === 'mcp.rpc' && entry.client).map(entry => `${entry.client}/${entry.clientVersion}`));
+  if (clients.size > 1) out.push(`${clients.size} different MCP clients: ${[...clients].join(', ')}`);
+  const overlapping = trials.filter(other => other !== trial && Date.parse(other.start) < Date.parse(trial.end) && Date.parse(other.end) > Date.parse(trial.start));
+  if (overlapping.length) out.push(`${overlapping.length} other trial(s) overlap this one`);
+  const releases = new Set(window.filter(entry => entry.release).map(entry => entry.release));
+  if (trial.release && trial.release !== 'unknown' && releases.size && ![...releases].every(release => release === trial.release)) out.push(`records from releases ${[...releases].join(', ')}, trial recorded ${trial.release}`);
+  return out;
+}
+
+for (const trial of trials) {
+  const start = Date.parse(trial.start);
+  const end = Date.parse(trial.end);
+  const retryAt = trial.retryAt ? Date.parse(trial.retryAt) : undefined;
+  const all = entries.filter(entry => entry.at >= start - LEAD_MS && entry.at <= end);
+  const serving = entries.filter(entry => entry.event === 'view.prepared' && entry.at <= end).at(-1);
+  console.log(`\n=== ${trial.host} / ${trial.deploy} / ${trial.card ?? '?'} card / ${trial.label}: first=${trial.first} retry=${trial.retry}`);
+  console.log(`    release ${trial.release ?? '?'} at ${trial.origin ?? '?'}; serving ${serving ? `${serving.uri} (${serving.bytes}B, diagnostics=${serving.diagnostics})` : 'not observed in these logs'}`);
+  for (const warning of ambiguity(all, trial)) console.log(`  ? AMBIGUOUS: ${warning}`);
+  const attempts = [['first attempt', start - LEAD_MS, retryAt ?? end]];
+  if (retryAt !== undefined) attempts.push(['retry', retryAt, end]);
+  for (const [name, from, to] of attempts) {
+    const window = entries.filter(entry => entry.at >= from && entry.at < to || (to === end && entry.at === end));
+    console.log(`  -- ${name} (${new Date(from).toISOString()} → ${new Date(to).toISOString()})`);
+    for (const entry of window) console.log(describe(entry, start));
+    for (const finding of findings(window, trial.card)) console.log(`  ! ${finding}`);
+  }
+}