diff --git a/packages/loopover-mcp/bin/loopover-mcp.ts b/packages/loopover-mcp/bin/loopover-mcp.ts index b016c15160..acd1e842ac 100644 --- a/packages/loopover-mcp/bin/loopover-mcp.ts +++ b/packages/loopover-mcp/bin/loopover-mcp.ts @@ -44,9 +44,8 @@ import { buildBranchAnalysisPayload, collectLocalDiff, collectLocalBranchMetadat import { formatTable } from "../lib/format-table.js"; import { argsWantJson, describeCliError, reportCliFailure } from "../lib/cli-error.js"; import { redactKnownLocalPaths, redactLocalPath } from "../lib/redact-local-path.js"; -// Aliased: this file's own recordStdioToolTelemetry is the chokepoint that calls it, and the two names sitting -// side by side unaliased would read as the same function (#6238). -import { recordMcpToolCall as recordLocalMcpToolCall } from "../lib/telemetry.js"; +// wrapStdioToolHandler owns the await-flush chokepoint (#8690); bin only wires telemetryState().enabled. +import { wrapStdioToolHandler } from "../lib/telemetry.js"; // Self-referencing package import (Node's own mechanism for "resolve a file that belongs to my own // package, correctly, regardless of my own current location on disk") -- requires the "exports" map @@ -1721,38 +1720,14 @@ export const server = new McpServer({ // #4777: register a stdio tool under its loopover_ name. Thin wrapper kept so all 37 call sites // stay uniform with the rest of this file's registration style. -// Single chokepoint for the #6228 PostHog tool-call telemetry (#6238): every registerStdioTool-registered tool -// routes through here exactly once per invocation, whether it returns or throws. Pure observability -- a -// telemetry failure must never reach the tool caller, so this keeps a defensive try/catch on top of -// recordMcpToolCall's own never-throw guarantee (#6236), mirroring recordMcpToolTelemetry on the remote side -// (#6237). -// -// 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) { - try { - recordLocalMcpToolCall({ telemetryEnabled: telemetryState().enabled }, { tool, callerType: "local", ok, durationMs }); - } catch { - // Telemetry must never affect the tool response (#6238). - } -} - +// Telemetry await/flush lives in wrapStdioToolHandler (lib/telemetry.ts, unit-tested) — #6238 / #8690. +// Reads telemetryState() HERE on purpose: registerStdioTool's second parameter is the TOOL's config and +// shadows the module-level `config`, so a read inside a nested function would silently see the wrong object. +/* v8 ignore start -- thin registration glue; wrapStdioToolHandler covered by unit tests (#8690) */ function registerStdioTool(name: any, config: any, handler: any) { - server.registerTool(name, config, async (...args) => { - const startedAt = Date.now(); - try { - 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); - return result; - } catch (error) { - recordStdioToolTelemetry(name, false, Date.now() - startedAt); - throw error; - } - }); + server.registerTool(name, config, wrapStdioToolHandler(name, () => telemetryState().enabled, handler)); } +/* v8 ignore stop */ registerStdioTool( "loopover_get_repo_context", diff --git a/packages/loopover-mcp/lib/telemetry.ts b/packages/loopover-mcp/lib/telemetry.ts index 122805dce9..5b6524c80d 100644 --- a/packages/loopover-mcp/lib/telemetry.ts +++ b/packages/loopover-mcp/lib/telemetry.ts @@ -29,8 +29,18 @@ 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 `src/mcp/telemetry.ts` fix (#7233). `capture()` itself is fire-and-forget and + * returns before the network POST lands; awaiting `client.flush()` lets the stdio server (and any + * short-lived CLI path) hold the process open until the event is sent or definitively failed. + * + * Client lifetime: constructs a fresh PostHog client per call (same as the remote wrapper) rather than + * reusing one across the process. That keeps each call's flush/shutdown self-contained and avoids + * holding an idle long-lived client in a long-running `--stdio` session; the flush-before-return + * guarantee does not depend on process-exit hooks. */ -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,12 +65,59 @@ 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. } } +/** + * Stdio-tool chokepoint (#6238 / #8690): every registerStdioTool-registered tool routes through here + * once per invocation. Awaits {@link recordMcpToolCall}'s flush, and never lets a telemetry failure + * reach the tool caller (defensive try/catch on top of recordMcpToolCall's own never-throw guarantee). + */ +export async function recordStdioToolTelemetry( + telemetryEnabled: boolean, + tool: string, + ok: boolean, + durationMs: number, + record: (options: RecordMcpToolCallOptions, event: McpToolCallEvent) => Promise = recordMcpToolCall, +): Promise { + try { + await record({ telemetryEnabled }, { tool, callerType: "local", ok, durationMs }); + } catch { + // Telemetry must never affect the tool response (#6238). + } +} + +type StdioToolHandler = (...args: any[]) => Promise; + +/** + * Wrap a stdio tool handler so success and throw paths both await telemetry flush before returning + * (#8690). Lives in lib/ (not bin/) so codecov/patch can attribute the await branches via unit tests; + * bin registration stays thin glue. + */ +export function wrapStdioToolHandler( + name: string, + getTelemetryEnabled: () => boolean, + handler: StdioToolHandler, +): StdioToolHandler { + return async (...args) => { + const startedAt = Date.now(); + try { + 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. + await recordStdioToolTelemetry(getTelemetryEnabled(), name, result?.isError !== true, Date.now() - startedAt); + return result; + } catch (error) { + await recordStdioToolTelemetry(getTelemetryEnabled(), name, false, Date.now() - startedAt); + throw error; + } + }; +} + /** Trim a possibly-undefined env string, treating blank/whitespace as absent. */ function trimmedOrUndefined(value: string | undefined): string | undefined { const trimmed = value?.trim(); diff --git a/test/unit/mcp-local-telemetry.test.ts b/test/unit/mcp-local-telemetry.test.ts index 5eb1149c89..7ba9cc5ddb 100644 --- a/test/unit/mcp-local-telemetry.test.ts +++ b/test/unit/mcp-local-telemetry.test.ts @@ -1,12 +1,19 @@ 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/#7233). 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, + /** Optional deferred flush body for proving await-before-resolve (#8690). */ + flushImpl: null as null | (() => Promise), + }, })); vi.mock("posthog-node", () => ({ @@ -19,10 +26,17 @@ 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.flushImpl) await h.state.flushImpl(); + } }, })); -const { recordMcpToolCall } = await import("../../packages/loopover-mcp/lib/telemetry.js"); +const { recordMcpToolCall, recordStdioToolTelemetry, wrapStdioToolHandler } = await import( + "../../packages/loopover-mcp/lib/telemetry.js" +); type LocalToolCallEvent = { tool: string; callerType?: "local"; ok: boolean; durationMs: number }; type CapturedMessage = { distinctId: string; event: string; properties: Record; disableGeoip: boolean }; @@ -33,45 +47,52 @@ 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.flushImpl = null; }); 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 +114,40 @@ 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: the event is actually flushed, not just queued, before recordMcpToolCall's promise resolves. + expect(h.flushSpy).toHaveBeenCalledTimes(1); + }); + + it("does not resolve until a delayed flush completes (#8690)", async () => { + vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); + let releaseFlush!: () => void; + const flushGate = new Promise((resolve) => { + releaseFlush = resolve; + }); + h.state.flushImpl = async () => { + await flushGate; + }; + + let settled = false; + const pending = recordMcpToolCall({ telemetryEnabled: true }, EVENT).then(() => { + settled = true; + }); + + // Give the capture/flush path a turn on the microtask queue without releasing flush. + await Promise.resolve(); + await Promise.resolve(); + expect(h.captureSpy).toHaveBeenCalledTimes(1); + expect(h.flushSpy).toHaveBeenCalledTimes(1); + expect(settled).toBe(false); + + releaseFlush(); + await pending; + expect(settled).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 +158,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 +177,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 +188,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 +199,128 @@ 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 throws 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); + }); +}); + +describe("recordStdioToolTelemetry / wrapStdioToolHandler (#8690)", () => { + beforeEach(() => { + h.constructSpy.mockClear(); + h.captureSpy.mockClear(); + h.flushSpy.mockClear(); + h.state.throwOnConstruct = false; + h.state.throwOnCapture = false; + h.state.throwOnFlush = false; + h.state.flushImpl = null; + }); + + afterEach(() => { + vi.unstubAllEnvs(); + }); + + it("awaits flush before recordStdioToolTelemetry resolves when opted in", async () => { + vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); + let releaseFlush!: () => void; + const flushGate = new Promise((resolve) => { + releaseFlush = resolve; + }); + h.state.flushImpl = async () => { + await flushGate; + }; + + let settled = false; + const pending = recordStdioToolTelemetry(true, "loopover_status", true, 12).then(() => { + settled = true; + }); + await Promise.resolve(); + await Promise.resolve(); + expect(h.flushSpy).toHaveBeenCalledTimes(1); + expect(settled).toBe(false); + releaseFlush(); + await pending; + expect(settled).toBe(true); + }); + + it("swallows a throwing recorder without rejecting (#6238)", async () => { + await expect( + recordStdioToolTelemetry(true, "loopover_status", true, 1, async () => { + throw new Error("recorder boom"); + }), + ).resolves.toBeUndefined(); + expect(h.constructSpy).not.toHaveBeenCalled(); + }); + + it("wrapStdioToolHandler awaits telemetry on success and preserves the handler result", async () => { + vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); + let releaseFlush!: () => void; + const flushGate = new Promise((resolve) => { + releaseFlush = resolve; + }); + h.state.flushImpl = async () => { + await flushGate; + }; + + const wrapped = wrapStdioToolHandler("loopover_demo", () => true, async () => ({ ok: true, isError: false })); + let settled = false; + const pending = wrapped().then((result) => { + settled = true; + return result; + }); + await Promise.resolve(); + await Promise.resolve(); + expect(settled).toBe(false); + releaseFlush(); + await expect(pending).resolves.toEqual({ ok: true, isError: false }); + expect(h.flushSpy).toHaveBeenCalledTimes(1); + const message = h.captureSpy.mock.calls[0]![0] as CapturedMessage; + expect(message.properties).toMatchObject({ tool: "loopover_demo", ok: true }); + }); + + it("wrapStdioToolHandler treats isError results as failed telemetry ok=false", async () => { + vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); + const wrapped = wrapStdioToolHandler("loopover_demo", () => true, async () => ({ isError: true })); + await wrapped(); + const message = h.captureSpy.mock.calls[0]![0] as CapturedMessage; + expect(message.properties).toMatchObject({ tool: "loopover_demo", ok: false }); + }); + + it("wrapStdioToolHandler records ok=false then rethrows when the handler throws", async () => { + vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); + const wrapped = wrapStdioToolHandler("loopover_demo", () => true, async () => { + throw new Error("handler boom"); + }); + await expect(wrapped()).rejects.toThrow("handler boom"); + expect(h.flushSpy).toHaveBeenCalledTimes(1); + const message = h.captureSpy.mock.calls[0]![0] as CapturedMessage; + expect(message.properties).toMatchObject({ tool: "loopover_demo", ok: false }); + }); + + it("wrapStdioToolHandler is a no-op for PostHog when telemetry is disabled", async () => { + vi.stubEnv("LOOPOVER_MCP_POSTHOG_API_KEY", "phc_test"); + const wrapped = wrapStdioToolHandler("loopover_demo", () => false, async () => ({ ok: true })); + await expect(wrapped()).resolves.toEqual({ ok: true }); + expect(h.constructSpy).not.toHaveBeenCalled(); }); });