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 = {