Federation: log every MCP call at both ends

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

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;

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<string, unknown>;
+  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)));
+}

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<PatientKind> {
  */
 async function mcpCall<T = RemoteAggregates>(url: string, name: string, args: unknown): Promise<T> {
   // a peer that refused or did not answer is a failed query: whatever this answer becomes is not cached
-  try { return await mcpCallOnce<T>(url, name, args); } catch (e) { noteFailedQuery(); throw e; }
+  const t0 = Date.now(), loopback = isLoopbackCall(url);
+  try {
+    const out = await mcpCallOnce<T>(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<T>(url: string, name: string, args: unknown): Promise<T> {
   const headers: Record<string, string> = {