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); + }); +});