mcp: one correlation id per tool call — sent to the backend, logged, shown in every error

withToolTelemetry mints a UUID per tool call and runs the handler in a
ToolCallContext (tool name + correlation id); apiFetch stamps it as
X-Correlation-ID next to X-MCP-Tool-Name, so every backend request of the call
(pagination scans included) and the MCP_TOOL_LOGGING tool_call line carry the
same id — a row-level join between the MCP log and the backend's request rows.
ApiError reads the X-Correlation-ID response header (body correlationId as
fallback), and the error handler names it in every branch — 5xx, quota 429,
structured 4xx and the unstructured 401/403/404/429 texts that had none. The
handler reads the envelope's `code` (errorCode as the pre-envelope fallback),
the quota body's `error`, and the log proxy's `upstreamCode`.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
This commit is contained in:
Oliver Kieselbach
2026-09-05 01:33:44 +02:00
parent 2abc78ab6d
commit 03116a97d1
6 changed files with 193 additions and 30 deletions
@@ -0,0 +1,69 @@
import { afterEach, describe, expect, it, vi } from 'vitest';
import { ApiError, apiFetch, getCurrentCorrelationId, getCurrentToolName, runWithCaller, runWithToolCall } from '../client.js';
/**
* The backend request headers apiFetch stamps: the tool name (per-tool aggregation in App Insights)
* and the per-call correlation id (row-level join between the MCP_TOOL_LOGGING line and the backend
* request rows), plus the header-borne correlation id on a failed response.
*/
afterEach(() => vi.unstubAllGlobals());
function stubFetch(status: number, body: unknown, headers: Record<string, string> = {}) {
const calls: Array<{ url: string; headers: Record<string, string> }> = [];
vi.stubGlobal('fetch', vi.fn(async (url: string, init: RequestInit) => {
calls.push({ url: String(url), headers: (init.headers as Record<string, string>) ?? {} });
return {
ok: status < 400,
status,
headers: { get: (name: string) => headers[name.toLowerCase()] ?? null },
json: async () => body,
text: async () => JSON.stringify(body),
} as unknown as Response;
}));
return calls;
}
describe('apiFetch headers', () => {
it('sends X-Client-Source, X-MCP-Tool-Name and X-Correlation-ID from the tool-call context', async () => {
const calls = stubFetch(200, { success: true });
await runWithCaller({ token: 'tok', isGlobalAdmin: true }, () =>
runWithToolCall('get_session', 'cid-tool-1', async () => {
expect(getCurrentToolName()).toBe('get_session');
expect(getCurrentCorrelationId()).toBe('cid-tool-1');
await apiFetch('/api/global/sessions/x');
await apiFetch('/api/global/sessions/x/events');
}),
);
expect(calls).toHaveLength(2);
for (const call of calls) {
expect(call.headers['X-Client-Source']).toBe('mcp');
expect(call.headers['X-MCP-Tool-Name']).toBe('get_session');
// Every request of one tool call carries the SAME id — the call is the join granularity.
expect(call.headers['X-Correlation-ID']).toBe('cid-tool-1');
}
});
it('sends no tool headers outside a tool-call context', async () => {
const calls = stubFetch(200, { success: true });
await runWithCaller({ token: 'tok', isGlobalAdmin: true }, () => apiFetch('/api/global/health'));
expect(calls[0].headers['X-Client-Source']).toBe('mcp');
expect(calls[0].headers['X-MCP-Tool-Name']).toBeUndefined();
expect(calls[0].headers['X-Correlation-ID']).toBeUndefined();
});
it('carries the response header correlation id into ApiError, falling back to the body', async () => {
stubFetch(404, { error: 'Session not found', code: 'NotFound', correlationId: 'body-cid' }, { 'x-correlation-id': 'hdr-cid' });
const fromHeader = await runWithCaller({ token: 'tok', isGlobalAdmin: true }, () => apiFetch('/api/global/sessions/x')).catch((e) => e);
expect(fromHeader).toBeInstanceOf(ApiError);
expect((fromHeader as ApiError).correlationId).toBe('hdr-cid');
expect((fromHeader as ApiError).parsed?.code).toBe('NotFound');
stubFetch(500, { error: 'boom', code: 'InternalError', correlationId: 'body-only' });
const fromBody = await runWithCaller({ token: 'tok', isGlobalAdmin: true }, () => apiFetch('/api/global/sessions/x')).catch((e) => e);
expect((fromBody as ApiError).correlationId).toBe('body-only');
});
});
@@ -3,6 +3,50 @@ import { toolError } from '../tools/error-handler.js';
import { ApiError } from '../client.js';
describe('toolError', () => {
it('names the correlation id from the response header on an unstructured 404 (no body id)', () => {
const err = new ApiError(404, 'not found', 'hdr-cid-1');
const text = toolError('get_session', { sessionId: 'x' }, err).content[0].text;
expect(text).toContain('Not found in get_session');
expect(text).toContain('**Correlation ID**: hdr-cid-1');
});
it('prefers the header id over the body id and reads the envelope `code`', () => {
const err = new ApiError(403, JSON.stringify({ error: 'Access denied.', code: 'CrossTenantAccessDenied', correlationId: 'body-cid' }), 'hdr-cid');
const text = toolError('search_sessions', {}, err).content[0].text;
expect(text).toContain('Access denied.');
expect(text).toContain('**Correlation ID**: hdr-cid');
expect(text).not.toContain('body-cid');
expect(text).toContain('**Error code**: CrossTenantAccessDenied');
});
it('names the correlation id and the envelope code on a sanitized 5xx', () => {
const err = new ApiError(500, JSON.stringify({ error: 'QueryTable failed.', code: 'InternalError', correlationId: 'cid-500', hint: 'internal' }), null);
const text = toolError('query_table', {}, err).content[0].text;
expect(text).toContain('**Correlation ID**: cid-500');
expect(text).toContain('**Error code**: InternalError');
expect(text).not.toContain('QueryTable failed.');
expect(text).not.toContain('internal');
});
it('renders the envelope quota body (error + correlationId) and the upstream code of a KQL rejection', () => {
const quota = new ApiError(429, JSON.stringify({
error: "MCP daily request quota exceeded for plan 'community'. Resets at 2026-09-06T00:00:00Z.",
code: 'QuotaExceeded', correlationId: 'cid-q', quotaExceeded: true, plan: 'community', scope: 'daily', level: 'user', limit: 200, used: 200, resetUtc: '2026-09-06T00:00:00Z',
}));
const quotaText = toolError('search_sessions', {}, quota).content[0].text;
expect(quotaText).toContain("quota exceeded for plan 'community'");
expect(quotaText).toContain('**Correlation ID**: cid-q');
const kql = new ApiError(400, JSON.stringify({
error: "Query could not be parsed at 'takee'", code: 'BadRequest', correlationId: 'cid-k',
upstreamCode: 'SyntaxError', statusCode: 400, source: 'web', hint: 'Fix the KQL.', upstream: '{"error":{"code":"BadArgumentError"}}',
}));
const kqlText = toolError('query_backend_logs', { query: 'x' }, kql).content[0].text;
expect(kqlText).toContain('**Error code**: BadRequest');
expect(kqlText).toContain('**Upstream code**: SyntaxError');
expect(kqlText).toContain('BadArgumentError');
});
it('detects a real AbortSignal.timeout DOMException (name TimeoutError, non-matching message)', () => {
// This is exactly what fetch rejects with under AbortSignal.timeout(): the
// message does NOT contain "TimeoutError", only the name does — so a
@@ -108,6 +108,8 @@ describe('withToolTelemetry', () => {
const line = lastLoggedJson(spy);
expect(line.type).toBe('tool_call');
expect(line.tool).toBe('search_sessions');
// The per-call correlation id: the join key to the backend's request rows (X-Correlation-ID).
expect(String(line.correlationId)).toMatch(/^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/);
expect(typeof line.durationMs).toBe('number');
expect(line.isError).toBe(false);
expect(line.resultChars).toBe(10);
@@ -15,8 +15,14 @@ export class ApiError extends Error {
readonly status: number;
readonly body: string;
readonly parsed: Record<string, unknown> | null;
/**
* The request's correlation id: the X-Correlation-ID response header (every backend answer
* carries it — the MCP is server-side, no CORS in the way), else the error envelope's
* `correlationId`. The handle an operator pivots on in the backend logs.
*/
readonly correlationId: string | null;
constructor(status: number, body: string) {
constructor(status: number, body: string, correlationIdHeader: string | null = null) {
super(`API error ${status}: ${body}`);
this.name = 'ApiError';
this.status = status;
@@ -26,6 +32,8 @@ export class ApiError extends Error {
} catch {
this.parsed = null;
}
const fromBody = typeof this.parsed?.correlationId === 'string' && this.parsed.correlationId ? this.parsed.correlationId : null;
this.correlationId = correlationIdHeader || fromBody;
}
}
@@ -287,17 +295,29 @@ export function enforceDelegatedTenantForPage(tenantId?: string, continuation?:
}
/**
* Per-request tool name store. Carries the MCP tool name through the async
* context so apiFetch can send it as X-MCP-Tool-Name header to the backend.
* Per-tool-call context. Carries the MCP tool name and the call's correlation id through the
* async context so apiFetch can send them as X-MCP-Tool-Name / X-Correlation-ID: every backend
* request a tool call makes (pagination scans included) shares the call's id, which is also
* what the MCP_TOOL_LOGGING `tool_call` line records — the row-level join between the MCP log
* and the backend's App Insights requests.
*/
const toolNameStore = new AsyncLocalStorage<string>();
export interface ToolCallContext {
toolName: string;
correlationId: string;
}
export function runWithToolName<T>(toolName: string, fn: () => T | Promise<T>): T | Promise<T> {
return toolNameStore.run(toolName, fn);
const toolCallStore = new AsyncLocalStorage<ToolCallContext>();
export function runWithToolCall<T>(toolName: string, correlationId: string, fn: () => T | Promise<T>): T | Promise<T> {
return toolCallStore.run({ toolName, correlationId }, fn);
}
export function getCurrentToolName(): string | undefined {
return toolNameStore.getStore();
return toolCallStore.getStore()?.toolName;
}
export function getCurrentCorrelationId(): string | undefined {
return toolCallStore.getStore()?.correlationId;
}
async function apiFetch(path: string, options: RequestInit = {}): Promise<unknown> {
@@ -314,8 +334,10 @@ async function apiFetch(path: string, options: RequestInit = {}): Promise<unknow
...((options.headers as Record<string, string>) ?? {}),
};
const toolName = getCurrentToolName();
if (toolName) headers['X-MCP-Tool-Name'] = toolName;
const call = toolCallStore.getStore();
if (call?.toolName) headers['X-MCP-Tool-Name'] = call.toolName;
// The backend honours an inbound id matching ^[A-Za-z0-9_-]{1,128}$ (a UUID does) and echoes it.
if (call?.correlationId) headers['X-Correlation-ID'] = call.correlationId;
// Apply timeout to prevent hanging on unresponsive backend
const signal = options.signal ?? AbortSignal.timeout(API_TIMEOUT_MS);
@@ -323,7 +345,7 @@ async function apiFetch(path: string, options: RequestInit = {}): Promise<unknow
const res = await fetch(url, { ...options, headers, signal });
if (!res.ok) {
const text = await res.text();
throw new ApiError(res.status, text);
throw new ApiError(res.status, text, res.headers?.get?.('x-correlation-id') ?? null);
}
return res.json();
}
@@ -1,4 +1,5 @@
import { runWithToolName, hasGlobalScope, isDelegated, getCallerUpn } from './client.js';
import { randomUUID } from 'node:crypto';
import { runWithToolCall, hasGlobalScope, isDelegated, getCallerUpn } from './client.js';
export const toolLoggingEnabled = process.env.MCP_TOOL_LOGGING === 'true';
@@ -94,8 +95,11 @@ export async function withToolTelemetry<T>(
fn: () => T | Promise<T>,
argPolicy?: ArgPolicy,
): Promise<T> {
// One correlation id per tool call — sent on every backend request the call makes and written
// into the tool_call line below, so an MCP log line and the backend request rows join on it.
const correlationId = randomUUID();
if (!toolLoggingEnabled) {
return runWithToolName(toolName, fn) as Promise<T>;
return runWithToolCall(toolName, correlationId, fn) as Promise<T>;
}
const start = Date.now();
@@ -103,7 +107,7 @@ export async function withToolTelemetry<T>(
let thrownMessage: string | undefined;
let result: T | undefined;
try {
result = await runWithToolName(toolName, fn);
result = await runWithToolCall(toolName, correlationId, fn);
return result;
} catch (err) {
threw = true;
@@ -124,6 +128,7 @@ export async function withToolTelemetry<T>(
console.error(JSON.stringify({
type: 'tool_call',
tool: toolName,
correlationId,
durationMs: Date.now() - start,
isError,
errorMessage,
@@ -6,13 +6,28 @@ interface ToolErrorResult {
content: Array<{ type: 'text'; text: string }>;
}
/**
* The correlation id line every backend failure carries — from the X-Correlation-ID response
* header (present on every backend answer) or the error envelope's `correlationId`. It is the
* one handle an operator needs to find the request in the backend logs, so no branch may drop it.
*/
function correlationLine(error: ApiError): string | null {
return error.correlationId ? `**Correlation ID**: ${error.correlationId}` : null;
}
/** Machine-readable code of the error envelope (`code`); `errorCode` is the pre-envelope spelling. */
function errorCodeOf(p: Record<string, unknown> | null): string | null {
const code = p?.code ?? p?.errorCode;
return typeof code === 'string' && code.length > 0 ? code : null;
}
/**
* Format any error into an MCP-compliant `{ isError: true }` response with
* structured, AI-consumable details. Never throws — always returns a result
* the SDK can send back to the model.
*
* Handles:
* - Structured backend errors (ApiError with parsed JSON body)
* - Structured backend errors (ApiError with the error envelope: error, code, correlationId, hint?)
* - Authentication errors
* - Timeouts (AbortError / timeout signals)
* - Legacy unstructured errors (fallback formatting)
@@ -26,14 +41,15 @@ export function toolError(
if (error instanceof ApiError && error.status >= 500) {
// Sanitize ALL 5xx — structured or not. Even structured backend errors
// can carry internal fingerprints (CLR exception types, stack frames,
// hint strings that name internal services), and the model has no
// legitimate reason to act on them. correlationId + errorCode stay —
// those are operational handles the operator can pivot on, not
// internals.
// can carry internal fingerprints (stack frames, hint strings that name
// internal services), and the model has no legitimate reason to act on
// them. correlationId + code stay — those are operational handles the
// operator can pivot on, not internals.
parts.push(`**Backend error in ${toolName}** (HTTP ${error.status}): the server returned an error.`);
if (error.parsed?.correlationId) parts.push(`**Correlation ID**: ${error.parsed.correlationId}`);
if (error.parsed?.errorCode) parts.push(`**Error code**: ${error.parsed.errorCode}`);
const cid = correlationLine(error);
if (cid) parts.push(cid);
const code = errorCodeOf(error.parsed);
if (code) parts.push(`**Error code**: ${code}`);
parts.push('**Suggestion**: retry in a few seconds; if persistent, ask an operator to inspect backend logs.');
} else if (error instanceof ApiError && error.status === 429 && error.parsed?.quotaExceeded === true) {
// Backend MCP quota (McpQuotaExceededResponse): the daily/monthly budget of the caller's own plan
@@ -48,7 +64,8 @@ export function toolError(
? p.targetTenantId
: undefined;
const whose = managedTenant ? `the managed tenant ${managedTenant}'s` : p.level === 'tenant' ? "your organization's" : 'your';
parts.push(`**Quota exceeded in ${toolName}**: ${p.message ?? `${whose} MCP ${p.scope ?? ''} request quota is exhausted.`}`);
// `error` is the envelope's message; `message` is the pre-envelope spelling.
parts.push(`**Quota exceeded in ${toolName}**: ${p.error ?? p.message ?? `${whose} MCP ${p.scope ?? ''} request quota is exhausted.`}`);
if (p.limit != null && p.used != null) parts.push(`**Budget**: ${p.used} of ${p.limit} requests used (${p.scope ?? 'window'}, ${p.level ?? 'user'} level).`);
if (p.resetUtc) parts.push(`**Resets at**: ${p.resetUtc}`);
parts.push(
@@ -58,18 +75,20 @@ export function toolError(
? '**Suggestion**: do not retry before the reset — the window is shared by every member of the tenant; a tenant admin can review consumption under Configuration → Reporting → MCP Usage.'
: '**Suggestion**: do not retry before the reset; narrow further queries, or ask an administrator about a larger usage plan.',
);
const cid = correlationLine(error);
if (cid) parts.push(cid);
} else if (error instanceof ApiError && error.parsed) {
// Structured backend error (4xx) — extract rich details
// Structured backend error (4xx) — the error envelope: error, code, correlationId, hint?
const p = error.parsed;
parts.push(`**Error in ${toolName}**: ${p.error ?? error.message}`);
if (p.hint) parts.push(`**Suggestion**: ${p.hint}`);
if (p.correlationId) parts.push(`**Correlation ID**: ${p.correlationId}`);
// exceptionType (CLR type names) is an internal fingerprint the model has no
// legitimate reason to act on — deliberately NOT surfaced here, mirroring the
// 5xx sanitization above. correlationId + errorCode remain as operator handles.
if (p.errorCode) parts.push(`**Error code**: ${p.errorCode}`);
// The operator log proxy forwards the telemetry store's own error JSON (query_backend_logs):
// that is what `az monitor … query` prints, and the parity promise is that nothing of it is lost.
const cid = correlationLine(error);
if (cid) parts.push(cid);
const code = errorCodeOf(p);
if (code) parts.push(`**Error code**: ${code}`);
// The operator log proxy (query_backend_logs) forwards the telemetry store's own error code and
// JSON: that is what `az monitor … query` prints, and the parity promise is that nothing of it is lost.
if (typeof p.upstreamCode === 'string' && p.upstreamCode.length > 0) parts.push(`**Upstream code**: ${p.upstreamCode}`);
if (typeof p.upstream === 'string' && p.upstream.length > 0) {
parts.push(`**Upstream response**:\n\`\`\`json\n${p.upstream.length > 4000 ? p.upstream.slice(0, 4000) + '…' : p.upstream}\n\`\`\``);
}
@@ -89,6 +108,8 @@ export function toolError(
const truncated = body.length > 500 ? body.slice(0, 500) + '…' : body;
parts.push(`**Error in ${toolName}** (HTTP ${error.status}): ${truncated}`);
}
const cid = correlationLine(error);
if (cid) parts.push(cid);
} else {
const message = error instanceof Error ? error.message : String(error);
if (message.includes('No authentication token')) {