fix(mcplocal): bounded, legible MCP failures — no request can hang forever #127

Merged
michal merged 9 commits from fix/bounded-mcp-failures into main 2026-08-25 23:03:51 +00:00
9 changed files with 441 additions and 15 deletions
Showing only changes of commit 2c90f5971d - Show all commits

View File

@@ -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`,
);
}
}

View File

@@ -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);

View File

@@ -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;
}
/**

View File

@@ -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<T> =
| { 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 <x>`.
* 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<T>(
run: (signal: AbortSignal) => Promise<T>,
options: BoundedOptions,
): Promise<BoundedResult<T>> {
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:
* `⚠ <feature> unavailable (<reason>). <hint>`
*
* 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<unknown>,
): { degraded: boolean; degradedReason: string | null } {
return result.degraded
? { degraded: true, degradedReason: result.reason }
: { degraded: false, degradedReason: null };
}

View File

@@ -38,3 +38,26 @@ export async function withTimeout<T>(
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;
}

View File

@@ -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>(() => { /* 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<never>((_, 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' });
});
});

View File

@@ -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<CompletionResult>((_, 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<CompletionResult>(() => { /* 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<CompletionResult>((_, 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();
});
});

View File

@@ -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),
});
});

View File

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