From c3518821ae9ec40c14b635559c46bd02a0f2e4d5 Mon Sep 17 00:00:00 2001 From: tryeverything24 <114252040+tryeverything24@users.noreply.github.com> Date: Sun, 26 Jul 2026 04:09:27 +0300 Subject: [PATCH] fix(mcp): await the local MCP telemetry PostHog flush before recordMcpToolCall resolves recordMcpToolCall constructed a PostHog client, called capture(), and returned synchronously -- fire-and-forget, with no awaited flush. Since capture() returns before the network POST lands, a --stdio process that exits shortly after a tool call silently dropped the in-flight event. Mirror the remote src/mcp/telemetry.ts fix (80f4aec99, #7233) exactly: recordMcpToolCall is now async and awaits client.flush() after capture, inside the same never-throw catch. The guarantee is threaded through the stdio chokepoint -- recordStdioToolTelemetry awaits the wrapper and registerStdioTool awaits it on both the success and throw paths -- so the event is on the wire before the tool response goes out. Per-call client construction is kept (not cached): with flushAt 1, flushInterval 0 and the flush awaited to completion, each client holds no queued events or pending work by the time the promise resolves, so nothing accumulates across a long session. Closes #8690 --- packages/loopover-mcp/bin/loopover-mcp.ts | 13 ++- packages/loopover-mcp/lib/telemetry.ts | 20 +++- test/unit/mcp-local-telemetry.test.ts | 120 +++++++++++++++++----- 3 files changed, 118 insertions(+), 35 deletions(-) diff --git a/packages/loopover-mcp/bin/loopover-mcp.ts b/packages/loopover-mcp/bin/loopover-mcp.ts index 4baef27098..026cbe7c44 100644 --- a/packages/loopover-mcp/bin/loopover-mcp.ts +++ b/packages/loopover-mcp/bin/loopover-mcp.ts @@ -1709,12 +1709,17 @@ export const server = new McpServer({ // recordMcpToolCall's own never-throw guarantee (#6236), mirroring recordMcpToolTelemetry on the remote side // (#6237). // +// Awaited end-to-end (#8690, mirroring the remote #7233 fix): recordMcpToolCall resolves only once the +// PostHog event has actually been flushed, and registerStdioTool awaits this wrapper before returning the +// tool result, so the event is on the wire before the stdio response goes out -- a client that disconnects +// (or a process that exits) right after a tool call no longer silently drops the in-flight event. +// // Reads the opt-in flag HERE, at module scope, on purpose: registerStdioTool's second parameter is the TOOL's // config and shadows the module-level `config` this resolves from, so a read inside that function would silently // see the wrong object and never fire. -function recordStdioToolTelemetry(tool: any, ok: any, durationMs: any) { +async function recordStdioToolTelemetry(tool: any, ok: any, durationMs: any) { try { - recordLocalMcpToolCall({ telemetryEnabled: telemetryState().enabled }, { tool, callerType: "local", ok, durationMs }); + await recordLocalMcpToolCall({ telemetryEnabled: telemetryState().enabled }, { tool, callerType: "local", ok, durationMs }); } catch { // Telemetry must never affect the tool response (#6238). } @@ -1727,10 +1732,10 @@ function registerStdioTool(name: any, config: any, handler: any) { const result = await handler(...args); // Mirror the remote's caller-visible outcome (`response.status < 400`): a handler that reports failure by // returning an error result is not a success, even though it never threw. - recordStdioToolTelemetry(name, result?.isError !== true, Date.now() - startedAt); + await recordStdioToolTelemetry(name, result?.isError !== true, Date.now() - startedAt); return result; } catch (error) { - recordStdioToolTelemetry(name, false, Date.now() - startedAt); + await recordStdioToolTelemetry(name, false, Date.now() - startedAt); throw error; } }); diff --git a/packages/loopover-mcp/lib/telemetry.ts b/packages/loopover-mcp/lib/telemetry.ts index 122805dce9..c04bca7f63 100644 --- a/packages/loopover-mcp/lib/telemetry.ts +++ b/packages/loopover-mcp/lib/telemetry.ts @@ -9,8 +9,9 @@ import { PostHog } from "posthog-node"; // // SAFE NO-OP: unless the caller passes `telemetryEnabled: true` AND LOOPOVER_MCP_POSTHOG_API_KEY is set, // this records nothing and behaves byte-identically to before this module existed -- true for every user -// who has not run `loopover-mcp telemetry enable` (the default). It also never throws: a PostHog init/ -// capture failure degrades to recording nothing, so it can never affect the CLI's actual command behavior. +// who has not run `loopover-mcp telemetry enable` (the default). It also never throws/rejects: a PostHog +// init/capture/flush failure degrades to recording nothing, so it can never affect the CLI's actual +// command behavior. /** PostHog US-cloud ingestion host -- the default when LOOPOVER_MCP_POSTHOG_HOST isn't set. */ const DEFAULT_POSTHOG_HOST = "https://us.i.posthog.com"; @@ -29,8 +30,16 @@ export type McpToolCallEvent = { tool: string; callerType?: "local"; ok: boolean * Record a single local MCP tool call to PostHog. Safe no-op unless `telemetryEnabled` is explicitly * `true` (the caller's resolved, persisted opt-in flag, default OFF -- #6236) AND * LOOPOVER_MCP_POSTHOG_API_KEY is configured; never throws. + * + * Returns a promise that resolves once the event has actually been flushed to PostHog (#8690, + * mirroring the remote wrapper's #7233 fix) -- 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()` means the caller + * (bin/loopover-mcp.js's `recordStdioToolTelemetry`) knows the event has been sent (or definitively + * failed) before it returns, so a stdio process that exits shortly after a tool call no longer + * silently drops the in-flight event. */ -export function recordMcpToolCall(options: RecordMcpToolCallOptions, event: McpToolCallEvent): void { +export async function recordMcpToolCall(options: RecordMcpToolCallOptions, event: McpToolCallEvent): Promise { // Opt-in default OFF (#6236, per #6228's privacy decision) -- unlike the remote wrapper, presence of an // API key alone is not enough; the user must have explicitly enabled telemetry. if (options?.telemetryEnabled !== true) return; @@ -55,9 +64,10 @@ export function recordMcpToolCall(options: RecordMcpToolCallOptions, event: McpT // 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 CLI (#6236): 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 CLI (#6236): a PostHog init/capture/flush + // failure degrades to recording nothing, identical to the unconfigured path above. } } diff --git a/test/unit/mcp-local-telemetry.test.ts b/test/unit/mcp-local-telemetry.test.ts index 5eb1149c89..1720ecc543 100644 --- a/test/unit/mcp-local-telemetry.test.ts +++ b/test/unit/mcp-local-telemetry.test.ts @@ -1,12 +1,22 @@ import { afterEach, 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. -// Mirrors test/unit/mcp-telemetry.test.ts's mock for the remote wrapper (#6235). +// 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. Mirrors test/unit/mcp-telemetry.test.ts's mock for the remote wrapper (#6235). +// `flushGate`, when set, is what the mocked flush awaits before resolving -- it stands in for the real +// network round-trip so #8690's tests can hold the "request" in flight and observe recordMcpToolCall's +// returned promise while it is still pending. 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, + flushGate: null as Promise | null, + flushCompleted: false, + }, })); vi.mock("posthog-node", () => ({ @@ -19,6 +29,12 @@ vi.mock("posthog-node", () => ({ h.captureSpy(message); if (h.state.throwOnCapture) throw new Error("posthog capture failed"); } + async flush(): Promise { + h.flushSpy(); + if (h.state.throwOnFlush) throw new Error("posthog flush failed"); + if (h.state.flushGate) await h.state.flushGate; + h.state.flushCompleted = true; + } }, })); @@ -29,49 +45,62 @@ type CapturedMessage = { distinctId: string; event: string; properties: Record { + await new Promise((resolve) => setImmediate(resolve)); +} + describe("recordMcpToolCall (local MCP wrapper, #6236)", () => { beforeEach(() => { h.constructSpy.mockClear(); h.captureSpy.mockClear(); + h.flushSpy.mockClear(); h.state.throwOnConstruct = false; h.state.throwOnCapture = false; + h.state.throwOnFlush = false; + h.state.flushGate = null; + h.state.flushCompleted = false; }); afterEach(() => { vi.unstubAllEnvs(); }); - it("is a safe no-op when telemetry is not opted in, even with an API key configured", () => { + it("is a safe no-op when telemetry is not opted in, even with an API key configured", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); - recordMcpToolCall({ telemetryEnabled: false }, EVENT); + await recordMcpToolCall({ telemetryEnabled: false }, EVENT); expect(h.constructSpy).not.toHaveBeenCalled(); expect(h.captureSpy).not.toHaveBeenCalled(); + expect(h.flushSpy).not.toHaveBeenCalled(); }); - it("is a safe no-op when telemetryEnabled is omitted (default OFF)", () => { + it("is a safe no-op when telemetryEnabled is omitted (default OFF)", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); - recordMcpToolCall({}, EVENT); + await recordMcpToolCall({}, EVENT); expect(h.constructSpy).not.toHaveBeenCalled(); expect(h.captureSpy).not.toHaveBeenCalled(); + expect(h.flushSpy).not.toHaveBeenCalled(); }); - it("is a safe no-op when opted in but LOOPOVER_MCP_POSTHOG_API_KEY is unset", () => { + it("is a safe no-op when opted in but LOOPOVER_MCP_POSTHOG_API_KEY is unset", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", undefined); - recordMcpToolCall({ telemetryEnabled: true }, EVENT); + await recordMcpToolCall({ telemetryEnabled: true }, 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", () => { + it("treats a blank/whitespace API key as unconfigured", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", " "); - recordMcpToolCall({ telemetryEnabled: true }, EVENT); + await recordMcpToolCall({ telemetryEnabled: true }, EVENT); expect(h.constructSpy).not.toHaveBeenCalled(); expect(h.captureSpy).not.toHaveBeenCalled(); + expect(h.flushSpy).not.toHaveBeenCalled(); }); - it("captures exactly the allowlisted fields against the US-cloud default host when opted in and configured", () => { + it("captures exactly the allowlisted fields against the US-cloud default host when opted in and configured", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); - recordMcpToolCall({ telemetryEnabled: true }, EVENT); + await recordMcpToolCall({ telemetryEnabled: true }, EVENT); expect(h.constructSpy).toHaveBeenCalledTimes(1); expect(h.constructSpy).toHaveBeenCalledWith("phc_test", { @@ -93,11 +122,39 @@ describe("recordMcpToolCall (local MCP wrapper, #6236)", () => { }); // 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"]); + // #8690 (mirroring the remote #7233): the event is actually flushed, not just queued, before the + // returned promise resolves. + expect(h.flushSpy).toHaveBeenCalledTimes(1); + }); + + it("does not resolve until the mocked flush/network call completes (#8690)", async () => { + vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); + // The mocked network round-trip resolves on a delay, standing in for a PostHog POST still in flight. + h.state.flushGate = new Promise((resolve) => setTimeout(resolve, 25)); + + let settled = false; + const pending = recordMcpToolCall({ telemetryEnabled: true }, EVENT).then(() => { + settled = true; + }); + + // The event has been captured and the flush is in flight, but the promise must still be pending. + // Before #8690, recordMcpToolCall had already returned synchronously at this point, with the network + // call fired and forgotten. + await drainMicrotasks(); + expect(h.captureSpy).toHaveBeenCalledTimes(1); + expect(h.flushSpy).toHaveBeenCalledTimes(1); + expect(settled).toBe(false); + expect(h.state.flushCompleted).toBe(false); + + await pending; + // Resolution happened, and only after the mocked network call actually completed. + expect(settled).toBe(true); + expect(h.state.flushCompleted).toBe(true); }); - it("defaults callerType to local when the caller omits it", () => { + it("defaults callerType to local when the caller omits it", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); - recordMcpToolCall({ telemetryEnabled: true }, { tool: "status", ok: false, durationMs: 0 }); + await recordMcpToolCall({ telemetryEnabled: true }, { tool: "status", ok: false, durationMs: 0 }); const message = h.captureSpy.mock.calls[0]![0] as CapturedMessage; expect(message.properties).toEqual({ @@ -108,10 +165,10 @@ describe("recordMcpToolCall (local MCP wrapper, #6236)", () => { }); }); - it("honors a LOOPOVER_MCP_POSTHOG_HOST override and carries a failed call verbatim", () => { + it("honors a LOOPOVER_MCP_POSTHOG_HOST override and carries a failed call verbatim", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); vi.stubEnv("LOOPOVER_MCP_POSTHOG_HOST", "https://eu.i.posthog.com"); - recordMcpToolCall({ telemetryEnabled: true }, { tool: "check_slop_risk", callerType: "local", ok: false, durationMs: 7 }); + await recordMcpToolCall({ telemetryEnabled: true }, { tool: "check_slop_risk", callerType: "local", ok: false, durationMs: 7 }); expect(h.constructSpy).toHaveBeenCalledWith("phc_test", { host: "https://eu.i.posthog.com", @@ -127,10 +184,10 @@ describe("recordMcpToolCall (local MCP wrapper, #6236)", () => { }); }); - it("trims surrounding whitespace from the API key and host", () => { + it("trims surrounding whitespace from the API key and host", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", " phc_test "); vi.stubEnv("LOOPOVER_MCP_POSTHOG_HOST", " https://eu.i.posthog.com "); - recordMcpToolCall({ telemetryEnabled: true }, EVENT); + await recordMcpToolCall({ telemetryEnabled: true }, EVENT); expect(h.constructSpy).toHaveBeenCalledWith("phc_test", { host: "https://eu.i.posthog.com", flushAt: 1, @@ -138,10 +195,10 @@ describe("recordMcpToolCall (local MCP wrapper, #6236)", () => { }); }); - it("falls back to the default host when LOOPOVER_MCP_POSTHOG_HOST is blank", () => { + it("falls back to the default host when LOOPOVER_MCP_POSTHOG_HOST is blank", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); vi.stubEnv("LOOPOVER_MCP_POSTHOG_HOST", " "); - recordMcpToolCall({ telemetryEnabled: true }, EVENT); + await recordMcpToolCall({ telemetryEnabled: true }, EVENT); expect(h.constructSpy).toHaveBeenCalledWith("phc_test", { host: "https://us.i.posthog.com", flushAt: 1, @@ -149,17 +206,28 @@ describe("recordMcpToolCall (local MCP wrapper, #6236)", () => { }); }); - it("never throws when the PostHog client fails to initialize", () => { + it("never throws when the PostHog client fails to initialize", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); h.state.throwOnConstruct = true; - expect(() => recordMcpToolCall({ telemetryEnabled: true }, EVENT)).not.toThrow(); + await expect(recordMcpToolCall({ telemetryEnabled: true }, EVENT)).resolves.toBeUndefined(); expect(h.captureSpy).not.toHaveBeenCalled(); + expect(h.flushSpy).not.toHaveBeenCalled(); }); - it("never throws when capture itself fails", () => { + it("never throws when capture itself fails", async () => { vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); h.state.throwOnCapture = true; - expect(() => recordMcpToolCall({ telemetryEnabled: true }, EVENT)).not.toThrow(); + await expect(recordMcpToolCall({ telemetryEnabled: true }, 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 rejects when flush itself fails (#8690) -- the event was captured/queued regardless", async () => { + vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); + h.state.throwOnFlush = true; + await expect(recordMcpToolCall({ telemetryEnabled: true }, EVENT)).resolves.toBeUndefined(); expect(h.captureSpy).toHaveBeenCalledTimes(1); + expect(h.flushSpy).toHaveBeenCalledTimes(1); }); });