From c15df261d99258cffe2f97ad9b4b334518c421af Mon Sep 17 00:00:00 2001 From: Ruth-1049 Date: Wed, 7 Oct 2026 09:20:36 -0400 Subject: [PATCH 01/18] fix(failures): bound failure text in every sink; classify the [inference-failed] notice A failure's text is its source's Error.message, and a provider can echo the whole rejected request there. In the brosefo household (2026-10-07) an OpenAI-compatible 400 echoed ~1.7 MB; noteInferenceExhausted stored it in the resident's own context as the [inference-failed] marker (~200K tokens the resident then carried in every request), and wrote it to stderr, logs/failures.log, ops alerts and traces. Membrane now bounds its own errors (antra-tess/membrane #102), but only in releases that carry that bound and only for provider errors, so the framework bounds its sinks itself. Module helpers beside truncateReason: boundFailureText (head and tail around a stated-omission marker, result within max, cuts only toward omission so no lone surrogate; idempotent), boundProviderErrorCode, and describeFailure (one bounded line: name, type, HTTP status, provider code, retryable, bounded message) for logs that printed error objects. Printing a MembraneError prints its rawRequest, so a long system prompt at depth 1 was written out in full (June-1016's stderr probe, room-225 #43700). - noteInferenceExhausted: the marker carries a 600-char excerpt and names the classification ("the model call failed (invalid_request, HTTP 400)"); metadata adds errorType, retryable, httpStatus, providerErrorCode and, when cut, reasonChars. stderr and failures.log carry 2,000 chars plus the same fields; the stderr line adds type=/status=/code= labels. A small unclassified failure produces exactly the old marker, metadata, record and line. - The OverBudget breaker's message-text fallback applies only when the failure is unclassified (the case its comment names: a reason that lost its Error object). A classified 400 quoting "exceed hard budget" or "no summary covers" from the agent's own context no longer kicks the drain. - classifyInferenceError adds httpStatus and providerErrorCode; the inference:exhausted trace type declares them; emitTrace passes them to noteInferenceExhausted with the unbounded error (so reasonChars is true), then bounds the string error and stack fields of every trace event before fan-out (Basil's module:batch_hook_failed and later failure events included; Iris-1006, room-203 #43736). - logFailure bounds every top-level string; opsAlert bounds its message; logInference bounds the stored error (the request is already a blob). - Context maintenance bounds the error message it records and logs (format unchanged: maintenance-timer asserts the plain message). The drain-kick, marker-write and provider-cooldown-resume logs print describeFailure. - Out of scope by agreement: [discord-awareness] sites (Ada-1017, room-203 #43730), the speech-route-failed reason and [discord-send-failed] marker (Petra-1012, #43778), and raw-request retention. Tests: inference-failure-bounds (13), prototype-harness sinks plus a real framework/store/CM through the stream-error, stream-throw and stream-setup exhaustion paths (MembraneError and plain Error) and a maintenance failure. On main 64c480b: 12 fail, 1 pass (the small-reason control). Neighbours (observability, exhaustion-rewind, ops-alert, overbudget, maintenance-timer) pass. Full suite, node --test, concurrency 2, load ~20: 1311 tests, 1310 pass, 1 fail: mcpl-coalescing 34c, the known timing-bound case (66/66 in isolation right after). main: 1298/1298 in this run. Co-Authored-By: Claude Opus 5.5 --- ...ix-bounded-inference-failure-text.fixed.md | 6 + src/framework.ts | 171 +++++++- src/types/trace.ts | 7 + test/inference-failure-bounds.test.ts | 388 ++++++++++++++++++ 4 files changed, 555 insertions(+), 17 deletions(-) create mode 100644 changelog.d/fix-bounded-inference-failure-text.fixed.md create mode 100644 test/inference-failure-bounds.test.ts diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md new file mode 100644 index 000000000..3cc137d00 --- /dev/null +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -0,0 +1,6 @@ +- Failure text is bounded wherever the framework records it. A failure's text is its source's `Error.message`, and a provider can echo the whole rejected request there: in one household an OpenAI-compatible 400 echoed ~1.7 MB, and the framework stored it in the resident's own context as an `[inference-failed]` marker (roughly 200K tokens the resident then carried), wrote it to stderr and `logs/failures.log`, and traced it. + - The `[inference-failed]` marker carries a 600-character excerpt: head and tail around a marker stating how many of how many characters were omitted. It also names the classification when there is one ("the model call failed (invalid_request, HTTP 400) …"). Its metadata adds `errorType`, `retryable`, `httpStatus`, `providerErrorCode` and, when the reason was cut, `reasonChars`. A small unclassified failure produces exactly the marker it did before. + - stderr, `logs/failures.log` (every top-level string field), ops alerts, the inference log's `error`, and every trace event's `error` and `stack` strings carry at most 2,000 characters. `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`. The stderr line adds `type=… status=… code=…` labels when known. + - Failure logs that printed the error object (the OverBudget drain kick, the marker write, the provider-cooldown resume) print a bounded one-line projection instead, and context maintenance records and logs a bounded message. Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. + - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. +- Excerpts never split a surrogate pair, and bounding is independent of the membrane version: membrane bounds its own errors too, but only in releases that carry that bound, and only for provider errors. diff --git a/src/framework.ts b/src/framework.ts index c527c488f..43e1459e0 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -949,6 +949,79 @@ function truncateReason(reason: string, max = 160): string { return reason.length <= max ? reason : reason.slice(0, max) + '…'; } +/** + * Longest failure text the framework writes to stderr, logs/failures.log, + * trace events, ops alerts and the inference log. A failure's text is + * whatever its source put in `Error.message`, and a provider can echo the + * entire rejected request there (one OpenAI-compatible 400 echoed ~1.7 MB), + * so every sink that records failure text bounds it here. Membrane bounds its + * own errors too, but only in releases that carry that bound, and only for + * provider errors. + */ +const FAILURE_TEXT_MAX_CHARS = 2_000; +/** Longest failure reason written into an agent's own context (the + * `[inference-failed]` marker): enough for a provider's explanation, not a + * self-dump the agent then carries in every later request. */ +const FAILURE_MARKER_REASON_MAX_CHARS = 600; +/** Longest provider error code recorded verbatim; real codes are short tokens. */ +const PROVIDER_ERROR_CODE_MAX_CHARS = 128; + +const isLowSurrogate = (text: string, index: number): boolean => { + const code = text.charCodeAt(index); + return code >= 0xdc00 && code <= 0xdfff; +}; + +/** + * `text` when it fits within `max` characters; otherwise its head and tail + * around a marker stating how many of how many characters were omitted, the + * whole within `max`. Both cuts move only toward omission, so the result never + * holds half of a surrogate pair, and bounding bounded text returns it as is. + */ +function boundFailureText(text: string, max: number = FAILURE_TEXT_MAX_CHARS): string { + if (text.length <= max) return text; + const markerLength = ` …[${text.length} of ${text.length} characters omitted]… `.length; + const budget = Math.max(0, max - markerLength); + const tailLength = Math.floor(budget / 4); + let headEnd = budget - tailLength; + if (headEnd > 0 && isLowSurrogate(text, headEnd)) headEnd--; + let tailStart = text.length - tailLength; + if (tailStart < text.length && isLowSurrogate(text, tailStart)) tailStart++; + return `${text.slice(0, headEnd)} …[${tailStart - headEnd} of ${text.length} characters omitted]… ${text.slice(tailStart)}`; +} + +/** A provider error code, verbatim when token-sized; otherwise bounded. */ +function boundProviderErrorCode(code: unknown): string | undefined { + if (typeof code !== 'string') return undefined; + return boundFailureText(code, PROVIDER_ERROR_CODE_MAX_CHARS); +} + +/** + * One bounded line describing a failure, for logs that would otherwise print + * the error object. Printing the object shows every own field, and a + * MembraneError's `rawRequest` is the whole request that failed: a long system + * prompt at depth one is printed in full. The projection keeps what a reader + * needs (name, classification, status, provider code, message) and nothing + * else. + */ +function describeFailure(error: unknown): string { + try { + if (!(error instanceof Error)) return boundFailureText(String(error)); + const fields = error as Error & { + type?: unknown; httpStatus?: unknown; providerErrorCode?: unknown; retryable?: unknown; + }; + const classification = [ + typeof fields.type === 'string' ? fields.type : undefined, + typeof fields.httpStatus === 'number' ? `HTTP ${fields.httpStatus}` : undefined, + boundProviderErrorCode(fields.providerErrorCode), + typeof fields.retryable === 'boolean' ? `retryable=${fields.retryable}` : undefined, + ].filter((part): part is string => part !== undefined); + const head = classification.length > 0 ? `${error.name} (${classification.join(', ')})` : error.name; + return `${head}: ${boundFailureText(error.message)}`; + } catch { + return '[failure could not be described]'; + } +} + export class AgentFramework { private toolPresentations = new Map(); private presentationPreviews = new WeakMap(); @@ -2221,7 +2294,7 @@ export class AgentFramework { private startQueuedMaintenance(): void { if (this.maintenancePass || !this.running) return; const pass = this.runQueuedMaintenance().catch((error) => { - const reason = error instanceof Error ? error.message : String(error); + const reason = boundFailureText(error instanceof Error ? error.message : String(error)); console.error( '[context-maintenance] pass failed:', reason, @@ -2288,7 +2361,7 @@ export class AgentFramework { record.ticks++; } } catch (error) { - record.error = error instanceof Error ? error.message : String(error); + record.error = boundFailureText(error instanceof Error ? error.message : String(error)); console.error(`[context-maintenance] agent=${agent.name} failed:`, record.error); this.opsAlert( 'context-maintenance-failed', @@ -8951,7 +9024,7 @@ export class AgentFramework { await this.startAgentStream(agent, trigger, attempt, true); }).catch((error) => { this.releasePrimaryProviderGate(agent.name); - console.error(`[provider-cooldown] failed to resume primary for ${agent.name}:`, error); + console.error(`[provider-cooldown] failed to resume primary for ${agent.name}: ${describeFailure(error)}`); }); return; } @@ -11949,6 +12022,9 @@ export class AgentFramework { private logInference(entry: InferenceLogEntry): void { // Store large request/response as blobs const entryToStore = { ...entry }; + // The failure text is stored inline in every record; the request that + // produced it is already stored separately as a blob. + if (typeof entryToStore.error === 'string') entryToStore.error = boundFailureText(entryToStore.error); // Blob threshold: 10KB - typical context-heavy requests exceed this const BLOB_THRESHOLD = 10000; @@ -12524,6 +12600,10 @@ export class AgentFramework { (event.error as string) ?? 'unknown error', event.retryable as boolean | undefined, event.errorType as string | undefined, + { + httpStatus: event.httpStatus as number | undefined, + providerErrorCode: event.providerErrorCode as string | undefined, + }, ); } else if (event.type === 'inference:completed') { // A successful response — even mid-turn between tool calls — proves the @@ -12542,6 +12622,13 @@ export class AgentFramework { ...event, timestamp: Date.now(), } as TraceEvent; + // Listeners (web UI, subagent observers, host loggers) receive bounded + // failure text. An event's `error` and `stack` strings are whatever its + // source's Error carried, which for a provider failure can be an echo of + // the whole request. + const bounded = traceEvent as unknown as Record; + if (typeof bounded.error === 'string') bounded.error = boundFailureText(bounded.error); + if (typeof bounded.stack === 'string') bounded.stack = boundFailureText(bounded.stack); for (const listener of this.traceListeners) { try { @@ -12619,10 +12706,16 @@ export class AgentFramework { * and kind-specific fields (additive only — doctor parses by regex). */ private logFailure(record: Record): void { try { + // Every top-level string is bounded: `reason` is conventionally free + // text, and any caller's field may carry an error message. + const bounded: Record = {}; + for (const [key, value] of Object.entries(record)) { + bounded[key] = typeof value === 'string' ? boundFailureText(value) : value; + } mkdirSync('logs', { recursive: true }); appendFileSync( 'logs/failures.log', - JSON.stringify({ at: new Date().toISOString(), ...record }) + '\n', + JSON.stringify({ at: new Date().toISOString(), ...bounded }) + '\n', ); } catch { /* best-effort */ } } @@ -12655,9 +12748,10 @@ export class AgentFramework { private opsAlert( kind: string, agentName: string, - message: string, + rawMessage: string, opts?: { data?: Record; skipLog?: boolean }, ): void { + const message = boundFailureText(rawMessage); if (!opts?.skipLog) { this.logFailure({ agent: agentName, kind, reason: message, ...opts?.data }); } @@ -12740,9 +12834,17 @@ export class AgentFramework { * Deliberately NOT a message match: the message wording belongs to CM and * can be reworded without warning. */ - private classifyInferenceError(err: Error): { retryable?: boolean; errorType?: string } { + private classifyInferenceError(err: Error): { + retryable?: boolean; errorType?: string; httpStatus?: number; providerErrorCode?: string; + } { if (err instanceof MembraneError) { - return { retryable: err.retryable, errorType: err.type }; + const providerErrorCode = boundProviderErrorCode(err.providerErrorCode); + return { + retryable: err.retryable, + errorType: err.type, + ...(typeof err.httpStatus === 'number' ? { httpStatus: err.httpStatus } : {}), + ...(providerErrorCode !== undefined ? { providerErrorCode } : {}), + }; } if (err instanceof OverBudgetError || err.name === 'OverBudgetError') { return { errorType: 'over_budget' }; @@ -12770,25 +12872,55 @@ export class AgentFramework { private noteInferenceExhausted( agentName: string, - reason: string, + rawReason: string, retryable?: boolean, errorType?: string, + detail?: { httpStatus?: number; providerErrorCode?: string }, ): void { + // The reason is the failure's own message, and a provider can echo the + // whole rejected request in it: one household's [inference-failed] + // marker carried ~1.7 MB of its own request back into its context. Every + // sink below gets a bounded excerpt: logs and alerts FAILURE_TEXT_MAX_CHARS, + // the agent's own context FAILURE_MARKER_REASON_MAX_CHARS. The + // classification travels as structured fields beside the text. + const reason = boundFailureText(rawReason); + const markerReason = boundFailureText(rawReason, FAILURE_MARKER_REASON_MAX_CHARS); + const httpStatus = typeof detail?.httpStatus === 'number' ? detail.httpStatus : undefined; + const providerErrorCode = boundProviderErrorCode(detail?.providerErrorCode); + const classification: Record = { + ...(errorType !== undefined ? { errorType } : {}), + ...(retryable !== undefined ? { retryable } : {}), + ...(httpStatus !== undefined ? { httpStatus } : {}), + ...(providerErrorCode !== undefined ? { providerErrorCode } : {}), + ...(rawReason.length > reason.length ? { reasonChars: rawReason.length } : {}), + }; const streak = (this.consecutiveInferenceFailures.get(agentName) ?? 0) + 1; this.consecutiveInferenceFailures.set(agentName, streak); this.lastInferenceAt.set(agentName, { ...this.lastInferenceAt.get(agentName), failedAt: Date.now(), lastError: reason.slice(0, 300) }); // (1) Durable stderr line — works in headless/daemon mode with no client. - console.error(`[inference-failed] agent=${agentName} consecutive=${streak}: ${reason}`); + const labels = [ + errorType !== undefined ? `type=${errorType}` : undefined, + httpStatus !== undefined ? `status=${httpStatus}` : undefined, + providerErrorCode !== undefined ? `code=${providerErrorCode}` : undefined, + ].filter((label): label is string => label !== undefined); + console.error( + `[inference-failed] agent=${agentName} consecutive=${streak}` + + `${labels.length > 0 ? ` ${labels.join(' ')}` : ''}: ${reason}`, + ); // (1b) Machine-greppable durable record, independent of journald/unit log // redirects: logs/failures.log under the host's working directory. This is - // what connectome-doctor reads. Legacy fields kept; `kind` is additive. - this.logFailure({ agent: agentName, consecutive: streak, reason, kind: 'inference-exhausted' }); + // what connectome-doctor reads. Legacy fields kept; `kind` and the + // classification fields are additive. + this.logFailure({ agent: agentName, consecutive: streak, reason, kind: 'inference-exhausted', ...classification }); // (2) Agent-facing chronicle marker (no inference triggered → no loop). const agent = this.agents.get(agentName); if (agent && process.env.SUPPRESS_INFERENCE_FAILED_MARKER !== '1') { + const cause = [errorType, httpStatus !== undefined ? `HTTP ${httpStatus}` : undefined] + .filter((part): part is string => part !== undefined) + .join(', '); try { agent.getContextManager().addMessage( 'user', @@ -12796,15 +12928,15 @@ export class AgentFramework { type: 'text', text: `[inference-failed] Your previous turn did not complete: the model ` + - `call failed and produced no response, so nothing was sent. Reason: ` + - `${reason}. If this recurs with the same cause, change approach ` + + `call failed${cause ? ` (${cause})` : ''} and produced no response, so nothing was sent. Reason: ` + + `${markerReason}. If this recurs with the same cause, change approach ` + `rather than retrying identically (e.g. drop an oversized attachment ` + `or an unsupported setting).`, }], - { system: true, kind: 'inference-failed', reason, consecutive: streak }, + { system: true, kind: 'inference-failed', reason: markerReason, consecutive: streak, ...classification }, ); } catch (err) { - console.error(`[inference-failed] could not record chronicle marker for ${agentName}:`, err); + console.error(`[inference-failed] could not record chronicle marker for ${agentName}: ${describeFailure(err)}`); } } @@ -12823,10 +12955,15 @@ export class AgentFramework { // (e.g. a reason string that crossed a serialization boundary). It matches // CM's current OverBudgetError wording and MAY rot if CM rewords it — the // errorType gate is the one that's load-bearing. + // + // The fallback applies only to an unclassified reason. A classified + // failure (a provider's 400, say) already says what it is, and its + // message is the provider's text, which can quote anything, including + // these phrases from the agent's own context. const overBudget = errorType === 'over_budget' || errorType === 'context_refusal' || - /exceed hard budget|no summary covers/i.test(reason); + (errorType === undefined && /exceed hard budget|no summary covers/i.test(reason)); // Observability: a refused compile means the agent cannot think AT ALL // this turn — surface it on the ops-alert pipeline (ops:alert trace + // webhook → fleet-watch) immediately, not only at the hard-down streak. @@ -12854,7 +12991,7 @@ export class AgentFramework { } console.error(`[inference-failed] drain kicked for ${agentName} (OverBudget breaker, ${ticks} ticks)`); } catch (err) { - console.error(`[inference-failed] drain kick failed for ${agentName} after ${ticks} ticks:`, err); + console.error(`[inference-failed] drain kick failed for ${agentName} after ${ticks} ticks: ${describeFailure(err)}`); } finally { this.overBudgetDrainInFlight.delete(agentName); } diff --git a/src/types/trace.ts b/src/types/trace.ts index bf7b2715d..b1dc4c249 100644 --- a/src/types/trace.ts +++ b/src/types/trace.ts @@ -66,12 +66,15 @@ export type TraceEvent = | (TraceEventBase & { type: 'inference:failed'; agentName: string; + /** The failure's message, bounded as every trace event's `error` is (2,000 characters). */ error: string; + /** Bounded like `error`. */ stack?: string; }) | (TraceEventBase & { type: 'inference:exhausted'; agentName: string; + /** The failure's message, bounded as every trace event's `error` is (2,000 characters). */ error: string; /** Whether membrane classified the failure as retryable (observability). */ retryable?: boolean; @@ -80,6 +83,10 @@ export type TraceEvent = * The poison-history breaker fires only on 'invalid_request'. */ errorType?: string; + /** The provider's HTTP status, when the failure carried one. */ + httpStatus?: number; + /** The provider's own error code, when it sent one (at most 128 characters). */ + providerErrorCode?: string; }) // Streaming inference lifecycle diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts new file mode 100644 index 000000000..bcde9f5b9 --- /dev/null +++ b/test/inference-failure-bounds.test.ts @@ -0,0 +1,388 @@ +/** + * Failure text is bounded in every sink the framework writes it to. + * + * A failure's text is whatever its source put in `Error.message`, and a + * provider can echo the whole rejected request there. In one household an + * OpenAI-compatible 400 echoed ~1.7 MB, and the framework stored it in the + * resident's own context as an [inference-failed] marker, wrote it to + * stderr and failures.log, and traced it. These tests drive ~1 MB reasons + * through the real failure paths and through each sink, and check that what + * a small failure produced before is produced unchanged. + */ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { mkdtempSync, readFileSync, rmSync, existsSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { MembraneError } from '@animalabs/membrane'; +import type { NormalizedRequest, StreamEvent, YieldingStream } from '@animalabs/membrane'; +import type { ContextEntry, ContextLogView, ContextStrategy, MessageStoreView, ReadinessState, StrategyContext, TokenBudget } from '@animalabs/context-manager'; +import type { EventResponse, Module, ModuleContext, ProcessEvent, ProcessState, ToolCall, ToolDefinition, ToolResult } from '../src/index.js'; +import { AgentFramework } from '../src/index.js'; +import { AgentFramework as FrameworkClass } from '../src/framework.js'; +import { MockMembrane } from './helpers/mock-membrane.js'; + +const MEGA = 1_000_000; +/** ~1 MB of echoed request with a recognizable head and tail. */ +const echo = (n = MEGA) => `zz-head ${'e'.repeat(n)} zz-tail`; +const loneSurrogate = /[\uD800-\uDBFF](?![\uDC00-\uDFFF])|(? Promise; addMessage?: (p: string, c: any[], m: any) => void }) { + const fw = Object.create(FrameworkClass.prototype) as any; + fw.consecutiveInferenceFailures = new Map(); + fw.inferenceFailureEscalationThreshold = 3; + fw.exhaustionRewinds = new Map(); + fw.rewindEpisode = new Map(); + fw.lastInferenceAt = new Map(); + fw.pendingRequests = []; + fw.overBudgetDrainInFlight = new Set(); + fw.opsAlertLastSent = new Map(); + fw.opsAlertCooldownMs = 15 * 60_000; + const traces: any[] = []; + fw.traceListeners = [(e: any) => traces.push(e)]; + const logged: Array> = []; + fw.logFailure = (r: Record) => logged.push(r); + const markers: Array<{ text: string; meta: any }> = []; + let ticks = 0; + fw.agents = new Map([['cairn', { + name: 'cairn', + refusalHandling: { maxRewinds: 3 }, + getContextManager: () => ({ + addMessage: opts?.addMessage ?? ((_p: string, content: any[], meta: any) => { markers.push({ text: content[0].text, meta }); }), + tick: async () => { ticks++; await opts?.tick?.(); }, + }), + }]]); + const errs: string[] = []; + const orig = console.error; + console.error = (...a: unknown[]) => { errs.push(a.map(String).join(' ')); }; + const restore = () => { console.error = orig; }; + return { fw, traces, logged, markers, errs, restore, ticks: () => ticks }; +} + +const settle = () => new Promise((resolve) => setTimeout(resolve, 20)); + +test('a ~1 MB classified reason: bounded marker, logs and stderr, with the classification beside the text', () => { + const { fw, markers, logged, errs, restore } = makeHarness(); + const reason = `Bad request: ${echo()}`; + try { + fw.noteInferenceExhausted('cairn', reason, false, 'invalid_request', { httpStatus: 400, providerErrorCode: 'zz_bad_request' }); + } finally { restore(); } + + assert.equal(markers.length, 1); + const { text, meta } = markers[0]; + assert.ok(text.length < 1_200, `marker text is ${text.length} chars`); + assert.match(text, /^\[inference-failed\] Your previous turn did not complete: the model call failed \(invalid_request, HTTP 400\) and produced no response/); + assert.match(text, /Reason: Bad request: zz-head e+ …\[\d+ of \d+ characters omitted\]… e+ zz-tail\. If this recurs/); + assert.ok(meta.reason.length <= 600); + assert.equal(meta.kind, 'inference-failed'); + assert.equal(meta.errorType, 'invalid_request'); + assert.equal(meta.retryable, false); + assert.equal(meta.httpStatus, 400); + assert.equal(meta.providerErrorCode, 'zz_bad_request'); + assert.equal(meta.reasonChars, reason.length); + + assert.equal(logged.length, 1); + assert.ok((logged[0].reason as string).length <= 2_000); + assert.deepEqual( + { kind: logged[0].kind, errorType: logged[0].errorType, httpStatus: logged[0].httpStatus, providerErrorCode: logged[0].providerErrorCode, reasonChars: logged[0].reasonChars }, + { kind: 'inference-exhausted', errorType: 'invalid_request', httpStatus: 400, providerErrorCode: 'zz_bad_request', reasonChars: reason.length }, + ); + + const line = errs.find((e) => e.startsWith('[inference-failed]'))!; + assert.ok(line.length < 2_200, `stderr line is ${line.length} chars`); + assert.match(line, /^\[inference-failed\] agent=cairn consecutive=1 type=invalid_request status=400 code=zz_bad_request: Bad request: zz-head/); +}); + +test('a small unclassified reason produces exactly the marker it did before', () => { + const { fw, markers, logged, errs, restore } = makeHarness(); + try { + fw.noteInferenceExhausted('cairn', '400 image exceeds 5 MB'); + } finally { restore(); } + assert.equal(markers[0].text, + '[inference-failed] Your previous turn did not complete: the model call failed and produced no response, ' + + 'so nothing was sent. Reason: 400 image exceeds 5 MB. If this recurs with the same cause, change approach ' + + 'rather than retrying identically (e.g. drop an oversized attachment or an unsupported setting).'); + assert.deepEqual(markers[0].meta, { system: true, kind: 'inference-failed', reason: '400 image exceeds 5 MB', consecutive: 1 }); + assert.deepEqual(logged[0], { agent: 'cairn', consecutive: 1, reason: '400 image exceeds 5 MB', kind: 'inference-exhausted' }); + assert.ok(errs.includes('[inference-failed] agent=cairn consecutive=1: 400 image exceeds 5 MB')); +}); + +test('no excerpt splits a surrogate pair, at any cut position', () => { + for (const at of [599, 600, 601, 1_000, MEGA - 100, MEGA - 101]) { + const { fw, markers, logged, restore } = makeHarness(); + const reason = `${'x'.repeat(at)}😀${'x'.repeat(MEGA - at)}`; + try { + fw.noteInferenceExhausted('cairn', reason, false, 'invalid_request'); + } finally { restore(); } + assert.equal(loneSurrogate.test(markers[0].meta.reason), false); + assert.equal(loneSurrogate.test(logged[0].reason as string), false); + assert.ok(markers[0].meta.reason.length <= 600); + } +}); + +test('an over-budget phrase quoted inside a classified provider error does not kick the drain', async () => { + const quoted = `Bad request. Request: [inference-failed] ... Context would exceed hard budget ... no summary covers ${echo(10_000)}`; + const classified = makeHarness(); + try { + classified.fw.noteInferenceExhausted('cairn', quoted, false, 'invalid_request', { httpStatus: 400 }); + await settle(); + } finally { classified.restore(); } + assert.equal(classified.ticks(), 0, 'a classified 400 is not an over-budget compile'); + assert.equal(classified.traces.filter((t) => t.type === 'ops:alert' && t.kind === 'context-refusal').length, 0); + + // The fallback still serves the unclassified string it exists for. + const unclassified = makeHarness(); + try { + unclassified.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget (90000 > 80000)'); + await settle(); + } finally { unclassified.restore(); } + assert.equal(unclassified.ticks(), 8); +}); + +test('failure logs print a bounded projection, never the error object with its request', async () => { + const error = hugeProviderError(); + const kicked = makeHarness({ tick: async () => { throw error; } }); + try { + kicked.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { kicked.restore(); } + const kick = kicked.errs.find((e) => e.includes('drain kick failed'))!; + assert.ok(kick, 'the drain kick failure is logged'); + assert.ok(kick.length < 2_500, `drain kick log line is ${kick.length} chars`); + assert.match(kick, /MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/); + + const refused = makeHarness({ addMessage: () => { throw error; } }); + try { + refused.fw.noteInferenceExhausted('cairn', 'boom'); + } finally { refused.restore(); } + const markerFailure = refused.errs.find((e) => e.includes('could not record chronicle marker'))!; + assert.ok(markerFailure.length < 2_500, `marker failure log line is ${markerFailure.length} chars`); +}); + +test('emitTrace: listeners get bounded error and stack; the marker still learns the full length', () => { + const { fw, traces, markers, restore } = makeHarness(); + const error = `Bad request: ${echo()}`; + try { + fw.emitTrace({ type: 'inference:exhausted', agentName: 'cairn', error, retryable: false, errorType: 'invalid_request', httpStatus: 400, providerErrorCode: 'zz_bad_request' }); + fw.emitTrace({ type: 'inference:failed', agentName: 'cairn', error, stack: `Error: ${error}\n at zz (zz.js:1:1)` }); + // Any event's error string, including failure events added later. + fw.emitTrace({ type: 'module:batch_hook_failed', agentName: 'cairn', module: 'zz', error }); + } finally { restore(); } + const failureEvents = traces.filter((t) => typeof t.error === 'string'); + assert.equal(failureEvents.length, 3); + for (const event of failureEvents) { + assert.ok(event.error.length <= 2_000, `${event.type} error is ${event.error.length} chars`); + if (event.stack) assert.ok(event.stack.length <= 2_000); + } + assert.equal(markers[0].meta.reasonChars, error.length); + assert.equal(markers[0].meta.httpStatus, 400); + assert.equal(markers[0].meta.providerErrorCode, 'zz_bad_request'); +}); + +test('opsAlert bounds its message on the trace and the failures.log record', () => { + const { fw, traces, logged, restore } = makeHarness(); + try { + fw.opsAlert('hard-down', 'cairn', `3 consecutive inference failures. Last reason: ${echo()}`); + } finally { restore(); } + const alert = traces.find((t) => t.type === 'ops:alert'); + assert.ok(alert.message.length <= 2_000); + assert.ok((logged[0].reason as string).length <= 2_000); +}); + +test('logFailure bounds every top-level string it writes', () => { + const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); + const cwd = process.cwd(); + process.chdir(dir); + try { + const fw = Object.create(FrameworkClass.prototype) as any; + fw.logFailure({ agent: 'cairn', reason: echo(), note: echo(), consecutive: 1 }); + const line = readFileSync(join(dir, 'logs', 'failures.log'), 'utf-8').trim(); + assert.ok(line.length < 4_500, `failures.log line is ${line.length} chars`); + const record = JSON.parse(line); + assert.ok(record.reason.length <= 2_000 && record.note.length <= 2_000); + assert.equal(record.consecutive, 1); + } finally { + process.chdir(cwd); + rmSync(dir, { recursive: true, force: true }); + } +}); + +// --------------------------------------------------------------------------- +// The real failure paths, on a real framework, store and context manager. +// --------------------------------------------------------------------------- + +class InputModule implements Module { + readonly name = 'input'; + async start(_ctx: ModuleContext): Promise {} + async stop(): Promise {} + getTools(): ToolDefinition[] { return []; } + async handleToolCall(_call: ToolCall): Promise { return { success: false, isError: true, error: 'none' }; } + async onProcess(event: ProcessEvent, _state: ProcessState): Promise { + if (event.type !== 'external-message') return {}; + return { addMessages: [{ participant: 'User', content: [{ type: 'text', text: String(event.content) }] }], requestInference: true }; + } +} + +class ErrorEventStream implements YieldingStream { + isWaitingForTools = false; + pendingToolCallIds: string[] = []; + toolDepth = 0; + isCancelled = false; + constructor(private readonly error: Error) {} + provideToolResults(): void { throw new Error('not waiting'); } + cancel(): void { this.isCancelled = true; } + async *[Symbol.asyncIterator](): AsyncIterator { + yield { type: 'error', error: this.error } as StreamEvent; + } +} + +class ThrowingStream extends ErrorEventStream { + constructor(private readonly thrown: Error) { super(thrown); } + override async *[Symbol.asyncIterator](): AsyncIterator { + throw this.thrown; + } +} + +type Path = 'stream error event' | 'stream throws' | 'stream setup throws'; + +class FailingMembrane extends MockMembrane { + constructor(private readonly path: Path, private readonly make: (request: NormalizedRequest) => Error) { super(); } + override streamYielding(request: NormalizedRequest): YieldingStream { + this.calls.push(request); + const error = this.make(request); + if (this.path === 'stream setup throws') throw error; + return this.path === 'stream throws' ? new ThrowingStream(error) : new ErrorEventStream(error); + } +} + +async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => Error) { + const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); + const cwd = process.cwd(); + process.chdir(dir); + const errs: string[] = []; + const orig = console.error; + console.error = (...a: unknown[]) => { errs.push(a.map((x) => (typeof x === 'string' ? x : String(x))).join(' ')); }; + const membrane = new FailingMembrane(path, make); + const framework = await AgentFramework.create({ + storePath: join(dir, 'store.chronicle'), membrane: membrane.asMembrane(), + agents: [{ name: 'resident', model: 'test-model', systemPrompt: 'system' }], + modules: [new InputModule()], syncIntervalMs: 0, maintenanceIntervalMs: 0, + }); + const traces: any[] = []; + framework.onTrace((e) => traces.push(e)); + try { + framework.pushEvent({ type: 'external-message', source: 'test', content: 'hello', metadata: {} }); + await framework.runUntilIdle(); + const messages = framework.getAgent('resident')!.getContextManager().queryMessages({}).messages; + const markers = messages.filter((m) => (m.metadata as { kind?: string } | undefined)?.kind === 'inference-failed'); + const failuresLog = existsSync(join(dir, 'logs', 'failures.log')) ? readFileSync(join(dir, 'logs', 'failures.log'), 'utf-8') : ''; + const inferenceLogs = framework.queryInferenceLogs({}).entries; + return { markers, traces, errs, failuresLog, inferenceLogs, calls: membrane.calls.length }; + } finally { + await framework.stop(); + console.error = orig; + process.chdir(cwd); + rmSync(dir, { recursive: true, force: true }); + } +} + +for (const path of ['stream error event', 'stream throws', 'stream setup throws'] as const) { + test(`${path}: a ~1 MB provider error leaves a bounded, classified trail`, async () => { + const { markers, traces, errs, failuresLog, inferenceLogs } = await runFailingTurn(path, (request) => hugeProviderError(request)); + assert.equal(markers.length, 1, 'one failure marker'); + const text = (markers[0].content[0] as { text: string }).text; + assert.ok(text.length < 1_200, `marker is ${text.length} chars`); + assert.match(text, /model call failed \(invalid_request, HTTP 400\)/); + const meta = markers[0].metadata as Record; + assert.equal(meta.errorType, 'invalid_request'); + assert.equal(meta.httpStatus, 400); + assert.ok((meta.reasonChars as number) > MEGA); + + for (const event of traces.filter((t) => typeof t.error === 'string')) { + assert.ok(event.error.length <= 2_000, `${event.type} error is ${event.error.length} chars`); + } + assert.ok(traces.some((t) => t.type === 'inference:exhausted' && t.httpStatus === 400 && t.providerErrorCode === 'zz_bad_request')); + for (const line of failuresLog.trim().split('\n').filter(Boolean)) { + assert.ok(line.length < 4_500, `failures.log line is ${line.length} chars`); + } + assert.ok(failuresLog.includes('"errorType":"invalid_request"')); + const longest = errs.reduce((max, e) => Math.max(max, e.length), 0); + assert.ok(longest < 4_500, `longest stderr line is ${longest} chars`); + const loggedErrors = inferenceLogs.map(({ entry }) => entry.error).filter((e): e is string => typeof e === 'string'); + // A stream that never started writes no inference-log entry (as before); + // the two stream paths do. + if (path !== 'stream setup throws') assert.ok(loggedErrors.length > 0, 'the failed inference is logged'); + for (const logged of loggedErrors) { + assert.ok(logged.length <= 2_000, `inference log error is ${logged.length} chars`); + } + }); +} + +test('a ~1 MB plain Error (no classification) is bounded the same way', async () => { + const { markers, errs } = await runFailingTurn('stream throws', () => new Error(`socket said: ${echo()}`)); + assert.equal(markers.length, 1); + const text = (markers[0].content[0] as { text: string }).text; + assert.ok(text.length < 1_200); + assert.match(text, /model call failed and produced no response/); + const longest = errs.reduce((max, e) => Math.max(max, e.length), 0); + assert.ok(longest < 4_500, `longest stderr line is ${longest} chars`); +}); + +class HugeFailureStrategy implements ContextStrategy { + readonly name = 'huge-failure-maintenance-test'; + checkReadiness(): ReadinessState { return { ready: false, description: 'compression blocked' }; } + async tick(_ctx: StrategyContext): Promise { throw hugeProviderError(); } + select(_store: MessageStoreView, _log: ContextLogView, _budget: TokenBudget): ContextEntry[] { return []; } +} + +test('a ~1 MB maintenance failure: bounded record, ops alert and stderr', async () => { + const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); + const cwd = process.cwd(); + process.chdir(dir); + const errs: string[] = []; + const orig = console.error; + console.error = (...a: unknown[]) => { errs.push(a.map((x) => (typeof x === 'string' ? x : String(x))).join(' ')); }; + const framework = await AgentFramework.create({ + storePath: join(dir, 'store.chronicle'), membrane: new MockMembrane().asMembrane(), + agents: [{ name: 'agent', model: 'test-model', systemPrompt: 'test', strategy: new HugeFailureStrategy() }], + modules: [], syncIntervalMs: 0, maintenanceIntervalMs: 10, + }); + const traces: any[] = []; + framework.onTrace((e) => traces.push(e)); + try { + framework.start(); + const deadline = Date.now() + 5_000; + while (framework.getContextMaintenanceSnapshot().history.length === 0 && Date.now() < deadline) { + await new Promise((resolve) => setTimeout(resolve, 10)); + } + const record = framework.getContextMaintenanceSnapshot().history[0].agents[0]; + assert.ok(typeof record.error === 'string' && record.error.length <= 2_000, `maintenance record error is ${record.error?.length} chars`); + assert.match(record.error!, /^Bad request: zz-head/); + const alert = traces.find((t) => t.type === 'ops:alert' && t.kind === 'context-maintenance-failed'); + assert.ok(alert && alert.message.length <= 2_000); + const longest = errs.reduce((max, e) => Math.max(max, e.length), 0); + assert.ok(longest < 4_500, `longest stderr line is ${longest} chars`); + } finally { + await framework.stop(); + console.error = orig; + process.chdir(cwd); + rmSync(dir, { recursive: true, force: true }); + } +}); From 4f5ea6310d31f28ef01ea03286425e2f194a0cf0 Mon Sep 17 00:00:00 2001 From: Ruth-1049 Date: Wed, 7 Oct 2026 09:49:22 -0400 Subject: [PATCH 02/18] fix(failures): decide the breaker on the whole reason; bound every projection part; per-excerpt reasonChars Review (June-1016, room-225 #44777, #44825) reproduced three misses at c15df26: 1. The OverBudget fallback tested the bounded excerpt, so an unclassified long reason with "exceed hard budget" in the omitted middle no longer kicked the drain (8 ticks for the short control, 0 mid-long-message). Presentation bounds must never change a control decision: the fallback keeps the errorType === undefined guard and tests rawReason. 2. describeFailure bounded only message and provider code; error.name and a string type were unbounded (a 1 MB name gave a 1,000,076-char drain-kick line). Name and type are bounded to 128, and the composed line to 2,000. 3. reasonChars was keyed on the 2,000-char log excerpt, so a 1,000-char reason cut to a 599-char marker carried no length. Each sink now states the whole length exactly when its own excerpt was cut (cutAt). Test-observer correction from the same review: the stderr spy stringified arguments, hiding the object inspection that leaked rawRequest. The harness now keeps raw console.error arguments, and assertBoundedStrings requires every argument of the drain-kick and marker-write failure lines to be a bounded string, for both a ~1 MB message and a *short* message whose rawRequest.system is ~1 MB (load-bearing even with membrane's cap), plus an Error with a 1 MB name and type. Fragment scoped as asked: "the inference-failure pipeline", with the exclusions named (awareness sites, speech-route reason and send-failed marker, other module/hook logs that print error objects). Tests: inference-failure-bounds 14 (13 + per-excerpt reasonChars); against c15df26 the three extended/new cases fail and 11 pass. Neighbours 42/42. Full suite, concurrency 2, load ~20: 1312 tests, 1311 pass, 1 fail: mcpl-coalescing 34c's timing bound ("300 coalesced messages took 34439ms"). Co-Authored-By: Claude Opus 5.5 --- ...ix-bounded-inference-failure-text.fixed.md | 20 +++-- src/framework.ts | 19 +++-- test/inference-failure-bounds.test.ts | 82 +++++++++++++++---- 3 files changed, 91 insertions(+), 30 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index 3cc137d00..f93e4715c 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -1,6 +1,14 @@ -- Failure text is bounded wherever the framework records it. A failure's text is its source's `Error.message`, and a provider can echo the whole rejected request there: in one household an OpenAI-compatible 400 echoed ~1.7 MB, and the framework stored it in the resident's own context as an `[inference-failed]` marker (roughly 200K tokens the resident then carried), wrote it to stderr and `logs/failures.log`, and traced it. - - The `[inference-failed]` marker carries a 600-character excerpt: head and tail around a marker stating how many of how many characters were omitted. It also names the classification when there is one ("the model call failed (invalid_request, HTTP 400) …"). Its metadata adds `errorType`, `retryable`, `httpStatus`, `providerErrorCode` and, when the reason was cut, `reasonChars`. A small unclassified failure produces exactly the marker it did before. - - stderr, `logs/failures.log` (every top-level string field), ops alerts, the inference log's `error`, and every trace event's `error` and `stack` strings carry at most 2,000 characters. `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`. The stderr line adds `type=… status=… code=…` labels when known. - - Failure logs that printed the error object (the OverBudget drain kick, the marker write, the provider-cooldown resume) print a bounded one-line projection instead, and context maintenance records and logs a bounded message. Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. - - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. -- Excerpts never split a surrogate pair, and bounding is independent of the membrane version: membrane bounds its own errors too, but only in releases that carry that bound, and only for provider errors. +- The inference-failure pipeline bounds the failure text it records. A failure's text is its source's `Error.message`, and a provider can echo the whole rejected request there: in one household an OpenAI-compatible 400 echoed ~1.7 MB, and the framework stored it in the resident's own context as an `[inference-failed]` marker (roughly 200K tokens the resident then carried), wrote it to stderr and `logs/failures.log`, and traced it. + - The `[inference-failed]` marker carries a 600-character excerpt: head and tail around a marker stating how many of how many characters were omitted. It also names the classification when there is one ("the model call failed (invalid_request, HTTP 400) …"). Its metadata adds `errorType`, `retryable`, `httpStatus` and `providerErrorCode`, plus `reasonChars` whenever the marker's excerpt was cut. A small unclassified failure produces exactly the marker it did before. + - These sinks carry at most 2,000 characters: + - the exhaustion stderr line, which adds `type=… status=… code=…` labels when known; + - every top-level string field of `logs/failures.log` records; + - ops alert messages; + - the inference log's `error`; + - every trace event's `error` and `stack` strings. + + `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. + - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed. They now print a bounded one-line projection: name, classification, status, provider code and message, each part bounded. Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. Context maintenance records and logs a bounded message, in its existing format. + - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. +- Excerpts never split a surrogate pair. This bound is independent of the membrane version: membrane bounds its own errors too, but only in releases that carry that bound, and only for provider errors. +- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as delivery evidence), and other module or hook logs that print error objects. diff --git a/src/framework.ts b/src/framework.ts index 43e1459e0..a0b178b58 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1009,14 +1009,16 @@ function describeFailure(error: unknown): string { const fields = error as Error & { type?: unknown; httpStatus?: unknown; providerErrorCode?: unknown; retryable?: unknown; }; + // Every component is remote or caller-supplied text, the name included. const classification = [ - typeof fields.type === 'string' ? fields.type : undefined, + typeof fields.type === 'string' ? boundFailureText(fields.type, PROVIDER_ERROR_CODE_MAX_CHARS) : undefined, typeof fields.httpStatus === 'number' ? `HTTP ${fields.httpStatus}` : undefined, boundProviderErrorCode(fields.providerErrorCode), typeof fields.retryable === 'boolean' ? `retryable=${fields.retryable}` : undefined, ].filter((part): part is string => part !== undefined); - const head = classification.length > 0 ? `${error.name} (${classification.join(', ')})` : error.name; - return `${head}: ${boundFailureText(error.message)}`; + const name = boundFailureText(String(error.name), PROVIDER_ERROR_CODE_MAX_CHARS); + const head = classification.length > 0 ? `${name} (${classification.join(', ')})` : name; + return boundFailureText(`${head}: ${boundFailureText(String(error.message))}`); } catch { return '[failure could not be described]'; } @@ -12892,8 +12894,10 @@ export class AgentFramework { ...(retryable !== undefined ? { retryable } : {}), ...(httpStatus !== undefined ? { httpStatus } : {}), ...(providerErrorCode !== undefined ? { providerErrorCode } : {}), - ...(rawReason.length > reason.length ? { reasonChars: rawReason.length } : {}), }; + // Each excerpt says how long the whole was when it was cut. + const cutAt = (excerpt: string): Record => + excerpt === rawReason ? {} : { reasonChars: rawReason.length }; const streak = (this.consecutiveInferenceFailures.get(agentName) ?? 0) + 1; this.consecutiveInferenceFailures.set(agentName, streak); this.lastInferenceAt.set(agentName, { ...this.lastInferenceAt.get(agentName), failedAt: Date.now(), lastError: reason.slice(0, 300) }); @@ -12913,7 +12917,7 @@ export class AgentFramework { // redirects: logs/failures.log under the host's working directory. This is // what connectome-doctor reads. Legacy fields kept; `kind` and the // classification fields are additive. - this.logFailure({ agent: agentName, consecutive: streak, reason, kind: 'inference-exhausted', ...classification }); + this.logFailure({ agent: agentName, consecutive: streak, reason, kind: 'inference-exhausted', ...classification, ...cutAt(reason) }); // (2) Agent-facing chronicle marker (no inference triggered → no loop). const agent = this.agents.get(agentName); @@ -12933,7 +12937,7 @@ export class AgentFramework { `rather than retrying identically (e.g. drop an oversized attachment ` + `or an unsupported setting).`, }], - { system: true, kind: 'inference-failed', reason: markerReason, consecutive: streak, ...classification }, + { system: true, kind: 'inference-failed', reason: markerReason, consecutive: streak, ...classification, ...cutAt(markerReason) }, ); } catch (err) { console.error(`[inference-failed] could not record chronicle marker for ${agentName}: ${describeFailure(err)}`); @@ -12963,7 +12967,8 @@ export class AgentFramework { const overBudget = errorType === 'over_budget' || errorType === 'context_refusal' || - (errorType === undefined && /exceed hard budget|no summary covers/i.test(reason)); + // Decided on the whole reason: presentation bounds never change it. + (errorType === undefined && /exceed hard budget|no summary covers/i.test(rawReason)); // Observability: a refused compile means the agent cannot think AT ALL // this turn — surface it on the ops-alert pipeline (ops:alert trace + // webhook → fleet-watch) immediately, not only at the hard-down streak. diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index bcde9f5b9..84f238ca5 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -70,10 +70,13 @@ function makeHarness(opts?: { tick?: () => Promise; addMessage?: (p: strin }), }]]); const errs: string[] = []; + // The arguments as passed: printing an object (rather than a string built + // from it) is what wrote a MembraneError's whole rawRequest to stderr. + const rawArgs: unknown[][] = []; const orig = console.error; - console.error = (...a: unknown[]) => { errs.push(a.map(String).join(' ')); }; + console.error = (...a: unknown[]) => { rawArgs.push(a); errs.push(a.map(String).join(' ')); }; const restore = () => { console.error = orig; }; - return { fw, traces, logged, markers, errs, restore, ticks: () => ticks }; + return { fw, traces, logged, markers, errs, rawArgs, restore, ticks: () => ticks }; } const settle = () => new Promise((resolve) => setTimeout(resolve, 20)); @@ -154,26 +157,71 @@ test('an over-budget phrase quoted inside a classified provider error does not k await settle(); } finally { unclassified.restore(); } assert.equal(unclassified.ticks(), 8); -}); -test('failure logs print a bounded projection, never the error object with its request', async () => { - const error = hugeProviderError(); - const kicked = makeHarness({ tick: async () => { throw error; } }); + // ...decided on the whole reason, even where the excerpts omit the phrase. + const long = makeHarness(); try { - kicked.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + long.fw.noteInferenceExhausted('cairn', `${'x'.repeat(50_000)} Context would exceed hard budget ${'y'.repeat(50_000)}`); await settle(); - } finally { kicked.restore(); } - const kick = kicked.errs.find((e) => e.includes('drain kick failed'))!; - assert.ok(kick, 'the drain kick failure is logged'); - assert.ok(kick.length < 2_500, `drain kick log line is ${kick.length} chars`); - assert.match(kick, /MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/); + } finally { long.restore(); } + assert.equal(long.ticks(), 8, 'presentation bounds never change the decision'); +}); - const refused = makeHarness({ addMessage: () => { throw error; } }); +test('each excerpt states the whole length when it was cut, and only then', () => { + const { fw, markers, logged, restore } = makeHarness(); + const reason = `zz-reason ${'r'.repeat(990)}`; // 1,000 chars: cut for the marker, whole in the logs try { - refused.fw.noteInferenceExhausted('cairn', 'boom'); - } finally { refused.restore(); } - const markerFailure = refused.errs.find((e) => e.includes('could not record chronicle marker'))!; - assert.ok(markerFailure.length < 2_500, `marker failure log line is ${markerFailure.length} chars`); + fw.noteInferenceExhausted('cairn', reason, false, 'invalid_request'); + } finally { restore(); } + assert.ok(markers[0].meta.reason.length <= 600); + assert.equal(markers[0].meta.reasonChars, 1_000); + assert.equal(logged[0].reason, reason); + assert.equal('reasonChars' in logged[0], false); +}); + +/** Every argument a failure log passed is a bounded string: no object for the runtime to inspect. */ +function assertBoundedStrings(rawArgs: unknown[][], marker: string): string { + const call = rawArgs.find((args) => typeof args[0] === 'string' && (args[0] as string).includes(marker)); + assert.ok(call, `a log line containing "${marker}"`); + for (const arg of call!) assert.equal(typeof arg, 'string', `${marker}: an argument was a ${typeof arg}`); + const line = call!.join(' '); + assert.ok(line.length < 2_500, `${marker} line is ${line.length} chars`); + return line; +} + +test('failure logs print a bounded projection, never the error object with its request', async () => { + // A short message with a huge request: Membrane's message cap does not help + // here; only not printing the object does. + const short = new MembraneError({ + type: 'invalid_request', retryable: false, httpStatus: 400, providerErrorCode: 'zz_bad_request', + message: 'Bad request: zz-short', rawError: { status: 400 }, rawRequest: { system: echo() }, + }); + for (const error of [hugeProviderError(), short]) { + const kicked = makeHarness({ tick: async () => { throw error; } }); + try { + kicked.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { kicked.restore(); } + const kick = assertBoundedStrings(kicked.rawArgs, 'drain kick failed'); + assert.match(kick, /MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-/); + + const refused = makeHarness({ addMessage: () => { throw error; } }); + try { + refused.fw.noteInferenceExhausted('cairn', 'boom'); + } finally { refused.restore(); } + assertBoundedStrings(refused.rawArgs, 'could not record chronicle marker'); + } + + // Every component of the projection is bounded, the name and type included. + const named = new Error('zz-short'); + named.name = `Zz${'N'.repeat(MEGA)}`; + (named as Error & { type?: string }).type = `t${'T'.repeat(MEGA)}`; + const odd = makeHarness({ tick: async () => { throw named; } }); + try { + odd.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { odd.restore(); } + assertBoundedStrings(odd.rawArgs, 'drain kick failed'); }); test('emitTrace: listeners get bounded error and stack; the marker still learns the full length', () => { From d38eca114439a90b0a0029420f811dd53a6445cd Mon Sep 17 00:00:00 2001 From: Ruth-1049 Date: Wed, 7 Oct 2026 10:24:33 -0400 Subject: [PATCH 03/18] docs(failures): state the stderr and projection bounds exactly Review (June-1016, room-225 #45257), wording only: - The 2,000-character cap applies to the reason excerpt in the exhaustion stderr line; the line also carries the agent, the streak and the type/status/code labels. - describeFailure returns a bounded string, one line unless the message itself contains newlines; the fragment no longer calls it "one-line". No code change (a doc comment and the changelog fragment). tsc clean. Co-Authored-By: Claude Opus 5.5 --- changelog.d/fix-bounded-inference-failure-text.fixed.md | 4 ++-- src/framework.ts | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index f93e4715c..50abfe14d 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -1,14 +1,14 @@ - The inference-failure pipeline bounds the failure text it records. A failure's text is its source's `Error.message`, and a provider can echo the whole rejected request there: in one household an OpenAI-compatible 400 echoed ~1.7 MB, and the framework stored it in the resident's own context as an `[inference-failed]` marker (roughly 200K tokens the resident then carried), wrote it to stderr and `logs/failures.log`, and traced it. - The `[inference-failed]` marker carries a 600-character excerpt: head and tail around a marker stating how many of how many characters were omitted. It also names the classification when there is one ("the model call failed (invalid_request, HTTP 400) …"). Its metadata adds `errorType`, `retryable`, `httpStatus` and `providerErrorCode`, plus `reasonChars` whenever the marker's excerpt was cut. A small unclassified failure produces exactly the marker it did before. - These sinks carry at most 2,000 characters: - - the exhaustion stderr line, which adds `type=… status=… code=…` labels when known; + - the reason excerpt in the exhaustion stderr line (the line also carries the agent, the streak and `type=… status=… code=…` labels when known); - every top-level string field of `logs/failures.log` records; - ops alert messages; - the inference log's `error`; - every trace event's `error` and `stack` strings. `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. - - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed. They now print a bounded one-line projection: name, classification, status, provider code and message, each part bounded. Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. Context maintenance records and logs a bounded message, in its existing format. + - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed. They now print a bounded projection instead of the object: name, classification, status, provider code and message, each part bounded and the whole within 2,000 characters (one line unless the message itself has newlines). Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. Context maintenance records and logs a bounded message, in its existing format. - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - Excerpts never split a surrogate pair. This bound is independent of the membrane version: membrane bounds its own errors too, but only in releases that carry that bound, and only for provider errors. - Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as delivery evidence), and other module or hook logs that print error objects. diff --git a/src/framework.ts b/src/framework.ts index a0b178b58..bd5158cf3 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -996,8 +996,8 @@ function boundProviderErrorCode(code: unknown): string | undefined { } /** - * One bounded line describing a failure, for logs that would otherwise print - * the error object. Printing the object shows every own field, and a + * A bounded string describing a failure, for logs that would otherwise print + * the error object (one line unless the message itself has newlines). Printing the object shows every own field, and a * MembraneError's `rawRequest` is the whole request that failed: a long system * prompt at depth one is printed in full. The projection keeps what a reader * needs (name, classification, status, provider code, message) and nothing From bbb4f8b7b5547264ed19b037be6e9a3f72fbda88 Mon Sep 17 00:00:00 2001 From: Greta-1453 Date: Wed, 7 Oct 2026 11:55:10 -0400 Subject: [PATCH 04/18] test(failures): sweep a surrogate pair across every cut, not six fixed positions Review (greptile-apps[bot], PR #249, discussion_r4208547998): the surrogate test's six emoji positions (599, 600, 601, 1,000, length-100, length-101 of a 1,000,002-character reason) straddle none of the cuts boundFailureText makes. The cuts are not at the bound: the omission marker and the tail share it, so at that length the 600-character excerpt is cut at 418 and 999,863 and the 2,000-character excerpt at 1,468 and 999,513. With both surrogate checks removed the test still passed (reproduced at d38eca1 by editing the compiled helper). The test now puts a pair at every position of a 2,500-character reason, longer than both bounds, so that some position straddles each cut wherever the layout puts it; deriving or hard-coding the four positions would go vacuous again if the head/tail split or the marker changed, and a sweep of a ~1 MB reason would be quadratic. Each excerpt (the marker's 600 and the log's 2,000) is checked for a lone surrogate, for its length bound, and for the stated omission (head + tail + stated count = the whole length): a cut moved off a pair omits one more character than the unmoved cut would, and the marker has to say so. Evidence, each a mutation of the compiled boundFailureText at this head run against the new test: - head check removed: fails (pair at 422, 600-character excerpt: a lone surrogate; the head cut there is 423) - tail check removed: fails (pair at 2009, 2,000-character excerpt; the tail cut there is 2,010) - both removed: fails - head cut, or tail cut, moved toward inclusion: fails (601 characters) - omission counted before the cuts move (text.length - budget): fails (the stated omission) - unmutated: passes inference-failure-bounds 14/14 at this head; tsc clean. Against main 64c480b the new file still gives 13 fail and 1 pass (the small-reason control), as the PR body states. Test-only: no source or changelog change. Co-Authored-By: Claude Opus 5.5 --- test/inference-failure-bounds.test.ts | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index 84f238ca5..29cd5f8dc 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -128,15 +128,24 @@ test('a small unclassified reason produces exactly the marker it did before', () }); test('no excerpt splits a surrogate pair, at any cut position', () => { - for (const at of [599, 600, 601, 1_000, MEGA - 100, MEGA - 101]) { + // A pair at every position of a reason longer than both bounds, so that + // wherever the cuts fall, some position straddles each of them. + const length = 2_500; + const omission = new RegExp(` …\\[(\\d+) of ${length} characters omitted\\]… `); + for (let at = 0; at <= length - 2; at++) { const { fw, markers, logged, restore } = makeHarness(); - const reason = `${'x'.repeat(at)}😀${'x'.repeat(MEGA - at)}`; try { - fw.noteInferenceExhausted('cairn', reason, false, 'invalid_request'); + fw.noteInferenceExhausted('cairn', `${'x'.repeat(at)}😀${'x'.repeat(length - 2 - at)}`, false, 'invalid_request'); } finally { restore(); } - assert.equal(loneSurrogate.test(markers[0].meta.reason), false); - assert.equal(loneSurrogate.test(logged[0].reason as string), false); - assert.ok(markers[0].meta.reason.length <= 600); + for (const [excerpt, max] of [[markers[0].meta.reason as string, 600], [logged[0].reason as string, 2_000]] as const) { + const where = `pair at ${at}, ${max}-character excerpt`; + assert.equal(loneSurrogate.test(excerpt), false, `${where}: a lone surrogate`); + assert.ok(excerpt.length <= max, `${where}: ${excerpt.length} characters`); + // A cut moved off a pair omits one more character, and says so. + const stated = omission.exec(excerpt); + assert.ok(stated, `${where}: no omission marker`); + assert.equal(excerpt.length - stated[0].length + Number(stated[1]), length, `${where}: the stated omission`); + } } }); From 9c2794f9372bfeb68cc3803afa8c8d47aa1c1e02 Mon Sep 17 00:00:00 2001 From: Ada-1017 Date: Sun, 11 Oct 2026 10:34:13 -0400 Subject: [PATCH 05/18] fix(failures): every cut through boundFailureText, from the whole text; bound hold reasons, alert data, the ephemeral rejection The haiku sweep of #249 (sw-af249, Oscar-1808's merge procedure in room-203; verdicts room-422 #70811, correction #70815) found 25 issues at bbb4f8b; 21 are fix-now. This commit is all of them. Code: - I1, I10, I19: the four plain slices of failure text go through boundFailureText at their own bounds, each cut from the WHOLE reason so its marker states the whole length: the rewind marker (160, REWIND_MARKER_REASON_MAX_CHARS; truncateReason is gone), lastInference.lastError and the compile-refused alert (300, FAILURE_SUMMARY_MAX_CHARS), the ops webhook (500 of the alert's raw message, OPS_WEBHOOK_MESSAGE_MAX_CHARS). quarantinePoisonedHistory now takes the whole reason. The hard-down alert's excerpt leaves room for its prefix (2,000 - prefix), so opsAlert's own bound never cuts it a second time with a marker stating the composed length. - I8: a cut moves only when it would separate a pair: splitsPair checks text[i-1] high AND text[i] low, at both cuts. The old head check moved back on any low surrogate, so a pair followed by a stray low at the cut kept the pair's high half alone. - I2, I7: the provider-cooldown reason is bounded where the hold is recorded: consultProviderHold's reason (host's own or the error's message), the acceleration cooldown's fallback, and the recovery record. The stderr lines and the status snapshot's cooldownReason read those. - I3: boundFailureFields bounds a record field by field: a string to 2,000, an Error to describeFailure (serialising one writes its own fields, rawRequest among them), any other value kept when its JSON fits 2,000, else its JSON bounded; a value JSON.stringify throws on becomes describeFailure's text (before, a circular value lost the whole failures.log record). logFailure uses it for every field; opsAlert bounds data once with it and passes the bounded copy to logFailure and the ops:alert trace (which got the caller's raw object). - I5: settleAgent rejects an ephemeral run with boundFailureText(error). - I11: errorType bounded to 128 in classifyInferenceError, the one source of every emit site's classification, so the trace, the marker and the logs agree with describeFailure. (The verdict said "where noteInferenceExhausted receives it"; at the classifier the trace listeners get the bounded type too.) - I13: the three converted logs (drain kick, marker write, cooldown resume) print describeFailureWithFrames: the projection, then the stack from its first `at` line, bounded to 2,000, on the lines below. Reading the stack is guarded (V8 formats it lazily with the current name, so a throwing name getter throws there too). - I18: noteInferenceExhausted describes a non-string reason (describeFailure) instead of throwing before anything is recorded. - I25: classifyInferenceError recognises a MembraneError by name as well (the host supplies config.membrane, so another copy's class can't match instanceof) and reads its fields as data. Text: - I9: markers already stored keep their size until folded or removed. - I12: describeFailure is one line unless one of its parts has newlines. - I16: see the next commit (the fragment keeps the reason, with its source). - I17: "about 200K tokens, by the household's notes" (their incident notes, quoted in snag:connectome-rollback-sent-awareness-reactions-to- other-peoples-messages). - I21: FAILURE_TEXT_MAX_CHARS names the inference-failure pipeline's sinks, not every sink. - I24: "This bound doesn't depend on membrane bounding its own errors"; the claim about membrane's own bound is gone (0.5.86 passes stream error messages through unbounded). - trace.ts: errorType at most 128; ops:alert message at most 2,000 and data bounded as the failures.log record. Tests (inference-failure-bounds, 14 -> 22): - The surrogate sweep now checks every cut against the whole text (assertCut: the text's own head and tail, the stated whole length and omission, no pair separated): the marker 600, failures.log 2,000, lastError 300, the rewind marker 160 (stubbed shed), the hard-down alert, the compile-refused alert 300 and the webhook 500 (stubbed fetch), for a pair at every position of a 2,500-character reason and for a pair followed by a stray low surrogate (I1, I8). - New: a non-string reason (I18); a thrown non-Error and a throwing name getter (I14); provider holds with a reason-less host hold, a host reason of its own on extension, the acceleration cooldown, and a failed resume with frames (I2, I7, I13); a failed maintenance pass (I15); alert data field by field (I3); logFailure with an Error, a large object and a circular value (I3); an oversized provider code (I4); a MembraneError from another copy, classified by name, with a 1 MB type bounded (I25, I11); an ephemeral run's rejection (I5). - The real-framework console spies keep raw arguments and assert that no object is printed (I23); the projection test asserts the frames. - assertBoundedStrings allows 4,500 (projection + frames, 2,000 each). Against bbb4f8b's source the new file gives 7 fail, 14 pass (the other new cases pin behaviour bbb4f8b already had). Mutations of the compiled helper and sinks, each killed by its test: the old head check, the old rewind/lastError/compile-refused/webhook slices, the rewind cut from the 2,000 excerpt, the old hard-down composition, raw trace data, top-level- only logFailure, no/unbounded frames, an unbounded non-Error branch, a changed fallback, the unbounded pass reason, no classifier code cap, no name fallback, an unbounded type, an unbounded rejection, each of the three hold-reason bounds, no non-string guard, and an object printed on the real exhaustion path (6 tests fail). Co-Authored-By: Claude Opus 5.5 --- ...ix-bounded-inference-failure-text.fixed.md | 23 +- src/framework.ts | 184 ++++++--- src/types/trace.ts | 9 +- test/inference-failure-bounds.test.ts | 379 ++++++++++++++++-- 4 files changed, 494 insertions(+), 101 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index 50abfe14d..a269926f6 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -1,14 +1,19 @@ -- The inference-failure pipeline bounds the failure text it records. A failure's text is its source's `Error.message`, and a provider can echo the whole rejected request there: in one household an OpenAI-compatible 400 echoed ~1.7 MB, and the framework stored it in the resident's own context as an `[inference-failed]` marker (roughly 200K tokens the resident then carried), wrote it to stderr and `logs/failures.log`, and traced it. - - The `[inference-failed]` marker carries a 600-character excerpt: head and tail around a marker stating how many of how many characters were omitted. It also names the classification when there is one ("the model call failed (invalid_request, HTTP 400) …"). Its metadata adds `errorType`, `retryable`, `httpStatus` and `providerErrorCode`, plus `reasonChars` whenever the marker's excerpt was cut. A small unclassified failure produces exactly the marker it did before. +- The inference-failure pipeline bounds the failure text it records. A failure's text is its source's `Error.message`, and a provider can echo the whole rejected request there: in one household an OpenAI-compatible 400 echoed ~1.7 MB, and the framework stored it in the resident's own context as an `[inference-failed]` marker (about 200K tokens, by the household's notes, which the resident then carried), wrote it to stderr and `logs/failures.log`, and traced it. + - Every cut of failure text follows one rule: the text's head and tail around a marker stating how many of how many characters were omitted. Each sink cuts the whole text, so its marker states the whole length, and no cut separates a surrogate pair. + - The `[inference-failed]` marker carries a 600-character excerpt. It also names the classification when there is one ("the model call failed (invalid_request, HTTP 400) …"). Its metadata adds `errorType`, `retryable`, `httpStatus` and `providerErrorCode`, plus `reasonChars` whenever the marker's excerpt was cut. A small unclassified failure produces exactly the marker it did before. Markers already stored keep their size until they're folded or removed. + - The rewind marker keeps 160 characters of the reason; an agent's `lastInference.lastError` and the compile-refused ops alert keep 300; the ops webhook posts 500 characters of the alert's message. - These sinks carry at most 2,000 characters: - the reason excerpt in the exhaustion stderr line (the line also carries the agent, the streak and `type=… status=… code=…` labels when known); - - every top-level string field of `logs/failures.log` records; - - ops alert messages; + - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as it is when its JSON fits, otherwise its JSON, bounded; + - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is; - the inference log's `error`; - - every trace event's `error` and `stack` strings. + - every trace event's `error` and `stack` strings; + - the provider cooldown's reason, in its stderr lines and the status snapshot's `cooldownReason`; + - the error an ephemeral run (`runEphemeralToCompletion`) rejects with. - `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. - - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed. They now print a bounded projection instead of the object: name, classification, status, provider code and message, each part bounded and the whole within 2,000 characters (one line unless the message itself has newlines). Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. Context maintenance records and logs a bounded message, in its existing format. + `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. The error type and the provider code are recorded to at most 128 characters each. + - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed. They now print a bounded projection instead: name, classification, status, provider code and message, each part bounded and the whole within 2,000 characters, on one line unless one of its parts has newlines, as a message can. The stack's frames follow on the lines below, also bounded to 2,000 characters. Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. Context maintenance records and logs a bounded message, in its existing format. - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. -- Excerpts never split a surrogate pair. This bound is independent of the membrane version: membrane bounds its own errors too, but only in releases that carry that bound, and only for provider errors. -- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as delivery evidence), and other module or hook logs that print error objects. + - A `MembraneError` from another copy of membrane is classified by its name as well as by its class, since the host supplies the `Membrane` instance. Its failure is classified as one from the framework's own copy is, rather than left unclassified. +- This bound doesn't depend on membrane bounding its own errors. +- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (out of scope here, by agreement), and other module or hook logs that print error objects. diff --git a/src/framework.ts b/src/framework.ts index bd5158cf3..a066f6572 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -942,40 +942,52 @@ interface EphemeralRun { toolCallsCount: number; } -/** Cap an API error message for inline use in a rewind marker: keep enough to - * identify the failure class without pasting a wall of provider JSON into the - * agent's context. */ -function truncateReason(reason: string, max = 160): string { - return reason.length <= max ? reason : reason.slice(0, max) + '…'; -} - /** - * Longest failure text the framework writes to stderr, logs/failures.log, - * trace events, ops alerts and the inference log. A failure's text is - * whatever its source put in `Error.message`, and a provider can echo the - * entire rejected request there (one OpenAI-compatible 400 echoed ~1.7 MB), - * so every sink that records failure text bounds it here. Membrane bounds its - * own errors too, but only in releases that carry that bound, and only for - * provider errors. + * Longest failure text the inference-failure pipeline writes to one sink: the + * reason in the exhaustion stderr line, a field of a logs/failures.log record, + * an ops alert's message, the inference log's `error`, and a trace event's + * `error` and `stack`. A failure's text is whatever its source put in + * `Error.message`, and a provider can echo the entire rejected request there + * (one OpenAI-compatible 400 echoed ~1.7 MB). The sinks with shorter bounds + * name them below, and every cut goes through boundFailureText. This bound + * doesn't depend on membrane bounding its own errors. */ const FAILURE_TEXT_MAX_CHARS = 2_000; /** Longest failure reason written into an agent's own context (the * `[inference-failed]` marker): enough for a provider's explanation, not a * self-dump the agent then carries in every later request. */ const FAILURE_MARKER_REASON_MAX_CHARS = 600; -/** Longest provider error code recorded verbatim; real codes are short tokens. */ +/** Longest failure reason in the rewind marker, also the agent's own context: + * enough to identify the failure class without a wall of provider JSON. */ +const REWIND_MARKER_REASON_MAX_CHARS = 160; +/** Longest failure reason in an agent's status (`lastInference.lastError`) and + * in the compile-refused ops alert. */ +const FAILURE_SUMMARY_MAX_CHARS = 300; +/** Longest alert message posted to the ops webhook. */ +const OPS_WEBHOOK_MESSAGE_MAX_CHARS = 500; +/** Longest provider error code recorded verbatim; real codes are short tokens. + * A failure's name and type are bounded the same way. */ const PROVIDER_ERROR_CODE_MAX_CHARS = 128; +const isHighSurrogate = (text: string, index: number): boolean => { + const code = text.charCodeAt(index); + return code >= 0xd800 && code <= 0xdbff; +}; const isLowSurrogate = (text: string, index: number): boolean => { const code = text.charCodeAt(index); return code >= 0xdc00 && code <= 0xdfff; }; +/** Whether a cut before `index` would separate the halves of a surrogate pair. */ +const splitsPair = (text: string, index: number): boolean => + index > 0 && index < text.length && isHighSurrogate(text, index - 1) && isLowSurrogate(text, index); /** * `text` when it fits within `max` characters; otherwise its head and tail * around a marker stating how many of how many characters were omitted, the - * whole within `max`. Both cuts move only toward omission, so the result never - * holds half of a surrogate pair, and bounding bounded text returns it as is. + * whole within `max`. A cut that would separate a surrogate pair moves toward + * omission, so the result never holds half of a pair the text held whole, and + * bounding bounded text returns it as is. Each sink cuts the whole text, so + * its marker states the whole length. */ function boundFailureText(text: string, max: number = FAILURE_TEXT_MAX_CHARS): string { if (text.length <= max) return text; @@ -983,9 +995,9 @@ function boundFailureText(text: string, max: number = FAILURE_TEXT_MAX_CHARS): s const budget = Math.max(0, max - markerLength); const tailLength = Math.floor(budget / 4); let headEnd = budget - tailLength; - if (headEnd > 0 && isLowSurrogate(text, headEnd)) headEnd--; + if (splitsPair(text, headEnd)) headEnd--; let tailStart = text.length - tailLength; - if (tailStart < text.length && isLowSurrogate(text, tailStart)) tailStart++; + if (splitsPair(text, tailStart)) tailStart++; return `${text.slice(0, headEnd)} …[${tailStart - headEnd} of ${text.length} characters omitted]… ${text.slice(tailStart)}`; } @@ -997,7 +1009,8 @@ function boundProviderErrorCode(code: unknown): string | undefined { /** * A bounded string describing a failure, for logs that would otherwise print - * the error object (one line unless the message itself has newlines). Printing the object shows every own field, and a + * the error object; it is one line unless one of its parts has newlines, as a + * message can. Printing the object shows every own field, and a * MembraneError's `rawRequest` is the whole request that failed: a long system * prompt at depth one is printed in full. The projection keeps what a reader * needs (name, classification, status, provider code, message) and nothing @@ -1024,6 +1037,44 @@ function describeFailure(error: unknown): string { } } +/** + * describeFailure, then the error's stack frames (the stack from its first + * `at` line), bounded, on the lines below: for a log of a failure the + * framework's own code may have thrown, where the frames say where. The leak + * the projection closes was the object's own fields, not its stack. + */ +function describeFailureWithFrames(error: unknown): string { + let frames: string | undefined; + try { + const stack = error instanceof Error ? error.stack : undefined; + const start = typeof stack === 'string' ? stack.search(/^\s+at /m) : -1; + if (start >= 0) frames = boundFailureText(stack!.slice(start)); + } catch { /* the projection alone */ } + const described = describeFailure(error); + return frames === undefined ? described : `${described}\n${frames}`; +} + +/** + * A failure record's fields, each bounded, for logs/failures.log and the + * ops:alert trace: a string to FAILURE_TEXT_MAX_CHARS; an Error to its + * projection, since serialising one writes its own fields, a MembraneError's + * whole `rawRequest` among them; any other value as it is when its JSON fits + * FAILURE_TEXT_MAX_CHARS, and otherwise its JSON, bounded. + */ +function boundFailureFields(record: Record): Record { + const bounded: Record = {}; + for (const [key, value] of Object.entries(record)) { + if (typeof value === 'string') bounded[key] = boundFailureText(value); + else if (value instanceof Error) bounded[key] = describeFailure(value); + else { + let json: string | undefined; + try { json = JSON.stringify(value); } catch { bounded[key] = describeFailure(value); continue; } + bounded[key] = json === undefined || json.length <= FAILURE_TEXT_MAX_CHARS ? value : boundFailureText(json); + } + } + return bounded; +} + export class AgentFramework { private toolPresentations = new Map(); private presentationPreviews = new WeakMap(); @@ -2190,8 +2241,11 @@ export class AgentFramework { try { const hold = this.providerHoldHook(error, agentName, { model: this.agents.get(agentName)?.model }); if (!hold || !Number.isFinite(hold.holdMs) || hold.holdMs <= 0) return undefined; + // The reason is printed, kept in the cooldown and shown in the status + // snapshot (cooldownReason); without the host's own, it is the error's + // message, which can echo the whole request. return { holdMs: Math.min(PROVIDER_ACCELERATION_MAX_COOLDOWN_MS, Math.max(1_000, hold.holdMs)), - reason: typeof hold.reason === 'string' && hold.reason ? hold.reason : error.message }; + reason: boundFailureText(typeof hold.reason === 'string' && hold.reason ? hold.reason : String(error.message)) }; } catch (err) { console.error(`[provider-cooldown] providerHold hook threw for ${agentName}; treating as no hold:`, err); return undefined; @@ -2228,7 +2282,7 @@ export class AgentFramework { if (existing) clearTimeout(existing.timer); const timer = setTimeout(() => this.releaseProviderAccelerationCooldown(agent.name), delayMs); timer.unref?.(); this.providerAccelerationCooldowns.set(agent.name, { startedAt: existing?.startedAt ?? now, - until: now + delayMs, timer, heldRequests: held, reason: hostHold?.reason ?? error.message, + until: now + delayMs, timer, heldRequests: held, reason: hostHold?.reason ?? boundFailureText(String(error.message)), failures: (existing?.failures ?? 0) + 1, ...(hostHold ? { hostHoldError: error } : {}), ...(auxiliary && (!existing || existing.auxiliaryOrigin) ? { auxiliaryOrigin: true } : {}) }); if (auxiliary && !existing) { @@ -2238,7 +2292,7 @@ export class AgentFramework { } const gate = this.providerGate(agent.name); gate.primaryPending = true; this.providerAccelerationRecoveries.set(agent.name, { startedAt: existing?.startedAt ?? now, - failures: (existing?.failures ?? 0) + 1, heldRequests: held.length, reason: error.message }); + failures: (existing?.failures ?? 0) + 1, heldRequests: held.length, reason: boundFailureText(String(error.message)) }); console.error(`[provider-cooldown] agent=${agent.name} ` + `${hostHold ? `host hold (${hostHold.reason})` : 'organization acceleration 429'} — ` + `holding primary/auxiliary for ${delayMs}ms; ${held.length} request(s) retained`); @@ -4266,7 +4320,8 @@ export class AgentFramework { if (!run) return; run.lastActivity = Date.now(); if (outcome.stopReason === 'exhausted') { - run.settle.reject(new Error(outcome.error ?? 'Unknown error')); + // The caller may log or relay the message, which can echo the whole request. + run.settle.reject(new Error(boundFailureText(outcome.error ?? 'Unknown error'))); return; } run.settle.resolve({ @@ -9026,7 +9081,7 @@ export class AgentFramework { await this.startAgentStream(agent, trigger, attempt, true); }).catch((error) => { this.releasePrimaryProviderGate(agent.name); - console.error(`[provider-cooldown] failed to resume primary for ${agent.name}: ${describeFailure(error)}`); + console.error(`[provider-cooldown] failed to resume primary for ${agent.name}: ${describeFailureWithFrames(error)}`); }); return; } @@ -12708,12 +12763,10 @@ export class AgentFramework { * and kind-specific fields (additive only — doctor parses by regex). */ private logFailure(record: Record): void { try { - // Every top-level string is bounded: `reason` is conventionally free - // text, and any caller's field may carry an error message. - const bounded: Record = {}; - for (const [key, value] of Object.entries(record)) { - bounded[key] = typeof value === 'string' ? boundFailureText(value) : value; - } + // Every field is bounded: `reason` is conventionally free text, and any + // caller's field may carry an error message, or an Error whose own + // fields include the whole request. + const bounded = boundFailureFields(record); mkdirSync('logs', { recursive: true }); appendFileSync( 'logs/failures.log', @@ -12754,10 +12807,13 @@ export class AgentFramework { opts?: { data?: Record; skipLog?: boolean }, ): void { const message = boundFailureText(rawMessage); + // The caller's data goes to failures.log and to trace listeners, bounded + // the same way for both. + const data = opts?.data === undefined ? undefined : boundFailureFields(opts.data); if (!opts?.skipLog) { - this.logFailure({ agent: agentName, kind, reason: message, ...opts?.data }); + this.logFailure({ agent: agentName, kind, reason: message, ...data }); } - this.emitTrace({ type: 'ops:alert', kind, agentName, message, data: opts?.data }); + this.emitTrace({ type: 'ops:alert', kind, agentName, message, data }); const hook = process.env.CONNECTOME_OPS_WEBHOOK; if (!hook) return; @@ -12770,7 +12826,7 @@ export class AgentFramework { method: 'POST', headers: { 'content-type': 'application/json' }, body: JSON.stringify({ - content: `\u{1F6A8} **${agentName}** ${kind}: ${message.slice(0, 500)}`, + content: `\u{1F6A8} **${agentName}** ${kind}: ${boundFailureText(rawMessage, OPS_WEBHOOK_MESSAGE_MAX_CHARS)}`, }), }).catch((err) => console.error( `[ops-alert] webhook post failed (${key}):`, @@ -12839,12 +12895,20 @@ export class AgentFramework { private classifyInferenceError(err: Error): { retryable?: boolean; errorType?: string; httpStatus?: number; providerErrorCode?: string; } { - if (err instanceof MembraneError) { - const providerErrorCode = boundProviderErrorCode(err.providerErrorCode); + // By name too, as below: the host supplies the Membrane instance + // (config.membrane), so its errors can come from another copy of the + // package, whose class this instanceof doesn't match. The fields are read + // as data, and the type is bounded like describeFailure's, for every sink + // the classification reaches (the trace, the marker, the logs). + if (err instanceof MembraneError || err.name === 'MembraneError') { + const fields = err as Error & { + retryable?: unknown; type?: unknown; httpStatus?: unknown; providerErrorCode?: unknown; + }; + const providerErrorCode = boundProviderErrorCode(fields.providerErrorCode); return { - retryable: err.retryable, - errorType: err.type, - ...(typeof err.httpStatus === 'number' ? { httpStatus: err.httpStatus } : {}), + ...(typeof fields.retryable === 'boolean' ? { retryable: fields.retryable } : {}), + ...(typeof fields.type === 'string' ? { errorType: boundFailureText(fields.type, PROVIDER_ERROR_CODE_MAX_CHARS) } : {}), + ...(typeof fields.httpStatus === 'number' ? { httpStatus: fields.httpStatus } : {}), ...(providerErrorCode !== undefined ? { providerErrorCode } : {}), }; } @@ -12882,11 +12946,19 @@ export class AgentFramework { // The reason is the failure's own message, and a provider can echo the // whole rejected request in it: one household's [inference-failed] // marker carried ~1.7 MB of its own request back into its context. Every - // sink below gets a bounded excerpt: logs and alerts FAILURE_TEXT_MAX_CHARS, - // the agent's own context FAILURE_MARKER_REASON_MAX_CHARS. The - // classification travels as structured fields beside the text. - const reason = boundFailureText(rawReason); - const markerReason = boundFailureText(rawReason, FAILURE_MARKER_REASON_MAX_CHARS); + // sink below gets an excerpt cut from the whole reason at its own bound + // (boundFailureText, so its marker states the whole length): the stderr + // line, failures.log and the hard-down alert FAILURE_TEXT_MAX_CHARS, the + // [inference-failed] marker FAILURE_MARKER_REASON_MAX_CHARS, the status's + // lastError and the compile-refused alert FAILURE_SUMMARY_MAX_CHARS, and + // the rewind marker REWIND_MARKER_REASON_MAX_CHARS. The classification + // travels as structured fields beside the text. + // + // A reason that isn't a string (the stream paths always pass a message) + // is described rather than allowed to throw before anything is recorded. + const wholeReason: string = typeof rawReason === 'string' ? rawReason : describeFailure(rawReason); + const reason = boundFailureText(wholeReason); + const markerReason = boundFailureText(wholeReason, FAILURE_MARKER_REASON_MAX_CHARS); const httpStatus = typeof detail?.httpStatus === 'number' ? detail.httpStatus : undefined; const providerErrorCode = boundProviderErrorCode(detail?.providerErrorCode); const classification: Record = { @@ -12897,10 +12969,10 @@ export class AgentFramework { }; // Each excerpt says how long the whole was when it was cut. const cutAt = (excerpt: string): Record => - excerpt === rawReason ? {} : { reasonChars: rawReason.length }; + excerpt === wholeReason ? {} : { reasonChars: wholeReason.length }; const streak = (this.consecutiveInferenceFailures.get(agentName) ?? 0) + 1; this.consecutiveInferenceFailures.set(agentName, streak); - this.lastInferenceAt.set(agentName, { ...this.lastInferenceAt.get(agentName), failedAt: Date.now(), lastError: reason.slice(0, 300) }); + this.lastInferenceAt.set(agentName, { ...this.lastInferenceAt.get(agentName), failedAt: Date.now(), lastError: boundFailureText(wholeReason, FAILURE_SUMMARY_MAX_CHARS) }); // (1) Durable stderr line — works in headless/daemon mode with no client. const labels = [ @@ -12940,7 +13012,7 @@ export class AgentFramework { { system: true, kind: 'inference-failed', reason: markerReason, consecutive: streak, ...classification, ...cutAt(markerReason) }, ); } catch (err) { - console.error(`[inference-failed] could not record chronicle marker for ${agentName}: ${describeFailure(err)}`); + console.error(`[inference-failed] could not record chronicle marker for ${agentName}: ${describeFailureWithFrames(err)}`); } } @@ -12968,7 +13040,7 @@ export class AgentFramework { errorType === 'over_budget' || errorType === 'context_refusal' || // Decided on the whole reason: presentation bounds never change it. - (errorType === undefined && /exceed hard budget|no summary covers/i.test(rawReason)); + (errorType === undefined && /exceed hard budget|no summary covers/i.test(wholeReason)); // Observability: a refused compile means the agent cannot think AT ALL // this turn — surface it on the ops-alert pipeline (ops:alert trace + // webhook → fleet-watch) immediately, not only at the hard-down streak. @@ -12978,7 +13050,7 @@ export class AgentFramework { this.opsAlert( 'context-refusal', agentName, - `compile refused (${errorType ?? 'unclassified'}): ${reason.slice(0, 300)} — ` + + `compile refused (${errorType ?? 'unclassified'}): ${boundFailureText(wholeReason, FAILURE_SUMMARY_MAX_CHARS)} — ` + `drain breaker ${agent ? 'kicking' : 'unavailable (no agent handle)'}; ` + `if this persists, raise contextBudgetTokens or overBudgetGraceRatio.`, { skipLog: true }, @@ -12996,7 +13068,7 @@ export class AgentFramework { } console.error(`[inference-failed] drain kicked for ${agentName} (OverBudget breaker, ${ticks} ticks)`); } catch (err) { - console.error(`[inference-failed] drain kick failed for ${agentName} after ${ticks} ticks: ${describeFailure(err)}`); + console.error(`[inference-failed] drain kick failed for ${agentName} after ${ticks} ticks: ${describeFailureWithFrames(err)}`); } finally { this.overBudgetDrainInFlight.delete(agentName); } @@ -13013,10 +13085,13 @@ export class AgentFramework { // Ops alert (webhook + ops:alert trace), throttled per (agent, kind) — // a hard-down agent re-posts every ~15 min, not on every failed retry. // failures.log already got the per-exhaustion record above. + // The excerpt leaves room for the prefix, so the alert's own bound + // never cuts it a second time. + const hardDown = `${streak} consecutive inference failures. Last reason: `; this.opsAlert( 'hard-down', agentName, - `${streak} consecutive inference failures. Last reason: ${reason}`, + hardDown + boundFailureText(wholeReason, FAILURE_TEXT_MAX_CHARS - hardDown.length), { skipLog: true }, ); @@ -13030,7 +13105,7 @@ export class AgentFramework { // rejecting your history" marker. `retryable` is kept only for the trace. void retryable; if (errorType === 'invalid_request' && agent) { - this.quarantinePoisonedHistory(agent, reason); + this.quarantinePoisonedHistory(agent, wholeReason); } } } @@ -13048,7 +13123,7 @@ export class AgentFramework { * At the cap (or with nothing left to shed) it stops — the agent stays up * and hard-down logging continues, but no further history is consumed. */ - private quarantinePoisonedHistory(agent: Agent, reason: string): void { + private quarantinePoisonedHistory(agent: Agent, wholeReason: string): void { const cap = Math.max(1, Math.min(10, agent.refusalHandling?.maxRewinds ?? 3)); const used = this.exhaustionRewinds.get(agent.name) ?? 0; if (used >= cap) { @@ -13069,7 +13144,8 @@ export class AgentFramework { } this.exhaustionRewinds.set(agent.name, used + 1); - const count = this.updateRewindMarker(agent, truncateReason(reason), 'inference-failure'); + const count = this.updateRewindMarker( + agent, boundFailureText(wholeReason, REWIND_MARKER_REASON_MAX_CHARS), 'inference-failure'); console.error( `[inference-rewind] agent=${agent.name} auto-quarantined ${rec.descriptor} ` + `(${count} turn(s) shed this episode, cap ${cap}) after non-retryable ` + diff --git a/src/types/trace.ts b/src/types/trace.ts index b1dc4c249..a188521ca 100644 --- a/src/types/trace.ts +++ b/src/types/trace.ts @@ -79,8 +79,9 @@ export type TraceEvent = /** Whether membrane classified the failure as retryable (observability). */ retryable?: boolean; /** - * The membrane error type (e.g. 'invalid_request', 'auth', 'context_length'). - * The poison-history breaker fires only on 'invalid_request'. + * The membrane error type (e.g. 'invalid_request', 'auth', 'context_length'), + * at most 128 characters. The poison-history breaker fires only on + * 'invalid_request'. */ errorType?: string; /** The provider's HTTP status, when the failure carried one. */ @@ -461,8 +462,10 @@ export type TraceEvent = kind: string; /** Agent name, or a server/component id for non-agent alerts (e.g. mcpl-down). */ agentName: string; + /** At most 2,000 characters. */ message: string; - /** Kind-specific structured payload (mirrors the failures.log record). */ + /** Kind-specific structured payload (mirrors the failures.log record), + * bounded field by field as that record is. */ data?: Record; }) diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index 29cd5f8dc..cb87e445a 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -17,7 +17,7 @@ import { join } from 'node:path'; import { MembraneError } from '@animalabs/membrane'; import type { NormalizedRequest, StreamEvent, YieldingStream } from '@animalabs/membrane'; import type { ContextEntry, ContextLogView, ContextStrategy, MessageStoreView, ReadinessState, StrategyContext, TokenBudget } from '@animalabs/context-manager'; -import type { EventResponse, Module, ModuleContext, ProcessEvent, ProcessState, ToolCall, ToolDefinition, ToolResult } from '../src/index.js'; +import type { ErrorPolicy, EventResponse, Module, ModuleContext, ProcessEvent, ProcessState, ToolCall, ToolDefinition, ToolResult } from '../src/index.js'; import { AgentFramework } from '../src/index.js'; import { AgentFramework as FrameworkClass } from '../src/framework.js'; import { MockMembrane } from './helpers/mock-membrane.js'; @@ -127,25 +127,97 @@ test('a small unclassified reason produces exactly the marker it did before', () assert.ok(errs.includes('[inference-failed] agent=cairn consecutive=1: 400 image exceeds 5 MB')); }); -test('no excerpt splits a surrogate pair, at any cut position', () => { - // A pair at every position of a reason longer than both bounds, so that - // wherever the cuts fall, some position straddles each of them. +const isHigh = (text: string, index: number) => { const code = text.charCodeAt(index); return code >= 0xd800 && code <= 0xdbff; }; +const isLow = (text: string, index: number) => { const code = text.charCodeAt(index); return code >= 0xdc00 && code <= 0xdfff; }; + +/** + * `excerpt` is `whole` cut to `max` by the one rule: the text's own head and + * tail around a marker that states the whole length and the omission exactly, + * with neither cut separating a surrogate pair the text held whole. + */ +function assertCut(whole: string, excerpt: string, max: number, where: string): void { + if (whole.length <= max) { + assert.equal(excerpt, whole, `${where}: cut though it fits`); + return; + } + assert.ok(excerpt.length <= max, `${where}: ${excerpt.length} characters`); + const stated = / …\[(\d+) of (\d+) characters omitted\]… /.exec(excerpt); + assert.ok(stated, `${where}: no omission marker`); + const head = excerpt.slice(0, stated.index); + const tail = excerpt.slice(stated.index + stated[0].length); + assert.equal(Number(stated[2]), whole.length, `${where}: the stated whole length`); + assert.equal(head.length + Number(stated[1]) + tail.length, whole.length, `${where}: the stated omission`); + assert.ok(whole.startsWith(head), `${where}: the head is not the text's own`); + assert.ok(whole.endsWith(tail), `${where}: the tail is not the text's own`); + const tailStart = whole.length - tail.length; + assert.ok(!(isHigh(whole, head.length - 1) && isLow(whole, head.length)), `${where}: the head cut splits a pair`); + assert.ok(!(isHigh(whole, tailStart - 1) && isLow(whole, tailStart)), `${where}: the tail cut splits a pair`); +} + +test('every cut of failure text keeps surrogate pairs whole and states the whole length, at any position', () => { + // A reason longer than every bound, with a pair at every position, so that + // wherever a sink's cuts fall, some position straddles each of them. The + // second family puts a stray low surrogate right after the pair: a head + // cut landing between them must not move into the pair. const length = 2_500; - const omission = new RegExp(` …\\[(\\d+) of ${length} characters omitted\\]… `); - for (let at = 0; at <= length - 2; at++) { - const { fw, markers, logged, restore } = makeHarness(); - try { - fw.noteInferenceExhausted('cairn', `${'x'.repeat(at)}😀${'x'.repeat(length - 2 - at)}`, false, 'invalid_request'); - } finally { restore(); } - for (const [excerpt, max] of [[markers[0].meta.reason as string, 600], [logged[0].reason as string, 2_000]] as const) { - const where = `pair at ${at}, ${max}-character excerpt`; - assert.equal(loneSurrogate.test(excerpt), false, `${where}: a lone surrogate`); - assert.ok(excerpt.length <= max, `${where}: ${excerpt.length} characters`); - // A cut moved off a pair omits one more character, and says so. - const stated = omission.exec(excerpt); - assert.ok(stated, `${where}: no omission marker`); - assert.equal(excerpt.length - stated[0].length + Number(stated[1]), length, `${where}: the stated omission`); + const hook = process.env.CONNECTOME_OPS_WEBHOOK; + const realFetch = globalThis.fetch; + const posted: string[] = []; + process.env.CONNECTOME_OPS_WEBHOOK = 'http://zz.invalid/hook'; + globalThis.fetch = (async (_url: unknown, init?: { body?: unknown }) => { + posted.push(JSON.parse(String(init?.body)).content); + return new Response(null); + }) as typeof fetch; + try { + for (const inserted of ['😀', '😀\uDC00']) { + for (let at = 0; at <= length - inserted.length; at++) { + const text = `${'x'.repeat(at)}${inserted}${'x'.repeat(length - inserted.length - at)}`; + const where = (sink: string) => `${JSON.stringify(inserted)} at ${at}, ${sink}`; + posted.length = 0; + + // An invalid_request at the escalation threshold: the marker, the + // logs, the status, the hard-down alert and the rewind marker. + const exhausted = makeHarness(); + exhausted.fw.inferenceFailureEscalationThreshold = 1; + const rewound: string[] = []; + exhausted.fw.shedNewestTurn = () => ({ descriptor: 'zz-turn' }); + exhausted.fw.updateRewindMarker = (_agent: unknown, category: string) => { rewound.push(category); return 1; }; + try { + exhausted.fw.noteInferenceExhausted('cairn', text, false, 'invalid_request'); + } finally { exhausted.restore(); } + assertCut(text, exhausted.markers[0].meta.reason, 600, where('[inference-failed] marker')); + assertCut(text, exhausted.logged[0].reason as string, 2_000, where('failures.log')); + assertCut(text, exhausted.fw.lastInferenceAt.get('cairn').lastError, 300, where('lastError')); + assertCut(text, rewound[0], 160, where('rewind marker')); + const hardDown = exhausted.traces.find((t) => t.type === 'ops:alert' && t.kind === 'hard-down').message as string; + const prefix = '1 consecutive inference failures. Last reason: '; + assert.ok(hardDown.startsWith(prefix), where('hard-down alert')); + assertCut(text, hardDown.slice(prefix.length), 2_000 - prefix.length, where('hard-down alert')); + + // A refused compile: the context-refusal alert (no drain kick here). + const refused = makeHarness(); + refused.fw.overBudgetDrainInFlight.add('cairn'); + try { + refused.fw.noteInferenceExhausted('cairn', text, undefined, 'over_budget'); + } finally { refused.restore(); } + const refusal = refused.traces.find((t) => t.type === 'ops:alert' && t.kind === 'context-refusal').message as string; + assertCut(text, /^compile refused \(over_budget\): ([\s\S]*) — drain breaker/.exec(refusal)![1], 300, where('compile-refused alert')); + + // An alert's message, posted to the ops webhook. + const alerted = makeHarness(); + try { + alerted.fw.opsAlert('zz-webhook', 'cairn', text); + } finally { alerted.restore(); } + const webhook = '\u{1F6A8} **cairn** zz-webhook: '; + const content = posted.find((c) => c.startsWith(webhook)); + assert.ok(content, where('webhook')); + assertCut(text, content.slice(webhook.length), 500, where('webhook')); + } } + } finally { + globalThis.fetch = realFetch; + if (hook === undefined) delete process.env.CONNECTOME_OPS_WEBHOOK; + else process.env.CONNECTOME_OPS_WEBHOOK = hook; } }); @@ -176,6 +248,18 @@ test('an over-budget phrase quoted inside a classified provider error does not k assert.equal(long.ticks(), 8, 'presentation bounds never change the decision'); }); +test('a reason that is not a string is described, not thrown on before anything is recorded', () => { + // Unreachable from the stream paths, which pass a message; a malformed + // trace event must still leave its failure record. + const { fw, markers, logged, restore } = makeHarness(); + try { + fw.noteInferenceExhausted('cairn', new Error(`zz-not-a-string ${echo()}`)); + } finally { restore(); } + assert.match(markers[0].meta.reason, /^Error: zz-not-a-string zz-head/); + assert.ok(markers[0].meta.reason.length <= 600); + assert.match(logged[0].reason as string, /^Error: zz-not-a-string zz-head/); +}); + test('each excerpt states the whole length when it was cut, and only then', () => { const { fw, markers, logged, restore } = makeHarness(); const reason = `zz-reason ${'r'.repeat(990)}`; // 1,000 chars: cut for the marker, whole in the logs @@ -188,13 +272,15 @@ test('each excerpt states the whole length when it was cut, and only then', () = assert.equal('reasonChars' in logged[0], false); }); -/** Every argument a failure log passed is a bounded string: no object for the runtime to inspect. */ +/** Every argument a failure log passed is a bounded string: no object for the + * runtime to inspect. The projection and the stack frames below it are each + * bounded to 2,000 characters. */ function assertBoundedStrings(rawArgs: unknown[][], marker: string): string { const call = rawArgs.find((args) => typeof args[0] === 'string' && (args[0] as string).includes(marker)); assert.ok(call, `a log line containing "${marker}"`); for (const arg of call!) assert.equal(typeof arg, 'string', `${marker}: an argument was a ${typeof arg}`); const line = call!.join(' '); - assert.ok(line.length < 2_500, `${marker} line is ${line.length} chars`); + assert.ok(line.length < 4_500, `${marker} line is ${line.length} chars`); return line; } @@ -213,6 +299,8 @@ test('failure logs print a bounded projection, never the error object with its r } finally { kicked.restore(); } const kick = assertBoundedStrings(kicked.rawArgs, 'drain kick failed'); assert.match(kick, /MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-/); + // The frames follow the projection, so an internal throw still says where. + assert.match(kick, /\n {4}at .*inference-failure-bounds\.test/); const refused = makeHarness({ addMessage: () => { throw error; } }); try { @@ -233,6 +321,108 @@ test('failure logs print a bounded projection, never the error object with its r assertBoundedStrings(odd.rawArgs, 'drain kick failed'); }); +test('a thrown non-Error, and an error whose projection throws, still log bounded lines', async () => { + const thrownString = makeHarness({ tick: async () => { throw `socket said: ${echo()}`; } }); + try { + thrownString.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { thrownString.restore(); } + const line = assertBoundedStrings(thrownString.rawArgs, 'drain kick failed'); + assert.match(line, /after 0 ticks: socket said: zz-head e+ …\[\d+ of \d+ characters omitted\]… e+ zz-tail$/); + + // A name getter that throws breaks the projection and the stack alike. + const hostile = new Error('zz-short'); + Object.defineProperty(hostile, 'name', { get() { throw new Error('zz-no-name'); } }); + const unprintable = makeHarness({ tick: async () => { throw hostile; } }); + try { + unprintable.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { unprintable.restore(); } + assert.match(assertBoundedStrings(unprintable.rawArgs, 'drain kick failed'), /after 0 ticks: \[failure could not be described\]$/); +}); + +test('a provider hold keeps a bounded reason, and a failed resume logs the bounded projection', async () => { + const providerState = (fw: any) => Object.assign(fw, { + ephemeralRuns: new Map(), conversationAgentHomes: new Map(), providerGates: new Map(), + providerAccelerationCooldowns: new Map(), providerAccelerationRecoveries: new Map(), + providerAdmissionClosed: false, activeTurnTokens: new Map(), quiesced: false, + }); + const held = makeHarness(); + providerState(held.fw); + const agent = held.fw.agents.get('cairn'); + try { + // A host hold with no reason of its own: the error's message stands in. + held.fw.providerHoldHook = () => ({ holdMs: 60_000 }); + assert.equal(held.fw.holdProviderAcceleration(agent, hugeProviderError()), true); + const cooldown = held.fw.providerAccelerationCooldowns.get('cairn'); + assert.ok(cooldown.reason.length <= 2_000, `cooldown reason is ${cooldown.reason.length} chars`); + assert.match(cooldown.reason, /^Bad request: zz-head/); + assert.ok(held.fw.providerAccelerationRecoveries.get('cairn').reason.length <= 2_000); + const holdLine = held.errs.find((e) => e.startsWith('[provider-cooldown] agent=cairn host hold (')); + assert.ok(holdLine && holdLine.length < 2_300, `hold line is ${holdLine?.length} chars`); + + // A reason of the host's own is bounded too, here when a slice is extended. + held.fw.providerHoldHook = () => ({ holdMs: 60_000, reason: `host says ${echo()}` }); + assert.equal(held.fw.extendHostProviderHold('cairn', cooldown), true); + assert.ok(cooldown.reason.length <= 2_000); + assert.match(cooldown.reason, /^host says zz-head/); + const extended = held.errs.find((e) => e.includes('host hold extended')); + assert.ok(extended && extended.length < 2_300, `extension line is ${extended?.length} chars`); + } finally { + held.fw.cancelProviderAdmission(); + held.restore(); + } + + // The built-in acceleration cooldown keeps the error's own message as its reason. + const accelerated = makeHarness(); + providerState(accelerated.fw); + Object.assign(accelerated.fw, { providerAccelerationDefaultCooldownMs: 30_000, providerAccelerationJitterMs: 0 }); + try { + const limited = new MembraneError({ + type: 'rate_limit', retryable: true, httpStatus: 429, rawError: { status: 429 }, + message: `Your organization has hit its acceleration limit. ${echo()}`, + }); + assert.equal(accelerated.fw.holdProviderAcceleration(accelerated.fw.agents.get('cairn'), limited), true); + const reason = accelerated.fw.providerAccelerationCooldowns.get('cairn').reason; + assert.ok(reason.length <= 2_000, `acceleration cooldown reason is ${reason.length} chars`); + assert.match(reason, /^Your organization has hit its acceleration limit\. zz-head/); + } finally { + accelerated.fw.cancelProviderAdmission(); + accelerated.restore(); + } + + // Resuming the primary after the auxiliary call drains, and failing. + const resumed = makeHarness(); + providerState(resumed.fw); + resumed.fw.providerGates.set('cairn', { + primaryDepth: 0, primaryPending: false, auxiliaryInFlight: 1, auxiliaryWaiters: [], idleWaiters: [], deferredAuxiliary: 0, + }); + resumed.fw.waitForAuxiliaryIdle = async () => {}; + resumed.fw.startAgentStream = async () => { throw hugeProviderError(); }; + try { + await (FrameworkClass.prototype as any).startAgentStream.call(resumed.fw, resumed.fw.agents.get('cairn')); + await settle(); + } finally { resumed.restore(); } + const line = assertBoundedStrings(resumed.rawArgs, 'failed to resume primary'); + assert.match(line, /failed to resume primary for cairn: MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/); + assert.match(line, /\n {4}at /); +}); + +test('a failed maintenance pass logs and alerts a bounded reason', async () => { + const { fw, traces, rawArgs, restore } = makeHarness(); + fw.running = true; + fw.maintenancePass = null; + fw.runQueuedMaintenance = async () => { throw hugeProviderError(); }; + try { + fw.startQueuedMaintenance(); + await settle(); + } finally { restore(); } + assert.match(assertBoundedStrings(rawArgs, '[context-maintenance] pass failed:'), /pass failed: Bad request: zz-head/); + const alert = traces.find((t) => t.type === 'ops:alert' && t.kind === 'context-maintenance-failed'); + assert.ok(alert && alert.message.length <= 2_000); + assert.deepEqual(alert.data, { scope: 'pass' }); +}); + test('emitTrace: listeners get bounded error and stack; the marker still learns the full length', () => { const { fw, traces, markers, restore } = makeHarness(); const error = `Bad request: ${echo()}`; @@ -263,18 +453,50 @@ test('opsAlert bounds its message on the trace and the failures.log record', () assert.ok((logged[0].reason as string).length <= 2_000); }); -test('logFailure bounds every top-level string it writes', () => { +test('alert data is bounded field by field, on the trace and the failures.log record', () => { + const { fw, traces, logged, restore } = makeHarness(); + const nested = { items: Array.from({ length: 2_000 }, (_, i) => ({ i, note: 'zz' })) }; + try { + fw.notifyOpsAlert('zz-detector', 'cairn', 'short message', { + text: echo(), error: hugeProviderError(), nested, count: 3, small: { a: 1 }, + }); + } finally { restore(); } + const alert = traces.find((t) => t.type === 'ops:alert'); + for (const [sink, fields] of [['trace', alert.data], ['failures.log', logged[0]]] as const) { + assert.ok(fields.text.length <= 2_000, `${sink}: text`); + // An Error is its projection: serialising it would write its rawRequest. + assert.match(fields.error, /^MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/, sink); + assert.ok(fields.error.length <= 2_000, `${sink}: error`); + // A value whose JSON is too long becomes its JSON, bounded. + assert.equal(typeof fields.nested, 'string', `${sink}: nested`); + assert.ok(fields.nested.length <= 2_000 && fields.nested.startsWith('{"items":[{"i":0,'), `${sink}: nested`); + // Small values are kept as they are. + assert.equal(fields.count, 3); + assert.deepEqual(fields.small, { a: 1 }); + } +}); + +test('logFailure bounds every field it writes', () => { const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); const cwd = process.cwd(); process.chdir(dir); try { const fw = Object.create(FrameworkClass.prototype) as any; - fw.logFailure({ agent: 'cairn', reason: echo(), note: echo(), consecutive: 1 }); + const circular: Record = { zz: 1 }; + circular.self = circular; + fw.logFailure({ + agent: 'cairn', reason: echo(), note: echo(), consecutive: 1, + error: hugeProviderError(), nested: { list: Array.from({ length: 2_000 }, (_, i) => i) }, circular, + }); const line = readFileSync(join(dir, 'logs', 'failures.log'), 'utf-8').trim(); - assert.ok(line.length < 4_500, `failures.log line is ${line.length} chars`); + assert.ok(line.length < 9_000, `failures.log line is ${line.length} chars`); const record = JSON.parse(line); assert.ok(record.reason.length <= 2_000 && record.note.length <= 2_000); assert.equal(record.consecutive, 1); + assert.match(record.error, /^MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/); + assert.ok(typeof record.nested === 'string' && record.nested.length <= 2_000); + // A value JSON can't write no longer loses the whole record. + assert.equal(record.circular, '[object Object]'); } finally { process.chdir(cwd); rmSync(dir, { recursive: true, force: true }); @@ -329,18 +551,38 @@ class FailingMembrane extends MockMembrane { } } -async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => Error) { +/** A console.error spy that keeps the arguments as passed: printing an object + * (rather than a string built from it) is what wrote a MembraneError's whole + * rawRequest to stderr, and String() of the argument would hide it. */ +function spyConsoleError() { + const errs: string[] = []; + const rawArgs: unknown[][] = []; + const orig = console.error; + console.error = (...a: unknown[]) => { rawArgs.push(a); errs.push(a.map(String).join(' ')); }; + return { errs, rawArgs, restore: () => { console.error = orig; } }; +} + +/** No failure log printed an object: every argument of every line was a string. */ +function assertNoObjectPrinted(rawArgs: unknown[][]): void { + for (const args of rawArgs) { + for (const arg of args) assert.equal(typeof arg, 'string', `${String(args[0]).slice(0, 80)}: an argument was a ${typeof arg}`); + } +} + +/** Never retries, so a test reaches exhaustion on the first failure. */ +const noRetry: ErrorPolicy = { maxRetries: 0, onInferenceError: () => ({ retry: false }) }; + +async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => Error, opts?: { errorPolicy?: ErrorPolicy }) { const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); const cwd = process.cwd(); process.chdir(dir); - const errs: string[] = []; - const orig = console.error; - console.error = (...a: unknown[]) => { errs.push(a.map((x) => (typeof x === 'string' ? x : String(x))).join(' ')); }; + const { errs, rawArgs, restore } = spyConsoleError(); const membrane = new FailingMembrane(path, make); const framework = await AgentFramework.create({ storePath: join(dir, 'store.chronicle'), membrane: membrane.asMembrane(), agents: [{ name: 'resident', model: 'test-model', systemPrompt: 'system' }], modules: [new InputModule()], syncIntervalMs: 0, maintenanceIntervalMs: 0, + ...(opts?.errorPolicy ? { errorPolicy: opts.errorPolicy } : {}), }); const traces: any[] = []; framework.onTrace((e) => traces.push(e)); @@ -351,10 +593,10 @@ async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => const markers = messages.filter((m) => (m.metadata as { kind?: string } | undefined)?.kind === 'inference-failed'); const failuresLog = existsSync(join(dir, 'logs', 'failures.log')) ? readFileSync(join(dir, 'logs', 'failures.log'), 'utf-8') : ''; const inferenceLogs = framework.queryInferenceLogs({}).entries; - return { markers, traces, errs, failuresLog, inferenceLogs, calls: membrane.calls.length }; + return { markers, traces, errs, rawArgs, failuresLog, inferenceLogs, calls: membrane.calls.length }; } finally { await framework.stop(); - console.error = orig; + restore(); process.chdir(cwd); rmSync(dir, { recursive: true, force: true }); } @@ -362,7 +604,8 @@ async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => for (const path of ['stream error event', 'stream throws', 'stream setup throws'] as const) { test(`${path}: a ~1 MB provider error leaves a bounded, classified trail`, async () => { - const { markers, traces, errs, failuresLog, inferenceLogs } = await runFailingTurn(path, (request) => hugeProviderError(request)); + const { markers, traces, errs, rawArgs, failuresLog, inferenceLogs } = await runFailingTurn(path, (request) => hugeProviderError(request)); + assertNoObjectPrinted(rawArgs); assert.equal(markers.length, 1, 'one failure marker'); const text = (markers[0].content[0] as { text: string }).text; assert.ok(text.length < 1_200, `marker is ${text.length} chars`); @@ -393,7 +636,8 @@ for (const path of ['stream error event', 'stream throws', 'stream setup throws' } test('a ~1 MB plain Error (no classification) is bounded the same way', async () => { - const { markers, errs } = await runFailingTurn('stream throws', () => new Error(`socket said: ${echo()}`)); + const { markers, errs, rawArgs } = await runFailingTurn('stream throws', () => new Error(`socket said: ${echo()}`)); + assertNoObjectPrinted(rawArgs); assert.equal(markers.length, 1); const text = (markers[0].content[0] as { text: string }).text; assert.ok(text.length < 1_200); @@ -402,6 +646,72 @@ test('a ~1 MB plain Error (no classification) is bounded the same way', async () assert.ok(longest < 4_500, `longest stderr line is ${longest} chars`); }); +test('an oversized provider code is bounded in the trace, the marker and failures.log', async () => { + const { markers, traces, failuresLog } = await runFailingTurn('stream error event', () => new MembraneError({ + type: 'invalid_request', retryable: false, httpStatus: 400, providerErrorCode: `zz${'C'.repeat(MEGA)}`, + message: 'Bad request: zz-short', rawError: { status: 400 }, + })); + const exhausted = traces.find((t) => t.type === 'inference:exhausted'); + assert.ok(exhausted.providerErrorCode.length <= 128, `trace code is ${exhausted.providerErrorCode.length} chars`); + assert.ok((markers[0].metadata as { providerErrorCode: string }).providerErrorCode.length <= 128); + const record = failuresLog.trim().split('\n').map((l) => JSON.parse(l)).find((r) => r.kind === 'inference-exhausted'); + assert.ok(record.providerErrorCode.length <= 128, `failures.log code is ${record.providerErrorCode.length} chars`); +}); + +/** A MembraneError built by another copy of the package: the same fields and name, another class. */ +function foreignMembraneError(message: string, type = 'invalid_request'): Error { + return Object.assign(new Error(message), { + name: 'MembraneError', type, retryable: false, httpStatus: 400, providerErrorCode: 'zz_bad_request', rawRequest: { system: echo() }, + }); +} + +test('a MembraneError from another copy of membrane is classified by its name', async () => { + const quoted = `Bad request. Request: ... Context would exceed hard budget ... ${echo(10_000)}`; + const { markers, traces, errs, rawArgs } = await runFailingTurn('stream throws', () => foreignMembraneError(quoted), { errorPolicy: noRetry }); + assert.match((markers[0].content[0] as { text: string }).text, /model call failed \(invalid_request, HTTP 400\)/); + assert.equal((markers[0].metadata as { errorType: string }).errorType, 'invalid_request'); + // Classified, so the quoted phrase is the provider's text, not a refused compile. + assert.equal(traces.filter((t) => t.type === 'ops:alert' && t.kind === 'context-refusal').length, 0); + assert.equal(errs.some((e) => e.includes('drain kicked')), false); + assertNoObjectPrinted(rawArgs); + + // Its type is bounded like a provider code, in every sink it reaches. + const odd = await runFailingTurn('stream throws', () => foreignMembraneError('Bad request: zz-short', `zz${'T'.repeat(MEGA)}`), { errorPolicy: noRetry }); + const exhausted = odd.traces.find((t) => t.type === 'inference:exhausted'); + assert.ok(exhausted.errorType.length <= 128, `trace type is ${exhausted.errorType.length} chars`); + assert.ok((odd.markers[0].metadata as { errorType: string }).errorType.length <= 128); + const line = odd.errs.find((e) => e.startsWith('[inference-failed] agent=resident'))!; + assert.ok(line.length < 2_500, `stderr line is ${line.length} chars`); +}); + +test('an ephemeral run rejects with the bounded failure text', async () => { + const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); + const cwd = process.cwd(); + process.chdir(dir); + const { restore } = spyConsoleError(); + const framework = await AgentFramework.create({ + storePath: join(dir, 'store.chronicle'), + membrane: new FailingMembrane('stream setup throws', () => hugeProviderError()).asMembrane(), + agents: [], modules: [], syncIntervalMs: 0, maintenanceIntervalMs: 0, errorPolicy: noRetry, + }); + try { + const { agent, contextManager } = await framework.createEphemeralAgent({ name: 'worker', model: 'test-model', systemPrompt: 'Do the task.' }); + contextManager.addMessage('user', [{ type: 'text', text: 'Run once.' }]); + const run = framework.runEphemeralToCompletion(agent, contextManager); + framework.start(); + await assert.rejects(run, (error: Error) => { + assert.ok(error.message.length <= 2_000, `rejection message is ${error.message.length} chars`); + assert.match(error.message, /^Bad request: zz-head e+ …\[\d+ of \d+ characters omitted\]… e+ zz-tail$/); + return true; + }); + } finally { + await framework.stop(); + restore(); + process.chdir(cwd); + rmSync(dir, { recursive: true, force: true }); + } +}); + class HugeFailureStrategy implements ContextStrategy { readonly name = 'huge-failure-maintenance-test'; checkReadiness(): ReadinessState { return { ready: false, description: 'compression blocked' }; } @@ -413,9 +723,7 @@ test('a ~1 MB maintenance failure: bounded record, ops alert and stderr', async const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); const cwd = process.cwd(); process.chdir(dir); - const errs: string[] = []; - const orig = console.error; - console.error = (...a: unknown[]) => { errs.push(a.map((x) => (typeof x === 'string' ? x : String(x))).join(' ')); }; + const { errs, rawArgs, restore } = spyConsoleError(); const framework = await AgentFramework.create({ storePath: join(dir, 'store.chronicle'), membrane: new MockMembrane().asMembrane(), agents: [{ name: 'agent', model: 'test-model', systemPrompt: 'test', strategy: new HugeFailureStrategy() }], @@ -436,9 +744,10 @@ test('a ~1 MB maintenance failure: bounded record, ops alert and stderr', async assert.ok(alert && alert.message.length <= 2_000); const longest = errs.reduce((max, e) => Math.max(max, e.length), 0); assert.ok(longest < 4_500, `longest stderr line is ${longest} chars`); + assertNoObjectPrinted(rawArgs); } finally { await framework.stop(); - console.error = orig; + restore(); process.chdir(cwd); rmSync(dir, { recursive: true, force: true }); } From b500e710161bf580701106a291fabec6289c1ed6 Mon Sep 17 00:00:00 2001 From: Ada-1017 Date: Sun, 11 Oct 2026 10:36:58 -0400 Subject: [PATCH 06/18] docs(failures): keep the reason the speech-route sites stay whole sw-af249 I16 found that the fragment's 'kept whole as delivery evidence' for the speech-route failure reason and the [discord-send-failed] marker appears in neither the commit nor the code. The previous commit replaced it with 'out of scope here, by agreement', following my verdict that the parenthetical invented a rationale. It didn't: the reason is Petra-1012's (room-203 #43778, the agreement c15df26's 'Out of scope by agreement' cites): the connector's partial-send report (posted, in flight, not sent) is the evidence a resident needs before resending, so the marker's reason stays whole. The fragment keeps that reason: 'kept whole as the delivery evidence a resident reads before resending'. Fragment only; no code or test change. Co-Authored-By: Claude Opus 5.5 --- changelog.d/fix-bounded-inference-failure-text.fixed.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index a269926f6..86701fb3e 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -16,4 +16,4 @@ - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - A `MembraneError` from another copy of membrane is classified by its name as well as by its class, since the host supplies the `Membrane` instance. Its failure is classified as one from the framework's own copy is, rather than left unclassified. - This bound doesn't depend on membrane bounding its own errors. -- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (out of scope here, by agreement), and other module or hook logs that print error objects. +- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as the delivery evidence a resident reads before resending), and other module or hook logs that print error objects. From 51aff7e4c5d3421c76b37baceed60817914658c7 Mon Sep 17 00:00:00 2001 From: Ada-1017 Date: Sun, 11 Oct 2026 10:41:10 -0400 Subject: [PATCH 07/18] fix(failures): recognise a MembraneError from another copy at every site, not only the classifier sw-af249 I25 (fixed in 9c2794f) had classifyInferenceError recognise a MembraneError by name as well as by class, since the host supplies config.membrane and with two copies of @animalabs/membrane installed its errors are instances of a class this framework's instanceof doesn't match. Two sibling sites kept the class-only test (the rule-at-one-site check on that fix): - DefaultErrorPolicy: a non-retryable MembraneError from the other copy was retried up to three times (1 s, 2 s, 4 s) as an unknown error, and its retryAfterMs was ignored. - isOrganizationAccelerationRateLimit: an organization acceleration 429 from the other copy armed no acceleration cooldown. With only the classifier fixed, the framework would classify such an error for the breakers while retrying and not holding it as an unknown one. isMembraneError(error) (instanceof, or an Error named 'MembraneError') now serves all four sites. The policy reads `retryable === false` and `typeof retryAfterMs === 'number'`, the same as before for the framework's own copy (membrane always sets retryable), and an unrelated error that happens to carry the name without the fields keeps the unknown-error path. The classifier reads each field with a typeof check, as before. Test ('a MembraneError from another copy of membrane is recognised by its name'): the first run now goes through a stream error event, the path that consults the default policy, and asserts one call (no retry); a prototype-harness case holds a foreign acceleration 429. Mutations, each killed by this test: the classifier, the policy and the detector each back to instanceof alone, and isMembraneError without the name. inference-failure-bounds 22/22; tsc clean. Fragment: the MembraneError line is its own entry, naming all three behaviours and what happened before. Co-Authored-By: Claude Opus 5.5 --- ...ix-bounded-inference-failure-text.fixed.md | 2 +- src/framework.ts | 27 ++++++++++++------- test/inference-failure-bounds.test.ts | 24 +++++++++++++++-- 3 files changed, 41 insertions(+), 12 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index 86701fb3e..ebe14cac7 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -14,6 +14,6 @@ `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. The error type and the provider code are recorded to at most 128 characters each. - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed. They now print a bounded projection instead: name, classification, status, provider code and message, each part bounded and the whole within 2,000 characters, on one line unless one of its parts has newlines, as a message can. The stack's frames follow on the lines below, also bounded to 2,000 characters. Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. Context maintenance records and logs a bounded message, in its existing format. - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - - A `MembraneError` from another copy of membrane is classified by its name as well as by its class, since the host supplies the `Membrane` instance. Its failure is classified as one from the framework's own copy is, rather than left unclassified. - This bound doesn't depend on membrane bounding its own errors. +- A `MembraneError` from another copy of membrane is recognised by its name as well as by its class, since the host supplies the `Membrane` instance and two copies can be installed. Its failure is classified, the default error policy reads its `retryable` and `retryAfterMs`, and an organization acceleration limit it reports is held, as for the framework's own copy. Before, each treated it as an unknown error: the default policy retried a non-retryable one up to three times, and its failure was then left unclassified. - Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as the delivery evidence a resident reads before resending), and other module or hook logs that print error objects. diff --git a/src/framework.ts b/src/framework.ts index a066f6572..3175a4652 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -751,11 +751,11 @@ class DefaultErrorPolicy implements ErrorPolicy { maxRetries = 3; onInferenceError(error: Error, _agentName: string, attempt: number): ErrorAction { - if (error instanceof MembraneError && !error.retryable) { + if (isMembraneError(error) && error.retryable === false) { return { retry: false }; } if (attempt < this.maxRetries) { - const delayMs = error instanceof MembraneError && error.retryAfterMs !== undefined + const delayMs = isMembraneError(error) && typeof error.retryAfterMs === 'number' ? error.retryAfterMs : Math.pow(2, attempt) * 1000; return { retry: true, delayMs }; @@ -816,8 +816,19 @@ interface ProviderAccelerationReceipt { const PROVIDER_ACCELERATION_DEFAULT_COOLDOWN_MS = 65_000; const PROVIDER_ACCELERATION_MAX_COOLDOWN_MS = 10 * 60_000; const PROVIDER_ACCELERATION_JITTER_MS = 5_000; +/** + * A MembraneError, from this framework's copy of membrane or from another: the + * host supplies the Membrane instance (config.membrane), so with two copies + * installed its errors are instances of a class this framework's `instanceof` + * doesn't match. Recognised by name as well, as context-manager's errors are; + * its fields are the same, so callers still check each one's type. + */ +function isMembraneError(error: unknown): error is MembraneError { + return error instanceof MembraneError || (error instanceof Error && error.name === 'MembraneError'); +} + function isOrganizationAccelerationRateLimit(error: Error): error is MembraneError { - if (!(error instanceof MembraneError) || error.type !== 'rate_limit') return false; + if (!isMembraneError(error) || error.type !== 'rate_limit') return false; return ( /organization(?:'s)?[^\n]{0,120}maximum(?:\s+usage)?\s+increase\s+rate/i.test(error.message) || /organization(?:'s)?[^\n]{0,120}acceleration(?:\s+limit)?/i.test(error.message) @@ -12895,12 +12906,10 @@ export class AgentFramework { private classifyInferenceError(err: Error): { retryable?: boolean; errorType?: string; httpStatus?: number; providerErrorCode?: string; } { - // By name too, as below: the host supplies the Membrane instance - // (config.membrane), so its errors can come from another copy of the - // package, whose class this instanceof doesn't match. The fields are read - // as data, and the type is bounded like describeFailure's, for every sink - // the classification reaches (the trace, the marker, the logs). - if (err instanceof MembraneError || err.name === 'MembraneError') { + // From either copy of membrane (isMembraneError). The fields are read as + // data, and the type is bounded like describeFailure's, for every sink the + // classification reaches (the trace, the marker, the logs). + if (isMembraneError(err)) { const fields = err as Error & { retryable?: unknown; type?: unknown; httpStatus?: unknown; providerErrorCode?: unknown; }; diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index cb87e445a..1df4398f4 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -665,9 +665,12 @@ function foreignMembraneError(message: string, type = 'invalid_request'): Error }); } -test('a MembraneError from another copy of membrane is classified by its name', async () => { +test('a MembraneError from another copy of membrane is recognised by its name', async () => { const quoted = `Bad request. Request: ... Context would exceed hard budget ... ${echo(10_000)}`; - const { markers, traces, errs, rawArgs } = await runFailingTurn('stream throws', () => foreignMembraneError(quoted), { errorPolicy: noRetry }); + // The default error policy, which a stream's error event consults: a + // non-retryable error fails at once, not after three retries. + const { markers, traces, errs, rawArgs, calls } = await runFailingTurn('stream error event', () => foreignMembraneError(quoted)); + assert.equal(calls, 1, 'not retried'); assert.match((markers[0].content[0] as { text: string }).text, /model call failed \(invalid_request, HTTP 400\)/); assert.equal((markers[0].metadata as { errorType: string }).errorType, 'invalid_request'); // Classified, so the quoted phrase is the provider's text, not a refused compile. @@ -682,6 +685,23 @@ test('a MembraneError from another copy of membrane is classified by its name', assert.ok((odd.markers[0].metadata as { errorType: string }).errorType.length <= 128); const line = odd.errs.find((e) => e.startsWith('[inference-failed] agent=resident'))!; assert.ok(line.length < 2_500, `stderr line is ${line.length} chars`); + + // The organization acceleration limit is recognised too, and held. + const harness = makeHarness(); + Object.assign(harness.fw, { + ephemeralRuns: new Map(), conversationAgentHomes: new Map(), providerGates: new Map(), + providerAccelerationCooldowns: new Map(), providerAccelerationRecoveries: new Map(), + providerAccelerationDefaultCooldownMs: 30_000, providerAccelerationJitterMs: 0, + }); + const limited = Object.assign(new Error('Your organization has hit its acceleration limit.'), { + name: 'MembraneError', type: 'rate_limit', retryable: true, httpStatus: 429, + }); + try { + assert.equal(harness.fw.holdProviderAcceleration(harness.fw.agents.get('cairn'), limited), true); + } finally { + harness.fw.cancelProviderAdmission(); + harness.restore(); + } }); test('an ephemeral run rejects with the bounded failure text', async () => { From 1baa83bba4e88e3d4f4ef9748b44fce9ca07c5fb Mon Sep 17 00:00:00 2001 From: Ada-1017 Date: Sun, 11 Oct 2026 10:47:43 -0400 Subject: [PATCH 08/18] fix(failures): a kept alert field is the plain data its JSON describes, never the value Petra-1012's review of bbb4f8b..51aff7e (room-422 #71006, approved, a take-or-leave note): boundFailureFields kept a non-string value as it was whenever its JSON fit 2,000 characters. failures.log only ever writes the JSON, but the ops:alert trace handed listeners the original value, and a Map, a Set or an object with toJSON can have small JSON and a large value (a Map's JSON is {}). No caller passes one today. A non-string, non-Error field is now always its JSON: JSON.parse of it when it fits (the plain data failures.log records), the bounded JSON text when it doesn't, and undefined when JSON.stringify gives none (a function: the log drops the key; the trace no longer passes the function). So the trace's data is what failures.log writes. A plain field (numbers, strings, plain objects and arrays, as every caller passes) is unchanged; a Date becomes its ISO string, as the log already wrote it. Test: 'alert data is bounded field by field' adds a Map holding ~1 MB and a Date; both sinks get {} and the ISO string. The mutation keeping the value when its JSON fits fails it. The full mutation list reruns at this tree, each killed (mutants-5). inference-failure-bounds 22/22; tsc clean. Fragment: the failures.log field rule says "kept as data when it fits". Co-Authored-By: Claude Opus 5.5 --- .../fix-bounded-inference-failure-text.fixed.md | 2 +- src/framework.ts | 10 +++++++--- test/inference-failure-bounds.test.ts | 6 +++++- 3 files changed, 13 insertions(+), 5 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index ebe14cac7..bd461cbe8 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -4,7 +4,7 @@ - The rewind marker keeps 160 characters of the reason; an agent's `lastInference.lastError` and the compile-refused ops alert keep 300; the ops webhook posts 500 characters of the alert's message. - These sinks carry at most 2,000 characters: - the reason excerpt in the exhaustion stderr line (the line also carries the agent, the streak and `type=… status=… code=…` labels when known); - - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as it is when its JSON fits, otherwise its JSON, bounded; + - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as its JSON, kept as data when it fits and as bounded text when it doesn't. A record with a value JSON can't write is no longer lost; - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is; - the inference log's `error`; - every trace event's `error` and `stack` strings; diff --git a/src/framework.ts b/src/framework.ts index 3175a4652..9c7f6ea84 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1069,8 +1069,11 @@ function describeFailureWithFrames(error: unknown): string { * A failure record's fields, each bounded, for logs/failures.log and the * ops:alert trace: a string to FAILURE_TEXT_MAX_CHARS; an Error to its * projection, since serialising one writes its own fields, a MembraneError's - * whole `rawRequest` among them; any other value as it is when its JSON fits - * FAILURE_TEXT_MAX_CHARS, and otherwise its JSON, bounded. + * whole `rawRequest` among them; any other value to its JSON, as the plain + * data that JSON describes when it fits FAILURE_TEXT_MAX_CHARS and as the + * JSON text, bounded, when it doesn't. So the trace's data is what + * failures.log writes: a Map or an object with toJSON whose JSON is small + * never hands a listener the value itself. */ function boundFailureFields(record: Record): Record { const bounded: Record = {}; @@ -1080,7 +1083,8 @@ function boundFailureFields(record: Record): Record t.type === 'ops:alert'); @@ -470,9 +472,11 @@ test('alert data is bounded field by field, on the trace and the failures.log re // A value whose JSON is too long becomes its JSON, bounded. assert.equal(typeof fields.nested, 'string', `${sink}: nested`); assert.ok(fields.nested.length <= 2_000 && fields.nested.startsWith('{"items":[{"i":0,'), `${sink}: nested`); - // Small values are kept as they are. + // Small values are what their JSON describes. assert.equal(fields.count, 3); assert.deepEqual(fields.small, { a: 1 }); + assert.deepEqual(fields.held, {}, `${sink}: a Map is its JSON's data`); + assert.equal(fields.at, '1970-01-01T00:00:00.000Z', `${sink}: a Date is its JSON's data`); } }); From 8764891174289a496c3b4dbef0be78d6bdf8884a Mon Sep 17 00:00:00 2001 From: Ada-1017 Date: Mon, 12 Oct 2026 00:07:06 -0400 Subject: [PATCH 09/18] fix(failures): cut the projection once, find frames after the message, bound the hook's catch, accept null alert data describeFailure cut the message to 2,000 characters and then cut the composed `name (classification): message` again. For a long message the second cut landed in the first one's marker: it stated the composed length (about 2,000) and dropped the marker that stated the message's. The head's parts are still bounded each (name, type and provider code to 128 characters), and the composed text is now cut once, so its marker states the length of the head and the whole message. describeFailureWithFrames took the frames from the first indented `at ` line of the whole stack. The stack opens with the message, and an echoed request that quotes a stack trace has such lines, so the frames could start inside the message, spend their bound on it, and cut the throw site. The frames are now looked for after the message's text in the stack, or in the whole stack when the message isn't found there. A host's providerHold hook is handed the model's error, so a hook that throws it back printed the whole object, rawRequest included. Its catch now prints describeFailureWithFrames, as the cooldown resume does. opsAlert bounded its data with Object.entries before any guard, so a JavaScript caller's null data threw out of the alert, and the log record and the trace were lost. Null is now no data, as it was before this change. Tests: the projection and the failure record's strings go through the sweep's exact-cut check (the stated whole length and omission); a message that quotes a frame-like line; a hook that throws the model's error; null alert data; the marker-write log's frames; and the default policy the framework builds for itself, which honours another copy's stated wait as it does its own copy's, and retries an error without `retryable` as an unknown error. Text: each bound includes its marker; 2,000 characters is per string or field; trace listeners get the log's plain data; another copy's invalid request now gets the history quarantine; printing the object wrote the message whole and each of rawRequest's strings up to Node's 10,000 characters; the two plain slices outside this change are named. --- ...ix-bounded-inference-failure-text.fixed.md | 16 ++-- src/framework.ts | 40 ++++++--- test/inference-failure-bounds.test.ts | 90 +++++++++++++++++-- 3 files changed, 115 insertions(+), 31 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index bd461cbe8..4b7983554 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -1,19 +1,19 @@ - The inference-failure pipeline bounds the failure text it records. A failure's text is its source's `Error.message`, and a provider can echo the whole rejected request there: in one household an OpenAI-compatible 400 echoed ~1.7 MB, and the framework stored it in the resident's own context as an `[inference-failed]` marker (about 200K tokens, by the household's notes, which the resident then carried), wrote it to stderr and `logs/failures.log`, and traced it. - - Every cut of failure text follows one rule: the text's head and tail around a marker stating how many of how many characters were omitted. Each sink cuts the whole text, so its marker states the whole length, and no cut separates a surrogate pair. - - The `[inference-failed]` marker carries a 600-character excerpt. It also names the classification when there is one ("the model call failed (invalid_request, HTTP 400) …"). Its metadata adds `errorType`, `retryable`, `httpStatus` and `providerErrorCode`, plus `reasonChars` whenever the marker's excerpt was cut. A small unclassified failure produces exactly the marker it did before. Markers already stored keep their size until they're folded or removed. - - The rewind marker keeps 160 characters of the reason; an agent's `lastInference.lastError` and the compile-refused ops alert keep 300; the ops webhook posts 500 characters of the alert's message. - - These sinks carry at most 2,000 characters: + - Every cut this change makes follows one rule: the text's head and tail around a marker stating how many of how many characters were omitted. Each sink cuts the whole text, so its marker states the whole length, and no cut separates a surrogate pair. + - The `[inference-failed]` marker carries an excerpt of at most 600 characters. It also names the classification when there is one ("the model call failed (invalid_request, HTTP 400) …"). Its metadata adds `errorType`, `retryable`, `httpStatus` and `providerErrorCode`, plus `reasonChars` whenever the marker's excerpt was cut. A small unclassified failure produces exactly the marker it did before. Markers already stored keep their size until they're folded or removed. + - The rewind marker's reason is cut to 160 characters, an agent's `lastInference.lastError` and the compile-refused ops alert's to 300, and the ops webhook's copy of the alert's message to 500. Each bound includes the marker. + - Each of these is bounded to 2,000 characters: - the reason excerpt in the exhaustion stderr line (the line also carries the agent, the streak and `type=… status=… code=…` labels when known); - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as its JSON, kept as data when it fits and as bounded text when it doesn't. A record with a value JSON can't write is no longer lost; - - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is; + - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is, so a trace listener gets the plain data the log writes: a `Date` as its ISO string, a `Map` as `{}`, an `Error` as its projection; - the inference log's `error`; - every trace event's `error` and `stack` strings; - the provider cooldown's reason, in its stderr lines and the status snapshot's `cooldownReason`; - the error an ephemeral run (`runEphemeralToCompletion`) rejects with. `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. The error type and the provider code are recorded to at most 128 characters each. - - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed. They now print a bounded projection instead: name, classification, status, provider code and message, each part bounded and the whole within 2,000 characters, on one line unless one of its parts has newlines, as a message can. The stack's frames follow on the lines below, also bounded to 2,000 characters. Printing a `MembraneError` prints its `rawRequest`, so a long system prompt was written out in full. Context maintenance records and logs a bounded message, in its existing format. + - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. The stack's frames, from after the message, follow on the lines below, also bounded to 2,000 characters. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - This bound doesn't depend on membrane bounding its own errors. -- A `MembraneError` from another copy of membrane is recognised by its name as well as by its class, since the host supplies the `Membrane` instance and two copies can be installed. Its failure is classified, the default error policy reads its `retryable` and `retryAfterMs`, and an organization acceleration limit it reports is held, as for the framework's own copy. Before, each treated it as an unknown error: the default policy retried a non-retryable one up to three times, and its failure was then left unclassified. -- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as the delivery evidence a resident reads before resending), and other module or hook logs that print error objects. +- A `MembraneError` from another copy of membrane is recognised by its name as well as by its class, since the host supplies the `Membrane` instance and two copies can be installed. Its failure is classified, and so gets the framework's recovery for its class: an invalid request now sheds the newest exchanges of the agent's history, up to the rewind cap, as the poisoned-history quarantine does for the framework's own copy. The default error policy reads its `retryable` and `retryAfterMs`, and an organization acceleration limit it reports is held, as for the framework's own copy. Before, each treated it as an unknown error: the default policy retried a non-retryable one up to three times, and its failure was then left unclassified. +- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as the delivery evidence a resident reads before resending), other module logs that print error objects, and two plain slices: the health report's 400 characters of the inference log's stored error (already bounded to 2,000), and the tool-result spill's 200 characters of a workspace write's failure. diff --git a/src/framework.ts b/src/framework.ts index 9c7f6ea84..fdbb115e7 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1021,11 +1021,13 @@ function boundProviderErrorCode(code: unknown): string | undefined { /** * A bounded string describing a failure, for logs that would otherwise print * the error object; it is one line unless one of its parts has newlines, as a - * message can. Printing the object shows every own field, and a - * MembraneError's `rawRequest` is the whole request that failed: a long system - * prompt at depth one is printed in full. The projection keeps what a reader - * needs (name, classification, status, provider code, message) and nothing - * else. + * message can. Printing the object prints its message whole, in the stack, + * and every own field: a MembraneError's `rawRequest` is the whole request + * that failed, and Node's console prints each of its strings, a long system + * prompt among them, up to 10,000 characters. The projection keeps what a + * reader needs (name, classification, status, provider code, message) and + * nothing else. The head's parts are bounded each, and the whole is cut once, + * so its marker states the length of the head and the whole message. */ function describeFailure(error: unknown): string { try { @@ -1042,7 +1044,7 @@ function describeFailure(error: unknown): string { ].filter((part): part is string => part !== undefined); const name = boundFailureText(String(error.name), PROVIDER_ERROR_CODE_MAX_CHARS); const head = classification.length > 0 ? `${name} (${classification.join(', ')})` : name; - return boundFailureText(`${head}: ${boundFailureText(String(error.message))}`); + return boundFailureText(`${head}: ${String(error.message)}`); } catch { return '[failure could not be described]'; } @@ -1050,16 +1052,25 @@ function describeFailure(error: unknown): string { /** * describeFailure, then the error's stack frames (the stack from its first - * `at` line), bounded, on the lines below: for a log of a failure the - * framework's own code may have thrown, where the frames say where. The leak - * the projection closes was the object's own fields, not its stack. + * `at` line after the message), bounded, on the lines below: for a log of a + * failure the framework's own code may have thrown, where the frames say + * where. The stack opens with the message, and a message's own lines can look + * like frames (an echoed request quoting a stack trace), so the frames are + * looked for after it. The leak the projection closes was the object's own + * fields, not its stack. */ function describeFailureWithFrames(error: unknown): string { let frames: string | undefined; try { const stack = error instanceof Error ? error.stack : undefined; - const start = typeof stack === 'string' ? stack.search(/^\s+at /m) : -1; - if (start >= 0) frames = boundFailureText(stack!.slice(start)); + if (typeof stack === 'string') { + const message = String((error as Error).message); + const at = message ? stack.indexOf(message) : -1; + const frameLine = /^\s+at /gm; + frameLine.lastIndex = at >= 0 ? at + message.length : 0; + const found = frameLine.exec(stack); + if (found) frames = boundFailureText(stack.slice(found.index)); + } } catch { /* the projection alone */ } const described = describeFailure(error); return frames === undefined ? described : `${described}\n${frames}`; @@ -2262,7 +2273,8 @@ export class AgentFramework { return { holdMs: Math.min(PROVIDER_ACCELERATION_MAX_COOLDOWN_MS, Math.max(1_000, hold.holdMs)), reason: boundFailureText(typeof hold.reason === 'string' && hold.reason ? hold.reason : String(error.message)) }; } catch (err) { - console.error(`[provider-cooldown] providerHold hook threw for ${agentName}; treating as no hold:`, err); + // The hook is handed the model's error, and may throw it back. + console.error(`[provider-cooldown] providerHold hook threw for ${agentName}; treating as no hold: ${describeFailureWithFrames(err)}`); return undefined; } } @@ -12823,8 +12835,8 @@ export class AgentFramework { ): void { const message = boundFailureText(rawMessage); // The caller's data goes to failures.log and to trace listeners, bounded - // the same way for both. - const data = opts?.data === undefined ? undefined : boundFailureFields(opts.data); + // the same way for both. A JavaScript caller's null is no data. + const data = opts?.data == null ? undefined : boundFailureFields(opts.data); if (!opts?.skipLog) { this.logFailure({ agent: agentName, kind, reason: message, ...data }); } diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index c82a144bd..62287dea3 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -306,9 +306,22 @@ test('failure logs print a bounded projection, never the error object with its r try { refused.fw.noteInferenceExhausted('cairn', 'boom'); } finally { refused.restore(); } - assertBoundedStrings(refused.rawArgs, 'could not record chronicle marker'); + assert.match(assertBoundedStrings(refused.rawArgs, 'could not record chronicle marker'), /\n {4}at .*inference-failure-bounds\.test/); } + // A message's own lines can look like frames (an echoed request quoting a + // stack trace): the frames are the stack's, after the message, so the throw + // site is kept rather than spending the frames' bound on the message. + const quoting = new Error(`tool output:\n at zz-quoted (quoted.js:1:1)\n${echo()}`); + const quoted = makeHarness({ tick: async () => { throw quoting; } }); + try { + quoted.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { quoted.restore(); } + const quotedLine = assertBoundedStrings(quoted.rawArgs, 'drain kick failed'); + assert.equal(quotedLine.split('zz-quoted').length - 1, 1, 'the quoted frame is in the projection only'); + assert.match(quotedLine, /\n {4}at .*inference-failure-bounds\.test/); + // Every component of the projection is bounded, the name and type included. const named = new Error('zz-short'); named.name = `Zz${'N'.repeat(MEGA)}`; @@ -373,6 +386,18 @@ test('a provider hold keeps a bounded reason, and a failed resume logs the bound held.restore(); } + // A hook is handed the model's error, and one that throws it back logs its + // projection, never the object with its request. + const threw = makeHarness(); + providerState(threw.fw); + try { + threw.fw.providerHoldHook = (error: Error) => { throw error; }; + assert.equal(threw.fw.holdProviderAcceleration(threw.fw.agents.get('cairn'), hugeProviderError()), false); + } finally { threw.restore(); } + const threwLine = assertBoundedStrings(threw.rawArgs, 'providerHold hook threw'); + assert.match(threwLine, /treating as no hold: MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/); + assert.match(threwLine, /\n {4}at /); + // The built-in acceleration cooldown keeps the error's own message as its reason. const accelerated = makeHarness(); providerState(accelerated.fw); @@ -453,22 +478,36 @@ test('opsAlert bounds its message on the trace and the failures.log record', () assert.ok((logged[0].reason as string).length <= 2_000); }); +test('alert data of null, from a JavaScript caller, is no data: the alert is still logged and traced', () => { + const { fw, traces, logged, restore } = makeHarness(); + try { + fw.notifyOpsAlert('zz-detector', 'cairn', 'short message', null); + } finally { restore(); } + assert.equal(traces.find((t) => t.type === 'ops:alert')?.message, 'short message'); + assert.deepEqual(logged, [{ agent: 'cairn', kind: 'zz-detector', reason: 'short message' }]); +}); + +/** The projection's head for hugeProviderError(), before ': ' and the message. */ +const HUGE_ERROR_HEAD = 'MembraneError (invalid_request, HTTP 400, zz_bad_request, retryable=false)'; + test('alert data is bounded field by field, on the trace and the failures.log record', () => { const { fw, traces, logged, restore } = makeHarness(); const nested = { items: Array.from({ length: 2_000 }, (_, i) => ({ i, note: 'zz' })) }; + const text = echo(); + const error = hugeProviderError(); try { fw.notifyOpsAlert('zz-detector', 'cairn', 'short message', { - text: echo(), error: hugeProviderError(), nested, count: 3, small: { a: 1 }, + text, error, nested, count: 3, small: { a: 1 }, // Small JSON, large value: the listener gets the JSON's data, not the value. held: new Map([['zz', echo()]]), at: new Date(0), }); } finally { restore(); } const alert = traces.find((t) => t.type === 'ops:alert'); for (const [sink, fields] of [['trace', alert.data], ['failures.log', logged[0]]] as const) { - assert.ok(fields.text.length <= 2_000, `${sink}: text`); + assertCut(text, fields.text, 2_000, `${sink}: text`); // An Error is its projection: serialising it would write its rawRequest. - assert.match(fields.error, /^MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/, sink); - assert.ok(fields.error.length <= 2_000, `${sink}: error`); + // It is cut once, so its marker states the head and the whole message. + assertCut(`${HUGE_ERROR_HEAD}: ${error.message}`, fields.error, 2_000, `${sink}: error`); // A value whose JSON is too long becomes its JSON, bounded. assert.equal(typeof fields.nested, 'string', `${sink}: nested`); assert.ok(fields.nested.length <= 2_000 && fields.nested.startsWith('{"items":[{"i":0,'), `${sink}: nested`); @@ -488,16 +527,21 @@ test('logFailure bounds every field it writes', () => { const fw = Object.create(FrameworkClass.prototype) as any; const circular: Record = { zz: 1 }; circular.self = circular; + const reason = echo(); + const note = `zz-note ${echo(5_000)}`; + const error = hugeProviderError(); fw.logFailure({ - agent: 'cairn', reason: echo(), note: echo(), consecutive: 1, - error: hugeProviderError(), nested: { list: Array.from({ length: 2_000 }, (_, i) => i) }, circular, + agent: 'cairn', reason, note, consecutive: 1, + error, nested: { list: Array.from({ length: 2_000 }, (_, i) => i) }, circular, }); const line = readFileSync(join(dir, 'logs', 'failures.log'), 'utf-8').trim(); assert.ok(line.length < 9_000, `failures.log line is ${line.length} chars`); const record = JSON.parse(line); - assert.ok(record.reason.length <= 2_000 && record.note.length <= 2_000); + // The written record, not what a caller passed: each string is cut by the one rule. + assertCut(reason, record.reason, 2_000, 'failures.log reason'); + assertCut(note, record.note, 2_000, 'failures.log note'); assert.equal(record.consecutive, 1); - assert.match(record.error, /^MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/); + assertCut(`${HUGE_ERROR_HEAD}: ${error.message}`, record.error, 2_000, 'failures.log error'); assert.ok(typeof record.nested === 'string' && record.nested.length <= 2_000); // A value JSON can't write no longer loses the whole record. assert.equal(record.circular, '[object Object]'); @@ -708,6 +752,34 @@ test('a MembraneError from another copy of membrane is recognised by its name', } }); +test("the default error policy reads either copy's retryable and retryAfterMs", async () => { + const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); + const framework = await AgentFramework.create({ + storePath: join(dir, 'store.chronicle'), + membrane: new FailingMembrane('stream setup throws', () => hugeProviderError()).asMembrane(), + agents: [], modules: [], syncIntervalMs: 0, maintenanceIntervalMs: 0, + }); + try { + // The policy the framework built for itself, with no errorPolicy configured. + const policy = (framework as any).errorPolicy as ErrorPolicy; + const foreign = (fields: Record) => Object.assign(new Error('Rate limited'), { + name: 'MembraneError', type: 'rate_limit', httpStatus: 429, ...fields, + }); + const own = new MembraneError({ + type: 'rate_limit', retryable: true, httpStatus: 429, retryAfterMs: 1234, message: 'Rate limited', rawError: { status: 429 }, + }); + // A stated wait is honoured, from another copy as from the framework's own. + assert.deepEqual(policy.onInferenceError(own, 'resident', 0), { retry: true, delayMs: 1234 }); + assert.deepEqual(policy.onInferenceError(foreign({ retryable: true, retryAfterMs: 1234 }), 'resident', 0), { retry: true, delayMs: 1234 }); + // Without retryable, it retries as an unknown error does; refused only when false. + assert.deepEqual(policy.onInferenceError(foreign({}), 'resident', 0), { retry: true, delayMs: 1_000 }); + assert.deepEqual(policy.onInferenceError(foreign({ retryable: false, retryAfterMs: 1234 }), 'resident', 0), { retry: false }); + } finally { + await framework.stop(); + rmSync(dir, { recursive: true, force: true }); + } +}); + test('an ephemeral run rejects with the bounded failure text', async () => { const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); const cwd = process.cwd(); From 1055608370bed951016541cbe1d0d1567cb22091 Mon Sep 17 00:00:00 2001 From: Ada-1017 Date: Mon, 12 Oct 2026 00:28:57 -0400 Subject: [PATCH 10/18] fix(failures): take the message for the stack's header only before its first frame The frames were looked for after the message's first occurrence in the stack. In a stack without its header, as a copied or frames-only stack can be, the message's text can occur inside a frame's name (a message "request" thrown from requestHandler), and the frames then started after the throw site's own line. The message's occurrence is now used only when it comes before the first frame; otherwise the frames start at the first one, as before the message was looked for. Test: a headerless stack whose throw site's name contains the message keeps that frame. --- src/framework.ts | 6 +++++- test/inference-failure-bounds.test.ts | 12 ++++++++++++ 2 files changed, 17 insertions(+), 1 deletion(-) diff --git a/src/framework.ts b/src/framework.ts index fdbb115e7..f675a3cbd 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1065,9 +1065,13 @@ function describeFailureWithFrames(error: unknown): string { const stack = error instanceof Error ? error.stack : undefined; if (typeof stack === 'string') { const message = String((error as Error).message); + // The message is the stack's header only before its first frame: a + // stack without its header (copied, or frames only) can hold the + // message's text inside a frame's name. + const firstFrame = stack.search(/^\s+at /m); const at = message ? stack.indexOf(message) : -1; const frameLine = /^\s+at /gm; - frameLine.lastIndex = at >= 0 ? at + message.length : 0; + frameLine.lastIndex = at >= 0 && (firstFrame < 0 || at < firstFrame) ? at + message.length : 0; const found = frameLine.exec(stack); if (found) frames = boundFailureText(stack.slice(found.index)); } diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index 62287dea3..65f2c0b38 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -322,6 +322,18 @@ test('failure logs print a bounded projection, never the error object with its r assert.equal(quotedLine.split('zz-quoted').length - 1, 1, 'the quoted frame is in the projection only'); assert.match(quotedLine, /\n {4}at .*inference-failure-bounds\.test/); + // A stack without its header, as a copied one can be: the message's text + // inside a frame's name isn't taken for the header, so the throw site stays. + const requestHandler = (): Error => new Error('request'); + const headless = requestHandler(); + headless.stack = headless.stack!.split('\n').slice(1).join('\n'); + const bare = makeHarness({ tick: async () => { throw headless; } }); + try { + bare.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { bare.restore(); } + assert.match(assertBoundedStrings(bare.rawArgs, 'drain kick failed'), /\n {4}at requestHandler /); + // Every component of the projection is bounded, the name and type included. const named = new Error('zz-short'); named.name = `Zz${'N'.repeat(MEGA)}`; From 865a6a8562b4d6ae980404c8cfdf8f4a53f858cc Mon Sep 17 00:00:00 2001 From: Gladys-2413 Date: Tue, 13 Oct 2026 09:40:17 -0400 Subject: [PATCH 11/18] fix(failures): keep non-object alert data as one field, write thrown objects and nested Errors as data, describe a non-string reason whole opsAlert bounded its data field by field through Object.entries, so data that isn't a plain object (a string, an array or a Buffer from a JavaScript caller) spread into a field per character or element, in failures.log and on the ops:alert trace. Data whose prototype isn't Object.prototype or null is now kept as one field, `data`, bounded as any field is. describeFailure printed a thrown value that isn't an Error as String(value), so a host's providerHold hook that threw a plain object logged "[object Object]" where printing the object had shown its fields. Such an object is now its JSON, bounded, and its String only when JSON can't write it. JSON.stringify writes an Error's own enumerable fields, so an Error nested in a failures.log field or in alert data was written as a MembraneError's fields, with the head of its rawRequest (the system prompt among it) filling the 2,000-character field. failureJson's replacer writes every Error inside a value as its projection; boundFailureFields and the thrown-object JSON share it. A reason that isn't a string reached noteInferenceExhausted as describeFailure's text, already cut to 2,000 characters, so each sink cut it a second time (its marker stated "of 2000") and the OverBudget fallback read the excerpt, missing a phrase past the cut. The whole description (failureDescription, describeFailure's text before its one cut) is now the whole reason: each sink cuts it once, and the fallback reads it uncut. noteInferenceExhausted bounds a caller's error type to 128 characters at entry, as classifyInferenceError bounds the types it reads, so every sink it reaches (the stderr type= label, the marker's cause and metadata, failures.log) gets the bounded type. The frame regexes matched a frame's indent with \s+, which crosses line breaks, so a long run of blank lines in a stack was rescanned from each line's start, quadratically. The indent is now spaces or tabs (FRAME_LINE). Tests: non-plain alert data (a long string, a long array, a small array); a thrown plain object from the providerHold hook; nested Errors in alert data and in a failures.log record on disk; a non-string reason cut once from its whole description, with the fallback reading a phrase every excerpt omits; a caller's 1 MB error type; a deep stack's frames cut by the one rule; a message absent from its stack and an empty message, whose frames start at the first frame line; a message ending in blank lines; and another membrane copy's invalid request shedding the newest exchanges up to the rewind cap over three turns. Text: describeFailureWithFrames' doc states the fallback to the stack's first frame line, and the changelog names, as outside this change, the framework's own logs that still print an error object (the beforeInference hook's catch and its preview's, the event loop's catch, periodic and final sync, and the maintenance pass's retry of the tool-result guard's storage), besides stating the behaviour above. Co-Authored-By: Claude Opus 5.5 --- ...ix-bounded-inference-failure-text.fixed.md | 8 +- src/framework.ts | 111 +++++++++---- test/inference-failure-bounds.test.ts | 147 ++++++++++++++++-- 3 files changed, 221 insertions(+), 45 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index 4b7983554..74283eedf 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -4,16 +4,16 @@ - The rewind marker's reason is cut to 160 characters, an agent's `lastInference.lastError` and the compile-refused ops alert's to 300, and the ops webhook's copy of the alert's message to 500. Each bound includes the marker. - Each of these is bounded to 2,000 characters: - the reason excerpt in the exhaustion stderr line (the line also carries the agent, the streak and `type=… status=… code=…` labels when known); - - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as its JSON, kept as data when it fits and as bounded text when it doesn't. A record with a value JSON can't write is no longer lost; - - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is, so a trace listener gets the plain data the log writes: a `Date` as its ISO string, a `Map` as `{}`, an `Error` as its projection; + - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as its JSON, with any `Error` inside it written as its projection, kept as data when it fits and as bounded text when it doesn't. A record with a value JSON can't write is no longer lost; + - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is, so a trace listener gets the plain data the log writes: a `Date` as its ISO string, a `Map` as `{}`, an `Error` as its projection. Data that isn't a plain object, such as a string or an array from a JavaScript caller, is kept as one field, `data`, rather than spread into a field per character or element; - the inference log's `error`; - every trace event's `error` and `stack` strings; - the provider cooldown's reason, in its stderr lines and the status snapshot's `cooldownReason`; - the error an ephemeral run (`runEphemeralToCompletion`) rejects with. `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. The error type and the provider code are recorded to at most 128 characters each. - - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. The stack's frames, from after the message, follow on the lines below, also bounded to 2,000 characters. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. + - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. A thrown value that isn't an `Error` is printed as its JSON, bounded, with any `Error` inside it as its projection, or as its `String` when JSON can't write it, so a thrown plain object keeps its fields. The stack's frames follow on the lines below, also bounded to 2,000 characters: from after the message when the message is the stack's header, and otherwise from the stack's first frame line. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - This bound doesn't depend on membrane bounding its own errors. - A `MembraneError` from another copy of membrane is recognised by its name as well as by its class, since the host supplies the `Membrane` instance and two copies can be installed. Its failure is classified, and so gets the framework's recovery for its class: an invalid request now sheds the newest exchanges of the agent's history, up to the rewind cap, as the poisoned-history quarantine does for the framework's own copy. The default error policy reads its `retryable` and `retryAfterMs`, and an organization acceleration limit it reports is held, as for the framework's own copy. Before, each treated it as an unknown error: the default policy retried a non-retryable one up to three times, and its failure was then left unclassified. -- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as the delivery evidence a resident reads before resending), other module logs that print error objects, and two plain slices: the health report's 400 characters of the inference log's stored error (already bounded to 2,000), and the tool-result spill's 200 characters of a workspace write's failure. +- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as the delivery evidence a resident reads before resending), logs outside the inference-failure pipeline that still print an error object, in modules and in the framework's own code (among them the `beforeInference` hook's catch and its preview's, the event loop's catch, periodic and final sync, and the maintenance pass's retry of the tool-result guard's storage), and two plain slices: the health report's 400 characters of the inference log's stored error (already bounded to 2,000), and the tool-result spill's 200 characters of a workspace write's failure. diff --git a/src/framework.ts b/src/framework.ts index f675a3cbd..1180f0ed2 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1019,19 +1019,33 @@ function boundProviderErrorCode(code: unknown): string | undefined { } /** - * A bounded string describing a failure, for logs that would otherwise print - * the error object; it is one line unless one of its parts has newlines, as a - * message can. Printing the object prints its message whole, in the stack, - * and every own field: a MembraneError's `rawRequest` is the whole request - * that failed, and Node's console prints each of its strings, a long system - * prompt among them, up to 10,000 characters. The projection keeps what a - * reader needs (name, classification, status, provider code, message) and - * nothing else. The head's parts are bounded each, and the whole is cut once, - * so its marker states the length of the head and the whole message. + * A value's JSON for a failure sink, with every Error inside it written as its + * projection (describeFailure): serialising an Error writes its own fields, a + * MembraneError's whole `rawRequest` among them. Throws, or returns undefined, + * as JSON.stringify does. */ -function describeFailure(error: unknown): string { +function failureJson(value: unknown): string | undefined { + return JSON.stringify(value, (_key, nested: unknown) => (nested instanceof Error ? describeFailure(nested) : nested)); +} + +/** + * The whole text describeFailure cuts: for an Error, its head (name, + * classification, status, provider code, each bounded) and its whole + * message; for another object, its JSON (failureJson), or its String when + * JSON can't write it, so a thrown plain object keeps its fields; for + * anything else, its String. + */ +function failureDescription(error: unknown): string { try { - if (!(error instanceof Error)) return boundFailureText(String(error)); + if (!(error instanceof Error)) { + if (typeof error === 'object' && error !== null) { + try { + const json = failureJson(error); + if (json !== undefined) return json; + } catch { /* its String, below */ } + } + return String(error); + } const fields = error as Error & { type?: unknown; httpStatus?: unknown; providerErrorCode?: unknown; retryable?: unknown; }; @@ -1044,20 +1058,43 @@ function describeFailure(error: unknown): string { ].filter((part): part is string => part !== undefined); const name = boundFailureText(String(error.name), PROVIDER_ERROR_CODE_MAX_CHARS); const head = classification.length > 0 ? `${name} (${classification.join(', ')})` : name; - return boundFailureText(`${head}: ${String(error.message)}`); + return `${head}: ${String(error.message)}`; } catch { return '[failure could not be described]'; } } /** - * describeFailure, then the error's stack frames (the stack from its first - * `at` line after the message), bounded, on the lines below: for a log of a - * failure the framework's own code may have thrown, where the frames say - * where. The stack opens with the message, and a message's own lines can look - * like frames (an echoed request quoting a stack trace), so the frames are - * looked for after it. The leak the projection closes was the object's own - * fields, not its stack. + * A bounded string describing a failure, for logs that would otherwise print + * the error object; it is one line unless one of its parts has newlines, as a + * message can. Printing the object prints its message whole, in the stack, + * and every own field: a MembraneError's `rawRequest` is the whole request + * that failed, and Node's console prints each of its strings, a long system + * prompt among them, up to 10,000 characters. The projection keeps what a + * reader needs (name, classification, status, provider code, message) and + * nothing else. The head's parts are bounded each, and the whole + * (failureDescription) is cut once, so its marker states the length of the + * head and the whole message. + */ +function describeFailure(error: unknown): string { + return boundFailureText(failureDescription(error)); +} + +/** A stack frame's line: an indent of spaces or tabs, then `at `. The indent + * never crosses a line break, so a run of blank lines isn't rescanned from + * each line's start. */ +const FRAME_LINE = /^[ \t]+at /m; + +/** + * describeFailure, then the error's stack frames, bounded, on the lines + * below: for a log of a failure the framework's own code may have thrown, + * where the frames say where. The stack opens with the message, and a + * message's own lines can look like frames (an echoed request quoting a stack + * trace), so when the message is the stack's header, before its first frame + * line, the frames are the stack from its first frame line after the + * message. Otherwise (a stack without its header, a message that isn't in + * the stack or is empty) they are the stack from its first frame line. The + * leak the projection closes was the object's own fields, not its stack. */ function describeFailureWithFrames(error: unknown): string { let frames: string | undefined; @@ -1068,9 +1105,9 @@ function describeFailureWithFrames(error: unknown): string { // The message is the stack's header only before its first frame: a // stack without its header (copied, or frames only) can hold the // message's text inside a frame's name. - const firstFrame = stack.search(/^\s+at /m); + const firstFrame = stack.search(FRAME_LINE); const at = message ? stack.indexOf(message) : -1; - const frameLine = /^\s+at /gm; + const frameLine = new RegExp(FRAME_LINE.source, 'gm'); frameLine.lastIndex = at >= 0 && (firstFrame < 0 || at < firstFrame) ? at + message.length : 0; const found = frameLine.exec(stack); if (found) frames = boundFailureText(stack.slice(found.index)); @@ -1084,11 +1121,12 @@ function describeFailureWithFrames(error: unknown): string { * A failure record's fields, each bounded, for logs/failures.log and the * ops:alert trace: a string to FAILURE_TEXT_MAX_CHARS; an Error to its * projection, since serialising one writes its own fields, a MembraneError's - * whole `rawRequest` among them; any other value to its JSON, as the plain - * data that JSON describes when it fits FAILURE_TEXT_MAX_CHARS and as the - * JSON text, bounded, when it doesn't. So the trace's data is what - * failures.log writes: a Map or an object with toJSON whose JSON is small - * never hands a listener the value itself. + * whole `rawRequest` among them; any other value to its JSON, with each Error + * inside it as its projection (failureJson), as the plain data that JSON + * describes when it fits FAILURE_TEXT_MAX_CHARS and as the JSON text, + * bounded, when it doesn't. So the trace's data is what failures.log writes: + * a Map or an object with toJSON whose JSON is small never hands a listener + * the value itself. */ function boundFailureFields(record: Record): Record { const bounded: Record = {}; @@ -1097,7 +1135,7 @@ function boundFailureFields(record: Record): Record : { data: rawData }); if (!opts?.skipLog) { this.logFailure({ agent: agentName, kind, reason: message, ...data }); } @@ -12969,7 +13013,7 @@ export class AgentFramework { agentName: string, rawReason: string, retryable?: boolean, - errorType?: string, + rawErrorType?: string, detail?: { httpStatus?: number; providerErrorCode?: string }, ): void { // The reason is the failure's own message, and a provider can echo the @@ -12985,7 +13029,12 @@ export class AgentFramework { // // A reason that isn't a string (the stream paths always pass a message) // is described rather than allowed to throw before anything is recorded. - const wholeReason: string = typeof rawReason === 'string' ? rawReason : describeFailure(rawReason); + // Its whole description is the whole reason, cut once by each sink. + const wholeReason: string = typeof rawReason === 'string' ? rawReason : failureDescription(rawReason); + // The type is bounded wherever it's written, as classifyInferenceError + // bounds the types it reads, since a caller can pass one it didn't classify. + const errorType = typeof rawErrorType === 'string' + ? boundFailureText(rawErrorType, PROVIDER_ERROR_CODE_MAX_CHARS) : rawErrorType; const reason = boundFailureText(wholeReason); const markerReason = boundFailureText(wholeReason, FAILURE_MARKER_REASON_MAX_CHARS); const httpStatus = typeof detail?.httpStatus === 'number' ? detail.httpStatus : undefined; diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index 65f2c0b38..e86306878 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -248,16 +248,43 @@ test('an over-budget phrase quoted inside a classified provider error does not k assert.equal(long.ticks(), 8, 'presentation bounds never change the decision'); }); -test('a reason that is not a string is described, not thrown on before anything is recorded', () => { +test('a reason that is not a string is described whole, not thrown on: each sink cuts it once, and the fallback reads it uncut', async () => { // Unreachable from the stream paths, which pass a message; a malformed // trace event must still leave its failure record. + const error = new Error(`zz-not-a-string ${echo()}`); const { fw, markers, logged, restore } = makeHarness(); try { - fw.noteInferenceExhausted('cairn', new Error(`zz-not-a-string ${echo()}`)); + fw.noteInferenceExhausted('cairn', error); } finally { restore(); } - assert.match(markers[0].meta.reason, /^Error: zz-not-a-string zz-head/); - assert.ok(markers[0].meta.reason.length <= 600); - assert.match(logged[0].reason as string, /^Error: zz-not-a-string zz-head/); + const whole = `Error: ${error.message}`; + assertCut(whole, markers[0].meta.reason, 600, 'marker'); + assert.equal(markers[0].meta.reasonChars, whole.length); + assertCut(whole, logged[0].reason as string, 2_000, 'failures.log'); + assert.equal(logged[0].reasonChars, whole.length); + + // The OverBudget fallback reads the whole description, so a phrase that + // every excerpt omits still kicks the drain. + const phrased = makeHarness(); + try { + phrased.fw.noteInferenceExhausted('cairn', new Error(`${'x'.repeat(50_000)} Context would exceed hard budget ${'y'.repeat(50_000)}`)); + await settle(); + } finally { phrased.restore(); } + assert.equal(phrased.ticks(), 8); +}); + +test("a caller's long error type is bounded wherever it is written", () => { + // classifyInferenceError bounds the types it reads; a caller that passes + // its own is bounded the same way. + const { fw, markers, logged, errs, restore } = makeHarness(); + const type = `zz${'T'.repeat(MEGA)}`; + try { + fw.noteInferenceExhausted('cairn', 'zz-reason', false, type); + } finally { restore(); } + assertCut(type, markers[0].meta.errorType, 128, 'marker metadata'); + assertCut(type, logged[0].errorType as string, 128, 'failures.log'); + assert.ok(markers[0].text.length < 1_000, `marker text is ${markers[0].text.length} chars`); + const line = errs.find((e) => e.startsWith('[inference-failed] agent=cairn'))!; + assert.ok(line.length < 400, `stderr line is ${line.length} chars`); }); test('each excerpt states the whole length when it was cut, and only then', () => { @@ -346,6 +373,46 @@ test('failure logs print a bounded projection, never the error object with its r assertBoundedStrings(odd.rawArgs, 'drain kick failed'); }); +test("a failure's frames: cut to their bound, and from the stack's first frame line when the message isn't its header", async () => { + const kickedWith = async (thrown: Error) => { + const kicked = makeHarness({ tick: async () => { throw thrown; } }); + try { + kicked.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { kicked.restore(); } + return assertBoundedStrings(kicked.rawArgs, 'drain kick failed'); + }; + const prefix = '[inference-failed] drain kick failed for cairn after 0 ticks: '; + const framesOf = (stack: string) => stack.slice(stack.search(/^[ \t]+at /m)); + + // A stack far past the bound: its frames are cut by the one rule. + const deep = new Error('zz-deep'); + const deepStack = `Error: zz-deep\n${Array.from({ length: 1_000 }, (_, i) => ` at zzFrame${i} (deep.js:${i + 1}:1)`).join('\n')}`; + deep.stack = deepStack; + const deepLine = await kickedWith(deep); + const deepHead = `${prefix}Error: zz-deep\n`; + assert.ok(deepLine.startsWith(deepHead)); + assertCut(framesOf(deepStack), deepLine.slice(deepHead.length), 2_000, 'the frames of a deep stack'); + + // A message that isn't in the stack (replaced after the stack was taken), + // and an empty message: the frames are the stack's from its first frame line. + const replaced = new Error('zz-original'); + const replacedStack = 'Error: zz-original\n at zzThrower (replaced.js:1:1)\n at zzCaller (replaced.js:2:1)'; + replaced.stack = replacedStack; + replaced.message = `zz-replaced ${'r'.repeat(300)}`; + assert.equal(await kickedWith(replaced), `${prefix}Error: ${replaced.message}\n${framesOf(replacedStack)}`); + const empty = new Error(''); + empty.stack = 'Error\n at zzThrower (empty.js:1:1)'; + assert.equal(await kickedWith(empty), `${prefix}Error: \n at zzThrower (empty.js:1:1)`); + + // A message that ends in blank lines: the frames start at the frame line, + // since a frame's indent is spaces or tabs and never crosses a line break + // (an indent that did made a run of blank lines quadratic to scan). + const blank = new Error('zz-blank\n\n'); + blank.stack = 'Error: zz-blank\n\n\n at zzThrower (blank.js:1:1)'; + assert.equal(await kickedWith(blank), `${prefix}Error: zz-blank\n\n\n at zzThrower (blank.js:1:1)`); +}); + test('a thrown non-Error, and an error whose projection throws, still log bounded lines', async () => { const thrownString = makeHarness({ tick: async () => { throw `socket said: ${echo()}`; } }); try { @@ -410,6 +477,19 @@ test('a provider hold keeps a bounded reason, and a failed resume logs the bound assert.match(threwLine, /treating as no hold: MembraneError \(invalid_request, HTTP 400, zz_bad_request, retryable=false\): Bad request: zz-head/); assert.match(threwLine, /\n {4}at /); + // One that throws a plain object logs its JSON, bounded, so the fields that + // printing the object showed are kept. + const thrown = { code: 'zz_hold', detail: echo() }; + const plain = makeHarness(); + providerState(plain.fw); + try { + plain.fw.providerHoldHook = () => { throw thrown; }; + assert.equal(plain.fw.holdProviderAcceleration(plain.fw.agents.get('cairn'), hugeProviderError()), false); + } finally { plain.restore(); } + const plainLine = assertBoundedStrings(plain.rawArgs, 'providerHold hook threw'); + const noHold = 'treating as no hold: '; + assertCut(JSON.stringify(thrown), plainLine.slice(plainLine.indexOf(noHold) + noHold.length), 2_000, 'a thrown plain object'); + // The built-in acceleration cooldown keeps the error's own message as its reason. const accelerated = makeHarness(); providerState(accelerated.fw); @@ -499,6 +579,30 @@ test('alert data of null, from a JavaScript caller, is no data: the alert is sti assert.deepEqual(logged, [{ agent: 'cairn', kind: 'zz-detector', reason: 'short message' }]); }); +test('alert data that is not a plain object is one bounded field, not a field per character or element', () => { + const { fw, traces, logged, restore } = makeHarness(); + const text = echo(10_000); + const list = Array.from({ length: 2_000 }, (_, i) => i); + try { + // From a JavaScript caller: bounded field by field, a string or an array + // would spread into a field per character or element. + fw.notifyOpsAlert('zz-string', 'cairn', 'short message', text); + fw.notifyOpsAlert('zz-array', 'cairn', 'short message', list); + fw.notifyOpsAlert('zz-small', 'cairn', 'short message', [1, 2]); + } finally { restore(); } + const [stringAlert, arrayAlert, smallAlert] = traces.filter((t) => t.type === 'ops:alert'); + for (const [sink, fields] of [['trace', stringAlert.data], ['failures.log', logged[0]]] as const) { + assert.equal(Object.keys(fields).length, sink === 'trace' ? 1 : 4, `${sink}: string data's fields`); + assertCut(text, fields.data, 2_000, `${sink}: string data`); + } + for (const [sink, fields] of [['trace', arrayAlert.data], ['failures.log', logged[1]]] as const) { + assert.equal(Object.keys(fields).length, sink === 'trace' ? 1 : 4, `${sink}: array data's fields`); + assertCut(JSON.stringify(list), fields.data, 2_000, `${sink}: array data`); + } + assert.deepEqual(smallAlert.data, { data: [1, 2] }); + assert.deepEqual(logged[2], { agent: 'cairn', kind: 'zz-small', reason: 'short message', data: [1, 2] }); +}); + /** The projection's head for hugeProviderError(), before ': ' and the message. */ const HUGE_ERROR_HEAD = 'MembraneError (invalid_request, HTTP 400, zz_bad_request, retryable=false)'; @@ -512,6 +616,8 @@ test('alert data is bounded field by field, on the trace and the failures.log re text, error, nested, count: 3, small: { a: 1 }, // Small JSON, large value: the listener gets the JSON's data, not the value. held: new Map([['zz', echo()]]), at: new Date(0), + // An Error inside a value is its projection too. + wrapped: { cause: new Error('zz-small') }, }); } finally { restore(); } const alert = traces.find((t) => t.type === 'ops:alert'); @@ -520,6 +626,7 @@ test('alert data is bounded field by field, on the trace and the failures.log re // An Error is its projection: serialising it would write its rawRequest. // It is cut once, so its marker states the head and the whole message. assertCut(`${HUGE_ERROR_HEAD}: ${error.message}`, fields.error, 2_000, `${sink}: error`); + assert.deepEqual(fields.wrapped, { cause: 'Error: zz-small' }, `${sink}: a nested Error`); // A value whose JSON is too long becomes its JSON, bounded. assert.equal(typeof fields.nested, 'string', `${sink}: nested`); assert.ok(fields.nested.length <= 2_000 && fields.nested.startsWith('{"items":[{"i":0,'), `${sink}: nested`); @@ -545,9 +652,10 @@ test('logFailure bounds every field it writes', () => { fw.logFailure({ agent: 'cairn', reason, note, consecutive: 1, error, nested: { list: Array.from({ length: 2_000 }, (_, i) => i) }, circular, + wrapped: { cause: error }, }); const line = readFileSync(join(dir, 'logs', 'failures.log'), 'utf-8').trim(); - assert.ok(line.length < 9_000, `failures.log line is ${line.length} chars`); + assert.ok(line.length < 11_000, `failures.log line is ${line.length} chars`); const record = JSON.parse(line); // The written record, not what a caller passed: each string is cut by the one rule. assertCut(reason, record.reason, 2_000, 'failures.log reason'); @@ -555,6 +663,10 @@ test('logFailure bounds every field it writes', () => { assert.equal(record.consecutive, 1); assertCut(`${HUGE_ERROR_HEAD}: ${error.message}`, record.error, 2_000, 'failures.log error'); assert.ok(typeof record.nested === 'string' && record.nested.length <= 2_000); + // An Error inside a value is written as its projection, not its own + // fields with the request. + assert.ok(typeof record.wrapped === 'string' && record.wrapped.length <= 2_000, 'failures.log wrapped'); + assert.ok(record.wrapped.startsWith(`{"cause":"${HUGE_ERROR_HEAD}: Bad request: zz-head`), record.wrapped.slice(0, 120)); // A value JSON can't write no longer loses the whole record. assert.equal(record.circular, '[object Object]'); } finally { @@ -632,7 +744,7 @@ function assertNoObjectPrinted(rawArgs: unknown[][]): void { /** Never retries, so a test reaches exhaustion on the first failure. */ const noRetry: ErrorPolicy = { maxRetries: 0, onInferenceError: () => ({ retry: false }) }; -async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => Error, opts?: { errorPolicy?: ErrorPolicy }) { +async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => Error, opts?: { errorPolicy?: ErrorPolicy; turns?: number }) { const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); const cwd = process.cwd(); process.chdir(dir); @@ -647,13 +759,15 @@ async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => const traces: any[] = []; framework.onTrace((e) => traces.push(e)); try { - framework.pushEvent({ type: 'external-message', source: 'test', content: 'hello', metadata: {} }); - await framework.runUntilIdle(); + for (let turn = 0; turn < (opts?.turns ?? 1); turn++) { + framework.pushEvent({ type: 'external-message', source: 'test', content: `hello ${turn}`, metadata: {} }); + await framework.runUntilIdle(); + } const messages = framework.getAgent('resident')!.getContextManager().queryMessages({}).messages; const markers = messages.filter((m) => (m.metadata as { kind?: string } | undefined)?.kind === 'inference-failed'); const failuresLog = existsSync(join(dir, 'logs', 'failures.log')) ? readFileSync(join(dir, 'logs', 'failures.log'), 'utf-8') : ''; const inferenceLogs = framework.queryInferenceLogs({}).entries; - return { markers, traces, errs, rawArgs, failuresLog, inferenceLogs, calls: membrane.calls.length }; + return { messages, markers, traces, errs, rawArgs, failuresLog, inferenceLogs, calls: membrane.calls.length }; } finally { await framework.stop(); restore(); @@ -738,6 +852,19 @@ test('a MembraneError from another copy of membrane is recognised by its name', assert.equal(errs.some((e) => e.includes('drain kicked')), false); assertNoObjectPrinted(rawArgs); + // Classified, it gets the poisoned-history quarantine at the hard-down + // threshold, as the framework's own copy does: the newest exchanges are + // shed, each retry on the rewound history failing again, up to the rewind + // cap, and the one rewind marker counts them. + const shed = await runFailingTurn('stream error event', () => foreignMembraneError(quoted), { turns: 3 }); + const counts = shed.errs.map((e) => /^\[inference-rewind\] agent=resident auto-quarantined .* \((\d+) turn\(s\) shed this episode, cap 3\)/.exec(e)?.[1]) + .filter((count): count is string => count !== undefined); + assert.deepEqual(counts, ['1', '2', '3']); + assert.equal(shed.messages.filter((m) => !(m.metadata as { system?: unknown } | undefined)?.system).length, 0, 'the three exchanges are shed'); + const rewind = shed.messages.filter((m) => (m.metadata as { kind?: string } | undefined)?.kind === 'refusal-rewind'); + assert.equal(rewind.length, 1); + assert.match((rewind[0].content[0] as { text: string }).text, /^\[refusal-rewind\] The 3 most recent turn\(s\) were set aside/); + // Its type is bounded like a provider code, in every sink it reaches. const odd = await runFailingTurn('stream throws', () => foreignMembraneError('Bad request: zz-short', `zz${'T'.repeat(MEGA)}`), { errorPolicy: noRetry }); const exhausted = odd.traces.find((t) => t.type === 'inference:exhausted'); From 831a5f8474eb2cd908c5b972f1099b8618ff6129 Mon Sep 17 00:00:00 2001 From: Gladys-2413 Date: Tue, 13 Oct 2026 10:21:45 -0400 Subject: [PATCH 12/18] fix(failures): print a thrown value's own text before its JSON; record a non-string alert message as its String The previous commit printed a thrown value that isn't an Error as its JSON whenever JSON could write it. That kept a plain object's fields, but it lost the text of values whose meaning is their String: a class with its own toString and no enumerable fields printed {}, a Buffer printed its byte array, and an Error from another realm, which fails instanceof Error, printed {} where String gave "Error: ". failureDescription now takes the String when it is text of its own, and an object's JSON only when its String is just the tag ([object Object], [object Foo]). The tag stands when JSON can't write the value (a cycle, a BigInt) or finds no fields in it, since the tag at least names its type. opsAlert bounded the raw message before any sink, so a JavaScript host that passed notifyOps or notifyOpsAlert a message that isn't a string got a TypeError, where main recorded the alert. The message is now its String in every sink and the webhook. Tests: each thrown-value case (a class with its own toString, a Buffer, an Error from a vm context, a plain object, a class instance without toString, a cyclic object, an object with only a tag); an undefined alert message; a class instance passed as alert data, kept whole under data, and a null-prototype record, spread; an Error inside an array in alert data, written as its projection. The drain-kick helper is shared by the thrown-value and frames tests. The changelog states the thrown-value rule, the non-string message, and that a failures.log value JSON can't write is written as its String while the record is kept. Co-Authored-By: Claude Opus 5.5 --- ...ix-bounded-inference-failure-text.fixed.md | 6 +- src/framework.ts | 34 ++++++---- test/inference-failure-bounds.test.ts | 68 +++++++++++++++---- 3 files changed, 80 insertions(+), 28 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index 74283eedf..494fbfd5a 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -4,15 +4,15 @@ - The rewind marker's reason is cut to 160 characters, an agent's `lastInference.lastError` and the compile-refused ops alert's to 300, and the ops webhook's copy of the alert's message to 500. Each bound includes the marker. - Each of these is bounded to 2,000 characters: - the reason excerpt in the exhaustion stderr line (the line also carries the agent, the streak and `type=… status=… code=…` labels when known); - - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as its JSON, with any `Error` inside it written as its projection, kept as data when it fits and as bounded text when it doesn't. A record with a value JSON can't write is no longer lost; - - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is, so a trace listener gets the plain data the log writes: a `Date` as its ISO string, a `Map` as `{}`, an `Error` as its projection. Data that isn't a plain object, such as a string or an array from a JavaScript caller, is kept as one field, `data`, rather than spread into a field per character or element; + - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as its JSON, with any `Error` inside it written as its projection, kept as data when it fits and as bounded text when it doesn't. A record with a value JSON can't write, such as one with a cycle, is no longer lost: that value is written as its `String`; + - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is, so a trace listener gets the plain data the log writes: a `Date` as its ISO string, a `Map` as `{}`, an `Error` as its projection. Data that isn't a plain object, such as a string or an array from a JavaScript caller, is kept as one field, `data`, rather than spread into a field per character or element, and a message that isn't a string is recorded as its `String` rather than thrown on; - the inference log's `error`; - every trace event's `error` and `stack` strings; - the provider cooldown's reason, in its stderr lines and the status snapshot's `cooldownReason`; - the error an ephemeral run (`runEphemeralToCompletion`) rejects with. `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. The error type and the provider code are recorded to at most 128 characters each. - - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. A thrown value that isn't an `Error` is printed as its JSON, bounded, with any `Error` inside it as its projection, or as its `String` when JSON can't write it, so a thrown plain object keeps its fields. The stack's frames follow on the lines below, also bounded to 2,000 characters: from after the message when the message is the stack's header, and otherwise from the stack's first frame line. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. + - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. A thrown value that isn't an `Error` is printed as its `String` when that's text of its own, as for a `Buffer`, an `Error` from another realm or a class with its own `toString`. When its `String` is only its tag, such as `[object Object]`, it's printed as its JSON, bounded, with any `Error` inside it as its projection, so a thrown plain object keeps its fields; the tag stands when JSON can't write the value or finds no fields in it. The stack's frames follow on the lines below, also bounded to 2,000 characters: from after the message when the message is the stack's header, and otherwise from the stack's first frame line. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - This bound doesn't depend on membrane bounding its own errors. - A `MembraneError` from another copy of membrane is recognised by its name as well as by its class, since the host supplies the `Membrane` instance and two copies can be installed. Its failure is classified, and so gets the framework's recovery for its class: an invalid request now sheds the newest exchanges of the agent's history, up to the rewind cap, as the poisoned-history quarantine does for the framework's own copy. The default error policy reads its `retryable` and `retryAfterMs`, and an organization acceleration limit it reports is held, as for the framework's own copy. Before, each treated it as an unknown error: the default policy retried a non-retryable one up to three times, and its failure was then left unclassified. diff --git a/src/framework.ts b/src/framework.ts index 1180f0ed2..b90500568 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1029,22 +1029,27 @@ function failureJson(value: unknown): string | undefined { } /** - * The whole text describeFailure cuts: for an Error, its head (name, + * The whole text describeFailure cuts. For an Error, its head (name, * classification, status, provider code, each bounded) and its whole - * message; for another object, its JSON (failureJson), or its String when - * JSON can't write it, so a thrown plain object keeps its fields; for - * anything else, its String. + * message. For anything else, its String when that's text of its own (a + * string, a Buffer, an Error from another realm, a class with its own + * toString). An object whose String is only its tag, such as + * `[object Object]`, is its JSON instead (failureJson), so a plain object + * keeps its fields; the tag stands when JSON can't write it or finds no + * fields to write. */ function failureDescription(error: unknown): string { try { if (!(error instanceof Error)) { - if (typeof error === 'object' && error !== null) { - try { - const json = failureJson(error); - if (json !== undefined) return json; - } catch { /* its String, below */ } - } - return String(error); + if (typeof error !== 'object' || error === null) return String(error); + let text: string | undefined; + try { text = String(error); } catch { /* no String: its JSON, below */ } + if (text !== undefined && !/^\[object [^\]]*\]$/.test(text)) return text; + try { + const json = failureJson(error); + if (json !== undefined && json !== '{}') return json; + } catch { /* the tag, below */ } + return text ?? '[failure could not be described]'; } const fields = error as Error & { type?: unknown; httpStatus?: unknown; providerErrorCode?: unknown; retryable?: unknown; @@ -12875,7 +12880,10 @@ export class AgentFramework { rawMessage: string, opts?: { data?: Record; skipLog?: boolean }, ): void { - const message = boundFailureText(rawMessage); + // A JavaScript caller of notifyOps or notifyOpsAlert can pass a message + // that isn't a string; it's recorded as its String rather than thrown on. + const wholeMessage = String(rawMessage); + const message = boundFailureText(wholeMessage); // The caller's data goes to failures.log and to trace listeners, bounded // the same way for both. A JavaScript caller's null is no data, and data // that isn't a plain object (a string, an array, a Buffer) is kept as one @@ -12901,7 +12909,7 @@ export class AgentFramework { method: 'POST', headers: { 'content-type': 'application/json' }, body: JSON.stringify({ - content: `\u{1F6A8} **${agentName}** ${kind}: ${boundFailureText(rawMessage, OPS_WEBHOOK_MESSAGE_MAX_CHARS)}`, + content: `\u{1F6A8} **${agentName}** ${kind}: ${boundFailureText(wholeMessage, OPS_WEBHOOK_MESSAGE_MAX_CHARS)}`, }), }).catch((err) => console.error( `[ops-alert] webhook post failed (${key}):`, diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index e86306878..a3c347297 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -14,6 +14,7 @@ import assert from 'node:assert/strict'; import { mkdtempSync, readFileSync, rmSync, existsSync } from 'node:fs'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; +import vm from 'node:vm'; import { MembraneError } from '@animalabs/membrane'; import type { NormalizedRequest, StreamEvent, YieldingStream } from '@animalabs/membrane'; import type { ContextEntry, ContextLogView, ContextStrategy, MessageStoreView, ReadinessState, StrategyContext, TokenBudget } from '@animalabs/context-manager'; @@ -373,15 +374,41 @@ test('failure logs print a bounded projection, never the error object with its r assertBoundedStrings(odd.rawArgs, 'drain kick failed'); }); +/** The line a drain kick logs when the context manager's tick throws `thrown`. */ +async function kickedWith(thrown: unknown): Promise { + const kicked = makeHarness({ tick: async () => { throw thrown; } }); + try { + kicked.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); + await settle(); + } finally { kicked.restore(); } + return assertBoundedStrings(kicked.rawArgs, 'drain kick failed'); +} + +test("a thrown value that isn't an Error logs its own text, or its JSON when its text is only a tag", async () => { + const prefix = '[inference-failed] drain kick failed for cairn after 0 ticks: '; + class Refusal { + readonly #why: string; + constructor(why: string) { this.#why = why; } + toString(): string { return `refused: ${this.#why}`; } + } + class Payload { code = 'zz_code'; detail = 'zz-detail'; } + const cyclic: Record = { zz: 1 }; + cyclic.self = cyclic; + const cases: Array<[string, unknown, string]> = [ + ['a class with its own toString', new Refusal('zz-quota'), 'refused: zz-quota'], + ['a Buffer', Buffer.from('zz-buffer text'), 'zz-buffer text'], + ['an Error from another realm', vm.runInNewContext("new Error('zz-realm')"), 'Error: zz-realm'], + ['a plain object', { code: 'zz_plain', count: 1 }, '{"code":"zz_plain","count":1}'], + ['a class instance without toString', new Payload(), '{"code":"zz_code","detail":"zz-detail"}'], + ['an object JSON cannot write', cyclic, '[object Object]'], + ['an object with no fields but its tag', { [Symbol.toStringTag]: 'ZzTagged' }, '[object ZzTagged]'], + ]; + for (const [what, thrown, logged] of cases) { + assert.equal(await kickedWith(thrown), `${prefix}${logged}`, what); + } +}); + test("a failure's frames: cut to their bound, and from the stack's first frame line when the message isn't its header", async () => { - const kickedWith = async (thrown: Error) => { - const kicked = makeHarness({ tick: async () => { throw thrown; } }); - try { - kicked.fw.noteInferenceExhausted('cairn', 'Context would exceed hard budget', undefined, 'over_budget'); - await settle(); - } finally { kicked.restore(); } - return assertBoundedStrings(kicked.rawArgs, 'drain kick failed'); - }; const prefix = '[inference-failed] drain kick failed for cairn after 0 ticks: '; const framesOf = (stack: string) => stack.slice(stack.search(/^[ \t]+at /m)); @@ -579,6 +606,15 @@ test('alert data of null, from a JavaScript caller, is no data: the alert is sti assert.deepEqual(logged, [{ agent: 'cairn', kind: 'zz-detector', reason: 'short message' }]); }); +test('an alert message that is not a string, from a JavaScript caller, is recorded as its String', () => { + const { fw, traces, logged, restore } = makeHarness(); + try { + fw.notifyOpsAlert('zz-untyped', 'cairn', undefined, { count: 1 }); + } finally { restore(); } + assert.equal(traces.find((t) => t.type === 'ops:alert')?.message, 'undefined'); + assert.deepEqual(logged, [{ agent: 'cairn', kind: 'zz-untyped', reason: 'undefined', count: 1 }]); +}); + test('alert data that is not a plain object is one bounded field, not a field per character or element', () => { const { fw, traces, logged, restore } = makeHarness(); const text = echo(10_000); @@ -589,8 +625,16 @@ test('alert data that is not a plain object is one bounded field, not a field pe fw.notifyOpsAlert('zz-string', 'cairn', 'short message', text); fw.notifyOpsAlert('zz-array', 'cairn', 'short message', list); fw.notifyOpsAlert('zz-small', 'cairn', 'short message', [1, 2]); + // Only a plain object's fields are spread: a class instance is kept whole + // as its JSON, and an object with a null prototype is a plain record. + fw.notifyOpsAlert('zz-instance', 'cairn', 'short message', new (class ZzPayload { channel = 'zz-channel'; })()); + fw.notifyOpsAlert('zz-record', 'cairn', 'short message', Object.assign(Object.create(null), { channel: 'zz-channel' })); } finally { restore(); } - const [stringAlert, arrayAlert, smallAlert] = traces.filter((t) => t.type === 'ops:alert'); + const [stringAlert, arrayAlert, smallAlert, instanceAlert, recordAlert] = traces.filter((t) => t.type === 'ops:alert'); + assert.deepEqual(instanceAlert.data, { data: { channel: 'zz-channel' } }); + assert.deepEqual(logged[3], { agent: 'cairn', kind: 'zz-instance', reason: 'short message', data: { channel: 'zz-channel' } }); + assert.deepEqual({ ...recordAlert.data }, { channel: 'zz-channel' }); + assert.deepEqual(logged[4], { agent: 'cairn', kind: 'zz-record', reason: 'short message', channel: 'zz-channel' }); for (const [sink, fields] of [['trace', stringAlert.data], ['failures.log', logged[0]]] as const) { assert.equal(Object.keys(fields).length, sink === 'trace' ? 1 : 4, `${sink}: string data's fields`); assertCut(text, fields.data, 2_000, `${sink}: string data`); @@ -616,8 +660,8 @@ test('alert data is bounded field by field, on the trace and the failures.log re text, error, nested, count: 3, small: { a: 1 }, // Small JSON, large value: the listener gets the JSON's data, not the value. held: new Map([['zz', echo()]]), at: new Date(0), - // An Error inside a value is its projection too. - wrapped: { cause: new Error('zz-small') }, + // An Error inside a value is its projection too, in an array as well. + wrapped: { cause: new Error('zz-small'), list: [new Error('zz-item')] }, }); } finally { restore(); } const alert = traces.find((t) => t.type === 'ops:alert'); @@ -626,7 +670,7 @@ test('alert data is bounded field by field, on the trace and the failures.log re // An Error is its projection: serialising it would write its rawRequest. // It is cut once, so its marker states the head and the whole message. assertCut(`${HUGE_ERROR_HEAD}: ${error.message}`, fields.error, 2_000, `${sink}: error`); - assert.deepEqual(fields.wrapped, { cause: 'Error: zz-small' }, `${sink}: a nested Error`); + assert.deepEqual(fields.wrapped, { cause: 'Error: zz-small', list: ['Error: zz-item'] }, `${sink}: nested Errors`); // A value whose JSON is too long becomes its JSON, bounded. assert.equal(typeof fields.nested, 'string', `${sink}: nested`); assert.ok(fields.nested.length <= 2_000 && fields.nested.startsWith('{"items":[{"i":0,'), `${sink}: nested`); From 98568c418f1bafc729580f55b841b03798fdc042 Mon Sep 17 00:00:00 2001 From: Gladys-2413 Date: Tue, 13 Oct 2026 10:34:27 -0400 Subject: [PATCH 13/18] fix(failures): describe an array by its JSON, fall back to a value's tag, and describe a non-string alert message and a maintenance throw the same way failureDescription took any object's String unless it was exactly a tag. An array's String is the join of its elements' Strings, which loses them: an array holding a plain object and an Error printed "[object Object],Error: ...", and `[]` printed nothing (an array of plain objects alone printed its JSON, since its String is only a tag). An object whose toString returns "" printed nothing too. An array is now its JSON, as is an object whose String is empty or only a tag. When neither gives text (JSON throws on a cycle, or finds no fields), the value's tag stands, from Object.prototype.toString, which also covers an object with no String of its own, such as one with a null prototype, which used to fall to the placeholder. opsAlert took String(rawMessage), which throws for a message with no String of its own, such as a null-prototype object, so notifyOps and notifyOpsAlert could still throw into a JavaScript host. A non-string message is now described as a thrown value is, which never throws, and a plain-object message keeps its fields. Context maintenance described a thrown non-Error with a bare String in both its catches, which throws inside the catch for a null-prototype value. It now uses failureDescription as the other failure logs do; an Error's message is logged as before. Tests: the thrown-value table adds an array holding a plain object and an Error, an empty array, an object with no String of its own, with fields and without, and an object whose String is empty; the non-string message test adds a null-prototype message and checks what the webhook posts; the maintenance-pass test throws a null-prototype object. The changelog says a failures.log value JSON throws on is described as a thrown value is, and that one JSON writes nothing for, such as a function, is left out as JSON leaves it out. Co-Authored-By: Claude Opus 5.5 --- ...ix-bounded-inference-failure-text.fixed.md | 6 +-- src/framework.ts | 33 +++++++------ test/inference-failure-bounds.test.ts | 46 +++++++++++++++++-- 3 files changed, 63 insertions(+), 22 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index 494fbfd5a..5fb4d4b1b 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -4,15 +4,15 @@ - The rewind marker's reason is cut to 160 characters, an agent's `lastInference.lastError` and the compile-refused ops alert's to 300, and the ops webhook's copy of the alert's message to 500. Each bound includes the marker. - Each of these is bounded to 2,000 characters: - the reason excerpt in the exhaustion stderr line (the line also carries the agent, the streak and `type=… status=… code=…` labels when known); - - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as its JSON, with any `Error` inside it written as its projection, kept as data when it fits and as bounded text when it doesn't. A record with a value JSON can't write, such as one with a cycle, is no longer lost: that value is written as its `String`; - - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is, so a trace listener gets the plain data the log writes: a `Date` as its ISO string, a `Map` as `{}`, an `Error` as its projection. Data that isn't a plain object, such as a string or an array from a JavaScript caller, is kept as one field, `data`, rather than spread into a field per character or element, and a message that isn't a string is recorded as its `String` rather than thrown on; + - every field of a `logs/failures.log` record: a string to 2,000 characters, an `Error` as its projection (below), and any other value as its JSON, with any `Error` inside it written as its projection, kept as data when it fits and as bounded text when it doesn't. A record with a value JSON throws on, such as one with a cycle, is no longer lost: that value is described as a thrown value is (below). A value JSON writes nothing for, such as a function, is left out, as JSON leaves it out; + - ops alert messages, and an alert's `data` on its `ops:alert` trace, bounded field by field as a failures.log record is, so a trace listener gets the plain data the log writes: a `Date` as its ISO string, a `Map` as `{}`, an `Error` as its projection. Data that isn't a plain object, such as a string or an array from a JavaScript caller, is kept as one field, `data`, rather than spread into a field per character or element, and a message that isn't a string is described as a thrown value is (below) rather than thrown on; - the inference log's `error`; - every trace event's `error` and `stack` strings; - the provider cooldown's reason, in its stderr lines and the status snapshot's `cooldownReason`; - the error an ephemeral run (`runEphemeralToCompletion`) rejects with. `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. The error type and the provider code are recorded to at most 128 characters each. - - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. A thrown value that isn't an `Error` is printed as its `String` when that's text of its own, as for a `Buffer`, an `Error` from another realm or a class with its own `toString`. When its `String` is only its tag, such as `[object Object]`, it's printed as its JSON, bounded, with any `Error` inside it as its projection, so a thrown plain object keeps its fields; the tag stands when JSON can't write the value or finds no fields in it. The stack's frames follow on the lines below, also bounded to 2,000 characters: from after the message when the message is the stack's header, and otherwise from the stack's first frame line. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. + - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. A thrown value that isn't an `Error` is printed as its `String` when that's text of its own, as for a `Buffer`, an `Error` from another realm or a class with its own `toString`. An array, or an object whose `String` is empty or only its tag, such as `[object Object]`, is printed as its JSON, bounded, with any `Error` inside it as its projection, so a thrown plain object keeps its fields and an array its elements; the tag stands when JSON can't write the value or finds nothing in it. Context maintenance describes one the same way. The stack's frames follow on the lines below, also bounded to 2,000 characters: from after the message when the message is the stack's header, and otherwise from the stack's first frame line. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - This bound doesn't depend on membrane bounding its own errors. - A `MembraneError` from another copy of membrane is recognised by its name as well as by its class, since the host supplies the `Membrane` instance and two copies can be installed. Its failure is classified, and so gets the framework's recovery for its class: an invalid request now sheds the newest exchanges of the agent's history, up to the rewind cap, as the poisoned-history quarantine does for the framework's own copy. The default error policy reads its `retryable` and `retryAfterMs`, and an organization acceleration limit it reports is held, as for the framework's own copy. Before, each treated it as an unknown error: the default policy retried a non-retryable one up to three times, and its failure was then left unclassified. diff --git a/src/framework.ts b/src/framework.ts index b90500568..b97df4d78 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1031,25 +1031,27 @@ function failureJson(value: unknown): string | undefined { /** * The whole text describeFailure cuts. For an Error, its head (name, * classification, status, provider code, each bounded) and its whole - * message. For anything else, its String when that's text of its own (a - * string, a Buffer, an Error from another realm, a class with its own - * toString). An object whose String is only its tag, such as - * `[object Object]`, is its JSON instead (failureJson), so a plain object - * keeps its fields; the tag stands when JSON can't write it or finds no - * fields to write. + * message. For a primitive, its String. For another object, its String when + * that's text of its own (a Buffer, an Error from another realm, a class + * with its own toString). An array, or an object whose String is empty or + * only its tag, such as `[object Object]`, is its JSON instead + * (failureJson), so its fields and elements are kept; its tag stands when + * JSON can't write it or finds nothing in it. */ function failureDescription(error: unknown): string { try { if (!(error instanceof Error)) { if (typeof error !== 'object' || error === null) return String(error); - let text: string | undefined; - try { text = String(error); } catch { /* no String: its JSON, below */ } - if (text !== undefined && !/^\[object [^\]]*\]$/.test(text)) return text; + if (!Array.isArray(error)) { + let text: string | undefined; + try { text = String(error); } catch { /* no String of its own: its JSON, below */ } + if (text && !/^\[object [^\]]*\]$/.test(text)) return text; + } try { const json = failureJson(error); if (json !== undefined && json !== '{}') return json; - } catch { /* the tag, below */ } - return text ?? '[failure could not be described]'; + } catch { /* its tag, below */ } + return Object.prototype.toString.call(error); } const fields = error as Error & { type?: unknown; httpStatus?: unknown; providerErrorCode?: unknown; retryable?: unknown; @@ -2424,7 +2426,7 @@ export class AgentFramework { private startQueuedMaintenance(): void { if (this.maintenancePass || !this.running) return; const pass = this.runQueuedMaintenance().catch((error) => { - const reason = boundFailureText(error instanceof Error ? error.message : String(error)); + const reason = boundFailureText(error instanceof Error ? error.message : failureDescription(error)); console.error( '[context-maintenance] pass failed:', reason, @@ -2491,7 +2493,7 @@ export class AgentFramework { record.ticks++; } } catch (error) { - record.error = boundFailureText(error instanceof Error ? error.message : String(error)); + record.error = boundFailureText(error instanceof Error ? error.message : failureDescription(error)); console.error(`[context-maintenance] agent=${agent.name} failed:`, record.error); this.opsAlert( 'context-maintenance-failed', @@ -12881,8 +12883,9 @@ export class AgentFramework { opts?: { data?: Record; skipLog?: boolean }, ): void { // A JavaScript caller of notifyOps or notifyOpsAlert can pass a message - // that isn't a string; it's recorded as its String rather than thrown on. - const wholeMessage = String(rawMessage); + // that isn't a string; it's described as a thrown value is, rather than + // thrown on. + const wholeMessage = typeof rawMessage === 'string' ? rawMessage : failureDescription(rawMessage); const message = boundFailureText(wholeMessage); // The caller's data goes to failures.log and to trace listeners, bounded // the same way for both. A JavaScript caller's null is no data, and data diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index a3c347297..6625bb40a 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -400,8 +400,14 @@ test("a thrown value that isn't an Error logs its own text, or its JSON when its ['an Error from another realm', vm.runInNewContext("new Error('zz-realm')"), 'Error: zz-realm'], ['a plain object', { code: 'zz_plain', count: 1 }, '{"code":"zz_plain","count":1}'], ['a class instance without toString', new Payload(), '{"code":"zz_code","detail":"zz-detail"}'], + // An array's String joins its elements' Strings; its JSON keeps them. + ['an array', [{ code: 'zz_a' }, new Error('zz-item')], '[{"code":"zz_a"},"Error: zz-item"]'], + ['an empty array', [], '[]'], + ['an object with no String of its own', Object.assign(Object.create(null), { code: 'zz_bare' }), '{"code":"zz_bare"}'], ['an object JSON cannot write', cyclic, '[object Object]'], ['an object with no fields but its tag', { [Symbol.toStringTag]: 'ZzTagged' }, '[object ZzTagged]'], + ['an object whose String is empty', { toString: () => '' }, '[object Object]'], + ['an object with neither a String nor fields', Object.create(null), '[object Object]'], ]; for (const [what, thrown, logged] of cases) { assert.equal(await kickedWith(thrown), `${prefix}${logged}`, what); @@ -565,6 +571,18 @@ test('a failed maintenance pass logs and alerts a bounded reason', async () => { const alert = traces.find((t) => t.type === 'ops:alert' && t.kind === 'context-maintenance-failed'); assert.ok(alert && alert.message.length <= 2_000); assert.deepEqual(alert.data, { scope: 'pass' }); + + // A thrown value that isn't an Error is described as the other logs + // describe one, with no String() to throw on it. + const bare = makeHarness(); + bare.fw.running = true; + bare.fw.maintenancePass = null; + bare.fw.runQueuedMaintenance = async () => { throw Object.assign(Object.create(null), { code: 'zz_bare' }); }; + try { + bare.fw.startQueuedMaintenance(); + await settle(); + } finally { bare.restore(); } + assert.match(assertBoundedStrings(bare.rawArgs, '[context-maintenance] pass failed:'), /pass failed: \{"code":"zz_bare"\}$/); }); test('emitTrace: listeners get bounded error and stack; the marker still learns the full length', () => { @@ -606,13 +624,33 @@ test('alert data of null, from a JavaScript caller, is no data: the alert is sti assert.deepEqual(logged, [{ agent: 'cairn', kind: 'zz-detector', reason: 'short message' }]); }); -test('an alert message that is not a string, from a JavaScript caller, is recorded as its String', () => { +test('an alert message that is not a string, from a JavaScript caller, is described as a thrown value is', async () => { + const hook = process.env.CONNECTOME_OPS_WEBHOOK; + const realFetch = globalThis.fetch; + const posted: string[] = []; + process.env.CONNECTOME_OPS_WEBHOOK = 'http://zz.invalid/hook'; + globalThis.fetch = (async (_url: unknown, init?: { body?: unknown }) => { + posted.push(JSON.parse(String(init?.body)).content); + return new Response(null); + }) as typeof fetch; const { fw, traces, logged, restore } = makeHarness(); try { fw.notifyOpsAlert('zz-untyped', 'cairn', undefined, { count: 1 }); - } finally { restore(); } - assert.equal(traces.find((t) => t.type === 'ops:alert')?.message, 'undefined'); - assert.deepEqual(logged, [{ agent: 'cairn', kind: 'zz-untyped', reason: 'undefined', count: 1 }]); + // One with no String of its own, which String() throws on. + fw.notifyOpsAlert('zz-bare', 'cairn', Object.assign(Object.create(null), { code: 'zz_bare' })); + await settle(); + } finally { + restore(); + globalThis.fetch = realFetch; + if (hook === undefined) delete process.env.CONNECTOME_OPS_WEBHOOK; + else process.env.CONNECTOME_OPS_WEBHOOK = hook; + } + assert.deepEqual(traces.filter((t) => t.type === 'ops:alert').map((t) => t.message), ['undefined', '{"code":"zz_bare"}']); + assert.deepEqual(logged, [ + { agent: 'cairn', kind: 'zz-untyped', reason: 'undefined', count: 1 }, + { agent: 'cairn', kind: 'zz-bare', reason: '{"code":"zz_bare"}' }, + ]); + assert.deepEqual(posted, ['\u{1F6A8} **cairn** zz-untyped: undefined', '\u{1F6A8} **cairn** zz-bare: {"code":"zz_bare"}']); }); test('alert data that is not a plain object is one bounded field, not a field per character or element', () => { From d68ba53df519a8c556f83bf1735a2cc963be76d0 Mon Sep 17 00:00:00 2001 From: Gladys-2413 Date: Tue, 13 Oct 2026 10:41:44 -0400 Subject: [PATCH 14/18] test(failures): assert only the first shed of another copy's quarantine The test for another membrane copy's invalid request asserted three sheds over three failed turns: the third failure's shed, then two more from the retries each shed queues on the rewound history. Those retries race the test's stop: runUntilIdle can return before a retry's inference has failed, so one run on the Anima VPS saw only the first shed and failed against a source that had the behaviour. The test now asserts what the third failure itself does: the auto-quarantine line counts one turn, the newest exchange is gone from the history, and one rewind marker holds the count. Five runs in a row pass. Co-Authored-By: Claude Opus 5.5 --- test/inference-failure-bounds.test.ts | 21 ++++++++++++--------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index 6625bb40a..c89841b43 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -935,17 +935,20 @@ test('a MembraneError from another copy of membrane is recognised by its name', assertNoObjectPrinted(rawArgs); // Classified, it gets the poisoned-history quarantine at the hard-down - // threshold, as the framework's own copy does: the newest exchanges are - // shed, each retry on the rewound history failing again, up to the rewind - // cap, and the one rewind marker counts them. + // threshold, as the framework's own copy does: the third failure sheds the + // newest exchange, counted in the one rewind marker. Each shed queues a + // retry on the rewound history, which may fail and shed again before the + // run is stopped, so only the first shed is asserted. const shed = await runFailingTurn('stream error event', () => foreignMembraneError(quoted), { turns: 3 }); - const counts = shed.errs.map((e) => /^\[inference-rewind\] agent=resident auto-quarantined .* \((\d+) turn\(s\) shed this episode, cap 3\)/.exec(e)?.[1]) - .filter((count): count is string => count !== undefined); - assert.deepEqual(counts, ['1', '2', '3']); - assert.equal(shed.messages.filter((m) => !(m.metadata as { system?: unknown } | undefined)?.system).length, 0, 'the three exchanges are shed'); + const quarantined = shed.errs.filter((e) => e.startsWith('[inference-rewind] agent=resident auto-quarantined')); + assert.ok(quarantined.length > 0, 'the third failure sheds'); + assert.match(quarantined[0], /\(1 turn\(s\) shed this episode, cap 3\)/); + const kept = shed.messages.filter((m) => !(m.metadata as { system?: unknown } | undefined)?.system) + .map((m) => (m.content[0] as { text: string }).text); + assert.ok(!kept.includes('hello 2'), 'the newest exchange is shed'); const rewind = shed.messages.filter((m) => (m.metadata as { kind?: string } | undefined)?.kind === 'refusal-rewind'); - assert.equal(rewind.length, 1); - assert.match((rewind[0].content[0] as { text: string }).text, /^\[refusal-rewind\] The 3 most recent turn\(s\) were set aside/); + assert.equal(rewind.length, 1, 'one consolidated rewind marker'); + assert.match((rewind[0].content[0] as { text: string }).text, /^\[refusal-rewind\] The \d+ most recent turn\(s\) were set aside/); // Its type is bounded like a provider code, in every sink it reaches. const odd = await runFailingTurn('stream throws', () => foreignMembraneError('Bad request: zz-short', `zz${'T'.repeat(MEGA)}`), { errorPolicy: noRetry }); From 1b34dd7d9dbed15f7e9ebe0339b7535bfdb4f4b3 Mon Sep 17 00:00:00 2001 From: Gladys-2413 Date: Tue, 13 Oct 2026 10:52:45 -0400 Subject: [PATCH 15/18] fix(failures): cut maintenance alerts once from the whole message; leave out a field JSON writes nothing for Both context-maintenance catches passed the failure's 2,000-character excerpt to opsAlert, which then cut its webhook copy from the excerpt, so the webhook's marker stated 2,000 rather than the message's length. They now pass the whole message, and opsAlert cuts each copy once, as the other failure sinks do; the record and the stderr line keep their 2,000-character excerpt. boundFailureFields kept a field whose value JSON writes nothing for (a function, undefined) as undefined, so an ops:alert trace listener saw a key the failures.log record leaves out. Such a field is now left out of both. opsAlert described a non-string message with failureDescription behind a typeof check that changed nothing, since failureDescription returns a string as it is; the check is gone. Tests: an object whose toJSON returns undefined is described by its tag; a function-valued field is left out of alert data in both sinks; the maintenance pass and a real framework's per-agent maintenance failure each post a webhook copy cut from the whole message, and the per-agent catch describes a thrown null-prototype object by its JSON. The webhook stub is one helper, shared by the tests that post. The changelog says the tag stands when JSON finds no fields in an object, and that maintenance alerts are cut once from the whole message. Co-Authored-By: Claude Opus 5.5 --- ...ix-bounded-inference-failure-text.fixed.md | 2 +- src/framework.ts | 22 ++-- test/inference-failure-bounds.test.ts | 123 ++++++++++++------ 3 files changed, 96 insertions(+), 51 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index 5fb4d4b1b..162703c2f 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -12,7 +12,7 @@ - the error an ephemeral run (`runEphemeralToCompletion`) rejects with. `inference:exhausted` traces and failures.log records add `httpStatus` and `providerErrorCode`, and a failures.log record adds `reasonChars` when its own excerpt was cut. The error type and the provider code are recorded to at most 128 characters each. - - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. A thrown value that isn't an `Error` is printed as its `String` when that's text of its own, as for a `Buffer`, an `Error` from another realm or a class with its own `toString`. An array, or an object whose `String` is empty or only its tag, such as `[object Object]`, is printed as its JSON, bounded, with any `Error` inside it as its projection, so a thrown plain object keeps its fields and an array its elements; the tag stands when JSON can't write the value or finds nothing in it. Context maintenance describes one the same way. The stack's frames follow on the lines below, also bounded to 2,000 characters: from after the message when the message is the stack's header, and otherwise from the stack's first frame line. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. + - The OverBudget drain kick, the marker write and the provider-cooldown resume used to print the error object when they failed, as did a host's `providerHold` hook when it threw (the hook is handed the model's error, and can throw it back). They now print a bounded projection instead: name, classification, status, provider code and message, cut once to 2,000 characters as one text after the name, type and provider code are bounded, on one line unless one of its parts has newlines, as a message can. A thrown value that isn't an `Error` is printed as its `String` when that's text of its own, as for a `Buffer`, an `Error` from another realm or a class with its own `toString`. An array, or an object whose `String` is empty or only its tag, such as `[object Object]`, is printed as its JSON, bounded, with any `Error` inside it as its projection, so a thrown plain object keeps its fields and an array its elements; the tag stands when JSON can't write the value or finds no fields in an object. Context maintenance describes one the same way, and its alert's copies, the webhook's included, are cut once from the whole message. The stack's frames follow on the lines below, also bounded to 2,000 characters: from after the message when the message is the stack's header, and otherwise from the stack's first frame line. Printing a `MembraneError` printed its message whole, in the stack, and its `rawRequest` with each string up to Node's 10,000-character limit, a long system prompt among them. Context maintenance records and logs a bounded message, in its existing format. - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - This bound doesn't depend on membrane bounding its own errors. - A `MembraneError` from another copy of membrane is recognised by its name as well as by its class, since the host supplies the `Membrane` instance and two copies can be installed. Its failure is classified, and so gets the framework's recovery for its class: an invalid request now sheds the newest exchanges of the agent's history, up to the rewind cap, as the poisoned-history quarantine does for the framework's own copy. The default error policy reads its `retryable` and `retryAfterMs`, and an organization acceleration limit it reports is held, as for the framework's own copy. Before, each treated it as an unknown error: the default policy retried a non-retryable one up to three times, and its failure was then left unclassified. diff --git a/src/framework.ts b/src/framework.ts index b97df4d78..a6d9a44a7 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1143,8 +1143,10 @@ function boundFailureFields(record: Record): Record { - const reason = boundFailureText(error instanceof Error ? error.message : failureDescription(error)); + // The alert cuts its own copies from the whole message, so the + // webhook's states the whole length. + const wholeReason = error instanceof Error ? String(error.message) : failureDescription(error); + const reason = boundFailureText(wholeReason); console.error( '[context-maintenance] pass failed:', reason, @@ -2434,7 +2439,7 @@ export class AgentFramework { this.opsAlert( 'context-maintenance-failed', 'framework', - reason, + wholeReason, { data: { scope: 'pass' } }, ); }); @@ -2493,12 +2498,13 @@ export class AgentFramework { record.ticks++; } } catch (error) { - record.error = boundFailureText(error instanceof Error ? error.message : failureDescription(error)); + const wholeError = error instanceof Error ? String(error.message) : failureDescription(error); + record.error = boundFailureText(wholeError); console.error(`[context-maintenance] agent=${agent.name} failed:`, record.error); this.opsAlert( 'context-maintenance-failed', agent.name, - record.error, + wholeError, { data: { scope: 'agent', @@ -12884,8 +12890,8 @@ export class AgentFramework { ): void { // A JavaScript caller of notifyOps or notifyOpsAlert can pass a message // that isn't a string; it's described as a thrown value is, rather than - // thrown on. - const wholeMessage = typeof rawMessage === 'string' ? rawMessage : failureDescription(rawMessage); + // thrown on (a string is its own description). + const wholeMessage = failureDescription(rawMessage); const message = boundFailureText(wholeMessage); // The caller's data goes to failures.log and to trace listeners, bounded // the same way for both. A JavaScript caller's null is no data, and data diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index c89841b43..81af7da6b 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -408,6 +408,7 @@ test("a thrown value that isn't an Error logs its own text, or its JSON when its ['an object with no fields but its tag', { [Symbol.toStringTag]: 'ZzTagged' }, '[object ZzTagged]'], ['an object whose String is empty', { toString: () => '' }, '[object Object]'], ['an object with neither a String nor fields', Object.create(null), '[object Object]'], + ['an object whose JSON is nothing', { toJSON: () => undefined }, '[object Object]'], ]; for (const [what, thrown, logged] of cases) { assert.equal(await kickedWith(thrown), `${prefix}${logged}`, what); @@ -558,19 +559,46 @@ test('a provider hold keeps a bounded reason, and a failed resume logs the bound assert.match(line, /\n {4}at /); }); +/** Runs `body` with the ops webhook set and fetch stubbed; returns what it posted. */ +async function withWebhook(body: () => Promise | void): Promise { + const hook = process.env.CONNECTOME_OPS_WEBHOOK; + const realFetch = globalThis.fetch; + const posted: string[] = []; + process.env.CONNECTOME_OPS_WEBHOOK = 'http://zz.invalid/hook'; + globalThis.fetch = (async (_url: unknown, init?: { body?: unknown }) => { + posted.push(JSON.parse(String(init?.body)).content); + return new Response(null); + }) as typeof fetch; + try { + await body(); + } finally { + globalThis.fetch = realFetch; + if (hook === undefined) delete process.env.CONNECTOME_OPS_WEBHOOK; + else process.env.CONNECTOME_OPS_WEBHOOK = hook; + } + return posted; +} + test('a failed maintenance pass logs and alerts a bounded reason', async () => { const { fw, traces, rawArgs, restore } = makeHarness(); fw.running = true; fw.maintenancePass = null; - fw.runQueuedMaintenance = async () => { throw hugeProviderError(); }; - try { - fw.startQueuedMaintenance(); - await settle(); - } finally { restore(); } + const error = hugeProviderError(); + fw.runQueuedMaintenance = async () => { throw error; }; + const posted = await withWebhook(async () => { + try { + fw.startQueuedMaintenance(); + await settle(); + } finally { restore(); } + }); assert.match(assertBoundedStrings(rawArgs, '[context-maintenance] pass failed:'), /pass failed: Bad request: zz-head/); const alert = traces.find((t) => t.type === 'ops:alert' && t.kind === 'context-maintenance-failed'); assert.ok(alert && alert.message.length <= 2_000); assert.deepEqual(alert.data, { scope: 'pass' }); + // The webhook's copy is cut from the whole message, so it states its length. + const webhook = '\u{1F6A8} **framework** context-maintenance-failed: '; + assert.ok(posted[0]?.startsWith(webhook), posted[0]?.slice(0, 80)); + assertCut(error.message, posted[0].slice(webhook.length), 500, 'maintenance webhook'); // A thrown value that isn't an Error is described as the other logs // describe one, with no String() to throw on it. @@ -625,26 +653,14 @@ test('alert data of null, from a JavaScript caller, is no data: the alert is sti }); test('an alert message that is not a string, from a JavaScript caller, is described as a thrown value is', async () => { - const hook = process.env.CONNECTOME_OPS_WEBHOOK; - const realFetch = globalThis.fetch; - const posted: string[] = []; - process.env.CONNECTOME_OPS_WEBHOOK = 'http://zz.invalid/hook'; - globalThis.fetch = (async (_url: unknown, init?: { body?: unknown }) => { - posted.push(JSON.parse(String(init?.body)).content); - return new Response(null); - }) as typeof fetch; const { fw, traces, logged, restore } = makeHarness(); - try { - fw.notifyOpsAlert('zz-untyped', 'cairn', undefined, { count: 1 }); - // One with no String of its own, which String() throws on. - fw.notifyOpsAlert('zz-bare', 'cairn', Object.assign(Object.create(null), { code: 'zz_bare' })); - await settle(); - } finally { - restore(); - globalThis.fetch = realFetch; - if (hook === undefined) delete process.env.CONNECTOME_OPS_WEBHOOK; - else process.env.CONNECTOME_OPS_WEBHOOK = hook; - } + const posted = await withWebhook(() => { + try { + fw.notifyOpsAlert('zz-untyped', 'cairn', undefined, { count: 1 }); + // One with no String of its own, which String() throws on. + fw.notifyOpsAlert('zz-bare', 'cairn', Object.assign(Object.create(null), { code: 'zz_bare' })); + } finally { restore(); } + }); assert.deepEqual(traces.filter((t) => t.type === 'ops:alert').map((t) => t.message), ['undefined', '{"code":"zz_bare"}']); assert.deepEqual(logged, [ { agent: 'cairn', kind: 'zz-untyped', reason: 'undefined', count: 1 }, @@ -700,6 +716,8 @@ test('alert data is bounded field by field, on the trace and the failures.log re held: new Map([['zz', echo()]]), at: new Date(0), // An Error inside a value is its projection too, in an array as well. wrapped: { cause: new Error('zz-small'), list: [new Error('zz-item')] }, + // A value JSON writes nothing for is left out, as the log's JSON leaves it out. + callback: () => 'zz', }); } finally { restore(); } const alert = traces.find((t) => t.type === 'ops:alert'); @@ -709,6 +727,7 @@ test('alert data is bounded field by field, on the trace and the failures.log re // It is cut once, so its marker states the head and the whole message. assertCut(`${HUGE_ERROR_HEAD}: ${error.message}`, fields.error, 2_000, `${sink}: error`); assert.deepEqual(fields.wrapped, { cause: 'Error: zz-small', list: ['Error: zz-item'] }, `${sink}: nested Errors`); + assert.equal('callback' in fields, false, `${sink}: a function is left out`); // A value whose JSON is too long becomes its JSON, bounded. assert.equal(typeof fields.nested, 'string', `${sink}: nested`); assert.ok(fields.nested.length <= 2_000 && fields.nested.startsWith('{"items":[{"i":0,'), `${sink}: nested`); @@ -1032,43 +1051,63 @@ test('an ephemeral run rejects with the bounded failure text', async () => { } }); -class HugeFailureStrategy implements ContextStrategy { - readonly name = 'huge-failure-maintenance-test'; +class FailingStrategy implements ContextStrategy { + readonly name = 'failing-maintenance-test'; + constructor(private readonly make: () => unknown) {} checkReadiness(): ReadinessState { return { ready: false, description: 'compression blocked' }; } - async tick(_ctx: StrategyContext): Promise { throw hugeProviderError(); } + async tick(_ctx: StrategyContext): Promise { throw this.make(); } select(_store: MessageStoreView, _log: ContextLogView, _budget: TokenBudget): ContextEntry[] { return []; } } -test('a ~1 MB maintenance failure: bounded record, ops alert and stderr', async () => { +/** A real framework's first maintenance pass, its agent's tick throwing `make()`, with the ops webhook set. */ +async function runFailingMaintenance(make: () => unknown) { const dir = mkdtempSync(join(tmpdir(), 'af-failure-bounds-')); const cwd = process.cwd(); process.chdir(dir); const { errs, rawArgs, restore } = spyConsoleError(); const framework = await AgentFramework.create({ storePath: join(dir, 'store.chronicle'), membrane: new MockMembrane().asMembrane(), - agents: [{ name: 'agent', model: 'test-model', systemPrompt: 'test', strategy: new HugeFailureStrategy() }], + agents: [{ name: 'agent', model: 'test-model', systemPrompt: 'test', strategy: new FailingStrategy(make) }], modules: [], syncIntervalMs: 0, maintenanceIntervalMs: 10, }); const traces: any[] = []; framework.onTrace((e) => traces.push(e)); try { - framework.start(); - const deadline = Date.now() + 5_000; - while (framework.getContextMaintenanceSnapshot().history.length === 0 && Date.now() < deadline) { - await new Promise((resolve) => setTimeout(resolve, 10)); - } - const record = framework.getContextMaintenanceSnapshot().history[0].agents[0]; - assert.ok(typeof record.error === 'string' && record.error.length <= 2_000, `maintenance record error is ${record.error?.length} chars`); - assert.match(record.error!, /^Bad request: zz-head/); - const alert = traces.find((t) => t.type === 'ops:alert' && t.kind === 'context-maintenance-failed'); - assert.ok(alert && alert.message.length <= 2_000); - const longest = errs.reduce((max, e) => Math.max(max, e.length), 0); - assert.ok(longest < 4_500, `longest stderr line is ${longest} chars`); - assertNoObjectPrinted(rawArgs); + let record: any; + const posted = await withWebhook(async () => { + framework.start(); + const deadline = Date.now() + 5_000; + while (framework.getContextMaintenanceSnapshot().history.length === 0 && Date.now() < deadline) { + await new Promise((resolve) => setTimeout(resolve, 10)); + } + record = framework.getContextMaintenanceSnapshot().history[0].agents[0]; + }); + return { record, traces, errs, rawArgs, posted }; } finally { await framework.stop(); restore(); process.chdir(cwd); rmSync(dir, { recursive: true, force: true }); } +} + +test('a ~1 MB maintenance failure: bounded record, ops alert and stderr', async () => { + const error = hugeProviderError(); + const { record, traces, errs, rawArgs, posted } = await runFailingMaintenance(() => error); + assert.ok(typeof record.error === 'string' && record.error.length <= 2_000, `maintenance record error is ${record.error?.length} chars`); + assert.match(record.error, /^Bad request: zz-head/); + const alert = traces.find((t) => t.type === 'ops:alert' && t.kind === 'context-maintenance-failed'); + assert.ok(alert && alert.message.length <= 2_000); + const longest = errs.reduce((max, e) => Math.max(max, e.length), 0); + assert.ok(longest < 4_500, `longest stderr line is ${longest} chars`); + assertNoObjectPrinted(rawArgs); + // The webhook's copy is cut from the whole message, so it states its length. + const webhook = '\u{1F6A8} **agent** context-maintenance-failed: '; + const content = posted.find((c) => c.startsWith(webhook)); + assert.ok(content, 'the webhook posted the alert'); + assertCut(error.message, content.slice(webhook.length), 500, 'maintenance webhook'); + + // A thrown value that isn't an Error is described as the other logs describe one. + const bare = await runFailingMaintenance(() => Object.assign(Object.create(null), { code: 'zz_bare' })); + assert.equal(bare.record.error, '{"code":"zz_bare"}'); }); From eecf9434b4c17dc1907e78788ed7f86778409f93 Mon Sep 17 00:00:00 2001 From: Gladys-2413 Date: Tue, 13 Oct 2026 11:24:17 -0400 Subject: [PATCH 16/18] fix(failures): write a nested Error's whole projection, so its value is cut once failureJson's replacer wrote an Error inside a value as describeFailure, which already cuts the projection to 2,000 characters. The sink then cut the value's JSON again, so the inner marker, the one stating the true length, fell inside the second cut's omission, and the record stated the excerpt's length: `{ cause: new Error(1 MB) }` was written with "48 of 2011 characters omitted" for a 1,000,035-character value. The replacer now writes the whole projection (failureDescription), as a nested string is written whole, and the sink's one cut states the whole length. A nested Error's message is serialised whole before that cut, as a nested string's already is. The replacer serves failures.log fields, alert data on the trace, and thrown values that hold an Error (the drain kick, the providerHold hook, context maintenance), so each now states the whole length. Test: the on-disk logFailure record's nested Error is checked as one cut of its whole JSON, which fails against the previous commit. Found by Naomi-2422's review, with a probe at 1b34dd7. Co-Authored-By: Claude Opus 5.5 --- src/framework.ts | 9 +++++---- test/inference-failure-bounds.test.ts | 7 +++---- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/src/framework.ts b/src/framework.ts index a6d9a44a7..c9dfdec61 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1020,12 +1020,13 @@ function boundProviderErrorCode(code: unknown): string | undefined { /** * A value's JSON for a failure sink, with every Error inside it written as its - * projection (describeFailure): serialising an Error writes its own fields, a - * MembraneError's whole `rawRequest` among them. Throws, or returns undefined, - * as JSON.stringify does. + * whole projection (failureDescription): serialising an Error writes its own + * fields, a MembraneError's whole `rawRequest` among them. The projection is + * left uncut, as a nested string is, so the sink's one cut of the JSON states + * its whole length. Throws, or returns undefined, as JSON.stringify does. */ function failureJson(value: unknown): string | undefined { - return JSON.stringify(value, (_key, nested: unknown) => (nested instanceof Error ? describeFailure(nested) : nested)); + return JSON.stringify(value, (_key, nested: unknown) => (nested instanceof Error ? failureDescription(nested) : nested)); } /** diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index 81af7da6b..fc6acad27 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -764,10 +764,9 @@ test('logFailure bounds every field it writes', () => { assert.equal(record.consecutive, 1); assertCut(`${HUGE_ERROR_HEAD}: ${error.message}`, record.error, 2_000, 'failures.log error'); assert.ok(typeof record.nested === 'string' && record.nested.length <= 2_000); - // An Error inside a value is written as its projection, not its own - // fields with the request. - assert.ok(typeof record.wrapped === 'string' && record.wrapped.length <= 2_000, 'failures.log wrapped'); - assert.ok(record.wrapped.startsWith(`{"cause":"${HUGE_ERROR_HEAD}: Bad request: zz-head`), record.wrapped.slice(0, 120)); + // An Error inside a value is written as its whole projection, not its own + // fields with the request, and the value's JSON is cut once. + assertCut(JSON.stringify({ cause: `${HUGE_ERROR_HEAD}: ${error.message}` }), record.wrapped, 2_000, 'failures.log wrapped'); // A value JSON can't write no longer loses the whole record. assert.equal(record.circular, '[object Object]'); } finally { From 424f832d59dab5538bb93855beb1a21ea90fc194 Mon Sep 17 00:00:00 2001 From: Gladys-2413 Date: Tue, 13 Oct 2026 11:32:48 -0400 Subject: [PATCH 17/18] test(failures): subscribe the harness's trace observer through onTrace The prototype harness assigned a bare callback to the framework's private traceListeners array. #318 changes that array to registration objects, so when the two compose the harness's observer would be skipped and every trace assertion would fail. The harness now starts an empty list and subscribes through onTrace, as a caller does and as #318's own fixtures now do, which holds under either form of the list. Found by Arthur-2378's read of eecf943 against #318. Co-Authored-By: Claude Opus 5.5 --- test/inference-failure-bounds.test.ts | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index fc6acad27..c4ab300c2 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -57,7 +57,10 @@ function makeHarness(opts?: { tick?: () => Promise; addMessage?: (p: strin fw.opsAlertLastSent = new Map(); fw.opsAlertCooldownMs = 15 * 60_000; const traces: any[] = []; - fw.traceListeners = [(e: any) => traces.push(e)]; + // Subscribed as a caller does, so the harness holds whatever form the + // framework keeps its listeners in. + fw.traceListeners = []; + fw.onTrace((e: any) => traces.push(e)); const logged: Array> = []; fw.logFailure = (r: Record) => logged.push(r); const markers: Array<{ text: string; meta: any }> = []; From f25e7b763a7f1c071f3498082e60935b18d812d3 Mon Sep 17 00:00:00 2001 From: Gladys-2413 Date: Tue, 13 Oct 2026 11:38:06 -0400 Subject: [PATCH 18/18] docs(failures): name the limit of the projection for an Error from another realm An Error is recognised by instanceof, so one from another realm (a vm context) nested inside a value is written as its own JSON, as any object is, rather than as its projection; at the top level a thrown one is printed as its String. The review judged that case not worth building for, but the changelog and failureJson's doc stated the projection for any Error inside a value. Both now name the limit. Raised by Arthur-2378 and Naomi-2422. Co-Authored-By: Claude Opus 5.5 --- changelog.d/fix-bounded-inference-failure-text.fixed.md | 2 +- src/framework.ts | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/changelog.d/fix-bounded-inference-failure-text.fixed.md b/changelog.d/fix-bounded-inference-failure-text.fixed.md index 162703c2f..986262afc 100644 --- a/changelog.d/fix-bounded-inference-failure-text.fixed.md +++ b/changelog.d/fix-bounded-inference-failure-text.fixed.md @@ -16,4 +16,4 @@ - The OverBudget drain breaker's message-text fallback now applies only to unclassified failures, and it is decided on the whole reason, never the excerpt. A classified provider error that quotes "exceed hard budget" or "no summary covers" (the agent's own context, echoed back) no longer kicks the compression drain. - This bound doesn't depend on membrane bounding its own errors. - A `MembraneError` from another copy of membrane is recognised by its name as well as by its class, since the host supplies the `Membrane` instance and two copies can be installed. Its failure is classified, and so gets the framework's recovery for its class: an invalid request now sheds the newest exchanges of the agent's history, up to the rewind cap, as the poisoned-history quarantine does for the framework's own copy. The default error policy reads its `retryable` and `retryAfterMs`, and an organization acceleration limit it reports is held, as for the framework's own copy. Before, each treated it as an unknown error: the default policy retried a non-retryable one up to three times, and its failure was then left unclassified. -- Not covered by this change: Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as the delivery evidence a resident reads before resending), logs outside the inference-failure pipeline that still print an error object, in modules and in the framework's own code (among them the `beforeInference` hook's catch and its preview's, the event loop's catch, periodic and final sync, and the maintenance pass's retry of the tool-result guard's storage), and two plain slices: the health report's 400 characters of the inference log's stored error (already bounded to 2,000), and the tool-result spill's 200 characters of a workspace write's failure. +- Not covered by this change: an `Error` from another realm (a `vm` context) nested inside a value, which fails `instanceof Error` and so is written as its own JSON rather than its projection (at the top level, a thrown one is printed as its `String`); Discord-awareness log sites, the speech-route failure reason and `[discord-send-failed]` marker (kept whole as the delivery evidence a resident reads before resending), logs outside the inference-failure pipeline that still print an error object, in modules and in the framework's own code (among them the `beforeInference` hook's catch and its preview's, the event loop's catch, periodic and final sync, and the maintenance pass's retry of the tool-result guard's storage), and two plain slices: the health report's 400 characters of the inference log's stored error (already bounded to 2,000), and the tool-result spill's 200 characters of a workspace write's failure. diff --git a/src/framework.ts b/src/framework.ts index c9dfdec61..ab032f0fe 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -1023,7 +1023,9 @@ function boundProviderErrorCode(code: unknown): string | undefined { * whole projection (failureDescription): serialising an Error writes its own * fields, a MembraneError's whole `rawRequest` among them. The projection is * left uncut, as a nested string is, so the sink's one cut of the JSON states - * its whole length. Throws, or returns undefined, as JSON.stringify does. + * its whole length. An Error is recognised by instanceof, so one from another + * realm (a vm context) is written as its own JSON, as any object is. Throws, + * or returns undefined, as JSON.stringify does. */ function failureJson(value: unknown): string | undefined { return JSON.stringify(value, (_key, nested: unknown) => (nested instanceof Error ? failureDescription(nested) : nested));