diff --git a/changelog.d/mcpl-agent-words.changed.md b/changelog.d/mcpl-agent-words.changed.md index 98b2a6228..a8ff6ccca 100644 --- a/changelog.d/mcpl-agent-words.changed.md +++ b/changelog.d/mcpl-agent-words.changed.md @@ -2,7 +2,7 @@ - **A failed MCPL request:** - A connection that closes with a call pending reads `The connection to the "" server closed before it answered, so whether the request took effect is unknown.` It then says whether this host is reconnecting, where it read `MCPL server "" disconnected unexpectedly (code=…, signal=…, reason=…) while awaiting (id=N)`. - The other texts change the same way: a close by this host, a request on a closed connection or one the transport couldn't write, a server's error answer (in the server's own words, or, with none, saying the outcome is unknown) and a timeout. - - The log gains a line for a close with requests pending, with the close's code, signal and reason, whether this host closed it, and the requests left unanswered; one for a server's error answer, with its method, id and code; one for a timeout, with its method and id; and one for a request the transport couldn't write, with its method, id and the transport's words. + - The log gains a line for a close with requests pending, with the close's code, signal and reason, whether this host closed it, and the requests left unanswered; one for a server's error answer, with its method, id and code, and its message, whatever JSON value it is, with any credential the server's configuration holds replaced, where the caller's text keeps the message unredacted; one for a timeout, with its method and id; and one for a request the transport couldn't write, with its method, id and the transport's words. - **The framework's MCPL tool calls:** - A call to a server missing from the registry, or to a tool its policy denies, says it didn't run and whether anything can change that, in the same words for the model's call and a script's. One made while this host is connecting to the server, in a runtime connect or a restart's, says so and to try again in a moment. - An error result with no text, or only whitespace, reads as one whose effect is unknown, where it read `Tool call failed`, or the blank text. diff --git a/changelog.d/mcpl-connect-in-flight.fixed.md b/changelog.d/mcpl-connect-in-flight.fixed.md index f3f6d9961..fb81d4663 100644 --- a/changelog.d/mcpl-connect-in-flight.fixed.md +++ b/changelog.d/mcpl-connect-in-flight.fixed.md @@ -1 +1 @@ -- A runtime connect, or a restart of another server into an id whose legacy connect is still in its handshake, is now refused before it changes anything, with `MCPL server "" has a connect in flight; try again once it settles`. While a modern connect is in flight, the id reads as already registered. Before, a second connect went ahead beside a legacy one, and whichever settled last replaced the other in the registry without closing it. A disconnect of the id, in either engine, now ends the connect in flight and removes whatever it registered. Before, the disconnect removed the server's config and tool prefix, and the connect then registered the server without them, where no call reached it and only another disconnect cleared it. +- A runtime connect, or a restart of another server into an id whose connect is still in flight, in either engine, is now refused before it changes anything, with `MCPL server "" has a connect in flight; try again once it settles`, until that connect lets go of the id, just before it lists its tools. Before, a second connect went ahead beside a legacy one, and whichever settled last replaced the other in the registry without closing it. A disconnect of the id now ends the connect in flight and removes whatever it registered. Before, the disconnect removed the server's config and tool prefix, and the connect then registered the server without them, where no call reached it and only another disconnect cleared it. diff --git a/changelog.d/modern-mcp-client.added.md b/changelog.d/modern-mcp-client.added.md index 6b276304c..4e7d92f0b 100644 --- a/changelog.d/modern-mcp-client.added.md +++ b/changelog.d/modern-mcp-client.added.md @@ -30,7 +30,12 @@ `complete` result is a final answer: a call that ends after an `input_required` answer, or after a result type this revision doesn't define, is `no-response`. A complete result that can't be used is a - plain error. + plain error. The message an agent reads is the one an MCPL server's + failure gives where the two share an outcome, and has its shape where + they don't: what happened, whether anything took effect, and what works + from there. The method, the tool, the JSON-RPC code and the HTTP status + go to the host's log. A tool call made while the server's connect is + still under way reads as one made while an MCPL server connects. - **Lifetime:** reconnects use the legacy backoff settings. A tool-list change subscription is kept open, reopened if refused or lost, and its changes go through ordinary admission, so they park under quiesce like diff --git a/changelog.d/redact-recorded-mcp-credentials.fixed.md b/changelog.d/redact-recorded-mcp-credentials.fixed.md index 98c9a85d6..3ddc668ac 100644 --- a/changelog.d/redact-recorded-mcp-credentials.fixed.md +++ b/changelog.d/redact-recorded-mcp-credentials.fixed.md @@ -1 +1 @@ -- Server and transport text the framework records has the server's configured credentials replaced, in both engines: connection traces, console lines, stderr traces, the last of a server's stderr that a failed handshake keeps (in its trace and console line), the ops alert (and so `logs/failures.log` and the webhook), an MCP tool call that fails without an answer, as its caller and the model get it and in the `tool:failed` trace's message and stack. The credentials are those the configuration holds and those its dials sent: from the url as each dial sends it (a WebSocket dial sets the token in the query, which writes the whole query again, form-encoded, and an access provider's token can be in it), credential-like path segments and query names, credential-shaped or credential-named query values (each as written and decoded), every non-empty parameter as its whole `name=value`, and a WebSocket url's username and password, its userinfo as one unit before its `@` (the username alone when there's no password), with no length floor, so a short password goes with its username and a short username alone goes too, and the Basic credential a WebSocket client sends for it; the static `token`, and each token an access provider handed a dial (the newest sixteen), raw, as JSON encoders write it (with `JSON.stringify`'s escapes, and with its slashes escaped too, as some encoders write them), and as a url carries it, percent- or form-encoded with either case of hex; and a stdio server's `env` values whose names have a part ending in a credential word, singular or plural, with any digits after it (`GITHUB_TOKEN`, `API_KEYS`, `PGPASSWORD`, `DB_PASS`, `AUTHORIZATION`, `SESSION_COOKIE`, `TOKEN2`), raw, as JSON encoders write them, and percent-encoded with either case of hex. A stdio server's command-line arguments are not derived. A string replaced on its own has at least eight characters, since a shorter one can't be told from ordinary text, and is replaced wherever it occurs. Every non-empty query parameter is also replaced as its whole `name=value`, only where no letter or digit adjoins the pair (so `v=2` leaves `dev=2` alone); a short value goes only that way. A connection's event records use a redactor built once for it, and built again once a dial has sent something new. An operation's records replace the credentials of the configurations present when it began and of those present when each record is made, so a server removed, or replaced by a restart, while the operation waits is still covered, and so is one connected meanwhile. Every place a credential matches is replaced, places that overlap included, and text that may come from any server is matched against every server's strings at once, so two servers' secrets that overlap are both replaced whole. Over HTTP, which only the modern engine speaks, a 401 or 403's response body is left out of the request error's data; where the HTTP client builds the error's message from the body, as it does for most statuses, the message is redacted like any record. Credentials neither the configuration holds nor a dial sent are outside this, and so are a stdio server's command-line arguments. JSON-RPC answers, and the error a host's own connect raises, pass as they are. +- Server and transport text the framework records has the server's configured credentials replaced, in both engines: connection traces, console lines, stderr traces, the last of a server's stderr that a failed handshake keeps (in its trace and console line), the ops alert (and so `logs/failures.log` and the webhook), an MCP tool call that fails without an answer, as its caller and the model get it and in the `tool:failed` trace's message and stack. The credentials are those the configuration holds and those its dials sent: from the url as each dial sends it (a WebSocket dial sets the token in the query, which writes the whole query again, form-encoded, and an access provider's token can be in it), credential-like path segments and query names, credential-shaped or credential-named query values (each as written and decoded), every non-empty parameter as its whole `name=value`, and a WebSocket url's username and password, its userinfo as one unit before its `@` (the username alone when there's no password), with no length floor, so a short password goes with its username and a short username alone goes too, and the Basic credential a WebSocket client sends for it; the static `token`, and each token an access provider handed a dial (the newest sixteen), raw, and as a url carries it, percent- or form-encoded with either case of hex; and a stdio server's `env` values whose names have a part ending in a credential word, singular or plural, with any digits after it (`GITHUB_TOKEN`, `API_KEYS`, `PGPASSWORD`, `DB_PASS`, `AUTHORIZATION`, `SESSION_COOKIE`, `TOKEN2`), raw, and percent-encoded with either case of hex. Each of these strings, from every source, the `name=value` pairs and userinfo units too, is also replaced as JSON encoders write it, with `JSON.stringify`'s escapes, and with its slashes escaped too, as some encoders write them. A stdio server's command-line arguments are not derived. A string replaced on its own has at least eight characters, since a shorter one can't be told from ordinary text, and is replaced wherever it occurs. Every non-empty query parameter is also replaced as its whole `name=value`, only where no letter or digit adjoins the pair (so `v=2` leaves `dev=2` alone; a JSON escape before it, such as `\n`, isn't one); a short value goes only that way. A connection's event records use a redactor built once for it, and built again once a dial has sent something new. An operation's records replace the credentials of the configurations present when it began and of those present when each record is made, so a server removed, or replaced by a restart, while the operation waits is still covered, and so is one connected meanwhile. Every place a credential matches is replaced, places that overlap included, and text that may come from any server is matched against every server's strings at once, so two servers' secrets that overlap are both replaced whole. Over HTTP, which only the modern engine speaks, a 401 or 403's response body is left out of the request error's data; where the HTTP client builds the error's message from the body, as it does for most statuses, the message is redacted like any record. Credentials neither the configuration holds nor a dial sent are outside this, and so are a stdio server's command-line arguments. JSON-RPC answers, and the error a host's own connect raises, pass as they are. diff --git a/src/framework.ts b/src/framework.ts index 1c61824fc..5898ae2e6 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -147,9 +147,10 @@ import { stampThinkingTokenEstimates } from './thinking-token-stamp.js'; * closed for good, one removed, or one whose connect failed without * reconnect, which this host doesn't bring back on its own. A server that's * reconnecting stays registered, as does the stub a failed connect with - * reconnect leaves, and its closed connection answers the call instead. One - * this host is connecting to isn't registered yet, and - * mcplServerConnectingText answers for it. */ + * reconnect leaves, and its closed connection answers the call instead. + * mcplServerConnectingText answers for one this host is connecting to: a + * legacy server, which isn't registered yet, or a modern connection, which + * is, until its first session is up. */ function mcplServerGoneText(serverId: string, toolName: string): string { return `The "${serverId}" server that provides ${toolName} isn't connected, and this host won't reconnect to it on its own, ` + "so the call didn't run. If you need it, ask whoever runs this host."; @@ -157,7 +158,9 @@ function mcplServerGoneText(serverId: string, toolName: string): string { /** A tool call refused while this host connects to its server, in a * runtime connect or a restart's: the server's prefix routes calls to it - * before the server is registered, which it is once its connect is done. */ + * before a legacy server is registered, which it is once its connect is + * done, and to a modern connection, registered before it starts, until its + * first session is up (modernStillConnecting). */ function mcplServerConnectingText(serverId: string, toolName: string): string { return `This host is connecting to the "${serverId}" server that provides ${toolName}, so the call didn't run. ` + 'Try again in a moment.'; @@ -171,12 +174,11 @@ function mcplToolDeniedText(serverId: string, toolName: string): string { "and calling it again won't change that. If you need it, ask whoever runs this host."; } -/** A runtime connect or restart refused because a legacy connect of the - * server's id is still in its handshake, before its server is registered - * (mcpServerIdTaken). A modern connect registers its connection first, so an - * id it holds reads as already registered. A disconnect isn't refused: it - * ends the connect in flight, in either engine. Whoever asked reads it: an - * operator, or an agent through a host's tool that passes it on. */ +/** A runtime connect or restart refused because a connect of the server's id + * is in flight, in either engine, whether or not it has registered its + * server yet (mcpServerIdTaken). A disconnect isn't refused: it ends that + * connect. Whoever asked reads it: an operator, or an agent through a host's + * tool that passes it on. */ function mcplConnectInFlightText(serverId: string): string { return `MCPL server "${serverId}" has a connect in flight; try again once it settles`; } @@ -18307,7 +18309,7 @@ export class AgentFramework { } const modern = this.modernServers().get(serverId) ?? null; const server = modern ? null : this.mcplServerRegistry.getServer(serverId); - if (!modern && !server) { + if ((!modern && !server) || this.modernStillConnecting(modern)) { return { success: false, error: this.mcplServerAbsentText(serverId, call.name), isError: true }; } const config = this.mcplServerConfigs.get(serverId); @@ -22948,14 +22950,19 @@ export class AgentFramework { const collision = this.mcplPrefixCollision(config, undefined, claim); if (collision) throw new Error(collision); + // The id is refused here too, before the trees are read, so a connect + // refused for its id reads nothing and reports only its refusal. The + // connect asks again as it takes the id, with nothing awaited between. + const taken = this.mcpServerIdTaken(config.id, claim); + if (taken) throw new Error(taken); // The server's restored host-managed trees are read before the server is // added, so a read that fails leaves it unconnected; MCPL itself stays // up, even when this connect brought it up. A feature set with no // restored tree, as after a disconnect removed it, is read when it - // registers. A server already connected is refused by addServer below, - // so its trees are left as they are. - if (!this.mcplServerRegistry?.getServer(config.id)) this.checkpointManager?.loadHostStates(config.id); + // registers. A server already registered was refused just above, so the + // read never reaches a registered server's trees. + this.checkpointManager?.loadHostStates(config.id); const oldToolNames = new Set(this.mcplTools.map(t => t.name)); const connection = await this.connectMcplServerInternal(config, false, claim); // A stop() that began during the connect's setup or its tool listing @@ -23235,11 +23242,14 @@ export class AgentFramework { } // A disconnect of the id began during the restart, and has finished. if (claim?.endedBy) return claim.endedBy; + // A connect in flight, in either engine: a legacy one registers its + // server once its handshake is done, and a modern one registers its + // connection before it starts. Whatever the id has registered meanwhile + // is that connect's. + if (op) return `${refused}${mcplConnectInFlightText(id)}`; const registered = this.modernServers().get(id) ?? this.mcplServerRegistry?.getServer(id); - // A connect in flight that hasn't registered its server yet. - if (op && !registered) return `${refused}${mcplConnectInFlightText(id)}`; - if (op || registered) { - const idle = !op && registered && !registered.isConnected && !registered.willReconnect; + if (registered) { + const idle = !registered.isConnected && !registered.willReconnect; return `${refused}MCPL server "${id}" is already registered${idle ? ' (not connected and not reconnecting: disconnect it first)' : ''}`; } return null; @@ -24427,18 +24437,27 @@ export class AgentFramework { } } - /** The refusal of a tool call whose server isn't registered, for the - * model's call and a script's alike: "connecting" while a connect of its - * id is in flight (mcpServerOps) or a restart holds the id, and "gone" - * otherwise. A legacy connect registers its server once its handshake is - * done; a modern connect registers its connection first, so a call during - * it reads that connection's own refusal. */ + /** The refusal of a tool call whose server isn't one to call yet, for the + * model's call, a script's and an in-process one alike: none registered, + * or a modern connection whose connect is still under way + * (modernStillConnecting). It says "connecting" while a connect of its id + * is in flight (mcpServerOps) or a restart holds the id, and "gone" + * otherwise. */ private mcplServerAbsentText(serverId: string, toolName: string): string { return this.mcpServerOps?.get(serverId)?.kind === 'connect' || this.restartClaims().ids.has(serverId) ? mcplServerConnectingText(serverId, toolName) : mcplServerGoneText(serverId, toolName); } + /** A modern connection a connect still under way registered: it registers + * before it starts, so until its first session is up it's no server to + * call, and a call reads the "connecting" text, as one during a legacy + * connect's handshake does. Once that session is up, a call goes to it, + * even while the connect lists its tools. */ + private modernStillConnecting(modern: ModernMcpConnection | null): boolean { + return modern !== null && !modern.isConnected && this.mcpServerOps?.get(modern.id)?.kind === 'connect'; + } + /** * Dispatch a tool call to an MCPL server. * Strips the configured toolPrefix and routes to the server. @@ -24448,7 +24467,7 @@ export class AgentFramework { const modern = this.modernServers().get(serverId) ?? null; const server = modern ? null : this.mcplServerRegistry!.getServer(serverId); - if (!modern && !server) { + if ((!modern && !server) || this.modernStillConnecting(modern)) { // RFC-007: refused before executing — no lifecycle events. this.toolLifecycleEmitter?.refuse(agentName, call.id); this.pushEvent({ diff --git a/src/mcpl/log-value.ts b/src/mcpl/log-value.ts index 905d58372..8ddb7d75a 100644 --- a/src/mcpl/log-value.ts +++ b/src/mcpl/log-value.ts @@ -45,6 +45,16 @@ export function logValue(value: unknown): string { return printed(textOf(value), FIELD); } +/** + * `logValue` of a value a server chose whose text may hold a credential: + * its text, as logValue reads it (a JSON value as its JSON text), with + * `redact` applied, then printed as logValue prints a field. A value whose + * text holds nothing `redact` replaces prints exactly as logValue prints it. + */ +export function logValueRedacted(value: unknown, redact: (text: string) => string): string { + return printed(redact(textOf(value)), FIELD); +} + /** * The host's own message, as the free text that ends a log line after its * fields: `reason=coalesce-invalid field=payload.content: "content must be an diff --git a/src/mcpl/modern-connection.ts b/src/mcpl/modern-connection.ts index 348327fe6..022b48954 100644 --- a/src/mcpl/modern-connection.ts +++ b/src/mcpl/modern-connection.ts @@ -70,6 +70,8 @@ import { StdioTransport, type McplTransport } from './transport.js'; import { McplProtocolVersionError, McplRequestError, McplUnreapedLaunchError } from './server-connection.js'; import { LEGACY_MCP_PROTOCOL_VERSION, MAX_TIMER_MS, MODERN_MCP_PROTOCOL_VERSION, checkServerConfig, describeCredentialError, noteDialSent, redactServerText, serverTextRedactor } from './protocol-family.js'; import type { McplServerConfig, McpToolDefinition } from './types.js'; +import { boundedForLog } from './errors.js'; +import { logDetail, logValue, logValueRedacted } from './log-value.js'; const DEFAULT_REQUEST_TIMEOUT_MS = 60_000; /** Bound on establishing the connection (`server/discover`), like the legacy @@ -113,12 +115,16 @@ interface WireRecord { /** * A send that Connectome's own transport refused before writing anything (its - * stdio line is closed): nothing of that request reached the server. + * stdio line is closed): nothing of that request reached the server. `pipe`: + * the child's stdin or stdout had failed, so this host can no longer write to + * that server at all. */ class NotWrittenError extends Error { - constructor(message: string) { + readonly pipe: boolean; + constructor(message: string, pipe = false) { super(message); this.name = 'NotWrittenError'; + this.pipe = pipe; } } @@ -315,7 +321,7 @@ class SpawnerStdioTransport implements Transport { // Once the child's stdin or stdout has failed, the line is ending it and // writes nothing more to it, so a message is refused here as not sent. const failed = this.line.pipeFailure; - if (failed) throw new NotWrittenError(`MCP server "${this.config.id}" stdio pipe failed with ${failed.message}`); + if (failed) throw new NotWrittenError(`MCP server "${this.config.id}" stdio pipe failed with ${failed.message}`, true); this.line.writeLine(JSON.stringify(message)); } @@ -858,7 +864,7 @@ export class ModernMcpConnection extends EventEmitter { */ async callTool(name: string, args: Record): Promise { const timeoutMs = this.requestTimeoutMs; - const result = await this.request('tools/call', `tools/call "${name}"`, (client) => + const result = await this.request('tools/call', `tools/call ${logValue(name)}`, (client) => client.callTool( { name, arguments: args }, { timeout: timeoutMs, maxTotalTimeout: timeoutMs, signal: AbortSignal.timeout(timeoutMs) }, @@ -872,18 +878,29 @@ export class ModernMcpConnection extends EventEmitter { } /** Run one logical request in a wire scope, and classify its failure by - * what that scope saw. */ + * what that scope saw. `what` names the request in the host's log: its + * method, and a tool call's tool as a log field. */ private async request(method: string, what: string, run: (client: Client) => Promise, timeoutMs?: number): Promise { const session = this.session; if (!session) { - // Connectome refuses before anything reaches the SDK: provably not sent. - throw new McplRequestError(`Cannot send ${what}: connection to "${this.id}" is not established`, 'not-sent'); + // Connectome refuses before anything reaches the SDK: provably not + // sent. In the agent's words, as the legacy engine's request on a + // closed connection: after this host's own close, only that holds; + // otherwise the connection is closed, and whether this host is + // reconnecting says what works from there. + throw new McplRequestError( + this.closedByHost + ? `The request wasn't sent: this host closed its connection to the "${this.id}" server, so nothing ran. ` + + 'If calling it again fails, ask whoever runs this host.' + : `The request wasn't sent: the connection to the "${this.id}" server is closed, so nothing ran. ${this.retryText()}`, + 'not-sent', + ); } const record: WireRecord = { method, handedOff: false, answer: 'none', continued: false }; try { return await wireScope.run(record, () => run(session.client)); } catch (error) { - throw this.requestFailure(what, record, error, timeoutMs); + throw this.requestFailure(what, record, error, timeoutMs, session.lost); } finally { session.wire.forget(record); } @@ -982,6 +999,14 @@ export class ModernMcpConnection extends EventEmitter { } } + /** What works from here after a request that didn't run, by whether this + * host is reconnecting to the server, in the legacy engine's words. */ + private retryText(): string { + return this.willReconnect + ? 'This host is reconnecting to it; try again later.' + : "This host won't reconnect to it on its own. If you need it, ask whoever runs this host."; + } + /** * Map a failure onto the request-outcome contract by what crossed the * transport boundary for this request, claiming no more than that shows. @@ -992,7 +1017,7 @@ export class ModernMcpConnection extends EventEmitter { * Connectome's stdio line refused before writing, an HTTP refusal before * any request went out); * - the most recent leg answered with a JSON-RPC error: `error-response` - * with that error's data, and its code in the message; + * with that error's data; * - the most recent leg answered with a complete result: the server * finished, but what it returned can't be used (output validation). * That's a plain error, not a request outcome; @@ -1011,69 +1036,147 @@ export class ModernMcpConnection extends EventEmitter { * already have acted on the call; * - handed off and unanswered: `no-response`. At the deadline, cancellation * was requested and the outcome is unknown. - * A `tools/list` failure says so: listing changes nothing on the server, so - * a retry is safe, where a tool call's retry may duplicate a side effect. + * + * The message is the agent's, in the legacy engine's words where it has + * words for the same outcome (#506), and in their shape where it hasn't: + * what happened, whether anything took effect, and what works from there. + * A request this host's close cut off, and one whose connection closed + * under it (`lost`), read as the legacy engine's do. The method, the tool, + * the JSON-RPC code, the HTTP status, the deadline in milliseconds and the + * SDK's or transport's words are the operator's, so they go to one log + * line, the server's text redacted. Where the effect is in doubt, a tool + * call's message says to check it before trying again, and a listing's that + * listing changes nothing on the server, so trying again is safe. */ - private requestFailure(what: string, record: WireRecord, error: unknown, timeoutMs?: number): Error { - const prefix = `MCP server "${this.id}"`; + private requestFailure(what: string, record: WireRecord, error: unknown, timeoutMs?: number, lost = false): Error { + const server = `the "${this.id}" server`; + const Server = `The "${this.id}" server`; const message = redactServerText(error instanceof Error ? error.message : String(error), this.config); - const advice = record.method === 'tools/list' - ? 'Listing changes nothing on the server, so it is safe to retry.' - : 'Verify state before retrying; a blind retry of a side-effecting tool may duplicate it.'; + const log = (line: string) => console.error(`MCP server "${this.id}" ${line}`); + const listing = record.method === 'tools/list'; + // What a failure whose effect is in doubt says: for a tool call, that the + // effect is unknown and to check it; for a listing, that it's safe to ask + // again. + const unknown = (said: string) => listing + ? `${said}. Listing changes nothing on the server, so it's safe to try again.` + : `${said}, so whether the request took effect is unknown. Check its effect before trying again.`; if (!record.handedOff) { - return new McplRequestError(`${prefix} ${what} was not sent: ${message}`, 'not-sent'); + log(`${what} not sent: ${logDetail(message)}`); + const pipe = error instanceof NotWrittenError && error.pipe; + return new McplRequestError( + pipe + ? `The request wasn't sent: this host can no longer write to ${server}, so nothing ran. ${this.retryText()}` + // Before the wire, the cause can pass (the stdio line closing as + // the connection is lost) or stay (a tool's outputSchema the SDK + // can't compile), so the message claims neither. + : `The request wasn't sent: this host couldn't send it to ${server}, so nothing ran. If calling it again fails, ask whoever runs this host.`, + 'not-sent', + ); } if (record.answer === 'error' && record.error) { const { code, message: wireMessage, data } = record.error; - return new McplRequestError(`${prefix} returned error for ${what}: [${code}] ${wireMessage}`, 'error-response', data); + // A JSON-RPC answer reaches the caller unredacted (redactServerText's + // scope). The log is a record of the server's text, so the message is + // redacted there, whatever JSON value it is, as every other line this + // connection writes is. + log(`answered ${what} with error ${logValue(code)}: ${logValueRedacted(wireMessage, (text) => redactServerText(text, this.config))}`); + // The server's own words, bounded as errors.ts says. Only a string is + // words: a message of any other JSON value reads as none. + const said = typeof wireMessage === 'string' ? boundedForLog(wireMessage.trim()) : ''; + return new McplRequestError( + said ? `${Server} answered with an error: ${said}` : unknown(`${Server} answered with an error without saying what went wrong`), + 'error-response', + data, + ); } if (record.answer === 'complete') { - return new Error(`${prefix} answered ${what}, but the result can't be used: ${message}`); + log(`answered ${what} with a result this host can't use: ${logDetail(message)}`); + return new Error(unknown(`${Server} answered, but not in a form this host can read`)); } const deadline = error instanceof SdkError && error.code === SdkErrorCode.RequestTimeout; const within = deadline && timeoutMs ? ` within ${timeoutMs}ms` : ''; if (record.answer === 'input-required' || record.answer === 'unrecognized') { const reason = /[.!?]$/.test(message) ? message : `${message}.`; - const ending = record.answer === 'unrecognized' - ? `its answer was not a complete result: ${reason}` + log(record.answer === 'unrecognized' + ? `did not finish ${what}${within}: its answer was not a complete result: ${logDetail(reason)}` : deadline - ? 'it asked for another round (input_required), and the deadline passed before that round was sent, so nothing was in flight to cancel.' - : `it asked for another round (input_required), and the call ended before that round was sent: ${reason}`; + ? `did not finish ${what}${within}: it asked for another round (input_required), and the deadline passed before that round was sent` + : `did not finish ${what}: it asked for another round (input_required), and the call ended before that round was sent: ${logDetail(reason)}`); return new McplRequestError( - `${prefix} did not finish ${what}${within}: ${ending} ` + - `The outcome is unknown: the server may already have acted on the call. ${advice}`, + unknown(record.answer === 'unrecognized' + ? `${Server}'s answer wasn't a complete result` + : `${Server} didn't finish the request: it asked for more from this host, and ${deadline ? 'the time ran out' : 'the call ended'} before this host sent it`), 'no-response', ); } // An HTTP refusal of the credential: 401 or 403, however the SDK raised // it. It raises a plain 403 under another code than its step-up limit's, // and an insufficient_scope 403 as InsufficientScopeError when no OAuth - // provider is configured. + // provider is configured. A 403 can refuse a valid credential that lacks + // permission, so the message says the server refused this host access. const refusedWith = error instanceof SdkHttpError && (error.status === 401 || error.status === 403) ? error.status : error instanceof InsufficientScopeError ? 403 : null; if (refusedWith !== null) { if (record.continued) { + log(`refused a later round of ${what}: HTTP ${refusedWith} (${logDetail(message)})`); return new McplRequestError( - `${prefix} did not finish ${what}: it asked for another round (input_required), and the server refused a later one: ` + - `HTTP ${refusedWith} (${message}). The outcome is unknown: the server may already have acted on the call. ${advice}`, + listing + ? unknown(`${Server} refused this host access partway through the request, after asking for more`) + : `${Server} refused this host access partway through the request, after asking for more, so whether it took effect is unknown. ` + + 'Check its effect before trying again; if calling it again fails, ask whoever runs this host.', 'no-response', ); } + log(`refused ${what}: HTTP ${refusedWith} (${logDetail(message)})`); // The response body (the SDK's `text`) is the server's text and can // echo the request's url, so it's left out of the data; the status stays. const { text: _body, ...data } = (error instanceof SdkHttpError && error.data && typeof error.data === 'object' ? error.data : {}) as Record; - return new McplRequestError(`${prefix} refused ${what}: HTTP ${refusedWith} (${message})`, 'error-response', { ...data, httpStatus: refusedWith }); + return new McplRequestError( + `${Server} refused this host access, so the request didn't run. If you need it, ask whoever runs this host.`, + 'error-response', + { ...data, httpStatus: refusedWith }, + ); } if (deadline) { - const outcome = record.method === 'tools/list' - ? 'the list did not arrive in time.' - : 'the outcome is unknown: the tool may still complete server-side.'; + log(`didn't answer ${what}${within}; cancellation requested`); + const seconds = timeoutMs ? timeoutMs / 1000 : null; + const late = seconds === null ? `${Server} didn't answer in time` : `${Server} didn't answer within ${seconds} second${seconds === 1 ? '' : 's'}`; return new McplRequestError( - `${prefix} did not answer ${what}${within}. Cancellation was requested; ${outcome} ${advice}`, + listing + ? `${late}, and this host asked it to cancel. Listing changes nothing on the server, so it's safe to try again.` + : `${late}, so whether the request took effect is unknown: this host asked it to cancel, and it may still complete on the server. ` + + 'Check its effect before trying again, since repeating something that changes state may do it twice.', 'no-response', ); } - return new McplRequestError(`${prefix} ${what} failed: ${message}`, 'no-response'); + // Anything else after the request went out. An HTTP status other than + // 401/403 is only in the SDK's error, not its message, so the log names it. + log(`${what} failed${error instanceof SdkHttpError ? ` with HTTP ${error.status}` : ''}: ${logDetail(message)}`); + if (this.closedByHost) { + // This host's close cut it off: the legacy engine's words. + return new McplRequestError(unknown(`${Server} didn't answer before this host closed its connection`), 'no-response'); + } + if (lost) { + // The connection closed under it: the legacy engine's words, with + // whether this host is reconnecting. + return new McplRequestError( + listing + ? unknown(`The connection to ${server} closed before it answered`) + : `The connection to ${server} closed before it answered, so whether the request took effect is unknown. ` + + (this.willReconnect + ? 'Check its effect before trying again; this host is reconnecting to it.' + : "This host won't reconnect to it on its own. If you need it, ask whoever runs this host."), + 'no-response', + ); + } + // The connection may still stand, as after an HTTP error with no JSON-RPC + // answer, so the message says nothing of reconnecting. + return new McplRequestError( + listing + ? `The request to ${server} failed before an answer came back. Listing changes nothing on the server, so it's safe to try again.` + : `The request to ${server} failed before an answer came back, so whether it took effect is unknown. Check its effect before trying again.`, + 'no-response', + ); } } diff --git a/src/mcpl/protocol-family.ts b/src/mcpl/protocol-family.ts index 3c2b6e3b1..c2def6aeb 100644 --- a/src/mcpl/protocol-family.ts +++ b/src/mcpl/protocol-family.ts @@ -107,19 +107,21 @@ export function redactUrl(url: string | undefined): string { * short password goes with its username and a short username alone goes * too, and the Basic credential a WebSocket client sends for that userinfo; * - the static token, and each token an access provider handed a dial for - * a header, raw, as JSON encoders write it (JSON.stringify's escapes, and - * with its slashes escaped too, as some encoders write them), and percent- - * or form-encoded with either case of hex; + * a header, raw, and percent- or form-encoded with either case of hex; * - a stdio server's environment values whose names say they're - * credentials, raw, as JSON encoders write them, and percent-encoded with - * either case of hex. + * credentials, raw, and percent-encoded with either case of hex. + * Each of these strings, from every source, the name=value pairs and + * userinfo units too, is also replaced as JSON encoders write it: + * JSON.stringify's escapes (a quote, a backslash, a control character), and + * with its slashes escaped too, as some encoders write them. * A string replaced on its own has at least 8 characters, since a shorter * one can't be told from ordinary text, and it is replaced wherever it * occurs, after an escape or inside a longer token too. A query parameter is * also replaced as its whole name=value, only where no letter or digit - * adjoins the pair, so v=2 leaves dev=2 alone; a short value goes only that - * way. Every place one of these matches is replaced, overlapping places - * included, and the replacement is never scanned again; text that may come + * adjoins the pair, so v=2 leaves dev=2 alone (a JSON escape before it, such + * as \n, isn't one); a short value goes only that way. Every place one of + * these matches is replaced, overlapping places included, and the + * replacement is never scanned again; text that may come * from several servers takes one pass over all their configurations' * strings (serverCredentialPatterns), so strings of different servers that * overlap are both replaced whole. A credential neither the configuration @@ -235,27 +237,21 @@ export function serverCredentialPatterns(config: Pick(); + const standalones = new Set(); const pairs = new Set(); const userinfo = new Set(); - const standalone = (value: string): void => { if (value.length >= 8) secrets.add(value); }; + const standalone = (value: string): void => { standalones.add(value); }; const decode = (value: string, query = false): string => { try { return decodeURIComponent(query ? value.replace(/\+/g, ' ') : value); } catch { return value; } }; // Percent-escapes in lowercase hex, as some encoders write them. const lowerEscapes = (value: string): string => value.replace(/%[0-9A-F]{2}/g, (escape) => escape.toLowerCase()); - // A string as written; as JSON encoders write it, with JSON.stringify's - // escapes (a quote, a backslash, a control character) and with its - // slashes escaped too, as some encoders write them; and percent-encoded in - // either case of hex (a string encodeURIComponent refuses, such as one - // with an unpaired surrogate, has no encoded form). + // A string as written, and percent-encoded in either case of hex (a string + // encodeURIComponent refuses, such as one with an unpaired surrogate, has + // no encoded form). Its JSON forms come with every other string's, below. const withEncoded = (value: string): void => { - const json = JSON.stringify(value).slice(1, -1); - for (const written of [value, json]) { - standalone(written); - standalone(written.replace(/\//g, '\\/')); - } + standalone(value); let encoded: string; try { encoded = encodeURIComponent(value); } catch { return; /* no percent-encoded form */ } standalone(encoded); @@ -341,11 +337,33 @@ export function serverCredentialPatterns(config: Pick, floor: number): Set => { + const forms = new Set(); + for (const value of values) { + const json = JSON.stringify(value).slice(1, -1); + for (const written of [value, json]) { + for (const form of [written, written.replace(/\//g, '\\/')]) if (form.length >= floor) forms.add(form); + } + } + return forms; + }; const escape = (value: string): string => value.replace(/[.*+?^${}()|[\]\\]/g, '\\$&'); + // Where a pair or userinfo unit may start: where no letter or digit + // adjoins it, at the text's start or after any other character, or after a + // JSON escape that ends in one (\b \f \n \r \t, \uXXXX), as a value's JSON + // text writes a control character before it. + const start = String.raw`(?<=^|[^A-Za-z0-9]|\\[bfnrt]|\\u[0-9A-Fa-f]{4})`; return [ - ...[...secrets].map(value => ({ value, source: escape(value) })), - ...[...pairs].map(value => ({ value, source: `(? ({ value, source: `(? ({ value, source: escape(value) })), + ...[...withJsonForms(pairs, 0)].map(value => ({ value, source: `${start}${escape(value)}(?![A-Za-z0-9])` })), + ...[...withJsonForms(userinfo, 0)].map(value => ({ value, source: `${start}${escape(value)}(?=@)` })), ]; } diff --git a/src/mcpl/server-connection.ts b/src/mcpl/server-connection.ts index 89d5dbf55..2aa2193da 100644 --- a/src/mcpl/server-connection.ts +++ b/src/mcpl/server-connection.ts @@ -15,7 +15,7 @@ import { openTransport, STDERR_END_WAIT_MS, type McplTransport, type TransportCl import { maskNegotiatedCapabilities } from './capability-mask.js'; import { CapabilityGrant, expandAdvertisementShorthand } from './capability-grant.js'; import { CAPABILITY_DISABLED, boundedForLog, describeCause } from './errors.js'; -import { logDetail, logValue } from './log-value.js'; +import { logDetail, logValue, logValueRedacted } from './log-value.js'; import { LEGACY_MCP_PROTOCOL_VERSION, MODERN_MCP_PROTOCOL_VERSION, @@ -844,10 +844,11 @@ export class McplServerConnection extends EventEmitter { connection.allowHostCommands = config.allowHostCommands === true; connection.requestTimeoutMs = config.requestTimeoutMs ?? DEFAULT_REQUEST_TIMEOUT_MS; - // Store config for reconnection. Only `true` turns reconnect on, as at + // Its configuration, which a reconnect reads and every log line of the + // server's text redacts with. Only `true` turns reconnect on, as at // every other reader of it. + connection.config = config; if (config.reconnect === true) { - connection.config = config; connection.hostCapabilities = hostCapabilities; connection.reconnectEnabled = true; connection.reconnectIntervalMs = config.reconnectIntervalMs ?? 5000; @@ -2089,12 +2090,17 @@ export class McplServerConnection extends EventEmitter { // errors.ts says, since they're the server's text. Only a string is // words: a message of any other JSON value reads as none. The method, // id and JSON-RPC code are the operator's, so they go to the log, which - // prints any value a server can send without throwing (logValue). + // prints any value a server can send without throwing (logValue). The + // caller's text keeps the server's words unredacted, as a JSON-RPC + // answer passes (redactServerText's scope); the log is a record of the + // server's text, so the message is redacted there, whatever JSON value + // it is, as every other line this connection writes is. const said = typeof response.error.message === 'string' ? boundedForLog(response.error.message.trim()) : ''; - console.error( - `MCPL server "${this.id}" answered ${pending.method} (id=${response.id}) with error ${logValue(response.error.code)}: ` + - logValue(response.error.message), - ); + // The call is settled before its log line: its entry is gone and its + // timer cleared, so nothing else would settle it, and a host's logger + // can throw. The dispatch's containment reports such a throw. (A + // configuration that can't be read withholds the message rather than + // throw: redactServerText.) pending.reject(new McplRequestError( said ? `The "${this.id}" server answered with an error: ${said}` @@ -2103,6 +2109,10 @@ export class McplServerConnection extends EventEmitter { 'error-response', (response.error as { data?: unknown }).data, )); + console.error( + `MCPL server "${this.id}" answered ${pending.method} (id=${response.id}) with error ${logValue(response.error.code)}: ` + + logValueRedacted(response.error.message, (text) => redactServerText(text, this.config ?? {})), + ); } else { pending.resolve(response.result); } diff --git a/test/mcp-modern-connection.test.ts b/test/mcp-modern-connection.test.ts index 615d807fe..a3129282f 100644 --- a/test/mcp-modern-connection.test.ts +++ b/test/mcp-modern-connection.test.ts @@ -113,8 +113,7 @@ test('a deadline requests cancellation and reports no-response, outcome unknown' await assert.rejects(connection.callTool('slow', { ms: 20_000 }), (err: unknown) => { assert.ok(err instanceof McplRequestError); assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /did not answer tools\/call "slow" within 300ms/); - assert.match(err.message, /Cancellation was requested; the outcome is unknown/); + assert.match(err.message, /^The "modern" server didn't answer within 0\.3 seconds, so whether the request took effect is unknown: this host asked it to cancel/); return true; }); assert.ok(!lines(join(dir, 'events.log')).includes('slow-finished'), 'rejected at the deadline, not at the tool\'s end'); diff --git a/test/mcp-modern-framework.test.ts b/test/mcp-modern-framework.test.ts index 82e5c88bf..63f0d62c9 100644 --- a/test/mcp-modern-framework.test.ts +++ b/test/mcp-modern-framework.test.ts @@ -518,7 +518,7 @@ test('quiesce: a lost modern child reconnects and relists without starting a tur }); }); -test('the framework owns a modern connect in flight: stop() ends it, and a second connect is refused', async () => { +test("the framework owns a modern connect in flight: a second connect is refused in #506's words, a tool call reads the connecting text, and stop() ends it", async () => { const RAW = join(here, 'fixtures', 'modern-raw-server.mjs'); const dir = mkdtempSync(join(tmpdir(), 'modern-framework-')); const framework = await AgentFramework.create({ @@ -532,7 +532,12 @@ test('the framework owns a modern connect in flight: stop() ends it, and a secon const config = { id: 'hang', command: process.execPath, args: [RAW, 'hang-discover', log], protocol: 'modern' as const }; const pending = framework.connectMcplServer(config); await waitFor('the launch waiting on discover', () => lines(log).some((l) => l.includes('server/discover'))); - await assert.rejects(framework.connectMcplServer(config), /already registered/); + await assert.rejects(framework.connectMcplServer(config), /^Error: MCPL server "hang" has a connect in flight; try again once it settles$/); + // Its connection is registered before it starts, and not one to call yet. + const during = await framework.executeToolCall({ id: 'during', name: 'mcpl--hang--echo', input: {} }); + assert.equal(during.success, false); + assert.equal(during.error, 'This host is connecting to the "hang" server that provides mcpl--hang--echo, so the call didn\'t run. Try again in a moment.'); + assert.equal(lines(log).filter((l) => l.includes('tools/call')).length, 0, 'nothing reached the server'); const pid = (JSON.parse(lines(log)[0]!) as { pid: number }).pid; // stop() ends the connect in flight rather than waiting for its handshake. const stopping = Date.now(); diff --git a/test/mcp-modern-http.test.ts b/test/mcp-modern-http.test.ts index 6e7a07448..aef71c105 100644 --- a/test/mcp-modern-http.test.ts +++ b/test/mcp-modern-http.test.ts @@ -123,7 +123,7 @@ test('HTTP: a deadline aborts the request stream, and the server sees the cancel await assert.rejects(connection.callTool('slow', { ms: 1500 }), (err: unknown) => { assert.ok(err instanceof McplRequestError); assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /Cancellation was requested/); + assert.match(err.message, /this host asked it to cancel/); return true; }); const deadline = Date.now() + 3000; @@ -153,7 +153,9 @@ test('HTTP: an auth wall on a call is an error-response with the status in data' }); }); -test('HTTP: an auth wall on a later round of a call is a no-response, since the first round may have acted', async () => { +test('HTTP: an auth wall on a later round of a call is a no-response, since the first round may have acted', async (t) => { + const consoleLines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => consoleLines.push(args.map(String).join(' '))); // The SDK server can't be made to ask for another round, so `cont`, which // it doesn't list, is answered here: a state-only input_required for the // first round, then 401 for every later one. @@ -179,14 +181,16 @@ test('HTTP: an auth wall on a later round of a call is a no-response, since the // Not the error-response a refused first round gets: the server took // the first round, and may have acted on it. assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /asked for another round \(input_required\), and the server refused a later one: HTTP 401/); + assert.equal(err.message, 'The "remote" server refused this host access partway through the request, after asking for more, ' + + 'so whether it took effect is unknown. Check its effect before trying again; if calling it again fails, ask whoever runs this host.'); return true; }); + assert.ok(consoleLines.some((line) => /^MCP server "remote" refused a later round of tools\/call cont: HTTP 401 \(/.test(line)), consoleLines.join('\n')); assert.equal(states[0], undefined, 'the first round carried no state'); assert.ok(states.length >= 2 && states.slice(1).every((s) => s === 'state-1'), `each later round carried it: ${JSON.stringify(states)}`); }); -test('HTTP: an echoed path in a tool transport failure is redacted, but a JSON-RPC error is the server answer', async (t) => { +test("HTTP: an echoed path in a tool transport failure is redacted in the log and kept from the agent's text, but a JSON-RPC error is the server answer", async (t) => { const consoleLines: string[] = []; t.mock.method(console, 'error', (...args: unknown[]) => consoleLines.push(args.map(String).join(' '))); const secret = 'pathSecret0123456789'; @@ -212,12 +216,16 @@ test('HTTP: an echoed path in a tool transport failure is redacted, but a JSON-R rpc = false; await assert.rejects(connection.callTool('echo', {}), (error: unknown) => { assert.ok(error instanceof McplRequestError); - assert.match(error.message, /Cannot POST \/api\/mcp\/s\/redacted\/mcp/); - assert.ok(!error.message.includes(secret)); + // The transport's words are the operator's: the log has them, redacted. + assert.equal(error.message, 'The request to the "remote" server failed before an answer came back, so whether it took effect is unknown. ' + + 'Check its effect before trying again.'); assert.equal(error.outcome, 'no-response'); return true; }); - assert.ok(consoleLines.some(line => line.includes('Cannot POST /api/mcp/s/redacted/mcp'))); + // The status is only in the SDK's error, so the log names it. + assert.ok(consoleLines.some(line => /^MCP server "remote" tools\/call echo failed with HTTP 500: .*Cannot POST \/api\/mcp\/s\/redacted\/mcp/.test(line)), consoleLines.join('\n')); + // The answer's log line is a record of the server's text, so it's redacted. + assert.ok(consoleLines.includes('MCP server "remote" answered tools/call echo with error -32603: redacted'), consoleLines.join('\n')); assert.ok(!consoleLines.join('\n').includes(secret)); const dir = mkdtempSync(join(tmpdir(), 'mcp-tool-transport-')); const framework = await AgentFramework.create({ @@ -229,7 +237,7 @@ test('HTTP: an echoed path in a tool transport failure is redacted, but a JSON-R try { const result = await framework.executeToolCall({ id: 'echo-failed', name: 'mcpl--remote--echo', input: {} }); assert.equal(result.success, false); - assert.match(result.error!, /Cannot POST \/api\/mcp\/s\/redacted\/mcp/); + assert.match(result.error!, /^The request to the "remote" server failed before an answer came back/); assert.ok(!JSON.stringify(result).includes(secret), 'the model-facing tool result contains no path credential'); } finally { await framework.stop(); diff --git a/test/mcp-modern-outcomes.test.ts b/test/mcp-modern-outcomes.test.ts index b948f3697..e32cd6200 100644 --- a/test/mcp-modern-outcomes.test.ts +++ b/test/mcp-modern-outcomes.test.ts @@ -6,7 +6,8 @@ * - an SDK-local rejection before dispatch is `not-sent` (0 calls on the wire); * - a result that fails validation is an answer that can't be used (1 call, * answered), never a claimed server error; - * - a JSON-RPC error on the wire is `error-response` with its code and data; + * - a JSON-RPC error on the wire is `error-response` with its data, and its + * code goes to the log line; * - a call that ends after an `input_required` answer, before a final one, is * `no-response`: at the deadline (with nothing in flight to cancel), with * the connection gone, or when this client can't go on (PR #262 review); @@ -39,6 +40,19 @@ afterEach(async () => { while (cleanups.length) await cleanups.pop()!(); }); +/** The host's log lines (console.error) from here to the test's end. Call + * it before connecting, so it's restored after the connection closes. */ +function hostLog(): string[] { + const lines: string[] = []; + const original = console.error; + console.error = (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }; + cleanups.push(() => { console.error = original; }); + return lines; +} + +/** Whether one of `lines` matches `pattern`, for an assertion's message too. */ +const loggedLine = (lines: string[], pattern: RegExp) => assert.ok(lines.some((line) => pattern.test(line)), `${pattern} in:\n${lines.join('\n')}`); + function scratchLog(): string { const dir = mkdtempSync(join(tmpdir(), 'modern-raw-')); cleanups.push(() => rmSync(dir, { recursive: true, force: true })); @@ -68,31 +82,38 @@ async function connect(flags: string, log: string, extra: Partial { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('invalid-schema', log); await connection.listTools(); await assert.rejects(connection.callTool('op', {}), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'not-sent'); - assert.match(err.message, /tools\/call "op" was not sent: .*invalid outputSchema/); + assert.equal(err.message, 'The request wasn\'t sent: this host couldn\'t send it to the "raw" server, so nothing ran. ' + + 'If calling it again fails, ask whoever runs this host.'); return true; }); + loggedLine(logged, /^MCP server "raw" tools\/call op not sent: .*invalid outputSchema/); assert.equal(calls(log, 'op'), 0); }); test('a result that fails its outputSchema was answered: a plain error, not a server error', async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log); await connection.listTools(); await assert.rejects(connection.callTool('op', {}), (err: unknown) => { assert.ok(!(err instanceof McplRequestError), 'no request outcome is claimed'); - assert.match((err as Error).message, /answered tools\/call "op", but the result can't be used: .*output schema/); + assert.equal((err as Error).message, 'The "raw" server answered, but not in a form this host can read, so whether the request took effect ' + + 'is unknown. Check its effect before trying again.'); return true; }); + loggedLine(logged, /^MCP server "raw" answered tools\/call op with a result this host can't use: .*output schema/); assert.equal(calls(log, 'op'), 1); }); -test('a JSON-RPC error on the wire is error-response with its data, and its code in the message', async () => { +test("a JSON-RPC error on the wire is error-response with its data, the server's words in the message, and its code in the log", async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log); await connection.listTools(); @@ -100,9 +121,10 @@ test('a JSON-RPC error on the wire is error-response with its data, and its code assert.ok(err instanceof McplRequestError); assert.equal(err.outcome, 'error-response'); assert.deepEqual(err.data, { why: 'on purpose' }); - assert.match(err.message, /returned error for tools\/call "err": \[-32603\] boom/); + assert.equal(err.message, 'The "raw" server answered with an error: boom'); return true; }); + loggedLine(logged, /^MCP server "raw" answered tools\/call err with error -32603: boom$/); // The plain call on the same connection is unaffected. assert.deepEqual((await connection.callTool('plain', {})).content, [{ type: 'text', text: 'plain' }]); }); @@ -347,26 +369,32 @@ test('close() during a reconnect handshake ends the launch it was waiting on, an }); test('an input_required continuation keeps its evidence: the second leg decides the outcome', async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log, { requestTimeoutMs: 600 }); await connection.listTools(); await assert.rejects(connection.callTool('cont', { leg2: 'error' }), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'error-response'); - assert.match(err.message, /\[-32603\]/); + assert.match(err.message, /^The "raw" server answered with an error: /); assert.deepEqual(err.data, { leg: 2, state: 'state-for-error' }); return true; }); + loggedLine(logged, /^MCP server "raw" answered tools\/call cont with error -32603: /); await assert.rejects(connection.callTool('cont', { leg2: 'hang' }), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /Cancellation was requested/); + assert.equal(err.message, 'The "raw" server didn\'t answer within 0.6 seconds, so whether the request took effect is unknown: ' + + 'this host asked it to cancel, and it may still complete on the server. ' + + 'Check its effect before trying again, since repeating something that changes state may do it twice.'); return true; }); + loggedLine(logged, /^MCP server "raw" didn't answer tools\/call cont within 600ms; cancellation requested$/); assert.equal(calls(log, 'cont'), 4, 'two legs each'); }); test('a deadline between continuation rounds is no-response, and claims no cancellation', async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log, { requestTimeoutMs: 1500 }); await connection.listTools(); @@ -390,13 +418,12 @@ test('a deadline between continuation rounds is no-response, and claims no cance await assert.rejects(connection.callTool('cont', { leg1: 'elicit' }), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'no-response'); - assert.match( - err.message, - /did not finish tools\/call "cont" within 1500ms: it asked for another round \(input_required\), and the deadline passed before that round was sent, so nothing was in flight to cancel\. The outcome is unknown/, - ); - assert.doesNotMatch(err.message, /Cancellation was requested|answered/); + assert.equal(err.message, 'The "raw" server didn\'t finish the request: it asked for more from this host, and the time ran out ' + + 'before this host sent it, so whether the request took effect is unknown. Check its effect before trying again.'); + assert.doesNotMatch(err.message, /cancel|answered/); return true; }); + loggedLine(logged, /^MCP server "raw" did not finish tools\/call cont within 1500ms: it asked for another round \(input_required\), and the deadline passed before that round was sent$/); assert.ok(held, 'the round was held'); // The wire is ordered: once a later call has reached the server, any // second leg sent before it would have too. @@ -407,22 +434,23 @@ test('a deadline between continuation rounds is no-response, and claims no cance }); test('a connection lost between continuation rounds is no-response, not an answer', async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log); await connection.listTools(); await assert.rejects(connection.callTool('cont', { leg1: 'exit', leg2: 'ok' }), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'no-response'); - assert.match( - err.message, - /did not finish tools\/call "cont": it asked for another round \(input_required\), and the call ended before that round was sent: Not connected\. The outcome is unknown/, - ); + assert.equal(err.message, 'The "raw" server didn\'t finish the request: it asked for more from this host, and the call ended ' + + 'before this host sent it, so whether the request took effect is unknown. Check its effect before trying again.'); return true; }); + loggedLine(logged, /^MCP server "raw" did not finish tools\/call cont: it asked for another round \(input_required\), and the call ended before that round was sent: "Not connected\."$/); assert.equal(calls(log, 'cont'), 1); }); test('a continuation this client cannot go on with is no-response: the server may have acted', async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log); await connection.listTools(); @@ -430,37 +458,43 @@ test('a continuation this client cannot go on with is no-response: the server ma await assert.rejects(connection.callTool('cont', { leg1: 'elicit' }), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /it asked for another round \(input_required\), and the call ended before that round was sent: Cannot fulfil input request 'confirm'/); + assert.match(err.message, /^The "raw" server didn't finish the request: it asked for more from this host, and the call ended before this host sent it/); return true; }); + loggedLine(logged, /it asked for another round \(input_required\), and the call ended before that round was sent: "Cannot fulfil input request 'confirm'/); assert.equal(calls(log, 'cont'), 1); // A server that sheds load on every round meets the rounds cap: the first // leg and ten retries. await assert.rejects(connection.callTool('cont', { leg2: 'again' }), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /the call ended before that round was sent: Multi-round-trip request 'tools\/call' still required input after 10 rounds/); + assert.match(err.message, /and the call ended before this host sent it, so whether the request took effect is unknown/); return true; }); + loggedLine(logged, /the call ended before that round was sent: "Multi-round-trip request 'tools\/call' still required input after 10 rounds/); assert.equal(calls(log, 'cont'), 1 + 11); }); test('a result type this revision does not define, or none, is not a final answer: no-response', async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log); await connection.listTools(); await assert.rejects(connection.callTool('task', {}), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /did not finish tools\/call "task": its answer was not a complete result: Unsupported result type 'task'.*The outcome is unknown/); + assert.equal(err.message, 'The "raw" server\'s answer wasn\'t a complete result, so whether the request took effect is unknown. ' + + 'Check its effect before trying again.'); return true; }); + loggedLine(logged, /^MCP server "raw" did not finish tools\/call task: its answer was not a complete result: "Unsupported result type 'task'/); await assert.rejects(connection.callTool('bare', {}), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /did not finish tools\/call "bare": its answer was not a complete result: .*missing required resultType.*The outcome is unknown/); + assert.match(err.message, /^The "raw" server's answer wasn't a complete result, so whether the request took effect is unknown/); return true; }); + loggedLine(logged, /^MCP server "raw" did not finish tools\/call bare: its answer was not a complete result: .*missing required resultType/); assert.equal(calls(log, 'task'), 1); assert.equal(calls(log, 'bare'), 1); }); @@ -607,6 +641,7 @@ test('start() runs once: a second call shares the first connect, and no second s }); test('a send the stdio line refused before writing anything is not-sent', async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log); await connection.listTools(); @@ -618,9 +653,11 @@ test('a send the stdio line refused before writing anything is not-sent', async await assert.rejects(connection.callTool('plain', {}), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'not-sent'); - assert.match(err.message, /tools\/call "plain" was not sent: .*stdio transport is closed/); + assert.equal(err.message, 'The request wasn\'t sent: this host couldn\'t send it to the "raw" server, so nothing ran. ' + + 'If calling it again fails, ask whoever runs this host.'); return true; }); + loggedLine(logged, /^MCP server "raw" tools\/call plain not sent: .*stdio transport is closed/); } finally { line._closed = false; } @@ -628,6 +665,7 @@ test('a send the stdio line refused before writing anything is not-sent', async }); test('a plain call whose child dies before answering is no-response', async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('', log); connection.on('error', () => {}); @@ -635,18 +673,69 @@ test('a plain call whose child dies before answering is no-response', async () = await assert.rejects(connection.callTool('vanish', {}), (err: unknown) => { assert.ok(err instanceof McplRequestError, String(err)); assert.equal(err.outcome, 'no-response'); - assert.match(err.message, /MCP server "raw" tools\/call "vanish" failed: /); + // The connection closed under it: the legacy engine's words, and this + // connection doesn't reconnect. + assert.equal(err.message, 'The connection to the "raw" server closed before it answered, so whether the request took effect is unknown. ' + + "This host won't reconnect to it on its own. If you need it, ask whoever runs this host."); return true; }); + loggedLine(logged, /^MCP server "raw" tools\/call vanish failed: /); assert.equal(calls(log, 'vanish'), 1, 'the call reached the server'); }); +test("a request this host's close cuts off reads as the legacy engine's: the server didn't answer before this host closed its connection", async () => { + const logged = hostLog(); + const log = scratchLog(); + const connection = await connect('', log); + await connection.listTools(); + // The second leg is never answered, so only the close ends the call. + const pending = connection.callTool('cont', { leg2: 'hang' }); + const failure = pending.then(() => null, (error: unknown) => error); + await until(() => calls(log, 'cont') === 2, 'the second leg on the wire'); + await connection.close(); + const err = await failure; + assert.ok(err instanceof McplRequestError, String(err)); + assert.equal(err.outcome, 'no-response'); + assert.equal(err.message, 'The "raw" server didn\'t answer before this host closed its connection, so whether the request took effect is unknown. ' + + 'Check its effect before trying again.'); + loggedLine(logged, /^MCP server "raw" tools\/call cont failed: /); +}); + +for (const reconnect of [true, false]) { +test(`a call with no session to send it on is not-sent: after a loss, whether this host is reconnecting${reconnect ? '' : ' (it is not)'}; after this host's close, only that`, async () => { + const log = scratchLog(); + // A reconnect a minute away, so the connection stays lost while it's asked. + const connection = await connect('', log, reconnect ? { reconnect: true, reconnectIntervalMs: 60_000, reconnectMaxIntervalMs: 60_000 } : {}); + connection.on('error', () => { /* the loss */ }); + await connection.listTools(); + await assert.rejects(connection.callTool('vanish', {}), { + message: 'The connection to the "raw" server closed before it answered, so whether the request took effect is unknown. ' + + (reconnect ? 'Check its effect before trying again; this host is reconnecting to it.' : "This host won't reconnect to it on its own. If you need it, ask whoever runs this host."), + }); + await until(() => !connection.isConnected, 'the connection lost'); + const refused = async (message: string) => assert.rejects(connection.callTool('plain', {}), (err: unknown) => { + assert.ok(err instanceof McplRequestError, String(err)); + assert.equal(err.outcome, 'not-sent'); + assert.equal(err.message, message); + return true; + }); + await refused('The request wasn\'t sent: the connection to the "raw" server is closed, so nothing ran. ' + + (reconnect ? 'This host is reconnecting to it; try again later.' : "This host won't reconnect to it on its own. If you need it, ask whoever runs this host.")); + await connection.close(); + await refused('The request wasn\'t sent: this host closed its connection to the "raw" server, so nothing ran. ' + + 'If calling it again fails, ask whoever runs this host.'); + assert.equal(calls(log, 'plain'), 0, 'nothing reached a server'); +}); +} + test('failures are classified in order: nothing sent first, then the answers, then an HTTP refusal', () => { - const connection = ModernMcpConnection.create({ id: 'raw', command: process.execPath, args: [SERVER, '', scratchLog()], protocol: 'modern' }); - const classify = (record: Record, error: unknown, method = 'tools/call') => + const logged = hostLog(); + const token = 'tok-0123456789abcdef'; + const connection = ModernMcpConnection.create({ id: 'raw', command: process.execPath, args: [SERVER, '', scratchLog()], protocol: 'modern', env: { API_TOKEN: token } }); + const classify = (record: Record, error: unknown, method = 'tools/call', lost = false) => (connection as unknown as { - requestFailure: (what: string, record: unknown, error: unknown, timeoutMs?: number) => Error; - }).requestFailure(method === 'tools/list' ? 'tools/list' : 'tools/call "op"', { method, handedOff: true, answer: 'none', continued: false, ...record }, error, 1000); + requestFailure: (what: string, record: unknown, error: unknown, timeoutMs?: number, lost?: boolean) => Error; + }).requestFailure(method === 'tools/list' ? 'tools/list' : 'tools/call op', { method, handedOff: true, answer: 'none', continued: false, ...record }, error, 1000, lost); const refused = () => new SdkHttpError(SdkErrorCode.ClientHttpAuthentication, 'Unauthorized', { status: 401 } as never); const outcome = (error: Error) => (error instanceof McplRequestError ? error.outcome : 'plain'); @@ -656,15 +745,61 @@ test('failures are classified in order: nothing sent first, then the answers, th const first = classify({}, refused()); assert.equal(outcome(first), 'error-response'); assert.equal(((first as McplRequestError).data as { httpStatus?: number }).httpStatus, 401); + assert.equal(first.message, 'The "raw" server refused this host access, so the request didn\'t run. If you need it, ask whoever runs this host.'); + loggedLine(logged, /^MCP server "raw" refused tools\/call op: HTTP 401 \(/); const later = classify({ continued: true }, refused()); assert.equal(outcome(later), 'no-response', 'after an earlier leg asked for another round'); - assert.match(later.message, /asked for another round \(input_required\), and the server refused a later one: HTTP 401/); + assert.equal(later.message, 'The "raw" server refused this host access partway through the request, after asking for more, so whether it ' + + 'took effect is unknown. Check its effect before trying again; if calling it again fails, ask whoever runs this host.'); + loggedLine(logged, /^MCP server "raw" refused a later round of tools\/call op: HTTP 401 \(/); + assert.equal(classify({ continued: true }, refused(), 'tools/list').message, 'The "raw" server refused this host access partway through ' + + 'the request, after asking for more. Listing changes nothing on the server, so it\'s safe to try again.'); + + const silent = classify({ answer: 'error', error: { code: -32603, message: ' ' } }, new Error('the SDK\'s words')); + assert.equal(outcome(silent), 'error-response'); + assert.equal(silent.message, 'The "raw" server answered with an error without saying what went wrong, so whether the request took effect ' + + 'is unknown. Check its effect before trying again.'); + loggedLine(logged, /^MCP server "raw" answered tools\/call op with error -32603: "\\u0020\\u0020"$/); + + // The server's words reach the caller unredacted, and the log redacted, + // whatever JSON value they are. + const echoed = classify({ answer: 'error', error: { code: -32603, message: `bad token ${token}` } }, new Error('the SDK\'s words')); + assert.equal(echoed.message, `The "raw" server answered with an error: bad token ${token}`); + loggedLine(logged, /^MCP server "raw" answered tools\/call op with error -32603: "bad\\u0020token\\u0020redacted"$/); + classify({ answer: 'error', error: { code: -32603, message: { said: `bad token ${token}` } } }, new Error('the SDK\'s words')); + assert.ok(logged.some((line) => line.endsWith('with error -32603: "{\\"said\\":\\"bad\\u0020token\\u0020redacted\\"}"')), logged.join('\n')); + assert.ok(!logged.some((line) => line.includes(token)), 'no log line has the token'); + + const unusableListing = classify({ answer: 'complete' }, new Error('the list failed its schema'), 'tools/list'); + assert.equal(outcome(unusableListing), 'plain'); + assert.equal(unusableListing.message, 'The "raw" server answered, but not in a form this host can read. ' + + 'Listing changes nothing on the server, so it\'s safe to try again.'); + + const droppedListing = classify({}, new Error('socket hang up'), 'tools/list'); + assert.equal(outcome(droppedListing), 'no-response'); + assert.equal(droppedListing.message, 'The request to the "raw" server failed before an answer came back. ' + + 'Listing changes nothing on the server, so it\'s safe to try again.'); + loggedLine(logged, /^MCP server "raw" tools\/list failed: "socket hang up"$/); const listing = classify({}, new SdkError(SdkErrorCode.RequestTimeout, 'Request timed out'), 'tools/list'); assert.equal(outcome(listing), 'no-response'); - assert.match(listing.message, /did not answer tools\/list within 1000ms\. Cancellation was requested; the list did not arrive in time\. Listing changes nothing on the server, so it is safe to retry\./); - assert.doesNotMatch(listing.message, /side-effecting/); + assert.equal(listing.message, 'The "raw" server didn\'t answer within 1 second, and this host asked it to cancel. ' + + 'Listing changes nothing on the server, so it\'s safe to try again.'); + assert.doesNotMatch(listing.message, /took effect|Check its effect/); + loggedLine(logged, /^MCP server "raw" didn't answer tools\/list within 1000ms; cancellation requested$/); + + // A listing whose connection closed under it, and one this host's close + // cut off: the effect clause is the listing's. + const lostListing = classify({}, new Error('Connection closed'), 'tools/list', true); + assert.equal(outcome(lostListing), 'no-response'); + assert.equal(lostListing.message, 'The connection to the "raw" server closed before it answered. ' + + 'Listing changes nothing on the server, so it\'s safe to try again.'); + (connection as unknown as { closedByHost: boolean }).closedByHost = true; + const closedListing = classify({}, new Error('Connection closed'), 'tools/list', true); + assert.equal(outcome(closedListing), 'no-response'); + assert.equal(closedListing.message, 'The "raw" server didn\'t answer before this host closed its connection. ' + + 'Listing changes nothing on the server, so it\'s safe to try again.'); }); test('a reconnect backoff never exceeds the timer limit', () => { @@ -779,6 +914,7 @@ test('close() during a connect waits for that connect\'s own cleanup, and report }); test('a server that closes its stdin and ignores SIGTERM is killed and reconnected, and a call made after the failure is refused as not sent', { timeout: 40_000 }, async () => { + const logged = hostLog(); const log = scratchLog(); const connection = await connect('ignore-sigterm', log, { reconnect: true, reconnectIntervalMs: 30, reconnectMaxIntervalMs: 60, requestTimeoutMs: 30_000 }); connection.on('error', () => { /* out-of-band SDK errors */ }); @@ -794,9 +930,11 @@ test('a server that closes its stdin and ignores SIGTERM is killed and reconnect await assert.rejects(connection.callTool('plain', {}), (error: unknown) => { assert.ok(error instanceof McplRequestError, String(error)); assert.equal(error.outcome, 'not-sent'); - assert.match(error.message, /stdio pipe failed with write EPIPE/); + assert.equal(error.message, 'The request wasn\'t sent: this host can no longer write to the "raw" server, so nothing ran. ' + + 'This host is reconnecting to it; try again later.'); return true; }); + loggedLine(logged, /^MCP server "raw" tools\/call plain not sent: ".*stdio pipe failed with write EPIPE"$/); // SIGKILL ends the child, and the connection reconnects as after any loss. await until(() => wire(log).filter((e) => e.event === 'start').length === 2 && connection.isConnected, 'the next launch, connected', 15_000); assert.equal(closes.length, 1, closes.join('; ')); diff --git a/test/mcp-protocol-family.test.ts b/test/mcp-protocol-family.test.ts index 6f23e44f9..1236732e2 100644 --- a/test/mcp-protocol-family.test.ts +++ b/test/mcp-protocol-family.test.ts @@ -22,6 +22,7 @@ import { mcplPolicyGrants, MAX_TIMER_MS, } from '../src/mcpl/protocol-family.js'; +import { logValueRedacted } from '../src/mcpl/log-value.js'; import { getEventListeners } from 'node:events'; import { DEFAULT_EAGER_FETCH_MAX_BYTES, DEFAULT_MAX_TOTAL_BYTES } from '../src/mcpl/reference-fetcher.js'; import { DEFAULT_MAX_INPUT_BYTES } from '../src/mcpl/tool-lifecycle.js'; @@ -554,6 +555,47 @@ test('recorded server text: a credential as JSON.stringify writes it, its quotes } }); +test("recorded server text: a url's credentials, pairs and userinfo as JSON.stringify writes them, as a token's are", () => { + // Decoded, each holds a quote and a backslash, or a slash: a path segment, + // a credential-named query value, a pair whose value is too short to go on + // its own, a ws:// password, and a userinfo unit too short to go on its own. + const config = cfg({ url: 'wss://bot:pa%22ss%5Cw0rd@h/mcpl/s3cr%22et%5C0123456789?password=sec%2Fret%22key123®ion=e%22u' }); + for (const decoded of ['s3cr"et\\0123456789', 'sec/ret"key123', 'pa"ss\\w0rd']) { + const json = JSON.stringify(decoded).slice(1, -1); + for (const form of [decoded, json, json.replace(/\//g, '\\/')]) { + assert.equal(redactServerText(`config {"secret":"${form}"} refused`, config), 'config {"secret":"redacted"} refused', form); + } + } + assert.equal(redactServerText('config {"q":"region=e\\"u"} refused', config), 'config {"q":"redacted"} refused'); + const short = cfg({ url: 'wss://b%22t:p%22w@h/mcp' }); + assert.equal(redactServerText('dial {"url":"wss://b\\"t:p\\"w@h/mcp"} failed', short), 'dial {"url":"wss://redacted@h/mcp"} failed'); +}); + +test('recorded server text: a pair or userinfo unit after a JSON escape goes, as after the control character it stands for', () => { + const config = cfg({ url: 'wss://bot:pw@h/mcpl?key=abc' }); + for (const escape of ['\\n', '\\t', '\\r', '\\b', '\\f', '\\u000b']) { + assert.equal(redactServerText(`{"said":"bad${escape}key=abc"}`, config), `{"said":"bad${escape}redacted"}`, escape); + assert.equal(redactServerText(`{"said":"dial${escape}bot:pw@h"}`, config), `{"said":"dial${escape}redacted@h"}`, escape); + } + // A letter or digit that's text, not an escape's end, still adjoins it. + assert.equal(redactServerText('monkey=abc', config), 'monkey=abc'); + assert.equal(redactServerText('robot:pw@h', config), 'robot:pw@h'); + // The case a JSON value's text makes: a string with a newline before the pair. + assert.equal(logValueRedacted({ said: 'bad\nkey=abc' }, (text) => redactServerText(text, config)), '"{\\"said\\":\\"bad\\\\nredacted\\"}"'); +}); + +test('recorded server text: the floor applies to each form, so a seven-character token goes in its eight-character JSON form', () => { + const config = cfg({ token: 'ab"cdef' }); + assert.equal(redactServerText('refused: ab"cdef', config), 'refused: ab"cdef'); + assert.equal(redactServerText('refused: ab\\"cdef', config), 'refused: redacted'); +}); + +test("a JSON value logged through logValueRedacted keeps no url credential, though its JSON text escapes the credential's quote", () => { + const config = cfg({ url: 'wss://h/mcpl?password=secret%22key123' }); + const line = logValueRedacted({ said: 'secret"key123' }, (text) => redactServerText(text, config)); + assert.equal(line, '"{\\"said\\":\\"redacted\\"}"'); +}); + test("one redactor over several configurations' strings takes the longest secret among them all", () => { const short = cfg({ id: 'a', token: 'ghp_SHAREDPREFIX123' }); const long = cfg({ id: 'b', token: 'ghp_SHAREDPREFIX123_but_longer_TAIL9' }); diff --git a/test/mcp-server-ownership.test.ts b/test/mcp-server-ownership.test.ts index b8da064c7..1871ae195 100644 --- a/test/mcp-server-ownership.test.ts +++ b/test/mcp-server-ownership.test.ts @@ -160,14 +160,21 @@ test('a hold releases only its own claim: a disconnect queued behind another sti }); }); -test('a modern connect is refused while a legacy connect for the same id is still handshaking', async () => { +test('a modern connect is refused while a legacy connect for the same id is still handshaking, before it reads anything', async () => { await withFramework(async ({ framework, dir }) => { const legacyLog = join(dir, 'legacy.log'); const modernLog = join(dir, 'raw.jsonl'); const pending = framework.connectMcplServer(legacy('same', 'slow', legacyLog, { SLOW_INIT_MS: '800' })); await until(() => launches(legacyLog).length === 1, 'the legacy launch, handshaking'); - await assert.rejects(framework.connectMcplServer(modern('same', '', modernLog)), /MCPL server "same" has a connect in flight; try again once it settles/); + // A connect reads the server's restored trees before it adds the server + // (the first one has, by now); one refused for its id reads none. + const read: string[] = []; + const checkpoints = (framework as unknown as { checkpointManager: { loadHostStates(id: string): void } | null }).checkpointManager!; + const load = checkpoints.loadHostStates.bind(checkpoints); + checkpoints.loadHostStates = (id: string) => { read.push(id); load(id); }; + await assert.rejects(framework.connectMcplServer(modern('same', '', modernLog)), /^Error: MCPL server "same" has a connect in flight; try again once it settles$/); assert.equal(launches(modernLog).length, 0, 'the modern server was never launched'); + assert.deepEqual(read, [], 'the refused connect read no trees'); await pending; const served = status(framework, 'same')!; assert.equal(served.family, 'legacy'); @@ -194,6 +201,34 @@ test('a disconnect during a legacy handshake ends that connect at once, and remo }); }); +test("legacy: a disconnect during a handshake whose child can't be reaped rejects, and the server stays registered until a retried disconnect confirms the exit", async () => { + await withFramework(async ({ framework, dir }) => { + const log = join(dir, 'legacy.log'); + const reaping = unreapable(); + // The handshake never finishes on its own, so only the disconnect ends + // the connect. Its cleanup can't reap the child, so the connect leaves + // the closed connection that owns it registered, after the disconnect's + // first removal found nothing there: the disconnect checks again once + // the connect has settled. + const pending = framework.connectMcplServer(legacy('l', 'slow', log, { SLOW_INIT_MS: '3600000' })); + const connectFailure = pending.then(() => null, (error: unknown) => error); + await until(() => launches(log).length === 1, 'the legacy launch, handshaking'); + await assert.rejects( + framework.disconnectMcplServer('l'), + /could not be reaped\. MCP server "l" stays registered, closed, until its exit is confirmed: disconnect it again to retry the reap$/, + ); + assert.match(String(await connectFailure), /MCP server "l" was not connected: it was disconnected while connecting; its cleanup also failed: .*could not be reaped/); + assert.equal(status(framework, 'l')?.connected, false, 'still listed, closed'); + await assert.rejects(framework.connectMcplServer(legacy('l', 'ok', log)), /"l" is already registered \(not connected and not reconnecting: disconnect it first\)/); + assert.equal(launches(log).length, 1, 'no launch beside the unreaped child'); + + await killAndWait(reaping.stuck[0]!); + reaping.active = false; + await framework.disconnectMcplServer('l'); + assert.equal(status(framework, 'l'), undefined, 'the retried disconnect completed'); + }); +}); + test('a disconnect during a modern connect ends it at once', async () => { await withFramework(async ({ framework, dir }) => { const log = join(dir, 'raw.jsonl'); diff --git a/test/mcpl-agent-words.test.ts b/test/mcpl-agent-words.test.ts index 30fb9d7cf..6ce53858f 100644 --- a/test/mcpl-agent-words.test.ts +++ b/test/mcpl-agent-words.test.ts @@ -25,6 +25,8 @@ import { import { convertBlock } from '../src/mcpl/convert-block.js'; import { toolResultDataToHistoryString } from '../src/tool-result-history.js'; import { McplServerConnection } from '../src/mcpl/server-connection.js'; +import { WITHHELD_TEXT } from '../src/mcpl/protocol-family.js'; +import { logValue } from '../src/mcpl/log-value.js'; import type { McplHostCapabilities, McplServerConfig } from '../src/mcpl/types.js'; // --------------------------------------------------------------------------- @@ -74,7 +76,9 @@ test("a reference block that can't be read says which part is missing, and what // Stdio server: answers initialize and tools/list; tools/call "refuse" gets a // JSON-RPC error, "mute" one with a blank message, "odd" one whose message -// isn't a string, "exit" ends the process with the call pending, +// isn't a string, "echo-token" one whose message echoes its API_TOKEN, +// "echo-token-object" one whose message is an object holding it, "exit" +// ends the process with the call pending, // "answer-then-exit" answers and then ends it, and "hang" is never answered. const SERVER = ` let buf = ''; @@ -91,6 +95,8 @@ process.stdin.on('data', (c) => { else if (m.method === 'tools/call' && m.params.name === 'refuse') send({ error: { code: -32000, message: 'Missing Access' } }); else if (m.method === 'tools/call' && m.params.name === 'mute') send({ error: { code: -32000, message: ' ' } }); else if (m.method === 'tools/call' && m.params.name === 'odd') send({ error: { code: -32000, message: 42 } }); + else if (m.method === 'tools/call' && m.params.name === 'echo-token') send({ error: { code: -32000, message: 'bad token ' + process.env.API_TOKEN } }); + else if (m.method === 'tools/call' && m.params.name === 'echo-token-object') send({ error: { code: -32000, message: { said: 'bad token ' + process.env.API_TOKEN } } }); else if (m.method === 'tools/call' && m.params.name === 'answer-then-exit') { send({ result: { content: [] } }); setTimeout(() => process.exit(0), 50); } else if (m.method === 'tools/call' && m.params.name === 'exit') process.exit(3); } @@ -134,6 +140,60 @@ test("a server's error answer is shown as the server's, and its method, id and c assert.ok(logged(errors.mock.calls, /^MCPL server "words" answered tools\/call \(id=\d+\) with error -32000: 42$/), 'the log has the number'); }); +test("a server's error answer that echoes a credential reaches the caller as sent, and the log redacted", async (t) => { + const errors = t.mock.method(console, 'error', () => {}); + const token = 'tok-0123456789abcdef'; + const connection = await McplServerConnection.connect(config({ env: { API_TOKEN: token } }), HOST_CAPS); + t.after(() => connection.close()); + connection.ready(); + // A JSON-RPC answer passes as it is (redactServerText's scope). + await assert.rejects(connection.sendToolsCall('echo-token', {}), + { message: `The "words" server answered with an error: bad token ${token}` }); + // The log is a record of the server's text, so the credential leaves it, + // in a message of any JSON value. + await assert.rejects(connection.sendToolsCall('echo-token-object', {}), { message: NO_WORDS }); + const lines = errors.mock.calls.map((call) => String(call.arguments[0])); + assert.ok(logged(errors.mock.calls, /^MCPL server "words" answered tools\/call \(id=\d+\) with error -32000: "bad\\u0020token\\u0020redacted"$/), lines.join('\n')); + assert.ok(lines.some((line) => line.endsWith('with error -32000: "{\\"said\\":\\"bad\\u0020token\\u0020redacted\\"}"')), lines.join('\n')); + assert.ok(!lines.some((line) => line.includes(token)), 'no log line has the token'); +}); + +test("an error answer whose configuration can't be read settles its call, and its log line withholds the server's text", async (t) => { + const errors = t.mock.method(console, 'error', () => {}); + // A stdio server's env, as the framework gives it, is a getter, which + // throws once the reaction baseline's ledger can't be read. + let unreadable = false; + const withGetter = config(); + Object.defineProperty(withGetter, 'env', { + enumerable: true, + get: () => { if (unreadable) throw new Error('reaction-baseline ledger unreadable'); return {}; }, + }); + const connection = await McplServerConnection.connect(withGetter, HOST_CAPS); + t.after(() => { unreadable = false; return connection.close(); }); + connection.ready(); + unreadable = true; + await within(assert.rejects(connection.sendToolsCall('refuse', {}), + { message: 'The "words" server answered with an error: Missing Access' }), 'settled call'); + const lines = errors.mock.calls.map((call) => String(call.arguments[0])); + assert.ok(!lines.some((line) => line.includes('Missing')), lines.join('\n')); + assert.ok(lines.some((line) => /^MCPL server "words" answered tools\/call \(id=\d+\) with error -32000: /.test(line) && line.endsWith(logValue(WITHHELD_TEXT))), lines.join('\n')); +}); + +test("an error answer settles its call when writing its log line throws", async (t) => { + // A host's logger can throw. The call's entry and timer are gone by the + // time the line is written, so nothing else would settle it. + const errors = t.mock.method(console, 'error', (line: unknown) => { + if (String(line).includes(' answered tools/call ')) throw new Error('the logger is down'); + }); + const connection = await McplServerConnection.connect(config(), HOST_CAPS); + t.after(() => connection.close()); + connection.ready(); + await within(assert.rejects(connection.sendToolsCall('refuse', {}), + { message: 'The "words" server answered with an error: Missing Access' }), 'settled call'); + const lines = errors.mock.calls.map((call) => String(call.arguments[0])); + assert.ok(lines.some((line) => /inbound dispatch failed .*the logger is down/.test(line)), lines.join('\n')); +}); + test("a server that drops with a call pending says the outcome is unknown, and whether it's coming back", async (t) => { const errors = t.mock.method(console, 'error', () => {}); const once = await McplServerConnection.connect(config(), HOST_CAPS); @@ -328,14 +388,44 @@ test("a call while this host connects to the tool's server says so, and after a assert.equal((await framework.executeMcplToolCall(call('c6'), 'words', 'words')).error, goneText, "a script's call reads the same"); }); +test('a call while a modern connect is under way reads the connecting text on both paths; once its session is up, the call goes to it', async () => { + // A modern connect registers its connection before it starts, so the + // connection is there while the connect holds the id. + const { framework, events } = frameworkWith(null); + const reached: string[] = []; + const modern = { + id: 'words', + isConnected: false, + callTool: async (name: string) => { reached.push(name); return { content: [{ type: 'text', text: 'ran' }] }; }, + }; + Object.assign(framework, { + modernMcpConnections: new Map([['words', modern]]), + mcpServerOps: new Map([['words', { kind: 'connect', settled: new Promise(() => {}) }]]), + }); + const call = (id: string) => ({ id, name: 'words--lookup', input: {} }); + const connectingText = 'This host is connecting to the "words" server that provides words--lookup, so the call didn\'t run. Try again in a moment.'; + framework.dispatchMcplToolCall('agent', call('m1'), 'words', 'words'); + assert.equal(events[0]?.result?.error, connectingText); + assert.equal((await framework.executeMcplToolCall(call('m2'), 'words', 'words')).error, connectingText, "a script's call reads the same"); + assert.deepEqual(reached, [], 'neither reached the connection'); + // Its first session is up while the connect still lists its tools: a call goes to it. + modern.isConnected = true; + const ran = await framework.executeMcplToolCall(call('m3'), 'words', 'words') as { success?: boolean }; + assert.equal(ran.success, true); + assert.deepEqual(reached, ['lookup']); +}); + test('a second connect, or a restart into the id, of a server whose connect is in flight is refused in these words before it writes anything', async () => { - // The registry takes the server once its handshake is done, so until then - // the connect's hold on the id (mcpServerIdTaken) says the id is taken. Each - // handshake here waits for the test. A disconnect isn't refused: it ends the - // connect, as mcp-server-ownership's tests of a disconnect during a legacy - // handshake and during a modern connect pin. + // The connect's hold on the id (mcpServerIdTaken) says the id is taken in + // these words for as long as the connect runs: through its handshake, and + // after the registry has taken the server, while the connect sets it up. + // Each handshake, and the setup after it, waits for the test. A disconnect + // isn't refused: it ends the connect, as mcp-server-ownership's tests of a + // disconnect during a legacy handshake and during a modern connect pin. const servers = new Map(); const handshakes: Array<() => void> = []; + let setUp!: () => void; + const settingUp = new Promise((r) => { setUp = r; }); const { framework } = frameworkWith(null); Object.assign(framework, { mcplServerRegistry: { @@ -356,7 +446,7 @@ test('a second connect, or a restart into the id, of a server whose connect is i discordAwarenessOutbox: null, discordAwarenessEmoji: '🔕', wireMcplEvents: () => {}, - registerMcplServerFeatures: async () => {}, + registerMcplServerFeatures: () => settingUp, }); const fw = framework as unknown as { connectMcplServerInternal(config: McplServerConfig, deferAwareness?: boolean): Promise; @@ -372,6 +462,10 @@ test('a second connect, or a restart into the id, of a server whose connect is i assert.equal(fw.mcpServerIdTaken('words', undefined, 'other'), `MCP server "other" was not restarted: ${inFlight}`, 'a restart of another server into its id'); handshakes[0]!(); + await new Promise((r) => setImmediate(r)); + assert.ok(servers.has('words'), 'the registry has taken the server'); + await assert.rejects(fw.connectMcplServerInternal(words, true), { message: inFlight }, 'a second connect while the first sets the server up'); + setUp(); await connecting; // Once the connect settles, the registered server holds the id. assert.equal(fw.mcpServerIdTaken('words'), 'MCPL server "words" is already registered');