diff --git a/completions/mcpctl.bash b/completions/mcpctl.bash index 0a6994f..dfae59d 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" @@ -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")) @@ -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..00b5c10 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)' @@ -385,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 @@ -678,6 +681,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/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/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/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/cli/src/commands/trace.ts b/src/cli/src/commands/trace.ts new file mode 100644 index 0000000..a3f2a41 --- /dev/null +++ b/src/cli/src/commands/trace.ts @@ -0,0 +1,176 @@ +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++; + + // 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, + 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/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/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/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/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); 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/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 22d239a..9a1340e 100644 --- a/src/mcplocal/src/http/project-mcp-endpoint.ts +++ b/src/mcplocal/src/http/project-mcp-endpoint.ts @@ -28,6 +28,11 @@ 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'; +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; @@ -46,6 +51,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. @@ -215,6 +226,75 @@ 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; + } + + /** + * 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, + deadlineMs: number, + ): unknown { + const timedOut = err instanceof DeadlineExceededError; + const detail = timedOut + ? `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})`); + + 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; @@ -227,10 +307,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; @@ -241,9 +326,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(), @@ -281,7 +368,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. @@ -325,7 +416,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,12 +442,49 @@ 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. + // + // 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. + // 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([ + 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, deadlineMs); + } 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. @@ -382,11 +514,34 @@ export function registerProjectMcpEndpoint(app: FastifyInstance, mcpdClient: Mcp correlationId, }); - requestCorrelations.delete(requestId); - await transport.send(response 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) { @@ -402,6 +557,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/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/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/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 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/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/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/stage-budget.ts b/src/mcplocal/src/proxymodel/stage-budget.ts new file mode 100644 index 0000000..8e648b9 --- /dev/null +++ b/src/mcplocal/src/proxymodel/stage-budget.ts @@ -0,0 +1,50 @@ +/** + * Wall-clock budget for ONE stage invocation's LLM work. + * + * A per-call timeout is not sufficient for a stage that calls the LLM in a + * loop. `summarize-tree` recurses (buildTree calls itself up to maxDepth, 3 by + * default) and loops per section at every level, then `groupSections` loops + * again — so a per-call cap multiplies instead of bounding, and a stage can + * issue hundreds of sequential calls. + * + * The stage shares ONE budget across every call it makes. Once it is gone the + * stage must switch to its deterministic path and report the degradation. + */ +export interface StageBudget { + remainingMs(): number; + exhausted(): boolean; + /** Aborted when the budget runs out; pass into ctx.llm.complete({ signal }). */ + readonly signal: AbortSignal; + /** Total budget, for degradation messages. */ + readonly totalMs: number; + dispose(): void; +} + +export const STAGE_LLM_BUDGET_MS = Number(process.env['MCPCTL_STAGE_LLM_BUDGET_MS'] ?? '30000'); + +export function createStageBudget(totalMs: number = STAGE_LLM_BUDGET_MS): StageBudget { + const controller = new AbortController(); + const startedAt = Date.now(); + const timer = setTimeout(() => { 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 83fbf67..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 { @@ -142,6 +151,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/request-context.ts b/src/mcplocal/src/request-context.ts new file mode 100644 index 0000000..f0e225a --- /dev/null +++ b/src/mcplocal/src/request-context.ts @@ -0,0 +1,44 @@ +/** + * 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'; +import type { RequestDeadline } from './http/deadline.js'; + +export interface RequestScope { + /** The trace code; also the audit correlationId. */ + correlationId: string; + 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(); + +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..7aa8c76 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, 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'; @@ -56,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; @@ -88,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 }); } @@ -175,11 +201,19 @@ 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 + // 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, @@ -187,6 +221,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 }; } @@ -868,6 +904,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 +942,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/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/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/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/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/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/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/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']); }); }); 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/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/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']); + }); +}); 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); + }); +}); 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/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, }; } 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..32f53c4 --- /dev/null +++ b/src/mcplocal/tests/toolcall-deadline.test.ts @@ -0,0 +1,101 @@ +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(); + }); +}); + +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(); + }); +}); 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); + }); +});