Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 9 additions & 6 deletions src/mcp/server.ts
Original file line number Diff line number Diff line change
Expand Up @@ -1654,10 +1654,11 @@ export async function handleMcpRequest(c: AppContext): Promise<Response> {
const usageMetadata = await describeMcpUsageRequest(c.req.raw, telemetry.metadata);
const startedAt = Date.now();
const server = new LoopoverMcp(c.env, identity).createServer();
const executionCtx = getExecutionContext(c);
try {
const response = await createMcpHandler(server, { route: "/mcp", enableJsonResponse: true })(c.req.raw, c.env, getExecutionContext(c));
const response = await createMcpHandler(server, { route: "/mcp", enableJsonResponse: true })(c.req.raw, c.env, executionCtx);
if (typeof usageMetadata.toolName === "string") {
recordMcpToolTelemetry(c.env, usageMetadata.toolName, response.status < 400, Date.now() - startedAt);
executionCtx.waitUntil(recordMcpToolTelemetry(c.env, usageMetadata.toolName, response.status < 400, Date.now() - startedAt));
}
await recordProductUsageEvent(c.env, {
surface: "mcp",
Expand All @@ -1675,7 +1676,7 @@ export async function handleMcpRequest(c: AppContext): Promise<Response> {
return response;
} catch (error) {
if (typeof usageMetadata.toolName === "string") {
recordMcpToolTelemetry(c.env, usageMetadata.toolName, false, Date.now() - startedAt);
executionCtx.waitUntil(recordMcpToolTelemetry(c.env, usageMetadata.toolName, false, Date.now() - startedAt));
}
await recordProductUsageEvent(c.env, {
surface: "mcp",
Expand All @@ -1697,10 +1698,12 @@ export async function handleMcpRequest(c: AppContext): Promise<Response> {
// Single chokepoint for the #6228 PostHog tool-call telemetry (#6237): every `tools/call` request that
// reaches handleMcpRequest routes through here exactly once, whether it succeeds or throws. Pure
// observability -- never lets a telemetry failure reach the caller, matching recordMcpToolCall's own
// no-op guarantee (#6235) with a second, defensive layer at the actual call site.
function recordMcpToolTelemetry(env: Env, tool: string, ok: boolean, durationMs: number): void {
// no-op guarantee (#6235) with a second, defensive layer at the actual call site. Called sites pass the
// returned promise to `waitUntil` (#7233) rather than awaiting it inline, so a slow PostHog flush can't
// delay the MCP tool response.
async function recordMcpToolTelemetry(env: Env, tool: string, ok: boolean, durationMs: number): Promise<void> {
try {
recordMcpToolCall(env, { tool, callerType: "remote", ok, durationMs });
await recordMcpToolCall(env, { tool, callerType: "remote", ok, durationMs });
} catch {
// Telemetry must never affect the tool response (#6237).
}
Expand Down
16 changes: 12 additions & 4 deletions src/mcp/telemetry.ts
Original file line number Diff line number Diff line change
Expand Up @@ -49,8 +49,15 @@ export interface McpToolCallEvent {
export type McpTelemetryEnv = Pick<Env, "POSTHOG_API_KEY" | "POSTHOG_HOST">;

/** Record a single MCP tool call to PostHog. Safe no-op when telemetry is unconfigured (no POSTHOG_API_KEY),
* and never throws — a PostHog init/capture failure degrades to recording nothing (#6235). */
export function recordMcpToolCall(env: McpTelemetryEnv, event: McpToolCallEvent): void {
* and never throws — a PostHog init/capture failure degrades to recording nothing (#6235).
*
* Returns a promise that resolves once the event has actually been flushed to PostHog (#7233) — the
* `flushAt: 1, flushInterval: 0` config makes `capture()` queue the network request immediately, but
* `capture()` itself is fire-and-forget and returns before that request lands. Awaiting `client.flush()`
* gives the caller (src/mcp/server.ts's `recordMcpToolTelemetry`, deferred via Cloudflare's `waitUntil`)
* real async work to hold the execution context open for, so the event isn't silently dropped if the
* Workers runtime tears the request down before an un-awaited background fetch completes. */
export async function recordMcpToolCall(env: McpTelemetryEnv, event: McpToolCallEvent): Promise<void> {
const apiKey = trimmedOrUndefined(env.POSTHOG_API_KEY);
// Unconfigured ⇒ record nothing, byte-identical to before this module existed.
if (!apiKey) return;
Expand All @@ -71,9 +78,10 @@ export function recordMcpToolCall(env: McpTelemetryEnv, event: McpToolCallEvent)
// No IP-based geo enrichment: the event is anonymous fleet telemetry, not a user location.
disableGeoip: true,
});
await client.flush();
} catch {
// Telemetry is best-effort and MUST NOT throw into the MCP tool caller (#6235): a PostHog init/capture
// failure degrades to recording nothing, identical to the unconfigured path above.
// Telemetry is best-effort and MUST NOT throw into the MCP tool caller (#6235): a PostHog init/capture/
// flush failure degrades to recording nothing, identical to the unconfigured path above.
}
}

Expand Down
51 changes: 51 additions & 0 deletions test/unit/mcp-server-telemetry.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -187,6 +187,57 @@ describe("MCP server telemetry", () => {
);
});

it("defers tool-call telemetry via executionCtx.waitUntil instead of firing it synchronously and forgetting it (#7233)", async () => {
vi.resetModules();
vi.doMock("agents/mcp", () => ({
createMcpHandler: () => () => Response.json({ ok: true }),
}));
let flushRecordMcpToolCall: (() => void) | undefined;
const recordMcpToolCallStarted = new Promise<void>((resolve) => {
flushRecordMcpToolCall = resolve;
});
const recordMcpToolCall = vi.fn(async () => {
flushRecordMcpToolCall?.();
});
vi.doMock("../../src/mcp/telemetry", () => ({ recordMcpToolCall }));
const { handleMcpRequest } = await import("../../src/mcp/server");
const env = createTestEnv({ PRODUCT_USAGE_HASH_SALT: "mcp-wait-until-telemetry-salt" });
const request = new Request("https://api.test/mcp", {
method: "POST",
headers: {
authorization: `Bearer ${env.LOOPOVER_MCP_TOKEN}`,
"content-type": "application/json",
},
body: JSON.stringify({ jsonrpc: "2.0", id: "tool-call", method: "tools/call", params: { name: "loopover_local_status" } }),
});

const waitUntilTasks: Promise<unknown>[] = [];
await expect(
handleMcpRequest({
env,
executionCtx: {
waitUntil(task: Promise<unknown>) {
waitUntilTasks.push(task);
},
passThroughOnException() {},
},
req: {
method: "POST",
raw: request,
header: (name: string) => request.headers.get(name) ?? undefined,
},
json: (body: unknown, status?: number) => Response.json(body, status === undefined ? undefined : { status }),
} as never),
).resolves.toMatchObject({ status: 200 });

// The telemetry promise was handed to waitUntil (not just fired-and-forgotten inline) before the response
// returned, and awaiting it resolves cleanly once the deferred recordMcpToolCall actually runs.
expect(waitUntilTasks).toHaveLength(1);
await recordMcpToolCallStarted;
await expect(waitUntilTasks[0]).resolves.toBeUndefined();
expect(recordMcpToolCall).toHaveBeenCalledTimes(1);
});

it("does not let a throwing recordMcpToolCall affect the tool response (#6237)", async () => {
vi.resetModules();
vi.doMock("agents/mcp", () => ({
Expand Down
58 changes: 39 additions & 19 deletions test/unit/mcp-telemetry.test.ts
Original file line number Diff line number Diff line change
@@ -1,11 +1,13 @@
import { beforeEach, describe, expect, it, vi } from "vitest";

// Mock the PostHog Node SDK so nothing hits the network: the class records every constructor + capture call
// on hoisted spies, and per-test flags let us force an init/capture failure to exercise the never-throw path.
// Mock the PostHog Node SDK so nothing hits the network: the class records every constructor + capture +
// flush call on hoisted spies, and per-test flags let us force an init/capture/flush failure to exercise
// the never-throw path.
const h = vi.hoisted(() => ({
constructSpy: vi.fn(),
captureSpy: vi.fn(),
state: { throwOnConstruct: false, throwOnCapture: false },
flushSpy: vi.fn(),
state: { throwOnConstruct: false, throwOnCapture: false, throwOnFlush: false },
}));

vi.mock("posthog-node", () => ({
Expand All @@ -18,6 +20,10 @@ vi.mock("posthog-node", () => ({
h.captureSpy(message);
if (h.state.throwOnCapture) throw new Error("posthog capture failed");
}
async flush(): Promise<void> {
h.flushSpy();
if (h.state.throwOnFlush) throw new Error("posthog flush failed");
}
},
}));

Expand All @@ -29,24 +35,27 @@ describe("recordMcpToolCall", () => {
beforeEach(() => {
h.constructSpy.mockClear();
h.captureSpy.mockClear();
h.flushSpy.mockClear();
h.state.throwOnConstruct = false;
h.state.throwOnCapture = false;
h.state.throwOnFlush = false;
});

it("is a safe no-op when POSTHOG_API_KEY is unset (unconfigured deployment)", () => {
recordMcpToolCall({}, EVENT);
it("is a safe no-op when POSTHOG_API_KEY is unset (unconfigured deployment)", async () => {
await recordMcpToolCall({}, EVENT);
expect(h.constructSpy).not.toHaveBeenCalled();
expect(h.captureSpy).not.toHaveBeenCalled();
expect(h.flushSpy).not.toHaveBeenCalled();
});

it("treats a blank/whitespace API key as unconfigured", () => {
recordMcpToolCall({ POSTHOG_API_KEY: " " }, EVENT);
it("treats a blank/whitespace API key as unconfigured", async () => {
await recordMcpToolCall({ POSTHOG_API_KEY: " " }, EVENT);
expect(h.constructSpy).not.toHaveBeenCalled();
expect(h.captureSpy).not.toHaveBeenCalled();
});

it("captures exactly the allowlisted fields against the US-cloud default host when configured", () => {
recordMcpToolCall({ POSTHOG_API_KEY: "phc_test" }, EVENT);
it("captures exactly the allowlisted fields against the US-cloud default host when configured", async () => {
await recordMcpToolCall({ POSTHOG_API_KEY: "phc_test" }, EVENT);

expect(h.constructSpy).toHaveBeenCalledTimes(1);
expect(h.constructSpy).toHaveBeenCalledWith("phc_test", {
Expand All @@ -73,10 +82,12 @@ describe("recordMcpToolCall", () => {
});
// The allowlist is the whole payload — no argument/source/wallet/hotkey/trust-score field can ride along.
expect(Object.keys(message.properties).sort()).toEqual(["caller_type", "duration_ms", "ok", "tool"]);
// #7233: the event is actually flushed, not just queued, before recordMcpToolCall's promise resolves.
expect(h.flushSpy).toHaveBeenCalledTimes(1);
});

it("honors a POSTHOG_HOST override and carries a local caller / failed call verbatim", () => {
recordMcpToolCall(
it("honors a POSTHOG_HOST override and carries a local caller / failed call verbatim", async () => {
await recordMcpToolCall(
{ POSTHOG_API_KEY: "phc_test", POSTHOG_HOST: "https://eu.i.posthog.com" },
{ tool: "check_slop_risk", callerType: "local", ok: false, durationMs: 0 },
);
Expand All @@ -95,33 +106,42 @@ describe("recordMcpToolCall", () => {
});
});

it("trims surrounding whitespace from the API key and host", () => {
recordMcpToolCall({ POSTHOG_API_KEY: " phc_test ", POSTHOG_HOST: " https://eu.i.posthog.com " }, EVENT);
it("trims surrounding whitespace from the API key and host", async () => {
await recordMcpToolCall({ POSTHOG_API_KEY: " phc_test ", POSTHOG_HOST: " https://eu.i.posthog.com " }, EVENT);
expect(h.constructSpy).toHaveBeenCalledWith("phc_test", {
host: "https://eu.i.posthog.com",
flushAt: 1,
flushInterval: 0,
});
});

it("falls back to the default host when POSTHOG_HOST is blank", () => {
recordMcpToolCall({ POSTHOG_API_KEY: "phc_test", POSTHOG_HOST: " " }, EVENT);
it("falls back to the default host when POSTHOG_HOST is blank", async () => {
await recordMcpToolCall({ POSTHOG_API_KEY: "phc_test", POSTHOG_HOST: " " }, EVENT);
expect(h.constructSpy).toHaveBeenCalledWith("phc_test", {
host: "https://us.i.posthog.com",
flushAt: 1,
flushInterval: 0,
});
});

it("never throws when the PostHog client fails to initialize", () => {
it("never throws when the PostHog client fails to initialize", async () => {
h.state.throwOnConstruct = true;
expect(() => recordMcpToolCall({ POSTHOG_API_KEY: "phc_test" }, EVENT)).not.toThrow();
await expect(recordMcpToolCall({ POSTHOG_API_KEY: "phc_test" }, EVENT)).resolves.toBeUndefined();
expect(h.captureSpy).not.toHaveBeenCalled();
});

it("never throws when capture itself fails", () => {
it("never throws when capture itself fails", async () => {
h.state.throwOnCapture = true;
expect(() => recordMcpToolCall({ POSTHOG_API_KEY: "phc_test" }, EVENT)).not.toThrow();
await expect(recordMcpToolCall({ POSTHOG_API_KEY: "phc_test" }, EVENT)).resolves.toBeUndefined();
expect(h.captureSpy).toHaveBeenCalledTimes(1);
// capture() threw, so flush() is never reached — same catch branch as the constructor failure above.
expect(h.flushSpy).not.toHaveBeenCalled();
});

it("never throws when flush itself fails (#7233) — the event was captured/queued regardless", async () => {
h.state.throwOnFlush = true;
await expect(recordMcpToolCall({ POSTHOG_API_KEY: "phc_test" }, EVENT)).resolves.toBeUndefined();
expect(h.captureSpy).toHaveBeenCalledTimes(1);
expect(h.flushSpy).toHaveBeenCalledTimes(1);
});
});