diff --git a/clients/cli/README.md b/clients/cli/README.md index 807b9881e..3c51324ed 100644 --- a/clients/cli/README.md +++ b/clients/cli/README.md @@ -162,7 +162,7 @@ Options that specify the MCP server (catalog/config file, ad-hoc command/URL, en | `--load-requests ` | With `--load`: stop after starting this many calls. With `--load-duration` too, whichever is reached first ends the run. | | `--load-rate ` | With `--load`: start at most this many calls per second across all workers, spaced evenly (default: unlimited). | | `--load-max-error-rate ` | With `--load`: after printing the summary, exit `10` (`load_error_rate_exceeded`) when the share of failed calls is above this value. `0` to `1`; `0` fails on any failed call. See [Thresholds for CI](#thresholds-for-ci). | -| `--load-max-p99 ` | With `--load`: after printing the summary, exit `10` (`load_p99_exceeded`) when the p99 latency is above this many milliseconds, or when no call completed. Positive number. | +| `--load-max-p99 ` | With `--load`: after printing the summary, exit `10` (`load_p99_exceeded`) when the p99 latency of the successful calls is above this many milliseconds, or when no call succeeded. Positive number. | | `--relogin` | Delete stored OAuth for this server URL from the shared store before connect; interactive login still only runs if the server requires auth. Requires an HTTP/SSE URL (rejected for stdio). Conflicts with `--stored-auth-only` / `--use-stored-auth` / `--wait-for-auth` / catalog short-circuits. | | `--no-revoke` | With `--relogin`, skip the [RFC 7009](https://datatracker.ietf.org/doc/html/rfc7009) revocation request that would otherwise end the grant at the authorization server when the local state is deleted. The per-server `oauth.revokeOnClear` setting is the persistent form of the same opt-out; either one is enough to skip it. See [Revoking on `--relogin`](#revoking-on---relogin). | | `--stored-auth-only` | **CI / non-interactive safe:** never start interactive OAuth / step-up (and never auto-open a browser); use the shared store if present, otherwise fail immediately with `auth_required`. Prefer this over a bare pipe/CI run that would otherwise attempt interactive login. | @@ -331,8 +331,11 @@ is printed on stdout (wrapped in `{ "result": … }` with `--format json`): "errorRate": 0.0006, "elapsedMs": 30012.4, "throughput": 1373.12, - "latencyMs": { "min": 2.1, "mean": 14.5, "p50": 12.9, "p90": 22.4, "p99": 61.3, "max": 30004.8 }, - "errorMessages": [{ "message": "Request timed out", "count": 23 }] + "okThroughput": 1372.35, + "latencyMs": { "min": 2.1, "mean": 14.5, "p50": 12.9, "p90": 22.4, "p99": 61.3, "max": 212.8 }, + "errorLatencyMs": { "min": 30001.2, "mean": 30003.1, "p50": 30002.9, "p90": 30004.1, "p99": 30004.8, "max": 30004.8 }, + "errorMessages": [{ "message": "Request timed out", "count": 23 }], + "toolErrorMessages": [] } ``` @@ -342,12 +345,25 @@ is printed on stdout (wrapped in `{ "result": … }` with `--format json`): together over `requests`, rounded to four places. - **`errorMessages`** groups the thrown messages by frequency. The first ten distinct messages are kept; any further ones are counted under `(other)`. + **`toolErrorMessages`** does the same for the `isError` results, using the + first text block of each, trimmed and cut to 200 characters (`(no text + content)` when a result has none), so a run that is all `rate limited` + says so ([#2836](https://github.com/modelcontextprotocol/inspector/issues/2836)). - **Latency** is per call, client-side, in milliseconds, with nearest-rank - percentiles. It includes everything the Inspector does around the request, - which is negligible next to a network round trip but not next to a + percentiles. **`latencyMs` covers the successful (`ok`) calls only**, and + **`errorLatencyMs`** the failed ones (tool errors and thrown alike), so a + failure that comes back instantly never makes a struggling server look + faster; either is `null` when it has no calls. `throughput` counts every + completed call per second, **`okThroughput`** only the successful ones. + Latency includes everything the Inspector does around the request, which + is negligible next to a network round trip but not next to a sub-millisecond stdio echo. - **Bounds.** `--load-duration` stops *starting* calls; anything in flight is allowed to finish, so `elapsedMs` can exceed the window by up to one call. + A run that reaches its `--load-duration` is measured to the end of that + window at least, so a `--load-rate 1` run over five seconds reports a + throughput of 1/s rather than the 1.25/s its last start would suggest + ([#2837](https://github.com/modelcontextprotocol/inspector/issues/2837)). With `--load-rate`, starts follow an even `1/rate` grid; a timer that wakes a little late keeps the grid, so the average rate holds. A slot missed entirely — every worker busy, or a stalled event loop — is dropped rather @@ -355,7 +371,42 @@ is printed on stdout (wrapped in `{ "result": … }` with `--format json`): slot that falls past the window is never started. Node's timers resolve to about a millisecond, so a rate in the high hundreds per second or above is reached only approximately (1000/s measured ~700 against a local stdio - server); compare `requests` against what you asked for. + server). +- **`plannedStarts`, `droppedSlots`, `achievedRate`** appear only with + `--load-rate` ([#2837](https://github.com/modelcontextprotocol/inspector/issues/2837)). + `plannedStarts` is what the `1/rate` grid called for over the window the run + was starting calls in (the whole `--load-duration` for a run that reached + it, or up to the last start of a run that `--load-requests` ended); + `droppedSlots` is how many of those were + never started because every worker was busy; `achievedRate` is the calls + started per second over that window. Dropping slots keeps a stall from + turning into a burst, but it also makes the run closed-loop: a server too + slow for the target rate reports healthy latency while most of the planned + load never ran. So when fewer than 90% of `plannedStarts` were started, a + warning naming the shortfall is printed on stderr after the summary + (dropped by `--quiet`). Raise `--load-concurrency` or lower the rate. +- **The run stops early when the server is clearly gone** + ([#2835](https://github.com/modelcontextprotocol/inspector/issues/2835)). + A refused connection fails each call in microseconds, so a server that dies + mid-run would otherwise turn the rest of the window into thousands of + instant failures. Once 50 calls in a row have thrown — or calls have done + nothing but throw for a second, at least 5 of them — no further call + starts. Only thrown calls count; a tool error is the server answering, and + any other outcome resets the streak. The summary covers what completed and + carries **`stoppedEarly`**: `{ "reason": "consecutive_errors", "detail": + "…" }`, with a warning on stderr. The exit code is unchanged — `0` unless a + threshold is breached. +- **Ctrl+C or SIGTERM ends the run, not the summary** + ([#2834](https://github.com/modelcontextprotocol/inspector/issues/2834)). + The first signal stops new calls from starting and lets the in-flight ones + finish; the summary of what completed is then printed with + `"stoppedEarly": { "reason": "interrupted", "detail": "received SIGINT" }`, + and the CLI exits `130` (`interrupted`) without checking any threshold. A + second Ctrl+C exits `130` immediately, for in-flight calls that will not + settle. A repeat of the same signal within half a second of the first is + taken as a re-raise rather than a second press — a dependency of the CLI + (`when-exit`) re-sends the signal to the process after its own cleanup — so + the press that exits at once is one made after that. - **`connections`** appears only with `--load-connections` above `1` (see below), so a default run's summary is unchanged. @@ -411,7 +462,10 @@ the run with exit `5` (`tool_not_found`) instead of reporting a 100% error rate. Otherwise a completed run exits `0` whatever its error rate — the summary is the result — unless a threshold below is set. `--load` is rejected with any other method and with `--app-info`, `--output`, `--output-format`, `--list-stored-auth` and `--print-handoff`, and each `--load-*` flag is -rejected without `--load`. +rejected without `--load`. Each of those refusals — and `--load-connections` +above `--load-concurrency`, or above `1` over stdio — exits `1` with the +envelope `code` `load_flag_conflict`, the code `mcpdo` uses for the same +mistakes. ##### Thresholds for CI @@ -434,8 +488,10 @@ mcp-inspector --cli --method tools/call --tool-name search \ share of failed calls (`toolErrors` plus `errors`, over `requests`), not the four-place `errorRate`, so `--load-max-error-rate 0` fails even one failure that rounds away in the summary. -- With `--load-max-p99`, a run in which no call completed has no p99 to - compare, and fails rather than passing a latency check it never measured. +- `--load-max-p99` judges the **successful** calls (`latencyMs`), so a run + in which half the calls fail instantly cannot pass on the strength of its + failures. A run in which no call succeeded has no p99 to compare, and fails + rather than passing a latency check it never measured. - With no threshold set, nothing changes: a completed run exits `0`. #### Schema portability (`--strict`) @@ -720,6 +776,7 @@ prose from stderr: | `9` | `--verify --require-digests` found a skill that advertised no digests (`skills_unverifiable` — `resources: "dynamic"`). Only produced under `--require-digests`; without it such a skill is reported `unverifiable` and the run exits `0`. | | `10` | A `--load` run breached a threshold (`load_error_rate_exceeded` for `--load-max-error-rate`, `load_p99_exceeded` for `--load-max-p99`). The summary is still printed on stdout first. See [Thresholds for CI](#thresholds-for-ci). | | `11` | The server rate limited the request (`rate_limited` — HTTP 429). The envelope carries the server's retry timing; see below. | +| `130` | A `--load` run was interrupted by Ctrl+C or SIGTERM (`interrupted`). The partial summary is printed on stdout first. See [Load testing a tool](#load-testing-a-tool---load). | On any non-zero exit the CLI also writes a single JSON line to **stderr** — the `ErrorEnvelope`: diff --git a/clients/cli/__tests__/helpers/load-clock.ts b/clients/cli/__tests__/helpers/load-clock.ts new file mode 100644 index 000000000..633bed698 --- /dev/null +++ b/clients/cli/__tests__/helpers/load-clock.ts @@ -0,0 +1,50 @@ +import type { LoadClock } from "@inspector/core/cli/handlers/load-test.js"; + +/** + * A clock that only moves when told to, with a timer queue: each `sleep` + * wakes at an absolute time, and timers fire one at a time in wake order, + * each on its own macrotask so the woken worker runs (up to its next await) + * before the clock moves again — as real timers behave. A rate-limited run + * therefore completes instantly while keeping the schedule it would in real + * time. + */ +export function fakeClock( + options: { lateUntil?: number; jitter?: number } = {}, +): LoadClock & { advance: (ms: number) => void; sleeps: () => number } { + let t = 1000; + // A stalled event loop: no timer fires before this many ms into the run. + const earliestWake = 1000 + (options.lateUntil ?? 0); + const timers: { wakeAt: number; resolve: () => void }[] = []; + let pumping = false; + let sleepCount = 0; + const pump = (): void => { + timers.sort((a, b) => a.wakeAt - b.wakeAt); + const next = timers.shift(); + if (!next) { + pumping = false; + return; + } + t = Math.max(t, next.wakeAt); + next.resolve(); + setImmediate(pump); + }; + return { + now: () => t, + sleep: (ms) => + new Promise((resolve) => { + sleepCount++; + timers.push({ + wakeAt: Math.max(t + ms + (options.jitter ?? 0), earliestWake), + resolve, + }); + if (!pumping) { + pumping = true; + setImmediate(pump); + } + }), + advance: (ms) => { + t += ms; + }, + sleeps: () => sleepCount, + }; +} diff --git a/clients/cli/__tests__/load-interrupt-e2e.test.ts b/clients/cli/__tests__/load-interrupt-e2e.test.ts new file mode 100644 index 000000000..afca26c23 --- /dev/null +++ b/clients/cli/__tests__/load-interrupt-e2e.test.ts @@ -0,0 +1,173 @@ +import { describe, it, expect, beforeEach, afterEach } from "vitest"; +import { spawn, type ChildProcess } from "node:child_process"; +import { resolve, dirname } from "node:path"; +import { fileURLToPath } from "node:url"; +import { + createTestServerHttp, + createTestServerInfo, +} from "@modelcontextprotocol/inspector-test-server"; +import { EXIT_CODES } from "@inspector/core/cli/error-handler.js"; +import { REPEAT_GRACE_MS } from "../src/handlers/load-interrupt.js"; + +const here = dirname(fileURLToPath(import.meta.url)); +const BIN = resolve(here, "../build/index.js"); + +/** + * Ctrl+C / SIGTERM delivered as a REAL signal to the BUILT CLI (#2834). + * + * The in-process suite (`load-summary.test.ts`) calls the CLI's own listener + * directly, which is exactly what let the first fix ship broken: `when-exit` + * (via `atomically`) also listens, and re-raises the signal with + * `process.kill(process.pid, …)` after its cleanups. That copy only exists + * when the kernel delivers a signal to a real process carrying the real + * dependency graph, so only a spawned binary can see it. + * + * Budgets: the child is killed after `CHILD_TIMEOUT_MS`, inside the test's own + * `E2E_SPAWN_MS`, so a hang names the CLI rather than timing out the test + * generically (the same arrangement as `e2e.test.ts`, #2323). + */ +const CHILD_TIMEOUT_MS = 15_000; +const E2E_SPAWN_MS = 25_000; + +type Run = { + child: ChildProcess; + done: Promise<{ code: number | null; stdout: string; stderr: string }>; + stderr: () => string; +}; + +function spawnLoad(url: string, tool: string): Run { + const child = spawn( + "node", + [ + BIN, + url, + "--transport", + "http", + "--method", + "tools/call", + "--tool-name", + tool, + "--load", + "--load-duration", + "60", + "--load-concurrency", + "2", + "--format", + "json", + ], + { stdio: ["ignore", "pipe", "pipe"] }, + ); + let stdout = ""; + let stderr = ""; + child.stdout!.on("data", (d) => (stdout += d.toString())); + child.stderr!.on("data", (d) => (stderr += d.toString())); + const done = new Promise<{ + code: number | null; + stdout: string; + stderr: string; + }>((resolveDone, reject) => { + const timer = setTimeout(() => { + child.kill("SIGKILL"); + reject(new Error(`built CLI did not exit within ${CHILD_TIMEOUT_MS}ms`)); + }, CHILD_TIMEOUT_MS); + child.on("error", (err) => { + clearTimeout(timer); + reject(err); + }); + child.on("close", (code) => { + clearTimeout(timer); + resolveDone({ code, stdout, stderr }); + }); + }); + return { child, done, stderr: () => stderr }; +} + +/** Resolve once `check` holds, polling every 50ms. */ +async function until(check: () => boolean): Promise { + while (!check()) await new Promise((r) => setTimeout(r, 50)); +} + +describe("--load under a real signal (built CLI)", () => { + let calls = 0; + let release: (() => void)[] = []; + const makeServer = () => + createTestServerHttp({ + serverInfo: createTestServerInfo("load-signal", "1.0.0"), + tools: [ + { + name: "slow", + description: "Answers after 50ms", + inputSchema: {}, + handler: async () => { + calls++; + await new Promise((r) => setTimeout(r, 50)); + return { content: [{ type: "text", text: "ok" }] }; + }, + }, + { + name: "hang", + description: "Answers only when the test lets it", + inputSchema: {}, + handler: async () => { + calls++; + await new Promise((r) => release.push(r)); + return { content: [{ type: "text", text: "late" }] }; + }, + }, + ], + }); + + let server: ReturnType; + + beforeEach(async () => { + calls = 0; + release = []; + server = makeServer(); + await server.start(); + }); + + afterEach(async () => { + for (const r of release) r(); + await server.stop(); + }); + + it.each(["SIGINT", "SIGTERM"] as const)( + "prints the partial summary and exits 130 on one %s", + async (signal) => { + const run = spawnLoad(server.url, "slow"); + await until(() => calls >= 10); + run.child.kill(signal); + const { code, stdout, stderr } = await run.done; + expect(code).toBe(EXIT_CODES.INTERRUPTED); + const { result } = JSON.parse(stdout.trim().split("\n")[0]!); + expect(result.stoppedEarly).toEqual({ + reason: "interrupted", + detail: `received ${signal}`, + }); + expect(result.ok).toBeGreaterThan(0); + expect(stderr).toContain(`Interrupted (${signal})`); + expect(JSON.parse(stderr.trim().split("\n").pop()!).error.code).toBe( + "interrupted", + ); + }, + E2E_SPAWN_MS, + ); + + it( + "exits 130 at once on a second Ctrl+C while calls will not settle", + async () => { + const run = spawnLoad(server.url, "hang"); + await until(() => calls >= 2); + run.child.kill("SIGINT"); + await until(() => run.stderr().includes("Interrupted (SIGINT)")); + // A person's second press, past the window that absorbs a re-raise. + await new Promise((r) => setTimeout(r, REPEAT_GRACE_MS + 200)); + run.child.kill("SIGINT"); + const { code, stdout } = await run.done; + expect(code).toBe(EXIT_CODES.INTERRUPTED); + // The in-flight calls never settled, so there was no summary to print. + expect(stdout).toBe(""); + }, + E2E_SPAWN_MS, + ); +}); diff --git a/clients/cli/__tests__/load-summary.test.ts b/clients/cli/__tests__/load-summary.test.ts new file mode 100644 index 000000000..c19367d69 --- /dev/null +++ b/clients/cli/__tests__/load-summary.test.ts @@ -0,0 +1,900 @@ +import { describe, it, expect, vi, afterEach } from "vitest"; +import { runCli } from "./helpers/cli-runner.js"; +import { expectCliSuccess, expectValidJson } from "./helpers/assertions.js"; +import { fakeClock } from "./helpers/load-clock.js"; +import { + createTestServerHttp, + createTestServerInfo, + getTestMcpServerCommand, +} from "@modelcontextprotocol/inspector-test-server"; +import { + CIRCUIT_BREAKER_ERRORS, + CIRCUIT_BREAKER_MIN_ERRORS, + LOAD_FLAG_CONFLICT, + MAX_TOOL_ERROR_MESSAGE_LENGTH, + NO_TOOL_ERROR_TEXT, + loadRateShortfallWarning, + loadSummaryWarnings, + runLoad, + toolErrorText, + type LoadCallOutcome, + type LoadClock, + type LoadStop, + type LoadSummary, +} from "@inspector/core/cli/handlers/load-test.js"; +import { + CliExitCodeError, + EXIT_CODES, +} from "@inspector/core/cli/error-handler.js"; +import { + REPEAT_GRACE_MS, + assertNotInterrupted, + withLoadInterrupt, +} from "../src/handlers/load-interrupt.js"; + +/** + * The `--load` summary fixes of the v2.14.0 milestone: Ctrl+C keeps the + * partial summary (#2834), a circuit breaker for a dead server (#2835), + * success-only latency and tool-error messages (#2836), and the planned + * versus achieved figures of a `--load-rate` run (#2837). + */ + +/** + * Deliver a signal to the listener `withLoadInterrupt` added, and to nothing + * else: `process.emit` would also reach the test worker's own SIGINT/SIGTERM + * handlers, which end the worker. Returns false while no new listener exists. + */ +function signalLoadRun( + signal: "SIGINT" | "SIGTERM", + existing: NodeJS.SignalsListener[], +): boolean { + const added = process + .listeners(signal) + .find((listener) => !existing.includes(listener)); + if (!added) return false; + (added as (s: NodeJS.Signals) => void)(signal); + return true; +} + +describe("success and failure latency (#2836)", () => { + it("times successes apart from failures and counts ok throughput", async () => { + const clock = fakeClock(); + let n = 0; + // Every second call fails instantly; the successes take 200ms. + const call = async (): Promise => { + if (n++ % 2 === 1) return "tool_error"; + clock.advance(200); + return "ok"; + }; + const summary = await runLoad( + call, + { concurrency: 1, requests: 10 }, + clock, + ); + expect(summary).toMatchObject({ + ok: 5, + toolErrors: 5, + elapsedMs: 1000, + throughput: 10, + okThroughput: 5, + latencyMs: { min: 200, p50: 200, p99: 200 }, + errorLatencyMs: { min: 0, max: 0 }, + }); + }); + + it("reports no success latency when nothing succeeded", async () => { + const summary = await runLoad( + async () => "tool_error", + { concurrency: 1, requests: 3 }, + fakeClock(), + ); + expect(summary.latencyMs).toBeNull(); + expect(summary.errorLatencyMs).not.toBeNull(); + expect(summary.okThroughput).toBe(0); + }); + + it("tallies tool-error messages apart from thrown ones", async () => { + let n = 0; + const call = async (): Promise => { + const i = n++; + if (i < 3) return { outcome: "tool_error", message: "rate limited" }; + if (i === 3) return "tool_error"; + throw new Error("boom"); + }; + const summary = await runLoad( + call, + { concurrency: 1, requests: 5 }, + fakeClock(), + ); + expect(summary.toolErrorMessages).toEqual([ + { message: "rate limited", count: 3 }, + { message: NO_TOOL_ERROR_TEXT, count: 1 }, + ]); + expect(summary.errorMessages).toEqual([{ message: "boom", count: 1 }]); + }); + + describe("toolErrorText", () => { + it("takes the first non-empty text block, trimmed", () => { + expect( + toolErrorText([ + { type: "image", data: "", mimeType: "image/png" }, + null, + { type: "text", text: " " }, + { type: "text", text: " rate limited \n" }, + { type: "text", text: "second" }, + ]), + ).toBe("rate limited"); + }); + + it("caps a long text", () => { + const text = toolErrorText([{ type: "text", text: "x".repeat(500) }]); + expect(text).toBe(`${"x".repeat(MAX_TOOL_ERROR_MESSAGE_LENGTH)}…`); + }); + + it("falls back when there is no text to report", () => { + expect(toolErrorText([])).toBe(NO_TOOL_ERROR_TEXT); + expect(toolErrorText(undefined)).toBe(NO_TOOL_ERROR_TEXT); + expect(toolErrorText([{ type: "text", text: 7 }])).toBe( + NO_TOOL_ERROR_TEXT, + ); + }); + }); +}); + +describe("circuit breaker (#2835)", () => { + it(`stops after ${CIRCUIT_BREAKER_ERRORS} thrown calls in a row`, async () => { + const summary = await runLoad( + async () => { + throw new Error("fetch failed"); + }, + { concurrency: 1, requests: 1000 }, + fakeClock(), + ); + expect(summary.requests).toBe(CIRCUIT_BREAKER_ERRORS); + expect(summary.stoppedEarly).toEqual({ + reason: "consecutive_errors", + detail: `${CIRCUIT_BREAKER_ERRORS} calls in a row threw over 0ms; the server looks unavailable`, + }); + expect(summary.errorMessages).toEqual([ + { message: "fetch failed", count: CIRCUIT_BREAKER_ERRORS }, + ]); + }); + + it("stops a slow run after a second of nothing but thrown calls", async () => { + const clock = fakeClock(); + const summary = await runLoad( + async () => { + clock.advance(250); + throw new Error("timed out"); + }, + { concurrency: 1, durationMs: 60_000 }, + clock, + ); + // The first failure lands at 250ms; the fifth, at 1250ms, closes a 1s + // streak. + expect(summary.requests).toBe(CIRCUIT_BREAKER_MIN_ERRORS); + expect(summary.stoppedEarly?.reason).toBe("consecutive_errors"); + // Not measured to the end of a window it never ran to. + expect(summary.elapsedMs).toBe(1250); + }); + + it("does not call draining in-flight failures an early stop", async () => { + const clock = fakeClock(); + let release!: () => void; + const allStarted = new Promise((r) => (release = r)); + let starts = 0; + // All five calls start at once, then fail 300ms apart, well past the + // breaker's one-second window — but no further call could start anyway. + const summary = await runLoad( + async () => { + if (++starts === 5) release(); + await allStarted; + clock.advance(300); + throw new Error("timed out"); + }, + { concurrency: 5, requests: 5 }, + clock, + ); + expect(summary.errors).toBe(5); + expect(summary.stoppedEarly).toBeUndefined(); + }); + + it("lets an interrupt override a breaker stop while calls drain", async () => { + const abort = new AbortController(); + let releaseSlow!: () => void; + const slow = new Promise((r) => (releaseSlow = r)); + let thrown = 0; + const call = async (worker: number): Promise => { + if (worker === 0) { + await slow; + return "ok"; + } + if (++thrown === CIRCUIT_BREAKER_ERRORS) { + // The breaker has tripped; Ctrl+C arrives while worker 0 drains. + setImmediate(() => { + abort.abort(); + releaseSlow(); + }); + } + throw new Error("fetch failed"); + }; + const summary = await runLoad( + call, + { concurrency: 2, requests: 1000 }, + fakeClock(), + abort.signal, + ); + expect(summary.stoppedEarly?.reason).toBe("interrupted"); + }); + + it("resets on any answer from the server, tool errors included", async () => { + let n = 0; + const call = async (): Promise => { + if (n++ % CIRCUIT_BREAKER_ERRORS === 0) return "tool_error"; + throw new Error("flaky"); + }; + const summary = await runLoad( + call, + { concurrency: 1, requests: 500 }, + fakeClock(), + ); + expect(summary.requests).toBe(500); + expect(summary.stoppedEarly).toBeUndefined(); + }); +}); + +describe("early stops (#2834)", () => { + it("reports an abort as interrupted by default", async () => { + const abort = new AbortController(); + let calls = 0; + const summary = await runLoad( + async () => { + if (++calls === 2) abort.abort(); + return "ok"; + }, + { concurrency: 1, requests: 10 }, + fakeClock(), + abort.signal, + ); + expect(summary.requests).toBe(2); + expect(summary.stoppedEarly).toEqual({ + reason: "interrupted", + detail: "the run was interrupted", + }); + }); + + it("keeps the reason the caller aborted with", async () => { + const stop: LoadStop = { + reason: "connection_lost", + detail: "the connection went error", + }; + const summary = await runLoad( + async () => "ok", + { concurrency: 1, requests: 10 }, + fakeClock(), + AbortSignal.abort(stop), + ); + expect(summary.stoppedEarly).toEqual(stop); + }); + + it.each([ + [{ reason: "bogus", detail: "x" }], + [{ reason: "interrupted" }], + ["a string"], + [null], + ])("does not trust a malformed reason %j", async (reason) => { + const summary = await runLoad( + async () => "ok", + { concurrency: 1, requests: 1 }, + fakeClock(), + AbortSignal.abort(reason), + ); + expect(summary.stoppedEarly?.reason).toBe("interrupted"); + }); +}); + +describe("planned and achieved rate (#2837)", () => { + it("reports the planned starts a saturated run dropped", async () => { + const clock = fakeClock(); + // Capacity is 10/s (one worker, 100ms calls) against a 100/s target. + const summary = await runLoad( + async () => { + clock.advance(100); + return "ok"; + }, + { concurrency: 1, durationMs: 1000, rate: 100 }, + clock, + ); + expect(summary).toMatchObject({ + rate: 100, + requests: 10, + plannedStarts: 100, + droppedSlots: 90, + achievedRate: 10, + }); + expect(loadRateShortfallWarning(summary)).toBe( + "Warning: --load-rate 100/s was not reached: 10 of 100 planned calls started (10/s); 90 slots were dropped because every worker was busy. Raise --load-concurrency or lower --load-rate.", + ); + }); + + it("measures a duration-bound run to the end of its window", async () => { + const summary = await runLoad( + async () => "ok", + { concurrency: 1, durationMs: 5000, rate: 1 }, + fakeClock(), + ); + expect(summary).toMatchObject({ + requests: 5, + elapsedMs: 5000, + throughput: 1, + plannedStarts: 5, + droppedSlots: 0, + achievedRate: 1, + }); + expect(loadRateShortfallWarning(summary)).toBeUndefined(); + }); + + it("plans a request-bound run up to its last start", async () => { + const summary = await runLoad( + async () => "ok", + { concurrency: 1, requests: 3, durationMs: 10_000, rate: 4 }, + fakeClock(), + ); + // Starts at 0, 250 and 500ms cover the grid to 750ms: exactly 4/s. + expect(summary).toMatchObject({ + plannedStarts: 3, + droppedSlots: 0, + achievedRate: 4, + }); + }); + + it("counts the slots a saturated request-bound run missed", async () => { + const clock = fakeClock(); + const summary = await runLoad( + async () => { + clock.advance(500); + return "ok"; + }, + { concurrency: 1, requests: 3, rate: 10 }, + clock, + ); + // Starts at 0, 500 and 1000ms: the grid to 1100ms held 11 slots. + expect(summary).toMatchObject({ + requests: 3, + plannedStarts: 11, + droppedSlots: 8, + }); + expect(loadRateShortfallWarning(summary)).toContain("3 of 11 planned"); + }); + + it("does not count a slightly late final timer as a dropped slot", async () => { + const summary = await runLoad( + async () => "ok", + { concurrency: 1, requests: 3, rate: 10 }, + fakeClock({ jitter: 0.1 }), + ); + // Starts at 0, 100.1 and 200.1ms keep the grid; the window ends at 300. + expect(summary).toMatchObject({ plannedStarts: 3, droppedSlots: 0 }); + expect(loadRateShortfallWarning(summary)).toBeUndefined(); + }); + + it("ends the window at the request bound when an interrupt lands later", async () => { + const clock = fakeClock(); + const abort = new AbortController(); + const summary = await runLoad( + async () => { + clock.advance(5000); + abort.abort(); + return "ok"; + }, + { concurrency: 1, requests: 1, rate: 1 }, + clock, + abort.signal, + ); + expect(summary.stoppedEarly?.reason).toBe("interrupted"); + expect(summary).toMatchObject({ plannedStarts: 1, droppedSlots: 0 }); + }); + + it("ends the window at the deadline when an interrupt lands later", async () => { + const clock = fakeClock(); + const abort = new AbortController(); + let calls = 0; + const summary = await runLoad( + async () => { + // The tenth call, started at 900ms, outlives the 1s window. + if (++calls === 10) { + clock.advance(4000); + abort.abort(); + } + return "ok"; + }, + { concurrency: 1, durationMs: 1000, rate: 10 }, + clock, + abort.signal, + ); + expect(summary.stoppedEarly?.reason).toBe("interrupted"); + expect(summary).toMatchObject({ plannedStarts: 10, droppedSlots: 0 }); + }); + + it("does not count a slot claimed after the run stopped as started", async () => { + // A clock that moves 1ms per read, so at 1000/s every claim finds its + // slot already due and never waits on a timer. + let t = 0; + const clock: LoadClock = { now: () => (t += 1), sleep: async () => {} }; + const abort = new AbortController(); + let calls = 0; + const summary = await runLoad( + async () => { + calls++; + // Worker 1 has claimed its slot by now; this abort lands before it + // resumes, so its call never runs. + abort.abort(); + return "ok"; + }, + { concurrency: 2, requests: 10, rate: 1000 }, + clock, + abort.signal, + ); + expect(calls).toBe(1); + expect(summary.plannedStarts! - summary.droppedSlots!).toBe(1); + }); + + it("does not warn on a fractional rate it held", async () => { + const summary = await runLoad( + async () => "ok", + { concurrency: 1, durationMs: 70_000, rate: 0.014 }, + fakeClock(), + ); + expect(summary).toMatchObject({ plannedStarts: 1, droppedSlots: 0 }); + expect(loadRateShortfallWarning(summary)).toBeUndefined(); + }); + + it("plans an interrupted run up to the moment it stopped", async () => { + const clock = fakeClock(); + const abort = new AbortController(); + let calls = 0; + const summary = await runLoad( + async () => { + if (++calls === 3) { + clock.advance(250); + abort.abort(); + } + return "ok"; + }, + { concurrency: 1, durationMs: 10_000, rate: 10 }, + clock, + abort.signal, + ); + // Stopped at 450ms: five slots were due, three were started. + expect(summary).toMatchObject({ + requests: 3, + plannedStarts: 5, + droppedSlots: 2, + }); + }); + + it("reports no achieved rate for a window of zero", async () => { + const summary = await runLoad( + async () => "ok", + { concurrency: 1, durationMs: 0, rate: 10 }, + fakeClock(), + ); + expect(summary).toMatchObject({ + requests: 0, + plannedStarts: 0, + droppedSlots: 0, + achievedRate: 0, + }); + expect(loadRateShortfallWarning(summary)).toBeUndefined(); + }); + + it("leaves the rate figures out of a run with no rate", async () => { + const summary = await runLoad( + async () => "ok", + { concurrency: 1, requests: 2 }, + fakeClock(), + ); + expect(summary).not.toHaveProperty("plannedStarts"); + expect(summary).not.toHaveProperty("droppedSlots"); + expect(summary).not.toHaveProperty("achievedRate"); + expect(loadRateShortfallWarning(summary)).toBeUndefined(); + }); +}); + +describe("loadSummaryWarnings", () => { + const base: LoadSummary = { + concurrency: 1, + requests: 1, + ok: 1, + toolErrors: 0, + errors: 0, + errorRate: 0, + elapsedMs: 1, + throughput: 1, + okThroughput: 1, + latencyMs: null, + errorLatencyMs: null, + errorMessages: [], + toolErrorMessages: [], + }; + + it("is empty for a run that held its bounds", () => { + expect(loadSummaryWarnings(base)).toEqual([]); + }); + + it("names an early stop the caller did not ask for, but not an interrupt", () => { + expect( + loadSummaryWarnings({ + ...base, + stoppedEarly: { reason: "consecutive_errors", detail: "50 in a row" }, + }), + ).toEqual([ + "Warning: the load run stopped early (consecutive_errors): 50 in a row.", + ]); + expect( + loadSummaryWarnings({ + ...base, + stoppedEarly: { reason: "interrupted", detail: "received SIGINT" }, + }), + ).toEqual([]); + }); + + it("adds the rate shortfall", () => { + const warnings = loadSummaryWarnings({ + ...base, + rate: 10, + plannedStarts: 10, + droppedSlots: 5, + achievedRate: 5, + }); + expect(warnings).toHaveLength(1); + expect(warnings[0]).toContain("--load-rate 10/s was not reached"); + }); +}); + +describe("withLoadInterrupt (#2834)", () => { + afterEach(() => { + vi.restoreAllMocks(); + }); + + /** Run until aborted, then settle with the abort's reason. */ + function untilAborted(signal: AbortSignal): Promise { + return new Promise((resolve) => + signal.addEventListener("abort", () => resolve(signal.reason)), + ); + } + + it("turns the first signal into an abort and says so on stderr", async () => { + const stderr = vi + .spyOn(process.stderr, "write") + .mockImplementation(() => true); + const existing = process.listeners("SIGTERM"); + const before = existing.length; + const run = withLoadInterrupt(untilAborted); + expect(process.listenerCount("SIGTERM")).toBe(before + 1); + expect(signalLoadRun("SIGTERM", existing)).toBe(true); + await expect(run).resolves.toEqual({ + reason: "interrupted", + detail: "received SIGTERM", + }); + expect(stderr).toHaveBeenCalledWith( + expect.stringContaining("Interrupted (SIGTERM)"), + ); + expect(process.listenerCount("SIGTERM")).toBe(before); + }); + + it("exits 130 on a second press, after the re-raise window", async () => { + const exit = vi.fn(); + const existing = process.listeners("SIGINT"); + let t = 0; + let finish!: () => void; + const run = withLoadInterrupt( + () => new Promise((resolve) => (finish = resolve)), + { quiet: true, exit, now: () => t }, + ); + signalLoadRun("SIGINT", existing); + // `when-exit` re-raises the first signal a moment later: not a press. + t = 5; + signalLoadRun("SIGINT", existing); + t = REPEAT_GRACE_MS - 1; + signalLoadRun("SIGINT", existing); + expect(exit).not.toHaveBeenCalled(); + t = REPEAT_GRACE_MS; + signalLoadRun("SIGINT", existing); + expect(exit).toHaveBeenCalledWith(EXIT_CODES.INTERRUPTED); + finish(); + await run; + }); + + it("exits at once on a different signal, inside the window too", async () => { + const exit = vi.fn(); + const ints = process.listeners("SIGINT"); + const terms = process.listeners("SIGTERM"); + let finish!: () => void; + const run = withLoadInterrupt( + () => new Promise((resolve) => (finish = resolve)), + { quiet: true, exit, now: () => 0 }, + ); + signalLoadRun("SIGINT", ints); + signalLoadRun("SIGTERM", terms); + expect(exit).toHaveBeenCalledWith(EXIT_CODES.INTERRUPTED); + finish(); + await run; + }); + + it("exits the real process by default on the second signal", async () => { + const exit = vi + .spyOn(process, "exit") + .mockImplementation((() => undefined) as never); + const ints = process.listeners("SIGINT"); + const terms = process.listeners("SIGTERM"); + let finish!: () => void; + const run = withLoadInterrupt( + () => new Promise((resolve) => (finish = resolve)), + { quiet: true }, + ); + // Different signals, so the real clock's re-raise window never applies. + signalLoadRun("SIGINT", ints); + signalLoadRun("SIGTERM", terms); + expect(exit).toHaveBeenCalledWith(130); + finish(); + await run; + }); + + it("removes its listeners when the run throws", async () => { + const before = process.listenerCount("SIGINT"); + await expect( + withLoadInterrupt(async () => { + throw new Error("nope"); + }), + ).rejects.toThrow("nope"); + expect(process.listenerCount("SIGINT")).toBe(before); + }); + + it("raises exit 130 only for an interrupted summary", () => { + const summary = { + requests: 7, + stoppedEarly: { reason: "interrupted", detail: "received SIGINT" }, + } as LoadSummary; + let err: unknown; + try { + assertNotInterrupted(summary); + } catch (e) { + err = e; + } + expect(err).toBeInstanceOf(CliExitCodeError); + expect(err).toMatchObject({ + exitCode: EXIT_CODES.INTERRUPTED, + envelope: { code: "interrupted" }, + }); + expect(() => + assertNotInterrupted({ + ...summary, + stoppedEarly: { reason: "consecutive_errors", detail: "x" }, + }), + ).not.toThrow(); + expect(() => + assertNotInterrupted({ ...summary, stoppedEarly: undefined }), + ).not.toThrow(); + }); +}); + +describe("--load summary fixes (CLI)", () => { + const { command, args } = getTestMcpServerCommand(); + + it("prints the partial summary on Ctrl+C and exits 130 (#2834)", async () => { + const existing = process.listeners("SIGINT"); + const baseline = existing.length; + const run = runCli( + [ + command, + ...args, + "--cli", + "--method", + "tools/call", + "--tool-name", + "echo", + "--tool-arg", + "message=hi", + "--load", + "--load-duration", + "30", + "--load-concurrency", + "2", + "--format", + "json", + ], + { timeout: 20_000 }, + ); + // Fired once the run is under way, so some calls have completed. + await vi.waitFor( + () => expect(signalLoadRun("SIGINT", existing)).toBe(true), + { timeout: 10_000, interval: 200 }, + ); + const result = await run; + expect(result.exitCode).toBe(EXIT_CODES.INTERRUPTED); + const lines = result.stdout.trim().split("\n"); + const { result: summary } = JSON.parse(lines[0]!); + expect(summary.stoppedEarly).toEqual({ + reason: "interrupted", + detail: "received SIGINT", + }); + expect(summary.requests).toBe(summary.ok); + expect(result.stderr).toContain("Interrupted (SIGINT)"); + const envelope = JSON.parse(result.stderr.trim().split("\n").pop()!); + expect(envelope.error.code).toBe("interrupted"); + expect(process.listenerCount("SIGINT")).toBe(baseline); + }); + + it.each([ + [["--load-duration", "1"]], + [["--load", "--app-info"]], + [["--load", "--load-connections", "3", "--load-concurrency", "2"]], + [["--load", "--load-connections", "2"]], + ])( + "uses the load_flag_conflict envelope code for %j (#2834)", + async (flags) => { + const result = await runCli([ + command, + ...args, + "--cli", + "--method", + "tools/call", + "--tool-name", + "echo", + ...flags, + ]); + expect(result.exitCode).toBe(EXIT_CODES.USAGE); + const envelope = JSON.parse(result.stderr.trim().split("\n").pop()!); + expect(envelope.error.code).toBe(LOAD_FLAG_CONFLICT); + }, + ); + + describe("over HTTP", () => { + let n = 0; + const makeServer = () => + createTestServerHttp({ + serverInfo: createTestServerInfo("load-summary", "1.0.0"), + tools: [ + { + name: "unique", + description: "Always fails", + inputSchema: {}, + // The SDK answers a throwing handler with `isError: true`. + handler: async () => { + throw new Error(`rate limited`); + }, + }, + { + name: "slow", + description: "Answers after 50ms", + inputSchema: {}, + handler: async () => { + n++; + await new Promise((r) => setTimeout(r, 50)); + return { content: [{ type: "text", text: "ok" }] }; + }, + }, + ], + }); + + let server: ReturnType; + const http = (tool: string, ...flags: string[]) => [ + server.url, + "--cli", + "--transport", + "http", + "--method", + "tools/call", + "--tool-name", + tool, + "--load", + ...flags, + ]; + + it("tallies the text of isError results (#2836)", async () => { + server = makeServer(); + await server.start(); + try { + const result = await runCli( + http("unique", "--load-requests", "6", "--load-concurrency", "2"), + ); + expectCliSuccess(result); + const json = expectValidJson(result); + expect(json).toMatchObject({ toolErrors: 6, errorMessages: [] }); + expect(json.latencyMs).toBeNull(); + expect(json.toolErrorMessages).toHaveLength(1); + expect(json.toolErrorMessages[0].count).toBe(6); + expect(json.toolErrorMessages[0].message).toContain("rate limited"); + } finally { + await server.stop(); + } + }); + + it("fails --load-max-p99 when no call succeeded (#2836)", async () => { + server = makeServer(); + await server.start(); + try { + const result = await runCli( + http("unique", "--load-requests", "3", "--load-max-p99", "60000"), + ); + expect(result.exitCode).toBe(EXIT_CODES.LOAD_THRESHOLD_EXCEEDED); + expect(result.stderr).toContain("no call succeeded"); + } finally { + await server.stop(); + } + }); + + it("warns when a --load-rate run falls short (#2837)", async () => { + server = makeServer(); + await server.start(); + try { + const result = await runCli( + http( + "slow", + "--load-rate", + "100", + "--load-concurrency", + "1", + "--load-duration", + "0.5", + ), + ); + expectCliSuccess(result); + const json = expectValidJson(result); + expect(json.plannedStarts).toBe(50); + expect(json.droppedSlots).toBeGreaterThan(25); + expect(json.achievedRate).toBeLessThan(90); + expect(result.stderr).toContain("Warning: --load-rate 100/s"); + // `--quiet` drops the advisory, not the summary. + const quiet = await runCli( + http( + "slow", + "--load-rate", + "100", + "--load-concurrency", + "1", + "--load-duration", + "0.2", + "--quiet", + ), + ); + expectCliSuccess(quiet); + expect(quiet.stderr).not.toContain("Warning"); + } finally { + await server.stop(); + } + }); + + it("stops early when the server dies mid-run (#2835)", async () => { + server = makeServer(); + await server.start(); + n = 0; + const run = runCli( + http( + "slow", + "--load-duration", + "15", + "--load-concurrency", + "4", + "--format", + "json", + ), + { timeout: 20_000 }, + ); + await vi.waitFor(() => expect(n).toBeGreaterThan(4), { + timeout: 10_000, + }); + await server.stop(); + const result = await run; + expectCliSuccess(result); + const { result: summary } = expectValidJson(result); + expect(summary.stoppedEarly?.reason).toBe("consecutive_errors"); + expect(summary.errors).toBeGreaterThan(0); + expect(summary.elapsedMs).toBeLessThan(15_000); + expect(result.stderr).toContain( + "Warning: the load run stopped early (consecutive_errors)", + ); + }); + }); +}); diff --git a/clients/cli/__tests__/load-test.test.ts b/clients/cli/__tests__/load-test.test.ts index c2e84df77..9a338c71c 100644 --- a/clients/cli/__tests__/load-test.test.ts +++ b/clients/cli/__tests__/load-test.test.ts @@ -28,55 +28,7 @@ import { type LoadCallOutcome, type LoadClock, } from "@inspector/core/cli/handlers/load-test.js"; - -/** - * A clock that only moves when told to, with a timer queue: each `sleep` - * wakes at an absolute time, and timers fire one at a time in wake order, - * each on its own macrotask so the woken worker runs (up to its next await) - * before the clock moves again — as real timers behave. A rate-limited run - * therefore completes instantly while keeping the schedule it would in real - * time. - */ -function fakeClock( - options: { lateUntil?: number; jitter?: number } = {}, -): LoadClock & { advance: (ms: number) => void; sleeps: () => number } { - let t = 1000; - // A stalled event loop: no timer fires before this many ms into the run. - const earliestWake = 1000 + (options.lateUntil ?? 0); - const timers: { wakeAt: number; resolve: () => void }[] = []; - let pumping = false; - let sleepCount = 0; - const pump = (): void => { - timers.sort((a, b) => a.wakeAt - b.wakeAt); - const next = timers.shift(); - if (!next) { - pumping = false; - return; - } - t = Math.max(t, next.wakeAt); - next.resolve(); - setImmediate(pump); - }; - return { - now: () => t, - sleep: (ms) => - new Promise((resolve) => { - sleepCount++; - timers.push({ - wakeAt: Math.max(t + ms + (options.jitter ?? 0), earliestWake), - resolve, - }); - if (!pumping) { - pumping = true; - setImmediate(pump); - } - }), - advance: (ms) => { - t += ms; - }, - sleeps: () => sleepCount, - }; -} +import { fakeClock } from "./helpers/load-clock.js"; describe("load-test engine", () => { describe("percentile / summarizeLatency", () => { @@ -472,10 +424,10 @@ describe("load-test engine", () => { // before the run has spent its whole request count. setImmediate(() => abort.abort()); const limit = 200_000; + // Tool errors, not throws: a run of thrown calls would trip the + // circuit breaker (#2835) long before the first forced yield. const summary = await runLoad( - async () => { - throw new Error("rejected up front"); - }, + async () => "tool_error", { concurrency: 4, requests: limit }, undefined, abort.signal, diff --git a/clients/cli/__tests__/load-thresholds.test.ts b/clients/cli/__tests__/load-thresholds.test.ts index d91233ec6..46cc5e8eb 100644 --- a/clients/cli/__tests__/load-thresholds.test.ts +++ b/clients/cli/__tests__/load-thresholds.test.ts @@ -33,8 +33,11 @@ function summary(overrides: Partial = {}): LoadSummary { errorRate: 0, elapsedMs: 100, throughput: 1000, + okThroughput: 1000, latencyMs: { min: 1, mean: 2, p50: 2, p90: 3, p99: 4, max: 5 }, + errorLatencyMs: null, errorMessages: [], + toolErrorMessages: [], ...overrides, }; } @@ -149,13 +152,13 @@ describe("load thresholds", () => { ); }); - it("fails a p99 threshold when no call completed, and says why", () => { + it("fails a p99 threshold when no call succeeded, and says why", () => { const err = judge(summary({ requests: 0, ok: 0, latencyMs: null }), { maxP99Ms: 100, }); expect(err?.envelope?.code).toBe(LOAD_P99_EXCEEDED); expect(err?.message).toContain( - "no call completed, so there is no p99 latency to check", + "no call succeeded, so there is no p99 latency to check", ); }); diff --git a/clients/cli/src/cli.ts b/clients/cli/src/cli.ts index 6a2abd119..cb9f3a4ed 100644 --- a/clients/cli/src/cli.ts +++ b/clients/cli/src/cli.ts @@ -6,7 +6,10 @@ import { registerCompletionOption, } from "./completion.js"; type McpResponse = Record; -import { awaitableLog } from "@inspector/core/cli/utils/awaitable-log.js"; +import { + awaitableError, + awaitableLog, +} from "@inspector/core/cli/utils/awaitable-log.js"; import type { InspectorServerSettings, MCPServerConfig, @@ -61,10 +64,16 @@ import { consumeMethodOutcome } from "./handlers/consume-outcome.js"; import { positiveIntegerParser, positiveNumberParser, + LOAD_FLAG_CONFLICT, + loadSummaryWarnings, resolveLoadOptions, runToolLoad, type LoadOptions, } from "@inspector/core/cli/handlers/load-test.js"; +import { + assertNotInterrupted, + withLoadInterrupt, +} from "./handlers/load-interrupt.js"; import { checkLoadThresholds, fractionParser, @@ -166,6 +175,7 @@ async function callMethod( throw new CliExitCodeError( EXIT_CODES.USAGE, "--load-connections above 1 requires an HTTP or SSE server; over stdio each connection would spawn its own server process.", + { code: LOAD_FLAG_CONFLICT }, ); } @@ -332,23 +342,39 @@ async function callMethod( // `--load` (#2439): many calls of one tool, then a single summary, in // place of the one result a plain `tools/call` prints. if (load) { - const summary = await withCliAuthRecoveryRetry( - inspectorClient, - serverConfig, - redirectUrlProvider, - callbackUrlConfig, - serverSettings, - () => - runToolLoad(inspectorClient, args, load, { - openConnection: openLoadConnection, - }), - { storedAuthOnly, autoOpenControl, quiet: args.quiet }, + // Ctrl+C / SIGTERM end the run early rather than the process (#2834), + // so the partial summary below still gets out. + const summary = await withLoadInterrupt( + (signal) => + withCliAuthRecoveryRetry( + inspectorClient, + serverConfig, + redirectUrlProvider, + callbackUrlConfig, + serverSettings, + () => + runToolLoad(inspectorClient, args, load, { + openConnection: openLoadConnection, + signal, + }), + { storedAuthOnly, autoOpenControl, quiet: args.quiet }, + ), + { quiet: args.quiet }, ); await writeFormattedResult( summary, args.format === "json" ? "json" : "text", ); - // After the summary is out, so a breached run still shows its numbers. + // Advisory, so `--quiet` drops them (#2435): a missed `--load-rate` + // (#2837) and an early stop the summary also records (#2835). + if (!args.quiet) { + for (const warning of loadSummaryWarnings(summary)) { + await awaitableError(`${warning}\n`); + } + } + // After the summary is out, so a cut-short or breached run still shows + // its numbers. An interrupted run exits 130 and is not graded. + assertNotInterrupted(summary); checkLoadThresholds(summary, loadThresholds); return; } @@ -1138,7 +1164,7 @@ async function parseArgs(argv?: string[]): Promise { ) .option( "--load-max-p99 ", - "With --load: exit 10 (load_p99_exceeded) when the p99 latency is above this many milliseconds, or when no call completed, after printing the summary (positive number).", + "With --load: exit 10 (load_p99_exceeded) when the p99 latency of the successful calls is above this many milliseconds, or when no call succeeded, after printing the summary (positive number).", maxP99Parser, ) .option( @@ -1437,24 +1463,24 @@ async function parseArgs(argv?: string[]): Promise { ] as const; for (const [flag, value] of loadBounds) { if (value !== undefined && !options.load) { - throw new Error(`${flag} requires --load.`); + throw loadFlagConflict(`${flag} requires --load.`); } } if (options.load) { if (options.method !== "tools/call") { - throw new Error("--load requires --method tools/call."); + throw loadFlagConflict("--load requires --method tools/call."); } // Each of these shapes a single result; a load run prints a summary. if (options.appInfo) { - throw new Error("--load cannot be combined with --app-info."); + throw loadFlagConflict("--load cannot be combined with --app-info."); } if (options.listStoredAuth || options.printHandoff) { - throw new Error( + throw loadFlagConflict( "--load cannot be combined with --list-stored-auth or --print-handoff.", ); } if (options.output !== undefined || options.outputFormat !== undefined) { - throw new Error( + throw loadFlagConflict( "--load cannot be combined with --output or --output-format; redirect stdout to keep the summary.", ); } @@ -1774,17 +1800,47 @@ async function parseArgs(argv?: string[]): Promise { // `--no-revoke` makes it false. revoke: options.revoke !== false, ...(options.load && { - load: resolveLoadOptions({ - concurrency: options.loadConcurrency, - connections: options.loadConnections, - durationSec: options.loadDuration, - requests: options.loadRequests, - rate: options.loadRate, - }), + load: resolveCliLoadOptions(options), }), }; } +/** + * A `--load` flag combination the CLI refuses, under the envelope code mcpdo + * uses for the same mistakes (#2834), so a script can branch on one code + * whichever CLI it drove. Still exit 1, as before. + */ +function loadFlagConflict(message: string): CliExitCodeError { + return new CliExitCodeError(EXIT_CODES.USAGE, message, { + code: LOAD_FLAG_CONFLICT, + }); +} + +/** + * {@link resolveLoadOptions}, with its one refusal (`--load-connections` + * above `--load-concurrency`) raised as a {@link loadFlagConflict}. The engine + * only ever throws an `Error` there. + */ +function resolveCliLoadOptions(options: { + loadConcurrency?: number; + loadConnections?: number; + loadDuration?: number; + loadRequests?: number; + loadRate?: number; +}): LoadOptions { + try { + return resolveLoadOptions({ + concurrency: options.loadConcurrency, + connections: options.loadConnections, + durationSec: options.loadDuration, + requests: options.loadRequests, + rate: options.loadRate, + }); + } catch (err) { + throw loadFlagConflict((err as Error).message); + } +} + /** Stands in for `console.warn` during a `--quiet` run (see `parseArgs`). */ function discardWarning(): void {} diff --git a/clients/cli/src/handlers/load-interrupt.ts b/clients/cli/src/handlers/load-interrupt.ts new file mode 100644 index 000000000..82431dca6 --- /dev/null +++ b/clients/cli/src/handlers/load-interrupt.ts @@ -0,0 +1,99 @@ +import { + CliExitCodeError, + EXIT_CODES, +} from "@inspector/core/cli/error-handler.js"; +import type { + LoadStop, + LoadSummary, +} from "@inspector/core/cli/handlers/load-test.js"; + +/** + * Ctrl+C / SIGTERM for a one-shot `--load` run (#2834). + * + * Without this the CLI had no SIGINT listener during a run, so Node's default + * handler killed the process and every number from the run was lost — the + * moment they are most wanted (the server was struggling, or a CI job hit its + * timeout and sent SIGTERM). Here the FIRST signal aborts the engine's + * `signal`: no further call starts, in-flight calls settle, and the caller + * prints the partial summary (marked `stoppedEarly.reason: "interrupted"`) + * before exiting 130 via {@link assertNotInterrupted}. A SECOND signal exits + * 130 at once, for a run whose in-flight calls will not settle. + * + * ⚠️ **A repeat of the first signal inside {@link REPEAT_GRACE_MS} is not a + * second press.** Dependencies of the CLI hook signals too, and `when-exit` + * (via `atomically`) runs its cleanups on SIGINT/SIGTERM and then + * unconditionally re-raises the signal with `process.kill(process.pid, …)`. + * That copy reaches this listener a moment after the first, and counting it + * as Ctrl+C #2 exited 130 before the partial summary was written — which only + * a real signal to the built binary showed. Telling the copy apart by origin + * is not possible from a listener, so the window is the discriminator: the + * re-raise lands within milliseconds, and a person who means "exit now" + * presses again after reading the line this prints. A press inside the window + * is dropped, and the next one exits. + * + * The listeners exist only while `run` is pending, so a signal before or after + * the run keeps Node's default behaviour, and an in-process caller (the + * launcher, the test runner) is left with no stray listener. + */ +/** How long after the first signal a repeat of it is treated as a re-raise. */ +export const REPEAT_GRACE_MS = 500; + +export async function withLoadInterrupt( + run: (signal: AbortSignal) => Promise, + options: { + quiet?: boolean; + /** Injected by tests; the real one ends the process. */ + exit?: (code: number) => void; + /** Injected by tests; milliseconds on a monotonic clock. */ + now?: () => number; + } = {}, +): Promise { + const controller = new AbortController(); + const exit = options.exit ?? ((code: number) => process.exit(code)); + const now = options.now ?? (() => performance.now()); + let first: { signal: NodeJS.Signals; at: number } | undefined; + const onSignal = (signal: NodeJS.Signals): void => { + if (first !== undefined) { + // A dependency's re-raise of the first signal, not a second press. + if (signal === first.signal && now() - first.at < REPEAT_GRACE_MS) { + return; + } + exit(EXIT_CODES.INTERRUPTED); + return; + } + first = { signal, at: now() }; + const stop: LoadStop = { + reason: "interrupted", + detail: `received ${signal}`, + }; + controller.abort(stop); + if (!options.quiet) { + process.stderr.write( + `Interrupted (${signal}): no further calls will start; waiting for in-flight calls to finish. Press Ctrl+C again to exit now.\n`, + ); + } + }; + process.on("SIGINT", onSignal); + process.on("SIGTERM", onSignal); + try { + return await run(controller.signal); + } finally { + process.off("SIGINT", onSignal); + process.off("SIGTERM", onSignal); + } +} + +/** + * After the summary is printed: exit 130 (`interrupted`) when the run was + * cut short by Ctrl+C / SIGTERM, the conventional status for a process ended + * by SIGINT. Checked before any `--load-max-*` threshold, since a partial run + * is not a verdict on the server. + */ +export function assertNotInterrupted(summary: LoadSummary): void { + if (summary.stoppedEarly?.reason !== "interrupted") return; + throw new CliExitCodeError( + EXIT_CODES.INTERRUPTED, + `Load run interrupted (${summary.stoppedEarly.detail}); the summary covers the ${summary.requests} calls that completed.`, + { code: "interrupted" }, + ); +} diff --git a/clients/mcpdo/README.md b/clients/mcpdo/README.md index b06d23d58..8d1b8462f 100644 --- a/clients/mcpdo/README.md +++ b/clients/mcpdo/README.md @@ -228,10 +228,18 @@ mcpdo connect https://example.com/mcp --elicit url [load mode](../cli/README.md#load-testing-a-tool---load), run against an open connection ([#2744](https://github.com/modelcontextprotocol/inspector/issues/2744)). It calls one tool repeatedly and concurrently and prints a single summary in -place of a result: `ok`, `toolErrors`, `errors`, `errorRate`, `throughput`, -latency `min`/`mean`/`p50`/`p90`/`p99`/`max`, and the most frequent error -messages. Both CLIs run the same engine, so the flags, their defaults and the -summary fields mean the same thing in each. +place of a result: `ok`, `toolErrors`, `errors`, `errorRate`, `throughput` +and the success-only `okThroughput`, latency `min`/`mean`/`p50`/`p90`/`p99`/`max` +of the successful calls (`latencyMs`) and of the failed ones +(`errorLatencyMs`), the most frequent thrown messages (`errorMessages`) and +`isError` texts (`toolErrorMessages`), and — with `--load-rate` — +`plannedStarts`, `droppedSlots` and `achievedRate`. Both CLIs run the same +engine, so the flags, their defaults and the summary fields mean the same +thing in each; the [CLI's load section](../cli/README.md#load-testing-a-tool---load) +defines each field ([#2836](https://github.com/modelcontextprotocol/inspector/issues/2836), +[#2837](https://github.com/modelcontextprotocol/inspector/issues/2837)). A +`--load-rate` run that achieves under 90% of its target also prints a warning +on stderr after the summary. ```bash # 20 calls in flight for 30 seconds @@ -250,7 +258,7 @@ mcpdo @prod tools/call search query:=mcp --load --load-requests 500 --load-rate | `--load-rate ` | Start at most this many calls per second, spaced evenly (default: unlimited). | | `--load-connections ` | Spread the calls over this many independent sessions (HTTP/SSE only; at most `--load-concurrency`; default `1`). | | `--load-max-error-rate ` | Exit `10` (`load_error_rate_exceeded`) when the share of failed calls is above this value (`0` to `1`). | -| `--load-max-p99 ` | Exit `10` (`load_p99_exceeded`) when the p99 latency is above this many milliseconds, or no call completed. | +| `--load-max-p99 ` | Exit `10` (`load_p99_exceeded`) when the p99 latency of the successful calls is above this many milliseconds, or no call succeeded. | Each `--load-*` flag requires `--load`, and `--load` cannot be combined with `--app-info`. `--format json` prints the summary object itself, with no @@ -292,8 +300,16 @@ How a run behaves on a shared daemon connection: cancelled, so the connection is free for the next command at once. No summary is printed, since the caller has gone. - **A dropped connection ends the run early** with the summary of what - completed, rather than spending the rest of the window counting instant - failures. The next command revives the connection as usual. + completed, marked `"stoppedEarly": { "reason": "connection_lost", … }`, + rather than spending the rest of the window counting instant failures. The + next command revives the connection as usual. +- **A server that stops answering ends the run early too**, even when the + connection never changes state — over Streamable HTTP a refused request + need not ([#2835](https://github.com/modelcontextprotocol/inspector/issues/2835)). + The shared engine's circuit breaker stops starting calls once 50 in a row + have thrown, or a second has passed with nothing but thrown calls; the + summary carries `"stoppedEarly": { "reason": "consecutive_errors", … }` and + a warning follows on stderr. - **Elicitations are cancelled.** Many calls are in flight at once and none of them can be answered mid-run, so a server that elicits during a load run sees each request cancelled. Use `connect --elicit off` to keep the server from diff --git a/clients/mcpdo/__tests__/daemon-load.test.ts b/clients/mcpdo/__tests__/daemon-load.test.ts index 41b385d3d..50e6a0fca 100644 --- a/clients/mcpdo/__tests__/daemon-load.test.ts +++ b/clients/mcpdo/__tests__/daemon-load.test.ts @@ -106,8 +106,11 @@ const SUMMARY: LoadSummary = { errorRate: 0, elapsedMs: 10, throughput: 400, + okThroughput: 400, latencyMs: { min: 1, mean: 2, p50: 2, p90: 3, p99: 3, max: 3 }, + errorLatencyMs: null, errorMessages: [], + toolErrorMessages: [], }; const LOAD: LoadOptions = { concurrency: 2, requests: 4 }; @@ -276,6 +279,11 @@ describe("daemon rpc with --load", () => { expect(runSignal.aborted).toBe(false); fake.emitStatus("disconnected"); expect(runSignal.aborted).toBe(true); + // Named, so the summary reports the drop rather than an interrupt. + expect(runSignal.reason).toEqual({ + reason: "connection_lost", + detail: "the connection went disconnected", + }); expect((await call).ok).toBe(true); }); diff --git a/clients/mcpdo/__tests__/load.test.ts b/clients/mcpdo/__tests__/load.test.ts index 20eeaa5af..96a9b2c0d 100644 --- a/clients/mcpdo/__tests__/load.test.ts +++ b/clients/mcpdo/__tests__/load.test.ts @@ -45,8 +45,11 @@ const SUMMARY: LoadSummary = { errorRate: 0.1, elapsedMs: 1500, throughput: 20, + okThroughput: 18, latencyMs: { min: 1, mean: 2.5, p50: 2, p90: 4, p99: 5, max: 6 }, + errorLatencyMs: null, errorMessages: [{ message: "Request timed out", count: 2 }], + toolErrorMessages: [], }; describe("resolveLoadFlags", () => { @@ -137,7 +140,7 @@ describe("formatLoadSummaryHuman", () => { expect(text).toBe( [ "Load test `echo` (concurrency 4, duration 1.5s, limit 40, rate 20/s)", - " Requests: 30 in 1.50s (20/s)", + " Requests: 30 in 1.50s (20/s, 18/s ok)", " Outcomes: 27 ok, 1 tool errors, 2 errors", " Error rate: 10.00%", " Latency: min 1 / mean 2.5 / p50 2 / p90 4 / p99 5 / max 6 ms", @@ -157,16 +160,58 @@ describe("formatLoadSummaryHuman", () => { errorRate: 0, elapsedMs: 0, throughput: 0, + okThroughput: 0, latencyMs: null, + errorLatencyMs: null, errorMessages: [], + toolErrorMessages: [], }); expect(text).toContain("Load test (concurrency 1)"); expect(text).toContain("Error rate: 0.00%"); - expect(text).toContain("Latency: no calls completed"); + expect(text).toContain("Latency: no calls succeeded"); + expect(text).not.toContain("Failed in:"); + expect(text).not.toContain("Rate:"); + expect(text).not.toContain("Stopped early"); expect(text).not.toContain("Top errors"); expect(text).not.toContain("Sessions:"); }); + it("renders failure latency, tool errors, the rate shortfall and an early stop", () => { + const text = formatLoadSummaryHuman( + { + ...SUMMARY, + plannedStarts: 30, + droppedSlots: 12, + achievedRate: 12, + errorLatencyMs: { min: 0, mean: 1, p50: 1, p90: 2, p99: 2, max: 2 }, + toolErrorMessages: [{ message: "rate limited", count: 1 }], + stoppedEarly: { + reason: "consecutive_errors", + detail: + "50 calls in a row threw over 3ms; the server looks unavailable", + }, + }, + PLAIN, + ); + expect(text).toContain( + " Rate: 12/s achieved; 30 planned, 12 dropped\n", + ); + expect(text).toContain( + " Failed in: min 0 / mean 1 / p50 1 / p90 2 / p99 2 / max 2 ms\n", + ); + expect(text).toContain(" Top tool errors:\n 1× rate limited"); + expect(text).toContain( + " Stopped early (consecutive_errors): 50 calls in a row threw over 3ms; the server looks unavailable", + ); + // A rate held in full reports nothing dropped. + expect( + formatLoadSummaryHuman( + { ...SUMMARY, plannedStarts: 30, droppedSlots: 0, achievedRate: 20 }, + PLAIN, + ), + ).toContain(" Rate: 20/s achieved; 30 planned, 0 dropped"); + }); + it("renders the sessions of a multi-connection run, failures included", () => { const text = formatLoadSummaryHuman( { @@ -356,6 +401,34 @@ describe("mcpdo tools/call --load", { timeout: DAEMON_TEST_MS }, () => { ); } + it("warns on stderr when a --load-rate run falls short (#2837)", async () => { + const e = env(); + await connectStdio(e); + // No single worker starts 100k calls a second. + const result = await runMcp( + [ + "tools/call", + "echo", + "message:=hi", + "--load", + "--load-rate", + "100000", + "--load-concurrency", + "1", + "--load-duration", + "0.3", + "--format", + "json", + ], + { env: e, timeout: DAEMON_COMMAND_MS }, + ); + expectCliSuccess(result); + const summary = JSON.parse(result.stdout); + expect(summary).toMatchObject({ rate: 100000, plannedStarts: 30000 }); + expect(summary.droppedSlots).toBeGreaterThan(0); + expect(result.stderr).toContain("Warning: --load-rate 100000/s"); + }); + it("prints the summary, then fails a breached threshold with the CLI's code", async () => { const e = env(); await connectStdio(e); diff --git a/clients/mcpdo/src/connection/dispatch.ts b/clients/mcpdo/src/connection/dispatch.ts index add91f612..59a731dc4 100644 --- a/clients/mcpdo/src/connection/dispatch.ts +++ b/clients/mcpdo/src/connection/dispatch.ts @@ -6,6 +6,8 @@ import type { } from "@inspector/core/cli/handlers/method-types.js"; import type { OutputFormat } from "@inspector/core/cli/handlers/format-output.js"; import { checkLoadThresholds } from "@inspector/core/cli/handlers/load-thresholds.js"; +import { loadSummaryWarnings } from "@inspector/core/cli/handlers/load-test.js"; +import { awaitableError } from "@inspector/core/cli/utils/awaitable-log.js"; import type { LoadFlags } from "./load-flags.js"; import { writeConnectionOutput } from "./format-connection.js"; import { styleFromOpts, type Style } from "@inspector/core/cli/style.js"; @@ -147,6 +149,11 @@ export async function dispatchConnectionRpc( // the one-shot CLI's order (#2745). The breach is a CliExitCodeError, so it // leaves as mcpdo's error envelope with the CLI's code and exit code. if (outcome.kind === "load") { + // On stderr, after the summary, as the one-shot CLI prints them: an early + // stop (#2835) and a missed `--load-rate` (#2837). + for (const warning of loadSummaryWarnings(outcome.summary)) { + await awaitableError(`${warning}\n`); + } checkLoadThresholds(outcome.summary, opts.load?.thresholds); } } diff --git a/clients/mcpdo/src/connection/format-human.ts b/clients/mcpdo/src/connection/format-human.ts index e1e6df99e..a71800d84 100644 --- a/clients/mcpdo/src/connection/format-human.ts +++ b/clients/mcpdo/src/connection/format-human.ts @@ -1000,22 +1000,47 @@ export function formatLoadSummaryHuman( const rate = `${(summary.errorRate * 100).toFixed(2)}%`; const lines = [ `${heading(style, "Load test")}${tool} ${style.dim(`(${bounds.join(", ")})`)}`, - ` Requests: ${summary.requests} in ${(summary.elapsedMs / 1000).toFixed(2)}s (${summary.throughput}/s)`, + ` Requests: ${summary.requests} in ${(summary.elapsedMs / 1000).toFixed(2)}s (${summary.throughput}/s, ${summary.okThroughput}/s ok)`, ` Outcomes: ${style.green(`${summary.ok} ok`)}, ${summary.toolErrors} tool errors, ${summary.errors} errors`, ` Error rate: ${failed > 0 ? style.red(rate) : rate}`, ]; + // `--load-rate` only (#2837): the planned starts the run missed. + if (summary.plannedStarts !== undefined) { + const dropped = `${summary.droppedSlots} dropped`; + lines.push( + ` Rate: ${summary.achievedRate}/s achieved; ${summary.plannedStarts} planned, ${summary.droppedSlots! > 0 ? style.red(dropped) : dropped}`, + ); + } const l = summary.latencyMs; lines.push( l === null - ? ` Latency: ${style.dim("no calls completed")}` + ? ` Latency: ${style.dim("no calls succeeded")}` : ` Latency: min ${l.min} / mean ${l.mean} / p50 ${l.p50} / p90 ${l.p90} / p99 ${l.p99} / max ${l.max} ms`, ); + // Failures are timed apart from successes (#2836). + const e = summary.errorLatencyMs; + if (e !== null) { + lines.push( + ` Failed in: min ${e.min} / mean ${e.mean} / p50 ${e.p50} / p90 ${e.p90} / p99 ${e.p99} / max ${e.max} ms`, + ); + } if (summary.errorMessages.length > 0) { lines.push(` ${style.bold("Top errors:")}`); for (const { message, count } of summary.errorMessages) { lines.push(` ${count}× ${message}`); } } + if (summary.toolErrorMessages.length > 0) { + lines.push(` ${style.bold("Top tool errors:")}`); + for (const { message, count } of summary.toolErrorMessages) { + lines.push(` ${count}× ${message}`); + } + } + if (summary.stoppedEarly !== undefined) { + lines.push( + ` ${style.red("Stopped early")} (${summary.stoppedEarly.reason}): ${summary.stoppedEarly.detail}`, + ); + } // `--load-connections` above 1 (#2800). Connect failures are not call // errors, so they are listed under this line rather than "Top errors". const c = summary.connections; diff --git a/clients/mcpdo/src/connection/load-flags.ts b/clients/mcpdo/src/connection/load-flags.ts index c9ad7cacd..a632a32d6 100644 --- a/clients/mcpdo/src/connection/load-flags.ts +++ b/clients/mcpdo/src/connection/load-flags.ts @@ -3,6 +3,7 @@ import { EXIT_CODES, } from "@inspector/core/cli/error-handler.js"; import { + LOAD_FLAG_CONFLICT, resolveLoadOptions, type LoadOptions, } from "@inspector/core/cli/handlers/load-test.js"; @@ -93,6 +94,6 @@ export function resolveLoadFlags(flags: { return { options, ...(thresholds && { thresholds }) }; } -function usage(message: string, code = "load_flag_conflict"): CliExitCodeError { +function usage(message: string, code = LOAD_FLAG_CONFLICT): CliExitCodeError { return new CliExitCodeError(EXIT_CODES.USAGE, message, { code }); } diff --git a/clients/mcpdo/src/connection/mcp.ts b/clients/mcpdo/src/connection/mcp.ts index e9bee4df0..3d4b7f4fb 100644 --- a/clients/mcpdo/src/connection/mcp.ts +++ b/clients/mcpdo/src/connection/mcp.ts @@ -1392,7 +1392,7 @@ function registerRpcCommands(program: CommandType): void { ) .option( "--load-max-p99 ", - "With --load: exit 10 (load_p99_exceeded) when the p99 latency is above this many milliseconds, or when no call completed, after printing the summary (positive number).", + "With --load: exit 10 (load_p99_exceeded) when the p99 latency of the successful calls is above this many milliseconds, or when no call succeeded, after printing the summary (positive number).", maxP99Parser, ); cmd.action( diff --git a/clients/mcpdo/src/daemon/server.ts b/clients/mcpdo/src/daemon/server.ts index 29fd73d35..bed3959e0 100644 --- a/clients/mcpdo/src/daemon/server.ts +++ b/clients/mcpdo/src/daemon/server.ts @@ -15,6 +15,7 @@ import type { MethodArgs } from "@inspector/core/cli/handlers/method-types.js"; import { runToolLoad, type LoadOptions, + type LoadStop, } from "@inspector/core/cli/handlers/load-test.js"; import { acceptDaemonConnection, @@ -770,7 +771,14 @@ export class DaemonServer { const onStatus = ( event: TypedEventGeneric, ) => { - if (isTerminalStatus(event.detail)) stop.abort(); + if (!isTerminalStatus(event.detail)) return; + // Named, so the summary says why it stopped (#2835) rather than + // reading as an interrupt. + const lost: LoadStop = { + reason: "connection_lost", + detail: `the connection went ${event.detail}`, + }; + stop.abort(lost); }; client.addEventListener("statusChange", onStatus); // In-flight calls abort with the run, not only new ones (#1783). diff --git a/core/cli/error-handler.ts b/core/cli/error-handler.ts index 2e5bf0207..2b4de9f19 100644 --- a/core/cli/error-handler.ts +++ b/core/cli/error-handler.ts @@ -21,6 +21,7 @@ import { HTTP_TOO_MANY_REQUESTS } from "../mcp/rateLimit.js"; * - 9: `--verify --require-digests` found a skill that advertised no digests * - 10: a `--load` run breached a `--load-max-*` threshold * - 11: the server rate limited the request (HTTP 429) + * - 130: a `--load` run was interrupted by Ctrl+C / SIGTERM * * Note 6 is `SCHEMA_UNPORTABLE`, not "invalid": the whole premise of the lint * is that these schemas ARE valid JSON Schema and are merely refused by some @@ -92,6 +93,14 @@ export const EXIT_CODES = { * a script to scrape the prose message to tell throttling from a real error. */ RATE_LIMITED: 11, + /** + * A `--load` run was interrupted by SIGINT or SIGTERM (#2834). The partial + * summary has already been printed, marked `stoppedEarly.reason: + * "interrupted"`; the envelope `code` is `interrupted`. 130 is the shell's + * own status for a process ended by SIGINT (128 + 2), so a script sees the + * same value whether or not the summary got out. + */ + INTERRUPTED: 130, } as const; /** Machine-readable error envelope written as one JSON line on stderr. */ diff --git a/core/cli/handlers/load-test.ts b/core/cli/handlers/load-test.ts index 520f12a85..bfbafc5f5 100644 --- a/core/cli/handlers/load-test.ts +++ b/core/cli/handlers/load-test.ts @@ -35,8 +35,32 @@ export type LoadOptions = { rate?: number; }; -/** How one call ended. `tool_error` is a result carrying `isError: true`. */ -export type LoadCallOutcome = "ok" | "tool_error"; +/** + * How one call ended. `tool_error` is a result carrying `isError: true`; the + * object form carries the message that result held (#2836), so a run that is + * 100% `rate limited` says so in `toolErrorMessages`. + */ +export type LoadCallOutcome = "ok" | "tool_error" | LoadToolError; + +/** A tool error with the text its result carried (#2836). */ +export type LoadToolError = { outcome: "tool_error"; message: string }; + +/** + * Why a run ended before its bounds did (#2834, #2835): + * + * - `interrupted`: the caller aborted it (Ctrl+C / SIGTERM, a hung-up client). + * - `connection_lost`: the caller saw the connection go terminal and aborted. + * - `consecutive_errors`: the engine's own circuit breaker tripped, because + * calls had done nothing but throw for long enough that the server is + * clearly gone (see {@link CIRCUIT_BREAKER_ERRORS}). + */ +export type LoadStopReason = + | "interrupted" + | "connection_lost" + | "consecutive_errors"; + +/** An early stop, as reported in {@link LoadSummary.stoppedEarly}. */ +export type LoadStop = { reason: LoadStopReason; detail: string }; /** Latency distribution in milliseconds, nearest-rank percentiles. */ export type LoadLatency = { @@ -56,6 +80,18 @@ export type LoadSummary = { rate?: number; /** Calls that completed, in any outcome. */ requests: number; + /** + * With `rate` only (#2837): the calls the `1 / rate` grid called for over + * the run's start window — the whole `--load-duration` on a run that ran + * to it, or up to the last start of a run ended by `--load-requests`. A + * slot nobody was free to take is + * dropped rather than owed, so this can exceed what was started. + */ + plannedStarts?: number; + /** With `rate` only: `plannedStarts` minus the calls actually started. */ + droppedSlots?: number; + /** With `rate` only: calls started per second over the start window. */ + achievedRate?: number; ok: number; /** Calls that returned a result with `isError: true`. */ toolErrors: number; @@ -63,13 +99,37 @@ export type LoadSummary = { errors: number; /** `(toolErrors + errors) / requests` to four places; 0 when none completed. */ errorRate: number; + /** + * Wall clock from the first start to the last completion. A run that ran + * to its `--load-duration` is measured to the end of that window at least + * (#2837), so a `--load-rate 1` run over 5s reports 1/s, not 1.25/s. + */ elapsedMs: number; - /** Completed calls per second of wall clock. */ + /** Completed calls per second of wall clock, in any outcome. */ throughput: number; - /** `null` when no call completed. */ + /** Successful (`ok`) calls per second of wall clock (#2836). */ + okThroughput: number; + /** + * Latency of the successful (`ok`) calls only (#2836), so an instant + * failure never makes a struggling server look faster. `null` when no call + * succeeded. + */ latencyMs: LoadLatency | null; + /** Latency of the failed calls, tool errors and thrown alike; `null` if none. */ + errorLatencyMs: LoadLatency | null; /** Thrown messages by frequency, at most {@link MAX_ERROR_KINDS} of them. */ errorMessages: { message: string; count: number }[]; + /** + * The first text block of each `isError` result (#2836), trimmed and cut to + * {@link MAX_TOOL_ERROR_MESSAGE_LENGTH}, tallied like `errorMessages`. + */ + toolErrorMessages: { message: string; count: number }[]; + /** + * Present only when the run ended before its bounds did — interrupted, or + * stopped by the circuit breaker (#2834, #2835). The counts cover what + * completed before it stopped. + */ + stoppedEarly?: LoadStop; /** * Present only when more than one connection was asked for, so a default * run's summary is exactly what it was before #2746. @@ -174,6 +234,37 @@ export function resolveLoadOptions(flags: { /** Distinct error messages kept; the rest fold into one `(other)` entry. */ export const MAX_ERROR_KINDS = 10; export const OTHER_ERRORS = "(other)"; +/** + * Longest tool-error text kept (#2836). A tool's error text is a whole + * result body, unlike a thrown message, and one tally entry per run should + * not carry kilobytes of it. + */ +export const MAX_TOOL_ERROR_MESSAGE_LENGTH = 200; +/** Tallied for an `isError` result with no text block to report. */ +export const NO_TOOL_ERROR_TEXT = "(no text content)"; + +/** + * Circuit breaker (#2835). Once this many calls IN A ROW have thrown, the + * run stops: a server that refuses every connection fails each call in + * microseconds, and the rest of the window would otherwise be a flood of + * instant failures that inflates throughput and deflates latency. Only + * thrown calls count — a tool error is the server answering — and any other + * outcome resets the streak. + */ +export const CIRCUIT_BREAKER_ERRORS = 50; +/** + * The breaker also trips once calls have done nothing but throw for this + * long, after at least {@link CIRCUIT_BREAKER_MIN_ERRORS} of them, so a slow + * low-rate run against a dead server stops in about a second too. + */ +export const CIRCUIT_BREAKER_WINDOW_MS = 1000; +export const CIRCUIT_BREAKER_MIN_ERRORS = 5; + +/** + * The share of `--load-rate` below which {@link loadRateShortfallWarning} + * speaks up (#2837). + */ +export const RATE_SHORTFALL_RATIO = 0.9; /** * Slots claimed between forced yields to the event loop. Without @@ -288,6 +379,89 @@ class ErrorTally { } } +/** Narrow an abort reason to a {@link LoadStop} a caller passed to `abort()`. */ +function isLoadStop(value: unknown): value is LoadStop { + if (typeof value !== "object" || value === null) return false; + const { reason, detail } = value as Record; + return ( + (reason === "interrupted" || + reason === "connection_lost" || + reason === "consecutive_errors") && + typeof detail === "string" + ); +} + +/** + * The message to tally for an `isError` result: its first text block, + * trimmed and capped at {@link MAX_TOOL_ERROR_MESSAGE_LENGTH}. + */ +export function toolErrorText(content: unknown): string { + const blocks = Array.isArray(content) ? (content as unknown[]) : []; + for (const block of blocks) { + if (typeof block !== "object" || block === null) continue; + const { type, text } = block as Record; + if (type !== "text" || typeof text !== "string") continue; + const trimmed = text.trim(); + if (trimmed === "") continue; + return trimmed.length > MAX_TOOL_ERROR_MESSAGE_LENGTH + ? `${trimmed.slice(0, MAX_TOOL_ERROR_MESSAGE_LENGTH)}…` + : trimmed; + } + return NO_TOOL_ERROR_TEXT; +} + +/** + * Envelope code for a `--load` flag combination either CLI refuses (#2834): + * a `--load-*` flag without `--load`, `--load-connections` above + * `--load-concurrency`, and the like. Exit 1 (`USAGE`) in both. + */ +export const LOAD_FLAG_CONFLICT = "load_flag_conflict"; + +/** + * The stderr lines a front end prints after a load summary (#2835, #2837): + * an early stop the caller did not ask for, and a missed `--load-rate`. + * An `interrupted` run is left out — whoever interrupted it knows, and the + * CLI says so in its exit envelope. + */ +export function loadSummaryWarnings(summary: LoadSummary): string[] { + const warnings: string[] = []; + const stop = summary.stoppedEarly; + if (stop !== undefined && stop.reason !== "interrupted") { + warnings.push( + `Warning: the load run stopped early (${stop.reason}): ${stop.detail}.`, + ); + } + const shortfall = loadRateShortfallWarning(summary); + if (shortfall !== undefined) warnings.push(shortfall); + return warnings; +} + +/** + * The stderr warning for a `--load-rate` run that started well short of its + * target (#2837), or `undefined` when it held the rate (or had none). + * Slots nobody was free to take are dropped by design, which makes a + * saturated run look healthy unless something says so. + */ +export function loadRateShortfallWarning( + summary: LoadSummary, +): string | undefined { + const { rate, achievedRate, plannedStarts, droppedSlots } = summary; + if ( + rate === undefined || + plannedStarts === undefined || + droppedSlots === undefined || + plannedStarts === 0 + ) { + return undefined; + } + // Judged on the exact counts rather than the two-place `achievedRate`, + // which rounds a fractional `--load-rate` (0.014/s → 0.01/s) far enough to + // read as a shortfall that never happened. + const started = plannedStarts - droppedSlots; + if (started >= plannedStarts * RATE_SHORTFALL_RATIO) return undefined; + return `Warning: --load-rate ${rate}/s was not reached: ${started} of ${plannedStarts} planned calls started (${achievedRate}/s); ${droppedSlots} slots were dropped because every worker was busy. Raise --load-concurrency or lower --load-rate.`; +} + /** * Run `call` under the given bounds and summarize what happened. Each call is * handed the index of the worker making it (0 to `concurrency - 1`), which @@ -303,7 +477,10 @@ class ErrorTally { * recovering. A slot past the duration is never started. * * Aborting `signal` ends the run early: no further call starts, in-flight - * calls are left to settle, and the summary covers what completed. + * calls are left to settle, and the summary covers what completed and says + * why in `stoppedEarly`. Abort with a {@link LoadStop} as the reason to name + * it; any other reason reports `interrupted`. The circuit breaker + * ({@link CIRCUIT_BREAKER_ERRORS}) ends a run the same way on its own. */ export async function runLoad( call: (worker: number) => Promise, @@ -312,8 +489,10 @@ export async function runLoad( signal?: AbortSignal, ): Promise { const { concurrency, durationMs, requests, rate } = options; - const latencies: number[] = []; + const okLatencies: number[] = []; + const errorLatencies: number[] = []; const tally = new ErrorTally(); + const toolTally = new ErrorTally(); let ok = 0; let toolErrors = 0; let errors = 0; @@ -325,6 +504,63 @@ export async function runLoad( // Earliest time the next slot may start. let nextStart = start; + // Everything inside the run watches `halt`, which the caller's `signal` and + // the circuit breaker both trip, so either ends the run the same way. + const halt = new AbortController(); + let stoppedEarly: LoadStop | undefined; + let stoppedAt = 0; + const stopRun = (stop: LoadStop): void => { + if (stoppedEarly) { + // An explicit interrupt outranks a breaker stop recorded while calls + // were still draining, so Ctrl+C still exits 130; the stop time stays + // the first one, which is when starts actually ended. + if (stop.reason === "interrupted") stoppedEarly = stop; + return; + } + stoppedEarly = stop; + stoppedAt = clock.now(); + halt.abort(); + }; + const onAbort = (): void => { + const reason: unknown = signal?.reason; + stopRun( + isLoadStop(reason) + ? reason + : { reason: "interrupted", detail: "the run was interrupted" }, + ); + }; + if (signal?.aborted) onAbort(); + else signal?.addEventListener("abort", onAbort, { once: true }); + + // Circuit breaker state (#2835): the current streak of thrown calls, and + // when the first of them completed. + let errorStreak = 0; + let streakSince = 0; + const noteThrown = (now: number): void => { + if (errorStreak++ === 0) streakSince = now; + const window = now - streakSince; + // Only while another call could still start: once the bounds have + // ended starts, the failures are in-flight calls draining, and calling + // that an early stop would misreport a run that ran to its bounds. + const canStart = + (requests === undefined || started < requests) && + now < deadline && + nextStart < deadline; + if ( + canStart && + (errorStreak >= CIRCUIT_BREAKER_ERRORS || + (errorStreak >= CIRCUIT_BREAKER_MIN_ERRORS && + window >= CIRCUIT_BREAKER_WINDOW_MS)) + ) { + stopRun({ + reason: "consecutive_errors", + // No server text here: it reaches stderr as a warning, and the + // messages themselves are already tallied in `errorMessages`. + detail: `${errorStreak} calls in a row threw over ${round(window)}ms; the server looks unavailable`, + }); + } + }; + // FIFO turnstile: workers wanting a slot queue on a promise chain, and only // the one at the head waits on the clock. Without it, every idle worker // armed its own timer for the same slot and all but one re-armed on waking @@ -351,7 +587,7 @@ export async function runLoad( await yieldToEventLoop(); } for (;;) { - if (signal?.aborted) return false; + if (halt.signal.aborted) return false; if (requests !== undefined && started >= requests) return false; const now = clock.now(); if (now >= deadline) return false; @@ -367,7 +603,7 @@ export async function runLoad( now - nextStart < interval ? nextStart + interval : now + interval; return true; } - await sleepUnlessAborted(clock, scheduled - now, signal); + await sleepUnlessAborted(clock, scheduled - now, halt.signal); } } finally { release(); @@ -377,30 +613,78 @@ export async function runLoad( const worker = async (index: number): Promise => { while (await claimSlot()) { // Another worker's call can abort the run between this worker taking - // its slot and resuming here. - if (signal?.aborted) return; + // its slot and resuming here. The slot was never used, so it is handed + // back: `started` feeds the `--load-rate` figures. + if (halt.signal.aborted) { + started--; + return; + } const t0 = clock.now(); try { const outcome = await call(index); - if (outcome === "ok") ok++; - else toolErrors++; + const latency = clock.now() - t0; + errorStreak = 0; + if (outcome === "ok") { + ok++; + okLatencies.push(latency); + } else { + toolErrors++; + errorLatencies.push(latency); + toolTally.add( + typeof outcome === "object" ? outcome.message : NO_TOOL_ERROR_TEXT, + ); + } } catch (err) { + const now = clock.now(); errors++; + errorLatencies.push(now - t0); tally.add(err instanceof Error ? err.message : String(err)); + noteThrown(now); } - latencies.push(clock.now() - t0); } }; - await Promise.all(Array.from({ length: concurrency }, (_, i) => worker(i))); + try { + await Promise.all(Array.from({ length: concurrency }, (_, i) => worker(i))); + } finally { + signal?.removeEventListener("abort", onAbort); + } - const elapsedMs = clock.now() - start; + const end = clock.now(); + const requestCapped = requests !== undefined && started >= requests; + // Ran to its `--load-duration`: neither stopped early nor ended by the + // request count. Measured to the end of that window at least (#2837). + const ranFullWindow = + durationMs !== undefined && stoppedEarly === undefined && !requestCapped; + const elapsedMs = ranFullWindow + ? Math.max(end - start, durationMs) + : end - start; const completed = ok + toolErrors + errors; + /** + * When the run stopped starting calls, for the `--load-rate` figures: the + * earliest of the bounds that applied. The duration deadline; for a run the + * request count ended, the grid slot after its last start — the scheduler's + * own `nextStart`, so a final timer that woke a little late does not count + * as a missed slot; and the moment an early stop landed. So an interrupt + * while calls drain past a bound does not stretch the window either. + */ + const startWindowEnd = (): number => { + let windowEnd = deadline; + if (requestCapped) windowEnd = Math.min(windowEnd, nextStart); + if (stoppedEarly !== undefined) windowEnd = Math.min(windowEnd, stoppedAt); + /* v8 ignore next -- defensive: a run with no duration, no request cap + and no stop never ends, so one of the three always applies. */ + return Number.isFinite(windowEnd) ? windowEnd : end; + }; return { concurrency, ...(durationMs !== undefined && { durationMs }), ...(requests !== undefined && { requestLimit: requests }), - ...(rate !== undefined && { rate }), + ...(rate !== undefined && + rateFigures(rate, { + started, + windowMs: startWindowEnd() - start, + })), requests: completed, ok, toolErrors, @@ -410,8 +694,39 @@ export async function runLoad( completed === 0 ? 0 : round((toolErrors + errors) / completed, 4), elapsedMs: round(elapsedMs), throughput: elapsedMs > 0 ? round((completed * 1000) / elapsedMs) : 0, - latencyMs: summarizeLatency(latencies), + okThroughput: elapsedMs > 0 ? round((ok * 1000) / elapsedMs) : 0, + latencyMs: summarizeLatency(okLatencies), + errorLatencyMs: summarizeLatency(errorLatencies), errorMessages: tally.entries(), + toolErrorMessages: toolTally.entries(), + ...(stoppedEarly !== undefined && { stoppedEarly }), + }; +} + +/** + * `rate`, plus the planned-versus-started figures for a `--load-rate` run + * (#2837), over `windowMs` — the span the run was starting calls in. + */ +function rateFigures( + rate: number, + run: { started: number; windowMs: number }, +): Pick< + LoadSummary, + "rate" | "plannedStarts" | "droppedSlots" | "achievedRate" +> { + const { started, windowMs } = run; + // The slots at 0, 1/rate, … that fall inside the window. The epsilon keeps + // floating-point noise (5000ms × 0.001/ms = 5.000000001) from adding one. + const slots = Math.ceil((windowMs * rate) / 1000 - 1e-9); + // Not capped at `--load-requests`: a request-bound run that was saturated + // throughout still missed slots while it was starting its calls, and a cap + // would report none. The limit bounds what is started, not the grid. + const plannedStarts = Math.max(started, slots); + return { + rate, + plannedStarts, + droppedSlots: plannedStarts - started, + achievedRate: windowMs > 0 ? round((started * 1000) / windowMs) : 0, }; } @@ -556,7 +871,11 @@ export async function runToolLoad( if (invocation.result === null) { throw new Error(invocation.error ?? "Tool call failed"); } - return invocation.result.isError === true ? "tool_error" : "ok"; + if (invocation.result.isError !== true) return "ok"; + return { + outcome: "tool_error", + message: toolErrorText(invocation.result.content), + }; }; const summary = await runLoadAcrossConnections( inspectorClient, diff --git a/core/cli/handlers/load-thresholds.ts b/core/cli/handlers/load-thresholds.ts index 9ae9acffb..86f41f8a4 100644 --- a/core/cli/handlers/load-thresholds.ts +++ b/core/cli/handlers/load-thresholds.ts @@ -94,14 +94,18 @@ function errorRateBreach( }; } +/** + * Judged on the successful calls only (#2836): `latencyMs` excludes failures, + * so an instant failure can never pull the p99 under the SLO. + */ function p99Breach(summary: LoadSummary, max: number): Breach | undefined { const p99 = summary.latencyMs?.p99; - // No completed call means no latency to compare. Passing would let a run - // that measured nothing satisfy a latency SLO, so it fails — and says why. + // No successful call means no latency to compare. Passing would let a run + // that served nothing satisfy a latency SLO, so it fails — and says why. if (p99 === undefined) { return { code: LOAD_P99_EXCEEDED, - message: `no call completed, so there is no p99 latency to check against --load-max-p99 ${max}`, + message: `no call succeeded, so there is no p99 latency to check against --load-max-p99 ${max}`, }; } if (p99 <= max) return undefined; diff --git a/skills/mcpdo/SKILL.md b/skills/mcpdo/SKILL.md index 790be6226..c1c252e70 100644 --- a/skills/mcpdo/SKILL.md +++ b/skills/mcpdo/SKILL.md @@ -163,3 +163,17 @@ more). - Parked calls expire after 10 minutes; one parked call per connection. Pass `--elicit off` on `connect` to have well-behaved servers fall back to their own defaults instead of asking. + +## Load runs (`tools/call --load`) + +- The summary's `latencyMs` and `okThroughput` cover **successful** calls + only; failures are timed in `errorLatencyMs`, and `isError` results' text + is tallied in `toolErrorMessages` (thrown ones in `errorMessages`). Judge a + run on these, not on `throughput`, which counts failures too. +- With `--load-rate`, compare `achievedRate` to `rate` and read + `droppedSlots`: slots nobody was free to take are dropped, so a server too + slow for the target can still report healthy latency. A shortfall under 90% + also prints a warning on stderr. +- `stoppedEarly` (`reason` + `detail`) means the run ended before its bounds: + `consecutive_errors` (the server stopped answering), `connection_lost`, or + `interrupted`. The counts cover only what completed.