From afa8750cbbca85e3ccb883538923413932427a45 Mon Sep 17 00:00:00 2001 From: Oliver Kieselbach Date: Wed, 5 Aug 2026 19:16:35 +0200 Subject: [PATCH] =?UTF-8?q?feat(mcp):=20tool-call=20quality=20telemetry=20?= =?UTF-8?q?=E2=80=94=20soft=20errors,=20result=20size,=20zero-hit=20search?= =?UTF-8?q?es,=20arg=20rejections?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit withToolTelemetry now receives the tool args and inspects the RESULT: handlers never throw (toolError returns isError:true), so the previous isError flag was effectively always false. Each MCP_TOOL_LOGGING line now carries soft-error status, resultChars + overCap (vs. the anthropic/maxResultSizeChars hint), a size-bounded args summary and the caller scope — the only telemetry that covers backend-free tools (search_docs, validate_rule, get_resource). New signals: search_zero_hit on the three search tools (unmet-demand signal) and tool_call_rejected for JSON-RPC-level Zod/unknown-tool rejections, sniffed at the /mcp route since the SDK answers those before any handler runs. Bicep default toolLoggingEnabled=true (desired state; live flag via az containerapp update). Docs: docs/mcp/tool-telemetry.md with KQL examples. Co-Authored-By: Claude Fable 5 --- docs/index.md | 1 + docs/log.md | 1 + docs/mcp/tool-telemetry.md | 75 +++++++++ infra/mcp-server.bicep | 4 +- .../src/__tests__/telemetry.test.ts | 152 ++++++++++++++++++ .../autopilot-monitor-mcp/src/index.ts | 28 ++++ .../autopilot-monitor-mcp/src/telemetry.ts | 141 ++++++++++++++-- .../autopilot-monitor-mcp/src/tools/admin.ts | 52 +++--- .../autopilot-monitor-mcp/src/tools/rules.ts | 4 +- .../autopilot-monitor-mcp/src/tools/search.ts | 17 +- .../src/tools/sessions.ts | 20 +-- 11 files changed, 436 insertions(+), 59 deletions(-) create mode 100644 docs/mcp/tool-telemetry.md create mode 100644 src/McpServer/autopilot-monitor-mcp/src/__tests__/telemetry.test.ts diff --git a/docs/index.md b/docs/index.md index f772724a..c920fe0a 100644 --- a/docs/index.md +++ b/docs/index.md @@ -44,6 +44,7 @@ https://docs.autopilotmonitor.com (separate repository). # MCP Server * [MCP Docs Corpus](mcp/docs-corpus.md) - How the published customer documentation becomes the `search_docs` corpus: CRLF-safe heading chunking, build-time embedding as a third precomputed section, and why a docs edit needs an MCP redeploy. +* [MCP Tool Telemetry](mcp/tool-telemetry.md) - The three telemetry layers for judging tool quality: backend App Insights via X-MCP-Tool-Name, the per-user usage table, and the MCP_TOOL_LOGGING stderr lines (soft errors, result size vs. cap, zero-hit searches, Zod rejections). # Web Portal diff --git a/docs/log.md b/docs/log.md index 58591734..69c5e9e5 100644 --- a/docs/log.md +++ b/docs/log.md @@ -2,6 +2,7 @@ ## 2026-08-05 +* **Creation**: Added `mcp/tool-telemetry.md` — the three MCP tool-telemetry layers (App Insights `McpToolName`, per-user usage table, `MCP_TOOL_LOGGING` stderr lines) and the new quality signals: soft-error capture (`toolError` returns instead of throwing, so backend telemetry counted those calls as successes), `resultChars`/`overCap` vs. the inline-size hint, bounded args summaries, caller scope, `search_zero_hit` on the three search tools (unmet-demand signal), and `tool_call_rejected` for JSON-RPC-level Zod/unknown-tool rejections sniffed at the `/mcp` route (previously invisible everywhere). Bicep default for `toolLoggingEnabled` flipped to `true` (documented desired state; live flag set via `az containerapp update`). * **Creation**: Added `rules/rule-authoring-surface.md` — the AI-assisted rule-authoring stack: three deterministic MCP resources (`rule_authoring_guide` hand-written, `rule_schemas` + `rule_guardrails` generated into `rule-authoring.generated.ts` by a new combine.js emitter, drift-guarded twice), the MCP-local `validate_rule` (ajv 2020-12 against the single-rule $defs, guardrail pre-flight mirroring GatherRuleGuards matching semantics incl. hard blocks, semantic lint for schema-valid-but-dead rules), and the side-effect-free `POST /api/rules/analyze/dryrun` (TenantAdminOrGlobalReader; `RuleEngine.DryRun.cs` trace twin sharing the production evaluators, all-conditions trace with per-condition evidence + matchingEventCount, parity and side-effect-freedom pinned by RuleEngineDryRunTests). MCP `test_analyze_rule` wraps the endpoint with `{{token}}`-interpolated previews; `author-rule` prompt drives the draft → validate → dry-run loop. Deliberately absent: gather-rule remote execution, rule writes via MCP. ## 2026-08-04 diff --git a/docs/mcp/tool-telemetry.md b/docs/mcp/tool-telemetry.md new file mode 100644 index 00000000..8c281a29 --- /dev/null +++ b/docs/mcp/tool-telemetry.md @@ -0,0 +1,75 @@ +--- +type: concept +title: MCP Tool Telemetry +description: The three telemetry layers for judging MCP tool quality — backend App Insights via X-MCP-Tool-Name, the per-user usage table, and the MCP_TOOL_LOGGING stderr lines that carry the signals the backend cannot see (soft errors, result size vs. cap, zero-hit searches, Zod rejections). +resource: src/McpServer/autopilot-monitor-mcp/src/telemetry.ts +tags: [mcp, telemetry, observability, tool-quality] +timestamp: 2026-08-05 +--- + +# Schema + +Three layers answer "are the MCP tools doing their job, and are tools missing?": + +1. **Backend App Insights** — every tool handler runs inside `withToolTelemetry` + (`src/telemetry.ts`), which propagates the tool name via AsyncLocalStorage so + `apiFetch` stamps `X-MCP-Tool-Name` on each backend request. + `RequestTelemetryMiddleware` copies it into the request telemetry as + `McpToolName`: per-tool call volume, latency percentiles and HTTP failure + rates by KQL. Blind spot: tools that never call the backend, and handler-level + soft errors (see layer 3). +2. **Usage table** — `McpQuotaEnforcementMiddleware.TrackUsage` counts per + user/day under the key `toolname:endpoint`; surfaced by the `get_api_usage` + tool. Counts only, every call counts as success. +3. **stderr JSON lines** (`MCP_TOOL_LOGGING=true`, queryable via Container App + Logs) — the layer that carries what the other two structurally cannot: + - `tool_call`: duration, `isError` **including soft errors** (handlers never + throw — `toolError` *returns* `isError: true`, so backend-only telemetry + records those calls as successes), `resultChars` + `overCap` (result + exceeds the tool's `anthropic/maxResultSizeChars` hint → the host truncates + it; a frequently-overCap tool needs tighter defaults or projections), a + size-bounded args summary, and the caller scope (ga/delegated/tenant). + This is the ONLY telemetry for backend-free tools: `search_docs`, + `validate_rule`, `get_resource`, the local ranking of `search_knowledge`. + - `search_zero_hit`: query text (capped) whenever `search_events` / + `search_knowledge` / `search_docs` return zero results — the most direct + "missing docs / missing knowledge / missing tool?" demand signal. + - `tool_call_rejected`: JSON-RPC-level rejections (Zod argument validation, + unknown tool name). The SDK answers these *before* any handler runs, so + they are captured by wrapping `res.end` in the `/mcp` route (stateless + mode guarantees one JSON-RPC request per POST; `enableJsonResponse` yields + a single buffered body). This is the strongest "the schema or description + confuses the model" signal and was previously invisible everywhere. + +The env flag defaults to `true` in `infra/mcp-server.bicep` (documented desired +state — the template is not routinely deployed; the live flag is set with +`az containerapp update --set-env-vars MCP_TOOL_LOGGING=true`). + +# Examples + +Count zero-hit queries to find unmet demand (Log Analytics): + +```kusto +ContainerAppConsoleLogs_CL +| where Log_s has '"type":"search_zero_hit"' +| extend d = parse_json(Log_s) +| summarize count() by tostring(d.tool), tostring(d.query) +``` + +Per-tool soft-error and truncation rates: + +```kusto +ContainerAppConsoleLogs_CL +| where Log_s has '"type":"tool_call"' +| extend d = parse_json(Log_s) +| summarize calls = count(), errors = countif(d.isError == true), + overCap = countif(d.overCap == true), p95ms = percentile(tolong(d.durationMs), 95) + by tool = tostring(d.tool) +``` + +# Citations + +- `src/McpServer/autopilot-monitor-mcp/src/telemetry.ts` — wrapper + log emitters +- `src/McpServer/autopilot-monitor-mcp/src/index.ts` — `/mcp` rejection sniffer +- `src/Backend/AutopilotMonitor.Functions/Middleware/RequestTelemetryMiddleware.cs` — `McpToolName` stamping +- `src/Backend/AutopilotMonitor.Functions/Middleware/McpQuotaEnforcementMiddleware.cs` — usage-table counting diff --git a/infra/mcp-server.bicep b/infra/mcp-server.bicep index 5b4e590d..0be9838d 100644 --- a/infra/mcp-server.bicep +++ b/infra/mcp-server.bicep @@ -80,8 +80,8 @@ param mcpPublicUrl string = '' @description('Base64-encoded HMAC key (>=32 bytes after decode) for signing the OAuth proxy state. Naming and format match the backend\'s PaginationTokenSigningKey for consistency. Empty = generate per-instance random key on startup (acceptable for single-replica deployments since state has 10 min lifetime). Generate with PowerShell: [Convert]::ToBase64String([Security.Cryptography.RandomNumberGenerator]::GetBytes(32))') param oAuthStateSigningKey string = '' -@description('Enable structured tool-call logging to stderr (queryable via Container App Logs)') -param toolLoggingEnabled bool = false +@description('Enable structured tool-call logging to stderr (queryable via Container App Logs). Volume is one small JSON line per tool call - negligible at current usage.') +param toolLoggingEnabled bool = true // --- Azure Container Registry --- diff --git a/src/McpServer/autopilot-monitor-mcp/src/__tests__/telemetry.test.ts b/src/McpServer/autopilot-monitor-mcp/src/__tests__/telemetry.test.ts new file mode 100644 index 00000000..83fea22a --- /dev/null +++ b/src/McpServer/autopilot-monitor-mcp/src/__tests__/telemetry.test.ts @@ -0,0 +1,152 @@ +import { describe, it, expect, vi, afterEach } from 'vitest'; + +/** + * telemetry.ts reads MCP_TOOL_LOGGING at module load, so each scenario + * re-imports the module with the env stubbed accordingly. + */ +async function loadTelemetry(loggingEnabled: boolean) { + vi.resetModules(); + if (loggingEnabled) { + vi.stubEnv('MCP_TOOL_LOGGING', 'true'); + } else { + vi.stubEnv('MCP_TOOL_LOGGING', ''); + } + return await import('../telemetry.js'); +} + +function lastLoggedJson(spy: ReturnType): Record { + expect(spy).toHaveBeenCalled(); + const line = spy.mock.calls[spy.mock.calls.length - 1][0] as string; + return JSON.parse(line) as Record; +} + +afterEach(() => { + vi.unstubAllEnvs(); + vi.restoreAllMocks(); +}); + +describe('summarizeArgs', () => { + it('drops null/undefined entries and keeps scalars', async () => { + const { summarizeArgs } = await loadTelemetry(false); + const out = summarizeArgs({ a: 'x', b: 42, c: true, d: null, e: undefined }); + expect(out).toEqual({ a: 'x', b: '42', c: 'true' }); + }); + + it('caps long string values and annotates the cut', async () => { + const { summarizeArgs } = await loadTelemetry(false); + const out = summarizeArgs({ q: 'y'.repeat(500) })!; + expect(out.q.length).toBeLessThan(230); + expect(out.q).toContain('…(+300)'); + }); + + it('stringifies and caps object values (validate_rule sends whole rule objects)', async () => { + const { summarizeArgs } = await loadTelemetry(false); + const out = summarizeArgs({ rule: { name: 'r', conditions: 'z'.repeat(400) } })!; + expect(out.rule.length).toBeLessThan(230); + expect(out.rule).toContain('"name":"r"'); + }); + + it('bounds the total summary size across many keys', async () => { + const { summarizeArgs } = await loadTelemetry(false); + const args: Record = {}; + for (let i = 0; i < 50; i++) args[`k${i}`] = 'v'.repeat(100); + const out = summarizeArgs(args)!; + expect(out['…']).toBe('args summary truncated'); + expect(JSON.stringify(out).length).toBeLessThan(2500); + }); + + it('returns undefined for empty args', async () => { + const { summarizeArgs } = await loadTelemetry(false); + expect(summarizeArgs({})).toBeUndefined(); + }); +}); + +describe('withToolTelemetry', () => { + it('does not log when disabled but still returns the result', async () => { + const { withToolTelemetry } = await loadTelemetry(false); + const spy = vi.spyOn(console, 'error').mockImplementation(() => {}); + const result = await withToolTelemetry('get_session', { sessionId: 's1' }, () => 'ok'); + expect(result).toBe('ok'); + expect(spy).not.toHaveBeenCalled(); + }); + + it('logs one tool_call line with duration, size and args when enabled', async () => { + const { withToolTelemetry } = await loadTelemetry(true); + const spy = vi.spyOn(console, 'error').mockImplementation(() => {}); + const toolResult = { + content: [{ type: 'text', text: '{"data":1}' }], + _meta: { 'anthropic/maxResultSizeChars': 50_000 }, + }; + await withToolTelemetry('search_sessions', { tenantId: 't1', days: 7 }, () => toolResult); + const line = lastLoggedJson(spy); + expect(line.type).toBe('tool_call'); + expect(line.tool).toBe('search_sessions'); + expect(typeof line.durationMs).toBe('number'); + expect(line.isError).toBe(false); + expect(line.resultChars).toBe(10); + expect(line.overCap).toBe(false); + expect(line.args).toEqual({ tenantId: 't1', days: '7' }); + }); + + it('flags overCap when the result exceeds the inline-size hint', async () => { + const { withToolTelemetry } = await loadTelemetry(true); + const spy = vi.spyOn(console, 'error').mockImplementation(() => {}); + const toolResult = { + content: [{ type: 'text', text: 'x'.repeat(100) }], + _meta: { 'anthropic/maxResultSizeChars': 10 }, + }; + await withToolTelemetry('query_table', {}, () => toolResult); + expect(lastLoggedJson(spy).overCap).toBe(true); + }); + + it('marks soft errors: toolError RETURNS isError:true instead of throwing', async () => { + const { withToolTelemetry } = await loadTelemetry(true); + const spy = vi.spyOn(console, 'error').mockImplementation(() => {}); + const errorResult = { isError: true, content: [{ type: 'text', text: 'Backend error' }] }; + const result = await withToolTelemetry('get_metrics', {}, () => errorResult); + expect(result).toBe(errorResult); + expect(lastLoggedJson(spy).isError).toBe(true); + }); + + it('marks thrown errors and rethrows them', async () => { + const { withToolTelemetry } = await loadTelemetry(true); + const spy = vi.spyOn(console, 'error').mockImplementation(() => {}); + await expect( + withToolTelemetry('get_session', {}, () => { throw new Error('boom'); }), + ).rejects.toThrow('boom'); + expect(lastLoggedJson(spy).isError).toBe(true); + }); +}); + +describe('logSearchZeroHit', () => { + it('is silent when disabled', async () => { + const { logSearchZeroHit } = await loadTelemetry(false); + const spy = vi.spyOn(console, 'error').mockImplementation(() => {}); + logSearchZeroHit('search_docs', 'how do I frobnicate'); + expect(spy).not.toHaveBeenCalled(); + }); + + it('logs the query (capped) with extra detail when enabled', async () => { + const { logSearchZeroHit } = await loadTelemetry(true); + const spy = vi.spyOn(console, 'error').mockImplementation(() => {}); + logSearchZeroHit('search_events', 'q'.repeat(400), { eventsFetched: 12 }); + const line = lastLoggedJson(spy); + expect(line.type).toBe('search_zero_hit'); + expect(line.tool).toBe('search_events'); + expect((line.query as string).length).toBeLessThan(330); + expect(line.eventsFetched).toBe(12); + }); +}); + +describe('logToolCallRejection', () => { + it('logs tool name, code and capped message when enabled', async () => { + const { logToolCallRejection } = await loadTelemetry(true); + const spy = vi.spyOn(console, 'error').mockImplementation(() => {}); + logToolCallRejection('get_session', -32602, 'Invalid arguments for tool get_session: ' + 'z'.repeat(600)); + const line = lastLoggedJson(spy); + expect(line.type).toBe('tool_call_rejected'); + expect(line.tool).toBe('get_session'); + expect(line.errorCode).toBe(-32602); + expect((line.message as string).length).toBeLessThan(530); + }); +}); diff --git a/src/McpServer/autopilot-monitor-mcp/src/index.ts b/src/McpServer/autopilot-monitor-mcp/src/index.ts index 0fd96275..ed480e58 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/index.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/index.ts @@ -18,6 +18,7 @@ import { buildEventTypeSearchDocs } from './resource-catalog.js'; import { createOAuthRouter } from './oauth.js'; import { accessGuard } from './access-guard.js'; import { hasGlobalScope, isGlobalAdmin, isDelegated, getDelegatedTenantIds, getHomeTenantId } from './client.js'; +import { toolLoggingEnabled, logToolCallRejection } from './telemetry.js'; import { API_BASE_URL } from './config.js'; const __dirname = dirname(fileURLToPath(import.meta.url)); @@ -372,6 +373,33 @@ app.all('/mcp', async (req, res) => { return; } + // Sniff JSON-RPC error envelopes on tool calls (Zod argument rejection, + // unknown tool name): the SDK answers these BEFORE any tool handler runs, + // so wrapping the response write is the only place they are observable — + // and they are the strongest "the schema/description confuses the model" + // signal. Stateless mode guarantees one JSON-RPC request per POST and + // enableJsonResponse yields a single buffered body, so inspecting the + // res.end chunk sees the whole envelope. Error envelopes are tiny; the + // length guard skips parsing large (i.e. successful) tool results. + if (toolLoggingEnabled && req.body?.method === 'tools/call') { + const toolName = typeof req.body?.params?.name === 'string' ? req.body.params.name : 'unknown'; + const originalEnd = res.end.bind(res); + res.end = ((chunk?: unknown, ...rest: unknown[]) => { + try { + const text = typeof chunk === 'string' ? chunk : Buffer.isBuffer(chunk) ? chunk.toString('utf8') : undefined; + if (text && text.length < 10_000 && text.includes('"error"')) { + const parsed = JSON.parse(text) as { error?: { code?: number; message?: unknown } }; + if (parsed?.error?.code !== undefined) { + logToolCallRejection(toolName, parsed.error.code, String(parsed.error.message ?? '')); + } + } + } catch { + // Sniffing must never break the response. + } + return originalEnd(chunk as never, ...(rest as never[])); + }) as typeof res.end; + } + const transport = new StreamableHTTPServerTransport({ sessionIdGenerator: undefined, // stateless: no session tracking // Return a single buffered application/json response instead of an SSE diff --git a/src/McpServer/autopilot-monitor-mcp/src/telemetry.ts b/src/McpServer/autopilot-monitor-mcp/src/telemetry.ts index c9c10c1c..0015d0c0 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/telemetry.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/telemetry.ts @@ -1,33 +1,144 @@ -import { runWithToolName } from './client.js'; +import { runWithToolName, hasGlobalScope, isDelegated } from './client.js'; -const toolLoggingEnabled = process.env.MCP_TOOL_LOGGING === 'true'; +export const toolLoggingEnabled = process.env.MCP_TOOL_LOGGING === 'true'; + +// Caps keep a single log line small no matter what the model sends (validate_rule +// takes whole rule JSON objects; queries are free text). +const ARG_VALUE_CAP = 200; +const ARGS_TOTAL_CAP = 1500; +const QUERY_CAP = 300; + +function cap(s: string, max: number): string { + return s.length > max ? s.slice(0, max) + `…(+${s.length - max})` : s; +} + +/** + * Compact, size-bounded view of the tool arguments for the log line. Values are + * individually capped and the whole summary is bounded, so a pathological arg + * object can never bloat a log line. Null/undefined entries are dropped. + */ +export function summarizeArgs(args: Record): Record | undefined { + const out: Record = {}; + let total = 0; + for (const [key, value] of Object.entries(args)) { + if (value === null || value === undefined) continue; + const rendered = + typeof value === 'string' ? cap(value, ARG_VALUE_CAP) : cap(JSON.stringify(value) ?? '', ARG_VALUE_CAP); + total += key.length + rendered.length; + if (total > ARGS_TOTAL_CAP) { + out['…'] = 'args summary truncated'; + break; + } + out[key] = rendered; + } + return Object.keys(out).length > 0 ? out : undefined; +} + +/** Caller scope for usage analysis — which audience a tool struggle belongs to. */ +function callerScope(): 'ga' | 'delegated' | 'tenant' { + if (hasGlobalScope()) return 'ga'; + if (isDelegated()) return 'delegated'; + return 'tenant'; +} + +interface ToolResultShape { + isError?: boolean; + content?: Array<{ type?: string; text?: string }>; + _meta?: Record; +} /** * Wraps an MCP tool handler to: * 1. Always: propagate the tool name via AsyncLocalStorage so apiFetch sends * the X-MCP-Tool-Name header to the backend (tracked in App Insights). - * 2. Optionally (MCP_TOOL_LOGGING=true): emit structured JSON to stderr, - * queryable via Container App Logs in Azure Monitor. + * 2. Optionally (MCP_TOOL_LOGGING=true): emit one structured JSON line per call + * to stderr, queryable via Container App Logs in Azure Monitor. Beyond + * duration, the line carries the quality signals backend telemetry cannot + * see: soft errors (handlers never throw — toolError RETURNS `isError: + * true`), result size vs. the tool's inline-size cap (overCap = the host + * will truncate), a size-bounded argument summary, and the caller scope. + * This is also the ONLY telemetry for tools that never call the backend + * (search_docs, search_knowledge ranking, validate_rule, get_resource). */ -export async function withToolTelemetry(toolName: string, fn: () => T | Promise): Promise { +export async function withToolTelemetry( + toolName: string, + args: Record, + fn: () => T | Promise, +): Promise { if (!toolLoggingEnabled) { return runWithToolName(toolName, fn) as Promise; } const start = Date.now(); - let isError = false; + let threw = false; + let result: T | undefined; try { - return await runWithToolName(toolName, fn); + result = await runWithToolName(toolName, fn); + return result; } catch (err) { - isError = true; + threw = true; throw err; } finally { - console.error(JSON.stringify({ - type: 'tool_call', - tool: toolName, - durationMs: Date.now() - start, - isError, - timestamp: new Date().toISOString(), - })); + try { + const r = result as ToolResultShape | undefined; + const resultChars = r?.content?.reduce((sum, c) => sum + (c.text?.length ?? 0), 0) ?? 0; + const capValue = Number(r?._meta?.['anthropic/maxResultSizeChars']); + console.error(JSON.stringify({ + type: 'tool_call', + tool: toolName, + durationMs: Date.now() - start, + isError: threw || r?.isError === true, + resultChars, + // Result exceeds the inline-size hint → the host truncates it. A tool + // that is frequently overCap needs tighter defaults or projections. + overCap: Number.isFinite(capValue) && capValue > 0 ? resultChars > capValue : false, + scope: callerScope(), + args: summarizeArgs(args), + timestamp: new Date().toISOString(), + })); + } catch { + // Telemetry must never break a tool response. + } + } +} + +/** + * Zero-hit search log — the "does content/a tool for this exist at all?" signal. + * Reviewing these queries periodically is the most direct way to find unmet + * demand (missing docs, missing knowledge-base rules, missing tools). + */ +export function logSearchZeroHit(tool: string, query: string, detail?: Record): void { + if (!toolLoggingEnabled) return; + try { + console.error(JSON.stringify({ + type: 'search_zero_hit', + tool, + query: cap(query, QUERY_CAP), + ...detail, + timestamp: new Date().toISOString(), + })); + } catch { + // Telemetry must never break a tool response. + } +} + +/** + * JSON-RPC-level tool-call rejection (Zod arg validation, unknown tool). These + * never reach a tool handler — the SDK rejects them before dispatch — so + * without this log the strongest "the schema/description confuses the model" + * signal is invisible everywhere. + */ +export function logToolCallRejection(toolName: string, errorCode: number, message: string): void { + if (!toolLoggingEnabled) return; + try { + console.error(JSON.stringify({ + type: 'tool_call_rejected', + tool: toolName, + errorCode, + message: cap(message, 500), + timestamp: new Date().toISOString(), + })); + } catch { + // Telemetry must never break a tool response. } } diff --git a/src/McpServer/autopilot-monitor-mcp/src/tools/admin.ts b/src/McpServer/autopilot-monitor-mcp/src/tools/admin.ts index 5cdada1a..1fd6e7f6 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/tools/admin.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/tools/admin.ts @@ -270,7 +270,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_api_usage', async () => { + async (args) => withToolTelemetry('get_api_usage', args, async () => { try { let data: unknown; const params: Record = { tenantId: args.tenantId, dateFrom: args.dateFrom, dateTo: args.dateTo }; @@ -310,7 +310,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_geographic_metrics', async () => { + async (args) => withToolTelemetry('get_geographic_metrics', args, async () => { try { const { tenantId: rawTenantId, ...rest } = args; // Delegated (MSP): require a managed tenantId (no aggregate); no-op for GA/Reader/tenant users. @@ -356,7 +356,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_geographic_sessions', async () => { + async (args) => withToolTelemetry('get_geographic_sessions', args, async () => { try { const { tenantId: rawTenantId, locationKey, country, region, city, pageSize, continuation, ...rest } = args; // Offset-based client-side pager (geo-offset:N carries no tenantId), so the explicit tenantId is @@ -420,7 +420,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_platform_metrics', async () => { + async (args) => withToolTelemetry('get_platform_metrics', args, async () => { try { type SessionMetric = { sessionId: string; tenantId: string; deviceName?: string; model?: string; status?: string; @@ -516,7 +516,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_usage_metrics', async () => { + async (args) => withToolTelemetry('get_usage_metrics', args, async () => { try { const { tenantId: rawTenantId, days } = args; const tenantId = enforceDelegatedTenant(rawTenantId); @@ -580,7 +580,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('list_tenants', async () => { + async (args) => withToolTelemetry('list_tenants', args, async () => { try { const { query, tenantId, fields, pageSize, continuation } = args; @@ -689,7 +689,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_audit_logs', async () => { + async (args) => withToolTelemetry('get_audit_logs', args, async () => { try { const { tenantId: rawTenantId, dateFrom, dateTo, action, performedBy, entityType, entityId, pageSize, continuation } = args; const tenantId = enforceDelegatedTenantForPage(rawTenantId, continuation); @@ -733,7 +733,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_ops_events', async () => { + async (args) => withToolTelemetry('get_ops_events', args, async () => { try { const { category, tenantId, dateFrom, dateTo, pageSize, continuation } = args; const path = followNextLink( @@ -769,7 +769,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('list_session_reports', async () => { + async (args) => withToolTelemetry('list_session_reports', args, async () => { try { const { tenantId, pageSize, continuation } = args; const path = followNextLink( @@ -834,7 +834,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('query_raw_events', async () => { + async (args) => withToolTelemetry('query_raw_events', args, async () => { try { const { tenantId: rawTenantId, sessionId, eventType, severity, source, startedAfter, startedBefore, fields, pageSize, continuation } = args; const tenantId = enforceDelegatedTenantForPage(rawTenantId, continuation); @@ -904,7 +904,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('query_raw_sessions', async () => { + async (args) => withToolTelemetry('query_raw_sessions', args, async () => { try { const { tenantId: rawTenantId, status, startedAfter, startedBefore, serialNumber, agentVersion, agentVersionPrefix, imeAgentVersion, imeAgentVersionPrefix, manufacturer, model, enrollmentType, deviceName, osBuild, @@ -942,7 +942,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo inputSchema: {}, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('list_tables', async () => { + async (args) => withToolTelemetry('list_tables', args, async () => { try { const data = await apiFetch('/api/global/raw/tables'); return toolResultText(data, MAX_RESULT_SIZE_CHARS.small); @@ -982,7 +982,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('query_table', async () => { + async (args) => withToolTelemetry('query_table', args, async () => { try { const { tableName, partitionKey, rowKeyPrefix, filter, fields, pageSize, continuation } = args; const basePath = `/api/global/raw/tables/${encodeURIComponent(tableName)}`; @@ -1029,7 +1029,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY_OPEN, }, - async (args) => withToolTelemetry('query_backend_logs', async () => { + async (args) => withToolTelemetry('query_backend_logs', args, async () => { try { const data = await apiFetch('/api/global/raw/logs', { method: 'POST', @@ -1065,7 +1065,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_tenant_config', async () => { + async (args) => withToolTelemetry('get_tenant_config', args, async () => { try { // view=redacted is load-bearing: without it the backend serves a GA the // clear-text secrets, which must never enter model context (pinned by @@ -1092,7 +1092,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo inputSchema: {}, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_tenant_config_schema', async () => { + async (args) => withToolTelemetry('get_tenant_config_schema', args, async () => { try { const data = await apiFetch('/api/config/fields-schema'); return toolResultText(data, MAX_RESULT_SIZE_CHARS.small); @@ -1127,7 +1127,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: MUTATING, }, - async (args) => withToolTelemetry('update_tenant_config', async () => { + async (args) => withToolTelemetry('update_tenant_config', args, async () => { try { const data = await apiFetch(`/api/config/${encodeURIComponent(args.tenantId)}/fields`, { method: 'PATCH', @@ -1156,7 +1156,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('list_tenant_config_backups', async () => { + async (args) => withToolTelemetry('list_tenant_config_backups', args, async () => { try { const query = args.max != null ? `?max=${encodeURIComponent(String(args.max))}` : ''; const data = await apiFetch(`/api/config/${encodeURIComponent(args.tenantId)}/backups${query}`); @@ -1189,7 +1189,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: MUTATING, }, - async (args) => withToolTelemetry('revert_tenant_config', async () => { + async (args) => withToolTelemetry('revert_tenant_config', args, async () => { try { const data = await apiFetch(`/api/config/${encodeURIComponent(args.tenantId)}/revert`, { method: 'POST', @@ -1231,7 +1231,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_rule_stats', async () => { + async (args) => withToolTelemetry('get_rule_stats', args, async () => { try { const tenantId = enforceDelegatedTenant(args.tenantId); const params: Record = { @@ -1272,7 +1272,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_vulnerability_summary', async () => { + async (args) => withToolTelemetry('get_vulnerability_summary', args, async () => { try { const { tenantId: rawTenantId, days, topN } = args; const tenantId = enforceDelegatedTenant(rawTenantId); @@ -1312,7 +1312,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_app_install_metrics', async () => { + async (args) => withToolTelemetry('get_app_install_metrics', args, async () => { try { const { tenantId: rawTenantId, days } = args; const tenantId = enforceDelegatedTenant(rawTenantId); @@ -1357,7 +1357,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_time_attribution', async () => { + async (args) => withToolTelemetry('get_time_attribution', args, async () => { try { const { sessionId, tenantId: rawTenantId } = args; const tenantId = enforceDelegatedTenant(rawTenantId); @@ -1410,7 +1410,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_device_history', async () => { + async (args) => withToolTelemetry('get_device_history', args, async () => { try { const { serialNumber, days, tenantId: rawTenantId } = args; const tenantId = enforceDelegatedTenant(rawTenantId); @@ -1483,7 +1483,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_software_inventory', async () => { + async (args) => withToolTelemetry('get_software_inventory', args, async () => { try { const { tenantId: rawTenantId, scope, pageSize, continuation } = args as { tenantId?: string; scope?: 'inventory' | 'unmatched'; pageSize: number; continuation?: string; @@ -1551,7 +1551,7 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo }, annotations: READ_ONLY_OPEN, }, - async (args) => withToolTelemetry('get_resource', async () => { + async (args) => withToolTelemetry('get_resource', args, async () => { try { const data = getResourceContent(args.name); return toolResultText(data, MAX_RESULT_SIZE_CHARS.small); diff --git a/src/McpServer/autopilot-monitor-mcp/src/tools/rules.ts b/src/McpServer/autopilot-monitor-mcp/src/tools/rules.ts index afedf7f4..e035493e 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/tools/rules.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/tools/rules.ts @@ -34,7 +34,7 @@ export function registerRuleTools(server: McpServer, ga: boolean): void { }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('validate_rule', async () => { + async (args) => withToolTelemetry('validate_rule', args, async () => { try { const result = validateRuleDraft(args.rule as Record); return toolResultText( @@ -79,7 +79,7 @@ export function registerRuleTools(server: McpServer, ga: boolean): void { }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('test_analyze_rule', async () => { + async (args) => withToolTelemetry('test_analyze_rule', args, async () => { try { const data = await apiFetch('/api/rules/analyze/dryrun', { method: 'POST', diff --git a/src/McpServer/autopilot-monitor-mcp/src/tools/search.ts b/src/McpServer/autopilot-monitor-mcp/src/tools/search.ts index 4efec108..6150843a 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/tools/search.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/tools/search.ts @@ -1,7 +1,7 @@ import { McpServer } from '@modelcontextprotocol/sdk/server/mcp.js'; import { z } from 'zod'; import { apiFetch, buildQuery, enforceDelegatedTenant, followNextLink, pickGlobalOrTenantPath } from '../client.js'; -import { withToolTelemetry } from '../telemetry.js'; +import { withToolTelemetry, logSearchZeroHit } from '../telemetry.js'; import type { SearchProvider, DocsSearchBundle } from '../search-provider.js'; import { READ_ONLY, MAX_RESULT_SIZE_CHARS, toolResultText, SessionIdSchema, isBenignHealthDetectionReport, tenantIdDescription } from './shared.js'; import { toolError } from './error-handler.js'; @@ -1046,7 +1046,7 @@ export function registerSearchTools( }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('search_events', async () => { + async (args) => withToolTelemetry('search_events', args, async () => { try { const { query, sessionId, tenantId: rawTenantId, depth, keywords, guaranteedTopRanked } = args; // Delegated (MSP): require a managed tenantId (no cross-tenant aggregate); no-op for others. @@ -1058,6 +1058,7 @@ export function registerSearchTools( // Extract keywords FIRST so we can use them for index-based pre-filtering const queryKeywords = resolveQueryKeywords(query, keywords); if (queryKeywords.length === 0) { + logSearchZeroHit('search_events', query, { reason: 'no_keywords' }); return toolResultText( { query, resultCount: 0, results: [], note: 'No searchable keywords extracted from query.' }, MAX_RESULT_SIZE_CHARS.small); @@ -1102,6 +1103,10 @@ export function registerSearchTools( const matchedSessionIds = [...new Set(results.map((r) => r.sessionId).filter(Boolean))]; const semanticOnlyCount = results.filter((r) => r.semanticOnly).length; + if (results.length === 0) { + logSearchZeroHit('search_events', query, { eventsFetched: events.length, sessionsSearched: sessionIds.length }); + } + return toolResultText({ query, // Honest reporting: semantic type-selection contributed only when the @@ -1154,7 +1159,7 @@ export function registerSearchTools( }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('search_knowledge', async () => { + async (args) => withToolTelemetry('search_knowledge', args, async () => { try { const { query, topK, type, minScore } = args; if (!knowledgeBase || knowledgeBase.size === 0) { @@ -1203,6 +1208,8 @@ export function registerSearchTools( matchType: errorCodeHitIds.has(r.id) ? ('error-code' as const) : undefined, })); + if (formatted.length === 0) logSearchZeroHit('search_knowledge', query); + return toolResultText({ query, searchBackend: knowledgeBase.name, @@ -1263,7 +1270,7 @@ export function registerSearchTools( }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('search_docs', async () => { + async (args) => withToolTelemetry('search_docs', args, async () => { try { const { query, topK, section, minScore } = args; @@ -1370,6 +1377,8 @@ export function registerSearchTools( : undefined, })); + if (formatted.length === 0) logSearchZeroHit('search_docs', query, section ? { section } : undefined); + return toolResultText({ query, searchBackend: docsIndex.name, diff --git a/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts b/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts index 2e57ed0c..8e943790 100644 --- a/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts +++ b/src/McpServer/autopilot-monitor-mcp/src/tools/sessions.ts @@ -166,7 +166,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('search_sessions', async () => { + async (args) => withToolTelemetry('search_sessions', args, async () => { try { const { deviceProperties, tenantId: rawTenantId, pageSize, continuation, ...rest } = args; // Delegated (MSP): require a managed tenantId (no aggregate); a page-2 call carries it inside the @@ -223,7 +223,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('search_sessions_by_event', async () => { + async (args) => withToolTelemetry('search_sessions_by_event', args, async () => { try { const { eventType, tenantId: rawTenantId, pageSize, continuation } = args; const tenantId = enforceDelegatedTenantForPage(rawTenantId, continuation); @@ -258,7 +258,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_session', async () => { + async (args) => withToolTelemetry('get_session', args, async () => { try { const { sessionId, tenantId: rawTenantId, includeAnalysis } = args; // Delegated (MSP): the session lives in a managed tenant — require + validate it (the backend @@ -316,7 +316,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_session_diagnostics', async () => { + async (args) => withToolTelemetry('get_session_diagnostics', args, async () => { try { const { sessionId, tenantId: rawTenantId } = args; const tenantId = enforceDelegatedTenant(rawTenantId); @@ -416,7 +416,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_session_events', async () => { + async (args) => withToolTelemetry('get_session_events', args, async () => { try { const { sessionId, tenantId: rawTenantId, pageSize, continuation, eventType, severity, source, fields } = args; const tenantId = enforceDelegatedTenantForPage(rawTenantId, continuation); @@ -458,7 +458,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_session_summary', async () => { + async (args) => withToolTelemetry('get_session_summary', args, async () => { try { const { sessionId, tenantId: rawTenantId } = args; const tenantId = enforceDelegatedTenant(rawTenantId); @@ -654,7 +654,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_metrics', async () => { + async (args) => withToolTelemetry('get_metrics', args, async () => { try { const { tenantId: rawTenantId, ...rest } = args; const tenantId = enforceDelegatedTenant(rawTenantId); @@ -719,7 +719,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('search_sessions_by_cve', async () => { + async (args) => withToolTelemetry('search_sessions_by_cve', args, async () => { try { const { cveId, tenantId: rawTenantId, minCvssScore, overallRisk, pageSize, continuation } = args; const tenantId = enforceDelegatedTenantForPage(rawTenantId, continuation); @@ -755,7 +755,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: }, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('list_blocked_devices', async () => { + async (args) => withToolTelemetry('list_blocked_devices', args, async () => { try { const { tenantId } = args; // GA: /api/global/devices/blocked (tenantId is filter); non-GA: /api/devices/blocked @@ -787,7 +787,7 @@ export function registerSessionTools(server: McpServer, ga: boolean, delegated: inputSchema: {}, annotations: READ_ONLY, }, - async (args) => withToolTelemetry('get_ime_version_history', async () => { + async (args) => withToolTelemetry('get_ime_version_history', args, async () => { try { const data = await apiFetch('/api/metrics/ime-versions'); return toolResultText(data, MAX_RESULT_SIZE_CHARS.small);