From 6854d31afccdab4476de6160de08126ff21cbcb3 Mon Sep 17 00:00:00 2001 From: Aaron Lisman Date: Sun, 18 Oct 2026 17:16:13 +0000 Subject: [PATCH] Federation: log every MCP call at both ends MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit To see that a study really is answered over MCP, every federated call now writes one line where this app asks a peer and one where its /api/mcp answers (lib/federation-log.ts): [federation →] federated_aggregates study=… peer=… (this app, as its simulated peer) 214ms ok 0.9 kB [federation ←] federated_aggregates study=… caller=this app (answered as its simulated peer) 89ms HTTP 200 answered 1.1 kB [federation ←] federated_patient_timeline study=… (patient-level) caller=outside 461ms HTTP 200 REFUSED The tool, the study and (patient-level tools) the table — never the arguments, so never a patient. The answering side logs once the response has been written (a streamed one is not when returned) and says whether the call was refused; a failed outbound call logs why. README: how to read them. Verified: scripts/gate.sh green (1258 unit, 253 e2e). The federation stage's production build logged 44 outgoing and 46 incoming calls (the extra two the e2e's outside callers, both refused), each once, with no patient id anywhere in the log. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01QLBVrkqBG7J7pqX6Qygx3z --- README.md | 15 +++++++++++++++ app/api/[transport]/route.ts | 19 ++++++++++++++++++- lib/federation-log.ts | 27 +++++++++++++++++++++++++++ lib/federation-remote.ts | 16 +++++++++++++++- 4 files changed, 75 insertions(+), 2 deletions(-) create mode 100644 lib/federation-log.ts diff --git a/README.md b/README.md index d1bbe6dc..c8d34ec9 100644 --- a/README.md +++ b/README.md @@ -61,6 +61,21 @@ Measured cost (`docs/DATA-BOUNDARY.md`, "Federation: where it stands"): about +0 analysis for aggregate views on a small study, about +2 s for the patient-level views; on a large study the database's own time dominates. +### Seeing it work + +Every federated call is logged at both ends (`lib/federation-log.ts`), in the server's output +(on Vercel, the project's runtime logs) — the study and tool, never a patient: + +``` +[federation →] federated_aggregates study=nsclc_public_genie_bpc peer=https://cbiolab.vercel.app/api/mcp (this app, as its simulated peer) 214ms ok 0.9 kB +[federation ←] federated_aggregates study=nsclc_public_genie_bpc caller=this app (answered as its simulated peer) 89ms HTTP 200 answered 1.1 kB +[federation ←] federated_patient_timeline study=nsclc_public_genie_bpc (patient-level) caller=outside 461ms HTTP 200 REFUSED +``` + +`→` is this app asking a peer, `←` its `/api/mcp` answering; `caller=outside` is anyone else. An +analysis answered from the result cache makes no calls, so it logs none. A `[boundary]` line means +a query reached the simulated peer's database directly and was refused (`lib/ch.ts`) — a bug. + ### Security notes - **No caller authentication yet.** Anyone who can reach a peer's `/api/mcp` can call it. On a diff --git a/app/api/[transport]/route.ts b/app/api/[transport]/route.ts index 24172e21..00ae0ae0 100644 --- a/app/api/[transport]/route.ts +++ b/app/api/[transport]/route.ts @@ -3,6 +3,7 @@ import { createMcpHandler } from "mcp-handler"; import { registerTools } from "../../../mcp/tools.ts"; import { cachedAnalysis, cachedContract } from "../../../lib/next-cache.ts"; import { asLoopbackPeer, isLoopbackRequest } from "../../../lib/loopback-peer.ts"; +import { logInbound } from "../../../lib/federation-log.ts"; const handler = createMcpHandler( (server) => registerTools(server, { runAnalysis: (doc) => cachedAnalysis(doc), buildContract: cachedContract }), @@ -11,7 +12,23 @@ const handler = createMcpHandler( ); // a call this app made to itself is answered as its simulated peer (lib/loopback-peer.ts) -const serve = (req: Request) => isLoopbackRequest(req) ? asLoopbackPeer(() => handler(req)) : handler(req); +const serve = async (req: Request) => { + const asPeer = isLoopbackRequest(req); + const call = req.method === "POST" ? await toolCall(req) : null; + const t0 = Date.now(); + const res = await (asPeer ? asLoopbackPeer(() => handler(req)) : handler(req)); + // logged once the answer has been written, which a streamed response is not when it is returned + if (call) void res.clone().text().then((body) => logInbound(call.name, call.args, asPeer, Date.now() - t0, res.status, body), () => {}); + return res; +}; + +/** The tool a JSON-RPC request calls, for the log (lib/federation-log.ts); read from a copy. */ +async function toolCall(req: Request): Promise<{ name: string; args: unknown } | null> { + try { + const body = await req.clone().json(); + return body?.method === "tools/call" && typeof body.params?.name === "string" ? { name: body.params.name, args: body.params.arguments } : null; + } catch { return null; } +} export { serve as GET, serve as POST, serve as DELETE }; export const maxDuration = 60; diff --git a/lib/federation-log.ts b/lib/federation-log.ts new file mode 100644 index 00000000..7f47d277 --- /dev/null +++ b/lib/federation-log.ts @@ -0,0 +1,27 @@ +// One log line per federated MCP call, at each end, so a deployment's runtime logs show that a +// study really was answered over MCP: "[federation →]" where this app asks a peer (lib/federation- +// remote.ts), "[federation ←]" where its /api/mcp answers a call (app/api/[transport]/route.ts). +// A line names the tool, the study, the peer or caller, how long and how much — never a patient: +// the arguments are not logged, only the study and, for the patient-level tools, the table. + +const kb = (n: number) => (n / 1024).toFixed(1) + " kB"; + +/** What a call is about, from its arguments: the study, and the table a patient-level call reads. */ +function subject(tool: string, args: unknown): string { + const a = (args && typeof args === "object" ? args : {}) as Record; + const study = typeof a.study === "string" ? " study=" + a.study.slice(0, 80) : ""; + const table = typeof a.table === "string" ? " table=" + a.table.slice(0, 40) : ""; + return study + table + (tool.startsWith("federated_patient") ? " (patient-level)" : ""); +} + +/** A call this app made to a peer. */ +export function logOutbound(tool: string, args: unknown, url: string, loopback: boolean, ms: number, outcome: { bytes: number } | { error: string }): void { + const end = "error" in outcome ? "FAILED: " + outcome.error.slice(0, 200) : "ok " + kb(outcome.bytes); + console.log("[federation →] " + tool + subject(tool, args) + " peer=" + url + (loopback ? " (this app, as its simulated peer)" : "") + " " + ms + "ms " + end); +} + +/** A tool call this app's MCP endpoint answered. */ +export function logInbound(tool: string, args: unknown, asPeer: boolean, ms: number, status: number, body: string): void { + const refused = /"isError"\s*:\s*true/.test(body); + console.log("[federation ←] " + tool + subject(tool, args) + " caller=" + (asPeer ? "this app (answered as its simulated peer)" : "outside") + " " + ms + "ms HTTP " + status + " " + (refused ? "REFUSED" : "answered " + kb(body.length))); +} diff --git a/lib/federation-remote.ts b/lib/federation-remote.ts index 6cbeff06..ce70bb7d 100644 --- a/lib/federation-remote.ts +++ b/lib/federation-remote.ts @@ -16,6 +16,7 @@ import type { AggregateCapable, GeneCounts, Instance, SurvivalCount, PairCounts, import { carriesPatientIds, studyRouting } from "./federation.ts"; import { loopbackConnId, loopbackHeaders, loopbackUrl, servingAsLoopbackPeer } from "./loopback-peer.ts"; import { loopbackOnlyConn, noteFailedQuery } from "./ch.ts"; +import { logOutbound } from "./federation-log.ts"; import { PEER_TABLES, type RemotePatientRows, type PeerRowsRequest, type PeerRowsAnswer } from "./federation.ts"; import { acceptedFromPeers, allowedKinds, PATIENT_KIND_NAMES, type PatientKind } from "./disclosure.ts"; import type { PatientTimeline, PatientEvent, PatientSample } from "./types.ts"; @@ -121,7 +122,20 @@ export function peerPatientKinds(study: string): Set { */ async function mcpCall(url: string, name: string, args: unknown): Promise { // a peer that refused or did not answer is a failed query: whatever this answer becomes is not cached - try { return await mcpCallOnce(url, name, args); } catch (e) { noteFailedQuery(); throw e; } + const t0 = Date.now(), loopback = isLoopbackCall(url); + try { + const out = await mcpCallOnce(url, name, args); + logOutbound(name, args, url, loopback, Date.now() - t0, { bytes: JSON.stringify(out).length }); + return out; + } catch (e) { + logOutbound(name, args, url, loopback, Date.now() - t0, { error: String((e as Error)?.message || e) }); + noteFailedQuery(); + throw e; + } +} +/** Whether a call to `url` is this app calling itself, for the log; never throws. */ +function isLoopbackCall(url: string): boolean { + try { return Object.keys(loopbackHeaders(url)).length > 0; } catch { return false; } } async function mcpCallOnce(url: string, name: string, args: unknown): Promise { const headers: Record = {