diff --git a/changelog.d/266-coalesced-content-parity.fixed.md b/changelog.d/266-coalesced-content-parity.fixed.md new file mode 100644 index 000000000..000b4355c --- /dev/null +++ b/changelog.d/266-coalesced-content-parity.fixed.md @@ -0,0 +1,3 @@ +- A coalesced MCPL message with inline images is admitted like any other message (#266). Coalesced `channels/incoming` and `push/event` items, and render results, were checked against a 1 MiB budget on their serialized content, inline base64 images included, which uncoalesced messages never had. Any message with a sizeable screenshot was refused as `coalesce_invalid`, never stored and never woke the agent, and discord-mcpl tags every message create with `coalesce`. An incoming coalesced item's content must be an array of objects with something visible in it (a retraction may be empty, and on the push lane so may a silent heartbeat), and within that it is admitted as an uncoalesced message is: a block the converters can't render, such as a video or an unknown type, becomes the same placeholder whether or not the message was coalesced. The converters of both lanes now take any object without throwing: a block's type, text, data, mimeType or uri that isn't a string is treated as absent, so a malformed block becomes a placeholder too (a text block, no text) instead of throwing in conversion, where the sender got no answer and a `channels/incoming` batch stopped before its later messages. An image or audio block that has data but no usable media type reads `[Image: no media type]` or `[Audio: no media type]` rather than claiming no data, and an image or audio block with a disposition is a reference only when its uri is a non-empty string. A `shouldTriggerInference` filter, and so the EventGate's content filter, reads on both lanes the text the agent's context gets, the converted text blocks joined with line breaks: on the channel lane, which read the message's own text blocks before, a block that converts to text (an unknown type's placeholder, an image with no data, a reference stub) is now part of what a filter matches, as it already was on the push lane, and text that isn't a string reads as empty. A render result, which the host delivers in the occurrence's place, gets every check a pushed payload gets (RFC-006 §5.2) except visible emptiness, since an empty render means nothing happened, and one more: each block must be one the converters show as itself (its text, or its image or audio source) or as a reference stub. A render with a block that would show as a placeholder falls back to the occurrence's own content, which a pushed payload doesn't have. The 4 KiB bound on `coalesce.data`, which the coalescer holds outside context, is unchanged. + Every coalesce rejection is now visible on the host as well as on the wire: as a `mcpl:channel-incoming-rejected` or `mcpl:push-event-rejected` trace with the error's message in `detail` and the failing `field` when the error names one, and as a line, unless it is a push refused for its channel within a minute of that channel's last line (below). A coalesce rejection's `[channel-incoming-rejected]` line names the server, channel, message id and failing field, and its `[push-event-rejected]` line names the server, feature set, event id and failing field; each ends with the error's message. When a channel's refusals were held back, the next line printed for it adds how many. The reason follows the answer the sender got: `coalesce-invalid` when the item was the sender's to fix (malformed, or a push to a channel it isn't permitted or hasn't registered), `coalesce-failed` when the host itself failed (coalescing unavailable, the host stopping or unable to make an acceptance durable, or an internal error). A `channels/incoming` message for an unregistered channel now gets a line too (`reason=unknown-channel`), coalesced or not. So that a server that never registered a busy channel doesn't print a line for every message in it, a channel's first refusal prints, and after that a refusal prints only once a minute has passed since the channel's last line, naming how many were held back since; a channel-scoped push refused because its channel isn't declared (-32023) or may not be used (-32017) prints the same way on its own lane, per channel, and its line and its trace name the channel. Every refusal is still answered and traced. The unknown-channel trace carries the message id, and its reason is now `unknown-channel`, the line's token (it was `unknown channel — not registered (§14.5)`). A render result the host refuses gets a `[push-render-failed]` line naming the server, subject, event id and failing field, and the occurrence's own content is delivered instead. A missing push `eventId` prints as `""` on every `[push-event-rejected]` line, and the push rejection trace carries `''`. The wire answers are unchanged. + The host log lines listed here now print the values a server chose (channel, message and event ids, feature set and field names, a tool's name and declared classes, an advertised capability's key, a discarded method's name) in a form a server can't use to add a line that reads as another host record, a word that reads as another field of the same line, or a `key=` that a search for that field finds before the real one. That covers every `[channel-incoming-rejected]` and `[push-event-rejected]` line, the existing empty-content, duplicate and feature-set rejections included; the `[channel-incoming-dropped]` and `[push-event-dropped]` backstops; the `[routeSpeech]` delivery and closed-locus lines; the `[inference-refusal]` line for a locus with no server; both conversation spawn-failure lines, the routed message's and the coalesced batch's; the `[heartbeat]` silent-wake line; the feature-set disabled line, the tool-class lines, the masked-capability line and the discarded-method line. A plain token (visible characters with no space, quote, backslash or `=`) prints as before. Anything else prints as a JSON string with every `=`, every space and every invisible character escaped (a line break, a terminal escape, a bidi control, a default-ignorable character such as a Hangul filler or a variation selector), so `JSON.parse` of it gives back exactly what was sent. A value longer than 256 UTF-16 units is cut instead: it prints, quoted, as its first 256 (255 when the 256th is a high surrogate) followed by `…(N)` with N its full length. A value that isn't a string prints as its JSON text, a non-finite number as `NaN` or `Infinity`. The feature-set rejection's reason, which names the feature set, is a field like any other: `reason="Unknown\u0020feature\u0020set:\u0020…"`. The `[inference-refusal]` line's locus, and a plain unknown tool class, now print without literal quotes. The host's own message at the end of a line is quoted and cut the same way but keeps its plain spaces and `=`. diff --git a/src/framework.ts b/src/framework.ts index 349bdd693..035e5daf1 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -65,6 +65,7 @@ import { REFUSAL_REACTIONS, REFUSAL_REACTION_FALLBACK } from './refusal-reaction import { Agent } from './agent.js'; import { ModuleRegistry, isStateExistsError } from './module-registry.js'; import { McplServerRegistry } from './mcpl/server-registry.js'; +import { 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'; @@ -4793,7 +4794,7 @@ export class AgentFramework { const server = serverId ? this.mcplServerRegistry?.getServer(serverId) : null; if (!server) { console.error( - `[inference-refusal] reaction skipped: no MCPL server for locus "${incoming.channelId}" (agent=${agentName})`, + `[inference-refusal] reaction skipped: no MCPL server for locus ${logValue(incoming.channelId)} (agent=${agentName})`, ); return; } @@ -7100,7 +7101,7 @@ export class AgentFramework { // Same backstop as the push lane: no row, no wake, no fork spawned for a // message with nothing visible in it. if (isVisiblyEmptyContent(event.content)) { - console.error(`[channel-incoming-dropped] server=${event.serverId} channel=${event.channelId} messageId=${event.messageId} reason=empty-content`); + console.error(`[channel-incoming-dropped] server=${event.serverId} channel=${logValue(event.channelId)} messageId=${logValue(event.messageId)} reason=empty-content`); this.emitTrace({ type: 'mcpl:empty-content-dropped', lane: 'channel', serverId: event.serverId, channelId: event.channelId, messageId: event.messageId, ...(event.eventId ? { eventId: event.eventId } : {}), @@ -7286,7 +7287,7 @@ export class AgentFramework { }); } catch (error) { const err = error instanceof Error ? error : new Error(String(error)); - console.error(`Failed to spawn conversation agent for ${event.channelId}:`, err); + console.error(`Failed to spawn conversation agent for ${logValue(event.channelId)}:`, err); this.emitTrace({ type: 'mcpl:conversation-spawn-failed', channelId: event.channelId, @@ -7642,7 +7643,21 @@ export class AgentFramework { if (!server?.isConnected) throw new Error('server disconnected'); return server.sendPushRender(params); }, - audit: (record) => this.emitTrace({ type: 'mcpl:coalescing', ...record }), + audit: (record) => { + // A render result the host refused falls back to the occurrence's own + // content; say so on the host, with the server, the subject and the + // failing field, not only in the trace. The error is a field like the + // rest (logValue, spaces escaped), not a host-message tail: a server + // that answers push/render with an error chooses its message. + if (record.kind === 'render-failed') { + console.error( + `[push-render-failed] server=${logValue(record.serverId ?? '')} subject=${logValue(record.subject ?? '')} ` + + `eventId=${logValue(record.eventId ?? '')}${record.field !== undefined ? ` field=${logValue(record.field)}` : ''}: ` + + `${logValue(record.error ?? '')} (the occurrence's own content is delivered instead)`, + ); + } + this.emitTrace({ type: 'mcpl:coalescing', ...record }); + }, save: (snapshot) => this.scheduleCoalescingSnapshot(snapshot), recordReceipt: (record) => { // Written now, not at the throttled flush: an acknowledged acceptance @@ -7749,7 +7764,7 @@ export class AgentFramework { throw new CoalesceError('eventId', 'eventId is required with coalesce'); } if (typeof message.timestamp !== 'string') throw new CoalesceError('timestamp', 'timestamp is required'); - validateCoalescedContent(message.content, undefined, { allowEmpty: message.coalesce.retract === true }); + validateCoalescedContent(message.content, { allowEmpty: message.coalesce.retract === true }); const c = message.coalesce; const result = await this.pushCoalescer.accept({ serverId, @@ -7776,7 +7791,7 @@ export class AgentFramework { validateCoalesceMember(params.coalesce, 'push'); if (typeof params.eventId !== 'string' || !params.eventId) throw new CoalesceError('eventId', 'eventId is required'); if (typeof params.timestamp !== 'string') throw new CoalesceError('timestamp', 'timestamp is required'); - validateCoalescedContent(params.payload?.content, undefined, { + validateCoalescedContent(params.payload?.content, { allowEmpty: params.coalesce.retract === true || isSilentHeartbeatMarker({ serverId, featureSet: params.featureSet, origin: params.origin, content: params.payload?.content, }), @@ -7865,7 +7880,7 @@ export class AgentFramework { this.persistConversationRouterState(); return [decision.agentName]; } catch (err) { - console.error(`[coalescing] could not spawn a conversation agent for ${occ.scope.id}:`, err); + console.error(`[coalescing] could not spawn a conversation agent for ${logValue(occ.scope.id)}:`, err); return []; } } @@ -8073,7 +8088,7 @@ export class AgentFramework { // model would wake to `[Continue]` or an older message re-presented as // the newest, a wake with no visible cause. if (isVisiblyEmptyContent(event.content) && !isSilentHeartbeatMarker(event)) { - console.error(`[push-event-dropped] server=${event.serverId} eventId=${event.eventId} reason=empty-content`); + console.error(`[push-event-dropped] server=${event.serverId} eventId=${logValue(event.eventId ?? '')} reason=empty-content`); this.emitTrace({ type: 'mcpl:empty-content-dropped', lane: 'push', serverId: event.serverId, eventId: event.eventId }); return undefined; } @@ -8138,7 +8153,7 @@ export class AgentFramework { const id = this.addMessage('user', content, metadata, { placement, bypassDeferralFor: event.assemblingFor }); this.emitTrace({ type: 'message:added', messageId: id, source: 'mcpl:push-event' }); } else { - console.error(`[heartbeat] ${event.serverId}: accepted silent scheduled wake ${event.eventId}`); + console.error(`[heartbeat] ${event.serverId}: accepted silent scheduled wake ${logValue(event.eventId ?? '')}`); } if (event.triggerInference) { diff --git a/src/mcpl/channel-registry.ts b/src/mcpl/channel-registry.ts index 64894a18f..41da16ead 100644 --- a/src/mcpl/channel-registry.ts +++ b/src/mcpl/channel-registry.ts @@ -37,8 +37,10 @@ import type { McplServerRegistry } from './server-registry.js'; import type { FeatureSetManager } from './feature-set-manager.js'; import type { ToolDefinition, ToolResult, ProcessEvent } from '../types/index.js'; import { expandCoreTags } from './tags.js'; -import { EmptyContentError, validateCoalescedContent } from './push-coalescer.js'; +import { coalesceRejectionReason, EmptyContentError, validateCoalescedContent } from './push-coalescer.js'; import { isVisiblyEmptyContent } from './visible-content.js'; +import { logDetail, logValue } from './log-value.js'; +import { RefusalLines } from './refusal-lines.js'; import { CapabilityGrant } from './capability-grant.js'; // ============================================================================ @@ -249,7 +251,9 @@ interface McplChannelIncomingEvent { function convertBlock(block: McplContentBlock): ContentBlock { switch (block.type) { case 'text': - return { type: 'text', text: block.text }; + // Text that isn't a string is no text, as the request sanitizer and + // the visible-content check already read it. + return { type: 'text', text: typeof block.text === 'string' ? block.text : '' }; case 'image': if (isInlineContradiction(block)) { @@ -257,24 +261,24 @@ function convertBlock(block: McplContentBlock): ContentBlock { // closed, withhold the data (checked BEFORE the data branch). return { type: 'text', text: INLINE_WITHHELD_TEXT }; } - if (block.uri && block.disposition) { + if (isFilledString(block.uri) && block.disposition) { // RFC-005 uri-form media with a disposition claim: stub, do not // hand the URI to the provider or inline it. return { type: 'text', text: referenceStubOrNull(block, 'attachment on channel message') ?? '[reference]' }; } - if (block.data && block.mimeType) { + if (isFilledString(block.data) && isFilledString(block.mimeType)) { return { type: 'image', source: { type: 'base64', data: block.data, mediaType: block.mimeType }, } as ContentBlock; } - if (block.uri) { + if (isFilledString(block.uri)) { return { type: 'image', source: { type: 'url', url: block.uri }, } as ContentBlock; } - return { type: 'text', text: '[Image: no data]' }; + return { type: 'text', text: isFilledString(block.data) ? '[Image: no media type]' : '[Image: no data]' }; case 'audio': if (isInlineContradiction(block)) { @@ -282,31 +286,43 @@ function convertBlock(block: McplContentBlock): ContentBlock { // closed, withhold the data (checked BEFORE the data branch). return { type: 'text', text: INLINE_WITHHELD_TEXT }; } - if (block.uri && block.disposition) { + if (isFilledString(block.uri) && block.disposition) { // RFC-005 uri-form media with a disposition claim: stub, do not // hand the URI to the provider or inline it. return { type: 'text', text: referenceStubOrNull(block, 'attachment on channel message') ?? '[reference]' }; } - if (block.data && block.mimeType) { + if (isFilledString(block.data) && isFilledString(block.mimeType)) { return { type: 'audio', source: { type: 'base64', data: block.data, mediaType: block.mimeType }, } as ContentBlock; } - return { type: 'text', text: '[Audio: no data]' }; + return { type: 'text', text: isFilledString(block.data) ? '[Audio: no media type]' : '[Audio: no data]' }; case 'resource': // RFC-005: reference blocks become bounded stubs — never raw URIs // (a signed URL is a bearer credential that looks like a location). return { type: 'text', text: referenceStubOrNull(block, 'attachment on channel message') ?? '[reference]' }; - default: + default: { // Unknown wire block types previously fell off the exhaustive switch - // and propagated `undefined` into ContentBlock[]. Fail visibly. - return { type: 'text', text: `[unrecognized content block: ${(block as { type?: string }).type ?? 'untyped'}]` }; + // and propagated `undefined` into ContentBlock[]. Fail visibly. A type + // that isn't a string is no type, and is never converted to one: an + // object can throw when it is. + const type: unknown = (block as { type?: unknown }).type; + return { type: 'text', text: `[unrecognized content block: ${typeof type === 'string' ? type : 'untyped'}]` }; + } } } +/** A string with something in it: the only data, mimeType or uri a block's + * source is built from, and the only uri that makes it a reference. Anything + * else a sender puts there leaves the block without it, so conversion never + * throws and never copies a non-string. */ +function isFilledString(value: unknown): value is string { + return typeof value === 'string' && value !== ''; +} + // ============================================================================ // Channel Tool Definitions // ============================================================================ @@ -577,6 +593,10 @@ export class ChannelRegistry { /** Registered channels, keyed by `{serverId}:{channelId}`. */ private channels = new Map(); + /** Holds back repeats of the line for a message refused because its + * channel isn't registered (RefusalLines). */ + private unknownChannelLines = new RefusalLines(); + /** * Most-recently-known label per channelId, replayed from * `CHANNEL_LABEL_HISTORY_LOG_ID` (last sighting wins) and kept current by @@ -848,6 +868,45 @@ export class ChannelRegistry { }); } + /** + * A coalesced message the host refused. Until now the host said nothing, so + * a dropped message (agent-framework#266: every Discord message with a + * screenshot) left no trace where operators look. The sender gets the + * per-message result this lane gives: `coalesce_invalid` for a malformed + * item, or the thrown error's message for anything else. `answered` is the + * code that result stands for (-32602 for `coalesce_invalid`), and the + * reason follows it (coalesceRejectionReason): `coalesce-failed` when the + * host itself failed, `coalesce-invalid` when the sender's item was + * refused, with the failing `field` and the error's message as `detail`. + * The line prints the ids the sender sent, whatever their type; the trace + * carries them when they are strings. + */ + private traceCoalesceRejection( + serverId: string, + message: { channelId?: unknown; messageId?: unknown } | null | undefined, + error: { field?: unknown; message: string }, + answered: number, + ): void { + const reason = coalesceRejectionReason(answered); + const field = typeof error.field === 'string' && error.field ? error.field : undefined; + const channelId = typeof message?.channelId === 'string' ? message.channelId : ''; + const messageId = typeof message?.messageId === 'string' && message.messageId ? message.messageId : undefined; + console.error( + `[channel-incoming-rejected] server=${serverId} channel=${logValue(message?.channelId ?? '')} ` + + `messageId=${logValue(message?.messageId ?? '')} ` + + `reason=${reason}${field ? ` field=${logValue(field)}` : ''}: ${logDetail(error.message)}`, + ); + this.emitTraceFn({ + type: 'mcpl:channel-incoming-rejected', + serverId, + channelId, + ...(messageId ? { messageId } : {}), + reason, + ...(field ? { field } : {}), + detail: error.message, + }); + } + /** * Handle `channels/incoming` from a server. * @@ -864,10 +923,20 @@ export class ChannelRegistry { for (const message of params.messages) { if (!message || typeof message.channelId !== 'string' || !message.channelId || typeof message.messageId !== 'string' || !message.messageId) { + // The same gate as admission below: with no coalescer wired, a + // message carrying `coalesce` is handled uncoalesced, and refused as + // any uncoalesced message without an identity is. + const coalescedItem = message?.coalesce !== undefined && !!this.handleCoalescedIncoming; + if (coalescedItem) { + this.traceCoalesceRejection(serverId, message, { + field: typeof message.channelId !== 'string' || !message.channelId ? 'channelId' : 'messageId', + message: 'a coalesced message needs a channelId and a messageId', + }, -32602); + } results.push({ messageId: typeof message?.messageId === 'string' ? message.messageId : '', accepted: false, - reason: message?.coalesce !== undefined ? 'coalesce_invalid' : 'invalid channel/message identity', + reason: coalescedItem ? 'coalesce_invalid' : 'invalid channel/message identity', }); continue; } @@ -899,11 +968,24 @@ export class ChannelRegistry { // routable entry rather than an open self-attested one. const incomingKey = `${serverId}:${message.channelId}`; if (!this.channels.has(incomingKey)) { + // Loud, coalesced or not, like every other refusal of a message, but + // at most once a minute per channel (RefusalLines): a server that + // never registered a busy channel would otherwise print a line for + // every message in it. Every refusal is traced. + const held = this.unknownChannelLines.admit(serverId, message.channelId); + if (held !== null) { + console.error( + `[channel-incoming-rejected] server=${serverId} channel=${logValue(message.channelId)} ` + + `messageId=${logValue(message.messageId)} reason=unknown-channel ` + + `(not registered, §14.5${held ? `; ${held} more since the last line` : ''})`, + ); + } this.emitTraceFn({ type: 'mcpl:channel-incoming-rejected', serverId, channelId: message.channelId, - reason: 'unknown channel — not registered (§14.5)', + messageId: message.messageId, + reason: 'unknown-channel', }); results.push({ messageId: message.messageId, @@ -921,7 +1003,7 @@ export class ChannelRegistry { // shows the model nothing would wake it with no visible cause. const emptyAllowed = coalesced && (message.coalesce as { retract?: unknown } | null)?.retract === true; const rejectEmpty = () => { - console.error(`[channel-incoming-rejected] server=${serverId} channel=${message.channelId} messageId=${message.messageId} reason=empty-content`); + console.error(`[channel-incoming-rejected] server=${serverId} channel=${logValue(message.channelId)} messageId=${logValue(message.messageId)} reason=empty-content`); this.emitTraceFn({ type: 'mcpl:channel-incoming-rejected', serverId, @@ -935,10 +1017,14 @@ export class ChannelRegistry { // RFC-006 §13: malformed content on a coalesced item is that item's // failure, not the batch's — check the shape before converting. try { - validateCoalescedContent(message.content, undefined, { allowEmpty: emptyAllowed }); + validateCoalescedContent(message.content, { allowEmpty: emptyAllowed }); } catch (error) { if (error instanceof EmptyContentError) rejectEmpty(); - else results.push({ messageId: message.messageId, accepted: false, reason: 'coalesce_invalid' }); + else { + // Answered coalesce_invalid whatever the error's code: -32602. + this.traceCoalesceRejection(serverId, message, error as Error & { field?: string }, -32602); + results.push({ messageId: message.messageId, accepted: false, reason: 'coalesce_invalid' }); + } continue; } } @@ -970,8 +1056,11 @@ export class ChannelRegistry { // Determine whether to trigger inference let triggerInference = true; if (this.shouldTriggerInference) { - const textContent = message.content - .filter((b): b is { type: 'text'; text: string } => b.type === 'text') + // The text the agent's context gets, as the push lane's filter reads + // it: the converted text blocks, a placeholder or reference stub + // among them, and a text block's non-string text as empty text. + const textContent = convertedContent + .filter((b): b is ContentBlock & { type: 'text' } => b.type === 'text') .map((b) => b.text) .join('\n'); triggerInference = this.shouldTriggerInference( @@ -1014,7 +1103,10 @@ export class ChannelRegistry { if (result.accepted) markAccepted(); results.push(result); } catch (error) { - const err = error as Error & { code?: number }; + const err = error as Error & { code?: number; field?: string }; + // -32602 is answered coalesce_invalid; anything else as its message, + // a plain Error standing for an internal error (-32603). + this.traceCoalesceRejection(serverId, message, err, typeof err.code === 'number' ? err.code : -32603); results.push({ messageId: message.messageId, accepted: false, @@ -3018,7 +3110,7 @@ export class ChannelRegistry { try { await this.openChannelNow(entry, 'opened-by-delivery'); console.error( - `[routeSpeech] ${conversationId}: locus ${channelId} was closed — opened by delivery (speech implies engagement)`, + `[routeSpeech] ${conversationId}: locus ${logValue(channelId)} was closed — opened by delivery (speech implies engagement)`, ); this.emitTraceFn({ type: 'mcpl:channel-opened-by-send', @@ -3071,7 +3163,7 @@ export class ChannelRegistry { return fail(channelId, `server "${entry.serverId}" reported delivered:false for "${channelId}"`); } - console.error(`[routeSpeech] ${conversationId}: routed ${text.length} chars -> ${channelId} (server=${entry.serverId}, delivered=${delivered})`); + console.error(`[routeSpeech] ${conversationId}: routed ${text.length} chars -> ${logValue(channelId)} (server=${entry.serverId}, delivered=${delivered})`); this.emitTraceFn({ type: 'mcpl:speech-routed', conversationId, diff --git a/src/mcpl/feature-set-manager.ts b/src/mcpl/feature-set-manager.ts index 6405c1f25..b4b92a88b 100644 --- a/src/mcpl/feature-set-manager.ts +++ b/src/mcpl/feature-set-manager.ts @@ -19,6 +19,7 @@ import { UNKNOWN_FEATURE_SET, } from './errors.js'; import { isKnownCapabilityPath } from './capability-grant.js'; +import { logValue } from './log-value.js'; // ============================================================================ // Error Class @@ -222,7 +223,7 @@ export class FeatureSetManager { ): void => { const selectedByConfig = state.enabled.delete(name); const note = explicitSelection && selectedByConfig ? ' — overrides enabledFeatureSets' : ''; - console.error(`[mcpl] ${serverId}/${name} disabled: ${detail}${note}`); + console.error(`[mcpl] ${serverId}/${logValue(name)} disabled: ${detail}${note}`); this.emitTrace?.({ type: 'mcpl:feature-set-disabled', serverId, @@ -240,14 +241,14 @@ export class FeatureSetManager { } const unknown = uses.filter((u) => typeof u !== 'string' || !isKnownCapabilityPath(u)); if (unknown.length > 0) { - disable(name, 'invalid_uses', `invalid_uses (§6.4 — unrecognized: ${unknown.join(', ')})`, { + disable(name, 'invalid_uses', `invalid_uses (§6.4 — unrecognized: ${unknown.map(logValue).join(', ')})`, { unrecognized: unknown.map((u) => (typeof u === 'string' ? u : JSON.stringify(u))), }); continue; } const missing = (uses as string[]).filter((u) => !grant.has(u)); if (missing.length > 0) { - disable(name, 'missing_capabilities', `missing capabilities ${missing.join(', ')} (§6.4)`, { missing }); + disable(name, 'missing_capabilities', `missing capabilities ${missing.map(logValue).join(', ')} (§6.4)`, { missing }); } } } diff --git a/src/mcpl/log-value.ts b/src/mcpl/log-value.ts new file mode 100644 index 000000000..905d58372 --- /dev/null +++ b/src/mcpl/log-value.ts @@ -0,0 +1,116 @@ +/** + * A value a connected server chose, as one field of a host log line. + * + * The rejection lines (`[channel-incoming-rejected]`, `[push-event-rejected]`) + * and the other host lines that name a server's own identifiers are read a + * line at a time, by eye and with grep. Printed raw, an identifier carrying a + * line break prints a second line that reads as another host record, about + * another server; one carrying a space can pose as another field of the same + * line; and one carrying `=` can hold a lookalike field (`reason=…`) that a + * search for that field finds before the real one. + * + * A plain token (visible characters only: no space, quote, backslash or `=`) + * prints as it is, so ordinary ids read and grep as they always have. + * Anything else prints as a JSON string with every `=` and every invisible + * character escaped: controls, format and bidi characters, line and paragraph + * separators, every space (the plain one included), default-ignorable + * characters (Hangul fillers, the combining grapheme joiner, variation + * selectors) and the blank Braille pattern. So it stays one field on one line, + * a reader that splits on whitespace keeps it whole, no field holds a raw + * `=` (so every `=` before a line's free-text tail, `logDetail`, belongs to + * a real field), and `JSON.parse` of a quoted value that isn't cut gives + * back exactly what was sent. Escaping rather than stripping keeps two + * identifiers that differ in invisible characters within the units a line + * prints from printing alike; canonically equivalent or lookalike + * identifiers still can. + * + * A value longer than 256 UTF-16 units is cut, so one value can't make a line + * long: it prints quoted, as its first 256 units (255 when the 256th is a + * high surrogate, so a pair is never split), each at most six characters once + * escaped, followed by `…(N)`, N being its full length. `JSON.parse` of the + * quoted part gives back those first units. A cut value always opens with a + * quote, and its marker follows the closing quote. A plain token never holds + * a quote, and a quoted value that isn't cut ends at its closing quote, so + * only a value that was cut prints as one. + * + * A value that isn't a string prints as its JSON text, quoted as any text is + * that isn't a plain token: the number 5 prints as `5`, and `{"toString":1}` + * as `"{\"toString\":1}"`. So the number 5 and the string "5" print alike, as + * they name the same message. A number JSON writes as `null` (NaN, Infinity) + * prints as `String()` of it. Converting a value never throws: one JSON can't + * write prints as `String()` of it, or else as its object tag, and one none + * of those can read (a revoked Proxy) as `[unprintable]`. + */ +export function logValue(value: unknown): string { + return printed(textOf(value), FIELD); +} + +/** + * The host's own message, as the free text that ends a log line after its + * fields: `reason=coalesce-invalid field=payload.content: "content must be an + * array"`. It prints as `logValue` prints a field, cut the same way, except + * that a plain space and `=` stay raw, for reading. That is safe because the + * text is the host's (an error the host raised), not an id a sender chose, + * and every real field of the line comes before it. + */ +export function logDetail(value: unknown): string { + return printed(textOf(value), DETAIL); +} + +/** How a form prints: the text that stands as it is, and what it escapes. */ +interface Form { + plain: RegExp; + escaped: RegExp; +} + +const FIELD: Form = { + plain: /^[^"\\=\p{C}\p{Z}\p{Default_Ignorable_Code_Point}\u2800]+$/u, + escaped: /[=\p{C}\p{Z}\p{Default_Ignorable_Code_Point}\u2800]/gu, +}; + +const DETAIL: Form = { + plain: /^[^"\\\p{C}\p{Z}\p{Default_Ignorable_Code_Point}\u2800]+$/u, + escaped: /(?! )[\p{C}\p{Z}\p{Default_Ignorable_Code_Point}\u2800]/gu, +}; + +/** The most of a value's text a line prints, in UTF-16 units. */ +const MAX_PRINTED = 256; + +function printed(text: string, form: Form): string { + if (text.length <= MAX_PRINTED) return form.plain.test(text) ? text : quoted(text, form); + let end = MAX_PRINTED; + const last = text.charCodeAt(end - 1); + if (last >= 0xd800 && last <= 0xdbff) end--; + return `${quoted(text.slice(0, end), form)}…(${text.length})`; +} + +function quoted(text: string, form: Form): string { + // JSON escapes C0 controls, quotes and backslashes and leaves the rest of + // the escaped set raw: escape those here, per UTF-16 unit, as JSON does. + return JSON.stringify(text).replace(form.escaped, escapeUnits); +} + +function textOf(value: unknown): string { + if (typeof value === 'string') return value; + // JSON writes a non-finite number as null, which reads as a missing value. + if (typeof value === 'number' && !Number.isFinite(value)) return String(value); + const readers = [ + () => JSON.stringify(value) ?? String(value), + () => String(value), + () => Object.prototype.toString.call(value), + ]; + for (const read of readers) { + try { + return read(); + } catch { + // the next reader + } + } + return '[unprintable]'; +} + +function escapeUnits(chars: string): string { + let out = ''; + for (let i = 0; i < chars.length; i++) out += `\\u${chars.charCodeAt(i).toString(16).padStart(4, '0')}`; + return out; +} diff --git a/src/mcpl/push-coalescer.ts b/src/mcpl/push-coalescer.ts index 871d7a3c9..7615256b1 100644 --- a/src/mcpl/push-coalescer.ts +++ b/src/mcpl/push-coalescer.ts @@ -18,6 +18,7 @@ * bookkeeping and is unit-tested without a framework. */ import type { McplContentBlock, PushEventResult } from './types.js'; +import { classifyBlock, isInlineContradiction } from './references.js'; import { isVisiblyEmptyContent } from './visible-content.js'; export const PUSH_COALESCING_SUPPORT = { @@ -37,6 +38,18 @@ export class CoalesceError extends Error { } } +/** + * How the host names a coalesce rejection, from the code the wire answered + * with. `coalesce-failed` is the host's own failure: -32000 (coalescing + * unavailable, the host stopping, or an acceptance it couldn't make durable) + * and -32603 (an internal error). `coalesce-invalid` is every other answer, + * the sender's: -32602 for a malformed item, -32017 or -32023 for a channel + * that isn't permitted or isn't registered. + */ +export function coalesceRejectionReason(answered: number): 'coalesce-failed' | 'coalesce-invalid' { + return answered === -32000 || answered === -32603 ? 'coalesce-failed' : 'coalesce-invalid'; +} + /** Content with nothing model-visible (see visible-content.ts): -32602. */ export class EmptyContentError extends CoalesceError { readonly reason = 'empty-content'; @@ -212,7 +225,6 @@ export interface CoalescerOptions { recoveryBackoffMs?: number; maxSubjects?: number; maxNotices?: number; - maxContentBytes?: number; maxDataBytes?: number; } @@ -232,6 +244,32 @@ function mergeIdentity(prior: CoalescedOccurrence['identity'], next: CoalescedOc /** * Validate wire content before it is stored, rendered or converted. * + * Its shape and its visible emptiness, nothing else. An incoming coalesced + * occurrence reaches context through the converters an uncoalesced message + * goes through: a plain occurrence the moment it is admitted (the coalescer + * only remembers where it landed), a deferred one when its render settles or + * falls back to it. Its content must be an array of objects. A block the + * converters can't render (a video, an unknown type, an image with neither + * uri nor data) becomes a placeholder, as it does uncoalesced, and so does a + * malformed one, since the converters take any object without throwing: a + * type, text, data, mimeType or uri that isn't a string counts as absent, a + * text block's as no text. The uncoalesced lane doesn't check the array: + * there a member that isn't an object becomes the untyped placeholder, and a + * null member or content that isn't an array throws in conversion + * (agent-framework#297 brings that lane to this rule). + * Nor does the uncoalesced path set a byte budget on content: + * an inline image is admitted here as it is there (agent-framework#266: a + * 1 MiB serialized-content budget here dropped every coalesced message + * carrying a screenshot). A deferred occurrence's content is held, until then, + * in the coalescer's state and its persisted snapshot and receipts. + * + * A render result, which the host delivers in the occurrence's place, gets + * these checks, as RFC-006 §5.2 gives it every check a pushed payload gets, + * and one more (`checkBlockShapes`): each block must be one the converters + * show as itself or as a reference stub, not as a placeholder. A malformed + * render falls back to the occurrence's own content; a pushed payload has + * nothing to fall back to, and gets its placeholders. + * * Visibly-empty content is refused unless `allowEmpty`: an admitted * occurrence with nothing to show would wake the model with no visible cause. * Empty is legitimate only where the RFC gives it a meaning — a retraction @@ -240,22 +278,38 @@ function mergeIdentity(prior: CoalescedOccurrence['identity'], next: CoalescedOc */ export function validateCoalescedContent( content: unknown, - maxBytes = 1024 * 1024, - options: { allowEmpty?: boolean } = {}, + options: { allowEmpty?: boolean; checkBlockShapes?: boolean } = {}, ): asserts content is McplContentBlock[] { if (!Array.isArray(content)) throw new CoalesceError('payload.content', 'content must be an array'); for (const b of content as Array>) { if (!b || typeof b !== 'object' || Array.isArray(b)) throw new CoalesceError('payload.content', 'invalid content block'); - if (b.type === 'text' && typeof b.text === 'string') continue; - if (b.type === 'resource' && typeof b.uri === 'string') continue; - if ((b.type === 'image' || b.type === 'audio') - && (typeof b.uri === 'string' || (typeof b.data === 'string' && typeof b.mimeType === 'string'))) continue; - throw new CoalesceError('payload.content', 'invalid content block'); + if (options.checkBlockShapes && !showsAsItself(b)) throw new CoalesceError('payload.content', 'invalid content block'); } - if (Buffer.byteLength(JSON.stringify(content)) > maxBytes) throw new CoalesceError('payload.content', 'content exceeds host byte limit'); if (!options.allowEmpty && isVisiblyEmptyContent(content)) throw new EmptyContentError(); } +/** + * Whether the converters (`convertBlock` in push-handler.ts and + * channel-registry.ts) show a block as itself, its text or its image or + * audio source, or as a reference stub, and not as a placeholder: an + * unrecognized block, a no-data or no-media-type one, or withheld inline + * data. A text block whose text isn't a string, which they show as no text, + * is refused too. This follows their branches in their order. + */ +function showsAsItself(b: Record): boolean { + if (b.type === 'text') return typeof b.text === 'string'; + if (b.type === 'resource') return classifyBlock(b).kind === 'reference'; + if (b.type !== 'image' && b.type !== 'audio') return false; + if (isInlineContradiction(b)) return false; + if (isFilledString(b.uri) && b.disposition) return classifyBlock(b).kind === 'reference'; + if (isFilledString(b.data) && isFilledString(b.mimeType)) return true; + return b.type === 'image' && isFilledString(b.uri); +} + +function isFilledString(value: unknown): value is string { + return typeof value === 'string' && value !== ''; +} + /** Validate the `coalesce` member of either lane (§13). */ export function validateCoalesceMember( c: unknown, @@ -700,14 +754,24 @@ export class PushCoalescer { try { const result = await this.host.render(occurrence, params); if (rendering.cancelled) { this.host.audit({ kind: 'late-render', subject, eventId: occurrence.eventId, discarded: true }); } - // §5.2: an empty result is legitimate ("nothing happened"). - else validateCoalescedContent(result?.content, this.options.maxContentBytes, { allowEmpty: true }); + // §5.2: an empty result is legitimate ("nothing happened"); each + // block must be well formed. + else validateCoalescedContent(result?.content, { allowEmpty: true, checkBlockShapes: true }); if (rendering.cancelled) throw new CancelledRender(); content = result.content; timestamp = typeof result.timestamp === 'string' ? result.timestamp : new Date().toISOString(); source = 'render'; } catch (error) { - if (!(error instanceof CancelledRender)) this.host.audit({ kind: 'render-failed', subject, eventId: occurrence.eventId, error: String(error) }); + if (!(error instanceof CancelledRender)) { + // The occurrence's own content is delivered instead; the host names + // the failure where operators look (a console line, not only this + // audit record). + this.host.audit({ + kind: 'render-failed', subject, serverId: occurrence.serverId, eventId: occurrence.eventId, + ...(error instanceof CoalesceError ? { field: error.field } : {}), + error: String(error), + }); + } } finally { const left = (this.rendersInFlight.get(occurrence.serverId) ?? 1) - 1; if (left > 0) this.rendersInFlight.set(occurrence.serverId, left); else this.rendersInFlight.delete(occurrence.serverId); diff --git a/src/mcpl/push-handler.ts b/src/mcpl/push-handler.ts index 294e18959..22dc9fb38 100644 --- a/src/mcpl/push-handler.ts +++ b/src/mcpl/push-handler.ts @@ -18,8 +18,10 @@ import type { import type { FeatureSetManager } from './feature-set-manager.js'; import { McplFeatureSetError } from './feature-set-manager.js'; import { expandCoreTags } from './tags.js'; -import { EmptyContentError, validateCoalescedContent } from './push-coalescer.js'; +import { coalesceRejectionReason, EmptyContentError, validateCoalescedContent } from './push-coalescer.js'; import { isSilentHeartbeatMarker, isVisiblyEmptyContent } from './visible-content.js'; +import { logDetail, logValue } from './log-value.js'; +import { RefusalLines } from './refusal-lines.js'; // ============================================================================ // McplPushEvent (the ProcessEvent shape pushed to the queue) @@ -55,13 +57,17 @@ export interface McplPushEvent { // ============================================================================ /** - * Convert a single MCPL wire-format content block to a membrane ContentBlock. - * Same logic as hook-orchestrator.ts. + * Convert a single MCPL wire-format content block to a membrane ContentBlock, + * as the channel lane's convertBlock (channel-registry.ts) does, apart from + * the provenance its reference stubs name. Hook context injections convert + * through hook-orchestrator.ts's own. */ export function convertBlock(block: McplContentBlock): ContentBlock { switch (block.type) { case 'text': - return { type: 'text', text: block.text }; + // Text that isn't a string is no text, as the request sanitizer and + // the visible-content check already read it. + return { type: 'text', text: typeof block.text === 'string' ? block.text : '' }; case 'image': if (isInlineContradiction(block)) { @@ -69,24 +75,24 @@ export function convertBlock(block: McplContentBlock): ContentBlock { // closed, withhold the data (checked BEFORE the data branch). return { type: 'text', text: INLINE_WITHHELD_TEXT }; } - if (block.uri && block.disposition) { + if (isFilledString(block.uri) && block.disposition) { // RFC-005 uri-form media with a disposition claim: stub, do not // hand the URI to the provider or inline it. return { type: 'text', text: referenceStubOrNull(block, 'attachment on push event') ?? '[reference]' }; } - if (block.data && block.mimeType) { + if (isFilledString(block.data) && isFilledString(block.mimeType)) { return { type: 'image', source: { type: 'base64', data: block.data, mediaType: block.mimeType }, } as ContentBlock; } - if (block.uri) { + if (isFilledString(block.uri)) { return { type: 'image', source: { type: 'url', url: block.uri }, } as ContentBlock; } - return { type: 'text', text: '[Image: no data]' }; + return { type: 'text', text: isFilledString(block.data) ? '[Image: no media type]' : '[Image: no data]' }; case 'audio': if (isInlineContradiction(block)) { @@ -94,31 +100,43 @@ export function convertBlock(block: McplContentBlock): ContentBlock { // closed, withhold the data (checked BEFORE the data branch). return { type: 'text', text: INLINE_WITHHELD_TEXT }; } - if (block.uri && block.disposition) { + if (isFilledString(block.uri) && block.disposition) { // RFC-005 uri-form media with a disposition claim: stub, do not // hand the URI to the provider or inline it. return { type: 'text', text: referenceStubOrNull(block, 'attachment on push event') ?? '[reference]' }; } - if (block.data && block.mimeType) { + if (isFilledString(block.data) && isFilledString(block.mimeType)) { return { type: 'audio', source: { type: 'base64', data: block.data, mediaType: block.mimeType }, } as ContentBlock; } - return { type: 'text', text: '[Audio: no data]' }; + return { type: 'text', text: isFilledString(block.data) ? '[Audio: no media type]' : '[Audio: no data]' }; case 'resource': // RFC-005: reference blocks become bounded stubs — never raw URIs // (a signed URL is a bearer credential that looks like a location). return { type: 'text', text: referenceStubOrNull(block, 'attachment on push event') ?? '[reference]' }; - default: + default: { // Unknown wire block types previously fell off the exhaustive switch - // and propagated `undefined` into ContentBlock[]. Fail visibly. - return { type: 'text', text: `[unrecognized content block: ${(block as { type?: string }).type ?? 'untyped'}]` }; + // and propagated `undefined` into ContentBlock[]. Fail visibly. A type + // that isn't a string is no type, and is never converted to one: an + // object can throw when it is. + const type: unknown = (block as { type?: unknown }).type; + return { type: 'text', text: `[unrecognized content block: ${typeof type === 'string' ? type : 'untyped'}]` }; + } } } +/** A string with something in it: the only data, mimeType or uri a block's + * source is built from, and the only uri that makes it a reference. Anything + * else a sender puts there leaves the block without it, so conversion never + * throws and never copies a non-string. */ +function isFilledString(value: unknown): value is string { + return typeof value === 'string' && value !== ''; +} + // ============================================================================ // LRU Dedup Set // ============================================================================ @@ -171,6 +189,9 @@ export class PushHandler { private emitTraceFn: (event: { type: string; [key: string]: unknown }) => void; private shouldTriggerInference?: (content: string, metadata: Record) => boolean; private dedup = new DedupSet(1000); + /** Holds back repeats of the line for a channel-scoped push refused because + * its channel isn't declared (-32023) or may not be used (-32017). */ + private channelRefusalLines = new RefusalLines(); constructor( featureSetManager: FeatureSetManager, @@ -221,7 +242,7 @@ export class PushHandler { : 'Feature set validation failed'; // Loud rejection — a rejected push event is an agent that silently // never hears the message. (2026-07-09 diagnosability pass.) - console.error(`[push-event-rejected] server=${serverId} eventId=${params.eventId} reason=${reason}`); + console.error(`[push-event-rejected] server=${serverId} eventId=${logValue(params.eventId ?? '')} reason=${logValue(reason)}`); if (err instanceof McplFeatureSetError && responder?.respondError) { responder.respondError(err.code, reason, { featureSet: err.featureSet }); } else { @@ -240,11 +261,13 @@ export class PushHandler { if (coalesced) { // RFC-006 §13: malformed content is a -32602, checked before conversion. try { - validateCoalescedContent(params.payload?.content, undefined, { allowEmpty: emptyAllowed }); + validateCoalescedContent(params.payload?.content, { allowEmpty: emptyAllowed }); } catch (error) { const err = error as Error & { code?: number; field?: string }; + const code = err.code ?? -32602; if (err instanceof EmptyContentError) this.traceEmptyRejection(serverId, params); - if (responder?.respondError) responder.respondError(err.code ?? -32602, err.message, { field: err.field }); + else this.traceCoalesceRejection(serverId, params, err, code); + if (responder?.respondError) responder.respondError(code, err.message, { field: err.field }); else responder?.respond({ accepted: false, reason: err instanceof EmptyContentError ? err.reason : err.message }); return; } @@ -265,7 +288,7 @@ export class PushHandler { // coalescer's receipts instead (RFC-006 §3.1: a retry within the window // gets its original result, which this set could not return). if (!coalesced && this.dedup.checkAndAdd(params.eventId)) { - console.error(`[push-event-rejected] server=${serverId} eventId=${params.eventId} reason=duplicate`); + console.error(`[push-event-rejected] server=${serverId} eventId=${logValue(params.eventId ?? '')} reason=duplicate`); responder?.respond({ accepted: false, reason: 'duplicate' }); return; } @@ -314,8 +337,9 @@ export class PushHandler { responder?.respond(result); } catch (error) { const err = error as Error & { code?: number; field?: string }; - console.error(`[push-event-rejected] server=${serverId} eventId=${params.eventId} reason=${err.message}`); - if (responder?.respondError) responder.respondError(typeof err.code === 'number' ? err.code : -32603, err.message, { field: err.field }); + const code = typeof err.code === 'number' ? err.code : -32603; + this.traceCoalesceRejection(serverId, params, err, code); + if (responder?.respondError) responder.respondError(code, err.message, { field: err.field }); else responder?.respond({ accepted: false, reason: err.message }); } return; @@ -334,13 +358,61 @@ export class PushHandler { responder?.respond({ accepted: true, inferenceId }); } - /** Loud, like every other push rejection: the producer's wake went nowhere. */ + /** + * A coalesced occurrence the host refused, as loud as every other push + * rejection: its producer is told on the wire, and until now the host said + * nothing, so a dropped message left no trace where operators look + * (agent-framework#266). The producer gets the wire answer this lane gives + * (`answered`): the thrown error's code and message, or -32602 for a + * malformed occurrence without one. The reason follows that answer + * (coalesceRejectionReason): `coalesce-failed` when the host itself failed, + * `coalesce-invalid` when the producer's occurrence was refused, with the + * failing `field` and the error's message as `detail`. A missing eventId + * prints as `""` and traces as `''`, as the channel lane's missing id does. + * A channel-scoped push refused because its channel isn't declared or may + * not be used names the channel on its line and its trace, and is refused + * for as long as that lasts, so its line prints at most once a minute per + * channel (RefusalLines); every refusal is traced. + */ + private traceCoalesceRejection( + serverId: string, + params: PushEventParams, + error: { field?: unknown; message: string }, + answered: number, + ): void { + const reason = coalesceRejectionReason(answered); + const field = typeof error.field === 'string' && error.field ? error.field : undefined; + const scoped = params.coalesce?.channelId; + const channelId = (answered === -32023 || answered === -32017) && typeof scoped === 'string' ? scoped : undefined; + const held = channelId === undefined ? 0 : this.channelRefusalLines.admit(serverId, channelId); + if (held !== null) { + console.error( + `[push-event-rejected] server=${serverId} featureSet=${logValue(params.featureSet ?? '')} eventId=${logValue(params.eventId ?? '')} ` + + (channelId === undefined ? '' : `channel=${logValue(channelId)} `) + + `reason=${reason}${field ? ` field=${logValue(field)}` : ''}: ${logDetail(error.message)}` + + (held ? ` (${held} more since the last line)` : ''), + ); + } + this.emitTraceFn({ + type: 'mcpl:push-event-rejected', + serverId, + eventId: typeof params.eventId === 'string' ? params.eventId : '', + featureSet: params.featureSet, + reason, + ...(field ? { field } : {}), + ...(channelId === undefined ? {} : { channelId }), + detail: error.message, + }); + } + + /** Loud, like every other push rejection: the producer's wake went nowhere. + * A missing eventId prints as `""` and traces as `''`, as on every push line. */ private traceEmptyRejection(serverId: string, params: PushEventParams): void { - console.error(`[push-event-rejected] server=${serverId} eventId=${params.eventId} reason=empty-content`); + console.error(`[push-event-rejected] server=${serverId} eventId=${logValue(params.eventId ?? '')} reason=empty-content`); this.emitTraceFn({ type: 'mcpl:push-event-rejected', serverId, - eventId: params.eventId, + eventId: typeof params.eventId === 'string' ? params.eventId : '', featureSet: params.featureSet, reason: 'empty-content', }); diff --git a/src/mcpl/refusal-lines.ts b/src/mcpl/refusal-lines.ts new file mode 100644 index 000000000..ee9ac48ed --- /dev/null +++ b/src/mcpl/refusal-lines.ts @@ -0,0 +1,59 @@ +import { logValue } from './log-value.js'; + +/** + * At most one host line a minute for a refusal a server keeps repeating for + * as long as a standing condition lasts: messages for a channel it never + * registered, or channel-scoped pushes to a channel it hasn't declared or may + * not use. A server that never registered a busy channel would otherwise + * print a line for every message in it. Only the line is held back: every + * refusal is still answered and traced. Each lane keeps its own records, as + * its lines are its own. + * + * Per server and channel, the first refusal prints. After that a refusal + * prints only once a minute has passed since that channel's last line, and + * its line names how many were held back since. The minute is timed with a + * monotonic clock, so a step of the wall clock can't silence a channel. A + * refusal within a minute of the channel's last line is counted into its + * next line, whatever happens to the channel in between (it may be + * registered, unregistered or reconnected). + * + * A record is keyed by the channel as its line prints it (logValue), so two + * ids share one exactly when their lines name them alike, which only ids + * over 256 units can. The records cover the 1,000 most recently refused + * channels: a new channel evicts the least recently refused one, with its + * minute and any count it held, and that channel's next refusal prints as a + * first. + */ +export class RefusalLines { + /** By key, from the least recently refused channel to the most. */ + private readonly records = new Map(); + + constructor(private readonly now: () => number = () => performance.now()) {} + + /** + * Record one refusal for a server's channel. Returns null when its line is + * held back, or else how many of the channel's refusals were held back + * since its last line (0 for its first). + */ + admit(serverId: string, channelId: string): number | null { + // logValue never prints a NUL, so the key's last NUL keeps the two apart + // whatever a server id holds. + const key = `${serverId}\u0000${logValue(channelId)}`; + const now = this.now(); + const record = this.records.get(key); + if (record) this.records.delete(key); + else if (this.records.size >= MAX_CHANNELS) this.records.delete(this.records.keys().next().value!); + if (!record || now - record.at >= EVERY_MS) { + this.records.set(key, { at: now, since: 0 }); + return record?.since ?? 0; + } + record.since++; + this.records.set(key, record); + return null; + } +} + +/** A channel's line prints at most this often. */ +const EVERY_MS = 60_000; +/** The channels the records cover at once. */ +const MAX_CHANNELS = 1_000; diff --git a/src/mcpl/server-connection.ts b/src/mcpl/server-connection.ts index f29fea22d..4d906d753 100644 --- a/src/mcpl/server-connection.ts +++ b/src/mcpl/server-connection.ts @@ -15,6 +15,7 @@ import { openTransport, type McplTransport, type TransportCloseInfo } from './tr import { maskNegotiatedCapabilities } from './capability-mask.js'; import { CapabilityGrant, expandAdvertisementShorthand } from './capability-grant.js'; import { CAPABILITY_DISABLED } from './errors.js'; +import { logValue } from './log-value.js'; import type { McplServerConfig, @@ -375,7 +376,7 @@ export class McplServerConnection extends EventEmitter { if (responder?.respondError) { responder.respondError(CAPABILITY_DISABLED, `${name} rejected: capability "${requiredCap}" ${phase}`, { capability: requiredCap }); } else { - console.error(`[mcpl] ${this.id}: discarded ${name} — "${requiredCap}" ${phase}`); + console.error(`[mcpl] ${this.id}: discarded ${logValue(name)} — "${requiredCap}" ${phase}`); } return true; } @@ -582,7 +583,7 @@ export class McplServerConnection extends EventEmitter { // had never been advertised (hooks, streaming, queries all read this). const { capabilities: scoped, dropped } = maskNegotiatedCapabilities(capabilities, config); if (dropped.length > 0) { - console.error(`MCPL server "${config.id}" capabilities masked by host config: ${dropped.join(', ')}`); + console.error(`MCPL server "${config.id}" capabilities masked by host config: ${dropped.map(logValue).join(', ')}`); } return { transport, capabilities: scoped, droppedCapabilities: new Set(dropped), mcpToolsAdvertised }; diff --git a/src/mcpl/tool-classes.ts b/src/mcpl/tool-classes.ts index 82c07a3b1..759a08986 100644 --- a/src/mcpl/tool-classes.ts +++ b/src/mcpl/tool-classes.ts @@ -21,6 +21,7 @@ */ import { globMatch } from './tool-glob.js'; +import { logValue } from './log-value.js'; export const TOOL_CLASSES = [ 'comms', @@ -116,7 +117,7 @@ export function parseDeclaredClasses(meta: unknown, toolName = '(unnamed)'): Too const raw = (meta as Record)[TOOL_CLASS_META_KEY]; if (raw === undefined) return undefined; if (!Array.isArray(raw)) { - console.error(`[mcpl] ${toolName}: _meta["${TOOL_CLASS_META_KEY}"] is not an array — treated as unclassed`); + console.error(`[mcpl] ${logValue(toolName)}: _meta["${TOOL_CLASS_META_KEY}"] is not an array — treated as unclassed`); return undefined; } const out: ToolClass[] = []; @@ -124,7 +125,7 @@ export function parseDeclaredClasses(meta: unknown, toolName = '(unnamed)'): Too if (isToolClass(value)) { if (!out.includes(value)) out.push(value); } else { - console.error(`[mcpl] ${toolName}: unknown tool class ${JSON.stringify(value)} ignored (RFC-008 §3)`); + console.error(`[mcpl] ${logValue(toolName)}: unknown tool class ${logValue(value)} ignored (RFC-008 §3)`); } } return out.length > 0 ? out : undefined; diff --git a/src/types/trace.ts b/src/types/trace.ts index de8f41ea8..341c813f8 100644 --- a/src/types/trace.ts +++ b/src/types/trace.ts @@ -217,22 +217,47 @@ export type TraceEvent = messageId: string; source: string; }) - /** A push/event refused at the MCPL boundary (today: visibly-empty content). */ + /** A push/event refused at the MCPL boundary: visibly-empty content + * (`empty-content`, answered -32602, with no `field` or `detail`), or a + * coalesced occurrence the host refused. A refused occurrence's reason + * follows the code the producer was answered with: `coalesce-invalid` when + * the occurrence was the producer's to fix (-32602 malformed; -32017 or + * -32023 for a channel not permitted or not registered), `coalesce-failed` + * when the host itself failed (-32000, -32603). Its trace carries the + * error's message in `detail`, and the failing `field` when the error + * names one, and `channelId` when the push is refused for its channel + * (-32017, -32023), so each refusal names its channel even while repeats + * of its line are held back. An `eventId` that is missing or isn't a + * string is traced as `''`. A push refused for its feature set, or as a + * duplicate, gets a `[push-event-rejected]` line and no trace. */ | (TraceEventBase & { type: 'mcpl:push-event-rejected'; serverId: string; eventId: string; featureSet: string; reason: string; - }) - /** A channels/incoming message refused at the MCPL boundary: unregistered - * channel (§14.5), or visibly-empty content (then `messageId` is set). */ + field?: string; + channelId?: string; + detail?: string; + }) + /** A channels/incoming message refused at the MCPL boundary: an + * unregistered channel (`unknown-channel`, §14.5), visibly-empty content + * (`empty-content`), or a coalesced item the host refused + * (`coalesce-invalid` / `coalesce-failed`, with `detail`, and `field` when + * the error names one, as for a push). A coalesced item refused with + * -32602 (malformed) is answered `coalesce_invalid`, and one refused + * otherwise (-32000, or an internal error) with the error's own message. + * `messageId` is set whenever the message carries one. An uncoalesced + * message without a channelId or messageId is answered `invalid + * channel/message identity`, with no line and no trace. */ | (TraceEventBase & { type: 'mcpl:channel-incoming-rejected'; serverId: string; channelId: string; messageId?: string; reason: string; + field?: string; + detail?: string; }) /** MCPL content with nothing model-visible reached the store/wake site * (module-emitted or coalescer-delivered) and was dropped: no row, no wake. */ diff --git a/test/helpers/coalescing-fixture.ts b/test/helpers/coalescing-fixture.ts index 2a2405683..a69d2e1f8 100644 --- a/test/helpers/coalescing-fixture.ts +++ b/test/helpers/coalescing-fixture.ts @@ -17,7 +17,7 @@ import { MockMembrane, MockYieldingStream, createMockResponse } from './mock-mem export const TS = '2026-09-30T00:00:00Z'; export const ok = () => createMockResponse([{ type: 'text', text: 'ok' }]); -export async function fixture(options: { server?: Record; framework?: Partial; agents?: unknown[]; dir?: string; port?: number } = {}) { +export async function fixture(options: { server?: Record; framework?: Partial; agents?: unknown[]; dir?: string; port?: number; featureSets?: Record; mcpl?: Record } = {}) { const wss = new WebSocketServer({ port: options.port ?? 0, host: '127.0.0.1' }); await once(wss, 'listening'); let online = true; @@ -40,14 +40,21 @@ export async function fixture(options: { server?: Record; frame reply({ protocolVersion: '2024-11-05', capabilities: { tools: {}, experimental: { mcpl: { version: '0.5', pushEvents: true, inferenceRequest: true, channels: { incoming: true, register: true, lifecycle: true, publish: true }, - featureSets: { doc: { description: 'doc', uses: ['pushEvents'] } }, + featureSets: options.featureSets ?? { doc: { description: 'doc', uses: ['pushEvents'] } }, + ...options.mcpl, } } }, serverInfo: { name: 'editor', version: '1' } }); } else if (m.method === 'featureSets/update') reply({ accepted: true }); else if (m.method === 'tools/list') reply({ tools: [] }); else if (m.method === 'channels/publish') { published.push(m.params); if (m.id !== undefined) reply({ delivered: true }); } else if (m.method === 'channels/close') reply({ closed: true }); else if (m.method === 'channels/open') reply({ channel: { id: m.params.channelId, type: 'discord', label: m.params.channelId } }); - else if (m.method === 'push/render') { renders.push(m.params); reply(await renderer(m.params)); } + else if (m.method === 'push/render') { + renders.push(m.params); + const out = await renderer(m.params) as { error?: unknown } | undefined; + // A renderer may answer with a JSON-RPC error: { error: { code, message } }. + if (out && typeof out === 'object' && 'error' in out) ws.send(JSON.stringify({ jsonrpc: '2.0', id: m.id, error: out.error })); + else reply(out); + } else if (m.id !== undefined) reply({}); }); }); diff --git a/test/mcpl-coalesced-content-parity.test.ts b/test/mcpl-coalesced-content-parity.test.ts new file mode 100644 index 000000000..4b8612b51 --- /dev/null +++ b/test/mcpl-coalesced-content-parity.test.ts @@ -0,0 +1,532 @@ +/** + * A coalesced occurrence is admitted exactly as an uncoalesced message is + * (agent-framework#266). + * + * RFC-006 keeps content in context: a plain coalesced occurrence is delivered + * through the ordinary channel/push path the moment it is admitted, and the + * coalescer only remembers where it landed. So the `coalesce` member must not + * decide whether a message carrying an image is admitted. A 1 MiB + * serialized-content budget on the coalesced path alone dropped every Discord + * message with a screenshot, silently on the host. + * + * Also: every coalesce rejection is visible on the host (a console line and a + * trace naming the field), not only on the wire. + * + * Run: node --import tsx --test test/mcpl-coalesced-content-parity.test.ts + */ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { fixture, TS } from './helpers/coalescing-fixture.js'; +import { RefusalLines } from '../src/mcpl/refusal-lines.js'; + +/** Base64 for an image well over 1 MiB once serialized (a Retina screenshot). */ +const BIG_IMAGE = { type: 'image', data: 'A'.repeat(1_600_000), mimeType: 'image/png' }; + +type Rejection = { type: string; reason?: string; field?: string; detail?: string; messageId?: string; eventId?: string; channelId?: string }; + +type Fixture = Awaited>; + +/** The agent's context keeps `count` images, each BIG_IMAGE with its data whole: stored, not only accepted. */ +function assertKeepsBigImage(f: Fixture, count: number): void { + const images = f.framework.getAgent('agent')!.getContextManager().getAllMessages() + .flatMap((m) => (Array.isArray(m.content) ? m.content : [])) + .filter((b) => (b as { type?: string }).type === 'image') as Array<{ source?: unknown }>; + assert.equal(images.length, count, `${count} image(s) stored`); + for (const image of images) { + assert.deepEqual(image.source, { type: 'base64', data: BIG_IMAGE.data, mediaType: BIG_IMAGE.mimeType }, 'the image data arrives whole'); + } +} + +function captureConsoleError(t: { after: (fn: () => void) => void }): string[] { + const lines: string[] = []; + const original = console.error; + console.error = (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }; + t.after(() => { console.error = original; }); + return lines; +} + +test('#266 repro: a coalesced channel message with a >1 MiB inline image is admitted and stored, as an uncoalesced one is', async (t) => { + const f = await fixture(); t.after(f.close); await f.register(); + const coalesced = { ...f.channel('e1', '', { initial: true }, 'chat', 'shot'), content: [{ type: 'text', text: 'look_at_this' }, BIG_IMAGE] }; + const plain = { + channelId: 'chat', messageId: 'plain', timestamp: TS, author: { id: 'u', name: 'User' }, + content: [{ type: 'text', text: 'plain_with_image' }, BIG_IMAGE], + }; + const r = await f.send('channels/incoming', { messages: [coalesced, plain] }); + assert.deepEqual(r.result.results.map((x: { accepted: boolean }) => x.accepted), [true, true]); + assert.equal(r.result.results[0].coalesce?.outcome, 'first'); + await f.framework.runUntilIdle(); + const context = f.context(); + assert(context.includes('look_at_this'), 'the coalesced message is stored'); + assert(context.includes('plain_with_image'), 'the uncoalesced one too'); + assertKeepsBigImage(f, 2); +}); + +test('#266: a coalesced push/event with a >1 MiB inline image is admitted and stored', async (t) => { + const f = await fixture(); t.after(f.close); + const params = { ...f.params('p1', '', { initial: true }), payload: { content: [{ type: 'text', text: 'pushed_with_image' }, BIG_IMAGE] } }; + const r = await f.send('push/event', params); + assert.equal(r.error, undefined); + assert.equal(r.result.accepted, true); + assert.equal(r.result.coalesce.outcome, 'first'); + await f.framework.runUntilIdle(); + assert(f.context().includes('pushed_with_image')); + assertKeepsBigImage(f, 1); +}); + +test('#266: a render result carrying a >1 MiB image is delivered, not replaced by the fallback (RFC-006 §5.2)', async (t) => { + const f = await fixture(); t.after(f.close); + f.renderer(async () => ({ content: [{ type: 'text', text: 'rendered_with_image' }, BIG_IMAGE] })); + await f.send('push/event', f.params('d1', 'render_fallback', { deferred: true })); + await f.framework.runUntilIdle(); + assert.equal(f.renders.length, 1); + const context = f.context(); + assert(context.includes('rendered_with_image'), 'the rendered content is delivered'); + assert(!context.includes('render_fallback'), 'not the fallback'); + assertKeepsBigImage(f, 1); +}); + +test('#266: a malformed coalesced channel item is refused on the wire and named on the host', async (t) => { + const f = await fixture(); t.after(f.close); await f.register(); + const lines = captureConsoleError(t); + const rejected: Rejection[] = []; + f.framework.onTrace((e) => { if (e.type === 'mcpl:channel-incoming-rejected') rejected.push(e); }); + const badBlock = { ...f.channel('e1', '', { initial: true }, 'chat', 'bad'), content: ['not-a-block'] }; + const noEventId = { ...f.channel('e2', 'no_event_id', { initial: true }, 'chat', 'noid'), eventId: undefined }; + const noMessageId = { ...f.channel('e3', 'no_message_id', { initial: true }, 'chat', 'x'), messageId: undefined }; + const r = await f.send('channels/incoming', { messages: [badBlock, noEventId, noMessageId] }); + assert.deepEqual(r.result.results.map((x: { reason?: string }) => x.reason), ['coalesce_invalid', 'coalesce_invalid', 'coalesce_invalid'], 'the wire is unchanged'); + assert.deepEqual( + rejected.map(({ reason, field, messageId }) => ({ reason, field, messageId })), + [ + { reason: 'coalesce-invalid', field: 'payload.content', messageId: 'bad' }, + { reason: 'coalesce-invalid', field: 'eventId', messageId: 'noid' }, + { reason: 'coalesce-invalid', field: 'messageId', messageId: undefined }, + ], + ); + assert(rejected.every((e) => typeof e.detail === 'string' && e.detail.length > 0), 'each says why'); + assert(lines.some((l) => l.includes('[channel-incoming-rejected]') && l.includes('messageId=bad') && l.includes('reason=coalesce-invalid') && l.includes('field=payload.content'))); + assert(lines.some((l) => l.includes('[channel-incoming-rejected]') && l.includes('messageId=noid') && l.includes('field=eventId'))); +}); + +test('#266: a malformed coalesced push is a -32602 on the wire and named on the host', async (t) => { + const f = await fixture(); t.after(f.close); + const lines = captureConsoleError(t); + const rejected: Rejection[] = []; + f.framework.onTrace((e) => { if (e.type === 'mcpl:push-event-rejected') rejected.push(e); }); + const badBlock = { ...f.params('b1', ''), payload: { content: ['not-a-block'] } }; + const badKey = f.params('b2', 'text', { key: 'k'.repeat(257) }); + const first = await f.send('push/event', badBlock); + const second = await f.send('push/event', badKey); + assert.equal(first.error?.code, -32602); + assert.equal(second.error?.code, -32602); + assert.deepEqual( + rejected.map(({ reason, field, eventId }) => ({ reason, field, eventId })), + [ + { reason: 'coalesce-invalid', field: 'payload.content', eventId: 'b1' }, + { reason: 'coalesce-invalid', field: 'coalesce.key', eventId: 'b2' }, + ], + ); + assert(lines.some((l) => l.includes('[push-event-rejected]') && l.includes('eventId=b1') && l.includes('reason=coalesce-invalid') && l.includes('field=payload.content'))); + assert(lines.some((l) => l.includes('[push-event-rejected]') && l.includes('eventId=b2') && l.includes('field=coalesce.key'))); +}); + +test('#266: a coalescer failure is traced as the host\'s (coalesce-failed), as the wire answers it, not as the sender\'s malformed item', async (t) => { + const f = await fixture(); t.after(f.close); await f.register(); + const lines = captureConsoleError(t); + const rejected: Rejection[] = []; + f.framework.onTrace((e) => { + if (e.type === 'mcpl:channel-incoming-rejected' || e.type === 'mcpl:push-event-rejected') rejected.push(e); + }); + // The coalescer itself throws a plain Error (no code) for well-formed items. + (f.framework as unknown as { pushCoalescer: { accept: () => Promise } }).pushCoalescer.accept = + async () => { throw new Error('coalescer_broke'); }; + const channel = await f.send('channels/incoming', { messages: [f.channel('c1', 'fine_text', { initial: true }, 'chat', 'fine')] }); + 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'); + assert.deepEqual( + rejected.map(({ type, reason, detail }) => ({ type, reason, detail })), + [ + { type: 'mcpl:channel-incoming-rejected', reason: 'coalesce-failed', detail: 'coalescer_broke' }, + { type: 'mcpl:push-event-rejected', reason: 'coalesce-failed', detail: 'coalescer_broke' }, + ], + ); + const [channelTrace, pushTrace] = rejected as Array; + assert.equal(channelTrace.channelId, 'chat', 'the channel trace names its channel'); + assert.equal(pushTrace.featureSet, 'doc', 'the push trace names its feature set'); + assert(rejected.every((e) => !('field' in e)), 'a plain Error has no field'); + assert(lines.some((l) => l.includes('[channel-incoming-rejected]') && l.includes('reason=coalesce-failed'))); + assert(lines.some((l) => l.includes('[push-event-rejected]') && l.includes('reason=coalesce-failed'))); +}); + +test('a push the coalescer can\'t take (-32000, coalescing unavailable) is the host\'s failure on both lanes', async (t) => { + const f = await fixture(); t.after(f.close); await f.register(); + const lines = captureConsoleError(t); + const rejected: Array = []; + f.framework.onTrace((e) => { + if (e.type === 'mcpl:channel-incoming-rejected' || e.type === 'mcpl:push-event-rejected') rejected.push(e); + }); + (f.framework as unknown as { pushCoalescer: unknown }).pushCoalescer = null; + const channel = await f.send('channels/incoming', { messages: [f.channel('c1', 'fine_text', { initial: true }, 'chat', 'fine')] }); + assert.deepEqual(channel.result.results[0], { messageId: 'fine', accepted: false, reason: 'coalescing unavailable' }); + const push = await f.send('push/event', f.params('p1', 'fine_push', { initial: true })); + assert.equal(push.error?.code, -32000); + assert.deepEqual( + rejected.map(({ type, reason, field }) => ({ type, reason, field })), + [ + { type: 'mcpl:channel-incoming-rejected', reason: 'coalesce-failed', field: 'coalesce' }, + { type: 'mcpl:push-event-rejected', reason: 'coalesce-failed', field: 'coalesce' }, + ], + ); + assert(lines.some((l) => l.startsWith('[push-event-rejected]') && l.includes('reason=coalesce-failed field=coalesce: "coalescing unavailable"'))); +}); + +test('a channel-scoped push the sender may not make is the sender\'s refusal (coalesce-invalid), as the wire answers it', async (t) => { + // -32023: the channel isn't one the server declared. + const f = await fixture(); t.after(f.close); + const rejected: Rejection[] = []; + f.framework.onTrace((e) => { if (e.type === 'mcpl:push-event-rejected') rejected.push(e); }); + const unknown = await f.send('push/event', f.params('u1', 'to_nowhere', { initial: true, channelId: 'nope' })); + assert.equal(unknown.error?.code, -32023); + // -32017: the server has no channels.incoming grant. + const g = await fixture({ server: { disabledCapabilities: ['channels.incoming'] } }); t.after(g.close); + g.framework.onTrace((e) => { if (e.type === 'mcpl:push-event-rejected') rejected.push(e); }); + const denied = await g.send('push/event', g.params('d1', 'not_permitted', { initial: true, channelId: 'chat' })); + assert.equal(denied.error?.code, -32017); + assert.deepEqual( + rejected.map(({ reason, field, eventId }) => ({ reason, field, eventId })), + [ + { reason: 'coalesce-invalid', field: 'coalesce.channelId', eventId: 'u1' }, + { reason: 'coalesce-invalid', field: 'coalesce.channelId', eventId: 'd1' }, + ], + ); +}); + +test('a block the converters can\'t render is admitted coalesced exactly as uncoalesced: a placeholder, not a refusal', async (t) => { + const f = await fixture(); t.after(f.close); await f.register(); + const odd = [ + [{ type: 'video', uri: 'https://example.invalid/v.mp4' }], + [{ type: 'mystery' }], + [{ type: 'image', mimeType: 'image/png' }], + ]; + const messages = odd.flatMap((content, i) => [ + { ...f.channel(`e${i}`, '', { initial: true }, 'chat', `coalesced${i}`), content }, + { channelId: 'chat', messageId: `plain${i}`, timestamp: TS, author: { id: 'u', name: 'User' }, content }, + ]); + const r = await f.send('channels/incoming', { messages }); + assert.deepEqual(r.result.results.map((x: { accepted: boolean }) => x.accepted), messages.map(() => true)); + for (const [i, content] of odd.entries()) { + const push = await f.send('push/event', { ...f.params(`p${i}`, '', { initial: true, key: `doc${i}` }), payload: { content } }); + assert.equal(push.error, undefined, JSON.stringify(content)); + assert.equal(push.result.accepted, true); + } +}); + +/** How many times `needle` occurs in `haystack`. */ +function occurrences(haystack: string, needle: string): number { + return haystack.split(needle).length - 1; +} + +test('a block whose type, text or source isn\'t a string converts on both lanes, coalesced or not, without stopping a batch', async (t) => { + const f = await fixture(); t.after(f.close); await f.register(); + f.alwaysRespond(); + // What isn't a string is left out of the block. An object whose toString + // isn't a function throws when converted to text, as a placeholder would. + // `shows` is what the context then holds for it. Each of text, data, + // mimeType and uri also takes an array, a number and null. + const odd = (marker: string) => [{ toString: 1 }, [marker], 424242, null]; + const malformed: Array<{ content: unknown[]; shows: string }> = [ + { content: [{ type: { toString: 1 } }], shows: '[unrecognized content block: untyped]' }, + { content: [{ type: 7 }], shows: '[unrecognized content block: untyped]' }, + ...odd('array_data').map((data) => ({ content: [{ type: 'image', data, mimeType: 'image/png' }], shows: '[Image: no data]' })), + ...odd('array_uri').map((uri) => ({ content: [{ type: 'image', uri }], shows: '[Image: no data]' })), + // Data whose media type is unusable is named as such, not as no data. + ...odd('array_mime').map((mimeType) => ({ content: [{ type: 'image', data: 'AAAA', mimeType }], shows: '[Image: no media type]' })), + ...odd('array_mime').map((mimeType) => ({ content: [{ type: 'audio', data: 'AAAA', mimeType }], shows: '[Audio: no media type]' })), + ...odd('array_text').map((text, i) => ({ + content: [{ type: 'text', text }, { type: 'text', text: `beside_text_without_text_${i}` }], shows: `beside_text_without_text_${i}`, + })), + // Reference-shaped: a uri that isn't a non-empty string never makes a + // reference, with a disposition or without. + { content: [{ type: 'resource', uri: 424242 }], shows: '[unrecognized content block: reference without string uri]' }, + { content: [{ type: 'image', uri: 424242, disposition: 'ref' }], shows: '[Image: no data]' }, + { content: [{ type: 'image', uri: '', disposition: 'ref' }], shows: '[Image: no data]' }, + { content: [{ type: 'audio', uri: { toString: 1 }, disposition: 'ref' }], shows: '[Audio: no data]' }, + ]; + const messages: unknown[] = malformed.flatMap(({ content }, i) => [ + { ...f.channel(`e${i}`, '', { initial: true }, 'chat', `coalesced${i}`), content }, + { channelId: 'chat', messageId: `plain${i}`, timestamp: TS, author: { id: 'u', name: 'User' }, content }, + ]); + // A valid message after them all, which a throw in conversion never reached. + messages.push(f.channel('last', 'sibling_after_malformed', { initial: true }, 'chat', 'last')); + const r = await f.send('channels/incoming', { messages }); + assert.equal(r.error, undefined); + assert.deepEqual(r.result.results.map((x: { accepted: boolean }) => x.accepted), messages.map(() => true)); + for (const [i, { content }] of malformed.entries()) { + const coalesced = await f.send('push/event', { ...f.params(`p${i}`, '', { initial: true, key: `doc${i}` }), payload: { content } }); + assert.equal(coalesced.error, undefined, JSON.stringify(content)); + assert.equal(coalesced.result.accepted, true); + const { coalesce: _coalesce, ...uncoalesced } = f.params(`q${i}`, ''); + const plain = await f.send('push/event', { ...uncoalesced, payload: { content } }); + assert.equal(plain.error, undefined, JSON.stringify(content)); + assert.equal(plain.result.accepted, true); + } + await f.framework.runUntilIdle(); + const context = f.context(); + assert(context.includes('sibling_after_malformed'), 'the batch went on past the malformed messages'); + // Each malformed block, four times: coalesced and not, on each lane. + for (const shows of new Set(malformed.map((m) => m.shows))) { + const expected = malformed.filter((m) => m.shows === shows).length * 4; + assert.equal(occurrences(context, JSON.stringify(shows)), expected, shows); + } + for (const leaked of ['toString', 'array_', '424242']) assert(!context.includes(leaked), `nothing that was not a string reaches the context (${leaked})`); +}); + +test('a text block whose text isn\'t a string is no text, so alone it is refused as empty on both lanes, coalesced or not', async (t) => { + const f = await fixture(); t.after(f.close); await f.register(); + const content = [{ type: 'text', text: { toString: 1 } }]; + const r = await f.send('channels/incoming', { messages: [ + { ...f.channel('e1', '', { initial: true }, 'chat', 'coalesced'), content }, + { channelId: 'chat', messageId: 'plain', timestamp: TS, author: { id: 'u', name: 'User' }, content }, + ] }); + assert.deepEqual(r.result.results.map((x: { accepted: boolean; reason?: string }) => [x.accepted, x.reason]), + [[false, 'empty_content'], [false, 'empty_content']]); + const coalesced = await f.send('push/event', { ...f.params('p1', '', { initial: true }), payload: { content } }); + const { coalesce: _coalesce, ...uncoalesced } = f.params('q1', ''); + const plain = await f.send('push/event', { ...uncoalesced, payload: { content } }); + assert.equal(coalesced.error?.code, -32602); + assert.equal(plain.error?.code, -32602); + assert.equal(coalesced.error?.message, plain.error?.message); +}); + +test('an inference filter reads the text conversion stores, a placeholder included, on both lanes, coalesced or not', async (t) => { + const seen: string[] = []; + const f = await fixture({ server: { shouldTriggerInference: (text: string) => { seen.push(text); return false; } } }); + t.after(f.close); await f.register(); + // A text block whose text isn't a string, which reads as no text; a block + // that converts to a placeholder; and visible text. + const content = [{ type: 'text', text: { toString: 1 } }, { type: 'video', uri: 'https://example.invalid/v.mp4' }, { type: 'text', text: 'visible_text' }]; + const shown = '\n[unrecognized content block: video]\nvisible_text'; + const r = await f.send('channels/incoming', { messages: [ + { ...f.channel('e1', '', { initial: true }, 'chat', 'coalesced'), content }, + { channelId: 'chat', messageId: 'plain', timestamp: TS, author: { id: 'u', name: 'User' }, content }, + // A valid message after them, which a throw in the filter never reached. + { channelId: 'chat', messageId: 'sibling', timestamp: TS, author: { id: 'u', name: 'User' }, content: [{ type: 'text', text: 'sibling_text' }] }, + ] }); + assert.equal(r.error, undefined); + assert.deepEqual(r.result.results.map((x: { accepted: boolean }) => x.accepted), [true, true, true]); + const coalesced = await f.send('push/event', { ...f.params('p1', '', { initial: true }), payload: { content } }); + const { coalesce: _coalesce, ...uncoalesced } = f.params('q1', ''); + const plain = await f.send('push/event', { ...uncoalesced, payload: { content } }); + assert.equal(coalesced.result?.accepted, true); + assert.equal(plain.result?.accepted, true); + // Each lane joins its converted text blocks with a line break, the + // non-string one as empty text and the video as its placeholder. + assert.deepEqual(seen, [shown, shown, 'sibling_text', shown, shown], + 'the filter gets the same text on both lanes, and is reached for every message'); +}); + +test('a render result with a malformed block falls back, and the host names it on a console line', async (t) => { + const f = await fixture(); t.after(f.close); + const lines = captureConsoleError(t); + f.renderer(async () => ({ content: [{ type: 'text' }] })); + await f.send('push/event', f.params('r1', 'render_fallback', { deferred: true })); + await f.framework.runUntilIdle(); + assert.equal(f.renders.length, 1); + assert(f.context().includes('render_fallback'), 'the occurrence\'s own content is delivered'); + const line = lines.find((l) => l.startsWith('[push-render-failed]')); + assert(line, lines.join('\n')); + assert.match(line, /^\[push-render-failed\] server=editor subject=\S+ eventId=r1 field=payload\.content: "CoalesceError:\\u0020invalid\\u0020content\\u0020block" \(the occurrence's own content is delivered instead\)$/); +}); + +test('a render result is delivered only when the converters show each block as itself or as a reference stub', async (t) => { + const f = await fixture(); t.after(f.close); + const lines = captureConsoleError(t); + f.alwaysRespond(); + const cases: Array<{ block: Record; delivered: boolean }> = [ + { block: { type: 'image', data: 'AAAA', mimeType: 'image/png' }, delivered: true }, + { block: { type: 'image', uri: 'https://example.invalid/i.png' }, delivered: true }, + { block: { type: 'audio', data: 'AAAA', mimeType: 'audio/wav' }, delivered: true }, + { block: { type: 'audio', uri: 'https://example.invalid/a.wav', disposition: 'ref' }, delivered: true }, + { block: { type: 'resource', uri: 'https://example.invalid/doc' }, delivered: true }, + // Each of these converts to a placeholder, so the occurrence's own + // content is delivered instead. + { block: { type: 'image', data: '', mimeType: 'image/png' }, delivered: false }, + { block: { type: 'image', data: 'AAAA', mimeType: '' }, delivered: false }, + { block: { type: 'image', data: 'AAAA', mimeType: 'image/png', uri: 'https://example.invalid/i.png' }, delivered: false }, + { block: { type: 'audio', data: '', mimeType: 'audio/wav' }, delivered: false }, + { block: { type: 'audio', uri: 'https://example.invalid/a.wav' }, delivered: false }, + { block: { type: 'resource', uri: '' }, delivered: false }, + { block: { type: 'resource', uri: `https://example.invalid/${'x'.repeat(4096)}` }, delivered: false }, + { block: { type: 'audio', uri: `https://example.invalid/${'x'.repeat(4096)}`, disposition: 'ref' }, delivered: false }, + { block: { type: 'image', uri: '' }, delivered: false }, + { block: { type: 'video', data: 'AAAA', mimeType: 'video/mp4' }, delivered: false }, + ]; + f.renderer(async (params) => { + const i = Number(String(params.eventId).slice(1)); + return { content: [{ type: 'text', text: `rendered_${i}` }, cases[i].block] }; + }); + for (const [i] of cases.entries()) await f.send('push/event', f.params(`r${i}`, `fallback_${i}`, { deferred: true, key: `doc${i}` })); + await f.framework.runUntilIdle(); + assert.equal(f.renders.length, cases.length); + const context = f.context(); + for (const [i, { block, delivered }] of cases.entries()) { + assert.equal(context.includes(JSON.stringify(`rendered_${i}`)), delivered, `rendered: ${JSON.stringify(block)}`); + assert.equal(context.includes(JSON.stringify(`fallback_${i}`)), !delivered, `fell back: ${JSON.stringify(block)}`); + } + // Each fallback is named on the host. + const failed = lines.filter((l) => l.startsWith('[push-render-failed]')).map((l) => /eventId=(\S+)/.exec(l)?.[1]).sort(); + assert.deepEqual(failed, cases.flatMap(({ delivered }, i) => (delivered ? [] : [`r${i}`])).sort()); +}); + +test('a render error the server words itself prints as one field, so it can\'t add fields to the line', async (t) => { + const f = await fixture(); t.after(f.close); + const lines = captureConsoleError(t); + f.renderer(async () => ({ error: { code: -32000, message: 'bad server=other eventId=forged' } })); + await f.send('push/event', f.params('r2', 'render_fallback', { deferred: true })); + await f.framework.runUntilIdle(); + assert(f.context().includes('render_fallback'), 'the occurrence\'s own content is delivered'); + const line = lines.find((l) => l.startsWith('[push-render-failed]')); + assert(line, lines.join('\n')); + assert(line.includes('bad\\u0020server\\u003dother\\u0020eventId\\u003dforged'), line); + // The last field before the tail ends with its colon. + const fields = line.split(' ').filter((word) => /^(server|eventId)=/.test(word)).map((word) => word.replace(/:$/, '')); + assert.deepEqual(fields, ['server=editor', 'eventId=r2'], 'no field but the real ones'); +}); + +test('an uncoalesced message without an identity is refused as one, with no coalesce line or trace', async (t) => { + const f = await fixture(); t.after(f.close); await f.register(); + const lines = captureConsoleError(t); + const rejected: Rejection[] = []; + f.framework.onTrace((e) => { if (e.type === 'mcpl:channel-incoming-rejected') rejected.push(e); }); + const plain = { channelId: 'chat', messageId: 'm1', timestamp: TS, author: { id: 'u', name: 'User' }, content: [{ type: 'text', text: 'hi' }] }; + // With no coalescer wired, a message carrying coalesce is handled uncoalesced too. + const withoutCoalescer = await fixture(); t.after(withoutCoalescer.close); await withoutCoalescer.register(); + (withoutCoalescer.framework as unknown as { channelRegistry: { handleCoalescedIncoming: unknown } }).channelRegistry.handleCoalescedIncoming = undefined; + withoutCoalescer.framework.onTrace((e) => { if (e.type === 'mcpl:channel-incoming-rejected') rejected.push(e); }); + + const r = await f.send('channels/incoming', { messages: [{ ...plain, channelId: undefined }, { ...plain, messageId: undefined }] }); + const w = await withoutCoalescer.send('channels/incoming', { messages: [{ ...withoutCoalescer.channel('e1', 'hi', { initial: true }), messageId: undefined }] }); + assert.deepEqual( + [...r.result.results, ...w.result.results].map((x: { reason?: string }) => x.reason), + ['invalid channel/message identity', 'invalid channel/message identity', 'invalid channel/message identity'], + ); + assert.deepEqual(rejected, [], 'no coalesce trace'); + assert(!lines.some((l) => l.includes('coalesce')), lines.join('\n')); +}); + +test('a coalesced push without an eventId, or with one that is not a string, is answered and named without throwing', async (t) => { + const f = await fixture(); t.after(f.close); + const lines = captureConsoleError(t); + const rejected: Rejection[] = []; + f.framework.onTrace((e) => { if (e.type === 'mcpl:push-event-rejected') rejected.push(e); }); + const missing = await f.send('push/event', { ...f.params('x', 'no_id', { initial: true }), eventId: undefined }); + assert.equal(missing.error?.code, -32602); + // An object eventId whose toString isn't callable, on the malformed-content + // path, where the line is written before the answer. + const odd = await f.send('push/event', { ...f.params('x', ''), eventId: { toString: 1 }, payload: { content: ['not-a-block'] } }); + assert.equal(odd.error?.code, -32602, 'answered'); + assert.deepEqual(rejected.map(({ eventId, field }) => ({ eventId, field })), [ + { eventId: '', field: 'eventId' }, + { eventId: '', field: 'payload.content' }, + ]); + assert(lines.some((l) => l.startsWith('[push-event-rejected] server=editor featureSet=doc eventId="" reason=coalesce-invalid field=eventId:')), lines.join('\n')); + assert(lines.some((l) => l.startsWith('[push-event-rejected] server=editor featureSet=doc eventId="{\\"toString\\":1}" reason=coalesce-invalid field=payload.content:')), lines.join('\n')); +}); + +test('a message for an unregistered channel is traced with its message id, coalesced or not, and named on the host at most once a minute per channel', async (t) => { + const f = await fixture(); t.after(f.close); + const lines = captureConsoleError(t); + const rejected: Rejection[] = []; + f.framework.onTrace((e) => { if (e.type === 'mcpl:channel-incoming-rejected') rejected.push(e); }); + let now = 0; + (f.framework as unknown as { channelRegistry: { unknownChannelLines: RefusalLines } }).channelRegistry.unknownChannelLines = new RefusalLines(() => now); + const plain = (channelId: string, messageId: string) => ({ + channelId, messageId, timestamp: TS, author: { id: 'u', name: 'User' }, content: [{ type: 'text', text: 'hi' }], + }); + const r = await f.send('channels/incoming', { messages: [ + plain('nowhere', 'p1'), f.channel('e1', 'hi', { initial: true }, 'nowhere', 'c1'), plain('nowhere', 'p2'), plain('elsewhere', 'q1'), + ] }); + assert.deepEqual(r.result.results.map((x: { accepted: boolean }) => x.accepted), [false, false, false, false]); + // A minute on, the channel's next refusal prints again, with how many came since. + now += 60_000; + await f.send('channels/incoming', { messages: [plain('nowhere', 'p3')] }); + assert.deepEqual(rejected.map(({ messageId, reason }) => [messageId, reason]), [ + ['p1', 'unknown-channel'], ['c1', 'unknown-channel'], ['p2', 'unknown-channel'], ['q1', 'unknown-channel'], ['p3', 'unknown-channel'], + ]); + assert.deepEqual(lines.filter((l) => l.startsWith('[channel-incoming-rejected]')), [ + '[channel-incoming-rejected] server=editor channel=nowhere messageId=p1 reason=unknown-channel (not registered, §14.5)', + '[channel-incoming-rejected] server=editor channel=elsewhere messageId=q1 reason=unknown-channel (not registered, §14.5)', + '[channel-incoming-rejected] server=editor channel=nowhere messageId=p3 reason=unknown-channel (not registered, §14.5; 2 more since the last line)', + ]); +}); + +test('a channel-scoped push refused for its channel (-32023, -32017) is traced each time and named, with its channel, on the host at most once a minute per channel', async (t) => { + let now = 0; + const throttle = (g: Awaited>) => { + (g.framework as unknown as { pushHandler: { channelRefusalLines: RefusalLines } }).pushHandler.channelRefusalLines = new RefusalLines(() => now); + }; + const lines = captureConsoleError(t); + const rejected: Rejection[] = []; + // -32023: a channel the server never declared. + const f = await fixture(); t.after(f.close); throttle(f); + f.framework.onTrace((e) => { if (e.type === 'mcpl:push-event-rejected') rejected.push(e); }); + for (const id of ['u1', 'u2', 'u3']) { + const r = await f.send('push/event', f.params(id, 'to_nowhere', { initial: true, channelId: 'nope', key: id })); + assert.equal(r.error?.code, -32023); + } + // Another channel of the same server prints its own first refusal. + const other = await f.send('push/event', f.params('v1', 'to_elsewhere', { initial: true, channelId: 'elsewhere', key: 'v1' })); + assert.equal(other.error?.code, -32023); + // A push refused for what it holds (-32602) prints every time, whatever its channel. + for (const id of ['m1', 'm2']) { + const { timestamp: _, ...untimed } = f.params(id, 'to_nowhere', { initial: true, channelId: 'nope', key: id }); + const r = await f.send('push/event', untimed); + assert.equal(r.error?.code, -32602); + } + // -32017: a server with no channels.incoming grant. + const g = await fixture({ server: { disabledCapabilities: ['channels.incoming'] } }); t.after(g.close); throttle(g); + g.framework.onTrace((e) => { if (e.type === 'mcpl:push-event-rejected') rejected.push(e); }); + for (const id of ['d1', 'd2']) { + const r = await g.send('push/event', g.params(id, 'not_permitted', { initial: true, channelId: 'chat', key: id })); + assert.equal(r.error?.code, -32017); + } + now += 60_000; + await f.send('push/event', f.params('u4', 'to_nowhere', { initial: true, channelId: 'nope', key: 'u4' })); + // Each refusal is traced, and one refused for its channel names it. + assert.deepEqual(rejected.map(({ eventId, reason, channelId }) => [eventId, reason, channelId]), [ + ['u1', 'coalesce-invalid', 'nope'], ['u2', 'coalesce-invalid', 'nope'], ['u3', 'coalesce-invalid', 'nope'], ['v1', 'coalesce-invalid', 'elsewhere'], + ['m1', 'coalesce-invalid', undefined], ['m2', 'coalesce-invalid', undefined], + ['d1', 'coalesce-invalid', 'chat'], ['d2', 'coalesce-invalid', 'chat'], ['u4', 'coalesce-invalid', 'nope'], + ]); + assert.deepEqual(lines.filter((l) => l.startsWith('[push-event-rejected]')), [ + '[push-event-rejected] server=editor featureSet=doc eventId=u1 channel=nope reason=coalesce-invalid field=coalesce.channelId: "Unknown channel"', + '[push-event-rejected] server=editor featureSet=doc eventId=v1 channel=elsewhere reason=coalesce-invalid field=coalesce.channelId: "Unknown channel"', + '[push-event-rejected] server=editor featureSet=doc eventId=m1 reason=coalesce-invalid field=timestamp: "timestamp is required"', + '[push-event-rejected] server=editor featureSet=doc eventId=m2 reason=coalesce-invalid field=timestamp: "timestamp is required"', + '[push-event-rejected] server=editor featureSet=doc eventId=d1 channel=chat reason=coalesce-invalid field=coalesce.channelId: "Channel not permitted"', + '[push-event-rejected] server=editor featureSet=doc eventId=u4 channel=nope reason=coalesce-invalid field=coalesce.channelId: "Unknown channel" (2 more since the last line)', + ]); +}); + +test('the framework\'s empty-content backstops name a module-emitted event\'s ids as one field each', async (t) => { + // Events that never crossed the MCPL boundary (here, emitted straight onto + // the queue) meet the store/wake backstop instead of the ingress refusal. + const f = await fixture(); t.after(f.close); + const lines = captureConsoleError(t); + const forged = 'x\n[forged] y'; + f.framework.pushEvent({ + type: 'mcpl:push-event', serverId: 'editor', featureSet: 'doc', eventId: forged, content: [], timestamp: TS, triggerInference: false, + } as never); + f.framework.pushEvent({ + type: 'mcpl:channel-incoming', serverId: 'editor', channelId: forged, messageId: forged, + author: { id: 'u', name: 'User' }, content: [], timestamp: TS, triggerInference: false, + } as never); + await f.framework.runUntilIdle(); + const shown = '"x\\n[forged]\\u0020y"'; + assert.deepEqual(lines.filter((l) => l.includes('-dropped]')).sort(), [ + `[channel-incoming-dropped] server=editor channel=${shown} messageId=${shown} reason=empty-content`, + `[push-event-dropped] server=editor eventId=${shown} reason=empty-content`, + ], lines.join('\n')); +}); diff --git a/test/mcpl-rejection-log-lines.test.ts b/test/mcpl-rejection-log-lines.test.ts new file mode 100644 index 000000000..31e94cede --- /dev/null +++ b/test/mcpl-rejection-log-lines.test.ts @@ -0,0 +1,371 @@ +/** + * A rejection line in the host log can't be forged by the sender's own + * identifiers (agent-framework#267 review). + * + * The ingress handlers' rejection lines name what the server sent (its + * channel, messageId, eventId and featureSet), and the host log is read a + * line at a time, by eye and with grep. Printed raw, a line break in an id + * printed a second line that read as another host record, about another + * server, and an `=` in it could hold a lookalike field that a search for + * that field found first. Each such value now prints through `logValue`: a + * plain id as it is, anything else as one JSON string with its `=` and + * invisible characters escaped, cut with its length named when it is long. + * + * Run: node --import tsx --test test/mcpl-rejection-log-lines.test.ts + */ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { fixture, TS } from './helpers/coalescing-fixture.js'; +import { logDetail, logValue } from '../src/mcpl/log-value.js'; +import { ChannelRegistry } from '../src/mcpl/channel-registry.js'; +import { CapabilityGrant, ALL_CAPABILITY_PATHS } from '../src/mcpl/capability-grant.js'; +import { parseDeclaredClasses } from '../src/mcpl/tool-classes.js'; +import { RefusalLines } from '../src/mcpl/refusal-lines.js'; +import { AgentFramework } from '../src/framework.js'; +import type { McplServerRegistry } from '../src/mcpl/server-registry.js'; +import type { FeatureSetManager } from '../src/mcpl/feature-set-manager.js'; + +/** A field as the host log shows it: one JSON string, its spaces and `=` escaped too. */ +const field = (value: string) => JSON.stringify(value).replace(/ /g, '\\u0020').replace(/=/g, '\\u003d'); +/** An id that, printed raw, would add a line reading as another server's record. */ +const FORGED = 'x\n[push-event-rejected] server=other eventId=y reason=duplicate'; +/** How the host log shows it: one quoted field. */ +const SHOWN = field(FORGED); +/** A feature set the server declares under a forged name, enabled by `*`. */ +const FORGED_SET = 'doc\n[push-event-rejected] server=other eventId=y reason=duplicate'; +/** A channel the server registers under a forged id. */ +const FORGED_CHANNEL = 'chat\n[channel-incoming-rejected] server=other channel=chat messageId=y reason=empty-content'; + +function captureConsoleError(t: { after: (fn: () => void) => void }): string[] { + const lines: string[] = []; + const original = console.error; + console.error = (...args: unknown[]) => { lines.push(args.map(String).join(' ')); }; + t.after(() => { console.error = original; }); + return lines; +} + +test('logValue: a plain id prints as it is', () => { + for (const id of ['bad', 'discord:1234567890', 'message:m', 'café', '日本']) assert.equal(logValue(id), id); + assert.equal(logValue(undefined), 'undefined'); +}); + +test('logValue: lookalikes print as they are; ids that differ only invisibly never print alike', () => { + // Canonically equivalent or lookalike ids can still print alike: café + // composed and decomposed, and a Cyrillic а for a Latin a. + for (const id of ['caf\u00e9', 'cafe\u0301', '\u0430bc', 'abc']) assert.equal(logValue(id), id, JSON.stringify(id)); + // A Hangul filler, a combining grapheme joiner, a variation selector and a + // blank Braille pattern are escaped, so each differs from plain abc. + const cases: Array<[string, string]> = [ + ['abc\u3164', '"abc\\u3164"'], + ['\u034fabc', '"\\u034fabc"'], + ['abc\ufe0f', '"abc\\ufe0f"'], + ['ab\u2800c', '"ab\\u2800c"'], + ]; + for (const [value, shown] of cases) { + assert.equal(logValue(value), shown, JSON.stringify(value)); + assert.equal(JSON.parse(logValue(value)), value); + } +}); + +test('logValue: an = is escaped, so a search for a field on the line finds only the real one', () => { + assert.equal(logValue('a=b'), '"a\\u003db"'); + assert.equal(logValue('reason=forged'), '"reason\\u003dforged"'); + assert.equal(JSON.parse(logValue('reason=forged')), 'reason=forged', 'JSON.parse gives back exactly what was sent'); + const line = `[push-event-rejected] server=editor eventId=${logValue('reason=forged')} reason=duplicate`; + assert.deepEqual(line.match(/reason=(\S+)/)?.[1], 'duplicate', 'the first reason= on the line is the real one'); +}); + +test('logValue: a value that is not a string prints as its JSON text, and converting it never throws', () => { + assert.equal(logValue(5), '5'); + assert.equal(logValue(null), 'null'); + assert.equal(logValue({ toString: 1 }), '"{\\"toString\\":1}"'); + assert.equal(logValue({ a: 'b c' }), '"{\\"a\\":\\"b\\u0020c\\"}"'); + assert.equal(logValue(10n), '10'); + assert.equal(logValue({ toJSON() { throw new Error('no'); }, toString: 1 }), '"[object\\u0020Object]"'); + const { proxy, revoke } = Proxy.revocable({}, {}); + revoke(); + assert.equal(logValue(proxy), '[unprintable]', 'a value no reader can read'); + // JSON writes these as null, which would read as a missing id. + assert.equal(logValue(NaN), 'NaN'); + assert.equal(logValue(Infinity), 'Infinity'); + assert.equal(logValue(-Infinity), '-Infinity'); +}); + +test('logValue: a value over 256 units prints quoted as its first 256, then its full length', () => { + assert.equal(logValue('A'.repeat(256)), 'A'.repeat(256), 'up to the bound, a plain token is whole'); + assert.equal(logValue('A'.repeat(1_600_000)), `"${'A'.repeat(256)}"…(1600000)`); + assert.equal(logValue('a b'.repeat(200)), `${field('a b'.repeat(200).slice(0, 256))}…(600)`); + // Never half a surrogate pair: the head stops before one the bound would split. + assert.equal(logValue(`${'A'.repeat(255)}\u{1F600}B`), `"${'A'.repeat(255)}"…(258)`); + const json = JSON.stringify({ id: 'A'.repeat(1000) }); + assert.equal(logValue({ id: 'A'.repeat(1000) }), `${field(json.slice(0, 256))}…(${json.length})`); + assert.equal(logDetail('x '.repeat(200)), `${JSON.stringify('x '.repeat(128))}…(400)`, 'the host\'s tail is bounded too'); +}); + +test('logDetail: the host\'s message keeps its plain spaces and = and escapes everything else logValue does', () => { + assert.equal(logDetail('invalid content block'), '"invalid content block"'); + assert.equal(logDetail('x\nforged a=b'), '"x\\nforged a=b"'); + assert.equal(logDetail('a\u00a0b\u3164'), '"a\\u00a0b\\u3164"'); + assert.equal(logDetail('timeout'), 'timeout'); + assert.equal(logDetail('a=b'), 'a=b'); +}); + +test('logValue: anything else prints as one JSON string, every invisible character escaped', () => { + const cases: Array<[string, string]> = [ + ['', '""'], + ['a b', '"a\\u0020b"'], + ['x\n[forged] server=other', '"x\\n[forged]\\u0020server\\u003dother"'], + ['x\r\ny', '"x\\r\\ny"'], + ['\x1b[31mred', '"\\u001b[31mred"'], + ['a\x7fb', '"a\\u007fb"'], + ['a\u0085b', '"a\\u0085b"'], + ['a\u2028b', '"a\\u2028b"'], + ['\u202eevil', '"\\u202eevil"'], + ['a\u00a0b', '"a\\u00a0b"'], + ['a\u{e0041}b', '"a\\udb40\\udc41b"'], + ['a"b', '"a\\"b"'], + ['a\\b', '"a\\\\b"'], + ]; + for (const [value, shown] of cases) { + assert.equal(logValue(value), shown, JSON.stringify(value)); + assert.equal(JSON.parse(logValue(value)), value, 'JSON.parse gives back exactly what was sent'); + } +}); + +test('every rejection line of the ingress handlers stays one line, whatever the sender\'s ids hold', async (t) => { + const f = await fixture({ + featureSets: { doc: { description: 'doc', uses: ['pushEvents'] }, [FORGED_SET]: { description: 'forged', uses: ['pushEvents'] } }, + server: { enabledFeatureSets: ['*'] }, + }); + t.after(f.close); await f.register(FORGED_CHANNEL); + const lines = captureConsoleError(t); + + // channels/incoming: a coalesced item with no channelId, a malformed + // coalesced one, an empty uncoalesced one, and one for a channel that was + // never registered. + await f.send('channels/incoming', { messages: [ + { ...f.channel('c1', 'text', { initial: true }, FORGED_CHANNEL, FORGED), channelId: undefined }, + { ...f.channel('c2', '', { initial: true }, FORGED_CHANNEL, FORGED), content: ['not-a-block'] }, + { channelId: FORGED_CHANNEL, messageId: FORGED, timestamp: TS, author: { id: 'u', name: 'User' }, content: [] }, + { channelId: FORGED_SET, messageId: FORGED, timestamp: TS, author: { id: 'u', name: 'User' }, content: [{ type: 'text', text: 'hi' }] }, + ] }); + // push/event: an unknown feature set (which its reason names too), a + // malformed coalesced occurrence, an empty push, then a duplicate. + const push = { featureSet: 'doc', eventId: FORGED, timestamp: TS, payload: { content: [{ type: 'text', text: 'hi' }] } }; + await f.send('push/event', { ...push, featureSet: FORGED }); + await f.send('push/event', { ...f.params(FORGED, ''), featureSet: FORGED_SET, payload: { content: ['not-a-block'] } }); + await f.send('push/event', { ...push, payload: { content: [] } }); + await f.send('push/event', push); + await f.send('push/event', push); + // A coalesced push to a channel the server never declared names it. + await f.send('push/event', f.params('u1', 'hi', { initial: true, channelId: FORGED_SET, key: 'u1' })); + + const rejected = lines.filter((l) => /^\[(channel-incoming|push-event)-rejected\]/.test(l)); + assert(rejected.every((l) => !/[\n\r\u0085\u2028\u2029]/.test(l)), 'no rejection line breaks'); + assert.deepEqual(rejected, [ + `[channel-incoming-rejected] server=editor channel="" messageId=${SHOWN} reason=coalesce-invalid field=channelId: "a coalesced message needs a channelId and a messageId"`, + `[channel-incoming-rejected] server=editor channel=${field(FORGED_CHANNEL)} messageId=${SHOWN} reason=coalesce-invalid field=payload.content: "invalid content block"`, + `[channel-incoming-rejected] server=editor channel=${field(FORGED_CHANNEL)} messageId=${SHOWN} reason=empty-content`, + `[channel-incoming-rejected] server=editor channel=${field(FORGED_SET)} messageId=${SHOWN} reason=unknown-channel (not registered, §14.5)`, + `[push-event-rejected] server=editor eventId=${SHOWN} reason=${field(`Unknown feature set: ${FORGED}`)}`, + `[push-event-rejected] server=editor featureSet=${field(FORGED_SET)} eventId=${SHOWN} reason=coalesce-invalid field=payload.content: "invalid content block"`, + `[push-event-rejected] server=editor eventId=${SHOWN} reason=empty-content`, + `[push-event-rejected] server=editor eventId=${SHOWN} reason=duplicate`, + `[push-event-rejected] server=editor featureSet=doc eventId=u1 channel=${field(FORGED_SET)} reason=coalesce-invalid field=coalesce.channelId: "Unknown channel"`, + ]); + // Each line names its server and its reason once: the forged ids hold neither. + for (const line of rejected) { + assert.equal(line.split('server=').length - 1, 1, line); + assert.equal(line.split('reason=').length - 1, 1, line); + } +}); + +test('a push without an eventId prints it as "" and traces it as \'\' on each rejection path', async (t) => { + const f = await fixture(); t.after(f.close); + const lines = captureConsoleError(t); + const rejected: Array<{ eventId?: unknown; reason?: string }> = []; + f.framework.onTrace((e) => { if (e.type === 'mcpl:push-event-rejected') rejected.push(e); }); + const { coalesce: _coalesce, ...uncoalesced } = f.params('x', ''); + const empty = await f.send('push/event', { ...uncoalesced, eventId: undefined }); + const coalescedEmpty = await f.send('push/event', { ...f.params('x', ''), eventId: undefined }); + const unknownSet = await f.send('push/event', { ...uncoalesced, eventId: undefined, featureSet: 'nope', payload: { content: [{ type: 'text', text: 'hi' }] } }); + assert.deepEqual([empty.error?.code, coalescedEmpty.error?.code, unknownSet.error?.code], [-32602, -32602, -32003]); + assert.deepEqual(lines.filter((l) => l.startsWith('[push-event-rejected]')), [ + '[push-event-rejected] server=editor eventId="" reason=empty-content', + '[push-event-rejected] server=editor eventId="" reason=empty-content', + `[push-event-rejected] server=editor eventId="" reason=${field('Unknown feature set: nope')}`, + ]); + // A feature-set refusal has no trace; each empty-content refusal has one. + assert.deepEqual(rejected.map(({ eventId, reason }) => ({ eventId, reason })), [ + { eventId: '', reason: 'empty-content' }, + { eventId: '', reason: 'empty-content' }, + ]); +}); + +test('a feature set the host disables is named as one field on its line', async (t) => { + const lines = captureConsoleError(t); + const f = await fixture({ + featureSets: { doc: { description: 'doc', uses: ['pushEvents'] }, [FORGED_SET]: { description: 'forged', uses: [] } }, + server: { enabledFeatureSets: ['*'] }, + }); + t.after(f.close); + const disabled = lines.filter((l) => l.startsWith('[mcpl] editor/')); + assert.deepEqual(disabled, [`[mcpl] editor/${field(FORGED_SET)} disabled: invalid_uses (§6.4 — uses absent or empty) — overrides enabledFeatureSets`]); +}); + +test('a capability the host masks is named as one field on its line', async (t) => { + const lines = captureConsoleError(t); + const forgedCapability = 'cap\n[push-event-rejected] server=other eventId=y reason=duplicate'; + const f = await fixture({ + server: { enabledCapabilities: ['pushEvents', 'inferenceRequest', 'channels'] }, + mcpl: { [forgedCapability]: true }, + }); + t.after(f.close); + assert.deepEqual(lines.filter((l) => l.includes('capabilities masked by host config')), [ + `MCPL server "editor" capabilities masked by host config: ${field(forgedCapability)}`, + ]); +}); + +test('a tool\'s name and its declared classes are named as one field each', (t) => { + const lines = captureConsoleError(t); + const tool = 'mcpl--editor--x\n[push-event-rejected] server=other'; + parseDeclaredClasses({ 'mcpl/class': 'comms' }, tool); + parseDeclaredClasses({ 'mcpl/class': ['comms', 'x\n[forged] y'] }, tool); + assert.deepEqual(lines, [ + `[mcpl] ${field(tool)}: _meta["mcpl/class"] is not an array — treated as unclassed`, + `[mcpl] ${field(tool)}: unknown tool class ${field('x\n[forged] y')} ignored (RFC-008 §3)`, + ]); +}); + +test('speech routed into a closed channel names the channel as one field on each line', async (t) => { + const lines = captureConsoleError(t); + const server = { + grant: new CapabilityGrant(new Set(ALL_CAPABILITY_PATHS), []), + sendChannelsPublish: async () => ({ delivered: true }), + sendChannelsOpen: async () => ({}), + }; + const registry = new ChannelRegistry( + { getServer: () => server } as unknown as McplServerRegistry, {} as FeatureSetManager, () => {}, () => {}, {}, + ); + (registry as unknown as { channels: Map }).channels.set(`editor:${FORGED_CHANNEL}`, { + serverId: 'editor', descriptor: { id: FORGED_CHANNEL, type: 'discord', label: 'chat' }, open: false, + }); + const routed = await registry.routeSpeech('agent', 'hello', FORGED_CHANNEL); + assert.equal(routed?.delivered, true); + assert.deepEqual(lines.filter((l) => l.startsWith('[routeSpeech]')), [ + `[routeSpeech] agent: locus ${field(FORGED_CHANNEL)} was closed — opened by delivery (speech implies engagement)`, + `[routeSpeech] agent: routed 5 chars -> ${field(FORGED_CHANNEL)} (server=editor, delivered=true)`, + ]); +}); + +test('a refusal reaction with no server for its locus names the locus as one field', async (t) => { + const lines = captureConsoleError(t); + const locus = `discord:g1:${FORGED_CHANNEL}`; + const fakeThis = { + channelRegistry: { buildChannelContext: () => ({ incoming: { channelId: locus, messageId: 'm1' } }), getChannelServerId: () => undefined }, + mcplServerRegistry: { getServer: () => undefined }, + }; + const react = (AgentFramework.prototype as unknown as { reactToRefusal: (agent: string, category: string) => Promise }).reactToRefusal; + await react.call(fakeThis, 'agent', 'harmful'); + assert.deepEqual(lines, [`[inference-refusal] reaction skipped: no MCPL server for locus ${field(locus)} (agent=agent)`]); +}); + +test('a conversation agent that fails to spawn names its channel as one field', async (t) => { + const lines = captureConsoleError(t); + const traces: Array<{ type: string }> = []; + const fakeThis = { + conversationRouter: { route: () => ({ kind: 'spawn', agentName: 'conversation-chat-g1', generation: 1, trigger: true }), templateAgent: 'agent' }, + channelRegistry: { getDescriptor: () => undefined }, + createConversationAgent: async () => { throw new Error('no room'); }, + emitTrace: (e: { type: string }) => { traces.push(e); }, + }; + const route = (AgentFramework.prototype as unknown as { routeConversationIncoming: (event: unknown, metadata: unknown) => Promise }).routeConversationIncoming; + await route.call(fakeThis, { serverId: 'editor', channelId: FORGED_CHANNEL, messageId: 'm1', author: { id: 'u', name: 'User' }, content: [] }, {}); + assert.deepEqual(lines, [`Failed to spawn conversation agent for ${field(FORGED_CHANNEL)}: Error: no room`]); + assert.deepEqual(traces.map((e) => e.type), ['mcpl:conversation-spawn-failed']); +}); + +test('a coalesced batch whose conversation agent fails to spawn names its channel as one field', async (t) => { + const lines = captureConsoleError(t); + const fakeThis = { + agents: new Map(), + conversationRouter: { + getBinding: () => undefined, + route: () => ({ kind: 'spawn', agentName: 'conversation-chat-g1', generation: 1, trigger: true }), + }, + channelRegistry: { getDescriptor: () => undefined }, + createConversationAgent: async () => { throw new Error('no room'); }, + }; + const audience = (AgentFramework.prototype as unknown as { coalescedAudience: (occ: unknown) => Promise }).coalescedAudience; + const occ = { scope: { kind: 'channel', id: FORGED_CHANNEL }, event: { lane: 'channel', event: { metadata: {} } } }; + assert.deepEqual(await audience.call(fakeThis, occ), []); + assert.deepEqual(lines, [`[coalescing] could not spawn a conversation agent for ${field(FORGED_CHANNEL)}: Error: no room`]); +}); + +test('a refusal line prints for a channel\'s first refusal, then at most once a minute with how many were held back', () => { + let now = 1_000; + const lines = new RefusalLines(() => now); + assert.equal(lines.admit('editor', 'nowhere'), 0, 'the first prints'); + assert.equal(lines.admit('editor', 'nowhere'), null, 'a repeat within the minute is held back'); + assert.equal(lines.admit('editor', 'elsewhere'), 0, 'another channel\'s first prints'); + assert.equal(lines.admit('other', 'nowhere'), 0, 'so does another server\'s'); + now += 59_999; + assert.equal(lines.admit('editor', 'nowhere'), null, 'still within the minute'); + now += 1; + assert.equal(lines.admit('editor', 'nowhere'), 2, 'a minute on, it prints with the two held back'); + assert.equal(lines.admit('editor', 'nowhere'), null, 'and its next minute starts'); +}); + +test('a refusal line keeps servers and channels apart, and keys a channel as its line prints it', () => { + const lines = new RefusalLines(() => 0); + assert.equal(lines.admit('a:b', 'c'), 0); + assert.equal(lines.admit('a', 'b:c'), 0, 'a colon doesn\'t merge two server and channel pairs'); + assert.equal(lines.admit('a\u0000b', 'c'), 0); + assert.equal(lines.admit('a', 'b\u0000c'), 0, 'nor does a NUL'); + assert.equal(lines.admit('ab', 'c'), 0); + assert.equal(lines.admit('a', 'bc'), 0, 'nor do two pairs that run together alike'); + const head = 'x'.repeat(256); + assert.equal(lines.admit('editor', `${head}one`), 0); + assert.equal(lines.admit('editor', `${head}two`), null, 'ids cut to the same 256 units at the same length print alike, and share a record'); + assert.equal(lines.admit('editor', `${head}three`), 0, 'an id of another length prints otherwise, and has its own'); +}); + +test('refusal lines time their minute with the monotonic clock, not the wall clock', (t) => { + let now = 0; + t.mock.method(performance, 'now', () => now); + const lines = new RefusalLines(); + assert.equal(lines.admit('editor', 'nowhere'), 0); + assert.equal(lines.admit('editor', 'nowhere'), null); + now += 60_000; + assert.equal(lines.admit('editor', 'nowhere'), 1, 'a minute on the monotonic clock, the wall clock standing still'); +}); + +test('refusal lines cover at most 1,000 channels, evicting the least recently refused', () => { + const lines = new RefusalLines(() => 0); + assert.equal(lines.admit('editor', 'busy'), 0); + assert.equal(lines.admit('editor', 'quiet'), 0); + for (let i = 0; i < 997; i++) assert.equal(lines.admit('editor', `c${i}`), 0); + // 999 channels; busy, refused again, is now the most recent and quiet the least. + assert.equal(lines.admit('editor', 'busy'), null); + assert.equal(lines.admit('editor', 'c997'), 0, 'the thousandth channel'); + assert.equal(lines.admit('editor', 'c998'), 0, 'one more evicts quiet'); + assert.equal(lines.admit('editor', 'busy'), null, 'busy keeps its record'); + assert.equal(lines.admit('editor', 'quiet'), 0, 'quiet, evicted, prints again as new'); +}); + +for (const [name, eventId, shown] of [['its eventId', FORGED, SHOWN], ['a missing eventId as ""', undefined, '""']] as const) { + test(`a silent heartbeat names ${name} as one field`, async (t) => { + const f = await fixture({ + server: { id: 'heartbeat', enabledFeatureSets: ['heartbeat'] }, + featureSets: { heartbeat: { description: 'heartbeat', uses: ['pushEvents'] } }, + }); + t.after(f.close); + const lines = captureConsoleError(t); + const r = await f.send('push/event', { + featureSet: 'heartbeat', eventId, timestamp: TS, origin: { source: 'heartbeat', silent: true }, payload: { content: [] }, + }); + assert.equal(r.result?.accepted, true); + await f.framework.runUntilIdle(); + assert.deepEqual(lines.filter((l) => l.startsWith('[heartbeat]')), [`[heartbeat] heartbeat: accepted silent scheduled wake ${shown}`]); + }); +}