From 2c90f5971d80b75d3da23e2acc83d4d0c21dadc3 Mon Sep 17 00:00:00 2001 From: Michal Date: Tue, 25 Aug 2026 23:23:16 +0100 Subject: [PATCH 1/9] fix(mcplocal): no LLM call can hang a tool call forever docs/reliability.md has stated the rule since it was written: "LLM-optional operations must be time-bounded, fall back deterministically, and report the degradation". The gate and llm/pagination.ts obey it. The newer proxymodel stages never adopted it -- stages/paginate.ts:72 awaited ctx.llm.complete() with no timeout and no signal, and its try/catch caught errors, not hangs. So when a provider hung rather than erroring, the promise never settled, the tool call never returned, mcplocal never wrote to the already-hijacked socket, and the client waited out its own 1800s timeout. In the journal that is three POST /projects/docmost/mcp requests accepted and never answered -- the only three such requests in 9,600 across every project, each followed immediately by [llm-adapter] "trying next" and [paginate] "Smart page titles failed". It read as a Docmost transport fault for two sessions. It was neither: Docmost answers /search in 203ms, and through mcplocal on a fresh session in 461ms. docmost_search returns ~14KB and crosses the pagination threshold; update_page returns a small ack and does not. One tool paginated, one did not, and only the paginating one could hang. Bound it centrally in the adapter rather than at each call site, so a stage that passes no options is still bounded and a stage written next year inherits the guarantee: - LLMCompleteOptions gains optional budgetMs/perCallTimeoutMs/signal. Optional matters -- seven inline stubs implement LLMProvider structurally and a required member would break every one. - LLMProviderAdapter.complete() runs one budget with a deadline across the whole failover chain, each attempt capped at min(perCall, remaining). A per-provider timeout would have made the worst case N x timeout; wrapping the method would have killed failover mid-chain. - Every attempt now gets a real AbortSignal. anthropic and openai (which back vllm) honour it; deepseek/ollama/gemini ignore it, and withTimeout's race unblocks the caller anyway -- exactly what its doc comment anticipated. - A caller abort stops failover: if nobody is waiting, don't burn the chain. util/degrade.ts generalises the gate's bounded -> fallback -> loud log -> degradedReason pattern into bounded(), which cannot throw, so the deterministic fallback is unconditional rather than something a catch block must remember. gate.ts is refactored onto it; plugin-gate and router-gate pass UNMODIFIED (61 tests), which is the proof the generalisation is faithful. anySignal() rather than AbortSignal.any: that landed in Node 20.3 and package.json declares >=20.0.0. proxymodel-llm-adapter.test.ts now asserts signal: expect.any(AbortSignal) -- every provider attempt being cancellable is the guarantee, so it is pinned. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- src/mcplocal/src/proxymodel/llm-adapter.ts | 45 +++++- src/mcplocal/src/proxymodel/plugins/gate.ts | 29 ++-- src/mcplocal/src/proxymodel/types.ts | 13 ++ src/mcplocal/src/util/degrade.ts | 79 +++++++++ src/mcplocal/src/util/with-timeout.ts | 23 +++ src/mcplocal/tests/degrade.test.ts | 77 +++++++++ src/mcplocal/tests/llm-adapter-budget.test.ts | 153 ++++++++++++++++++ .../tests/proxymodel-llm-adapter.test.ts | 4 + src/mcplocal/tests/with-timeout.test.ts | 33 +++- 9 files changed, 441 insertions(+), 15 deletions(-) create mode 100644 src/mcplocal/src/util/degrade.ts create mode 100644 src/mcplocal/tests/degrade.test.ts create mode 100644 src/mcplocal/tests/llm-adapter-budget.test.ts diff --git a/src/mcplocal/src/proxymodel/llm-adapter.ts b/src/mcplocal/src/proxymodel/llm-adapter.ts index ad8a6ff..cb9da43 100644 --- a/src/mcplocal/src/proxymodel/llm-adapter.ts +++ b/src/mcplocal/src/proxymodel/llm-adapter.ts @@ -8,6 +8,20 @@ import type { ProviderRegistry } from '../providers/registry.js'; import type { LlmProvider, CompletionOptions } from '../providers/types.js'; import type { LLMProvider, LLMCompleteOptions } from './types.js'; +import { withTimeout, TimeoutError, anySignal } from '../util/with-timeout.js'; + +/** + * Wall-clock budget for one ctx.llm.complete(), spanning ALL failover + * candidates. Bounds the worst case at one budget rather than N × per-attempt. + * + * Enforced here, in the adapter, rather than at each call site: a stage that + * passes no options is still bounded, and a stage written next year inherits + * the guarantee. Three production tool calls hung forever because + * stages/paginate.ts simply forgot to wrap its call. + */ +export const LLM_CALL_BUDGET_MS = Number(process.env['MCPCTL_LLM_CALL_BUDGET_MS'] ?? '20000'); +/** Cap on any single provider attempt inside that budget. */ +export const LLM_PROVIDER_TIMEOUT_MS = Number(process.env['MCPCTL_LLM_PROVIDER_TIMEOUT_MS'] ?? '10000'); export class LLMProviderAdapter implements LLMProvider { constructor( @@ -22,17 +36,44 @@ export class LLMProviderAdapter implements LLMProvider { throw new Error('No LLM provider available'); } + const budgetMs = options?.budgetMs ?? LLM_CALL_BUDGET_MS; + const perCallMs = options?.perCallTimeoutMs ?? LLM_PROVIDER_TIMEOUT_MS; + const deadline = Date.now() + budgetMs; const opts = this.buildOpts(prompt, options); let lastError: Error | null = null; + let tried = 0; for (const provider of candidates) { + const remaining = deadline - Date.now(); + if (remaining <= 0) { + // Budget spent mid-chain. Report the real cause where we have one — + // a provider that actually failed is more useful than "timed out". + throw lastError ?? new TimeoutError( + `llm completion (${String(tried)}/${String(candidates.length)} providers tried)`, + budgetMs, + ); + } + tried++; + const startedAt = Date.now(); try { - const result = await provider.complete(opts); + const result = await withTimeout( + (timeoutSignal) => provider.complete({ + ...opts, + signal: anySignal(timeoutSignal, options?.signal), + }), + Math.min(perCallMs, remaining), + `llm ${provider.name}`, + ); return result.content; } catch (err) { + // The caller gave up (stage budget / request deadline). Don't burn the + // rest of the chain on a request nobody is waiting for any more. + if (options?.signal?.aborted === true) throw err; lastError = err as Error; process.stderr.write( - `[llm-adapter] ${provider.name} failed, trying next: ${lastError.message}\n`, + `[llm-adapter] ${provider.name} failed after ${String(Date.now() - startedAt)}ms ` + + `(${String(Math.max(0, deadline - Date.now()))}ms budget left), ` + + `trying next: ${lastError.message}\n`, ); } } diff --git a/src/mcplocal/src/proxymodel/plugins/gate.ts b/src/mcplocal/src/proxymodel/plugins/gate.ts index 7dfdd53..1b240b8 100644 --- a/src/mcplocal/src/proxymodel/plugins/gate.ts +++ b/src/mcplocal/src/proxymodel/plugins/gate.ts @@ -15,7 +15,7 @@ import { TagMatcher, extractKeywordsFromToolCall, tokenizeDescription } from '.. import type { TagMatchResult } from '../../gate/tag-matcher.js'; import { LlmPromptSelector, pickCompletionText, type ServerInfer } from '../../gate/llm-selector.js'; import type { ProviderRegistry } from '../../providers/registry.js'; -import { withTimeout, TimeoutError } from '../../util/with-timeout.js'; +import { bounded } from '../../util/degrade.js'; import { sanitizeWireName } from '../../util/wire-names.js'; /** Cap on the gate's LLM prompt-selection. A slow/thinking LLM must never block @@ -314,7 +314,9 @@ async function handleBeginSession( let degradedReason: string | null = null; if (llmSelector) { - try { + // Labelled block, not try/catch: bounded() cannot throw, so falling back is + // an ordinary early exit rather than an exception path. + llmSelection: { const llmIndex = promptIndex.map((p) => ({ name: p.name, priority: p.priority, @@ -336,15 +338,25 @@ async function handleBeginSession( return pickCompletionText(resp); } : undefined; - const llmResult = await withTimeout( + const selection = await bounded( (signal) => llmSelector.selectPrompts(tags, llmIndex, { getSystemPromptFn, signal, ...(serverInfer ? { serverInfer } : {}), }), - GATE_LLM_TIMEOUT_MS, - 'gate LLM prompt-selection', + { + label: 'gate', + operation: 'LLM prompt-selection', + timeoutMs: GATE_LLM_TIMEOUT_MS, + fallback: 'to priority-ordered prompts', + }, ); + if (selection.degraded) { + degradedReason = selection.reason; + matchResult = tagMatcher.match(tags, promptIndex); + break llmSelection; + } + const llmResult = selection.value; reasoning = llmResult.reasoning; const selectedSet = new Set(llmResult.selectedNames); @@ -356,13 +368,6 @@ async function handleBeginSession( selected, ); matchResult.remaining = [...matchResult.remaining, ...remaining]; - } catch (err) { - degradedReason = err instanceof TimeoutError - ? `LLM prompt-selection timed out after ${String(GATE_LLM_TIMEOUT_MS)}ms` - : `LLM prompt-selection failed: ${(err as Error).message}`; - // Loud, not silent — visible in mcplocal logs. - console.error(`[gate] ${degradedReason} — falling back to priority-ordered prompts`); - matchResult = tagMatcher.match(tags, promptIndex); } } else { matchResult = tagMatcher.match(tags, promptIndex); diff --git a/src/mcplocal/src/proxymodel/types.ts b/src/mcplocal/src/proxymodel/types.ts index 83fbf67..da3b8a8 100644 --- a/src/mcplocal/src/proxymodel/types.ts +++ b/src/mcplocal/src/proxymodel/types.ts @@ -142,6 +142,19 @@ export interface LLMProvider { export interface LLMCompleteOptions { system?: string; maxTokens?: number; + /** + * Wall-clock budget for this call INCLUDING provider failover — N candidates + * share one budget, so the worst case is `budgetMs`, not N × per-attempt. + * Defaults to MCPCTL_LLM_CALL_BUDGET_MS. + */ + budgetMs?: number; + /** Cap on any single provider attempt inside that budget. */ + perCallTimeoutMs?: number; + /** + * Caller cancellation (stage budget, request deadline). Aborts failover too: + * if the caller has given up there is no point trying the next provider. + */ + signal?: AbortSignal; } /** diff --git a/src/mcplocal/src/util/degrade.ts b/src/mcplocal/src/util/degrade.ts new file mode 100644 index 0000000..b228d8a --- /dev/null +++ b/src/mcplocal/src/util/degrade.ts @@ -0,0 +1,79 @@ +/** + * Run an LLM-*optional* operation under a hard bound, never throwing. + * + * This is `docs/reliability.md`'s principle in one place: **bounded, + * deterministic fallback, loud not silent.** The pattern was previously + * open-coded in the gate (`proxymodel/plugins/gate.ts`) and pagination + * (`llm/pagination.ts`) while the newer proxymodel stages simply omitted it — + * `stages/paginate.ts` awaited a completion with no timeout at all, so a hung + * provider never settled, the tool call never returned, and the client waited + * out its own 1800s timeout. Three such requests were served (or rather, not + * served) in production. + * + * `bounded()` cannot throw. The caller always receives either a value or a + * reason string, which makes the deterministic fallback unconditional rather + * than something a `catch` block has to remember to do. + */ +import { withTimeout, TimeoutError, anySignal } from './with-timeout.js'; + +export type BoundedResult = + | { degraded: false; value: T } + | { degraded: true; reason: string }; + +export interface BoundedOptions { + /** Log prefix, e.g. 'gate' renders as `[gate] …`. */ + label: string; + /** What is being attempted, e.g. 'LLM prompt-selection'. Used in the reason. */ + operation: string; + timeoutMs: number; + /** Extra cancellation (stage budget, request deadline). */ + signal?: AbortSignal; + /** + * What happens instead, appended to the log line as `— falling back `. + * Keep it specific: these strings are what an operator greps for when a + * degradation has to be diagnosed after the fact. + */ + fallback?: string; +} + +export async function bounded( + run: (signal: AbortSignal) => Promise, + options: BoundedOptions, +): Promise> { + try { + const value = await withTimeout( + (timeoutSignal) => run(anySignal(timeoutSignal, options.signal)), + options.timeoutMs, + options.operation, + ); + return { degraded: false, value }; + } catch (err) { + const reason = err instanceof TimeoutError + ? `${options.operation} timed out after ${String(options.timeoutMs)}ms` + : `${options.operation} failed: ${(err as Error).message}`; + // Loud, not silent — visible in mcplocal logs. + const fallback = options.fallback ?? ''; + console.error(`[${options.label}] ${reason} — falling back${fallback ? ` ${fallback}` : ''}`); + return { degraded: true, reason }; + } +} + +/** + * The established user-facing wording: + * `⚠ unavailable (). ` + * + * Kept here so every degradation reads the same to a model, whichever + * subsystem produced it. + */ +export function degradationNotice(feature: string, reason: string, hint: string): string { + return `⚠ ${feature} unavailable (${reason}). ${hint}\n`; +} + +/** Audit payload fragment matching the existing `gate_decision` shape. */ +export function degradationAudit( + result: BoundedResult, +): { degraded: boolean; degradedReason: string | null } { + return result.degraded + ? { degraded: true, degradedReason: result.reason } + : { degraded: false, degradedReason: null }; +} diff --git a/src/mcplocal/src/util/with-timeout.ts b/src/mcplocal/src/util/with-timeout.ts index c67c720..8c25499 100644 --- a/src/mcplocal/src/util/with-timeout.ts +++ b/src/mcplocal/src/util/with-timeout.ts @@ -38,3 +38,26 @@ export async function withTimeout( if (timer !== undefined) clearTimeout(timer); } } + +/** + * Combine a timeout signal with an optional caller signal. + * + * `AbortSignal.any` landed in Node 20.3 but `package.json` declares `>=20.0.0`, + * so we cannot rely on it being present. Falls back to a small controller that + * mirrors whichever input aborts first. + */ +export function anySignal(timeoutSignal: AbortSignal, callerSignal?: AbortSignal): AbortSignal { + if (!callerSignal) return timeoutSignal; + const anyFn = (AbortSignal as { any?: (signals: AbortSignal[]) => AbortSignal }).any; + if (typeof anyFn === 'function') return anyFn([timeoutSignal, callerSignal]); + + const controller = new AbortController(); + if (timeoutSignal.aborted || callerSignal.aborted) { + controller.abort(); + return controller.signal; + } + const onAbort = (): void => { controller.abort(); }; + timeoutSignal.addEventListener('abort', onAbort, { once: true }); + callerSignal.addEventListener('abort', onAbort, { once: true }); + return controller.signal; +} diff --git a/src/mcplocal/tests/degrade.test.ts b/src/mcplocal/tests/degrade.test.ts new file mode 100644 index 0000000..7e63889 --- /dev/null +++ b/src/mcplocal/tests/degrade.test.ts @@ -0,0 +1,77 @@ +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { bounded, degradationNotice, degradationAudit } from '../src/util/degrade.js'; + +afterEach(() => { vi.restoreAllMocks(); }); + +describe('bounded', () => { + it('passes a value through untouched when the operation succeeds', async () => { + const res = await bounded(async () => 'ok', { + label: 'test', operation: 'thing', timeoutMs: 100, + }); + expect(res).toEqual({ degraded: false, value: 'ok' }); + }); + + it('degrades with a reason naming the timeout, instead of hanging', async () => { + const err = vi.spyOn(console, 'error').mockImplementation(() => { /* quiet */ }); + const start = Date.now(); + const res = await bounded(() => new Promise(() => { /* never settles */ }), { + label: 'paginate', operation: 'Smart page titles', timeoutMs: 50, + }); + expect(res.degraded).toBe(true); + if (!res.degraded) throw new Error('unreachable'); + expect(res.reason).toBe('Smart page titles timed out after 50ms'); + expect(Date.now() - start).toBeLessThan(1000); + expect(err).toHaveBeenCalledWith(expect.stringContaining('[paginate]')); + }); + + it('degrades with the message when the operation throws', async () => { + vi.spyOn(console, 'error').mockImplementation(() => { /* quiet */ }); + const res = await bounded(() => Promise.reject(new Error('boom')), { + label: 'test', operation: 'thing', timeoutMs: 100, + }); + if (!res.degraded) throw new Error('expected degradation'); + expect(res.reason).toBe('thing failed: boom'); + }); + + it('never throws — that is what makes the fallback unconditional', async () => { + vi.spyOn(console, 'error').mockImplementation(() => { /* quiet */ }); + await expect(bounded(() => { throw new Error('sync throw'); }, { + label: 'test', operation: 'thing', timeoutMs: 100, + })).resolves.toMatchObject({ degraded: true }); + }); + + it('honours a caller signal as well as the timeout', async () => { + vi.spyOn(console, 'error').mockImplementation(() => { /* quiet */ }); + const caller = new AbortController(); + let sawAbort = false; + const p = bounded((signal) => new Promise((_, reject) => { + signal.addEventListener('abort', () => { sawAbort = true; reject(new Error('aborted')); }); + }), { label: 'test', operation: 'thing', timeoutMs: 5000, signal: caller.signal }); + caller.abort(); + const res = await p; + expect(sawAbort).toBe(true); + expect(res.degraded).toBe(true); + }); +}); + +describe('degradationNotice', () => { + it('reproduces the established gate wording exactly', () => { + expect(degradationNotice( + 'Smart prompt-selection', + 'LLM prompt-selection timed out after 8000ms', + 'Showing priority-ordered prompts — still relevant, just not LLM-ranked.', + )).toBe( + '⚠ Smart prompt-selection unavailable (LLM prompt-selection timed out after 8000ms). ' + + 'Showing priority-ordered prompts — still relevant, just not LLM-ranked.\n', + ); + }); +}); + +describe('degradationAudit', () => { + it('matches the existing gate_decision payload shape', () => { + expect(degradationAudit({ degraded: false, value: 1 })) + .toEqual({ degraded: false, degradedReason: null }); + expect(degradationAudit({ degraded: true, reason: 'why' })) + .toEqual({ degraded: true, degradedReason: 'why' }); + }); +}); diff --git a/src/mcplocal/tests/llm-adapter-budget.test.ts b/src/mcplocal/tests/llm-adapter-budget.test.ts new file mode 100644 index 0000000..0a6ca04 --- /dev/null +++ b/src/mcplocal/tests/llm-adapter-budget.test.ts @@ -0,0 +1,153 @@ +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { LLMProviderAdapter } from '../src/proxymodel/llm-adapter.js'; +import { TimeoutError } from '../src/util/with-timeout.js'; +import type { ProviderRegistry } from '../src/providers/registry.js'; +import type { LlmProvider, CompletionOptions, CompletionResult } from '../src/providers/types.js'; + +/** A provider whose complete() never settles unless its signal aborts. */ +function hangingProvider(name: string): LlmProvider { + return { + name, + complete: (opts: CompletionOptions) => new Promise((_, reject) => { + opts.signal?.addEventListener('abort', () => { reject(new Error('aborted')); }); + }), + } as unknown as LlmProvider; +} + +/** + * A provider that ignores its AbortSignal entirely — deepseek, ollama, + * gemini-cli and gemini-acp all do. withTimeout's race must still unblock us. + */ +function deafProvider(name: string): LlmProvider { + return { + name, + complete: () => new Promise(() => { /* never settles, never listens */ }), + } as unknown as LlmProvider; +} + +function okProvider(name: string, content: string): LlmProvider { + return { + name, + complete: async () => ({ content, finishReason: 'stop' }), + } as unknown as LlmProvider; +} + +function failingProvider(name: string, message: string): LlmProvider { + return { + name, + complete: () => Promise.reject(new Error(message)), + } as unknown as LlmProvider; +} + +/** Registry stub exposing only what getCandidates() touches. */ +function registryOf(...providers: LlmProvider[]): ProviderRegistry { + const byName = new Map(providers.map((p) => [p.name, p])); + return { + get: (n: string) => byName.get(n) ?? null, + getTierProviders: (tier: string) => (tier === 'fast' ? [...byName.keys()] : []), + getActive: () => null, + } as unknown as ProviderRegistry; +} + +afterEach(() => { vi.restoreAllMocks(); }); + +describe('LLMProviderAdapter failover budget', () => { + it('shares one budget across all candidates instead of multiplying it', async () => { + vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + const adapter = new LLMProviderAdapter( + registryOf(hangingProvider('a'), hangingProvider('b'), hangingProvider('c')), + ); + + const start = Date.now(); + await expect( + adapter.complete('hi', { budgetMs: 300, perCallTimeoutMs: 100 }), + ).rejects.toBeInstanceOf(Error); + const elapsed = Date.now() - start; + + // Three hanging providers at 100ms each would be ~300ms either way, but the + // budget must cap the TOTAL: without it, a larger perCall would run 3x. + expect(elapsed).toBeLessThan(1000); + }); + + it('caps total time by budgetMs even when per-attempt would allow more', async () => { + vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + const adapter = new LLMProviderAdapter( + registryOf(hangingProvider('a'), hangingProvider('b'), hangingProvider('c')), + ); + + const start = Date.now(); + // perCall (10s) far exceeds the budget: pre-fix this was 3 x 10s. + await expect( + adapter.complete('hi', { budgetMs: 250, perCallTimeoutMs: 10_000 }), + ).rejects.toBeInstanceOf(Error); + expect(Date.now() - start).toBeLessThan(1500); + }); + + it('still fails over — a healthy provider after a broken one succeeds', async () => { + vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + const adapter = new LLMProviderAdapter( + registryOf(failingProvider('broken', 'nope'), okProvider('good', 'answer')), + ); + await expect(adapter.complete('hi')).resolves.toBe('answer'); + }); + + it('bounds a provider that ignores its abort signal', async () => { + vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + const adapter = new LLMProviderAdapter(registryOf(deafProvider('deaf-a'), deafProvider('deaf-b'))); + // Nothing honours the signal, so withTimeout's race is the only thing that + // can unblock the caller — and the surfaced cause is the timeout itself. + const start = Date.now(); + await expect( + adapter.complete('hi', { budgetMs: 200, perCallTimeoutMs: 80 }), + ).rejects.toBeInstanceOf(TimeoutError); + expect(Date.now() - start).toBeLessThan(1500); + }); + + it('surfaces the real provider failure rather than the budget when there is one', async () => { + vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + const adapter = new LLMProviderAdapter( + registryOf(failingProvider('broken', 'upstream 503'), deafProvider('deaf')), + ); + // 'broken' failing is more useful diagnostically than "budget expired". + await expect(adapter.complete('hi', { budgetMs: 150, perCallTimeoutMs: 80 })) + .rejects.toThrow(/upstream 503|timed out/); + }); + + it('stops failing over as soon as the caller aborts', async () => { + vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + let attempts = 0; + const counting = (name: string): LlmProvider => ({ + name, + complete: (opts: CompletionOptions) => { + attempts++; + return new Promise((_, reject) => { + opts.signal?.addEventListener('abort', () => { reject(new Error('aborted')); }); + }); + }, + } as unknown as LlmProvider); + + const adapter = new LLMProviderAdapter(registryOf(counting('a'), counting('b'), counting('c'))); + const caller = new AbortController(); + const p = adapter.complete('hi', { budgetMs: 5000, perCallTimeoutMs: 5000, signal: caller.signal }); + caller.abort(); + await expect(p).rejects.toBeInstanceOf(Error); + expect(attempts).toBe(1); // did not burn the rest of the chain + }); + + it('is bounded even when the caller passes no options at all', async () => { + vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + // The whole point of enforcing in the adapter: an unwrapped call site + // (stages/paginate.ts was exactly this) is still bounded by the env + // default. Re-import with a short default so the test is fast. + vi.stubEnv('MCPCTL_LLM_CALL_BUDGET_MS', '150'); + vi.stubEnv('MCPCTL_LLM_PROVIDER_TIMEOUT_MS', '80'); + vi.resetModules(); + const { LLMProviderAdapter: Fresh } = await import('../src/proxymodel/llm-adapter.js'); + const adapter = new Fresh(registryOf(deafProvider('deaf'))); + + const start = Date.now(); + await expect(adapter.complete('hi')).rejects.toBeInstanceOf(Error); + expect(Date.now() - start).toBeLessThan(1500); + vi.unstubAllEnvs(); + }); +}); diff --git a/src/mcplocal/tests/proxymodel-llm-adapter.test.ts b/src/mcplocal/tests/proxymodel-llm-adapter.test.ts index 815d46e..717df9f 100644 --- a/src/mcplocal/tests/proxymodel-llm-adapter.test.ts +++ b/src/mcplocal/tests/proxymodel-llm-adapter.test.ts @@ -52,9 +52,12 @@ describe('LLMProviderAdapter', () => { const result = await adapter.complete('summarize this'); expect(result).toBe('mock response'); + // signal is always supplied now: every provider attempt must be + // cancellable, so a hung provider can never outlive its budget. expect(provider.complete).toHaveBeenCalledWith({ messages: [{ role: 'user', content: 'summarize this' }], temperature: 0, + signal: expect.any(AbortSignal), }); }); @@ -74,6 +77,7 @@ describe('LLMProviderAdapter', () => { ], maxTokens: 200, temperature: 0, + signal: expect.any(AbortSignal), }); }); diff --git a/src/mcplocal/tests/with-timeout.test.ts b/src/mcplocal/tests/with-timeout.test.ts index f58ab99..e140569 100644 --- a/src/mcplocal/tests/with-timeout.test.ts +++ b/src/mcplocal/tests/with-timeout.test.ts @@ -1,5 +1,5 @@ import { describe, it, expect } from 'vitest'; -import { withTimeout, TimeoutError } from '../src/util/with-timeout.js'; +import { withTimeout, TimeoutError, anySignal } from '../src/util/with-timeout.js'; describe('withTimeout', () => { it('resolves when the operation finishes in time', async () => { @@ -33,3 +33,34 @@ describe('withTimeout', () => { ).rejects.toThrow('boom'); }); }); + +describe('anySignal', () => { + it('returns the timeout signal unchanged when there is no caller signal', () => { + const c = new AbortController(); + expect(anySignal(c.signal)).toBe(c.signal); + }); + + it('aborts when the timeout signal aborts', () => { + const timeout = new AbortController(); + const caller = new AbortController(); + const merged = anySignal(timeout.signal, caller.signal); + expect(merged.aborted).toBe(false); + timeout.abort(); + expect(merged.aborted).toBe(true); + }); + + it('aborts when the caller signal aborts', () => { + const timeout = new AbortController(); + const caller = new AbortController(); + const merged = anySignal(timeout.signal, caller.signal); + caller.abort(); + expect(merged.aborted).toBe(true); + }); + + it('is already aborted when an input was aborted before merging', () => { + const timeout = new AbortController(); + const caller = new AbortController(); + caller.abort(); + expect(anySignal(timeout.signal, caller.signal).aborted).toBe(true); + }); +}); -- 2.49.1 From c2a419b4f7945dcdd02938427ddfeeb115e8ab0d Mon Sep 17 00:00:00 2001 From: Michal Date: Tue, 25 Aug 2026 23:29:45 +0100 Subject: [PATCH 2/9] fix(mcplocal): one LLM budget per stage, so a loop cannot multiply it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A per-call timeout bounds one call. It does not bound a stage that calls the LLM in a loop -- and summarize-tree does worse than loop: buildTree recurses to maxDepth (3 by default) and iterates per section at every level, then groupSections iterates again. Hundreds of sequential calls are reachable, so a 10s per-call cap is a multiplier, not a bound. StageBudget is one wall-clock budget shared across everything a single stage invocation does. Once it is gone the stage takes its deterministic path -- first-line excerpts, numbered pages -- and says so. The executor builds one per stage from config.budgetMs ?? MCPCTL_STAGE_LLM_BUDGET_MS (30s) and disposes it in a finally, so a long-lived mcplocal never accumulates timers. Two details that matter more than they look: - A warm cache is never budget-gated. cachedSummarize and generatePageTitles used ctx.cache.getOrCompute, which makes the budget check impossible to place correctly; split into get/set so a cached summary -- which costs nothing -- is still returned when the budget is spent. - "No LLM configured" is NOT a degradation. It is a deliberate choice, and numbered pages are the expected output there, so it gets no warning. Only failures, timeouts and exhausted budgets do. Crying wolf on a working configuration would train people to ignore the notice. summarize-tree's single-block path previously had no try/catch at all, so a failure escaped the stage entirely and executor.ts discarded the whole stage's work. It now degrades like the others. Degradation is reported three ways, all from util/degrade.ts: the reason in the content behind the established "⚠ unavailable ()" prefix, the count of affected sections (the recursion can hit one exhausted budget dozens of times, so the user needs the reason once plus what it cost), and degraded/degradedReason on the stage_execution audit event -- previously a degradation was invisible in the trace. docs/reliability.md now names ONE helper rather than a list of compliant call sites. That list is exactly how this drifted: the doc named the gate and llm/pagination.ts, and the newer stages never joined it. Tests: the 20-section recursion completes in ~300ms against a 300ms budget; a warm cache still serves real titles with the budget exhausted. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- docs/reliability.md | 45 ++++++- src/mcplocal/src/proxymodel/executor.ts | 17 +++ src/mcplocal/src/proxymodel/stage-budget.ts | 50 +++++++ .../src/proxymodel/stages/paginate.ts | 96 ++++++++++---- .../src/proxymodel/stages/summarize-tree.ts | 108 +++++++++++++--- src/mcplocal/src/proxymodel/types.ts | 9 ++ src/mcplocal/tests/proxymodel-stages.test.ts | 2 + src/mcplocal/tests/proxymodel-types.test.ts | 2 + src/mcplocal/tests/stage-budget.test.ts | 122 ++++++++++++++++++ .../tests/system-prompt-fetching.test.ts | 2 + 10 files changed, 405 insertions(+), 48 deletions(-) create mode 100644 src/mcplocal/src/proxymodel/stage-budget.ts create mode 100644 src/mcplocal/tests/stage-budget.test.ts diff --git a/docs/reliability.md b/docs/reliability.md index 30423c8..0eae89f 100644 --- a/docs/reliability.md +++ b/docs/reliability.md @@ -19,10 +19,47 @@ and report the degradation — never hang and never degrade silently.** ()…` and sets `degraded: true` + `degradedReason` on the audit `gate_decision` event. -Applied in: the gate's `begin_session` prompt selection -(`proxymodel/plugins/gate.ts`, cap `MCPCTL_GATE_LLM_TIMEOUT_MS`, default 8s) and -pagination's smart index (`llm/pagination.ts`, `MCPCTL_PAGINATION_LLM_TIMEOUT_MS`, -default 10s). `read_prompts` is LLM-free by design. +**One implementation:** [`util/degrade.ts`](../src/mcplocal/src/util/degrade.ts)'s +`bounded()`. It cannot throw — the caller always gets a value or a reason — so +the deterministic fallback is unconditional rather than something a `catch` +block has to remember. `degradationNotice()` produces the `⚠ … unavailable +(reason). hint` wording, and `degradationAudit()` the `degraded`/`degradedReason` +payload, so every degradation reads the same whichever subsystem produced it. + +**Nothing optional is unbounded by construction.** The budget lives in +`LLMProviderAdapter.complete()` (`proxymodel/llm-adapter.ts`), not at each call +site, so a stage that passes no options is still bounded and a stage written +next year inherits the guarantee. One budget spans the whole failover chain — +a per-provider timeout would make the worst case N × timeout. + +| Knob | Default | Bounds | +|---|---|---| +| `MCPCTL_LLM_CALL_BUDGET_MS` | 20s | one `ctx.llm.complete()`, failover included | +| `MCPCTL_LLM_PROVIDER_TIMEOUT_MS` | 10s | a single provider attempt inside that budget | +| `MCPCTL_STAGE_LLM_BUDGET_MS` | 30s | all LLM work in one stage invocation | +| `MCPCTL_GATE_LLM_TIMEOUT_MS` | 8s | the gate's `begin_session` prompt selection | +| `MCPCTL_PAGINATION_LLM_TIMEOUT_MS` | 10s | pagination's smart index (`llm/pagination.ts`) | + +The **stage** budget exists because a per-call timeout multiplies rather than +bounds when a stage loops: `summarize-tree` recurses to `maxDepth` (3) and loops +per section at every level, so hundreds of sequential calls are reachable. One +budget is shared across the whole recursion; when it is gone the stage switches +to first-line excerpts and says so. A **warm cache is never budget-gated** — a +cached summary costs nothing, so an exhausted budget must not degrade a result +we already hold. + +`read_prompts` is LLM-free by design. + +### Why this is written down twice + +This document stated the principle while `proxymodel/stages/paginate.ts` awaited +`ctx.llm.complete()` with no timeout at all. When a provider hung rather than +erroring, the promise never settled, the tool call never returned, and the +client waited out its own 1800s timeout — three such requests in production, +misdiagnosed twice as an upstream "transport fault". The doc named the gate and +`llm/pagination.ts` as the compliant sites, and the newer stages simply never +joined the list. Naming **one** helper here, rather than a list of call sites, +is what stops that drift recurring. Note: the gate's prompt-ranking uses the **heavy client provider's own model** — it deliberately does *not* force the project's vLLM model onto it (doing so made diff --git a/src/mcplocal/src/proxymodel/executor.ts b/src/mcplocal/src/proxymodel/executor.ts index 9b3f69d..6f8e208 100644 --- a/src/mcplocal/src/proxymodel/executor.ts +++ b/src/mcplocal/src/proxymodel/executor.ts @@ -6,6 +6,7 @@ import type { StageContext, StageResult, StageLogger, Section, ContentType, LLMProvider, CacheProvider, SystemPromptFetcher } from './types.js'; import type { ProxyModelDefinition } from './schema.js'; import { getStage } from './stage-registry.js'; +import { createStageBudget, STAGE_LLM_BUDGET_MS } from './stage-budget.js'; import type { AuditCollector } from '../audit/collector.js'; export interface ExecuteOptions { @@ -87,6 +88,11 @@ export async function executePipeline(opts: ExecuteOptions): Promise { controller.abort(); }, totalMs); + // Node keeps the process alive for pending timers; a stage budget must not. + if (typeof timer.unref === 'function') timer.unref(); + + return { + totalMs, + signal: controller.signal, + remainingMs: (): number => Math.max(0, totalMs - (Date.now() - startedAt)), + exhausted: (): boolean => Date.now() - startedAt >= totalMs, + dispose: (): void => { clearTimeout(timer); }, + }; +} + +/** Never-expiring budget, for tests and non-LLM call paths. */ +export function unlimitedStageBudget(): StageBudget { + return { + totalMs: Number.POSITIVE_INFINITY, + signal: new AbortController().signal, + remainingMs: (): number => Number.POSITIVE_INFINITY, + exhausted: (): boolean => false, + dispose: (): void => { /* nothing to clean up */ }, + }; +} diff --git a/src/mcplocal/src/proxymodel/stages/paginate.ts b/src/mcplocal/src/proxymodel/stages/paginate.ts index 7b522e0..664f474 100644 --- a/src/mcplocal/src/proxymodel/stages/paginate.ts +++ b/src/mcplocal/src/proxymodel/stages/paginate.ts @@ -9,6 +9,7 @@ * previewChars: number (chars per page sent to LLM for title generation, default 300) */ import type { StageHandler, StageContext, Section } from '../types.js'; +import { bounded, degradationNotice } from '../../util/degrade.js'; const handler: StageHandler = async (content, ctx) => { const pageSize = (ctx.config.pageSize as number | undefined) ?? 8000; @@ -24,7 +25,7 @@ const handler: StageHandler = async (content, ctx) => { return { content }; } - const titles = await generatePageTitles(pages, ctx); + const { titles, degradedReason } = await generatePageTitles(pages, ctx); const sections: Section[] = pages.map((page, i) => ({ id: `page-${i + 1}`, @@ -36,65 +37,104 @@ const handler: StageHandler = async (content, ctx) => { `[${s.id}] ${s.title} (${pages[i]!.length} chars)`, ).join('\n'); + // Loud, not silent: if the titles are numbered because the LLM was slow or + // down, say so rather than letting the model assume the pages are unnamed. + const notice = degradedReason === null + ? '' + : degradationNotice('Smart page titles', degradedReason, 'Pages are numbered instead.'); + return { // No navigation hint here — the caller (content-pipeline / router) appends // the authoritative _resultId/_section instruction once sections are stored. - content: `Content split into ${sections.length} pages (${content.length} total chars):\n${toc}`, + content: `${notice}Content split into ${sections.length} pages (${content.length} total chars):\n${toc}`, sections, + ...(degradedReason === null ? {} : { metadata: { degraded: true, degradedReason } }), }; }; /** - * Generate descriptive titles for each page using LLM. - * Falls back to generic "Page N" titles if LLM is unavailable or fails. + * Generate descriptive titles for each page using the LLM. + * + * Returns a degradation reason instead of throwing: the deterministic + * "Page N" fallback is unconditional. Before this was bounded, a provider that + * hung (rather than erroring) left the awaited promise unsettled forever — the + * tool call never returned and the client waited out its own 1800s timeout. */ -async function generatePageTitles(pages: string[], ctx: StageContext): Promise { +async function generatePageTitles( + pages: string[], + ctx: StageContext, +): Promise<{ titles: string[]; degradedReason: string | null }> { const fallback = pages.map((_, i) => `Page ${i + 1}`); + // No LLM configured is a deliberate choice, not a degradation — numbered + // pages are the expected output there, so don't warn about them. if (!ctx.llm.available()) { - return fallback; + return { titles: fallback, degradedReason: null }; } const previewChars = (ctx.config.previewChars as number | undefined) ?? 300; const cacheKey = `paginate-titles:${ctx.cache.hash(ctx.originalContent)}:${pages.length}`; - try { - const cached = await ctx.cache.getOrCompute(cacheKey, async () => { - const previews = pages.map((page, i) => { - const preview = page.slice(0, previewChars).trim(); - return `--- Page ${i + 1} (${page.length} chars) ---\n${preview}`; - }).join('\n\n'); + // Read the cache BEFORE consulting the budget — a warm cache costs nothing, + // so an exhausted budget must not degrade a result we already hold. + const cached = await ctx.cache.get(cacheKey); + if (cached !== null) { + try { + return { titles: JSON.parse(cached) as string[], degradedReason: null }; + } catch { + // Corrupt entry — fall through and recompute. + } + } - const DEFAULT_PROMPT = `Generate exactly {{pageCount}} short descriptive titles (max 60 chars each) for the following {{pageCount}} pages. Return ONLY a JSON array of {{pageCount}} strings. No markdown, no explanation.`; - const template = await ctx.getSystemPrompt('llm-paginate-titles', DEFAULT_PROMPT); - const prompt = template.replaceAll('{{pageCount}}', String(pages.length)); + if (ctx.budget.exhausted()) { + return { + titles: fallback, + degradedReason: `stage LLM budget of ${String(ctx.budget.totalMs)}ms exhausted`, + }; + } - const result = await ctx.llm.complete( - `${prompt}\n\n${previews}`, - { maxTokens: pages.length * 30 }, - ); + const previews = pages.map((page, i) => { + const preview = page.slice(0, previewChars).trim(); + return `--- Page ${i + 1} (${page.length} chars) ---\n${preview}`; + }).join('\n\n'); - // Parse JSON array from response, pad/truncate to match page count + const DEFAULT_PROMPT = `Generate exactly {{pageCount}} short descriptive titles (max 60 chars each) for the following {{pageCount}} pages. Return ONLY a JSON array of {{pageCount}} strings. No markdown, no explanation.`; + const template = await ctx.getSystemPrompt('llm-paginate-titles', DEFAULT_PROMPT); + const prompt = template.replaceAll('{{pageCount}}', String(pages.length)); + + const outcome = await bounded( + async (signal) => { + const result = await ctx.llm.complete(`${prompt}\n\n${previews}`, { + maxTokens: pages.length * 30, + budgetMs: ctx.budget.remainingMs(), + signal, + }); const match = result.match(/\[[\s\S]*\]/); if (!match) throw new Error('No JSON array in response'); const raw = JSON.parse(match[0]) as string[]; if (!Array.isArray(raw) || raw.length === 0) { throw new Error('Empty or invalid title array'); } - // Pad with generic titles if model returned fewer, truncate if more - const titles = pages.map((_, i) => + return pages.map((_, i) => (i < raw.length && typeof raw[i] === 'string' && raw[i]!.trim()) ? raw[i]!.trim().slice(0, 80) : `Page ${i + 1}`, ); - return JSON.stringify(titles); - }); + }, + { + label: 'paginate', + operation: 'Smart page titles', + timeoutMs: ctx.budget.remainingMs(), + signal: ctx.budget.signal, + fallback: 'to numbered pages', + }, + ); - return JSON.parse(cached) as string[]; - } catch (err) { - ctx.log.warn(`Smart page titles failed, using generic: ${(err as Error).message}`); - return fallback; + if (outcome.degraded) { + return { titles: fallback, degradedReason: outcome.reason }; } + await ctx.cache.set(cacheKey, JSON.stringify(outcome.value)); + return { titles: outcome.value, degradedReason: null }; } function splitPages(content: string, pageSize: number): string[] { diff --git a/src/mcplocal/src/proxymodel/stages/summarize-tree.ts b/src/mcplocal/src/proxymodel/stages/summarize-tree.ts index b75e419..312de5f 100644 --- a/src/mcplocal/src/proxymodel/stages/summarize-tree.ts +++ b/src/mcplocal/src/proxymodel/stages/summarize-tree.ts @@ -14,11 +14,13 @@ */ import type { StageHandler, Section } from '../types.js'; import { detectContentType } from '../content-type.js'; +import { bounded, degradationNotice } from '../../util/degrade.js'; const handler: StageHandler = async (content, ctx) => { const maxTokens = (ctx.config.maxSummaryTokens as number | undefined) ?? 200; const maxGroup = (ctx.config.maxGroupSize as number | undefined) ?? 5; const maxDepth = (ctx.config.maxDepth as number | undefined) ?? 3; + const deg = createDegradeSink(); // If content is small, just return it unchanged if (content.length < 2000) { @@ -37,7 +39,16 @@ const handler: StageHandler = async (content, ctx) => { return { content }; } - const summary = await cachedSummarize(ctx, ctx.originalContent, maxTokens); + const summary = await cachedSummarize(ctx, ctx.originalContent, maxTokens, deg); + if (summary === null) { + // Budget gone or the LLM failed: return the content untouched rather + // than a summary we could not produce. Previously this path had no + // try/catch at all, so a failure escaped the stage entirely. + return { + content: degradationNotice('Smart summaries', deg.reason ?? 'unavailable', 'Content is unsummarised.') + content, + metadata: { degraded: true, degradedReason: deg.reason }, + }; + } return { content: summary + '\n\nSection "full" holds the complete content.', sections: [{ id: 'full', title: 'Full Content', content: ctx.originalContent }], @@ -45,7 +56,7 @@ const handler: StageHandler = async (content, ctx) => { } // Build the summary tree - const tree = await buildTree(sections, ctx, { maxTokens, maxGroup, maxDepth, depth: 0 }); + const tree = await buildTree(sections, ctx, { maxTokens, maxGroup, maxDepth, depth: 0, deg }); // Format top-level ToC const toc = tree.map((s) => { @@ -55,9 +66,20 @@ const handler: StageHandler = async (content, ctx) => { return `[${s.id}] ${s.title}${childHint}`; }).join('\n'); + // One reason, plus how many summaries it cost — the recursion can hit the + // same exhausted budget dozens of times. + const notice = deg.reason === null + ? '' + : degradationNotice( + 'Smart summaries', + deg.reason, + `Showing first-line excerpts for ${String(deg.count)} of ${String(tree.length)} sections.`, + ); + return { - content: `${tree.length} sections:\n${toc}`, + content: `${notice}${tree.length} sections:\n${toc}`, sections: tree, + ...(deg.reason === null ? {} : { metadata: { degraded: true, degradedReason: deg.reason } }), }; }; @@ -66,6 +88,8 @@ interface TreeOpts { maxGroup: number; maxDepth: number; depth: number; + /** Shared across the whole recursion — one budget, one reported reason. */ + deg: DegradeSink; } async function buildTree( @@ -84,7 +108,8 @@ async function buildTree( summary = structuralSummary(section.content, contentType); } else if (ctx.llm.available()) { // LLM summary for prose/code - summary = await cachedSummarize(ctx, section.content, opts.maxTokens); + summary = await cachedSummarize(ctx, section.content, opts.maxTokens, opts.deg) + ?? (section.content.split('\n')[0] ?? '').slice(0, 200); } else { // No LLM — use first line as summary summary = (section.content.split('\n')[0] ?? '').slice(0, 200); @@ -125,18 +150,68 @@ async function cachedSummarize( ctx: import('../types.js').StageContext, content: string, maxTokens: number, -): Promise { + deg: DegradeSink, +): Promise { const key = `summary:${ctx.cache.hash(content)}:${maxTokens}`; - return ctx.cache.getOrCompute(key, async () => { - const DEFAULT_PROMPT = `Summarize the following in about {{maxTokens}} tokens. Preserve all items marked MUST, REQUIRED, or CRITICAL verbatim. Be specific — mention names, IDs, counts, key values.`; - const template = await ctx.getSystemPrompt('llm-summarize', DEFAULT_PROMPT); - const prompt = template.replaceAll('{{maxTokens}}', String(maxTokens)); - return ctx.llm.complete( - `${prompt}\n\n${content}`, - { maxTokens }, - ); - }); + // Read the cache BEFORE consulting the budget: a warm entry costs nothing, + // so an exhausted budget must never degrade a summary we already hold. + const cached = await ctx.cache.get(key); + if (cached !== null) return cached; + + if (ctx.budget.exhausted()) { + deg.note(`stage LLM budget of ${String(ctx.budget.totalMs)}ms exhausted`); + return null; + } + + const DEFAULT_PROMPT = `Summarize the following in about {{maxTokens}} tokens. Preserve all items marked MUST, REQUIRED, or CRITICAL verbatim. Be specific — mention names, IDs, counts, key values.`; + const template = await ctx.getSystemPrompt('llm-summarize', DEFAULT_PROMPT); + const prompt = template.replaceAll('{{maxTokens}}', String(maxTokens)); + + const outcome = await bounded( + (signal) => ctx.llm.complete(`${prompt}\n\n${content}`, { + maxTokens, + budgetMs: ctx.budget.remainingMs(), + signal, + }), + { + label: 'summarize-tree', + operation: 'Smart summaries', + timeoutMs: ctx.budget.remainingMs(), + signal: ctx.budget.signal, + fallback: 'to first-line excerpts', + }, + ); + + if (outcome.degraded) { + deg.note(outcome.reason); + return null; + } + await ctx.cache.set(key, outcome.value); + return outcome.value; +} + +/** + * Collects the first degradation reason and a count. + * + * buildTree recurses and loops, so one exhausted budget can produce dozens of + * identical reasons; the user needs the reason once plus how many summaries it + * cost them. + */ +export interface DegradeSink { + note(reason: string): void; + readonly reason: string | null; + readonly count: number; +} + +export function createDegradeSink(): DegradeSink { + let reason: string | null = null; + let count = 0; + return { + note(r: string): void { reason ??= r; count++; }, + get reason(): string | null { return reason; }, + get count(): number { return count; }, + }; } function structuralSummary(content: string, type: string): string { @@ -267,9 +342,10 @@ async function groupSections( const groupContent = chunk.map((s) => `[${s.id}] ${s.title}`).join('\n'); const groupId = `group-${Math.floor(i / opts.maxGroup) + 1}`; + const genericTitle = `Group ${Math.floor(i / opts.maxGroup) + 1} (${chunk.length} sections)`; const groupTitle = ctx.llm.available() - ? await cachedSummarize(ctx, groupContent, 50) - : `Group ${Math.floor(i / opts.maxGroup) + 1} (${chunk.length} sections)`; + ? (await cachedSummarize(ctx, groupContent, 50, opts.deg) ?? genericTitle) + : genericTitle; groups.push({ id: groupId, diff --git a/src/mcplocal/src/proxymodel/types.ts b/src/mcplocal/src/proxymodel/types.ts index da3b8a8..4ad62c1 100644 --- a/src/mcplocal/src/proxymodel/types.ts +++ b/src/mcplocal/src/proxymodel/types.ts @@ -10,6 +10,8 @@ * SessionController — method-level hooks with per-session state */ +import type { StageBudget } from './stage-budget.js'; + /** Fetches a system prompt by name, falling back to the provided default. */ export type SystemPromptFetcher = (name: string, fallback: string) => Promise; @@ -48,6 +50,13 @@ export interface StageContext { /** Stage-specific configuration from the proxymodel YAML */ config: Record; + + /** + * Shared wall-clock budget for this stage's LLM work. A stage that calls the + * LLM in a loop must check this between calls and fall back deterministically + * once it is gone — a per-call timeout alone multiplies rather than bounds. + */ + budget: StageBudget; } export interface StageResult { diff --git a/src/mcplocal/tests/proxymodel-stages.test.ts b/src/mcplocal/tests/proxymodel-stages.test.ts index d58a8b7..f11b076 100644 --- a/src/mcplocal/tests/proxymodel-stages.test.ts +++ b/src/mcplocal/tests/proxymodel-stages.test.ts @@ -5,6 +5,7 @@ import paginate from '../src/proxymodel/stages/paginate.js'; import sectionSplit from '../src/proxymodel/stages/section-split.js'; import summarizeTree from '../src/proxymodel/stages/summarize-tree.js'; import { BUILT_IN_STAGES } from '../src/proxymodel/stages/index.js'; +import { unlimitedStageBudget } from '../src/proxymodel/stage-budget.js'; function mockCtx(original: string, config: Record = {}, llmAvailable = false): StageContext { const llmResponses: string[] = []; @@ -48,6 +49,7 @@ function mockCtx(original: string, config: Record = {}, llmAvai cache: mockCache, log: mockLog, getSystemPrompt: async (_name: string, fallback: string) => fallback, + budget: unlimitedStageBudget(), config, }; } diff --git a/src/mcplocal/tests/proxymodel-types.test.ts b/src/mcplocal/tests/proxymodel-types.test.ts index 2983475..7febbba 100644 --- a/src/mcplocal/tests/proxymodel-types.test.ts +++ b/src/mcplocal/tests/proxymodel-types.test.ts @@ -12,6 +12,7 @@ import type { SessionContext, ContentType, } from '../src/proxymodel/index.js'; +import { unlimitedStageBudget } from '../src/proxymodel/stage-budget.js'; describe('ProxyModel type contract', () => { it('StageHandler can be implemented as a simple function', async () => { @@ -137,6 +138,7 @@ function createMockContext(original: string): StageContext { cache: mockCache, log: mockLog, getSystemPrompt: async (_name: string, fallback: string) => fallback, + budget: unlimitedStageBudget(), config: {}, }; } diff --git a/src/mcplocal/tests/stage-budget.test.ts b/src/mcplocal/tests/stage-budget.test.ts new file mode 100644 index 0000000..9e96177 --- /dev/null +++ b/src/mcplocal/tests/stage-budget.test.ts @@ -0,0 +1,122 @@ +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { createStageBudget, unlimitedStageBudget, STAGE_LLM_BUDGET_MS } from '../src/proxymodel/stage-budget.js'; +import { getStage } from '../src/proxymodel/stage-registry.js'; +import '../src/proxymodel/stages/index.js'; +import type { StageContext, LLMProvider, CacheProvider, StageLogger } from '../src/proxymodel/types.js'; + +afterEach(() => { vi.restoreAllMocks(); }); + +function ctxWith(llm: LLMProvider, original: string, budgetMs: number): StageContext { + const store = new Map(); + const cache: CacheProvider = { + async getOrCompute(k, c) { + if (store.has(k)) return store.get(k)!; + const v = await c(); store.set(k, v); return v; + }, + hash: (c) => c.slice(0, 8), + async get(k) { return store.get(k) ?? null; }, + async set(k, v) { store.set(k, v); }, + }; + const log: StageLogger = { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn() }; + return { + contentType: 'toolResult', sourceName: 'test/tool', projectName: 'test', sessionId: 's1', + originalContent: original, llm, cache, log, + getSystemPrompt: async (_n, f) => f, + config: {}, + budget: createStageBudget(budgetMs), + }; +} + +/** Never settles and ignores the signal — the shape that caused the outage. */ +const hangingLlm: LLMProvider = { + complete: () => new Promise(() => { /* never */ }), + available: () => true, +}; + +describe('StageBudget', () => { + it('reports remaining time and expires', async () => { + const b = createStageBudget(60); + expect(b.exhausted()).toBe(false); + expect(b.remainingMs()).toBeGreaterThan(0); + await new Promise((r) => setTimeout(r, 90)); + expect(b.exhausted()).toBe(true); + expect(b.remainingMs()).toBe(0); + expect(b.signal.aborted).toBe(true); + b.dispose(); + }); + + it('unlimited budget never expires', () => { + const b = unlimitedStageBudget(); + expect(b.exhausted()).toBe(false); + expect(b.remainingMs()).toBe(Number.POSITIVE_INFINITY); + b.dispose(); + }); + + it('defaults to the documented 30s', () => { + expect(STAGE_LLM_BUDGET_MS).toBe(30_000); + }); +}); + +describe('paginate under a hung LLM', () => { + it('returns numbered pages within the budget instead of hanging', async () => { + vi.spyOn(console, 'error').mockImplementation(() => { /* quiet */ }); + const handler = getStage('paginate')!; + const content = 'x'.repeat(30_000); + const ctx = ctxWith(hangingLlm, content, 200); + + const start = Date.now(); + const result = await handler(content, ctx); + const elapsed = Date.now() - start; + + // The whole point: this used to never return at all. + expect(elapsed).toBeLessThan(3000); + expect(result.content).toContain('⚠ Smart page titles unavailable'); + expect(result.content).toContain('page-1'); + expect(result.metadata?.['degraded']).toBe(true); + ctx.budget.dispose(); + }); + + it('serves a warm cache even with an exhausted budget', async () => { + const handler = getStage('paginate')!; + const content = 'y'.repeat(30_000); + + // Warm the cache with a working LLM and a generous budget. + const good: LLMProvider = { + complete: async () => '["Alpha","Beta","Gamma","Delta"]', + available: () => true, + }; + const warm = ctxWith(good, content, 5000); + await handler(content, warm); + + // Same cache, no budget left: the cached titles must still be used. + const cold: StageContext = { ...warm, llm: hangingLlm, budget: createStageBudget(1) }; + await new Promise((r) => setTimeout(r, 10)); + const result = await handler(content, cold); + + expect(result.content).toContain('Alpha'); + expect(result.content).not.toContain('⚠'); + warm.budget.dispose(); + cold.budget.dispose(); + }); +}); + +describe('summarize-tree under a hung LLM', () => { + it('bounds the whole recursion, not each call', async () => { + vi.spyOn(console, 'error').mockImplementation(() => { /* quiet */ }); + const handler = getStage('summarize-tree')!; + // Many sections: pre-fix, a per-call timeout would multiply across the + // sequential loop AND the recursion (maxDepth 3). + const sections = Array.from({ length: 20 }, (_, i) => + `## Section ${i + 1}\n${'prose '.repeat(400)}`).join('\n\n'); + const ctx = ctxWith(hangingLlm, sections, 300); + + const start = Date.now(); + const result = await handler(sections, ctx); + const elapsed = Date.now() - start; + + expect(elapsed).toBeLessThan(5000); + expect(result.content).toContain('⚠ Smart summaries unavailable'); + expect(result.metadata?.['degraded']).toBe(true); + ctx.budget.dispose(); + }); +}); diff --git a/src/mcplocal/tests/system-prompt-fetching.test.ts b/src/mcplocal/tests/system-prompt-fetching.test.ts index 545b34b..8730a38 100644 --- a/src/mcplocal/tests/system-prompt-fetching.test.ts +++ b/src/mcplocal/tests/system-prompt-fetching.test.ts @@ -2,6 +2,7 @@ import { describe, it, expect, vi } from 'vitest'; import type { StageContext, LLMProvider, CacheProvider, StageLogger, SystemPromptFetcher } from '../src/proxymodel/types.js'; import paginate from '../src/proxymodel/stages/paginate.js'; import summarizeTree from '../src/proxymodel/stages/summarize-tree.js'; +import { unlimitedStageBudget } from '../src/proxymodel/stage-budget.js'; function mockCtx( original: string, @@ -50,6 +51,7 @@ function mockCtx( cache: mockCache, log: mockLog, getSystemPrompt: opts.getSystemPrompt ?? (async (_name, fallback) => fallback), + budget: unlimitedStageBudget(), config, }; } -- 2.49.1 From c06c34f0a26513491516ea5e695c545f3ed897fb Mon Sep 17 00:00:00 2001 From: Michal Date: Tue, 25 Aug 2026 23:32:10 +0100 Subject: [PATCH 3/9] feat(mcplocal): a trace code that actually reaches the audit trail The plumbing for request tracing was all present and almost entirely inert. correlationId was generated at the endpoint and threaded into traffic events, but: - emitTrace() dropped it, so every durable tool_call_trace row had correlationId = null and could not be joined to anything; - ExecuteOptions.correlationId existed but its only production caller never passed it, making every stage_execution and pipeline_execution row unjoinable too -- dead code that looked like a feature; - plugin events (all three gate emits) had no access to it at all; - and the value itself was `:`, which nobody can retype from a screenshot. Also fixed: onToolCallBefore intercepts returned without emitTrace, so every tool call made while a session was gated produced no trace whatsoever. The trace code now IS the correlationId. Nothing parses the old format -- checked across mcpd's audit repository and route, mcplocal's router and traffic capture, and the CLI console -- sessionId is its own audit column and the JSON-RPC id is in the traffic body, so nothing is lost. AuditEvent.correlationId is already an indexed Postgres column, so lookup works with no migration. 8 chars of Crockford base32 without I/L/O/U: readable aloud, typeable from a screenshot, 40 bits (a collision shows two traces, it corrupts nothing). Getting it to the plugins and the executor needed AsyncLocalStorage, not a parameter. Both are constructed per SESSION, not per request -- processContent is a closure with no RouteContext -- so threading an argument would have touched PluginSessionContext, every plugin, ExecuteOptions and StageContext. ALS also stays correct with two requests in flight on one session, which a mutable field on the session-scoped context would not; there is a test for exactly that. PluginContextImpl.emitAuditEvent auto-fills it the way it already auto-fills sessionId, so this covers every gate event and every plugin written later without a per-callsite edit. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- src/mcplocal/src/http/project-mcp-endpoint.ts | 22 +++++-- src/mcplocal/src/http/traffic.ts | 5 ++ src/mcplocal/src/proxymodel/plugin-context.ts | 7 ++- src/mcplocal/src/request-context.ts | 37 +++++++++++ src/mcplocal/src/router.ts | 16 ++++- src/mcplocal/src/util/trace-code.ts | 28 +++++++++ src/mcplocal/tests/request-context.test.ts | 62 +++++++++++++++++++ 7 files changed, 170 insertions(+), 7 deletions(-) create mode 100644 src/mcplocal/src/request-context.ts create mode 100644 src/mcplocal/src/util/trace-code.ts create mode 100644 src/mcplocal/tests/request-context.test.ts diff --git a/src/mcplocal/src/http/project-mcp-endpoint.ts b/src/mcplocal/src/http/project-mcp-endpoint.ts index 22d239a..7f64636 100644 --- a/src/mcplocal/src/http/project-mcp-endpoint.ts +++ b/src/mcplocal/src/http/project-mcp-endpoint.ts @@ -28,6 +28,8 @@ import { composePlugins } from '../proxymodel/plugins/compose.js'; import type { ProxyModelPlugin } from '../proxymodel/plugin.js'; import { AuditCollector } from '../audit/collector.js'; import { WireNameCodec, routeWithWireNames } from '../util/wire-names.js'; +import { newTraceCode } from '../util/trace-code.js'; +import { runInRequestScope } from '../request-context.js'; interface ProjectCacheEntry { router: McpRouter; @@ -325,7 +327,11 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp const requestId = message.id as string | number; const sid = transport.sessionId ?? 'unknown'; const method = (message as { method?: string }).method; - const correlationId = `${sid}:${requestId}`; + // Short, transcribable, and the audit correlationId itself. Nothing + // parses the old `:` form, sessionId is its own audit column + // and the JSON-RPC id is in the traffic body, so no migration is needed + // and `mcpctl trace ` works against the existing index. + const correlationId = newTraceCode(); requestCorrelations.set(requestId, correlationId); // Capture client request @@ -347,10 +353,16 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp codec = new WireNameCodec(); wireCodecs.set(projectName, codec); } - const response = await routeWithWireNames( - codec, - (req) => router.route(req, ctx), - message as unknown as JsonRpcRequest, + // Everything downstream — plugins, stages, the pipeline executor — is + // built per SESSION, not per request, so the trace code reaches them + // through the async scope rather than a parameter on every signature. + const response = await runInRequestScope( + { correlationId, sessionId: sid, projectName, method: method ?? 'unknown' }, + () => routeWithWireNames( + codec, + (req) => router.route(req, ctx), + message as unknown as JsonRpcRequest, + ), ); // Forward queued notifications BEFORE the response — the response send diff --git a/src/mcplocal/src/http/traffic.ts b/src/mcplocal/src/http/traffic.ts index f41e94f..745aba8 100644 --- a/src/mcplocal/src/http/traffic.ts +++ b/src/mcplocal/src/http/traffic.ts @@ -36,6 +36,8 @@ export interface ActiveSession { export interface TrafficFilter { project?: string | undefined; session?: string | undefined; + /** Trace code — narrows the buffer to one request's events. */ + correlationId?: string | undefined; } type Listener = (event: TrafficEvent) => void; @@ -97,6 +99,9 @@ export class TrafficCapture { if (filter?.session) { events = events.filter((e) => e.sessionId === filter.session); } + if (filter?.correlationId) { + events = events.filter((e) => e.correlationId === filter.correlationId); + } return events; } diff --git a/src/mcplocal/src/proxymodel/plugin-context.ts b/src/mcplocal/src/proxymodel/plugin-context.ts index 5575692..fbbc338 100644 --- a/src/mcplocal/src/proxymodel/plugin-context.ts +++ b/src/mcplocal/src/proxymodel/plugin-context.ts @@ -9,6 +9,7 @@ import type { LLMProvider, CacheProvider, StageLogger, Section, ToolDefinition, import type { PluginSessionContext, VirtualToolHandler, VirtualServer, PromptIndexEntry } from './plugin.js'; import type { AuditCollector } from '../audit/collector.js'; import type { AuditEvent } from '../audit/types.js'; +import { currentCorrelationId } from '../request-context.js'; /** Dependencies injected from the router into each context. */ export interface PluginContextDeps { @@ -119,11 +120,15 @@ export class PluginContextImpl implements PluginSessionContext { return this.deps.getFromMcpd(path); } - /** Emit an audit event, auto-filling sessionId and projectName. */ + /** Emit an audit event, auto-filling sessionId, projectName and correlationId. */ emitAuditEvent(event: Omit): void { + // Auto-filled here rather than at each call site: this covers every gate + // event and every plugin written later, with no per-callsite edit. + const correlationId = event.correlationId ?? currentCorrelationId(); this.deps.auditCollector?.emit({ ...event, sessionId: this.sessionId, + ...(correlationId !== undefined ? { correlationId } : {}), }); } } diff --git a/src/mcplocal/src/request-context.ts b/src/mcplocal/src/request-context.ts new file mode 100644 index 0000000..25f8318 --- /dev/null +++ b/src/mcplocal/src/request-context.ts @@ -0,0 +1,37 @@ +/** + * Per-request scope, carried through code that has no request parameter. + * + * The plugin context and the pipeline executor are both constructed **per + * session**, not per request: `getOrCreatePluginContext` builds one + * PluginContextDeps per session, and `processContent` is a closure with no + * RouteContext argument. Threading a correlationId parameter would touch + * PluginSessionContext, every plugin, ExecuteOptions and StageContext. + * + * AsyncLocalStorage gets it there with no signature churn, and — unlike a + * mutable field on the session-scoped context — stays correct when two + * requests are in flight on the same session. + */ +import { AsyncLocalStorage } from 'node:async_hooks'; + +export interface RequestScope { + /** The trace code; also the audit correlationId. */ + correlationId: string; + sessionId: string; + projectName: string; + method: string; +} + +const storage = new AsyncLocalStorage(); + +export function runInRequestScope(scope: RequestScope, fn: () => T): T { + return storage.run(scope, fn); +} + +export function currentScope(): RequestScope | undefined { + return storage.getStore(); +} + +/** Convenience: the current trace code, or undefined outside a request. */ +export function currentCorrelationId(): string | undefined { + return storage.getStore()?.correlationId; +} diff --git a/src/mcplocal/src/router.ts b/src/mcplocal/src/router.ts index 3715a01..06fbbf1 100644 --- a/src/mcplocal/src/router.ts +++ b/src/mcplocal/src/router.ts @@ -6,6 +6,7 @@ import type { PromptIndexEntry } from './gate/tag-matcher.js'; import { LinkResolver } from './services/link-resolver.js'; import type { LLMProvider, CacheProvider, Section } from './proxymodel/types.js'; import { executePipeline } from './proxymodel/executor.js'; +import { currentCorrelationId } from './request-context.js'; import { getProxyModel } from './proxymodel/loader.js'; import type { ProxyModelPlugin, PluginSessionContext } from './proxymodel/plugin.js'; import { PluginContextImpl, type PluginContextDeps } from './proxymodel/plugin-context.js'; @@ -175,6 +176,11 @@ export class McpRouter { getSystemPrompt: (name, fallback) => this.getSystemPrompt(name, fallback), ...(this.auditCollector ? { auditCollector: this.auditCollector } : {}), ...(serverName !== undefined ? { serverName } : {}), + // processContent is a per-session closure with no RouteContext, so + // the id comes from the request scope. Without this, + // ExecuteOptions.correlationId was dead code and every + // stage_execution / pipeline_execution row landed unjoinable. + ...(currentCorrelationId() !== undefined ? { correlationId: currentCorrelationId()! } : {}), }); // Pause queue: if paused, hold the result until released/edited/dropped @@ -868,6 +874,9 @@ export class McpRouter { eventKind: 'tool_call_trace' as const, source: 'mcplocal' as const, verified: true, + // Already in scope and previously dropped, which left every durable + // tool_call_trace row unjoinable to the rest of its request. + ...(context.correlationId !== undefined ? { correlationId: context.correlationId } : {}), payload: { toolName, argKeys: Object.keys(toolArgs).join(', '), @@ -903,7 +912,12 @@ export class McpRouter { // onToolCallBefore — can intercept and return a response directly if (this.plugin.onToolCallBefore) { const intercepted = await this.plugin.onToolCallBefore(toolName ?? '', toolArgs, request, ctx); - if (intercepted) return intercepted; + if (intercepted) { + // Intercepts were previously invisible in tool_call_trace, so every + // call made while the session was gated produced no trace at all. + emitTrace(intercepted, 'plugin'); + return intercepted; + } } // Route to upstream diff --git a/src/mcplocal/src/util/trace-code.ts b/src/mcplocal/src/util/trace-code.ts new file mode 100644 index 0000000..75d6742 --- /dev/null +++ b/src/mcplocal/src/util/trace-code.ts @@ -0,0 +1,28 @@ +/** + * Short, human-transcribable code identifying one MCP request end to end. + * + * This IS the correlationId — it replaces the previous `:` + * form. Nothing parses that format (checked across every consumer: mcpd's + * audit repository and route, mcplocal's router and traffic capture, and the + * CLI console), `sessionId` is its own column on every audit event, and the + * JSON-RPC id is in the traffic body — so nothing is lost and no migration is + * needed. `AuditEvent.correlationId` is already an indexed Postgres column, so + * lookup by code works from day one. + * + * Crockford base32 without I/L/O/U: unambiguous read aloud, typed from a + * screenshot, or pasted into a bug report. 40 bits of randomness — a collision + * shows two traces, it does not corrupt anything. + */ +import { randomBytes } from 'node:crypto'; + +const ALPHABET = '0123456789ABCDEFGHJKMNPQRSTVWXYZ'; + +export function newTraceCode(): string { + const buf = randomBytes(5); + const value = buf.readUIntBE(0, 5); + let out = ''; + for (let i = 0; i < 8; i++) { + out += ALPHABET[Math.floor(value / 32 ** (7 - i)) % 32]; + } + return out; +} diff --git a/src/mcplocal/tests/request-context.test.ts b/src/mcplocal/tests/request-context.test.ts new file mode 100644 index 0000000..aec215d --- /dev/null +++ b/src/mcplocal/tests/request-context.test.ts @@ -0,0 +1,62 @@ +import { describe, it, expect } from 'vitest'; +import { runInRequestScope, currentScope, currentCorrelationId } from '../src/request-context.js'; +import { newTraceCode } from '../src/util/trace-code.js'; + +describe('newTraceCode', () => { + it('is 8 unambiguous Crockford characters', () => { + for (let i = 0; i < 200; i++) { + expect(newTraceCode()).toMatch(/^[0-9ABCDEFGHJKMNPQRSTVWXYZ]{8}$/); + } + }); + + it('excludes I, L, O and U so a code can be read aloud or retyped', () => { + const codes = Array.from({ length: 500 }, () => newTraceCode()).join(''); + expect(codes).not.toMatch(/[ILOU]/); + }); + + it('does not collide over a realistic request volume', () => { + const seen = new Set(Array.from({ length: 20_000 }, () => newTraceCode())); + expect(seen.size).toBe(20_000); + }); +}); + +describe('request scope', () => { + it('is undefined outside a request', () => { + expect(currentScope()).toBeUndefined(); + expect(currentCorrelationId()).toBeUndefined(); + }); + + it('survives awaits', async () => { + await runInRequestScope( + { correlationId: 'ABC12345', sessionId: 's', projectName: 'p', method: 'tools/call' }, + async () => { + await new Promise((r) => setTimeout(r, 5)); + expect(currentCorrelationId()).toBe('ABC12345'); + await new Promise((r) => setTimeout(r, 5)); + expect(currentScope()?.method).toBe('tools/call'); + }, + ); + }); + + it('does not cross-contaminate concurrent requests on one session', async () => { + // The case a mutable field on the session-scoped plugin context would get + // wrong — two in-flight requests share a session but not a trace code. + const seen: string[] = []; + const one = runInRequestScope( + { correlationId: 'AAAAAAAA', sessionId: 'same', projectName: 'p', method: 'tools/call' }, + async () => { + await new Promise((r) => setTimeout(r, 20)); + seen.push(currentCorrelationId() ?? 'none'); + }, + ); + const two = runInRequestScope( + { correlationId: 'BBBBBBBB', sessionId: 'same', projectName: 'p', method: 'tools/call' }, + async () => { + await new Promise((r) => setTimeout(r, 5)); + seen.push(currentCorrelationId() ?? 'none'); + }, + ); + await Promise.all([one, two]); + expect(seen.sort()).toEqual(['AAAAAAAA', 'BBBBBBBB']); + }); +}); -- 2.49.1 From 0eca4148e3633b378ea34213bac292274adc6e88 Mon Sep 17 00:00:00 2001 From: Michal Date: Tue, 25 Aug 2026 23:36:27 +0100 Subject: [PATCH 4/9] fix(mcplocal): recreate a stale session instead of 404ing outside the envelope MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Second of the two faults that both presented as a 1800s hang. mcplocal keeps MCP sessions in memory only, so any restart -- a deploy, an RPM install, scripts/release.sh -- invalidates every connected client's session id. The response was a bare 404 {"error":"Session not found"}: 3.5ms server-side, but it lands OUTSIDE the JSON-RPC envelope with no id, so the client cannot correlate it to its request and simply waits out its own timeout. Every mcpctl tool call in that session became a 30-minute stall while the server was perfectly healthy and answering other traffic in milliseconds. Now the session is recreated, keeping the id the client already holds -- a re-handshake would change it and invalidate everything the client has cached. The SDK assigns sessionId/_initialized only while handling an `initialize` (webStandardStreamableHttp.js:419-420), so adoptSession() replays exactly those two assignments. It reaches into SDK internals, so it fails LOUDLY: the guard throws with a pointer to itself, and session-adopt.test.ts is the canary that goes red at `pnpm test` rather than in production on the next SDK bump. Recreation is not silent. Doing it quietly would hand an agent an ungated tool list with no signal that its gate state had vanished, so the first tools/call result carries the established "⚠ Session state unavailable (...)" notice telling it to call begin_session again. onsessioninitialized does NOT fire on the adopt path, so its body is factored into registerSession() and called explicitly. That is the subtle part: skipping it would have produced recreated sessions with null userName on every audit event, silently. Also fixed, and it is the CAUSE rather than the symptom: MCP clients close a session with DELETE + Content-Type: application/json and an empty body, which Fastify's default parser rejected with FST_ERR_CTP_EMPTY_JSON_BODY before the route handler ran. sessions.delete() therefore never happened and every "closed" session leaked -- manufacturing the stale-session condition this commit handles. Fixing recreation without fixing teardown would have shipped the workaround and kept the cause. project-mcp-endpoint.test.ts's "returns 404 for unknown session ID" inverts to "recreates an unknown session instead of 404ing it", and asserts the id comes back unchanged. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- src/mcplocal/src/http/project-mcp-endpoint.ts | 73 ++++++++++++++++--- src/mcplocal/src/http/server.ts | 18 +++++ src/mcplocal/src/http/session-adopt.ts | 47 ++++++++++++ .../tests/project-mcp-endpoint.test.ts | 12 ++- src/mcplocal/tests/session-adopt.test.ts | 40 ++++++++++ 5 files changed, 179 insertions(+), 11 deletions(-) create mode 100644 src/mcplocal/src/http/session-adopt.ts create mode 100644 src/mcplocal/tests/session-adopt.test.ts diff --git a/src/mcplocal/src/http/project-mcp-endpoint.ts b/src/mcplocal/src/http/project-mcp-endpoint.ts index 7f64636..8b298de 100644 --- a/src/mcplocal/src/http/project-mcp-endpoint.ts +++ b/src/mcplocal/src/http/project-mcp-endpoint.ts @@ -30,6 +30,8 @@ import { AuditCollector } from '../audit/collector.js'; import { WireNameCodec, routeWithWireNames } from '../util/wire-names.js'; import { newTraceCode } from '../util/trace-code.js'; import { runInRequestScope } from '../request-context.js'; +import { adoptSession } from './session-adopt.js'; +import { degradationNotice } from '../util/degrade.js'; interface ProjectCacheEntry { router: McpRouter; @@ -48,6 +50,12 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp let resolvedUserName: string | null | undefined; // undefined = not yet resolved const projectCache = new Map(); const sessions = new Map(); + /** + * Sessions recreated after a restart, awaiting their one-shot ⚠ notice. + * Delivered on the next tools/call result — the only response a model + * reliably reads as prose. + */ + const pendingRecreationNotice = new Set(); // Wire-name codecs are keyed per project and OUTLIVE the router cache TTL: // a client may call a tool it listed minutes ago through a refreshed router, // and the mapping must still resolve. @@ -217,6 +225,27 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp } // POST /projects/:projectName/mcp — JSON-RPC requests + /** + * Prepend the recreation notice to the first tool result after a session was + * rebuilt. Silent recreation would hand an agent an ungated tool list with no + * signal that its gate state had vanished. + */ + function maybeAnnotateRecreation(response: unknown, sid: string, method?: string): unknown { + if (method !== 'tools/call' || !pendingRecreationNotice.has(sid)) return response; + pendingRecreationNotice.delete(sid); + + const r = response as { result?: { content?: Array<{ type?: string; text?: string }> } }; + const first = r.result?.content?.[0]; + if (!first || first.type !== 'text' || typeof first.text !== 'string') return response; + + first.text = degradationNotice( + 'Session state', + `mcplocal restarted; session ${sid.slice(0, 8)} was recreated`, + 'Gate state and cached results were lost — if an expected tool is missing, call begin_session again.', + ) + first.text; + return response; + } + app.post<{ Params: { projectName: string } }>('/projects/:projectName/mcp', async (request, reply) => { const { projectName } = request.params; const sessionId = request.headers['mcp-session-id'] as string | undefined; @@ -229,10 +258,15 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp return; } - if (sessionId && !sessions.has(sessionId)) { - reply.code(404).send({ error: 'Session not found' }); - return; - } + // An unknown session id means mcplocal restarted (or the session was + // evicted) while the client still holds a perfectly good id. Replying 404 + // is a dead end: it lands OUTSIDE the JSON-RPC envelope with no id, so the + // client cannot correlate it and stalls until its own timeout — 3.5ms + // server-side became 1800s client-side. Recreate instead, keep the id the + // client already has, and tell the model what it lost. + const recreatingSessionId = sessionId !== undefined && !sessions.has(sessionId) + ? sessionId + : undefined; // New session — get/create project router let router: McpRouter; @@ -243,9 +277,11 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp return; } - const transport = new StreamableHTTPServerTransport({ - sessionIdGenerator: () => randomUUID(), - onsessioninitialized: (id) => { + // Called by onsessioninitialized on the normal path, and explicitly on the + // recreation path — where onsessioninitialized never fires. Missing any of + // this on the adopt path would give recreated sessions null userName on + // every audit event. + const registerSession = (id: string): void => { sessions.set(id, { transport, projectName }); trafficCapture?.emit({ timestamp: new Date().toISOString(), @@ -283,7 +319,11 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp verified: true, payload: { projectName }, }); - }, + }; + + const transport = new StreamableHTTPServerTransport({ + sessionIdGenerator: () => randomUUID(), + onsessioninitialized: (id) => { registerSession(id); }, }); // Per-request correlationId map for linking client ↔ upstream event pairs. @@ -395,7 +435,9 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp }); requestCorrelations.delete(requestId); - await transport.send(response as unknown as JSONRPCMessage); + await transport.send( + maybeAnnotateRecreation(response, sid, method) as unknown as JSONRPCMessage, + ); } }; @@ -414,6 +456,19 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp } }; + if (recreatingSessionId !== undefined) { + // Adopt the client's existing id rather than minting a new one: a + // re-handshake would invalidate everything the client has cached about + // this session. + adoptSession(transport, recreatingSessionId); + registerSession(recreatingSessionId); + pendingRecreationNotice.add(recreatingSessionId); + console.error( + `[mcp] recreated session ${recreatingSessionId.slice(0, 8)} for project '${projectName}' ` + + '(mcplocal restarted or the session was evicted); gate state was lost', + ); + } + await transport.handleRequest(request.raw, reply.raw, request.body); reply.hijack(); }); diff --git a/src/mcplocal/src/http/server.ts b/src/mcplocal/src/http/server.ts index 56a0210..21219a6 100644 --- a/src/mcplocal/src/http/server.ts +++ b/src/mcplocal/src/http/server.ts @@ -42,6 +42,24 @@ export async function createHttpServer( methods: ['GET', 'POST', 'PUT', 'DELETE', 'PATCH'], }); + // MCP clients close a session with DELETE + `Content-Type: application/json` + // and an EMPTY body. Fastify's default JSON parser rejects that with + // FST_ERR_CTP_EMPTY_JSON_BODY before the route handler ever runs, so + // sessions.delete() never happened and every "closed" session leaked -- + // which is a direct producer of the stale-session condition that used to + // 404. Treat an empty body as no body. + app.addContentTypeParser('application/json', { parseAs: 'string' }, (_req, body, done) => { + if (body === '' || body === undefined) { + done(null, undefined); + return; + } + try { + done(null, JSON.parse(body as string) as unknown); + } catch (err) { + done(err as Error, undefined); + } + }); + // Health endpoint app.get('/health', async (_request, reply) => { const upstreams = deps.router.getUpstreamNames(); diff --git a/src/mcplocal/src/http/session-adopt.ts b/src/mcplocal/src/http/session-adopt.ts new file mode 100644 index 0000000..336370b --- /dev/null +++ b/src/mcplocal/src/http/session-adopt.ts @@ -0,0 +1,47 @@ +/** + * Let a freshly-built transport adopt a session ID the client already holds. + * + * mcplocal keeps MCP sessions in memory only, so any restart — a deploy, an RPM + * install, `scripts/release.sh` — invalidates every live client's session id. + * The old behaviour was a bare `404 {"error":"Session not found"}` outside the + * JSON-RPC envelope: 3.5ms server-side, but the client cannot correlate it and + * stalls until its own timeout (1800s in Claude Code). Recreating the session + * is strictly better, and keeping the client's EXISTING id is the point — a + * re-handshake would change it and every assumption the client has cached. + * + * The SDK assigns `sessionId` and `_initialized` in exactly one place: while + * handling an `initialize` POST (webStandardStreamableHttp.js:419-420, SDK + * 1.26.0). A non-initialize message on a fresh transport is rejected by + * `validateSession` with "Bad Request: Server not initialized". Replaying those + * two assignments is far less fragile than synthesising an `initialize` request + * through hono's request listener. + * + * This reaches into SDK internals, so it fails LOUDLY rather than silently: if + * the shape moves in an SDK upgrade, `session-adopt.test.ts` goes red at + * `pnpm test` instead of in production. + */ +import type { StreamableHTTPServerTransport } from '@modelcontextprotocol/sdk/server/streamableHttp.js'; + +interface WebStandardInternals { + sessionId?: string | undefined; + _initialized?: boolean; +} + +export function adoptSession(transport: StreamableHTTPServerTransport, sessionId: string): void { + const inner = (transport as unknown as { _webStandardTransport?: WebStandardInternals }) + ._webStandardTransport; + + // Guard on `_initialized` only: the SDK sets it in the constructor, whereas + // `sessionId` is not assigned until an initialize arrives — so on the fresh + // transport we are adopting onto, the property genuinely does not exist yet. + if (!inner || !('_initialized' in inner)) { + throw new Error( + 'MCP SDK internals changed: cannot adopt an existing session id ' + + '(_webStandardTransport._initialized / .sessionId not found). ' + + 'See src/mcplocal/src/http/session-adopt.ts and its test.', + ); + } + + inner.sessionId = sessionId; + inner._initialized = true; +} diff --git a/src/mcplocal/tests/project-mcp-endpoint.test.ts b/src/mcplocal/tests/project-mcp-endpoint.test.ts index 04b5892..d5540b4 100644 --- a/src/mcplocal/tests/project-mcp-endpoint.test.ts +++ b/src/mcplocal/tests/project-mcp-endpoint.test.ts @@ -113,18 +113,26 @@ describe('registerProjectMcpEndpoint', () => { expect(res.json().error).toContain('Failed to load project'); }); - it('returns 404 for unknown session ID', async () => { + it('recreates an unknown session instead of 404ing it', async () => { + // A 404 here lands OUTSIDE the JSON-RPC envelope with no id, so a client + // cannot correlate it and stalls until its own timeout — a 3.5ms failure + // that cost 1800s in production. mcplocal restarts routinely (deploys, RPM + // installs, release.sh), which is exactly when clients hold stale ids. const res = await app.inject({ method: 'POST', url: '/projects/smart-home/mcp', payload: { jsonrpc: '2.0', id: 1, method: 'tools/list', params: {} }, headers: { 'content-type': 'application/json', + 'accept': 'application/json, text/event-stream', 'mcp-session-id': 'nonexistent-session', }, }); - expect(res.statusCode).toBe(404); + expect(res.statusCode).not.toBe(404); + // The client keeps the id it already holds — a re-handshake would + // invalidate everything it has cached about the session. + expect(res.headers['mcp-session-id'] ?? 'nonexistent-session').toBe('nonexistent-session'); }); it('returns 400 for GET without session', async () => { diff --git a/src/mcplocal/tests/session-adopt.test.ts b/src/mcplocal/tests/session-adopt.test.ts new file mode 100644 index 0000000..216efdb --- /dev/null +++ b/src/mcplocal/tests/session-adopt.test.ts @@ -0,0 +1,40 @@ +import { describe, it, expect } from 'vitest'; +import { randomUUID } from 'node:crypto'; +import { StreamableHTTPServerTransport } from '@modelcontextprotocol/sdk/server/streamableHttp.js'; +import { adoptSession } from '../src/http/session-adopt.js'; + +/** + * Canary for SDK upgrades. adoptSession() reaches into + * _webStandardTransport.{sessionId,_initialized}, which the SDK sets only while + * handling an `initialize`. If a future SDK moves them, this fails here rather + * than turning every session recovery into a 400 in production. + */ +describe('adoptSession', () => { + it('marks a fresh transport as initialized with the given session id', () => { + const transport = new StreamableHTTPServerTransport({ sessionIdGenerator: () => randomUUID() }); + expect(transport.sessionId).toBeUndefined(); + + const id = randomUUID(); + adoptSession(transport, id); + + expect(transport.sessionId).toBe(id); + }); + + it('throws loudly when the SDK internals are not what we expect', () => { + expect(() => adoptSession({} as never, 'x')).toThrow(/MCP SDK internals changed/); + expect(() => adoptSession({ _webStandardTransport: undefined } as never, 'x')) + .toThrow(/MCP SDK internals changed/); + }); + + it('satisfies the SDK session check that rejects uninitialized transports', () => { + const transport = new StreamableHTTPServerTransport({ sessionIdGenerator: () => randomUUID() }); + const id = randomUUID(); + adoptSession(transport, id); + + // validateSession() rejects on !_initialized before it ever compares ids, + // so this flag is the half that actually unblocks a non-initialize message. + const inner = (transport as unknown as { _webStandardTransport: { _initialized: boolean } }) + ._webStandardTransport; + expect(inner._initialized).toBe(true); + }); +}); -- 2.49.1 From b6e270ee4856ae6adde66789e42c068eb489100f Mon Sep 17 00:00:00 2001 From: Michal Date: Tue, 25 Aug 2026 23:41:09 +0100 Subject: [PATCH 5/9] feat(mcplocal): every request answers, even when the pipeline wedges MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The LLM budgets bound the failure we actually hit. This is the backstop for the ones they cannot see: a wedged plugin hook, a virtual-tool handler, an upstream path without its own timeout. transport.onmessage IS the whole request pipeline, and it writes to a socket that has already been hijacked from Fastify. The SDK does not await it, so a throw became an unhandled rejection and a hang became silence -- in both cases the client got no response at all and waited out its own timeout. onmessage is now structured so that reaching transport.send() is unconditional: the route call is raced against a deadline, and the notification flush and the send each carry their own catch, so a failure while flushing can no longer cost the client its response. transport.onerror was never assigned, so SDK-level transport errors were swallowed entirely. It is now. Shape of the answer is deliberate. A tools/call comes back as a SUCCESSFUL result with isError and readable text naming the trace code -- the same shape router.ts already uses for an expired _resultId, because a transport error tends to surface as a hard failure while a tool error is something the model reads and acts on. It also says the upstream may still be running, which is true and matters. Other methods get a JSON-RPC error (-32001). MCPLOCAL_TOOLCALL_DEADLINE_MS defaults to TOOLCALL_TIMEOUT_MS + 30s rather than 120s. The watchdog arms earlier in the request than mcpd's fetch does, so at equal values it would always fire first, masking mcpd's specific UpstreamTimeoutError with a generic message and cutting off pagination and the rest of the post-processing. There is a test asserting the two stay ordered. The pause queue is exempt, but not bypassed. It blocks until a human operator releases, edits or drops a response, so the deadline SUSPENDS -- clock stopped, then re-armed with whatever was left. A test asserts the re-arm, because an exemption that forgot to re-arm would silently make every paused request immortal. End-to-end: an upstream that never settles now yields a response in under a second carrying ⚠, the deadline, and `mcpctl trace `. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- src/mcplocal/src/http/deadline.ts | 75 ++++++++++++ src/mcplocal/src/http/project-mcp-endpoint.ts | 113 +++++++++++++++-- src/mcplocal/src/request-context.ts | 7 ++ src/mcplocal/src/router.ts | 11 +- .../tests/toolcall-deadline-e2e.test.ts | 115 ++++++++++++++++++ src/mcplocal/tests/toolcall-deadline.test.ts | 74 +++++++++++ 6 files changed, 380 insertions(+), 15 deletions(-) create mode 100644 src/mcplocal/src/http/deadline.ts create mode 100644 src/mcplocal/tests/toolcall-deadline-e2e.test.ts create mode 100644 src/mcplocal/tests/toolcall-deadline.test.ts diff --git a/src/mcplocal/src/http/deadline.ts b/src/mcplocal/src/http/deadline.ts new file mode 100644 index 0000000..44a4b80 --- /dev/null +++ b/src/mcplocal/src/http/deadline.ts @@ -0,0 +1,75 @@ +/** + * Outer bound on one client request. + * + * The LLM budgets (proxymodel/llm-adapter.ts, proxymodel/stage-budget.ts) bound + * the failure mode we actually hit in production. This is the backstop for the + * ones they cannot see: a wedged plugin hook, a virtual-tool handler, an + * upstream path without its own timeout. `transport.onmessage` writes to an + * already-hijacked socket, so if it never completes the client gets silence and + * waits out its own timeout — 1800s in Claude Code. + * + * MUST exceed McpdClient's TOOLCALL_TIMEOUT_MS. The watchdog arms earlier in + * the request than the mcpd fetch does, so at equal values it would always fire + * first and mask mcpd's specific UpstreamTimeoutError with a generic deadline + * message — and cut off pagination and the rest of the post-processing besides. + */ +import { TOOLCALL_TIMEOUT_MS } from './mcpd-client.js'; + +export const TOOLCALL_DEADLINE_MS = + Number(process.env['MCPLOCAL_TOOLCALL_DEADLINE_MS']) || (TOOLCALL_TIMEOUT_MS + 30_000); + +export class DeadlineExceededError extends Error { + constructor(public readonly method: string, public readonly ms: number) { + super(`${method} exceeded the ${String(ms)}ms mcplocal deadline`); + this.name = 'DeadlineExceededError'; + } +} + +export interface RequestDeadline { + /** Rejects with DeadlineExceededError when the budget runs out. */ + readonly expiry: Promise; + /** Run `fn` with the clock stopped, then re-arm with what was left. */ + suspended(fn: () => Promise): Promise; + dispose(): void; +} + +export function createRequestDeadline(method: string, totalMs: number): RequestDeadline { + let remaining = totalMs; + let startedAt = Date.now(); + let timer: ReturnType | undefined; + let reject!: (err: Error) => void; + let settled = false; + + const expiry = new Promise((_, rej) => { reject = rej; }); + // Nothing else may observe this rejection until it is raced, and an unraced + // rejection would be an unhandled rejection at process level. + expiry.catch(() => { /* raced by the caller */ }); + + const arm = (ms: number): void => { + startedAt = Date.now(); + timer = setTimeout(() => { + settled = true; + reject(new DeadlineExceededError(method, totalMs)); + }, ms); + if (typeof timer.unref === 'function') timer.unref(); + }; + arm(remaining); + + return { + expiry, + async suspended(fn: () => Promise): Promise { + if (settled) return fn(); + if (timer !== undefined) clearTimeout(timer); + remaining = Math.max(0, remaining - (Date.now() - startedAt)); + try { + return await fn(); + } finally { + if (!settled) arm(remaining); + } + }, + dispose(): void { + settled = true; + if (timer !== undefined) clearTimeout(timer); + }, + }; +} diff --git a/src/mcplocal/src/http/project-mcp-endpoint.ts b/src/mcplocal/src/http/project-mcp-endpoint.ts index 8b298de..d6e56b8 100644 --- a/src/mcplocal/src/http/project-mcp-endpoint.ts +++ b/src/mcplocal/src/http/project-mcp-endpoint.ts @@ -32,6 +32,7 @@ import { newTraceCode } from '../util/trace-code.js'; import { runInRequestScope } from '../request-context.js'; import { adoptSession } from './session-adopt.js'; import { degradationNotice } from '../util/degrade.js'; +import { createRequestDeadline, DeadlineExceededError, TOOLCALL_DEADLINE_MS } from './deadline.js'; interface ProjectCacheEntry { router: McpRouter; @@ -246,6 +247,53 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp return response; } + /** + * Turn a deadline or an unexpected throw into something the client can read. + * + * A tools/call becomes a SUCCESSFUL result with isError — a transport error + * tends to surface to the user as a hard failure, whereas a tool error is + * text the model reads and acts on (the same shape router.ts already uses for + * an expired _resultId). Everything else gets a JSON-RPC error. + */ + function failureResponse( + requestId: string | number, + method: string | undefined, + err: unknown, + traceCode: string, + ): unknown { + const timedOut = err instanceof DeadlineExceededError; + const detail = timedOut + ? `exceeded the ${String(TOOLCALL_DEADLINE_MS)}ms mcplocal deadline and was abandoned` + : `failed: ${err instanceof Error ? err.message : String(err)}`; + console.error(`[mcp] ${method ?? 'request'} ${detail} (trace ${traceCode})`); + + if (method === 'tools/call') { + return { + jsonrpc: '2.0', + id: requestId, + result: { + content: [{ + type: 'text', + text: + `⚠ This tool call ${detail} (trace ${traceCode}).\n` + + 'The upstream may still be running — do not assume it did nothing. ' + + 'Retry with narrower arguments, or run ' + + `\`mcpctl trace ${traceCode}\` to see which stage consumed the time.`, + }], + isError: true, + }, + }; + } + return { + jsonrpc: '2.0', + id: requestId, + error: { + code: timedOut ? -32001 : -32603, + message: `${method ?? 'request'} ${detail} (trace ${traceCode})`, + }, + }; + } + app.post<{ Params: { projectName: string } }>('/projects/:projectName/mcp', async (request, reply) => { const { projectName } = request.params; const sessionId = request.headers['mcp-session-id'] as string | undefined; @@ -396,15 +444,35 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp // Everything downstream — plugins, stages, the pipeline executor — is // built per SESSION, not per request, so the trace code reaches them // through the async scope rather than a parameter on every signature. - const response = await runInRequestScope( - { correlationId, sessionId: sid, projectName, method: method ?? 'unknown' }, - () => routeWithWireNames( - codec, - (req) => router.route(req, ctx), - message as unknown as JsonRpcRequest, - ), - ); + // + // The deadline is the backstop for hangs the LLM budgets cannot see: a + // wedged plugin hook, a virtual-tool handler, an upstream without its + // own timeout. Whatever happens, this function MUST reach a send() — + // the SDK does not await onmessage, so an escaping throw becomes an + // unhandled rejection and the client gets nothing but silence. + const deadline = createRequestDeadline(method ?? 'request', TOOLCALL_DEADLINE_MS); + let response: unknown; + try { + response = await Promise.race([ + runInRequestScope( + { correlationId, sessionId: sid, projectName, method: method ?? 'unknown', deadline }, + () => routeWithWireNames( + codec, + (req) => router.route(req, ctx), + message as unknown as JsonRpcRequest, + ), + ), + deadline.expiry, + ]); + } catch (err) { + response = failureResponse(requestId, method, err, correlationId); + } finally { + deadline.dispose(); + } + // Guaranteed-send tail. Everything from here on is best-effort: a throw + // while flushing notifications must not cost the client its response. + try { // Forward queued notifications BEFORE the response — the response send // closes the POST SSE stream, so notifications must go first. // relatedRequestId routes them onto the same SSE stream as the response. @@ -434,13 +502,34 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp correlationId, }); - requestCorrelations.delete(requestId); - await transport.send( - maybeAnnotateRecreation(response, sid, method) as unknown as JSONRPCMessage, - ); + } catch (tailErr) { + console.error( + `[mcp] notification flush failed for trace ${correlationId}: ` + + `${tailErr instanceof Error ? tailErr.message : String(tailErr)}`, + ); + } + + try { + await transport.send( + maybeAnnotateRecreation(response, sid, method) as unknown as JSONRPCMessage, + ); + } catch (sendErr) { + console.error( + `[mcp] failed to deliver response for trace ${correlationId} (${method ?? 'unknown'}): ` + + `${sendErr instanceof Error ? sendErr.message : String(sendErr)}`, + ); + } finally { + requestCorrelations.delete(requestId); + } } }; + // Never assigned before this change, so an SDK-level transport error was + // swallowed entirely. + transport.onerror = (err: Error) => { + console.error(`[mcp] transport error (${projectName}): ${err.message}`); + }; + transport.onclose = () => { const id = transport.sessionId; if (id) { diff --git a/src/mcplocal/src/request-context.ts b/src/mcplocal/src/request-context.ts index 25f8318..f0e225a 100644 --- a/src/mcplocal/src/request-context.ts +++ b/src/mcplocal/src/request-context.ts @@ -12,6 +12,7 @@ * requests are in flight on the same session. */ import { AsyncLocalStorage } from 'node:async_hooks'; +import type { RequestDeadline } from './http/deadline.js'; export interface RequestScope { /** The trace code; also the audit correlationId. */ @@ -19,6 +20,12 @@ export interface RequestScope { sessionId: string; projectName: string; method: string; + /** + * The request's deadline, so deliberately-unbounded waits (the pause queue, + * which blocks until a human operator releases a response) can stop its clock + * instead of being killed by it. + */ + deadline?: RequestDeadline | undefined; } const storage = new AsyncLocalStorage(); diff --git a/src/mcplocal/src/router.ts b/src/mcplocal/src/router.ts index 06fbbf1..02eba13 100644 --- a/src/mcplocal/src/router.ts +++ b/src/mcplocal/src/router.ts @@ -6,7 +6,7 @@ import type { PromptIndexEntry } from './gate/tag-matcher.js'; import { LinkResolver } from './services/link-resolver.js'; import type { LLMProvider, CacheProvider, Section } from './proxymodel/types.js'; import { executePipeline } from './proxymodel/executor.js'; -import { currentCorrelationId } from './request-context.js'; +import { currentCorrelationId, currentScope } from './request-context.js'; import { getProxyModel } from './proxymodel/loader.js'; import type { ProxyModelPlugin, PluginSessionContext } from './proxymodel/plugin.js'; import { PluginContextImpl, type PluginContextDeps } from './proxymodel/plugin-context.js'; @@ -183,9 +183,12 @@ export class McpRouter { ...(currentCorrelationId() !== undefined ? { correlationId: currentCorrelationId()! } : {}), }); - // Pause queue: if paused, hold the result until released/edited/dropped + // Pause queue: if paused, hold the result until released/edited/dropped. + // This wait is deliberately unbounded — it ends when a human operator + // acts — so the request deadline stops its clock rather than killing + // it, and re-arms with whatever was left once the operator releases. if (pauseQueue.paused) { - const pausedContent = await pauseQueue.enqueue({ + const enqueue = (): Promise => pauseQueue.enqueue({ sessionId, projectName: this.projectName ?? 'unknown', contentType, @@ -193,6 +196,8 @@ export class McpRouter { original: content, transformed: result.content, }); + const deadline = currentScope()?.deadline; + const pausedContent = deadline ? await deadline.suspended(enqueue) : await enqueue(); return { ...result, content: pausedContent }; } diff --git a/src/mcplocal/tests/toolcall-deadline-e2e.test.ts b/src/mcplocal/tests/toolcall-deadline-e2e.test.ts new file mode 100644 index 0000000..f69bc2c --- /dev/null +++ b/src/mcplocal/tests/toolcall-deadline-e2e.test.ts @@ -0,0 +1,115 @@ +import { describe, it, expect, vi, beforeEach } from 'vitest'; +import Fastify from 'fastify'; +import { registerProjectMcpEndpoint } from '../src/http/project-mcp-endpoint.js'; +import type { McpRouter } from '../src/router.js'; +import type { JsonRpcRequest, JsonRpcResponse } from '../src/types.js'; + +/** + * The guarantee this whole change exists for: a tool call whose upstream never + * settles must still produce a response. Before the watchdog, onmessage simply + * never reached transport.send(), the hijacked socket stayed silent, and the + * client waited out its own 1800s timeout — which is precisely what happened + * in production three times. + */ + +vi.mock('../src/discovery.js', () => ({ + refreshProjectUpstreams: vi.fn(async (router: McpRouter) => { + router.addUpstream({ + name: 'blackhole', + send: async (req: JsonRpcRequest): Promise => { + if (req.method === 'tools/list') { + return { + jsonrpc: '2.0', + id: req.id, + result: { tools: [{ name: 'wedge', description: 'never returns', inputSchema: { type: 'object' } }] }, + }; + } + // A call that never settles and never errors. + return new Promise(() => { /* the hang */ }); + }, + close: async () => { /* noop */ }, + isAlive: () => true, + }); + return ['blackhole']; + }), + fetchProjectLlmConfig: vi.fn(async () => ({ gated: false, llmProvider: 'none' })), +})); + +vi.mock('../src/http/config.js', async () => { + const actual = await vi.importActual('../src/http/config.js'); + return { ...actual, loadProjectLlmOverride: vi.fn(() => undefined) }; +}); + +function mockMcpdClient(): Record { + const client: Record = { + baseUrl: 'http://test:3100', token: 't', + get: vi.fn(async () => []), post: vi.fn(async () => ({})), + put: vi.fn(), delete: vi.fn(), + forward: vi.fn(async () => ({ status: 200, body: [] })), + withHeaders: vi.fn(), withToken: vi.fn(), withTimeout: vi.fn(), + }; + for (const k of ['withHeaders', 'withToken', 'withTimeout']) { + (client[k] as ReturnType).mockReturnValue(client); + } + return client; +} + +function parseSse(body: string): JsonRpcResponse { + const line = body.split('\n').find((l) => l.startsWith('data: ')); + if (!line) throw new Error(`no SSE data line in: ${body}`); + return JSON.parse(line.slice('data: '.length)) as JsonRpcResponse; +} + +beforeEach(() => { vi.stubEnv('MCPLOCAL_TOOLCALL_DEADLINE_MS', '300'); vi.resetModules(); }); + +describe('tool-call watchdog, end to end', () => { + it('answers a wedged tool call instead of leaving the client hanging', async () => { + vi.spyOn(console, 'error').mockImplementation(() => { /* quiet */ }); + const { registerProjectMcpEndpoint: register } = + await import('../src/http/project-mcp-endpoint.js'); + + const app = Fastify(); + register(app, mockMcpdClient() as never); + await app.ready(); + try { + const headers = { 'content-type': 'application/json', accept: 'application/json, text/event-stream' }; + const init = await app.inject({ + method: 'POST', url: '/projects/wedge-test/mcp', headers, + payload: { jsonrpc: '2.0', id: 1, method: 'initialize', params: { protocolVersion: '2024-11-05', capabilities: {}, clientInfo: { name: 't', version: '0' } } }, + }); + const sessionId = init.headers['mcp-session-id'] as string; + expect(sessionId).toBeTruthy(); + + // tools/list first: the wire-name codec learns the mapping there. + await app.inject({ + method: 'POST', url: '/projects/wedge-test/mcp', + headers: { ...headers, 'mcp-session-id': sessionId }, + payload: { jsonrpc: '2.0', id: 2, method: 'tools/list', params: {} }, + }); + + const start = Date.now(); + const res = await app.inject({ + method: 'POST', url: '/projects/wedge-test/mcp', + headers: { ...headers, 'mcp-session-id': sessionId }, + payload: { jsonrpc: '2.0', id: 3, method: 'tools/call', params: { name: 'blackhole_wedge', arguments: {} } }, + }); + const elapsed = Date.now() - start; + + expect(elapsed).toBeLessThan(5000); + const body = parseSse(res.body); + expect(body.id).toBe(3); + + // A tools/call comes back as a RESULT with isError, not a transport + // error: it is text the model reads and acts on. + const result = body.result as { content?: Array<{ text?: string }>; isError?: boolean }; + expect(result.isError).toBe(true); + const text = result.content?.[0]?.text ?? ''; + expect(text).toContain('⚠'); + expect(text).toContain('mcplocal deadline'); + // The trace code must be present and actionable. + expect(text).toMatch(/mcpctl trace [0-9ABCDEFGHJKMNPQRSTVWXYZ]{8}/); + } finally { + await app.close(); + } + }); +}); diff --git a/src/mcplocal/tests/toolcall-deadline.test.ts b/src/mcplocal/tests/toolcall-deadline.test.ts new file mode 100644 index 0000000..b06f8a2 --- /dev/null +++ b/src/mcplocal/tests/toolcall-deadline.test.ts @@ -0,0 +1,74 @@ +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { + createRequestDeadline, + DeadlineExceededError, + TOOLCALL_DEADLINE_MS, +} from '../src/http/deadline.js'; +import { TOOLCALL_TIMEOUT_MS } from '../src/http/mcpd-client.js'; + +afterEach(() => { vi.restoreAllMocks(); }); + +describe('TOOLCALL_DEADLINE_MS', () => { + it('exceeds mcpd\'s own tool-call timeout', () => { + // The watchdog arms earlier in the request than mcpd's fetch does. At equal + // values it would always fire first, masking mcpd's specific + // UpstreamTimeoutError with a generic deadline message and cutting off + // pagination and the rest of the post-processing. + expect(TOOLCALL_DEADLINE_MS).toBeGreaterThan(TOOLCALL_TIMEOUT_MS); + }); + + it('stays well below a typical client timeout so our error arrives first', () => { + expect(TOOLCALL_DEADLINE_MS).toBeLessThan(600_000); + }); +}); + +describe('createRequestDeadline', () => { + it('rejects with DeadlineExceededError when the budget runs out', async () => { + const d = createRequestDeadline('tools/call', 40); + await expect(Promise.race([ + new Promise(() => { /* the hang we are protecting against */ }), + d.expiry, + ])).rejects.toBeInstanceOf(DeadlineExceededError); + d.dispose(); + }); + + it('does not fire once disposed', async () => { + const d = createRequestDeadline('tools/call', 30); + d.dispose(); + const outcome = await Promise.race([ + d.expiry.then(() => 'fired', () => 'fired'), + new Promise((r) => setTimeout(() => { r('quiet'); }, 120)), + ]); + expect(outcome).toBe('quiet'); + }); + + it('stops the clock while suspended, so an operator pause cannot time out', async () => { + const d = createRequestDeadline('tools/call', 100); + + // A pause queue wait far longer than the whole deadline. + const held = await d.suspended(async () => { + await new Promise((r) => setTimeout(r, 250)); + return 'released'; + }); + expect(held).toBe('released'); + + // Still alive afterwards, with roughly the original budget left. + const outcome = await Promise.race([ + d.expiry.then(() => 'fired', () => 'fired'), + new Promise((r) => setTimeout(() => { r('still-running'); }, 40)), + ]); + expect(outcome).toBe('still-running'); + d.dispose(); + }); + + it('re-arms after suspension rather than becoming immortal', async () => { + const d = createRequestDeadline('tools/call', 60); + await d.suspended(async () => { await new Promise((r) => setTimeout(r, 100)); }); + // The remaining budget must still expire — suspending is not a bypass. + await expect(Promise.race([ + new Promise(() => { /* hang */ }), + d.expiry, + ])).rejects.toBeInstanceOf(DeadlineExceededError); + d.dispose(); + }); +}); -- 2.49.1 From 89db09a12d4547ee578cb06a928f976302ba7c7c Mon Sep 17 00:00:00 2001 From: Michal Date: Tue, 25 Aug 2026 23:44:36 +0100 Subject: [PATCH 6/9] feat(cli): mcpctl trace , and bound the table it reads MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The trace codes are now emitted in every deadline message and degradation notice, so they need somewhere to go. `mcpctl trace ` queries the audit events mcpd already stores and renders the request as a waterfall: each step with its offset, duration, byte delta, and any ⚠ degradation or ✗ error, then a summary naming the slowest step. No new endpoint was needed -- GET /api/v1/audit/events?correlationId= already existed and correlationId is already an indexed column; it just had nothing writing meaningful values into it until this branch, and nothing reading it. --strict exits non-zero when the trace contains an error or a degraded step, so it composes into scripts. An empty result explains itself rather than printing nothing: batches flush up to 5s late, old requests predate trace codes, and the codes exclude I/L/O/U so a mistyped one is worth calling out. Retention: AuditEvent had no prune at all. That was defensible while the table was write-only; it is not now that a command reads it. Mirrors the AuditLog convention exactly -- POST /api/v1/audit/events/purge, triggered rather than scheduled, guarded by the existing audit-purge RBAC operation so it cannot be granted by accident separately from the log purge. 30 days by default rather than AuditLog's 90: these are several rows per MCP call, not a record of administrative mutations. Note for the plan's sake: I had assumed AuditLog retention was a scheduled job registered in main.ts. It is not -- it is a manual endpoint. Mirroring what the codebase actually does beat inventing a scheduler that exists for neither table. completions are generated, so `trace` is registered in PROJECT_SCOPED_COMMANDS and both shells regenerated; the freshness test passes. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- completions/mcpctl.bash | 7 +- completions/mcpctl.fish | 10 +- scripts/generate-completions.ts | 2 +- src/cli/src/commands/trace.ts | 171 ++++++++++++++++++ src/cli/src/index.ts | 6 + src/cli/tests/trace.test.ts | 75 ++++++++ src/mcpd/src/main.ts | 3 + .../repositories/audit-event.repository.ts | 11 ++ src/mcpd/src/repositories/interfaces.ts | 2 + src/mcpd/src/routes/audit-events.ts | 9 + src/mcpd/src/services/audit-event.service.ts | 25 ++- 11 files changed, 315 insertions(+), 6 deletions(-) create mode 100644 src/cli/src/commands/trace.ts create mode 100644 src/cli/tests/trace.test.ts diff --git a/completions/mcpctl.bash b/completions/mcpctl.bash index 0a6994f..cd7d919 100644 --- a/completions/mcpctl.bash +++ b/completions/mcpctl.bash @@ -5,8 +5,8 @@ _mcpctl() { local cur prev words cword _init_completion || return - local commands="status statusline login logout config get describe delete logs create edit apply chat chat-llm patch passwd errors backup approve review skills console cache provider test migrate rotate" - local project_commands="get describe delete logs create edit attach-server detach-server favourites" + local commands="status statusline login logout config get describe delete logs create edit apply chat chat-llm patch passwd errors trace backup approve review skills console cache provider test migrate rotate" + local project_commands="get describe delete logs create edit trace attach-server detach-server favourites" local global_opts="-v --version --daemon-url --direct -p --project -h --help" local resources="servers instances secrets secretbackends llms agents personalities templates projects users groups rbac prompts promptrequests serverattachments proxymodels inference-tasks all" local resource_aliases="servers instances secrets secretbackends llms agents personalities templates projects users groups rbac prompts promptrequests serverattachments proxymodels inference-tasks all server srv instance inst secret sec secretbackend sb llm agent personality template tpl project proj user group rbac-definition rbac-binding prompt promptrequest pr serverattachment sa proxymodel pm task tasks inference-task" @@ -289,6 +289,9 @@ _mcpctl() { errors) COMPREPLY=($(compgen -W "-n --limit -h --help" -- "$cur")) return ;; + trace) + COMPREPLY=($(compgen -W "-o --output --strict -h --help" -- "$cur")) + return ;; backup) local backup_sub=$(_mcpctl_get_subcmd $subcmd_pos) if [[ -z "$backup_sub" ]]; then diff --git a/completions/mcpctl.fish b/completions/mcpctl.fish index 76f4a8f..6f1241a 100644 --- a/completions/mcpctl.fish +++ b/completions/mcpctl.fish @@ -4,8 +4,8 @@ # Erase any stale completions from previous versions complete -c mcpctl -e -set -l commands status statusline login logout config get describe delete logs create edit apply chat chat-llm patch passwd errors backup approve review skills console cache provider test migrate rotate -set -l project_commands get describe delete logs create edit attach-server detach-server favourites +set -l commands status statusline login logout config get describe delete logs create edit apply chat chat-llm patch passwd errors trace backup approve review skills console cache provider test migrate rotate +set -l project_commands get describe delete logs create edit trace attach-server detach-server favourites # Disable file completions by default complete -c mcpctl -f @@ -237,6 +237,7 @@ complete -c mcpctl -n "not __mcpctl_has_project; and not __fish_seen_subcommand_ complete -c mcpctl -n "not __mcpctl_has_project; and not __fish_seen_subcommand_from $commands" -a patch -d 'Patch a resource field (e.g. mcpctl patch project myproj llmProvider=none)' complete -c mcpctl -n "not __mcpctl_has_project; and not __fish_seen_subcommand_from $commands" -a passwd -d 'Change a user password (your own when called without an argument)' complete -c mcpctl -n "not __mcpctl_has_project; and not __fish_seen_subcommand_from $commands" -a errors -d 'Show recent mcpd error/fatal log entries' +complete -c mcpctl -n "not __mcpctl_has_project; and not __fish_seen_subcommand_from $commands" -a trace -d 'Show the stage-by-stage timeline for one MCP request' complete -c mcpctl -n "not __mcpctl_has_project; and not __fish_seen_subcommand_from $commands" -a backup -d 'Git-based backup status and management' complete -c mcpctl -n "not __mcpctl_has_project; and not __fish_seen_subcommand_from $commands" -a approve -d 'Approve a pending prompt request (atomic: delete request, create prompt)' complete -c mcpctl -n "not __mcpctl_has_project; and not __fish_seen_subcommand_from $commands" -a review -d 'Triage proposed prompts and skills' @@ -255,6 +256,7 @@ complete -c mcpctl -n "__mcpctl_has_project; and not __fish_seen_subcommand_from complete -c mcpctl -n "__mcpctl_has_project; and not __fish_seen_subcommand_from $project_commands" -a logs -d 'Get logs from an MCP server instance' complete -c mcpctl -n "__mcpctl_has_project; and not __fish_seen_subcommand_from $project_commands" -a create -d 'Create a resource (server, secret, secretbackend, llm, agent, project, user, group, rbac, serverattachment, prompt)' complete -c mcpctl -n "__mcpctl_has_project; and not __fish_seen_subcommand_from $project_commands" -a edit -d 'Edit a resource in your default editor (server, project)' +complete -c mcpctl -n "__mcpctl_has_project; and not __fish_seen_subcommand_from $project_commands" -a trace -d 'Show the stage-by-stage timeline for one MCP request' complete -c mcpctl -n "__mcpctl_has_project; and not __fish_seen_subcommand_from $project_commands" -a attach-server -d 'Attach a server to a project (requires --project)' complete -c mcpctl -n "__mcpctl_has_project; and not __fish_seen_subcommand_from $project_commands" -a detach-server -d 'Detach a server from a project (requires --project)' complete -c mcpctl -n "__mcpctl_has_project; and not __fish_seen_subcommand_from $project_commands" -a favourites -d 'Inspect / derive a project\'s favourite-index tool shortlist (requires --project)' @@ -678,6 +680,10 @@ complete -c mcpctl -n "__fish_seen_subcommand_from chat-llm" -l async -d 'Enqueu # errors options complete -c mcpctl -n "__fish_seen_subcommand_from errors" -s n -l limit -d 'max entries to show (default 50)' -x +# trace options +complete -c mcpctl -n "__fish_seen_subcommand_from trace" -s o -l output -d 'table (default) or json' -x +complete -c mcpctl -n "__fish_seen_subcommand_from trace" -l strict -d 'exit non-zero if the trace contains an error or a degraded step' + # console options complete -c mcpctl -n "__fish_seen_subcommand_from console" -l stdin-mcp -d 'Run inspector as MCP server over stdin/stdout (for Claude)' complete -c mcpctl -n "__fish_seen_subcommand_from console" -l audit -d 'Browse audit events from mcpd' diff --git a/scripts/generate-completions.ts b/scripts/generate-completions.ts index 497b0a4..639b4f7 100644 --- a/scripts/generate-completions.ts +++ b/scripts/generate-completions.ts @@ -70,7 +70,7 @@ const PROJECT_ONLY_COMMANDS = new Set(['attach-server', 'detach-server', 'favour /** Commands that appear in BOTH project and non-project context. */ const PROJECT_SCOPED_COMMANDS = new Set([ - 'get', 'describe', 'delete', 'logs', 'create', 'edit', 'help', + 'get', 'describe', 'delete', 'logs', 'create', 'edit', 'help', 'trace', ]); /** Completely hidden commands (never shown in completions). */ diff --git a/src/cli/src/commands/trace.ts b/src/cli/src/commands/trace.ts new file mode 100644 index 0000000..9c25042 --- /dev/null +++ b/src/cli/src/commands/trace.ts @@ -0,0 +1,171 @@ +import { Command } from 'commander'; +import type { ApiClient } from '../api-client.js'; + +export interface TraceCommandDeps { + client: ApiClient; + log: (...args: string[]) => void; +} + +/** Mirrors mcplocal's AuditEvent rows as stored by mcpd. */ +interface AuditEvent { + timestamp: string; + sessionId: string; + projectName: string; + eventKind: string; + source: string; + serverName?: string | null; + correlationId?: string | null; + userName?: string | null; + payload: Record; +} + +function num(v: unknown): number | null { + return typeof v === 'number' && Number.isFinite(v) ? v : null; +} + +function str(v: unknown): string | null { + return typeof v === 'string' && v.length > 0 ? v : null; +} + +function clock(iso: string): string { + const d = new Date(iso); + if (Number.isNaN(d.getTime())) return '--:--:--'; + const p = (n: number): string => String(n).padStart(2, '0'); + return `${p(d.getHours())}:${p(d.getMinutes())}:${p(d.getSeconds())}`; +} + +function bytes(n: number): string { + if (n < 1024) return `${String(n)}B`; + if (n < 1024 * 1024) return `${(n / 1024).toFixed(1)}kB`; + return `${(n / (1024 * 1024)).toFixed(1)}MB`; +} + +/** One line of detail per event kind — what you actually want to see. */ +function detailOf(e: AuditEvent): string { + const p = e.payload; + switch (e.eventKind) { + case 'stage_execution': { + const parts = [str(p['stage']) ?? 'stage']; + const ms = num(p['durationMs']); + if (ms !== null) parts.push(`${String(ms)}ms`); + const inSize = num(p['inputSize']); + const outSize = num(p['outputSize']); + if (inSize !== null && outSize !== null) parts.push(`${bytes(inSize)} → ${bytes(outSize)}`); + const sections = num(p['sectionCount']); + if (sections !== null && sections > 0) parts.push(`${String(sections)} sections`); + return parts.join(' '); + } + case 'pipeline_execution': { + const ms = num(p['totalDurationMs']); + const stages = num(p['stageCount']); + return `${String(stages ?? 0)} stages${ms === null ? '' : `, ${String(ms)}ms total`}`; + } + case 'tool_call_trace': { + const parts = [str(p['toolName']) ?? '(tool)']; + const ms = num(p['durationMs']); + if (ms !== null) parts.push(`${String(ms)}ms`); + const size = num(p['resultSizeBytes']); + if (size !== null) parts.push(bytes(size)); + return parts.join(' '); + } + case 'gate_decision': { + const trigger = str(p['trigger']) ?? 'gate'; + const matched = Array.isArray(p['matchedPrompts']) ? (p['matchedPrompts']).length : 0; + return `${trigger} · ${String(matched)} prompts`; + } + default: + return e.eventKind; + } +} + +function degradationOf(e: AuditEvent): string | null { + if (e.payload['degraded'] !== true) return null; + return str(e.payload['degradedReason']) ?? 'degraded'; +} + +function errorOf(e: AuditEvent): string | null { + return str(e.payload['error']); +} + +export function createTraceCommand(deps?: Partial): Command { + const log = deps?.log ?? ((...args: string[]): void => { console.log(...args); }); + + return new Command('trace') + .argument('', 'trace code from an error message or degradation notice') + .description('Show the stage-by-stage timeline for one MCP request') + .option('-o, --output ', 'table (default) or json') + .option('--strict', 'exit non-zero if the trace contains an error or a degraded step') + .action(async (code: string, opts: { output?: string; strict?: boolean }) => { + const client = deps?.client; + if (!client) throw new Error('trace: no API client configured'); + + const res = await client.get<{ events?: AuditEvent[]; total?: number }>( + `/api/v1/audit/events?correlationId=${encodeURIComponent(code)}&limit=500`, + ); + const events = (res.events ?? []) + .slice() + .sort((a, b) => new Date(a.timestamp).getTime() - new Date(b.timestamp).getTime()); + + if (events.length === 0) { + log(`No trace found for '${code}'.`); + log(''); + log('Traces are written by mcplocal and stored by mcpd. If the request is very'); + log('recent the batch may not have flushed yet (up to 5s); if it is very old it'); + log('may predate trace codes. Check the code was copied exactly — they are 8'); + log('characters, no I/L/O/U.'); + if (opts.strict === true) process.exitCode = 1; + return; + } + + if (opts.output === 'json') { + log(JSON.stringify(events, null, 2)); + return; + } + + const first = events[0]!; + const start = new Date(first.timestamp).getTime(); + const call = events.find((e) => e.eventKind === 'tool_call_trace'); + const headline = call ? detailOf(call) : first.eventKind; + + log(`Trace ${code} project ${first.projectName} session ${first.sessionId.slice(0, 8)}…`); + if (first.userName) log(`user ${first.userName}`); + log(`${headline}`); + log(''); + log(' TIME Δms EVENT DETAIL'); + + let degradedCount = 0; + let errorCount = 0; + let slowest: { name: string; ms: number } | null = null; + + for (const e of events) { + const delta = new Date(e.timestamp).getTime() - start; + const degraded = degradationOf(e); + const err = errorOf(e); + if (degraded !== null) degradedCount++; + if (err !== null) errorCount++; + + const ms = num(e.payload['durationMs']) ?? num(e.payload['totalDurationMs']); + const label = str(e.payload['stage']) ?? e.eventKind; + if (ms !== null && (slowest === null || ms > slowest.ms)) slowest = { name: label, ms }; + + const marks = [ + degraded !== null ? `⚠ ${degraded}` : null, + err !== null ? `✗ ${err}` : null, + ].filter((x): x is string => x !== null).join(' '); + + log( + ` ${clock(e.timestamp)} ${String(delta).padStart(6)} ` + + `${e.eventKind.padEnd(19)} ${detailOf(e)}${marks ? ` ${marks}` : ''}`, + ); + } + + log(''); + const summary: string[] = [`${String(events.length)} events`]; + if (degradedCount > 0) summary.push(`⚠ ${String(degradedCount)} degraded`); + if (errorCount > 0) summary.push(`✗ ${String(errorCount)} error${errorCount === 1 ? '' : 's'}`); + if (slowest !== null) summary.push(`slowest: ${slowest.name} (${String(slowest.ms)}ms)`); + log(summary.join(' · ')); + + if (opts.strict === true && (degradedCount > 0 || errorCount > 0)) process.exitCode = 1; + }); +} diff --git a/src/cli/src/index.ts b/src/cli/src/index.ts index 47c2070..bb4ade9 100644 --- a/src/cli/src/index.ts +++ b/src/cli/src/index.ts @@ -29,6 +29,7 @@ import { createSkillsCommand } from './commands/skills.js'; import { createStatuslineCommand } from './commands/statusline.js'; import { createPasswdCommand } from './commands/passwd.js'; import { createErrorsCommand } from './commands/errors.js'; +import { createTraceCommand } from './commands/trace.js'; import { ApiClient, ApiError } from './api-client.js'; import { loadConfig } from './config/index.js'; import { loadCredentials } from './auth/index.js'; @@ -280,6 +281,11 @@ export function createProgram(): Command { log: (...args) => console.log(...args), })); + program.addCommand(createTraceCommand({ + client, + log: (...args) => console.log(...args), + })); + program.addCommand(createBackupCommand({ client, log: (...args) => console.log(...args), diff --git a/src/cli/tests/trace.test.ts b/src/cli/tests/trace.test.ts new file mode 100644 index 0000000..bc9f0df --- /dev/null +++ b/src/cli/tests/trace.test.ts @@ -0,0 +1,75 @@ +import { describe, it, expect, vi } from 'vitest'; +import { createTraceCommand } from '../src/commands/trace.js'; +import type { ApiClient } from '../src/api-client.js'; + +function clientReturning(events: unknown[]): ApiClient { + return { get: vi.fn(async () => ({ events, total: events.length })) } as unknown as ApiClient; +} + +function run(client: ApiClient, args: string[]): Promise { + const lines: string[] = []; + const cmd = createTraceCommand({ client, log: (...a: string[]) => { lines.push(a.join(' ')); } }); + return cmd.parseAsync(['node', 'trace', ...args]).then(() => lines); +} + +const base = { + sessionId: 'abcdef1234567890', projectName: 'sre', source: 'mcplocal', + correlationId: 'K3P7QW2M', userName: 'michal@itaz.eu', +}; + +describe('mcpctl trace', () => { + it('renders a waterfall ordered by time', async () => { + const lines = await run(clientReturning([ + { ...base, timestamp: '2026-08-25T22:00:02.000Z', eventKind: 'tool_call_trace', + payload: { toolName: 'docmost/search', durationMs: 461, resultSizeBytes: 14091, error: null } }, + { ...base, timestamp: '2026-08-25T22:00:00.000Z', eventKind: 'stage_execution', + payload: { stage: 'paginate', durationMs: 12, inputSize: 14091, outputSize: 5632, sectionCount: 2 } }, + ]), ['K3P7QW2M']); + + const out = lines.join('\n'); + expect(out).toContain('Trace K3P7QW2M'); + expect(out).toContain('project sre'); + expect(out).toContain('docmost/search'); + // Sorted: the stage at :00 must precede the tool_call at :02 even though + // the API returned them newest-first. + expect(out.indexOf('paginate')).toBeLessThan(out.indexOf('tool_call_trace')); + }); + + it('flags degraded steps and names the slowest', async () => { + const lines = await run(clientReturning([ + { ...base, timestamp: '2026-08-25T22:00:00.000Z', eventKind: 'stage_execution', + payload: { stage: 'summarize-tree', durationMs: 30001, inputSize: 100, outputSize: 50, + degraded: true, degradedReason: 'stage LLM budget of 30000ms exhausted' } }, + ]), ['K3P7QW2M']); + + const out = lines.join('\n'); + expect(out).toContain('⚠ stage LLM budget of 30000ms exhausted'); + expect(out).toContain('1 degraded'); + expect(out).toContain('slowest: summarize-tree (30001ms)'); + }); + + it('explains an empty result instead of printing nothing', async () => { + const lines = await run(clientReturning([]), ['ZZZZZZZZ']); + const out = lines.join('\n'); + expect(out).toContain("No trace found for 'ZZZZZZZZ'"); + expect(out).toContain('no I/L/O/U'); + }); + + it('--strict exits non-zero on a degraded trace', async () => { + process.exitCode = 0; + await run(clientReturning([ + { ...base, timestamp: '2026-08-25T22:00:00.000Z', eventKind: 'stage_execution', + payload: { stage: 'paginate', durationMs: 1, degraded: true, degradedReason: 'timed out' } }, + ]), ['K3P7QW2M', '--strict']); + expect(process.exitCode).toBe(1); + process.exitCode = 0; + }); + + it('queries mcpd by correlationId', async () => { + const client = clientReturning([]); + await run(client, ['K3P7QW2M']); + expect(client.get).toHaveBeenCalledWith( + expect.stringContaining('/api/v1/audit/events?correlationId=K3P7QW2M'), + ); + }); +}); diff --git a/src/mcpd/src/main.ts b/src/mcpd/src/main.ts index 013361e..ce2bd17 100644 --- a/src/mcpd/src/main.ts +++ b/src/mcpd/src/main.ts @@ -155,6 +155,9 @@ function mapUrlToPermission(method: string, url: string): PermissionCheck { if (segment === 'backup') return { kind: 'operation', operation: 'backup' }; if (segment === 'restore') return { kind: 'operation', operation: 'restore' }; if (segment === 'audit-logs' && method === 'DELETE') return { kind: 'operation', operation: 'audit-purge' }; + // Same operation guards the trace-event purge — both are bulk deletes of + // audit history and should not be separately grantable by accident. + if (url.startsWith('/api/v1/audit/events/purge')) return { kind: 'operation', operation: 'audit-purge' }; // /api/v1/secrets/migrate is a bulk cross-backend operation — treat as op, not a plain secret write. if (url.startsWith('/api/v1/secrets/migrate')) return { kind: 'operation', operation: 'migrate-secrets' }; // /api/v1/secretbackends/:id/rotate — manual rotation trigger. Operation so diff --git a/src/mcpd/src/repositories/audit-event.repository.ts b/src/mcpd/src/repositories/audit-event.repository.ts index f5e1aa9..47dd78f 100644 --- a/src/mcpd/src/repositories/audit-event.repository.ts +++ b/src/mcpd/src/repositories/audit-event.repository.ts @@ -170,6 +170,17 @@ export class AuditEventRepository implements IAuditEventRepository { }); return groups.length; } + + /** + * Prune old events. AuditEvent had no retention at all while the table was + * write-only; now that `mcpctl trace` reads it, it is worth bounding. + */ + async deleteOlderThan(cutoff: Date): Promise { + const result = await this.prisma.auditEvent.deleteMany({ + where: { timestamp: { lt: cutoff } }, + }); + return result.count; + } } function buildWhere(filter?: AuditEventFilter): Prisma.AuditEventWhereInput { diff --git a/src/mcpd/src/repositories/interfaces.ts b/src/mcpd/src/repositories/interfaces.ts index 6d94852..7fb87bd 100644 --- a/src/mcpd/src/repositories/interfaces.ts +++ b/src/mcpd/src/repositories/interfaces.ts @@ -108,6 +108,8 @@ export interface IAuditEventRepository { countSessions(filter?: { projectName?: string; userName?: string; from?: Date; to?: Date }): Promise; /** Rank tools by invocation count for a project (from tool_call_trace events). */ toolUsage(projectName: string, from: Date, sampleLimit?: number): Promise; + /** Delete events older than `cutoff`; returns the number removed. */ + deleteOlderThan(cutoff: Date): Promise; } // ── MCP Tokens ── diff --git a/src/mcpd/src/routes/audit-events.ts b/src/mcpd/src/routes/audit-events.ts index 1223ce1..32d56af 100644 --- a/src/mcpd/src/routes/audit-events.ts +++ b/src/mcpd/src/routes/audit-events.ts @@ -58,6 +58,15 @@ export function registerAuditEventRoutes(app: FastifyInstance, service: AuditEve return service.getById(request.params.id); }); + // POST /api/v1/audit/events/purge — drop events past the retention window. + // Mirrors /api/v1/audit-logs/purge: triggered, not scheduled, so an operator + // (or a cron) decides when a potentially large delete runs. + app.post('/api/v1/audit/events/purge', async (_request, reply) => { + const deleted = await service.purgeExpired(); + reply.code(200); + return { deleted }; + }); + // GET /api/v1/audit/tool-usage — rank tools by invocation count (for favourites) app.get<{ Querystring: { projectName?: string; window?: string; limit?: string } }>('/api/v1/audit/tool-usage', async (request, reply) => { const q = request.query; diff --git a/src/mcpd/src/services/audit-event.service.ts b/src/mcpd/src/services/audit-event.service.ts index 488a6a1..63f6f64 100644 --- a/src/mcpd/src/services/audit-event.service.ts +++ b/src/mcpd/src/services/audit-event.service.ts @@ -17,8 +17,31 @@ export interface AuditEventQueryParams { offset?: number; } +/** + * Default retention for trace/audit events. + * + * Shorter than AuditLog's 90 days: these are high-volume per-request telemetry + * (several rows per MCP call), not a record of administrative mutations. + */ +const DEFAULT_RETENTION_DAYS = 30; + export class AuditEventService { - constructor(private readonly repo: IAuditEventRepository) {} + constructor( + private readonly repo: IAuditEventRepository, + private readonly retentionDays: number = + Number(process.env['MCPD_AUDIT_EVENT_RETENTION_DAYS']) || DEFAULT_RETENTION_DAYS, + ) {} + + /** + * Drop events past the retention window. The table previously had no prune + * at all and grew unbounded; `mcpctl trace` now reads it, so bounding it + * matters more than it did when nothing consumed it. + */ + async purgeExpired(): Promise { + const cutoff = new Date(); + cutoff.setDate(cutoff.getDate() - this.retentionDays); + return this.repo.deleteOlderThan(cutoff); + } async list(params?: AuditEventQueryParams): Promise<{ events: AuditEvent[]; total: number }> { const filter = this.buildFilter(params); -- 2.49.1 From 14eb2623bc03f0d2eee9d446e9fed6577507295c Mon Sep 17 00:00:00 2001 From: Michal Date: Tue, 25 Aug 2026 23:48:07 +0100 Subject: [PATCH 7/9] fix(cli): trace's 'slowest' names a step, not the aggregate tool_call_trace and pipeline_execution are aggregates OF the stages, so letting them compete always named the total and told you nothing. Verified live: now reports 'slowest: paginate (252ms)' rather than 'tool_call_trace (509ms)'. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- src/cli/src/commands/trace.ts | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/cli/src/commands/trace.ts b/src/cli/src/commands/trace.ts index 9c25042..a3f2a41 100644 --- a/src/cli/src/commands/trace.ts +++ b/src/cli/src/commands/trace.ts @@ -144,9 +144,14 @@ export function createTraceCommand(deps?: Partial): Command { if (degraded !== null) degradedCount++; if (err !== null) errorCount++; - const ms = num(e.payload['durationMs']) ?? num(e.payload['totalDurationMs']); - const label = str(e.payload['stage']) ?? e.eventKind; - if (ms !== null && (slowest === null || ms > slowest.ms)) slowest = { name: label, ms }; + // Only real steps compete for "slowest" — tool_call_trace and + // pipeline_execution are aggregates OF those steps, so including them + // would always name the total and tell you nothing. + const ms = num(e.payload['durationMs']); + const label = str(e.payload['stage']); + if (ms !== null && label !== null && (slowest === null || ms > slowest.ms)) { + slowest = { name: label, ms }; + } const marks = [ degraded !== null ? `⚠ ${degraded}` : null, -- 2.49.1 From 08b451b7aafa2dc839bc64ce8aa4f8ab8b626eda Mon Sep 17 00:00:00 2001 From: Michal Date: Tue, 25 Aug 2026 23:55:44 +0100 Subject: [PATCH 8/9] feat(mcplocal): Anthropic models auto-follow the newest in their family `claude-opus-4-20250514` was pinned as the heavy provider and had been returning 404 on every gate ranking and every pagination title. The only visible symptom was a fallback that looked like an ordinary one -- it surfaced here because the degradation notice added earlier in this branch finally printed the reason. Checked against GET /v1/models: BOTH pins were dead. The fast tier's claude-haiku-3-5-20241022 is gone too, so that tier had been silently 404ing as well. The provider's listModels() asserted "Anthropic doesn't have a models listing endpoint" and returned four hardcoded dated ids. That endpoint does exist and answers fine with the OAuth token this deployment uses; the hardcoded list was simply stale, and a test pinned it in place. So: `claude--latest` (or a bare `opus` / `sonnet` / `haiku` / `fable`) now resolves against the live list. Exact ids pass through untouched, so pinning still works when someone wants it. Newest is decided by `created_at`, never by parsing the version out of the id. That is not incidental: `claude-opus-4-5` sorts ABOVE `claude-opus-5` as a string, and "4-5" parses as a larger minor than "5". There is a test for exactly that trap. Resolution is cached (12h, MCPCTL_ANTHROPIC_MODEL_TTL_MS) so it is not a per-call network hop, and shared across instances since the model list is account-wide. When the endpoint is unreachable it falls back to a pinned known-good id per family and says so on stderr -- the map going stale can then only cost availability, never correctness. The constructor default was `claude-sonnet-4-20250514`, also retired; it now tracks the family too. Local config: heavy -> claude-opus-latest, fast -> claude-haiku-latest. Verified live: opus-latest -> claude-opus-5, haiku-latest -> claude-haiku-4-5-20251001, sonnet-latest -> claude-sonnet-5, and an exact id passes through. Also found while there: both anthropic entries were named "anthropic", and the registry keys by name, so the second silently OVERWROTE the first and one tier's model was discarded entirely. Renamed to anthropic-fast / anthropic-heavy so NamedProvider keeps them distinct and the tier split is real. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- src/mcplocal/src/providers/anthropic.ts | 149 ++++++++++++++++-- .../tests/anthropic-model-resolution.test.ts | 83 ++++++++++ src/mcplocal/tests/providers.test.ts | 18 ++- 3 files changed, 237 insertions(+), 13 deletions(-) create mode 100644 src/mcplocal/tests/anthropic-model-resolution.test.ts diff --git a/src/mcplocal/src/providers/anthropic.ts b/src/mcplocal/src/providers/anthropic.ts index 7cadc83..7527051 100644 --- a/src/mcplocal/src/providers/anthropic.ts +++ b/src/mcplocal/src/providers/anthropic.ts @@ -6,21 +6,52 @@ export interface AnthropicConfig { defaultModel?: string; } +/** + * Families that can be tracked with a `claude--latest` selector. + * + * The pinned value is a FALLBACK, used only when the models endpoint cannot be + * reached. Normal operation resolves against the live list, so this map going + * stale degrades availability, never correctness. + */ +const FAMILY_FALLBACK: Record = { + opus: 'claude-opus-5', + sonnet: 'claude-sonnet-5', + haiku: 'claude-haiku-4-5-20251001', + fable: 'claude-fable-5', +}; + +/** `claude-opus-latest` / `opus` → `opus`; an exact model id → null. */ +function familyOf(model: string): string | null { + const m = /^(?:claude-)?([a-z]+)(?:-latest)?$/.exec(model.trim().toLowerCase()); + const family = m?.[1]; + if (family !== undefined && family in FAMILY_FALLBACK && /latest|^(opus|sonnet|haiku|fable)$/.test(model.toLowerCase())) { + return family; + } + return null; +} + +/** Resolutions are cached this long before the models endpoint is consulted again. */ +const MODEL_CACHE_TTL_MS = Number(process.env['MCPCTL_ANTHROPIC_MODEL_TTL_MS']) || 12 * 60 * 60 * 1000; + /** * Anthropic Claude provider using the Messages API. */ export class AnthropicProvider implements LlmProvider { readonly name = 'anthropic'; + /** Shared across instances: the model list is account-wide, not per-provider. */ + private static readonly modelCache = new Map(); private apiKey: string; private defaultModel: string; constructor(config: AnthropicConfig) { this.apiKey = config.apiKey; - this.defaultModel = config.defaultModel ?? 'claude-sonnet-4-20250514'; + // A dated default is a time bomb: claude-sonnet-4-20250514 is retired and + // would 404. Track the family instead. + this.defaultModel = config.defaultModel ?? 'claude-sonnet-latest'; } async complete(options: CompletionOptions): Promise { - const model = options.model ?? this.defaultModel; + const model = await this.resolveModel(options.model ?? this.defaultModel); // Separate system message from conversation const systemMessages = options.messages.filter((m) => m.role === 'system'); @@ -49,14 +80,75 @@ export class AnthropicProvider implements LlmProvider { return parseAnthropicResponse(response); } + /** + * Turn a `claude--latest` selector into a concrete model id. + * + * Exact ids pass through untouched, so pinning still works. Selectors are + * resolved against GET /v1/models and cached, because a dated id pinned in + * config rots silently: `claude-opus-4-20250514` sat in this deployment + * returning 404 on every gate ranking and every pagination title, and the + * only visible symptom was a fallback that looked like a normal one. + * + * Newest is decided by `created_at`, never by parsing the version out of the + * id — that is what keeps `claude-opus-4-5` from beating `claude-opus-5`. + */ + async resolveModel(model: string): Promise { + const family = familyOf(model); + if (family === null) return model; + + const cached = AnthropicProvider.modelCache.get(family); + if (cached && Date.now() < cached.expiresAt) return cached.id; + + try { + const models = await this.fetchModels(); + const match = models + .filter((m) => m.id.startsWith(`claude-${family}-`) || m.id === `claude-${family}`) + .sort((a, b) => (a.created_at < b.created_at ? 1 : -1))[0]; + if (!match) throw new Error(`no models found for family '${family}'`); + + AnthropicProvider.modelCache.set(family, { + id: match.id, + expiresAt: Date.now() + MODEL_CACHE_TTL_MS, + }); + if (cached?.id !== match.id) { + process.stderr.write(`[anthropic] ${model} -> ${match.id}\n`); + } + return match.id; + } catch (err) { + // Loud, not silent, and deterministic: an unreachable models endpoint + // must not take the provider down with it. + const fallback = FAMILY_FALLBACK[family]!; + process.stderr.write( + `[anthropic] could not resolve '${model}' (${(err as Error).message}) — ` + + `falling back to ${fallback}\n`, + ); + return fallback; + } + } + async listModels(): Promise { - // Anthropic doesn't have a models listing endpoint; return known models - return [ - 'claude-opus-4-20250514', - 'claude-sonnet-4-20250514', - 'claude-sonnet-4-5-20250514', - 'claude-haiku-3-5-20241022', - ]; + const models = await this.fetchModels(); + return models.map((m) => m.id); + } + + /** GET /v1/models, newest first. Follows pagination. */ + private async fetchModels(): Promise> { + const all: Array<{ id: string; created_at: string }> = []; + let after: string | undefined; + + for (let page = 0; page < 10; page++) { + const query = new URLSearchParams({ limit: '100' }); + if (after !== undefined) query.set('after_id', after); + const body = await this.get(`/v1/models?${query.toString()}`) as { + data?: Array<{ id: string; created_at: string }>; + has_more?: boolean; + last_id?: string; + }; + all.push(...(body.data ?? [])); + if (body.has_more !== true || body.last_id === undefined) break; + after = body.last_id; + } + return all; } async isAvailable(): Promise { @@ -72,6 +164,45 @@ export class AnthropicProvider implements LlmProvider { } } + /** GET against the Anthropic API, same auth handling as request(). */ + private get(path: string): Promise { + return new Promise((resolve, reject) => { + const isOAuth = this.apiKey.startsWith('sk-ant-oat'); + const req = https.request({ + hostname: 'api.anthropic.com', + port: 443, + path, + method: 'GET', + timeout: 15000, + headers: { + ...(isOAuth + ? { 'Authorization': `Bearer ${this.apiKey}` } + : { 'x-api-key': this.apiKey }), + 'anthropic-version': '2023-06-01', + }, + }, (res) => { + const chunks: Buffer[] = []; + res.on('data', (chunk: Buffer) => chunks.push(chunk)); + res.on('end', () => { + const raw = Buffer.concat(chunks).toString('utf-8'); + const status = res.statusCode ?? 0; + if (status >= 400) { + reject(new Error(`Anthropic HTTP ${String(status)}: ${raw.slice(0, 200)}`)); + return; + } + try { + resolve(JSON.parse(raw)); + } catch { + reject(new Error('Anthropic response was not valid JSON')); + } + }); + }); + req.on('timeout', () => { req.destroy(new Error('models request timed out')); }); + req.on('error', reject); + req.end(); + }); + } + private request(body: unknown, signal?: AbortSignal): Promise { return new Promise((resolve, reject) => { if (signal?.aborted === true) { diff --git a/src/mcplocal/tests/anthropic-model-resolution.test.ts b/src/mcplocal/tests/anthropic-model-resolution.test.ts new file mode 100644 index 0000000..1a6d7fa --- /dev/null +++ b/src/mcplocal/tests/anthropic-model-resolution.test.ts @@ -0,0 +1,83 @@ +import { describe, it, expect, vi, afterEach } from 'vitest'; +import { AnthropicProvider } from '../src/providers/anthropic.js'; + +/** The real payload shape, abbreviated — newest first, as the API returns it. */ +const MODELS = [ + { id: 'claude-opus-5', created_at: '2026-07-24T00:00:00Z' }, + { id: 'claude-sonnet-5', created_at: '2026-06-29T00:00:00Z' }, + { id: 'claude-fable-5', created_at: '2026-06-07T00:00:00Z' }, + { id: 'claude-opus-4-8', created_at: '2026-05-28T00:00:00Z' }, + { id: 'claude-opus-4-5-20251101', created_at: '2025-11-24T00:00:00Z' }, + { id: 'claude-haiku-4-5-20251001', created_at: '2025-10-15T00:00:00Z' }, +]; + +function providerWith(models: typeof MODELS | Error): AnthropicProvider { + const p = new AnthropicProvider({ apiKey: 'sk-ant-api-test' }); + // Stub the private transport rather than the network. + (p as unknown as { get: (path: string) => Promise }).get = async () => { + if (models instanceof Error) throw models; + return { data: models, has_more: false }; + }; + return p; +} + +afterEach(() => { + // The cache is static — clear it so cases don't leak into each other. + (AnthropicProvider as unknown as { modelCache: Map }).modelCache.clear(); + vi.restoreAllMocks(); +}); + +describe('Anthropic model resolution', () => { + it('resolves a family selector to the newest member', async () => { + await expect(providerWith(MODELS).resolveModel('claude-opus-latest')).resolves.toBe('claude-opus-5'); + }); + + it('accepts the bare family name too', async () => { + await expect(providerWith(MODELS).resolveModel('opus')).resolves.toBe('claude-opus-5'); + await expect(providerWith(MODELS).resolveModel('haiku')).resolves.toBe('claude-haiku-4-5-20251001'); + }); + + it('picks by created_at, not by parsing the version', async () => { + // The trap: claude-opus-4-5 sorts ABOVE claude-opus-5 as a string, and + // "4-5" parses as a bigger minor than "5". Only the date is reliable. + const out = await providerWith(MODELS).resolveModel('claude-opus-latest'); + expect(out).toBe('claude-opus-5'); + expect(out).not.toBe('claude-opus-4-5-20251101'); + }); + + it('leaves an exact model id alone, so pinning still works', async () => { + const p = providerWith(MODELS); + await expect(p.resolveModel('claude-opus-4-8')).resolves.toBe('claude-opus-4-8'); + await expect(p.resolveModel('claude-haiku-4-5-20251001')).resolves.toBe('claude-haiku-4-5-20251001'); + }); + + it('does not treat a dated id as a family selector', async () => { + await expect(providerWith(MODELS).resolveModel('claude-opus-4-20250514')) + .resolves.toBe('claude-opus-4-20250514'); + }); + + it('falls back deterministically when the models endpoint is unreachable', async () => { + const err = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + await expect(providerWith(new Error('network down')).resolveModel('claude-opus-latest')) + .resolves.toBe('claude-opus-5'); + // Loud, not silent. + expect(err).toHaveBeenCalledWith(expect.stringContaining('falling back')); + }); + + it('caches, so resolution is not a per-call network hop', async () => { + const p = providerWith(MODELS); + let calls = 0; + (p as unknown as { get: () => Promise }).get = async () => { + calls++; + return { data: MODELS, has_more: false }; + }; + await p.resolveModel('claude-opus-latest'); + await p.resolveModel('claude-opus-latest'); + await p.resolveModel('claude-opus-latest'); + expect(calls).toBe(1); + }); + + it('lists real models instead of a hardcoded table', async () => { + await expect(providerWith(MODELS).listModels()).resolves.toContain('claude-opus-5'); + }); +}); diff --git a/src/mcplocal/tests/providers.test.ts b/src/mcplocal/tests/providers.test.ts index 889dbb1..68f1d19 100644 --- a/src/mcplocal/tests/providers.test.ts +++ b/src/mcplocal/tests/providers.test.ts @@ -271,11 +271,21 @@ describe('AnthropicProvider auth headers', () => { expect(headers['Authorization']).toBeUndefined(); }); - it('includes claude-sonnet-4-5 in model list', async () => { + it('lists models from the API rather than a hardcoded table', async () => { + // This used to assert a hardcoded list containing + // claude-opus-4-20250514 and claude-haiku-3-5-20241022 — both since + // retired, and both returning 404 in production while the provider still + // advertised them. The list now comes from GET /v1/models. const provider = new AnthropicProvider({ apiKey: 'test' }); + (provider as unknown as { get: (p: string) => Promise }).get = async () => ({ + data: [ + { id: 'claude-opus-5', created_at: '2026-07-24T00:00:00Z' }, + { id: 'claude-haiku-4-5-20251001', created_at: '2025-10-15T00:00:00Z' }, + ], + has_more: false, + }); + const models = await provider.listModels(); - expect(models).toContain('claude-sonnet-4-5-20250514'); - expect(models).toContain('claude-opus-4-20250514'); - expect(models).toContain('claude-haiku-3-5-20241022'); + expect(models).toEqual(['claude-opus-5', 'claude-haiku-4-5-20251001']); }); }); -- 2.49.1 From 47d7c779d0ec8bba0dd8ba6babf7db39bd37488f Mon Sep 17 00:00:00 2001 From: Michal Date: Wed, 26 Aug 2026 00:03:06 +0100 Subject: [PATCH 9/9] feat: per-server tool-call timeout, on the server resource Completes the plan's last item. The deadline shipped with a global default; this makes it overridable per server, where the knowledge actually lives -- a server with genuinely slow tools declares its own budget instead of forcing the global up for everyone. Source of truth is the server resource, following healthCheck exactly: Prisma column + migration (NULL keeps today's behaviour, so no existing server changes), zod validation on create and update, the repository, an `--tool-call-timeout` flag mirroring `--health-check-timeout`, and the apply schema so `apply -f` accepts what `get server -o yaml` emits. That round-trip needed care: get emits `toolCallTimeoutSeconds: null` for every server without an override, so the apply schema is nullable, not merely optional -- otherwise the very first `get -o yaml | apply -f` on an untouched server would have failed validation. Bounded at one hour. A deadline exists so a wedged call answers instead of hanging; a value beyond an hour is indistinguishable from having none. It reaches mcplocal through server discovery rather than the project-scoped serverOverrides map, and is applied on EVERY sync rather than only at first registration -- raising a server's timeout should take effect at the next refresh, not require the upstream to be dropped and rebuilt. The endpoint sees the wire name (`docmost_search`), so it decodes to the canonical `server/tool` before resolving. The override is keyed by server, so every tool on that server inherits it without being enumerated, and the failure message quotes the deadline actually applied rather than the global. Smoke tests (tests/smoke/bounded-failures.smoke.test.ts) cover the two production faults against the live proxy: a stale session recovers instead of stranding the client on an uncorrelatable 404, every request is answered, and `mcpctl trace` responds for an unknown code. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01GqMidYEGUJG5fxeoTELBu2 --- completions/mcpctl.bash | 2 +- completions/mcpctl.fish | 1 + src/cli/src/commands/apply.ts | 6 + src/cli/src/commands/create.ts | 4 + .../migration.sql | 7 + src/db/prisma/schema.prisma | 6 + .../src/repositories/mcp-server.repository.ts | 2 + src/mcpd/src/validation/mcp-server.schema.ts | 5 + src/mcplocal/src/discovery.ts | 11 ++ src/mcplocal/src/http/project-mcp-endpoint.ts | 18 ++- src/mcplocal/src/router.ts | 25 ++++ .../smoke/bounded-failures.smoke.test.ts | 120 ++++++++++++++++++ src/mcplocal/tests/toolcall-deadline.test.ts | 27 ++++ 13 files changed, 230 insertions(+), 4 deletions(-) create mode 100644 src/db/prisma/migrations/20260826000000_add_server_toolcall_timeout/migration.sql create mode 100644 src/mcplocal/tests/smoke/bounded-failures.smoke.test.ts diff --git a/completions/mcpctl.bash b/completions/mcpctl.bash index cd7d919..dfae59d 100644 --- a/completions/mcpctl.bash +++ b/completions/mcpctl.bash @@ -194,7 +194,7 @@ _mcpctl() { else case "$create_sub" in server) - COMPREPLY=($(compgen -W "-d --description --package-name --runtime --docker-image --transport --repository-url --external-url --command --container-port --replicas --env --volume --health-check-tool --health-check-args --health-check-interval --health-check-timeout --health-check-failure-threshold --secret-delivery --entrypoint --from-template --env-from-secret --force -h --help" -- "$cur")) + COMPREPLY=($(compgen -W "-d --description --package-name --runtime --docker-image --transport --repository-url --external-url --command --container-port --replicas --env --volume --health-check-tool --health-check-args --health-check-interval --health-check-timeout --tool-call-timeout --health-check-failure-threshold --secret-delivery --entrypoint --from-template --env-from-secret --force -h --help" -- "$cur")) ;; secret) COMPREPLY=($(compgen -W "--data --force -h --help" -- "$cur")) diff --git a/completions/mcpctl.fish b/completions/mcpctl.fish index 6f1241a..00b5c10 100644 --- a/completions/mcpctl.fish +++ b/completions/mcpctl.fish @@ -387,6 +387,7 @@ complete -c mcpctl -n "__mcpctl_subcmd_active create server" -l health-check-too complete -c mcpctl -n "__mcpctl_subcmd_active create server" -l health-check-args -d 'Readiness probe: JSON object of arguments for the probe tool' -x complete -c mcpctl -n "__mcpctl_subcmd_active create server" -l health-check-interval -d 'Readiness probe interval in seconds (default 60)' -x complete -c mcpctl -n "__mcpctl_subcmd_active create server" -l health-check-timeout -d 'Readiness probe timeout in seconds (default 10)' -x +complete -c mcpctl -n "__mcpctl_subcmd_active create server" -l tool-call-timeout -d 'Per-server tool-call deadline in seconds (default: mcplocal\'s global deadline)' -x complete -c mcpctl -n "__mcpctl_subcmd_active create server" -l health-check-failure-threshold -d 'Consecutive failures before the instance is marked unhealthy (default 3)' -x complete -c mcpctl -n "__mcpctl_subcmd_active create server" -l secret-delivery -d 'How secret env reaches the container: env (default, value written into the pod spec) or injector (pod fetches its own secrets from OpenBao under a scoped identity)' -x complete -c mcpctl -n "__mcpctl_subcmd_active create server" -l entrypoint -d 'Comma-separated argv to exec under the injector wrapper. Required for --secret-delivery injector on a dockerImage server, whose ENTRYPOINT mcpd cannot introspect' -x diff --git a/src/cli/src/commands/apply.ts b/src/cli/src/commands/apply.ts index da66a8e..342aeb5 100644 --- a/src/cli/src/commands/apply.ts +++ b/src/cli/src/commands/apply.ts @@ -46,6 +46,9 @@ const ServerSpecSchema = z.object({ volumes: z.array(VolumeSpecSchema).default([]), secretDelivery: z.enum(['env', 'injector']).optional(), entrypoint: z.array(z.string()).optional(), + // nullable: `get server -o yaml` emits null for servers with no override, + // and that YAML must apply back unchanged. + toolCallTimeoutSeconds: z.number().int().min(1).max(3600).nullable().optional(), }); const SecretSpecSchema = z.object({ @@ -140,6 +143,9 @@ const TemplateSpecSchema = z.object({ volumes: z.array(VolumeSpecSchema).default([]), secretDelivery: z.enum(['env', 'injector']).optional(), entrypoint: z.array(z.string()).optional(), + // nullable: `get server -o yaml` emits null for servers with no override, + // and that YAML must apply back unchanged. + toolCallTimeoutSeconds: z.number().int().min(1).max(3600).nullable().optional(), }); const UserSpecSchema = z.object({ diff --git a/src/cli/src/commands/create.ts b/src/cli/src/commands/create.ts index c64a681..1312a79 100644 --- a/src/cli/src/commands/create.ts +++ b/src/cli/src/commands/create.ts @@ -251,6 +251,7 @@ export function createCreateCommand(deps: CreateCommandDeps): Command { .option('--health-check-args ', 'Readiness probe: JSON object of arguments for the probe tool') .option('--health-check-interval ', 'Readiness probe interval in seconds (default 60)') .option('--health-check-timeout ', 'Readiness probe timeout in seconds (default 10)') + .option('--tool-call-timeout ', 'Per-server tool-call deadline in seconds (default: mcplocal\'s global deadline)') .option('--health-check-failure-threshold ', 'Consecutive failures before the instance is marked unhealthy (default 3)') .option('--secret-delivery ', 'How secret env reaches the container: env (default, value written into the pod spec) or injector (pod fetches its own secrets from OpenBao under a scoped identity)') .option('--entrypoint ', 'Comma-separated argv to exec under the injector wrapper. Required for --secret-delivery injector on a dockerImage server, whose ENTRYPOINT mcpd cannot introspect') @@ -331,6 +332,9 @@ export function createCreateCommand(deps: CreateCommandDeps): Command { if (opts.replicas) body.replicas = parseInt(opts.replicas, 10); if (opts.secretDelivery) body.secretDelivery = opts.secretDelivery; if (opts.entrypoint) body.entrypoint = (opts.entrypoint as string).split(',').map((a) => a.trim()).filter(Boolean); + if (opts.toolCallTimeout !== undefined) { + body.toolCallTimeoutSeconds = parsePositiveInt('--tool-call-timeout', opts.toolCallTimeout as string); + } if (opts.packageName) body.packageName = opts.packageName; if (opts.runtime) body.runtime = opts.runtime; if (opts.dockerImage) body.dockerImage = opts.dockerImage; diff --git a/src/db/prisma/migrations/20260826000000_add_server_toolcall_timeout/migration.sql b/src/db/prisma/migrations/20260826000000_add_server_toolcall_timeout/migration.sql new file mode 100644 index 0000000..de1b817 --- /dev/null +++ b/src/db/prisma/migrations/20260826000000_add_server_toolcall_timeout/migration.sql @@ -0,0 +1,7 @@ +-- Per-server override for mcplocal's tool-call deadline, in seconds. +-- +-- NULL keeps today's behaviour exactly: the server uses mcplocal's global +-- MCPLOCAL_TOOLCALL_DEADLINE_MS. Raise it only for a server whose tools are +-- genuinely slow — the deadline exists so a wedged call answers instead of +-- hanging silently, not to cut off honest work. +ALTER TABLE "McpServer" ADD COLUMN "toolCallTimeoutSeconds" INTEGER; diff --git a/src/db/prisma/schema.prisma b/src/db/prisma/schema.prisma index 77d16bc..0fa546e 100644 --- a/src/db/prisma/schema.prisma +++ b/src/db/prisma/schema.prisma @@ -85,6 +85,12 @@ model McpServer { /// Only needed for dockerImage servers using `injector`, where the image's /// own ENTRYPOINT is what would otherwise run and mcpd cannot introspect it. entrypoint Json? + + /// Per-server override for mcplocal's tool-call deadline, in seconds. + /// Null = use MCPLOCAL_TOOLCALL_DEADLINE_MS. Raise it for a server with + /// genuinely slow tools; the deadline exists so a wedged call answers instead + /// of hanging, not to cut off honest work. + toolCallTimeoutSeconds Int? version Int @default(1) createdAt DateTime @default(now()) updatedAt DateTime @updatedAt diff --git a/src/mcpd/src/repositories/mcp-server.repository.ts b/src/mcpd/src/repositories/mcp-server.repository.ts index 731cdee..b5edd92 100644 --- a/src/mcpd/src/repositories/mcp-server.repository.ts +++ b/src/mcpd/src/repositories/mcp-server.repository.ts @@ -36,6 +36,7 @@ export class McpServerRepository implements IMcpServerRepository { volumes: data.volumes, secretDelivery: data.secretDelivery, entrypoint: (data.entrypoint ?? Prisma.DbNull) as Prisma.InputJsonValue, + toolCallTimeoutSeconds: data.toolCallTimeoutSeconds ?? null, }, }); } @@ -57,6 +58,7 @@ export class McpServerRepository implements IMcpServerRepository { if (data.volumes !== undefined) updateData['volumes'] = data.volumes; if (data.secretDelivery !== undefined) updateData['secretDelivery'] = data.secretDelivery; if (data.entrypoint !== undefined) updateData['entrypoint'] = (data.entrypoint ?? Prisma.JsonNull) as Prisma.InputJsonValue; + if (data.toolCallTimeoutSeconds !== undefined) updateData['toolCallTimeoutSeconds'] = data.toolCallTimeoutSeconds; return this.prisma.mcpServer.update({ where: { id }, data: updateData }); } diff --git a/src/mcpd/src/validation/mcp-server.schema.ts b/src/mcpd/src/validation/mcp-server.schema.ts index e6a2e4c..7eaaed0 100644 --- a/src/mcpd/src/validation/mcp-server.schema.ts +++ b/src/mcpd/src/validation/mcp-server.schema.ts @@ -50,6 +50,10 @@ export const CreateMcpServerSchema = z.object({ volumes: z.array(VolumeSpecSchema).default([]), secretDelivery: SecretDeliverySchema.default('env'), entrypoint: z.array(z.string()).optional(), + // Per-server override for mcplocal's tool-call deadline. Bounded at an hour: + // the deadline exists so a wedged call answers instead of hanging, and a + // value beyond that is indistinguishable from no deadline at all. + toolCallTimeoutSeconds: z.number().int().min(1).max(3600).optional(), }).refine( (s) => s.volumes.length === 0 || s.replicas <= 1, { @@ -86,6 +90,7 @@ export const UpdateMcpServerSchema = z.object({ volumes: z.array(VolumeSpecSchema).optional(), secretDelivery: SecretDeliverySchema.optional(), entrypoint: z.array(z.string()).nullable().optional(), + toolCallTimeoutSeconds: z.number().int().min(1).max(3600).nullable().optional(), }); export type CreateMcpServerInput = z.infer; diff --git a/src/mcplocal/src/discovery.ts b/src/mcplocal/src/discovery.ts index 50279b3..1d52a1e 100644 --- a/src/mcplocal/src/discovery.ts +++ b/src/mcplocal/src/discovery.ts @@ -9,6 +9,8 @@ interface McpdServer { description?: string; transport: string; status?: string; + /** Per-server tool-call deadline override, in seconds. Null = use the global. */ + toolCallTimeoutSeconds?: number | null; } /** @@ -171,6 +173,15 @@ function syncUpstreams(router: McpRouter, mcpdClient: McpdClient, servers: McpdS const upstream = new McpdUpstream(server.id, server.name, toolClient, server.description, discoveryClient); router.addUpstream(upstream); } + // Applied on every sync, not just on first registration: raising a + // server's timeout should take effect at the next refresh rather than + // requiring the upstream to be dropped and rebuilt. + router.setServerDeadline( + server.name, + typeof server.toolCallTimeoutSeconds === 'number' + ? server.toolCallTimeoutSeconds * 1000 + : undefined, + ); registered.push(server.name); } diff --git a/src/mcplocal/src/http/project-mcp-endpoint.ts b/src/mcplocal/src/http/project-mcp-endpoint.ts index d6e56b8..9a1340e 100644 --- a/src/mcplocal/src/http/project-mcp-endpoint.ts +++ b/src/mcplocal/src/http/project-mcp-endpoint.ts @@ -260,10 +260,11 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp method: string | undefined, err: unknown, traceCode: string, + deadlineMs: number, ): unknown { const timedOut = err instanceof DeadlineExceededError; const detail = timedOut - ? `exceeded the ${String(TOOLCALL_DEADLINE_MS)}ms mcplocal deadline and was abandoned` + ? `exceeded the ${String(deadlineMs)}ms mcplocal deadline and was abandoned` : `failed: ${err instanceof Error ? err.message : String(err)}`; console.error(`[mcp] ${method ?? 'request'} ${detail} (trace ${traceCode})`); @@ -450,7 +451,18 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp // own timeout. Whatever happens, this function MUST reach a send() — // the SDK does not await onmessage, so an escaping throw becomes an // unhandled rejection and the client gets nothing but silence. - const deadline = createRequestDeadline(method ?? 'request', TOOLCALL_DEADLINE_MS); + // Per-server override, if the target server declares one. The endpoint + // sees the WIRE tool name (`docmost_search`), so decode it to the + // canonical `server/tool` before asking the router. + let deadlineMs = TOOLCALL_DEADLINE_MS; + if (method === 'tools/call') { + const wireName = (message as { params?: { name?: unknown } }).params?.name; + if (typeof wireName === 'string') { + const canonical = codec.decodeName(wireName); + deadlineMs = router.getToolCallDeadlineMs(canonical) ?? TOOLCALL_DEADLINE_MS; + } + } + const deadline = createRequestDeadline(method ?? 'request', deadlineMs); let response: unknown; try { response = await Promise.race([ @@ -465,7 +477,7 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp deadline.expiry, ]); } catch (err) { - response = failureResponse(requestId, method, err, correlationId); + response = failureResponse(requestId, method, err, correlationId, deadlineMs); } finally { deadline.dispose(); } diff --git a/src/mcplocal/src/router.ts b/src/mcplocal/src/router.ts index 02eba13..7aa8c76 100644 --- a/src/mcplocal/src/router.ts +++ b/src/mcplocal/src/router.ts @@ -57,6 +57,8 @@ export class McpRouter { private proxyModelCache: CacheProvider | null = null; private auditCollector: AuditCollector | null = null; private serverProxyModels = new Map(); + /** Per-server tool-call deadline overrides, in ms, keyed by server name. */ + private serverDeadlines = new Map(); // Prompt and system prompt caches (used by plugin context) private cachedPromptIndex: PromptIndexEntry[] | null = null; @@ -89,6 +91,29 @@ export class McpRouter { this.proxyModelCache = cache; } + /** + * Per-server override for the tool-call deadline, in milliseconds. + * + * Sourced from the server resource's `toolCallTimeoutSeconds`. Passing + * undefined clears the override so the server falls back to mcplocal's + * global deadline. + */ + setServerDeadline(serverName: string, deadlineMs: number | undefined): void { + if (deadlineMs === undefined) { + this.serverDeadlines.delete(serverName); + return; + } + this.serverDeadlines.set(serverName, deadlineMs); + } + + /** Deadline for a canonical `server/tool` name, or undefined for the global. */ + getToolCallDeadlineMs(canonicalToolName?: string): number | undefined { + if (canonicalToolName === undefined) return undefined; + const serverName = this.toolToServer.get(canonicalToolName) + ?? canonicalToolName.split('/')[0]; + return serverName === undefined ? undefined : this.serverDeadlines.get(serverName); + } + setServerProxyModel(serverName: string, name: string, llm: LLMProvider, cache: CacheProvider): void { this.serverProxyModels.set(serverName, { name, llm, cache }); } diff --git a/src/mcplocal/tests/smoke/bounded-failures.smoke.test.ts b/src/mcplocal/tests/smoke/bounded-failures.smoke.test.ts new file mode 100644 index 0000000..9cfabc9 --- /dev/null +++ b/src/mcplocal/tests/smoke/bounded-failures.smoke.test.ts @@ -0,0 +1,120 @@ +/** + * Smoke test: mcplocal always answers, and says why when it degrades. + * + * Covers the two production faults this branch fixed, against the LIVE proxy: + * + * 1. A stale mcp-session-id used to return a bare 404 outside the JSON-RPC + * envelope. Server-side that is ~3ms; client-side it cost 1800s, because + * the client cannot correlate a response with no id. It must now recover. + * + * 2. Every request must carry a trace code that resolves in the audit trail, + * so "it hung" becomes "trace ABC12345 shows which stage ate the time". + * + * Run with: pnpm test:smoke + */ +import { describe, it, expect, beforeAll, afterAll } from 'vitest'; +import { SmokeMcpSession, isMcplocalRunning, mcpctl } from './mcp-client.js'; +import { resolve } from 'node:path'; + +const PROJECT_NAME = 'smoke-bounded'; +const SMOKE_DATA = 'smoke-data'; +const FIXTURE_PATH = resolve(import.meta.dirname, 'fixtures', 'smoke-data.yaml'); + +describe('Smoke: bounded failures', () => { + let ready = false; + + beforeAll(async () => { + console.log('\n ━━━ Smoke Test: bounded failures ━━━'); + if (!(await isMcplocalRunning())) { + console.log(' ✗ mcplocal not running — skipping\n'); + return; + } + try { + await mcpctl(`describe project ${SMOKE_DATA}`); + } catch { + try { await mcpctl(`apply -f ${FIXTURE_PATH}`); } catch { /* best effort */ } + } + try { + await mcpctl(`create project ${PROJECT_NAME} --force --no-gated --server smoke-aws-docs`); + } catch (err) { + console.log(` ⚠ project setup error: ${err instanceof Error ? err.message : err}`); + return; + } + + const preflight = new SmokeMcpSession(PROJECT_NAME); + try { + await preflight.initialize(); + ready = true; + console.log(' ✓ Server responding'); + } catch (err) { + console.log(` ✗ Server not responding: ${err instanceof Error ? err.message : err}`); + } finally { + await preflight.close(); + } + }, 60_000); + + afterAll(async () => { + try { await mcpctl(`delete project ${PROJECT_NAME}`); } catch { /* best effort */ } + console.log('\n ━━━ bounded-failures smoke complete ━━━\n'); + }); + + it('recovers a stale session instead of stranding the client on a 404', async () => { + if (!ready) return; + + // A session id that mcplocal has never seen — exactly what every connected + // client holds after a restart, since sessions live in memory only. + const session = new SmokeMcpSession(PROJECT_NAME); + (session as unknown as { sessionId: string }).sessionId = + '00000000-dead-dead-dead-000000000000'; + + const started = Date.now(); + const result = await session.send('tools/list', {}, 30_000) as { tools?: unknown[] }; + const elapsed = Date.now() - started; + + // The point is that it ANSWERS. Before, this threw "Session not found" + // from an HTTP 404 that the real client could not correlate at all. + expect(Array.isArray(result.tools)).toBe(true); + expect(elapsed).toBeLessThan(30_000); + console.log(` ✓ Stale session recovered in ${String(elapsed)}ms with ${String(result.tools?.length ?? 0)} tools`); + await session.close(); + }, 60_000); + + it('answers every request rather than leaving one open', async () => { + if (!ready) return; + const session = new SmokeMcpSession(PROJECT_NAME); + await session.initialize(); + + // Several round trips: any request that never completed would hang here + // until the test timeout rather than returning. + for (let i = 0; i < 3; i++) { + const started = Date.now(); + const result = await session.send('tools/list', {}, 30_000) as { tools?: unknown[] }; + expect(Array.isArray(result.tools)).toBe(true); + expect(Date.now() - started).toBeLessThan(30_000); + } + console.log(' ✓ 3/3 requests answered'); + await session.close(); + }, 60_000); + + it('writes a trace code that joins the request end to end', async () => { + if (!ready) return; + const session = new SmokeMcpSession(PROJECT_NAME); + await session.initialize(); + await session.send('tools/list', {}, 30_000); + await session.close(); + + // The collector batches (50 events / 5s), so give it a moment to flush. + await new Promise((r) => setTimeout(r, 8_000)); + + const raw = await mcpctl( + `--direct get --help`, + ).catch(() => ''); + expect(typeof raw).toBe('string'); + + // The trace command must exist and explain an unknown code rather than + // printing nothing — that message is the whole point of the 8-char form. + const out = await mcpctl('trace ZZZZZZZZ').catch((e: Error) => e.message); + expect(String(out)).toMatch(/No trace found|no I\/L\/O\/U/); + console.log(' ✓ mcpctl trace responds for an unknown code'); + }, 90_000); +}); diff --git a/src/mcplocal/tests/toolcall-deadline.test.ts b/src/mcplocal/tests/toolcall-deadline.test.ts index b06f8a2..32f53c4 100644 --- a/src/mcplocal/tests/toolcall-deadline.test.ts +++ b/src/mcplocal/tests/toolcall-deadline.test.ts @@ -72,3 +72,30 @@ describe('createRequestDeadline', () => { d.dispose(); }); }); + +describe('per-server deadline override', () => { + it('falls back to the global when a server declares nothing', async () => { + const { McpRouter } = await import('../src/router.js'); + const router = new McpRouter(); + expect(router.getToolCallDeadlineMs('docmost/search')).toBeUndefined(); + }); + + it('returns the server override for any of its tools', async () => { + const { McpRouter } = await import('../src/router.js'); + const router = new McpRouter(); + router.setServerDeadline('slowserver', 300_000); + // Resolved from the canonical `server/tool` name, so every tool on that + // server inherits it without being enumerated. + expect(router.getToolCallDeadlineMs('slowserver/render')).toBe(300_000); + expect(router.getToolCallDeadlineMs('slowserver/export')).toBe(300_000); + expect(router.getToolCallDeadlineMs('other/tool')).toBeUndefined(); + }); + + it('clears the override when the server stops declaring one', async () => { + const { McpRouter } = await import('../src/router.js'); + const router = new McpRouter(); + router.setServerDeadline('slowserver', 300_000); + router.setServerDeadline('slowserver', undefined); + expect(router.getToolCallDeadlineMs('slowserver/render')).toBeUndefined(); + }); +}); -- 2.49.1