diff --git a/changelog.d/208-handler-failure-replies.changed.md b/changelog.d/208-handler-failure-replies.changed.md new file mode 100644 index 000000000..e4b5c6159 --- /dev/null +++ b/changelog.d/208-handler-failure-replies.changed.md @@ -0,0 +1 @@ +- **MCPL server authors:** when the host's handler for a server's request throws or rejects before it has answered, the server's answer no longer carries the handler's own message (#208). 0.22.x answered such a failure of a `push/event`, `inference/request`, `channels/register`, `channels/changed`, `channels/incoming` or `host/command` handler with `-32603` and the handler's message, or, once the host was stopping, with `-32000` and "the host stopped while handling this request" followed by the handler's message in parentheses. These requests now get `-32603` "Internal error", or, while the host is stopping, `-32000` "the host stopped while handling this request" alone. A handler's message can name the host's internal paths and errors, and the server may be a third party's. A server that shows or parses the handler's text from these replies no longer receives it: the host writes it to stderr and to its `mcpl:request-handler-error` trace instead. A handler that answers a failure itself still sends its own code and message, as before: `inference/request` when the inference fails, and `push/event` when a coalesced push fails. diff --git a/changelog.d/208-inbound-handler-containment.fixed.md b/changelog.d/208-inbound-handler-containment.fixed.md new file mode 100644 index 000000000..ad2ec697c --- /dev/null +++ b/changelog.d/208-inbound-handler-containment.fixed.md @@ -0,0 +1,11 @@ +- MCPL's inbound handlers are contained at one boundary, the framework's wiring, for every request and notification it handles (#186). The `channels/list`, `tools/observe` and `model/info` requests and the `notifications/tools/list_changed` notification are newly contained: a throw or rejection of theirs is reported as the other handlers' are. `mcpl/manifestChanged` goes through the same boundary, and so does a refresh its handler schedules for later, after the fetch floor or behind a fetch in flight: a manifest fetch that fails is still caught and logged inside the handler, as in 0.22.x, and anything else the handler throws or rejects with is now reported as the others' are. 0.22.x logged that from an announcement's own run, and dropped it from a scheduled re-run. The six requests whose handler failures 0.22.0 already answered (`push/event`, `inference/request`, `channels/register`, `channels/changed`, `channels/incoming` and `host/command`) go through the same boundary now. On a connection the framework wires, no handler's throw or rejection ends the host, and a rejection reason that can't be printed is reported as one that can. + - **A request whose handler fails is answered `-32603` "Internal error",** or, while the host is stopping, `-32000` "the host stopped while handling this request". The handler's error stays in the trace and on stderr. For the six that 0.22.x answered with the handler's own message, that's a change, described under Changed. A request is answered this way when its handler fails without having written a reply, which includes a reply whose write threw, such as one that can't be encoded. A notification gets no reply. + - **Each failure emits a new trace, `mcpl:request-handler-error`, and a stderr line.** Its `error` is the handler's own error, or, for a handler that resolved, the reply write it swallowed, or a note that it tried to answer a second time. A reply write that failed before it is `responseFailure`, and a reply the handler tried to send after one was already attempted is `refusedResponse` (a result, or an error with its code and message): refused, never written. `responseError` is the internal-error reply's own failure, which the stderr line prints too. `requestId` is the request's id when that is a number, and a string id bounded as the trace's other texts are. A request form of `mcpl/manifestChanged` or `notifications/tools/list_changed` has none, since it's answered as it's admitted and then handled as the notification is. + - **A request whose method isn't a string,** or isn't one the host handles, or whose event nothing on the host listens for, is answered `-32601` "Method not found", with a stderr line. A notification nobody handles is ignored. + - **`mcpl/manifestChanged` and `notifications/tools/list_changed` sent as requests,** with an id, are answered with an empty result when the connection admits them, which waits while their plane is paused, if something on the host listens for them, as the framework's wiring always does, and are handled as the notification is. + - **Non-object JSON** (`null`, `42`, `"hi"`, `true`) is ignored before property access, in the handshake reader and in routing, as a non-JSON line already is. One such line from a server used to end the host (#217). + - **An `initialize` error whose `message` has no string form,** such as `{"toString":1}`, refuses the connect, with `initialize error: [object Object]`. 0.22.x converted that message after the handshake had stopped listening and cleared its timeout, so the conversion's throw escaped as an uncaught exception, which ends a host that doesn't catch them, and the connect never settled. + - **An error answer to a request the host sent,** such as its manifest fetch, settles that request whatever its `code` and `message` are. 0.22.x's conversion of them threw out of the transport's line listener in the same way. + - **A server's text in these errors is bounded:** in an `initialize` error's message and in an error answer's code and message, control, format and line-separator characters become `?`, and each is cut after 200 code points, with `…` marking the cut. + - **A synchronous failure while dispatching an inbound message**, buffered plane flushes and a server's stderr lines included, is reported without interrupting later messages. Its `mcpl:server-error` names the event or method, the request id, and the cause. +- A trace listener that throws a value `console.error` can't print, such as one whose `util.inspect.custom` throws, no longer keeps the listeners after it from getting the event, or throws out at the code that emitted it: its error is printed as text instead. diff --git a/src/framework.ts b/src/framework.ts index 7fe1bdda8..f9b153d87 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -77,7 +77,7 @@ import { REFUSAL_REACTIONS, REFUSAL_REACTION_FALLBACK, REFUSAL_REACTION_BASELINE import { Agent } from './agent.js'; import { ModuleRegistry, checkedToolResult, isStateExistsError, storableToolResult, thrownResult } from './module-registry.js'; import { McplServerRegistry } from './mcpl/server-registry.js'; -import { logValue } from './mcpl/log-value.js'; +import { logDetail, logValue } from './mcpl/log-value.js'; import { FeatureSetManager } from './mcpl/feature-set-manager.js'; import { computeGrant, CapabilityGrant, expandAdvertisementShorthand } from './mcpl/capability-grant.js'; import { maskNegotiatedCapabilities } from './mcpl/capability-mask.js'; @@ -421,6 +421,7 @@ import { EventGate, formatShadowWarning } from './gate/event-gate.js'; import { UsageTracker, persistedUsageProblem, type PersistedUsageState } from './usage/usage-tracker.js'; import type { SessionUsageSnapshot, UsageUpdatedEvent } from './usage/types.js'; import { stderrTailOf, withStderr, type McplConnectionCloseInfo, type McplServerConnection } from './mcpl/server-connection.js'; +import { boundedForLog, describeCause } from './mcpl/errors.js'; import { assertServerConfigBooleans, isWebSocketTransport } from './mcpl/transport.js'; import type { McplServerConfig, @@ -507,6 +508,13 @@ interface DeferredWrite { } const bySeq = (a: { seq: number }, b: { seq: number }): number => a.seq - b.seq; +/** The reply helpers an MCPL connection hands an inbound request's handler. */ +type InboundResponder = { + id: string | number; + respond: (result: unknown) => void; + respondError: (code: number, message: string, data?: unknown) => void; +}; + /** A drained entry as writeDrainedInOrder wrote it: the id its store gave it * (empty when addMessage deferred it again; a sharded body's first shard) * and what the store holds of it. For an entry whose write threw after @@ -1679,66 +1687,6 @@ function jsonKind(value: unknown): string { : `a ${typeof value}`; } -/** - * A failed handler's reason, never throwing: an Error's message, else "the - * handler failed" and what it threw (nothing, for `undefined`). Telling an - * Error apart is itself guarded, since instanceof throws on a revoked Proxy. - */ -function handlerFailureText(error: unknown): string { - let isError = false; - try { - isError = error instanceof Error; - } catch { - // Not an Error that can be read; thrownText says so. - } - if (isError) return thrownText(error); - return error === undefined ? 'the handler failed' : `the handler failed: ${thrownText(error)}`; -} - -/** A server's responder, and whether the request it belongs to has been answered yet. */ -type AnswerOnce = { - responder: { respond?: (result: unknown) => void; respondError?: (code: number, message: string, data?: unknown) => void } | undefined; - answered: () => boolean; -}; - -/** - * Wrap a server request's responder so the request is answered at most once, - * and a later failure can tell whether the handler already answered. - * - An answer counts once the responder returns. One that throws, such as a - * result the transport can't serialize, leaves the request unanswered, so - * the listener's failure answer still goes out. This assumes a responder - * that throws has sent nothing, which holds for the connection's own: they - * serialize before they write, and their transports' writes don't throw - * after writing. - * - A second answer is refused and logged: a handler that answered and then - * threw isn't answered again, and a handler that answers after the - * listener answered its failure doesn't send a second response. - * - Only the methods the responder has are wrapped, so a handler that checks - * for `respondError` still finds a responder without one. - */ -function answerOnce void; respondError?: (code: number, message: string, data?: unknown) => void }>( - responder: R | undefined, - method: string, - serverId: string, -): AnswerOnce & { responder: R | undefined } { - if (!responder) return { responder: undefined, answered: () => false }; - let done = false; - const once = (kind: string, send: (...args: A) => void) => (...args: A): void => { - if (done) { - console.error(`[mcpl] ${method} from ${serverId}: a second answer (${kind}) was refused; the request was already answered`); - return; - } - send(...args); - done = true; - }; - const wrapped: { respond?: (result: unknown) => void; respondError?: (code: number, message: string, data?: unknown) => void } = { ...responder }; - if (responder.respond) wrapped.respond = once('respond', (result: unknown) => responder.respond!(result)); - if (responder.respondError) { - wrapped.respondError = once('respondError', (code: number, message: string, data?: unknown) => responder.respondError!(code, message, data)); - } - return { responder: wrapped as R, answered: () => done }; -} - export class AgentFramework { private toolPresentations = new Map(); private presentationPreviews = new WeakMap(); @@ -4064,47 +4012,21 @@ export class AgentFramework { } /** - * A server's request or notification the host couldn't handle, answered - * with a JSON-RPC error when it is a request (a notification has no one to - * answer, and is logged), rather than thrown out of the connection's - * listener, where it was an unhandled rejection and the server's request - * waited for its timeout. - * - `refused`: the listener turned it away before its handler ran; the - * host is stopping, and none of it was taken. Answered -32000, "the host - * is stopping", the code the push coalescer already gives a stopping - * host: the server can send it again to the host's next run. - * - `failed`: the handler threw, whatever it threw, `undefined` included. - * While the host stops (its queue closed), that's answered -32000 too, - * with the handler's own message after the stop wording; on a live host - * it's a fault, answered -32603 with the handler's message. The handler - * may have admitted part of the request first (an earlier message of a - * batch), so nothing here claims that none of it was taken. - * A request the handler already answered before it threw isn't answered - * again: the failure is logged. + * A server's request turned away before its handler ran, because the host + * is stopping and none of it was taken: answered -32000, "the host is + * stopping", the code the push coalescer already gives a stopping host, so + * the server can send it again to the host's next run, and logged. A + * handler's own failure is answered by containedInboundHandler, with + * -32000 and the stop wording alone once the host is stopping. */ private refuseServerItem( method: string, serverId: string, - answer: AnswerOnce, - outcome: { kind: 'refused' } | { kind: 'failed'; error: unknown }, + responder: { respondError?: (code: number, message: string, data?: unknown) => void } | undefined, ): void { - // Optional chaining: prototype-built harnesses leave the queue unset. - const stopping = outcome.kind === 'refused' || !!this.queue?.isClosed; - const what = outcome.kind === 'refused' ? '' : handlerFailureText(outcome.error); - const reason = outcome.kind === 'refused' - ? 'the host is stopping' - : stopping - ? `the host stopped while handling this request (${what})` - : what; - if (outcome.kind === 'failed' && answer.answered()) { - console.error(`[mcpl] ${method} from ${serverId} failed after it was answered: ${reason}`); - return; - } - console.error(outcome.kind === 'refused' - ? `[mcpl] ${method} from ${serverId} refused: ${reason}` - : `[mcpl] ${method} from ${serverId} failed: ${reason} (part of it may already have been admitted)`); + console.error(`[mcpl] ${method} from ${serverId} refused: the host is stopping`); try { - answer.responder?.respondError?.(stopping ? -32000 : -32603, reason); + responder?.respondError?.(-32000, 'the host is stopping'); } catch { // The connection is going too; there is no one left to tell. } @@ -16919,7 +16841,17 @@ export class AgentFramework { try { listener(traceEvent); } catch (error) { - console.error('Trace listener error:', error); + // console.error inspects the value, and inspecting can throw (a + // throwing util.inspect.custom, say). That throw would leave this + // loop, so the listeners after this one would miss the event and the + // code that emitted it would get the throw. describeCause never + // throws, a template string isn't inspected, and log-value prints + // the text as one escaped, bounded line. + try { + console.error('Trace listener error:', error); + } catch { + console.error(`Trace listener error: ${logDetail(describeCause(error))}`); + } } } } @@ -18293,7 +18225,7 @@ export class AgentFramework { const cur = this.manifestRefreshState.get(connection.id); if (cur?.queued && !cur.inFlight) { cur.queued = false; - void this.handleManifestChanged(connection, announce).catch(() => {}); + this.rerunManifestRefresh(connection, announce); } }, AgentFramework.MANIFEST_FETCH_FLOOR_MS - sinceLast).unref?.(); } @@ -18438,12 +18370,25 @@ export class AgentFramework { st.lastCompletedAt = Date.now(); if (st.queued) { st.queued = false; - setTimeout(() => { void this.handleManifestChanged(connection, announce).catch(() => {}); }, + setTimeout(() => { this.rerunManifestRefresh(connection, announce); }, AgentFramework.MANIFEST_FETCH_FLOOR_MS).unref?.(); } } } + /** A refresh handleManifestChanged schedules for itself, after the fetch + * floor or behind a fetch in flight. It's contained as the announcement's + * own run is. Its fetch's own failure is logged by the fetch's catch, as + * in 0.22.x; any other failure emits mcpl:request-handler-error and a + * stderr line through the containment. */ + private rerunManifestRefresh( + connection: McplServerConnection, + announce: unknown, + ): void { + this.containedInboundHandler(connection.id, 'manifest-changed', + (params: unknown) => this.handleManifestChanged(connection, params))(announce); + } + /** * (Re-)establish a server's host-side MCPL registration: feature-set state * (plus the featureSets/update sent to the server), scope patterns, and @@ -18873,11 +18818,192 @@ export class AgentFramework { return result; } + /** + * An inbound MCPL handler, contained: EventEmitter doesn't consume the + * promise a listener returns, so this keeps each handler's throw or + * rejection at this boundary, including failures after channels/register or + * channels/changed has acknowledged the request. It's invoked at once, so + * control-plane replies keep their acknowledge-before-reconcile order. + */ + private containedInboundHandler( + serverId: string, + event: string, + handler: (params: T, responder?: InboundResponder) => void | Promise, + ): (params: T, responder?: InboundResponder) => void { + return (params: T, responder?: InboundResponder) => { + // Whether the handler wrote a reply. A reply counts once its write + // returns: a write that throws has sent nothing, since the connection + // encodes a reply before it writes it, and neither transport's write + // throws after writing (a stream write reports a failure + // asynchronously, and a WebSocket is written only while it's open). A + // transport whose write could throw after sending bytes would break + // this: the internal-error reply would follow part of a reply. + let responseAttempted = false; + // The first reply write that threw, if any, which a handler may have + // swallowed. + let writeFailure: unknown; + let writeFailed = false; + // A write the handler tried after a reply was written. It's refused + // without throwing, so a handler that answers again in its own catch + // and then rethrows reports its own error; what it tried to send is + // kept for the report. + let refused: { kind: 'result' } | { kind: 'error'; code: number; message: string } | undefined; + // Once a failure is reported, no report follows, so a later answer is + // logged as it's refused. + let reported = false; + const writeResponse = ( + write: () => void, + refusedAs: { kind: 'result' } | { kind: 'error'; code: number; message: string }, + ): void => { + if (responseAttempted) { + refused ??= refusedAs; + if (reported) { + console.error(`[mcpl] ${serverId} ${event}: a second answer was refused; the request was already answered`); + } + return; + } + try { + write(); + } catch (error) { + if (!writeFailed) { + writeFailed = true; + writeFailure = error; + } + throw error; + } + responseAttempted = true; + }; + // Only the methods the responder has are wrapped, so a handler that + // checks for respondError still finds a responder without one, such + // as a caller's own that has none. + const respondError = responder?.respondError as InboundResponder['respondError'] | undefined; + const tracked = (responder && { + ...responder, + respond: (result: unknown) => writeResponse(() => responder.respond(result), { kind: 'result' }), + ...(respondError ? { + respondError: (code: number, message: string, data?: unknown) => + writeResponse(() => respondError(code, message, data), { + kind: 'error', code, message: typeof message === 'string' ? message : describeCause(message), + }), + } : {}), + }) as InboundResponder | undefined; + // Report a failure: the handler's own error when it threw or + // rejected, else the reply write it swallowed, else the reply it + // tried to send twice. Nothing in here may throw: on the async path + // it runs as a rejection handler, where an exception would leave the + // report unfinished for the backstop below to log. So every value it + // puts in text, the code of an answer the handler tried again + // included, is converted with describeCause, the internal-error + // reply's send is caught, and emitTrace's own catch can't throw. + const report = (handlerError: { error: unknown } | undefined): void => { + const primary = handlerError + ? handlerError.error + : writeFailed ? writeFailure : new Error('the handler tried to answer a second time after its reply'); + reported = true; + const message = describeCause(primary); + // What the handler's own writes did, before any internal-error + // reply sent here. + const handlerResponseAttempted = responseAttempted; + // A reply write the handler's own attempt failed, read before the + // internal-error reply below, whose own failure is responseError. + const responseFailure = writeFailed && handlerError && handlerError.error !== writeFailure + ? describeCause(writeFailure) : undefined; + let responseError: string | undefined; + if (tracked && !responseAttempted) { + // The server gets the standard message, not the handler's own + // text, which may name internal paths or errors; the trace and + // stderr carry the detail. Once the host is stopping (its queue + // closed), it gets -32000 with the stop wording alone, the code a + // request turned away at stop gets, so it can send it again to + // the host's next run. Optional chaining: prototype-built + // harnesses leave the queue unset. + const stopping = !!this.queue?.isClosed; + try { + tracked.respondError?.( + stopping ? -32000 : -32603, + stopping ? 'the host stopped while handling this request' : 'Internal error', + ); + } catch (sendError) { + responseError = describeCause(sendError); + } + } + this.emitTrace({ + type: 'mcpl:request-handler-error', + serverId, + event, + // The trace's type is string | number. Only those are kept, as + // the connection's own reports keep them, and a string is + // bounded like the texts beside it. + requestId: typeof responder?.id === 'number' ? responder.id + : typeof responder?.id === 'string' ? boundedForLog(responder.id, 500) : undefined, + responseAttempted: handlerResponseAttempted, + // The trace's copies are bounded, as data; the log line below + // prints each text raw through log-value, which escapes it. + error: boundedForLog(message, 500), + ...(responseFailure === undefined ? {} : { responseFailure: boundedForLog(responseFailure, 500) }), + ...(refused === undefined ? {} : { + refusedResponse: refused.kind === 'error' ? { ...refused, message: boundedForLog(refused.message, 500) } : refused, + }), + ...(responseError === undefined ? {} : { responseError: boundedForLog(responseError, 500) }), + }); + // Keep headless hosts diagnosable even without a trace subscriber. + // The handler's text and the server's go through log-value, so a + // line stays one line of bounded, escaped text. + const tried = refused === undefined ? undefined + : refused.kind === 'result' ? 'a result' : `error ${describeCause(refused.code)}: ${refused.message}`; + console.error( + `[mcpl] ${serverId} ${event} handler failed: ${logDetail(message)}` + + (responseFailure === undefined ? '' : ` | its reply write had failed: ${logDetail(responseFailure)}`) + + (tried === undefined ? '' : ` | it then tried to answer again with ${logDetail(tried)}`) + + (responseError === undefined ? '' : ` | the internal-error reply failed too: ${logDetail(responseError)}`), + ); + }; + const failed = (error: unknown): void => report({ error }); + // A handler may swallow a write failure, or answer twice, and still + // resolve. + const succeeded = (): void => { + if (writeFailed || refused) report(undefined); + }; + try { + // Invoke immediately: control-plane responses must retain their + // ACK-before-reconcile ordering and data-plane barrier semantics. + const result = handler(params, tracked); + if (result) { + // On this path the report runs as a rejection handler, where a + // throw would be an unhandled rejection, which ends the host. The + // report converts and catches what it knows can throw; this + // backstop catches anything else, a defect in the report itself, + // and logs it on a line of its own, printed through log-value as + // the report's line is. Nothing catches the backstop, so a failure + // of its own log is swallowed. + void Promise.resolve(result).then(succeeded, failed).catch((reportFailure: unknown) => { + try { + console.error(`[mcpl] ${serverId} ${event}: the handler failure's report threw: ${logDetail(describeCause(reportFailure))}`); + } catch { /* nothing is left to log it to */ } + }); + } else succeeded(); + } catch (error) { + failed(error); + } + }; + } + /** * Wire event listeners on an MCPL server connection. * Push events and inference requests are deferred to Steps 6/7. */ private wireMcplEvents(connection: McplServerConnection): void { + type Responder = InboundResponder; + + // Every inbound handler, request or notification, is contained + // (containedInboundHandler). + const onRequest = ( + event: string, + handler: (params: T, responder?: Responder) => void | Promise, + ): void => { + connection.on(event, this.containedInboundHandler(connection.id, event, handler)); + }; + // Forward subprocess stderr lines as trace events so consumers (conhost, // log sinks, TUI badges) can persist and surface them. connection.on('stderr', (params: { line: string }) => { @@ -18895,30 +19021,25 @@ export class AgentFramework { // framework; the ScopeManager and config `scopes` wiring went with it. // Handle push events (Step 6) - connection.on('push-event', async ( + onRequest('push-event', async ( params: PushEventParams, responder?: { respond: (result: unknown) => void; respondError: (code: number, message: string) => void }, ) => { - const answer = answerOnce(responder, 'push/event', connection.id); - try { - // Only when a generation is current: with none, the event is handled in - // the turn it arrives, as it always was (the push coalescer's ordering of - // a push against its retraction depends on that). - if (this.discordAwarenessBarrier) await this.awaitDiscordAwarenessBarriers(); - // Checked here, after the barrier and before anything records the - // push as accepted: a stopped host refuses it. - if (this.queue?.isClosed) { - this.refuseServerItem('push/event', connection.id, answer, { kind: 'refused' }); - return; - } - await this.pushHandler?.handlePushEvent(connection.id, params, answer.responder as never); - } catch (error) { - this.refuseServerItem('push/event', connection.id, answer, { kind: 'failed', error }); + // Only when a generation is current: with none, the event is handled in + // the turn it arrives, as it always was (the push coalescer's ordering of + // a push against its retraction depends on that). + if (this.discordAwarenessBarrier) await this.awaitDiscordAwarenessBarriers(); + // Checked here, after the barrier and before anything records the + // push as accepted: a stopped host refuses it. + if (this.queue?.isClosed) { + this.refuseServerItem('push/event', connection.id, responder); + return; } + await this.pushHandler?.handlePushEvent(connection.id, params, responder as never); }); // Handle server-initiated inference requests (Step 6) - connection.on('inference-request', async ( + onRequest('inference-request', async ( params: McplInferenceRequestParams, responder?: { id: string | number; respond: (result: unknown) => void; respondError: (code: number, message: string) => void }, ) => { @@ -18932,61 +19053,46 @@ export class AgentFramework { return; } if (this.inferenceRouter && responder) { - const answer = answerOnce(responder, 'inference/request', connection.id); - try { - if (this.discordAwarenessBarrier) await this.awaitDiscordAwarenessBarriers(); - // A stopping host starts no inference for a server: refused, like a - // push, before the router runs. - if (this.queue?.isClosed) { - this.refuseServerItem('inference/request', connection.id, answer, { kind: 'refused' }); - return; - } - await this.inferenceRouter.handleInferenceRequest(connection.id, params, { - respond: answer.responder!.respond, - respondError: answer.responder!.respondError, - requestId: responder.id, - }); - } catch (error) { - this.refuseServerItem('inference/request', connection.id, answer, { kind: 'failed', error }); + if (this.discordAwarenessBarrier) await this.awaitDiscordAwarenessBarriers(); + // A stopping host starts no inference for a server: refused, like a + // push, before the router runs. + if (this.queue?.isClosed) { + this.refuseServerItem('inference/request', connection.id, responder); + return; } + await this.inferenceRouter.handleInferenceRequest(connection.id, params, { + respond: responder.respond, + respondError: responder.respondError, + requestId: responder.id, + }); } }); // Handle channel registration (Step 7) - connection.on('channels-register', async ( + onRequest('channels-register', async ( params: ChannelsRegisterParams, responder?: { respond: (result: unknown) => void; respondError?: (code: number, message: string) => void }, ) => { - const answer = answerOnce(responder, 'channels/register', connection.id); - try { - if (this.queue?.isClosed) { - this.refuseServerItem('channels/register', connection.id, answer, { kind: 'refused' }); - return; - } - await this.channelRegistry?.handleRegister(connection.id, params, answer.responder as never); - } catch (error) { - this.refuseServerItem('channels/register', connection.id, answer, { kind: 'failed', error }); + if (this.queue?.isClosed) { + this.refuseServerItem('channels/register', connection.id, responder); + return; } + await this.channelRegistry?.handleRegister(connection.id, params, responder as never); }); // Handle channel changes (Step 7) — §14.5 dual-mode: the responder is // present for the Request form and carries itemized added-descriptor // results; absent for Notifications, where rejection is itemwise // filtering plus a diagnostic trace. - connection.on('channels-changed', async ( + onRequest('channels-changed', async ( params: ChannelsChangedParams, responder?: { respond: (result: unknown) => void; respondError?: (code: number, message: string) => void }, ) => { - const answer = answerOnce(responder, 'channels/changed', connection.id); - try { - if (this.queue?.isClosed) { - this.refuseServerItem('channels/changed', connection.id, answer, { kind: 'refused' }); - return; - } - await this.channelRegistry?.handleChanged(connection.id, params, answer.responder as never); - } catch (error) { - this.refuseServerItem('channels/changed', connection.id, answer, { kind: 'failed', error }); + if (this.queue?.isClosed) { + this.refuseServerItem('channels/changed', connection.id, responder); + return; } + await this.channelRegistry?.handleChanged(connection.id, params, responder as never); }); // §6.6/§12: requests that previously had no handler and hung forever @@ -18994,13 +19100,15 @@ export class AgentFramework { // §17.3: a manifest-change announcement. Rate-limited re-fetch → diff // → §6.7 consequences → one receipt. The announcement itself carries no // payload and no authority; everything below acts on FETCHED content. - connection.on('manifest-changed', (params: unknown) => { - void this.handleManifestChanged(connection, params).catch((err) => { - console.error(`[mcpl] ${connection.id} manifest refresh failed:`, err instanceof Error ? err.message : err); - }); - }); - - connection.on('channels-list', ( + // A notification, contained like every inbound handler. A manifest fetch + // that fails is caught and logged inside handleManifestChanged, and the + // previous manifest stands (§17.5); anything else it throws or rejects + // with emits mcpl:request-handler-error, in this run or in a re-run it + // schedules (rerunManifestRefresh). + onRequest('manifest-changed', (params: unknown) => + this.handleManifestChanged(connection, params)); + + onRequest('channels-list', ( _params: unknown, responder?: { respond: (result: unknown) => void }, ) => { @@ -19012,7 +19120,7 @@ export class AgentFramework { // RFC-007 §6: the server's filter over tools/lifecycle. Admission already // required toolLifecycle.observe (-32002 otherwise). Validation failures // leave the previous filter in force (§6.6). - connection.on('tools-observe', ( + onRequest('tools-observe', ( params: unknown, responder?: { respond: (result: unknown) => void; respondError?: (code: number, message: string, data?: unknown) => void }, ) => { @@ -19026,7 +19134,7 @@ export class AgentFramework { responder?.respond({}); }); - connection.on('model-info', ( + onRequest('model-info', ( _params: unknown, responder?: { respond: (result: unknown) => void; respondError?: (code: number, message: string, data?: unknown) => void }, ) => { @@ -19043,60 +19151,60 @@ export class AgentFramework { }); // Handle incoming channel messages (Step 7) - connection.on('channels-incoming', async ( + onRequest('channels-incoming', async ( params: ChannelsIncomingParams, responder?: { respond: (result: unknown) => void; respondError?: (code: number, message: string) => void }, ) => { - const answer = answerOnce(responder, 'channels/incoming', connection.id); - try { - if (this.discordAwarenessBarrier) await this.awaitDiscordAwarenessBarriers(); - if (this.queue?.isClosed) { - this.refuseServerItem('channels/incoming', connection.id, answer, { kind: 'refused' }); - return; - } - await this.channelRegistry?.handleIncoming(connection.id, params, answer.responder as never); - } catch (error) { - this.refuseServerItem('channels/incoming', connection.id, answer, { kind: 'failed', error }); + if (this.discordAwarenessBarrier) await this.awaitDiscordAwarenessBarriers(); + if (this.queue?.isClosed) { + this.refuseServerItem('channels/incoming', connection.id, responder); + return; } + await this.channelRegistry?.handleIncoming(connection.id, params, responder as never); }); // Handle host-level admin commands from a surface (e.g. Discord /undo) - connection.on('host-command', async ( + onRequest('host-command', async ( params: HostCommandParams, responder?: { respond: (result: unknown) => void; respondError: (code: number, message: string) => void }, ) => { if (!responder) return; - const answer = answerOnce(responder, 'host/command', connection.id); - try { - if (this.discordAwarenessBarrier) await this.awaitDiscordAwarenessBarriers(); - // A stopping host runs no host command: refused like the requests - // above, before its handler runs, from the moment stop() has begun. - if (this.stopHasBegun()) { - this.refuseServerItem('host/command', connection.id, answer, { kind: 'refused' }); - return; - } - const result = await this.handleHostCommand(connection.id, params ?? {}); - answer.responder!.respond(result); - } catch (error) { - this.refuseServerItem('host/command', connection.id, answer, { kind: 'failed', error }); + if (this.discordAwarenessBarrier) await this.awaitDiscordAwarenessBarriers(); + // A stopping host runs no host command: refused like the requests + // above, before its handler runs, from the moment stop() has begun. + if (this.stopHasBegun()) { + this.refuseServerItem('host/command', connection.id, responder); + return; } + const result = await this.handleHostCommand(connection.id, params ?? {}); + responder.respond(result); }); - // Handle dynamic tool list changes (notifications/tools/list_changed) - connection.on('tools-list-changed', () => { + // Handle dynamic tool list changes (notifications/tools/list_changed). + // Contained like every inbound handler: a synchronous failure here emits + // mcpl:request-handler-error. A failure of the awareness accounting its + // barrier waits on is global, and failMcplDataPlaneGate reports it for + // every connection (mcpl:server-error) as it recycles them. + onRequest('tools-list-changed', () => { // Pause before starting any async refresh. This listener runs // synchronously in the transport line callback, so a following inbound // data event cannot pass before the new barrier exists. const awarenessBarrier = this.installMcplDataPlaneGate(); this.releaseMcplDataPlaneGate(awarenessBarrier); - this.handleToolsListChanged(connection.id); - void awarenessBarrier.promise.then(() => { - this.completeMcplDataPlaneGate(awarenessBarrier); - }).catch((error) => this.failMcplDataPlaneGate( - awarenessBarrier, - 'tools-list reconciliation', - error, - )); + try { + this.handleToolsListChanged(connection.id); + } finally { + // A throw from the refresh is contained like the handler's; the gate + // is still completed when its barrier settles, or failed with it, as + // on the way through. + void awarenessBarrier.promise.then(() => { + this.completeMcplDataPlaneGate(awarenessBarrier); + }).catch((error) => this.failMcplDataPlaneGate( + awarenessBarrier, + 'tools-list reconciliation', + error, + )); + } }); // Re-establish full server registration on reconnect. The 'close' handler diff --git a/src/mcpl/errors.ts b/src/mcpl/errors.ts index 7bbb90297..651c2cb92 100644 --- a/src/mcpl/errors.ts +++ b/src/mcpl/errors.ts @@ -40,6 +40,34 @@ export const CHANNEL_OPEN_FAILED = -32024; // Error Factories // ============================================================================ +/** The text of any value: anything thrown or rejected, or a value a server + * sent, such as an error answer's code. Never throws, whatever it is: a + * null-prototype object, or a message getter or toString that throws. */ +export function describeCause(cause: unknown): string { + try { + return cause instanceof Error ? String(cause.message) : String(cause); + } catch { + try { + return Object.prototype.toString.call(cause); + } catch { + return 'an error that could not be printed'; + } + } +} + +/** Text a server or a handler chose, made fit for an error's message or a + * trace field: control and format characters replaced (C0 and C1 controls, + * bidi and other \p{Cf} characters, and the line and paragraph separators + * some log readers break lines on), and cut after `max` code points, with + * "…" marking the cut. Those are read as data, by a trace's or an error + * listener's reader, so the text is bounded rather than escaped. A log line + * prints text a server or a handler chose through log-value instead + * (logValue for a field, logDetail for the free text that ends the line). */ +export function boundedForLog(text: string, max = 200): string { + const points = [...text.replace(/[\p{Cc}\p{Cf}\u2028\u2029]/gu, '?')]; + return points.length > max ? `${points.slice(0, max).join('')}…` : points.join(''); +} + /** * Create a "feature set not enabled" error. * Returned when a server sends a message tagged with a feature set diff --git a/src/mcpl/server-connection.ts b/src/mcpl/server-connection.ts index bb105f53b..7f7eb4337 100644 --- a/src/mcpl/server-connection.ts +++ b/src/mcpl/server-connection.ts @@ -14,7 +14,7 @@ import { EventEmitter } from 'node:events'; import { openTransport, type McplTransport, type TransportCloseInfo } from './transport.js'; import { maskNegotiatedCapabilities } from './capability-mask.js'; import { CapabilityGrant, expandAdvertisementShorthand } from './capability-grant.js'; -import { CAPABILITY_DISABLED } from './errors.js'; +import { CAPABILITY_DISABLED, boundedForLog, describeCause } from './errors.js'; import { logDetail, logValue } from './log-value.js'; import type { @@ -137,6 +137,13 @@ interface RequestOptions { surfaceOrphanedResponse?: boolean; } +/** A request's method for a log line, whatever the server sent there. */ +function describeMethod(method: unknown): string { + return typeof method === 'string' + ? `method ${logValue(method)}` + : `a method of type ${method === null ? 'null' : typeof method}`; +} + /** * McplServerConnection manages a single JSON-RPC 2.0 connection to an * MCPL server over stdio. Use the static `connect()` factory to create @@ -380,7 +387,7 @@ export class McplServerConnection extends EventEmitter { // Re-enter the gate for every buffered item. A control handler (notably // tools/list_changed) may install a newer data-plane barrier while this // snapshot is being flushed; later data items must observe that pause. - this.emit(event, ...args); + this.dispatchInboundEvent(event, ...args); } } finally { this.flushDepth--; @@ -407,7 +414,7 @@ export class McplServerConnection extends EventEmitter { // the old direct flush bypassed positive-grant enforcement entirely // (PR #79 review blocker 3). Data-plane items re-buffer in order via // the same call, since dataPlaneReady is still false. - this.emit(item.event, ...item.args); + this.dispatchInboundEvent(item.event, ...item.args); } } finally { this.flushDepth--; @@ -469,6 +476,29 @@ export class McplServerConnection extends EventEmitter { } return true; } + // §6.6: a request that will never be answered MUST get an error. A + // request whose event nothing on this host listens for would never be. + const request = args[1] as { + respond?: (result: unknown) => void; + respondError?: (code: number, message: string, data?: unknown) => void; + } | undefined; + if (typeof request?.respondError === 'function' && this.listenerCount(event) === 0) { + request.respondError(-32601, 'Method not found'); + console.error(`[mcpl] ${this.id}: answered -32601 to ${logValue(name)}, which nothing on this host handles`); + return true; + } + // mcpl/manifestChanged (§17.3) and tools/list_changed are notifications. + // Sent as a request, either is answered with an empty result as it's + // admitted, and passed on as the notification is, with no responder: + // the host acts on it the same way, so the answer doesn't depend on what + // the refresh does, and it's written before any request the refresh + // sends. This is where live routing and buffer flushes meet, so a request + // held while its plane is closed is answered only when it's let through, + // never by a startup that fails first. + if ((name === 'manifest-changed' || name === 'tools-list-changed') && typeof request?.respond === 'function') { + request.respond({}); + return super.emit(event, args[0]); + } return super.emit(event, ...args); } // Buffer cap (issue #122): a long data-plane pause (quiesce window) on a @@ -643,10 +673,18 @@ export class McplServerConnection extends EventEmitter { } catch { return; // Ignore non-JSON lines (e.g. logback output from Java servers) } + if (msg === null || typeof msg !== 'object' || Array.isArray(msg)) return; if (msg.id !== initId) return; cleanup(); if (msg.error) { - reject(new Error(`MCPL server "${config.id}" initialize error: ${msg.error.message}`)); + // describeCause rather than the template's own conversion: the + // server's `message` can be any JSON value, and one that has no + // primitive form, such as {"toString":1}, would throw out of this + // listener after cleanup() has cleared the timeout: an uncaught + // exception, which ends a host that doesn't catch them, and a + // handshake left to wait forever. It's the server's text in an + // error's message, so it's bounded as errors.ts says. + reject(new Error(`MCPL server "${config.id}" initialize error: ${boundedForLog(describeCause(msg.error.message))}`)); return; } const result = msg.result as Record | undefined; @@ -1262,7 +1300,9 @@ export class McplServerConnection extends EventEmitter { this.setupLifecycle(transport); // Surface transport diagnostics (stdio child stderr) as 'stderr' events, // preserving the `{ line }` payload existing consumers expect. - transport.on('stderr', (line: string) => this.emit('stderr', { line })); + // Through the same containment boundary as every inbound event, so a + // stderr listener that throws is reported, not thrown into the transport. + transport.on('stderr', (line: string) => this.dispatchInboundEvent('stderr', { line })); } /** @@ -1278,61 +1318,120 @@ export class McplServerConnection extends EventEmitter { return; } - // Is this a response to one of our outbound requests? - if ('id' in msg && msg.id != null && !('method' in msg)) { - this.handleResponse(msg as JsonRpcResponse); - return; + // JSON-RPC messages must be objects. Ignore unrelated stdout/log values + // before property access, just as malformed JSON lines are ignored. + if (msg === null || typeof msg !== 'object' || Array.isArray(msg)) return; + try { + this.dispatchMessage(msg); + } catch (error) { + const request = msg as { method?: unknown; id?: unknown }; + this.reportInboundFailure(error, { + ...(typeof request.method === 'string' ? { event: request.method } : {}), + ...(typeof request.id === 'string' || typeof request.id === 'number' ? { requestId: request.id } : {}), + }); } + }); + } - // It is an inbound request or notification from the server - const request = msg as JsonRpcRequest; - const eventName = McplServerConnection.METHOD_TO_EVENT[request.method]; - - // §7 is removed in 0.5.0: scope/elevate is no longer a method. Answer - // rather than hang (§6.6 — a method that will never be answered MUST - // return an error). - // featureSets/changed is REMOVED in 0.5.0 (§6.7 — it carried a - // server-authored change payload, the self-attestation defect; the - // need is met by §17's host-diffed manifest fetch). It was still - // routed, control-plane classified, and mutating declarations — a - // live ungated self-attestation path (PR #79 review blocker 4). - if (request.method === McplMethod.FeatureSetsChanged) { - if (request.id != null) { - this.sendErrorResponse(request.id, -32601, 'featureSets/changed removed in MCPL 0.5.0 (superseded by mcpl/manifestChanged, SPEC §17)'); - } else { - console.error(`[mcpl] ${this.id}: discarded featureSets/changed — removed in 0.5.0 (§6.7/§17)`); - } - return; + /** Contain synchronous dispatch failures; async RPC handlers own their promises. */ + private dispatchMessage(msg: JsonRpcRequest | JsonRpcResponse): void { + // Is this a response to one of our outbound requests? + if ('id' in msg && msg.id != null && !('method' in msg)) { + this.handleResponse(msg as JsonRpcResponse); + return; + } + + // It is an inbound request or notification from the server + const request = msg as JsonRpcRequest; + const eventName = typeof request.method === 'string' && Object.hasOwn(McplServerConnection.METHOD_TO_EVENT, request.method) + ? McplServerConnection.METHOD_TO_EVENT[request.method] : undefined; + + // §7 is removed in 0.5.0: scope/elevate is no longer a method. Answer + // rather than hang (§6.6 — a method that will never be answered MUST + // return an error). + // featureSets/changed is REMOVED in 0.5.0 (§6.7 — it carried a + // server-authored change payload, the self-attestation defect; the + // need is met by §17's host-diffed manifest fetch). It was still + // routed, control-plane classified, and mutating declarations — a + // live ungated self-attestation path (PR #79 review blocker 4). + if (request.method === McplMethod.FeatureSetsChanged) { + if (request.id != null) { + this.sendErrorResponse(request.id, -32601, 'featureSets/changed removed in MCPL 0.5.0 (superseded by mcpl/manifestChanged, SPEC §17)'); + } else { + console.error(`[mcpl] ${this.id}: discarded featureSets/changed — removed in 0.5.0 (§6.7/§17)`); } + return; + } - if (request.method === McplMethod.ScopeElevate) { - if (request.id != null) { - this.sendErrorResponse(request.id, -32601, 'scope/elevate removed in MCPL 0.5.0 (SPEC §7)'); - } - return; + if (request.method === McplMethod.ScopeElevate) { + if (request.id != null) { + this.sendErrorResponse(request.id, -32601, 'scope/elevate removed in MCPL 0.5.0 (SPEC §7)'); } + return; + } - // Positive-grant enforcement (§5.4, §14.1) happens at ADMISSION, in - // the emit() override below — the one choke-point that live routing - // and staged-buffer flushes share. See the comment there for why - // rejecting here, at line receipt, was wrong for staged connections. - - if (eventName) { - // Emit the typed event with params and (for requests) a respond callback - if (request.id != null) { - // Server expects a response — provide a respond helper - this.emit(eventName, request.params, { - id: request.id, - respond: (result: unknown) => this.sendResponse(request.id!, result), - respondError: (code: number, message: string, data?: unknown) => - this.sendErrorResponse(request.id!, code, message, data), - }); - } else { - // Notification — no response expected - this.emit(eventName, request.params); - } + // Positive-grant enforcement (§5.4, §14.1) happens at ADMISSION, in + // the emit() override below — the one choke-point that live routing + // and staged-buffer flushes share. See the comment there for why + // rejecting here, at line receipt, was wrong for staged connections. + + if (!eventName) { + // §6.6: a request that will never be answered MUST get an error, so a + // request (it has an id) whose method isn't a string, or isn't one this + // host handles, is answered -32601. A notification nobody handles is + // ignored, as JSON-RPC asks. + if (request.id != null) { + this.sendErrorResponse(request.id, -32601, 'Method not found'); + console.error(`[mcpl] ${this.id}: answered -32601 to a request for ${describeMethod(request.method)}, which this host doesn't handle`); } - }); + return; + } + + // Emit the typed event with params and (for requests) a respond callback + if (request.id != null) { + // Server expects a response — provide a respond helper + this.dispatchInboundEvent(eventName, request.params, { + id: request.id, + respond: (result: unknown) => this.sendResponse(request.id!, result), + respondError: (code: number, message: string, data?: unknown) => + this.sendErrorResponse(request.id!, code, message, data), + }); + } else { + // Notification — no response expected + this.dispatchInboundEvent(eventName, request.params); + } + } + + /** Live delivery and delayed plane flushes share the same containment boundary. */ + private dispatchInboundEvent(event: string, ...args: unknown[]): void { + try { + this.emit(event, ...args); + } catch (error) { + const requestId = (args[1] as { id?: unknown } | undefined)?.id; + this.reportInboundFailure(error, { + event, + ...(typeof requestId === 'string' || typeof requestId === 'number' ? { requestId } : {}), + }); + } + } + + /** Report a failure the containment boundary caught, naming the event (or + * method) and request it was dispatching, and what failed. The message is + * what the framework's 'error' listener traces. */ + private reportInboundFailure(cause: unknown, context: { event?: string; requestId?: string | number } = {}): void { + const where = (show: (text: string) => string): string => (context.event === undefined ? '' : ` for ${show(context.event)}`) + + (context.requestId === undefined ? '' : ` (request ${show(String(context.requestId))})`); + // The error's message is what the 'error' listener traces, as text a + // reader parses, so it is bounded rather than escaped (boundedForLog); + // the log line prints the same through log-value. + const error = new Error(`MCPL server "${this.id}" inbound dispatch failed${where(boundedForLog)}: ${boundedForLog(describeCause(cause))}`, { cause }); + console.error(`[mcpl] ${this.id}: inbound dispatch failed${where(logValue)}: ${logDetail(describeCause(cause))}`); + // EventEmitter's unhandled 'error' behavior would defeat containment before + // framework wiring, so stderr remains the fallback when no listener exists. + if (this.listenerCount('error') > 0) { + try { this.emit('error', error); } + catch (reportError) { console.error(`[mcpl] ${this.id}: an 'error' listener failed: ${logDetail(describeCause(reportError))}`); } + } } /** @@ -1379,8 +1478,15 @@ export class McplServerConnection extends EventEmitter { if (pending.timer) clearTimeout(pending.timer); if (response.error) { + // describeCause rather than the template's own conversion, as for an + // initialize error: the server's code and message can be any JSON + // value, and one with no primitive form, such as {"toString":1}, would + // throw here, after the request has left pendingRequests and its timer + // is cleared, so it would never settle. Both are the server's text, a + // code as much as a message, since a server can send a string, so both + // are bounded as errors.ts says. pending.reject( - new Error(`MCPL server "${this.id}" returned error for ${pending.method}: [${response.error.code}] ${response.error.message}`), + new Error(`MCPL server "${this.id}" returned error for ${pending.method}: [${boundedForLog(describeCause(response.error.code))}] ${boundedForLog(describeCause(response.error.message))}`), ); } else { pending.resolve(response.result); diff --git a/src/types/trace.ts b/src/types/trace.ts index e678a46c9..e3d951925 100644 --- a/src/types/trace.ts +++ b/src/types/trace.ts @@ -576,6 +576,47 @@ export type TraceEvent = suggestion?: string; hint: string; }) + | (TraceEventBase & { + /** An inbound RPC request/notification handler failed: it threw or + * rejected, or it resolved after a reply write of its own failed or + * after it tried to answer a second time. */ + type: 'mcpl:request-handler-error'; + serverId: string; + /** Connection event name, e.g. channels-register or push-event. */ + event: string; + /** The request's id when it is a number, or a string id bounded as the + * other texts here are: control, format and line-separator characters + * replaced, and cut after 500 code points, with "…" marking the cut. + * Absent for a notification, for a request whose id is neither, and + * for a request form of mcpl/manifestChanged or + * notifications/tools/list_changed, which is answered as it's admitted + * and then handled as the notification is. */ + requestId?: string | number; + /** Whether a reply write of the handler's returned: true once one + * did. On a connection that had already closed, that write dropped + * the reply, as the connection then drops every reply, so nothing + * reached the server. A write that throws, as one that can't be + * encoded does, sends nothing. When it's false and the responder + * can send an error reply (it has respondError), the host sent -32603 + * "Internal error" itself, or -32000 while it stops, unless + * `responseError` says that reply failed. A connection that has + * already closed drops that reply, as it drops every reply, with no + * `responseError`. */ + responseAttempted: boolean; + /** The handler's own error when it threw or rejected; otherwise the + * reply write that failed and that it swallowed, or that it tried to + * answer a second time. */ + error: string; + /** A reply write that failed, when the handler then failed with an + * error of its own (which is `error`). */ + responseFailure?: string; + /** What the handler tried to send after a reply was already attempted: + * refused, never written. A result, or an error reply with its code + * and (bounded) message. */ + refusedResponse?: { kind: 'result' } | { kind: 'error'; code: number; message: string }; + /** Failure while trying to send the internal-error response. */ + responseError?: string; + }) | (TraceEventBase & { type: 'mcpl:orphaned-response'; serverId: string; diff --git a/test/fixtures/mcpl-inbound-host-probe.mjs b/test/fixtures/mcpl-inbound-host-probe.mjs new file mode 100644 index 000000000..9906d7615 --- /dev/null +++ b/test/fixtures/mcpl-inbound-host-probe.mjs @@ -0,0 +1,48 @@ +// Runs as a separate host process: an uncaught inbound exception fails the test. +import assert from 'node:assert/strict'; +import { McplServerConnection } from '../../src/mcpl/server-connection.js'; + +const mode = process.argv[2]; +const server = String.raw` +let input = ''; +const values = ['null', '42', '"hi"', 'true', '[]']; +const send = (value) => process.stdout.write(JSON.stringify(value) + '\n'); +process.stdin.on('data', (chunk) => { + input += chunk; + let end; + while ((end = input.indexOf('\n')) >= 0) { + const line = input.slice(0, end); input = input.slice(end + 1); + const request = JSON.parse(line); + if (request.method === 'initialize') { + if (process.argv[1] === 'handshake') { + for (const value of values) process.stdout.write(value + '\n'); + } + send({jsonrpc:'2.0', id:request.id, result:{capabilities:{}}}); + } else if (request.method === 'tools/list') { + if (process.argv[1] === 'connected') { + for (const value of values) process.stdout.write(value + '\n'); + } + send({jsonrpc:'2.0', method:'notifications/tools/list_changed', params:{sequence:1}}); + send({jsonrpc:'2.0', method:'notifications/tools/list_changed', params:{sequence:2}}); + send({jsonrpc:'2.0', id:request.id, result:{tools:[]}}); + } + } +}); +`; +const connection = await McplServerConnection.connect({ + id: 'probe', command: process.execPath, args: ['-e', server, mode], requestTimeoutMs: 60_000, +}, { version: '0.5' }); +try { + const received = []; + connection.on('tools-list-changed', (params) => { + if (mode === 'throwing-listener' && params.sequence === 1) throw new Error('injected sync notification failure'); + received.push(params.sequence); + }); + // Deliberately no connection error subscriber: diagnostics must not throw. + connection.ready(); + assert.deepEqual(await connection.sendToolsList(), { tools: [] }); + assert.deepEqual(received, mode === 'throwing-listener' ? [2] : [1, 2]); + console.log('continued'); +} finally { + await connection.close(); +} diff --git a/test/fixtures/mcpl-initialize-error-probe.mjs b/test/fixtures/mcpl-initialize-error-probe.mjs new file mode 100644 index 000000000..c6ab6d134 --- /dev/null +++ b/test/fixtures/mcpl-initialize-error-probe.mjs @@ -0,0 +1,30 @@ +// Runs as a separate host process: an uncaught exception ends it, as it would end a host. +import assert from 'node:assert/strict'; +import { McplServerConnection } from '../../src/mcpl/server-connection.js'; + +// A server that answers initialize with an error whose message is an object +// with no primitive form, so a template literal can't convert it. +const server = String.raw` +let input = ''; +process.stdin.on('data', (chunk) => { + input += chunk; + let end; + while ((end = input.indexOf('\n')) >= 0) { + const request = JSON.parse(input.slice(0, end)); + input = input.slice(end + 1); + if (request.method === 'initialize') { + process.stdout.write(JSON.stringify({jsonrpc:'2.0', id:request.id, error:{code:-32603, message:{toString:1, valueOf:1}}}) + '\n'); + } + } +}); +`; +let timer; +const outcome = await Promise.race([ + McplServerConnection.connect({ id: 'probe', command: process.execPath, args: ['-e', server] }, { version: '0.5' }) + .then(() => 'connected', (error) => error), + new Promise((resolve) => { timer = setTimeout(resolve, 10_000, 'still pending after 10 s'); }), +]); +clearTimeout(timer); +assert.ok(outcome instanceof Error, String(outcome)); +assert.equal(outcome.message, 'MCPL server "probe" initialize error: [object Object]'); +console.log('refused'); diff --git a/test/mcpl-awareness-barrier.test.ts b/test/mcpl-awareness-barrier.test.ts index 6277c0797..23b6350d5 100644 --- a/test/mcpl-awareness-barrier.test.ts +++ b/test/mcpl-awareness-barrier.test.ts @@ -1181,6 +1181,10 @@ test('an inbound handler waiting on a generation that fails refuses its request // its marks were not all attempted: nothing that waited behind it may run, // and each request is answered with the failure rather than left waiting. const framework = Object.create(AgentFramework.prototype) as any; + // Each refused request is reported as a handler failure, through + // emitTrace, which iterates the trace listeners a constructed framework + // always has (#318's registrations, which onTrace makes). + framework.traceListeners = []; const failing = deferred(); framework.discordAwarenessBarrier = { generation: 1, requiresBarrier: true, promise: failing.promise }; const handled: string[] = []; diff --git a/test/mcpl-coalesced-content-parity.test.ts b/test/mcpl-coalesced-content-parity.test.ts index 4b8612b51..0c54823b6 100644 --- a/test/mcpl-coalesced-content-parity.test.ts +++ b/test/mcpl-coalesced-content-parity.test.ts @@ -145,6 +145,8 @@ test('#266: a coalescer failure is traced as the host\'s (coalesce-failed), as t assert.deepEqual(channel.result.results[0], { messageId: 'fine', accepted: false, reason: 'coalescer_broke' }, 'the wire calls it a failure'); const push = await f.send('push/event', f.params('p1', 'fine_push', { initial: true })); assert.equal(push.error?.code, -32603, 'the wire calls it a failure'); + // The push handler answers a failure itself, with its own message, as in 0.22.x. + assert.equal(push.error?.message, 'coalescer_broke'); assert.deepEqual( rejected.map(({ type, reason, detail }) => ({ type, reason, detail })), [ diff --git a/test/mcpl-request-handler-errors.test.ts b/test/mcpl-request-handler-errors.test.ts new file mode 100644 index 000000000..adfbdd081 --- /dev/null +++ b/test/mcpl-request-handler-errors.test.ts @@ -0,0 +1,1281 @@ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { EventEmitter } from 'node:events'; +import { spawnSync } from 'node:child_process'; +import { fileURLToPath } from 'node:url'; +import { inspect } from 'node:util'; + +import { AgentFramework } from '../src/framework.js'; +import { ChannelRegistry } from '../src/mcpl/channel-registry.js'; +import { InferenceRouter } from '../src/mcpl/inference-router.js'; +import { McplServerConnection } from '../src/mcpl/server-connection.js'; +import { McplTransport } from '../src/mcpl/transport.js'; +import { CapabilityGrant, ALL_CAPABILITY_PATHS } from '../src/mcpl/capability-grant.js'; +import { createMockResponse } from './helpers/mock-membrane.js'; + +function harness(connection = Object.assign(new EventEmitter(), { id: 'srv' })) { + const traces: any[] = []; + const framework = Object.create(AgentFramework.prototype) as any; + // Main's trace listeners are registrations (#318), which onTrace makes. + framework.traceListeners = []; + framework.onTrace((event: unknown) => traces.push(event)); + framework.wireMcplEvents(connection); + return { framework, connection, traces }; +} + +function responder() { + const results: unknown[] = []; + const errors: unknown[] = []; + return { + results, + errors, + id: 17, + respond(result: unknown) { results.push(result); }, + respondError(code: number, message: string, data?: unknown) { + errors.push({ code, message, data }); + }, + }; +} + +const settle = () => new Promise((resolve) => setImmediate(resolve)); +const failureTraces = (traces: any[]) => traces.filter((t) => t.type === 'mcpl:request-handler-error'); + +for (const [event, field] of [['channels-register', 'channels'], ['channels-changed', 'added']] as const) { + test(event + ': lifecycle persistence failure after ACK is traced without another response', async () => { + const { framework, connection, traces } = harness(); + const server = { + grant: new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), []), + async sendChannelsOpen() { return {}; }, + async sendChannelsClose() { return {}; }, + }; + const registry = new ChannelRegistry( + { getServer: () => server } as never, + {} as never, + () => {}, + () => {}, + ); + // Inject the reported failure at the real Chronicle append boundary. + // A descriptor without a label avoids the unrelated label-history write. + (registry as any).store = { + appendToStateJson() { throw new Error('injected lifecycle-store failure'); }, + }; + registry.setSubscriptionPolicy('srv', 'auto'); + framework.channelRegistry = registry; + const reply = responder(); + connection.emit(event, { [field]: [{ id: 'room', type: 'test', direction: 'bidirectional' }] }, reply); + // Synchronously, before reconciliation's first await settles. + assert.equal(reply.results.length, 1, 'ACK precedes reconciliation'); + await settle(); + + assert.equal(reply.results.length, 1, 'and nothing else is answered'); + assert.equal(reply.errors.length, 0, 'an accepted registration must not get a second response'); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].serverId, 'srv'); + assert.equal(failures[0].event, event); + assert.equal(failures[0].requestId, 17); + assert.equal(failures[0].responseAttempted, true); + assert.match(failures[0].error, /injected lifecycle-store failure/); + }); +} + +for (const [event, component, method] of [ + ['channels-register', 'channelRegistry', 'handleRegister'], + ['channels-changed', 'channelRegistry', 'handleChanged'], + ['channels-incoming', 'channelRegistry', 'handleIncoming'], + ['push-event', 'pushHandler', 'handlePushEvent'], + ['inference-request', 'inferenceRouter', 'handleInferenceRequest'], +] as const) { + test(event + ': rejection before a response gets one JSON-RPC internal error', async () => { + const { framework, connection, traces } = harness(); + framework[component] = { + async [method]() { + await Promise.resolve(); + throw new Error('handler failed before response'); + }, + }; + const reply = responder(); + connection.emit(event, {}, reply); + await settle(); + + assert.equal(reply.results.length, 0); + // The server gets the standard message; the handler's own text stays home. + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }]); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].event, event); + assert.equal(failures[0].responseAttempted, false); + assert.match(failures[0].error, /handler failed before response/); + }); +} + +test('notification rejection is traced without inventing a response', async () => { + const { framework, connection, traces } = harness(); + framework.channelRegistry = { async handleChanged() { throw new Error('notification failed'); } }; + connection.emit('channels-changed', {}); + await settle(); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].requestId, undefined); + assert.match(failures[0].error, /notification failed/); +}); + +test('a synchronous handler throw is contained and answered', async () => { + const { framework, connection, traces } = harness(); + framework.channelRegistry = { descriptorsForServer() { throw new Error('list failed'); } }; + const reply = responder(); + assert.doesNotThrow(() => connection.emit('channels-list', {}, reply)); + await settle(); + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }]); + assert.equal(failureTraces(traces).length, 1); + assert.match(failureTraces(traces)[0].error, /list failed/); +}); + +test('a success response whose write throws has sent nothing, so the request gets one internal-error reply', async () => { + const { framework, connection, traces } = harness(); + framework.channelRegistry = { descriptorsForServer() { return []; } }; + const reply = responder(); + let tries = 0; + reply.respond = () => { tries++; throw new Error('the result could not be encoded'); }; + assert.doesNotThrow(() => connection.emit('channels-list', {}, reply)); + await settle(); + assert.equal(tries, 1); + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }]); + assert.equal(failureTraces(traces)[0].responseAttempted, false); +}); + +test('a failed error response is traced without an escaping rejection', async () => { + const { framework, connection, traces } = harness(); + framework.channelRegistry = { async handleRegister() { throw new Error('original failure'); } }; + const reply = responder(); + let writes = 0; + reply.respondError = () => { writes++; throw new Error('error response transport failed'); }; + connection.emit('channels-register', {}, reply); + await settle(); + assert.equal(writes, 1); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.match(failures[0].error, /original failure/); + assert.match(failures[0].responseError, /error response transport failed/); +}); + +test('inference responders retain request IDs and successful handling stays synchronous', async () => { + const { framework, connection, traces } = harness(); + framework.inferenceRouter = { + handleInferenceRequest(_server: string, _params: unknown, reply: any) { + assert.equal(reply.requestId, 17); + reply.respond({ accepted: true }); + }, + }; + const reply = responder(); + connection.emit('inference-request', {}, reply); + assert.deepEqual(reply.results, [{ accepted: true }]); + await settle(); + assert.equal(reply.errors.length, 0); + assert.equal(failureTraces(traces).length, 0); +}); + +test('a real inference handler whose result write throws answers with its own error, its only reply, and the failed write is reported', async () => { + const { framework, connection, traces } = harness(); + framework.inferenceRouter = new InferenceRouter( + // The shared helper's response, so a change that has the router read more + // of a response gives this test that field along with every other test. + { async complete() { return createMockResponse([{ type: 'text', text: 'done' }]); } } as never, + { isInHook: false } as never, + { validateInbound() {} } as never, + null, + (event) => traces.push(event), + ); + const reply = responder(); + let resultWrites = 0; + // A write that throws has sent nothing, as when a result can't be encoded. + reply.respond = () => { resultWrites++; throw new Error('the result could not be encoded'); }; + connection.emit('inference-request', { + featureSet: 'test', messages: [{ role: 'user', content: 'hello' }], + }, reply); + await settle(); + assert.equal(resultWrites, 1); + // The router's own catch answers, as in 0.22.x, and the wrapper sends no + // internal-error reply after it. + assert.deepEqual(reply.errors, [{ code: -32603, message: 'the result could not be encoded', data: undefined }]); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.match(failures[0].error, /the result could not be encoded/); + assert.equal(failures[0].responseAttempted, true); +}); + +test('a real inference handler whose inference fails answers -32603 with the failure\'s own message, as in 0.22.x, and no handler failure is reported', async () => { + const { framework, connection, traces } = harness(); + framework.inferenceRouter = new InferenceRouter( + { async complete() { throw new Error('the provider refused the request'); } } as never, + { isInHook: false } as never, + { validateInbound() {} } as never, + null, + (event) => traces.push(event), + ); + const reply = responder(); + connection.emit('inference-request', { + featureSet: 'test', messages: [{ role: 'user', content: 'hello' }], + }, reply); + await settle(); + // The router answers the failure itself, so the wrapper sees none. + assert.deepEqual(reply.errors, [{ code: -32603, message: 'the provider refused the request', data: undefined }]); + assert.deepEqual(failureTraces(traces), []); +}); + +test('an error response followed by a handler rejection is not answered again', async () => { + const { framework, connection, traces } = harness(); + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + reply.respondError(-32602, 'bad params'); + throw new Error('after error response'); + }, + }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + assert.equal(reply.errors.length, 1); + assert.equal(failureTraces(traces).length, 1); + assert.match(failureTraces(traces)[0].error, /after error response/); + assert.equal(failureTraces(traces)[0].responseAttempted, true); +}); + +class ResponseTransport extends McplTransport { + constructor() { super(); } + readonly kind = 'stdio' as const; + readonly lines: string[] = []; + writeLine(line: string): void { + this.lines.push(line); + } + async close(): Promise {} +} + +function wireHarness() { + const transport = new ResponseTransport(); + // Use real connection routing and response encoding without launching a server. + const connection = new (McplServerConnection as any)('srv', null, transport) as McplServerConnection; + (connection as any).allowHostCommands = true; + connection.establishGrant(new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), [])); + const h = harness(connection); + connection.ready(); + const request = (method = 'host/command') => transport.emit('line', JSON.stringify({ + jsonrpc: '2.0', id: 17, method, params: { command: 'maintain' }, + })); + return { ...h, transport, request }; +} + +for (const kind of ['bigint', 'circular', 'throwing toJSON'] as const) { + test('host-command ' + kind + ' serialization failure receives one internal-error response', async () => { + const { framework, traces, transport, request } = wireHarness(); + let calls = 0; + const circular: any = {}; + circular.self = circular; + const progress = kind === 'bigint' ? { count: 1n } : kind === 'circular' ? circular : { + toJSON() { calls++; throw new Error('snapshot serialization failed'); }, + }; + framework.handleHostCommand = async () => ({ progress }); + request(); + await settle(); + assert.equal(transport.lines.length, 1, 'encoding failed before any result bytes were written'); + const reply = JSON.parse(transport.lines[0]!); + assert.equal(reply.id, 17); + assert.equal(reply.error.code, -32603); + assert.equal(reply.result, undefined); + assert.equal(reply.error.message, 'Internal error'); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].responseAttempted, false); + // JSON.stringify's own message says why. + assert.match(failures[0].error, kind === 'bigint' ? /BigInt/ + : kind === 'circular' ? /circular structure/ + : /snapshot serialization failed/); + if (kind === 'throwing toJSON') assert.equal(calls, 1, 'results are encoded only once'); + }); +} + +test('unserializable error data also permits one encodable error response', async () => { + const { framework, traces, transport, request } = wireHarness(); + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + reply.respondError(-32602, 'bad input', { count: 1n }); + }, + }; + request('channels/register'); + await settle(); + assert.equal(transport.lines.length, 1); + assert.equal(JSON.parse(transport.lines[0]!).error.code, -32603); + assert.equal(failureTraces(traces)[0].responseAttempted, false); +}); + +test('a swallowed pre-write encoding failure still receives a fallback response', async () => { + const { framework, traces, transport, request } = wireHarness(); + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + try { reply.respond({ count: 1n }); } catch { /* handler swallowed the error */ } + }, + }; + request('channels/register'); + await settle(); + assert.equal(transport.lines.length, 1); + assert.equal(JSON.parse(transport.lines[0]!).error.code, -32603); + assert.equal(failureTraces(traces)[0].responseAttempted, false); + assert.match(failureTraces(traces)[0].error, /BigInt/); +}); + +test('post-response failures reach stderr when no trace subscriber is attached', async (t) => { + const { framework, connection } = harness(); + framework.traceListeners = []; + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + reply.respond({ registered: [] }); + throw new Error('headless reconciliation failed'); + }, + }; + const errors: unknown[][] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { errors.push(args); }); + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + assert.equal(reply.results.length, 1); + assert.equal(reply.errors.length, 0); + assert.equal(errors.length, 1); + // One line, its text through log-value. + assert.equal(errors[0]?.length, 1); + assert.match(String(errors[0]?.[0]), /^\[mcpl\] srv channels-register handler failed: "headless reconciliation failed"$/); +}); + +for (const mode of ['handshake', 'connected', 'throwing-listener']) { + test('separate stdio host survives inbound ' + mode + ' faults and processes later messages', () => { + const probe = spawnSync(process.execPath, [ + '--import', 'tsx', fileURLToPath(new URL('./fixtures/mcpl-inbound-host-probe.mjs', import.meta.url)), mode, + ], { encoding: 'utf8', timeout: 120_000 }); + assert.equal(probe.error, undefined); + assert.equal(probe.status, 0, probe.stderr); + assert.match(probe.stdout, /continued/); + }); +} + +test('a separate stdio host whose server answers initialize with an error message no template can convert is refused well before the handshake times out, and survives', () => { + const probe = spawnSync(process.execPath, [ + '--import', 'tsx', fileURLToPath(new URL('./fixtures/mcpl-initialize-error-probe.mjs', import.meta.url)), + ], { encoding: 'utf8', timeout: 120_000 }); + assert.equal(probe.error, undefined); + assert.equal(probe.status, 0, probe.stderr); + assert.match(probe.stdout, /refused/); +}); + +test("an initialize error's message is bounded, as a server's text in the framework's errors is", { timeout: 30_000 }, async () => { + // Its message has a line break and runs past 200 code points. + const server = String.raw` +let input = ''; +process.stdin.on('data', (chunk) => { + input += chunk; + let end; + while ((end = input.indexOf('\n')) >= 0) { + const request = JSON.parse(input.slice(0, end)); + input = input.slice(end + 1); + if (request.method === 'initialize') { + process.stdout.write(JSON.stringify({jsonrpc:'2.0', id:request.id, error:{code:-32603, message:'first line\nsecond' + 'x'.repeat(300)}}) + '\n'); + } + } +}); +`; + await assert.rejects( + McplServerConnection.connect({ id: 'srv', command: process.execPath, args: ['-e', server] }, { version: '0.5' }), + { message: `MCPL server "srv" initialize error: first line?second${'x'.repeat(183)}…` }, + ); +}); + +for (const value of [null, 42, 'hi', true, []]) { + test('non-object inbound ' + JSON.stringify(value) + ' leaves the next notification deliverable', () => { + const { connection, transport } = wireHarness(); + let received = false; + connection.removeAllListeners('tools-list-changed'); + connection.on('tools-list-changed', () => { received = true; }); + assert.doesNotThrow(() => transport.emit('line', JSON.stringify(value))); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: 'notifications/tools/list_changed' })); + assert.equal(received, true); + }); +} + +for (const release of ['live', 'ready', 'readyControlPlane'] as const) { + test('synchronous notification failure is contained during ' + release + ' dispatch and traced', (t) => { + const transport = new ResponseTransport(); + const connection = new (McplServerConnection as any)('srv', null, transport) as McplServerConnection; + const { traces } = harness(connection); + const errors: unknown[][] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { errors.push(args); }); + const seen: number[] = []; + connection.removeAllListeners('tools-list-changed'); + connection.on('tools-list-changed', (params: { sequence: number }) => { + if (params.sequence === 1) throw new Error('raw notification failed'); + seen.push(params.sequence); + }); + if (release === 'live') connection.ready(); + const send = (sequence: number) => transport.emit('line', JSON.stringify({ + jsonrpc: '2.0', method: 'notifications/tools/list_changed', params: { sequence }, + })); + assert.doesNotThrow(() => { send(1); send(2); }); + if (release !== 'live') assert.doesNotThrow(() => connection[release]()); + assert.deepEqual(seen, [2]); + assert.equal(traces.filter((e) => e.type === 'mcpl:server-error').length, 1); + assert.equal(errors.length, 1); + }); +} + +for (const value of [null, 42, 'hi', true]) { + test('non-object inbound ' + JSON.stringify(value) + ' is ignored like a non-JSON line, with no failure report', (t) => { + const { connection, transport } = wireHarness(); + const errors: unknown[][] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { errors.push(args); }); + const reported: unknown[] = []; + connection.on('error', (error: unknown) => { reported.push(error); }); + transport.emit('line', JSON.stringify(value)); + assert.deepEqual(errors, []); + assert.deepEqual(reported, []); + }); +} + +test('a throwing orphaned-response listener is contained, and later messages still arrive', (t) => { + const { connection, transport, traces } = wireHarness(); + t.mock.method(console, 'error', () => {}); + connection.prependListener('orphaned-response', () => { throw new Error('orphan listener failed'); }); + let received = false; + connection.removeAllListeners('tools-list-changed'); + connection.on('tools-list-changed', () => { received = true; }); + // A response to no pending request, carrying state, is surfaced as orphaned. + assert.doesNotThrow(() => transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 999, result: { state: {} } }))); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: 'notifications/tools/list_changed' })); + assert.equal(received, true); + assert.equal(traces.filter((e) => e.type === 'mcpl:server-error').length, 1); +}); + +test('a method that is not a string is not dispatched, even if it stringifies to a known method', () => { + const { connection, transport } = wireHarness(); + let received = false; + connection.removeAllListeners('tools-list-changed'); + connection.on('tools-list-changed', () => { received = true; }); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: ['notifications/tools/list_changed'] })); + assert.equal(received, false); + // The control: the same method as a string is dispatched in this setup. + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: 'notifications/tools/list_changed' })); + assert.equal(received, true); +}); + +test('tools-observe: a synchronous failure is answered with one internal error', async () => { + const { connection, traces } = harness(); + Object.defineProperty(connection, 'toolObserveFilter', { set() { throw new Error('filter store failed'); } }); + const reply = responder(); + assert.doesNotThrow(() => connection.emit('tools-observe', { rules: [] }, reply)); + await settle(); + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }]); + assert.equal(failureTraces(traces).length, 1); + assert.match(failureTraces(traces)[0].error, /filter store failed/); +}); + +test('model-info: an error write that throws has sent nothing, so one internal-error reply is tried, and neither throw escapes', async () => { + const { connection, traces } = harness(); + const reply = responder(); + const tried: Array<{ code: number; message: string }> = []; + reply.respondError = (code: number, message: string) => { tried.push({ code, message }); throw new Error('response transport failed'); }; + assert.doesNotThrow(() => connection.emit('model-info', {}, reply)); + await settle(); + assert.equal(tried.length, 2); + assert.equal(tried[0]!.code, -32601); + assert.match(tried[0]!.message, /model\/info unavailable/); + assert.deepEqual(tried[1], { code: -32603, message: 'Internal error' }); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].responseAttempted, false); + assert.match(failures[0].error, /response transport failed/); + assert.equal(failures[0].responseFailure, undefined, 'the write failure is the error itself, not repeated'); + assert.match(failures[0].responseError, /response transport failed/); +}); + +test('a method named after an Object.prototype member is not buffered while the planes are paused', () => { + const transport = new ResponseTransport(); + const connection = new (McplServerConnection as any)('srv', null, transport) as McplServerConnection; + connection.establishGrant(new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), [])); + // Before ready(), inbound events wait in the buffer; an unknown method must not take a slot. + for (const method of ['constructor', '__proto__', 'toString', 'no/such-method']) { + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method })); + } + assert.equal((connection as any).bufferedEvents.length, 0); + // The control: a known notification does wait in the buffer here. + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: 'notifications/tools/list_changed' })); + assert.equal((connection as any).bufferedEvents.length, 1); +}); + +test('a handler that swallows an encoding failure and then fails reports its own error, and the failed write beside it', async () => { + const { framework, traces, transport, request } = wireHarness(); + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + try { reply.respond({ count: 1n }); } catch { /* swallowed */ } + throw new Error('db down'); + }, + }; + request('channels/register'); + await settle(); + assert.equal(transport.lines.length, 1, 'no bytes of the result went out, so one internal-error reply does'); + assert.deepEqual(JSON.parse(transport.lines[0]!).error, { code: -32603, message: 'Internal error' }); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.match(failures[0].error, /db down/); + assert.match(failures[0].responseFailure, /BigInt/); + assert.equal(failures[0].responseAttempted, false); +}); + +test('an answer tried after the reply is refused without throwing, so the handler reports its own error', async () => { + const { framework, connection, traces } = harness(); + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + reply.respond({ registered: [] }); + try { + await Promise.resolve(); + throw new Error('store append failed'); + } catch (error) { + reply.respondError(-32603, 'could not record the registration'); + throw error; + } + }, + }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + assert.equal(reply.results.length, 1); + assert.equal(reply.errors.length, 0, 'the second answer is never written'); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.match(failures[0].error, /store append failed/); + assert.deepEqual(failures[0].refusedResponse, { kind: 'error', code: -32603, message: 'could not record the registration' }); + assert.equal(failures[0].responseAttempted, true); +}); + +test('a handler that answers twice and resolves is still reported', async () => { + const { framework, connection, traces } = harness(); + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + reply.respond({ registered: [] }); + reply.respondError(-32602, 'second thoughts'); + }, + }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + assert.equal(reply.results.length, 1); + assert.equal(reply.errors.length, 0); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.match(failures[0].error, /second time/); + assert.deepEqual(failures[0].refusedResponse, { kind: 'error', code: -32602, message: 'second thoughts' }); +}); + +test('a rejection whose reason cannot be printed is reported and answered, with no unhandled rejection', async () => { + const { framework, connection, traces } = harness(); + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown) => { unhandled.push(reason); }; + process.on('unhandledRejection', onUnhandled); + try { + framework.channelRegistry = { + async handleRegister() { throw Object.create(null); }, + }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + await settle(); + assert.deepEqual(unhandled, []); + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }]); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(typeof failures[0].error, 'string'); + } finally { + process.off('unhandledRejection', onUnhandled); + } +}); + +test('a request for a method nothing handles is answered -32601; such a notification is ignored', (t) => { + const { transport } = wireHarness(); + const logged: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { logged.push(args.map(String).join(' ')); }); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 31, method: 'no/such-method' })); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 32, method: ['host/command'] })); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 33, method: 7 })); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: 'no/such-notification' })); + const replies = transport.lines.map((line) => JSON.parse(line)); + assert.deepEqual(replies.map((r) => [r.id, r.error?.code, r.error?.message]), [ + [31, -32601, 'Method not found'], + [32, -32601, 'Method not found'], + [33, -32601, 'Method not found'], + ]); + // One line per answered request, naming the method; none for the notification. + assert.deepEqual(logged, [ + "[mcpl] srv: answered -32601 to a request for method no/such-method, which this host doesn't handle", + "[mcpl] srv: answered -32601 to a request for a method of type object, which this host doesn't handle", + "[mcpl] srv: answered -32601 to a request for a method of type number, which this host doesn't handle", + ]); +}); + +test('a dispatch failure names the event, the request and what failed', (t) => { + const { connection, transport, traces } = wireHarness(); + const logged: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { logged.push(args.map(String).join(' ')); }); + connection.prependListener('channels-list', () => { throw new Error('listener exploded'); }); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 41, method: 'channels/list' })); + const errors = traces.filter((e) => e.type === 'mcpl:server-error'); + assert.equal(errors.length, 1); + assert.match(errors[0].error, /inbound dispatch failed for channels-list \(request 41\): listener exploded/); + // The stderr line says the same, through log-value. + assert.ok(logged.includes('[mcpl] srv: inbound dispatch failed for channels-list (request 41): "listener exploded"'), logged.join('\n')); +}); + +test('a manifest-changed handler that throws is reported as a handler failure', async (t) => { + const { framework, connection, traces } = harness(); + t.mock.method(console, 'error', () => {}); + framework.handleManifestChanged = async () => { throw new Error('manifest fetch failed'); }; + connection.emit('manifest-changed', { revision: 'r2' }); + await settle(); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].event, 'manifest-changed'); + assert.equal(failures[0].requestId, undefined); + assert.match(failures[0].error, /manifest fetch failed/); +}); + +test('a manifest fetch that fails is only logged, as in 0.22.x: the previous manifest stands, and no handler failure is reported', async (t) => { + const { framework, connection, traces } = harness(); + const errors = t.mock.method(console, 'error', () => {}); + framework.manifestRefreshState = new Map(); + framework.mcplServerConfigs = new Map([['srv', { id: 'srv' }]]); + // What a refresh changes: the grant, the feature sets, and the manifest it + // adopts with its tracking. + const changed: string[] = []; + const previous = { + capabilities: { version: '0.5' }, + manifestState: { lastValidatedRevision: 'r1', lastFetchedAt: 1 }, + droppedCapabilities: new Set(), + }; + Object.assign(connection, previous, { establishGrant() { changed.push('grant'); } }); + framework.featureSetManager = { initializeServer() { changed.push('feature sets'); } }; + (connection as any).sendManifestRequest = async () => { throw new Error('the server is gone'); }; + connection.emit('manifest-changed', { revision: 'r2' }); + await settle(); + assert.deepEqual(failureTraces(traces), []); + assert.deepEqual(errors.mock.calls.map((call) => String(call.arguments[0])), [ + '[mcpl] srv: mcpl/manifest fetch failed — previous manifest stands (§17.5): the server is gone', + ]); + assert.deepEqual(changed, []); + assert.equal((connection as any).capabilities, previous.capabilities); + assert.deepEqual((connection as any).manifestState, { lastValidatedRevision: 'r1', lastFetchedAt: 1 }); + assert.equal((connection as any).droppedCapabilities, previous.droppedCapabilities); +}); + +const manifestFetchFloorMs = (AgentFramework as any).MANIFEST_FETCH_FLOOR_MS as number; + +test('a manifest refresh deferred by the fetch floor reports a failure other than its fetch\'s, as the announcement\'s own run does', async (t) => { + t.mock.timers.enable({ apis: ['setTimeout', 'Date'], now: 100_000 }); + const { framework, connection, traces } = harness(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + // The last refresh completed just now, so this announcement waits out the floor. + framework.manifestRefreshState = new Map([['srv', { inFlight: false, queued: false, lastCompletedAt: 100_000 }]]); + framework.mcplServerConfigs = { get() { throw new Error('the deferred refresh failed before its fetch'); } }; + connection.emit('manifest-changed', { revision: 'r2' }); + await settle(); + assert.deepEqual(failureTraces(traces), [], 'nothing has run yet'); + t.mock.timers.tick(manifestFetchFloorMs); + await settle(); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].event, 'manifest-changed'); + assert.equal(failures[0].requestId, undefined); + assert.match(failures[0].error, /the deferred refresh failed before its fetch/); + assert.ok(lines.includes('[mcpl] srv manifest-changed handler failed: "the deferred refresh failed before its fetch"'), lines.join('\n')); +}); + +test('a manifest refresh queued behind a fetch in flight reports a failure other than its fetch\'s, after the first run\'s failed fetch is only logged', async (t) => { + t.mock.timers.enable({ apis: ['setTimeout', 'Date'], now: 100_000 }); + const { framework, connection, traces } = harness(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + framework.manifestRefreshState = new Map(); + let lookups = 0; + framework.mcplServerConfigs = { + get() { + lookups++; + if (lookups > 1) throw new Error('the queued refresh failed before its fetch'); + return { id: 'srv' }; + }, + }; + let failFetch!: (error: Error) => void; + (connection as any).sendManifestRequest = () => new Promise((_resolve, reject) => { failFetch = reject; }); + connection.emit('manifest-changed', { revision: 'r2' }); + // This one arrives while the first fetch is in flight, so it queues a re-run. + connection.emit('manifest-changed', { revision: 'r3' }); + failFetch(new Error('the server is gone')); + await settle(); + assert.deepEqual(failureTraces(traces), [], 'a failed fetch is only logged'); + assert.deepEqual(lines, ['[mcpl] srv: mcpl/manifest fetch failed — previous manifest stands (§17.5): the server is gone']); + t.mock.timers.tick(manifestFetchFloorMs); + await settle(); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].event, 'manifest-changed'); + assert.match(failures[0].error, /the queued refresh failed before its fetch/); + assert.equal(lookups, 2); + assert.ok(lines.includes('[mcpl] srv manifest-changed handler failed: "the queued refresh failed before its fetch"'), lines.join('\n')); +}); + +test('a server\'s error answer that no template can convert settles the host\'s request: a manifest fetch answered so is logged and leaves no refresh in flight', async (t) => { + const transport = new ResponseTransport(); + const connection = new (McplServerConnection as any)('srv', null, transport) as McplServerConnection; + connection.establishGrant(new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), [])); + const { framework, traces } = harness(connection); + connection.ready(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + framework.manifestRefreshState = new Map(); + framework.mcplServerConfigs = new Map([['srv', { id: 'srv' }]]); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: 'mcpl/manifestChanged', params: { revision: 'r2' } })); + const fetch = JSON.parse(transport.lines.at(-1)!); + assert.equal(fetch.method, 'mcpl/manifest'); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: fetch.id, error: { code: { toString: 1 }, message: { toString: 1 } } })); + await settle(); + assert.deepEqual(lines, [ + '[mcpl] srv: mcpl/manifest fetch failed — previous manifest stands (§17.5): MCPL server "srv" returned error for mcpl/manifest: [[object Object]] [object Object]', + ]); + assert.deepEqual(traces.filter((e) => e.type === 'mcpl:server-error' || e.type === 'mcpl:request-handler-error'), []); + assert.equal(framework.manifestRefreshState.get('srv').inFlight, false); +}); + +test('a server\'s error code and message in the error a host request rejects with are bounded: control, format and line characters replaced, and each cut after 200 code points', async () => { + const transport = new ResponseTransport(); + const connection = new (McplServerConnection as any)('srv', null, transport) as McplServerConnection; + connection.establishGrant(new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), [])); + connection.ready(); + const fetched = connection.sendManifestRequest(); + const fetch = JSON.parse(transport.lines.at(-1)!); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: fetch.id, error: { code: -32000, message: `line one\nline two\u202e${'x'.repeat(300)}` } })); + await assert.rejects(fetched, { + message: `MCPL server "srv" returned error for mcpl/manifest: [-32000] line one?line two?${'x'.repeat(182)}…`, + }); + // JSON-RPC's code is an integer, but a server can send a string, and it's + // the server's text as much as the message is. + const again = connection.sendManifestRequest(); + const second = JSON.parse(transport.lines.at(-1)!); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: second.id, error: { code: `E\nx\u202e${'y'.repeat(300)}`, message: 'refused' } })); + await assert.rejects(again, { + message: `MCPL server "srv" returned error for mcpl/manifest: [E?x?${'y'.repeat(196)}…] refused`, + }); +}); + +test('a throw from the wired tools/list_changed handler is contained, traced and logged as the other handlers\' are', (t) => { + const { framework, connection, traces } = harness(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + framework.handleToolsListChanged = () => { throw new Error('the tool list refresh failed'); }; + connection.emit('tools-list-changed'); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].event, 'tools-list-changed'); + assert.equal(failures[0].requestId, undefined); + assert.equal(failures[0].error, 'the tool list refresh failed'); + assert.deepEqual(lines, ['[mcpl] srv tools-list-changed handler failed: "the tool list refresh failed"']); +}); + +test('after a throw from the wired tools/list_changed handler, its data-plane gate is still completed when its barrier settles, or failed with it', async (t) => { + const { framework, connection } = harness(); + t.mock.method(console, 'error', () => {}); + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown) => { unhandled.push(reason); }; + process.on('unhandledRejection', onUnhandled); + try { + framework.handleToolsListChanged = () => { throw new Error('the tool list refresh failed'); }; + const failed: unknown[][] = []; + framework.failMcplDataPlaneGate = async (barrier: unknown, what: string, error: unknown) => { failed.push([barrier, what, error]); }; + // A barrier the data planes wait for, which settles: the gate completes. + framework.beginDiscordAwarenessBarrier = () => ({ + requiresBarrier: true, + promise: Promise.resolve({ status: 'delivered', delivered: 0, failed: 0 }), + }); + connection.emit('tools-list-changed'); + const settling = framework.discordAwarenessBarrier; + assert.ok(settling, 'the gate is installed until its barrier settles'); + await settle(); + assert.equal(framework.discordAwarenessBarrier, null, 'the gate completed'); + // One that fails: the gate is failed with it, and its rejection is handled. + const accounting = new Error('the awareness accounting failed'); + framework.beginDiscordAwarenessBarrier = () => ({ requiresBarrier: true, promise: Promise.reject(accounting) }); + connection.emit('tools-list-changed'); + const failing = framework.discordAwarenessBarrier; + await settle(); + await settle(); + assert.deepEqual(failed, [[failing, 'tools-list reconciliation', accounting]]); + assert.deepEqual(unhandled, []); + } finally { + process.off('unhandledRejection', onUnhandled); + } +}); + +test('mcpl/manifestChanged and tools/list_changed sent as requests are answered with an empty result as they are admitted, whatever their handlers do', async (t) => { + const { framework, connection, transport, traces } = wireHarness(); + t.mock.method(console, 'error', () => {}); + const manifestParams: unknown[] = []; + framework.handleManifestChanged = async (_connection: unknown, params: unknown) => { + manifestParams.push(params); + throw new Error('manifest fetch failed'); + }; + const seen: Array<{ answered: number; params: unknown; responder: unknown }> = []; + // A listener in place of the framework's tools-list-changed one, to see + // when it runs and with what. + connection.removeAllListeners('tools-list-changed'); + connection.on('tools-list-changed', (params: unknown, responder?: unknown) => { + seen.push({ answered: transport.lines.length, params, responder }); + }); + // An id of 0 makes a request like any other id. + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 0, method: 'notifications/tools/list_changed', params: { sequence: 4 } })); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 0, method: 'mcpl/manifestChanged', params: { revision: 'r2' } })); + await settle(); + assert.deepEqual(transport.lines.map((line) => JSON.parse(line)), [ + { jsonrpc: '2.0', id: 0, result: {} }, + { jsonrpc: '2.0', id: 0, result: {} }, + ]); + // Each is handled as its notification is, with its params and no + // responder, once its answer is written. + assert.deepEqual(seen, [{ answered: 1, params: { sequence: 4 }, responder: undefined }]); + assert.deepEqual(manifestParams, [{ revision: 'r2' }]); + // The failed manifest refresh is reported, and answers nothing more. + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].event, 'manifest-changed'); + assert.equal(failures[0].requestId, undefined); +}); + +test('a request form that arrives before the framework wires the connection is answered when its plane opens', async (t) => { + t.mock.method(console, 'error', () => {}); + const transport = new ResponseTransport(); + const connection = new (McplServerConnection as any)('srv', null, transport) as McplServerConnection; + connection.establishGrant(new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), [])); + // Nothing on the host listens yet, and both planes are closed, so it's held. + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 0, method: 'notifications/tools/list_changed' })); + assert.deepEqual(transport.lines, []); + harness(connection); + const seen: unknown[] = []; + connection.removeAllListeners('tools-list-changed'); + connection.on('tools-list-changed', (_params: unknown, responder?: unknown) => { seen.push(responder); }); + connection.ready(); + await settle(); + assert.deepEqual(transport.lines.map((line) => JSON.parse(line)), [{ jsonrpc: '2.0', id: 0, result: {} }]); + assert.deepEqual(seen, [undefined]); +}); + +function stagedHarness() { + const transport = new ResponseTransport(); + const connection = new (McplServerConnection as any)('srv', null, transport) as McplServerConnection; + connection.establishGrant(new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), [])); + const { framework } = harness(connection); + const refreshed: Array<{ revision?: string }> = []; + framework.handleManifestChanged = async (_connection: unknown, params: { revision?: string }) => { refreshed.push(params); }; + // The control plane open and the data plane paused, as in a quiesce. + connection.readyControlPlane(); + return { connection, transport, refreshed }; +} + +test('a request-form mcpl/manifestChanged held while the data plane is paused is answered, and its params passed on, when the data plane opens', async (t) => { + t.mock.method(console, 'error', () => {}); + const { connection, transport, refreshed } = stagedHarness(); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 3, method: 'mcpl/manifestChanged', params: { revision: 'r2' } })); + await settle(); + assert.deepEqual(transport.lines, [], 'held: mcpl/manifestChanged is a data-plane event'); + assert.deepEqual(refreshed, []); + connection.ready(); + await settle(); + assert.deepEqual(transport.lines.map((line) => JSON.parse(line)), [{ jsonrpc: '2.0', id: 3, result: {} }]); + assert.deepEqual(refreshed, [{ revision: 'r2' }]); +}); + +test('a request-form notifications/tools/list_changed is answered at once while the data plane is paused, since the control plane carries it', (t) => { + t.mock.method(console, 'error', () => {}); + const { connection, transport } = stagedHarness(); + const seen: unknown[] = []; + connection.removeAllListeners('tools-list-changed'); + connection.on('tools-list-changed', (params: unknown, responder?: unknown) => { seen.push({ params, responder }); }); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 4, method: 'notifications/tools/list_changed', params: { sequence: 9 } })); + assert.deepEqual(transport.lines.map((line) => JSON.parse(line)), [{ jsonrpc: '2.0', id: 4, result: {} }]); + assert.deepEqual(seen, [{ params: { sequence: 9 }, responder: undefined }]); +}); + +test('a request form held at the buffer cap is kept, and answered when its plane opens, while the oldest notifications are dropped', async (t) => { + const errors = t.mock.method(console, 'error', () => {}); + const { connection, transport, refreshed } = stagedHarness(); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 5, method: 'mcpl/manifestChanged', params: { revision: 'held' } })); + // 1,100 notifications pass the cap of 1,000 held events by 101. + for (let i = 0; i < 1_100; i++) { + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: 'mcpl/manifestChanged', params: { revision: `n${i}` } })); + } + connection.ready(); + await settle(); + assert.deepEqual(transport.lines.map((line) => JSON.parse(line)), [{ jsonrpc: '2.0', id: 5, result: {} }]); + assert.equal(refreshed.length, 1_000); + assert.deepEqual(refreshed.slice(0, 2), [{ revision: 'held' }, { revision: 'n101' }]); + assert.deepEqual(refreshed.at(-1), { revision: 'n1099' }); + assert.deepEqual(errors.mock.calls.map((call) => String(call.arguments[0])), [ + '[mcpl] srv: buffered-event cap (1000) — dropped 1 responder-less event(s) while the plane is paused', + '[mcpl] srv: buffered-event cap (1000) — dropped 101 responder-less event(s) while the plane is paused', + '[mcpl] srv: flushing 1000 buffered event(s) synchronously (long pause backlog; 101 dropped at cap)', + ]); +}); + +test('with nothing listening for them, their request forms are still answered -32601', (t) => { + const transport = new ResponseTransport(); + const connection = new (McplServerConnection as any)('srv', null, transport) as McplServerConnection; + connection.establishGrant(new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), [])); + connection.ready(); + t.mock.method(console, 'error', () => {}); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 0, method: 'notifications/tools/list_changed' })); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 0, method: 'mcpl/manifestChanged' })); + assert.deepEqual(transport.lines.map((line) => JSON.parse(line)), [ + { jsonrpc: '2.0', id: 0, error: { code: -32601, message: 'Method not found' } }, + { jsonrpc: '2.0', id: 0, error: { code: -32601, message: 'Method not found' } }, + ]); +}); + +test('a failed request is answered -32603 with its own id, while its trace bounds a string id and leaves out one that is neither a string nor a number', async (t) => { + const { framework, traces, transport } = wireHarness(); + t.mock.method(console, 'error', () => {}); + framework.channelRegistry = { async handleRegister() { throw new Error('register failed'); } }; + for (const id of ['a\u0000b\nc\u202e', true]) { + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id, method: 'channels/register', params: { channels: [] } })); + } + await settle(); + assert.deepEqual( + transport.lines.map((line) => JSON.parse(line)).map((reply) => [reply.id, reply.error?.code]), + [['a\u0000b\nc\u202e', -32603], [true, -32603]], + ); + assert.deepEqual(failureTraces(traces).map((trace) => trace.requestId), ['a?b?c?', undefined]); +}); + +test('the failure trace keeps a request id only when it is a string or a number, and bounds a long string', async (t) => { + const { framework, connection, traces } = harness(); + t.mock.method(console, 'error', () => {}); + framework.channelRegistry = { async handleRegister() { throw new Error('register failed'); } }; + for (const id of [{ nested: [1] }, 'x'.repeat(2000), 0]) { + connection.emit('channels-register', {}, { ...responder(), id }); + } + await settle(); + assert.deepEqual(failureTraces(traces).map((trace) => trace.requestId), [undefined, `${'x'.repeat(500)}…`, 0]); +}); + +test('a failed internal-error reply reaches stderr too', async (t) => { + const { framework, connection } = harness(); + framework.traceListeners = []; + framework.channelRegistry = { async handleRegister() { throw new Error('register failed'); } }; + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + const reply = responder(); + reply.respondError = () => { throw new Error('internal-error reply could not be written'); }; + connection.emit('channels-register', {}, reply); + await settle(); + assert.equal(lines.length, 1); + assert.match(lines[0]!, /channels-register handler failed: "register failed"/); + assert.match(lines[0]!, /the internal-error reply failed too: "internal-error reply could not be written"/); + // Its failure is the internal-error reply's, not a reply write of the handler's own. + assert.doesNotMatch(lines[0]!, /its reply write had failed/); +}); + +test("an 'error' listener that throws is caught and logged, and the next message still arrives", (t) => { + const { connection, transport } = wireHarness(); + const logged: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { logged.push(String(args[0])); }); + connection.removeAllListeners('error'); + connection.on('error', () => { throw new Error('error listener exploded'); }); + connection.prependListener('channels-list', () => { throw new Error('listener exploded'); }); + let received = false; + connection.removeAllListeners('tools-list-changed'); + connection.on('tools-list-changed', () => { received = true; }); + assert.doesNotThrow(() => transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 51, method: 'channels/list' }))); + assert.ok(logged.some((line) => line.includes(`an 'error' listener failed: "error listener exploded"`)), logged.join('\n')); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', method: 'notifications/tools/list_changed' })); + assert.equal(received, true); +}); + +test('a synchronous handler that swallows an encoding failure is reported and answered once', async () => { + const { framework, traces } = harness(); + const listener = framework.containedInboundHandler('srv', 'test-sync', (_params: unknown, reply: any) => { + try { reply.respond({ count: 1n }); } catch { /* swallowed, synchronously */ } + }); + const writes: unknown[] = []; + listener({}, { + id: 61, + // Encode before writing, as the connection does, so a reply that can't + // be encoded throws with nothing sent. + respond(result: unknown) { + JSON.stringify(result); + writes.push(result); + }, + respondError(code: number, message: string) { writes.push({ code, message }); }, + }); + await settle(); + assert.deepEqual(writes, [{ code: -32603, message: 'Internal error' }]); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(failures[0].event, 'test-sync'); + assert.match(failures[0].error, /BigInt/); +}); + +test("a stderr line whose listener throws is contained like any inbound event", (t) => { + const { connection, transport, traces } = wireHarness(); + t.mock.method(console, 'error', () => {}); + connection.prependListener('stderr', () => { throw new Error('stderr listener exploded'); }); + assert.doesNotThrow(() => transport.emit('stderr', 'a line from the server')); + const errors = traces.filter((e) => e.type === 'mcpl:server-error'); + assert.equal(errors.length, 1); + assert.match(errors[0].error, /inbound dispatch failed for stderr: stderr listener exploded/); +}); + +test('a rejection no printer can inspect still reaches the trace first', async (t) => { + const { framework, connection, traces } = harness(); + // Print as console.error does: every argument goes through util.inspect. + t.mock.method(console, 'error', (...args: unknown[]) => { for (const arg of args) inspect(arg); }); + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown) => { unhandled.push(reason); }; + process.on('unhandledRejection', onUnhandled); + try { + // String() throws on it, and so does printing it. + const hostile = { + [inspect.custom]() { throw new Error('inspect refused'); }, + [Symbol.toPrimitive]() { throw new Error('toPrimitive refused'); }, + }; + framework.channelRegistry = { async handleRegister() { throw hostile; } }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + await settle(); + assert.deepEqual(unhandled, []); + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }]); + const failures = failureTraces(traces); + assert.equal(failures.length, 1); + assert.equal(typeof failures[0].error, 'string'); + } finally { + process.off('unhandledRejection', onUnhandled); + } +}); + +test("a trace listener that throws a value no printer can inspect is logged as text, the listeners after it still get the trace, and nothing escapes", async (t) => { + const { framework, connection, traces } = harness(); + // Print as console.error does: an argument that isn't a string goes + // through util.inspect, so logging the listener's throw raw throws too. + const logged: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { + logged.push(args.map((arg) => (typeof arg === 'string' ? arg : inspect(arg))).join(' ')); + }); + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown) => { unhandled.push(reason); }; + process.on('unhandledRejection', onUnhandled); + // With no prototype, a template can't convert it either: only + // describeCause's text keeps the fallback line from throwing. + const hostile = Object.assign(Object.create(null), { [inspect.custom]() { throw new Error('inspect refused'); } }); + const offHostile = framework.onTrace(() => { throw hostile; }); + const after: any[] = []; + const offAfter = framework.onTrace((event: unknown) => after.push(event)); + // The handler's own error can't be put in a template either, so the + // report must convert it. + const primary = Object.assign(new Error('register failed'), { + [Symbol.toPrimitive]() { throw new Error('toPrimitive refused'); }, + }); + try { + framework.channelRegistry = { async handleRegister() { throw primary; } }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + await settle(); + assert.deepEqual(unhandled, []); + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }]); + assert.equal(failureTraces(traces).length, 1, 'the listener before the throwing one has the trace'); + assert.equal(failureTraces(after).length, 1, 'the listener after the throwing one has it too'); + assert.deepEqual(logged, [ + 'Trace listener error: "[object Object]"', + '[mcpl] srv channels-register handler failed: "register failed"', + ]); + } finally { + offHostile(); + offAfter(); + process.off('unhandledRejection', onUnhandled); + } +}); + +test('a request for an event nothing on the host listens for is answered -32601', (t) => { + const { connection, transport } = wireHarness(); + const logged: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { logged.push(args.map(String).join(' ')); }); + connection.removeAllListeners('channels-list'); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 71, method: 'channels/list' })); + const replies = transport.lines.map((line) => JSON.parse(line)); + assert.deepEqual(replies.map((r) => [r.id, r.error?.code, r.error?.message]), [[71, -32601, 'Method not found']]); + assert.deepEqual(logged, ['[mcpl] srv: answered -32601 to channels-list, which nothing on this host handles']); +}); + +test("a long handler error is bounded in its trace, and its log line is cut with its length", async (t) => { + const { framework, connection, traces } = harness(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + framework.channelRegistry = { async handleRegister() { throw new Error('x'.repeat(5000)); } }; + connection.emit('channels-register', {}, responder()); + await settle(); + const failure = traces.find((e) => e.type === 'mcpl:request-handler-error'); + assert.equal(failure?.error, `${'x'.repeat(500)}…`); + assert.equal(lines.length, 1); + assert.ok(lines[0]!.length < 600, `logged ${lines[0]!.length} characters`); + assert.ok(lines[0]!.endsWith('…(5000)'), lines[0]!.slice(-40)); +}); + +test("the log line prints a failed reply write and a refused answer raw, and only the trace's copies are bounded", async (t) => { + const { framework, connection, traces } = harness(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + // The first write throws, sending nothing; the second is written; the + // third is refused. + try { reply.respond({ registered: [] }); } catch { /* swallowed */ } + reply.respond({ registered: [] }); + reply.respondError(-32602, 'second\u0007answer'); + throw new Error('handler\u0007failed'); + }, + }; + const reply = responder(); + const respond = reply.respond; + let first = true; + reply.respond = (result: unknown) => { + if (first) { first = false; throw new Error('write\u0007broke'); } + respond(result); + }; + connection.emit('channels-register', {}, reply); + await settle(); + assert.equal(reply.errors.length, 0, 'the written answer stands: no internal-error reply follows it'); + const failure = failureTraces(traces)[0]; + assert.equal(failure.responseAttempted, true); + assert.equal(failure.error, 'handler?failed'); + assert.equal(failure.responseFailure, 'write?broke'); + assert.deepEqual(failure.refusedResponse, { kind: 'error', code: -32602, message: 'second?answer' }); + assert.equal(lines.length, 1); + assert.ok(lines[0]!.includes('handler failed: "handler\\u0007failed"'), lines[0]); + assert.ok(lines[0]!.includes('its reply write had failed: "write\\u0007broke"'), lines[0]); + assert.ok(lines[0]!.includes('it then tried to answer again with "error -32602: second\\u0007answer"'), lines[0]); +}); + +test('an answer the handler tried after its first, with a code no template can convert, is printed with describeCause\'s text for the code, and nothing escapes', async (t) => { + const { framework, connection, traces } = harness(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown) => { unhandled.push(reason); }; + process.on('unhandledRejection', onUnhandled); + // A code with no prototype: a template throws on it. + const code = Object.create(null) as number; + try { + framework.channelRegistry = { + async handleRegister(_server: string, _params: unknown, reply: any) { + reply.respond({ registered: [] }); + reply.respondError(code, 'again'); + throw new Error('register failed'); + }, + }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + await settle(); + assert.deepEqual(unhandled, []); + assert.equal(failureTraces(traces).length, 1); + assert.equal(lines.length, 1); + assert.ok(lines[0]!.includes('handler failed: "register failed"'), lines[0]); + assert.ok(lines[0]!.includes('it then tried to answer again with "error [object Object]: again"'), lines[0]); + } finally { + process.off('unhandledRejection', onUnhandled); + } +}); + +test('a throw out of the report on the async path is caught by its backstop and logged on a line of its own, and nothing escapes', async (t) => { + const { framework, connection } = harness(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown) => { unhandled.push(reason); }; + process.on('unhandledRejection', onUnhandled); + // A defect in the report itself: its trace throws, with a text that + // would print a second line raw. + framework.emitTrace = () => { throw new Error('the trace failed\n[mcpl] srv forged'); }; + try { + framework.channelRegistry = { async handleRegister() { throw new Error('register failed'); } }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + await settle(); + assert.deepEqual(unhandled, []); + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }], 'the reply is sent before the trace'); + assert.deepEqual(lines, ["[mcpl] srv channels-register: the handler failure's report threw: \"the trace failed\\n[mcpl] srv forged\""]); + } finally { + process.off('unhandledRejection', onUnhandled); + } +}); + +test('a backstop whose own log line throws leaves nothing unhandled', async (t) => { + const { framework, connection } = harness(); + t.mock.method(console, 'error', () => { throw new Error('the console is gone'); }); + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown) => { unhandled.push(reason); }; + process.on('unhandledRejection', onUnhandled); + framework.emitTrace = () => { throw new Error('the trace failed'); }; + try { + framework.channelRegistry = { async handleRegister() { throw new Error('register failed'); } }; + const reply = responder(); + connection.emit('channels-register', {}, reply); + await settle(); + await settle(); + assert.deepEqual(unhandled, []); + assert.deepEqual(reply.errors, [{ code: -32603, message: 'Internal error', data: undefined }]); + } finally { + process.off('unhandledRejection', onUnhandled); + } +}); + +test("the log line prints a failed internal-error reply raw, and only the trace's copy is bounded", async (t) => { + const { framework, connection, traces } = harness(); + const lines: string[] = []; + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }); + framework.channelRegistry = { async handleRegister() { throw new Error('original failure'); } }; + const reply = responder(); + reply.respondError = () => { throw new Error('send\u0007failed'); }; + connection.emit('channels-register', {}, reply); + await settle(); + assert.equal(failureTraces(traces)[0].responseError, 'send?failed'); + assert.equal(lines.length, 1); + assert.ok(lines[0]!.includes('the internal-error reply failed too: "send\\u0007failed"'), lines[0]); +}); + +test('a value printing cannot handle still leaves a stderr line naming the failure', async (t) => { + const { framework, connection } = harness(); + framework.traceListeners = []; + const lines: string[] = []; + // Print as console.error does, and keep what it printed. + t.mock.method(console, 'error', (...args: unknown[]) => { lines.push(args.map((a) => typeof a === 'string' ? a : inspect(a)).join(' ')); }); + const hostile = { + [inspect.custom]() { throw new Error('inspect refused'); }, + toString() { return 'the hostile failure'; }, + }; + framework.channelRegistry = { async handleRegister() { throw hostile; } }; + connection.emit('channels-register', {}, responder()); + await settle(); + assert.equal(lines.length, 1); + // The line is built from strings through log-value, so nothing inspects the value. + assert.match(lines[0]!, /channels-register handler failed: "the hostile failure"$/); +}); + +test('log text from a server has control, format and separator characters replaced', (t) => { + const { connection, transport, traces } = wireHarness(); + t.mock.method(console, 'error', () => {}); + connection.prependListener('channels-list', () => { throw new Error('a\u2028b\u202ec\u0007d'); }); + transport.emit('line', JSON.stringify({ jsonrpc: '2.0', id: 81, method: 'channels/list' })); + const errors = traces.filter((e) => e.type === 'mcpl:server-error'); + assert.equal(errors.length, 1); + assert.match(errors[0].error, /: a\?b\?c\?d$/); +}); diff --git a/test/stop-with-work-in-flight.test.ts b/test/stop-with-work-in-flight.test.ts index bfc28ddfa..f192572a5 100644 --- a/test/stop-with-work-in-flight.test.ts +++ b/test/stop-with-work-in-flight.test.ts @@ -14,7 +14,9 @@ * - a server's push, incoming message or other request the host can't * take any more is answered with a JSON-RPC error (-32000, "the host is * stopping"), never "accepted", and never thrown out of the - * connection's listener; a handler's own fault is answered -32603. + * connection's listener; a handler's own fault is answered -32603, + * "Internal error", or -32000 with the stop wording alone once the host + * is stopping, and its own text goes only to the host's log. * Any other event pushed to a stopped framework still throws to its caller. * A turn waiting to retry is work in flight too: stop() cancels the retry, * and leaves no agent inferring at the event gate, which a start() after the @@ -680,23 +682,28 @@ describe('stop() with work still in flight', () => { ] as const; /** - * A server's responder, recording each answer. - * - throws: respondError records its answer, then throws (the connection is going). + * A server's responder, recording each answer it sends, and in `tried` + * each error answer asked of it. + * - throws: respondError throws, sending nothing (the connection is going). * - serializes: respond serializes the result before it records it, as the - * connection's sendResponse does, so a result JSON can't hold throws. + * connection's sendResponse does, so a result JSON can't hold throws, + * with nothing sent. */ function responder(opts: { throws?: boolean; serializes?: boolean } = {}) { const answers: Array<{ result?: unknown; error?: { code: number; message: string } }> = []; + const tried: Array<{ code: number; message: string }> = []; return { id: 7, answers, + tried, respond: (result: unknown) => { if (opts.serializes) JSON.stringify(result); answers.push({ result }); }, respondError: (code: number, message: string) => { - answers.push({ error: { code, message } }); + tried.push({ code, message }); if (opts.throws) throw new Error('the connection is gone'); + answers.push({ error: { code, message } }); }, }; } @@ -763,7 +770,7 @@ describe('stop() with work still in flight', () => { }); } - it('a handler running when the host stops, and then failing, is answered -32000 with its own message', async () => { + it('a handler running when the host stops, and then failing, is answered -32000 with the stop wording alone', async () => { const { framework, connection } = await wiredFramework(); let release!: () => void; const gate = new Promise((r) => { release = r; }); @@ -777,13 +784,12 @@ describe('stop() with work still in flight', () => { release(); await answered(push); - const reason = 'the host stopped while handling this request (Queue is closed)'; - assert.deepEqual(push.answers, [{ error: { code: -32000, message: reason } }]); - assert.ok(logged.some((line) => line.includes(`push/event from srv failed: ${reason} (part of it may already have been admitted)`)), logged.join('\n')); + assert.deepEqual(push.answers, [{ error: { code: -32000, message: 'the host stopped while handling this request' } }]); + assert.ok(logged.some((line) => line.includes('[mcpl] srv push-event handler failed: "Queue is closed"')), logged.join('\n')); assert.deepEqual(rejections, []); }); - it('a handler that throws is answered -32603 with its error, not rejected into the listener; a notification is only logged', async () => { + it('a handler that throws is answered -32603 "Internal error", not rejected into the listener, and its error is logged; a notification is only logged', async () => { const { framework, connection } = await wiredFramework(); try { (framework as unknown as { pushHandler: unknown }).pushHandler = { @@ -796,8 +802,9 @@ describe('stop() with work still in flight', () => { await answered(push); await until(() => logged.some((line) => line.includes('the handler broke on e4')), "the notification's log line"); - assert.deepEqual(push.answers, [{ error: { code: -32603, message: 'the handler broke on e3' } }]); - assert.ok(logged.some((line) => line.includes('push/event from srv failed: the handler broke on e4 (part of it may already have been admitted)')), logged.join('\n')); + assert.deepEqual(push.answers, [{ error: { code: -32603, message: 'Internal error' } }]); + assert.ok(logged.some((line) => line.includes('[mcpl] srv push-event handler failed: "the handler broke on e3"')), logged.join('\n')); + assert.ok(logged.some((line) => line.includes('[mcpl] srv push-event handler failed: "the handler broke on e4"')), logged.join('\n')); assert.deepEqual(rejections, []); } finally { await framework.stop(); @@ -840,13 +847,9 @@ describe('stop() with work still in flight', () => { connection.emit('channels-incoming', { messages: [{ channelId: 'c', messageId: 'm', content: [] }] }, incoming); await answered(e5, e7, e8, e12, e13, e14, incoming); - assert.deepEqual(e5.answers, [{ error: { code: -32603, message: 'the handler failed' } }]); - assert.deepEqual(e7.answers, [{ error: { code: -32603, message: 'the handler failed: a plain string' } }]); - assert.deepEqual(e8.answers, [{ error: { code: -32603, message: 'the handler failed: (a value that could not be read)' } }]); - assert.deepEqual(e12.answers, [{ error: { code: -32603, message: 'the handler failed: (a value that could not be read)' } }]); - assert.deepEqual(e13.answers, [{ error: { code: -32603, message: '42' } }]); - assert.deepEqual(e14.answers, [{ error: { code: -32603, message: '(a value that could not be read)' } }]); - assert.deepEqual(incoming.answers, [{ error: { code: -32603, message: 'the handler failed' } }]); + for (const r of [e5, e7, e8, e12, e13, e14, incoming]) { + assert.deepEqual(r.answers, [{ error: { code: -32603, message: 'Internal error' } }]); + } assert.ok(!logged.some((line) => line.includes('refused')), 'a live host refuses nothing'); assert.deepEqual(rejections, []); } finally { @@ -854,7 +857,7 @@ describe('stop() with work still in flight', () => { } }); - it('a long error is answered and logged bounded', async () => { + it("a long error is answered with the standard message, and logged bounded", async () => { const { framework, connection } = await wiredFramework(); try { (framework as unknown as { pushHandler: unknown }).pushHandler = { @@ -863,9 +866,10 @@ describe('stop() with work still in flight', () => { const push = responder(); connection.emit('push-event', { featureSet: 'chat', eventId: 'e9', payload: { content: [{ type: 'text', text: 'x' }] } }, push); await answered(push); - const message = push.answers[0]!.error!.message; - assert.ok(message.length < 600, `answered ${message.length} characters`); - assert.match(message, /… \(5000 characters\)$/); + assert.deepEqual(push.answers, [{ error: { code: -32603, message: 'Internal error' } }]); + const line = logged.find((l) => l.includes('push-event handler failed')) ?? ''; + assert.ok(line.length < 600, `logged ${line.length} characters`); + assert.ok(line.endsWith('…(5000)'), line.slice(-40)); } finally { await framework.stop(); } @@ -883,10 +887,10 @@ describe('stop() with work still in flight', () => { const push = responder(); connection.emit('push-event', { featureSet: 'chat', eventId: 'e10', payload: { content: [{ type: 'text', text: 'x' }] } }, push); await answered(push); - await until(() => logged.some((line) => line.includes('failed after it was answered')), 'the log line'); + await until(() => logged.some((line) => line.includes('the trace emit broke')), 'the log line'); assert.deepEqual(push.answers, [{ result: { accepted: true } }]); - assert.ok(logged.some((line) => line.includes('push/event from srv failed after it was answered: the trace emit broke')), logged.join('\n')); + assert.ok(logged.some((line) => line.includes('[mcpl] srv push-event handler failed: "the trace emit broke"')), logged.join('\n')); assert.deepEqual(rejections, []); } finally { await framework.stop(); @@ -903,8 +907,8 @@ describe('stop() with work still in flight', () => { connection.emit('push-event', { featureSet: 'chat', eventId: 'e21', payload: { content: [{ type: 'text', text: 'x' }] } }, push); await answered(push); - assert.deepEqual(push.answers, [{ error: { code: -32603, message: 'Do not know how to serialize a BigInt' } }]); - assert.ok(!logged.some((line) => line.includes('failed after it was answered')), logged.join('\n')); + assert.deepEqual(push.answers, [{ error: { code: -32603, message: 'Internal error' } }]); + assert.ok(!logged.some((line) => line.includes('a second answer was refused')), logged.join('\n')); assert.deepEqual(rejections, []); } finally { await framework.stop(); @@ -921,11 +925,11 @@ describe('stop() with work still in flight', () => { const push = responder(); connection.emit('push-event', { featureSet: 'chat', eventId: 'e22', payload: { content: [{ type: 'text', text: 'x' }] } }, push); await answered(push); - await until(() => logged.some((line) => line.includes('a second answer (respond) was refused')), 'the refused second answer'); + await until(() => logged.some((line) => line.includes('a second answer was refused')), 'the refused second answer'); await turn(); - assert.deepEqual(push.answers, [{ error: { code: -32603, message: 'the handler broke first' } }]); - assert.ok(logged.some((line) => line.includes('push/event from srv: a second answer (respond) was refused; the request was already answered')), logged.join('\n')); + assert.deepEqual(push.answers, [{ error: { code: -32603, message: 'Internal error' } }]); + assert.ok(logged.some((line) => line.includes('[mcpl] srv push-event: a second answer was refused; the request was already answered')), logged.join('\n')); assert.deepEqual(rejections, []); } finally { await framework.stop(); @@ -955,7 +959,7 @@ describe('stop() with work still in flight', () => { } }); - it("every request listener answers its handler's throw -32603 with its error, never rejecting into the listener", async () => { + it("every request listener answers its handler's throw -32603 \"Internal error\" and logs the error, never rejecting into the listener", async () => { const { framework, connection } = await wiredFramework(); try { standIns(framework, async () => { throw new Error('the handler broke'); }); @@ -966,9 +970,9 @@ describe('stop() with work still in flight', () => { }); await answered(...answers); - for (const [i, [, method]] of requests.entries()) { - assert.deepEqual(answers[i]!.answers, [{ error: { code: -32603, message: 'the handler broke' } }], method); - assert.ok(logged.some((line) => line.includes(`${method} from srv failed: the handler broke`)), `${method}:\n${logged.join('\n')}`); + for (const [i, [event, method]] of requests.entries()) { + assert.deepEqual(answers[i]!.answers, [{ error: { code: -32603, message: 'Internal error' } }], method); + assert.ok(logged.some((line) => line.includes(`[mcpl] srv ${event} handler failed: "the handler broke"`)), `${method}:\n${logged.join('\n')}`); } assert.deepEqual(rejections, []); } finally { @@ -984,9 +988,16 @@ describe('stop() with work still in flight', () => { fw.pushCoalescer = { isRendering: () => true, suspend: () => {}, flush: () => {} }; const inference = responder({ throws: true }); connection.emit('inference-request', { messages: [] }, inference); - await answered(inference); + // A write that throws sent nothing, so the request is answered once + // more, as any handler's unanswered failure is; that throws too. + await until(() => inference.tried.length >= 2, 'the internal-error answer after the refusal failed'); + await turn(); - assert.deepEqual(inference.answers, [{ error: { code: -32600, message: 'Cannot request inference while push/render is in progress' } }]); + assert.deepEqual(inference.tried, [ + { code: -32600, message: 'Cannot request inference while push/render is in progress' }, + { code: -32603, message: 'Internal error' }, + ]); + assert.deepEqual(inference.answers, []); assert.deepEqual(rejections, []); fw.pushCoalescer = coalescer; } finally { @@ -999,9 +1010,13 @@ describe('stop() with work still in flight', () => { await framework.stop(); const push = responder({ throws: true }); connection.emit('push-event', { featureSet: 'chat', eventId: 'e11', payload: { content: [{ type: 'text', text: 'x' }] } }, push); - await answered(push); + // The refusal's write threw, sending nothing, so the request is answered + // once more with the stop wording a failed handler gets; that throws too. + await until(() => push.tried.length >= 2, 'the stop answer after the refusal failed'); + await turn(); - assert.deepEqual(push.answers, [stopping]); + assert.deepEqual(push.tried, [stopping.error, { code: -32000, message: 'the host stopped while handling this request' }]); + assert.deepEqual(push.answers, []); assert.ok(logged.some((line) => line.includes('push/event from srv refused: the host is stopping')), logged.join('\n')); assert.deepEqual(rejections, []); });