From 227878ad545b37d2da59286702f757246305c383 Mon Sep 17 00:00:00 2001 From: Alfred-2451 Date: Thu, 5 Nov 2026 18:40:47 -0500 Subject: [PATCH 1/6] fix(framework): an exhausted turn that did nothing writes no [inference-failed] note #979: every exhausted turn wrote an [inference-failed] note into the agent's context as a user row, which stayed until a fold or removal took it. A resident whose provider was down or whose context was too long gathered one per failed turn, and each was sent with every request after it. Per the maintainer's answer on #979 (issuecomment-6671382711), a turn that did nothing now writes no row: its failure is telemetry alone. A turn that got partway, that is one noteFailedTurnEnd recorded because a round ran or had its tool calls cut off, keeps one note, since that note is where the agent learns its calls may have taken effect, without the "change approach" advice. - src/framework.ts: - noteInferenceExhausted writes the note only for a turn noteFailedTurnEnd recorded. The "produced no response, so nothing was sent" wording goes with the case it described. - FAILURE_ADVICE goes. A timed-out turn's note keeps TIMEOUT_ADVICE ("If a reply is still owed from that turn, you can give it now."). - exhaustingRearms goes: its one reader was the note's `!(rearmed && !ended)`, which `ended` now decides alone. The set, its three adds, its clear in cancelProviderAdmission and its delete in releaseAgentRuntime go with it. - The stderr line, the failures.log record, the streak, lastInferenceAt, the inference:exhausted trace, the hard-down alert and the breaker are unchanged. SUPPRESS_INFERENCE_FAILED_MARKER=1 still leaves out the note, now the partway one. - The doc comments that described the note say what it is now, and two comments' clauses about the old note and its advice are cut. - src/types/framework.ts: exhaustedTurnRearmMs's doc said a re-armed turn's failure other than a transient one writes a note. It now says a failure of a re-armed turn writes one only when the turn got partway, as any turn's does. - src/agent.ts: the empty-block sanitizer's comment no longer says such a request writes a note on every attempt. The thinking-only guard's comment and stderr line pointed to an [inference-failed] notice for a refused turn. A refusal ends its stream as a completion and never reaches noteInferenceExhausted, so they name the [inference-refusal] line and failures.log's refusal record instead. Shown by a probe: a refused turn traced inference:completed and no inference:exhausted, wrote no [inference-failed] row, and left those two stderr lines and a failures.log record of kind refusal. - test/inference-failed-telemetry.test.ts, the issue's acceptance: - three exhausted turns that did nothing leave three failures.log records and stderr lines, and nothing in the context but what was said; - operators keep the failure's category, status and provider code in failures.log and stderr, and its request id in the inference log; - a framework reopened on the store holds none of them; - seventeen failures leave each next request as what was said before plus the new message; - a turn that got partway leaves exactly one note, with no advice; - a timed-out partway turn's note keeps TIMEOUT_ADVICE; - SUPPRESS_INFERENCE_FAILED_MARKER=1 leaves out the partway note. - Tests that pinned a note for a turn that did nothing now pin none, with the failure's telemetry where the note was their signal: exhausted-turn-rearm, inference-failure-observability, inference-failure-bounds, prose-drafts, provider-waits and turn-inputs-pin. Tests whose subject is the note's own text (its 600-character bound, its one-line cause and reason, "The call was made again", a 408's wording) drive a turn that got partway, so that text stays pinned: inference-bounds, inference-failure-bounds and one exhausted-turn-rearm test. - README: the bounds section says a doubly cut call's note exists only for a turn that got partway, and a new paragraph after the failure and stop notes says when the note is written. - changelog.d/979-inference-failed-telemetry.changed.md, with the sentences this makes untrue, old beside new: the README's, exhaustedTurnRearmMs's doc, and 0.29.0's and 0.31.0's. Red first: the new tests at main 074ac60be failed 4 of 7: the three did-nothing tests on the note they found, and the partway test on the advice. The telemetry, timeout and switch tests passed, as they pin what stays. Mutants against the new tests, with predictions written first, each failing exactly the tests predicted: - a row restored for a turn that did nothing: the three did-nothing tests; - the advice restored on the partway note: the partway test; - the partway note written twice: the partway and timeout tests. --- README.md | 4 +- .../979-inference-failed-telemetry.changed.md | 46 ++++ src/agent.ts | 11 +- src/framework.ts | 59 ++--- src/types/framework.ts | 8 +- test/exhausted-turn-rearm.test.ts | 52 ++--- test/inference-bounds.test.ts | 38 ++-- test/inference-failed-telemetry.test.ts | 212 ++++++++++++++++++ test/inference-failure-bounds.test.ts | 129 ++++++----- test/inference-failure-observability.test.ts | 17 +- test/prose-drafts.test.ts | 8 +- test/provider-waits.test.ts | 10 +- test/turn-inputs-pin.test.ts | 5 +- 13 files changed, 440 insertions(+), 159 deletions(-) create mode 100644 changelog.d/979-inference-failed-telemetry.changed.md create mode 100644 test/inference-failed-telemetry.test.ts diff --git a/README.md b/README.md index 09e158ac3..cfef37dbf 100644 --- a/README.md +++ b/README.md @@ -768,7 +768,7 @@ A model call that stops making progress is cut, so an agent isn't held by a prov - **A resident's streamed call**, and an MCPL server's streamed inference request, get membrane's progress bounds where the adapter's stream reports content (`AnthropicAdapter`, `BedrockAdapter`). Before content, a call ends 60 s after its send, or, once a thinking block has started, at the later of that and the block's allowance, its `max_tokens` at 87 tokens a second. Once content has begun, it ends after 150 s without a provider event, or after the block's allowance when the last event was a thinking block's start and the allowance is longer. Membrane's README gives the rules whole. - **Every streamed call the framework makes** also gets a flat bound from its last provider event: the larger of a setup term plus that allowance and 1,862 s (`FLAT_MINIMUM_MS`). The setup term is the larger of the before-content and between-events bounds, 150 s by default. So on an adapter with progress bounds the flat bound never runs out first. On one without, such as `OpenAICompatibleAdapter`, it's the only progress bound, and an SSE keepalive comment doesn't restart it, though a data frame that parses as an event does, a provider's own ping object included. - **A whole non-streamed call**, a compression's, the reply judge's, or an MCPL server's non-streamed inference request, ends the setup term plus its allowance after its send, or, when it names no `max_tokens`, at the larger of the setup term and the flat minimum, unless its caller passed a `progressTimeoutMs` of its own. Its caller gets the `timeout` error. The event gate's own 20 s judge timeout ends the reply judge's call first at the defaults. Context-manager takes a cut compression call as a transient failure: the lane pauses and tries again, so compression that never lands within its bound shows as a lane that keeps pausing, not as a failed turn, and is a reason to raise the bound. On an adapter whose `complete()` streams under the hood, such as membrane's OpenAI Responses adapter in subscription mode, membrane renews the bound at each parsed provider event, so there it runs from the last event, as a stream's flat bound does. -- **A turn's call a bound cuts** fails as a `timeout`, and `DefaultErrorPolicy` gives it one fresh call, 1 s later, whatever other failures its turn had, except in a turn sent again after its retries ran out, before one of its rounds has run or had its tool calls cut off, whose failures get no retries. A fresh call that's cut too, with no other failure between, ends the turn, and its `[inference-failed]` note says the call timed out, that the call was made again and timed out again, and the reason. For a bound's cut the reason names the bound that ran out and the host's setting for it. A deadline expiry membrane throws (the Anthropic adapter's own watchdogs, the SDK's request timeout, a runtime's fetch timeout on a silent connection) counts the same toward the fresh call and the turn's end, and its reason is its own message, which names no setting. A bound's cut isn't `retryable`, so a host's own `errorPolicy` that retries only retryable errors gives it no fresh call; an expiry membrane throws stays `retryable`, as membrane made it. +- **A turn's call a bound cuts** fails as a `timeout`, and `DefaultErrorPolicy` gives it one fresh call, 1 s later, whatever other failures its turn had, except in a turn sent again after its retries ran out, before one of its rounds has run or had its tool calls cut off, whose failures get no retries. A fresh call that's cut too, with no other failure between, ends the turn. If the turn got partway (see the `[inference-failed]` note below), its note says the call timed out, that the call was made again and timed out again, and the reason; a turn that did nothing gets no note, and its stderr line and `failures.log` record give the reason. For a bound's cut the reason names the bound that ran out and the host's setting for it. A deadline expiry membrane throws (the Anthropic adapter's own watchdogs, the SDK's request timeout, a runtime's fetch timeout on a silent connection) counts the same toward the fresh call and the turn's end, and its reason is its own message, which names no setting. A bound's cut isn't `retryable`, so a host's own `errorPolicy` that retries only retryable errors gives it no fresh call; an expiry membrane throws stays `retryable`, as membrane made it. - **A stream that keeps sending content** isn't ended by any of these, since content is progress. These bounds don't replace the deadlines below them: a silent connection still meets the runtime's own fetch timeout (360 s on Bun 1.4.4) and, on `AnthropicAdapter`, the adapter's 600 s first-event and idle watchdogs, so on a silent connection a bound raised past those is met by them first. @@ -806,6 +806,8 @@ A caller's stop and an operator's quiesce abandon also reach a turn that has no In XML tool mode, or with a membrane that gives a tool round no `roundContent`, such a round's speech reaches a channel only when its stream completes. When the stream ends any other way (a failure, a stop, a tool that ends the turn, an error policy's retry, a context-budget or tool-result-guard restart, a quiesce abandon or `stop()`), the rounds' words are already in the agent's context, and a `[speech-not-posted]` notice tells the agent that nothing it wrote before its tool calls in those rounds was posted, so it can send what should go out again. It's written once for those rounds: where the turn ends, or before a retry's or a restart's request is sent. A turn its own `skip_reply` ends, a silent turn, a round still waiting on its tools when its stream ends (which never reaches the context) and the rounds of a stream that completes get none. In XML tool mode with thinking on, a round whose text was only thinking gets the notice too, since the framework has only the round's raw text there. A failed turn's `[inference-failed]` note says that its earlier rounds ran when any round reached the context with its results, and that a round's tool calls were started and may have taken effect when any of its streams ended before that round's results came back; a caller's stop says the latter in its `[turn-interrupted]` note too. A turn that fails, or that a caller stops, writes no `[delivered]` receipt, so when its rounds' plain speech was delivered live (native tool mode, in locus or hybrid routing), its `[inference-failed]` note, or the stop's `[turn-interrupted]` note, says that speech was handed on for delivery as written and that no `[delivered]` line was written for it. When some of its speech was still being routed as the turn ended, the note also says it may yet be posted and to check the channel before sending it again. A delivery that finished undelivered gets neither: a channel delivery's `[discord-send-failed]` note, or a refused `>>>` envelope's bounce, already says what happened. A quiesce abandon and `stop()` write neither note. +A failed turn writes its `[inference-failed]` note only when it got partway: when one of its rounds reached the agent's context with its results, or had its tool calls started and cut off. A turn that failed before either writes no note: its failure goes to operators alone, as before, in stderr's `[inference-failed] agent=…` line, `failures.log`'s `inference-exhausted` record and the `inference:exhausted` trace, and a message that woke it is already in the agent's context. So a failure that comes back at every turn's first call, such as a provider that's down or a context that's too long, no longer grows the agent's context. A turn that got partway gets one note, which says how far it got and the reason, and, when its last call timed out, that a reply still owed can be given now. `SUPPRESS_INFERENCE_FAILED_MARKER=1` leaves that note out. Notes already in a store stay. + ## API Server WebSocket server for external clients (UIs, scripts, other agents). diff --git a/changelog.d/979-inference-failed-telemetry.changed.md b/changelog.d/979-inference-failed-telemetry.changed.md new file mode 100644 index 000000000..3d32d4381 --- /dev/null +++ b/changelog.d/979-inference-failed-telemetry.changed.md @@ -0,0 +1,46 @@ +- **Residents:** a turn whose inference is exhausted before it got partway + writes no `[inference-failed]` note into the agent's context. Partway means + one of its rounds reached the context with its results, or had its tool + calls started and cut off. Its failure goes to operators alone: + stderr's `[inference-failed] agent=…` line, `failures.log`'s + `inference-exhausted` record, the consecutive-failure streak, the + `inference:exhausted` trace, the hard-down alert and the poison-history + breaker, each as before. So a failure that comes back at every turn's first + call, such as a provider that's down or a context that's too long, no longer + adds a note per turn to the context it's sent with (#979). + - A turn that got partway still gets one note, which says how far it got + (its earlier rounds ran, or a round's tool calls were started and may + have taken effect) and the reason, without the advice + "If this recurs with the same cause, change approach rather than retrying + identically (e.g. drop an oversized attachment or an unsupported + setting)." A timed-out turn's note keeps "If a reply is still owed from + that turn, you can give it now." + - `SUPPRESS_INFERENCE_FAILED_MARKER=1` now leaves out only that note, since + no other is written. + - Notes already in a store stay as they are. + - What this changes in what's published: + - README, a turn's call a bound cuts: "A fresh call that's cut too, with + no other failure between, ends the turn, and its `[inference-failed]` + note says the call timed out, that the call was made again and timed + out again, and the reason" now reads that the turn's note says so if + the turn got partway, and that a turn that did nothing gets no note. + - README, after the failure and stop notes: a new paragraph says when the + note is written, as above. + - `FrameworkConfig.exhaustedTurnRearmMs`'s doc: "A re-armed turn's + transient failure writes no `[inference-failed]` marker unless a round + of it ran or had its tool calls cut off; any other failure of it writes + one." Now a failure of a re-armed turn writes a note only when a round + of it ran or had its tool calls cut off, as any turn's failure does. + - 0.29.0: "A re-armed turn's transient failure writes no + `[inference-failed]` marker unless it got partway, so the agent's + context keeps the one the first exhaustion wrote; a failure of another + kind writes its own." Now no failure of a turn that didn't get partway + writes one, the first exhaustion's included, whatever its kind. + - 0.31.0: "A turn that ends on a timeout says so in its + `[inference-failed]` note: the model call timed out, or its last call + did … Other failures keep their wording and advice." Now only a turn + that got partway has the note, which says its last call timed out, and + no failure's note carries the advice. + - Earlier entries' wording of the note for a turn that did nothing ("the + model call failed … and produced no response, so nothing was sent") + describes only notes already in stores. diff --git a/src/agent.ts b/src/agent.ts index d0c820a75..0b2b81d42 100644 --- a/src/agent.ts +++ b/src/agent.ts @@ -1983,8 +1983,7 @@ export class Agent { // no content. The Anthropic API rejects empty text blocks with 400 // "messages: text content blocks must be non-empty"; when such a block // reaches a live activation request the agent cannot complete ANY turn - // ([inference-failed] on every attempt) until the offending message ages - // out of the window. Empty text blocks occur naturally: tool-only turns, + // until the offending message ages out of the window. Empty text blocks occur naturally: tool-only turns, // delivery-failure placeholders, silent/skip turns. Non-text blocks pass // through unchanged, so tool pairing is unaffected. (Field-observed // 2026-07-10 on a resident agent: one empty block muted the agent's live @@ -2372,16 +2371,16 @@ export class Agent { // in the latest assistant message cannot be modified", unrecoverable by // retry (labclaude, 2026-07-27: hard down ~4h on exactly this pair). // - // Refused turns are surfaced by the refusal path (stderr, failures.log, - // the [inference-failed] notice); the store does not also need a - // content-free artifact of them. Loud, never silent. + // Refused turns are surfaced by the refusal path (stderr's + // [inference-refusal] line and failures.log's refusal record); the store + // does not also need a content-free artifact of them. Loud, never silent. if (content.length > 0 && content.every( (b) => b.type === 'thinking' || b.type === 'redacted_thinking', )) { console.error( `[assistant-persist] agent=${this.name}: refusing to store a thinking-only assistant ` + `message (${content.length} block(s), no text and no tool_use) — the turn produced no ` + - `output. See the refusal/inference-failed record for why.`, + `output. If it was refused, its [inference-refusal] line and failures.log record say why.`, ); return undefined; } diff --git a/src/framework.ts b/src/framework.ts index a100d3c4c..7e5501dd7 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -2668,8 +2668,6 @@ const PROVIDER_ACCELERATION_DEFAULT_COOLDOWN_MS = 65_000; * longest stated wait an ephemeral run sleeps in its turn: a longer one ends * the run instead (nonOwningProviderWait). */ const PROVIDER_ACCELERATION_MAX_COOLDOWN_MS = 10 * 60_000; -const FAILURE_ADVICE = 'If this recurs with the same cause, change approach rather than retrying identically ' + - '(e.g. drop an oversized attachment or an unsupported setting).'; const TIMEOUT_ADVICE = 'If a reply is still owed from that turn, you can give it now.'; const MADE_AGAIN = 'The call was made again, and it timed out again.'; const OVERLOADED_TURN_TRIES = 13; @@ -4005,7 +4003,6 @@ export class AgentFramework { private consecutiveInferenceFailures: Map = new Map(); private turnRearmMs: readonly number[] = DEFAULT_TURN_REARM_MS; private turnRearms: Map = new Map(); - private exhaustingRearms: Set = new Set(); private rearmDeadlineCuts: Set = new Set(); private statedWaitRuns: Map = new Map(); /** N consecutive failed inferences ⇒ the agent is treated as hard-down and @@ -7153,7 +7150,7 @@ export class AgentFramework { private cancelProviderAdmission(): void { for (const cooldown of this.providerAccelerationCooldowns.values()) clearTimeout(cooldown.timer); this.providerAccelerationCooldowns.clear(); this.providerAccelerationRecoveries.clear(); - this.turnRearms?.clear(); this.exhaustingRearms?.clear(); + this.turnRearms?.clear(); for (const gate of this.providerGates.values()) { gate.primaryDepth = 0; gate.primaryPending = false; for (const resolve of gate.auxiliaryWaiters.splice(0)) resolve(); @@ -7718,10 +7715,8 @@ export class AgentFramework { * [turn-interrupted] marker, an attributable inference-log terminal, gate * release. Deliberately none of the failure accounting: inference:failed / * inference:exhausted feed the consecutive-failure streak, hard-down ops - * alerts, the poison-history breaker and the "[inference-failed]" marker — - * all of which told a resident, in the user's voice, that its turn failed - * and advised remediation for a failure that never happened — and - * errorPolicy would relaunch the very inference someone just stopped. + * alerts, the poison-history breaker and the "[inference-failed]" marker, + * and errorPolicy would relaunch the very inference someone just stopped. * * Only called while `agent` still owns stream `myStreamId`. */ @@ -7772,7 +7767,7 @@ export class AgentFramework { error: 'Stream cancelled', }, closes, stream); // Distinct trace type: emitTrace funnels every inference:exhausted into - // noteInferenceExhausted (streak, failures.log, marker); inference:aborted + // noteInferenceExhausted (streak, failures.log, a partway turn's note); inference:aborted // carries the honest cause without any of that. this.emitTrace({ type: 'inference:aborted', @@ -12128,7 +12123,6 @@ export class AgentFramework { // (endStatedWaitRun). this.turnRearms.delete(name); this.rearmDeadlineCuts.delete(name); - this.exhaustingRearms.delete(name); this.exhaustedTurns.delete(name); this.endStatedWaitRun(name); if (name === this.subconsciousAgentName) { @@ -25196,7 +25190,6 @@ export class AgentFramework { speech: '', ...(statedWait === 'fail' ? this.statedWaitNotSlept(err) : { error: err.message }), }, routing); - if (isRearmed(trigger) && asTransient) this.exhaustingRearms.add(agent.name); this.emitTrace({ type: 'inference:exhausted', agentName: agent.name, @@ -27049,7 +27042,6 @@ export class AgentFramework { speech: '', ...(statedWait === 'fail' ? this.statedWaitNotSlept(err) : { error: err.message }), }, this.agents.get(agent.name) === agent && agent.streamId === myStreamId ? streamRouting : undefined, streamRouting); - if (isRearmed(trigger) && asTransient) this.exhaustingRearms.add(agent.name); this.emitTrace({ type: 'inference:exhausted', agentName: agent.name, @@ -27094,11 +27086,7 @@ export class AgentFramework { // the host's Stop button, an admin abort, a subagent reclaim. // That is a DELIBERATE cancellation, not a failure, and it must // not feed the consecutive-failure streak, ops alerts, or the - // "[inference-failed] the model call failed" marker — all of - // which told the agent, in the user's voice, that its turn - // failed and advised remediation for a failure that never - // happened. For a long-lived resident whose transcript is - // memory, those accumulate as false self-knowledge. + // [inference-failed] note. // // What 'user' does NOT say is WHO cancelled: the wire reason // names the call, not the actor. Framework-owned cancels record @@ -27432,7 +27420,6 @@ export class AgentFramework { speech: '', ...(statedWait === 'fail' ? this.statedWaitNotSlept(err) : { error: err.message }), }, streamRouting); - if (isRearmed(trigger) && asTransient) this.exhaustingRearms.add(agent.name); this.emitTrace({ type: 'inference:exhausted', agentName: agent.name, @@ -32166,10 +32153,13 @@ export class AgentFramework { * * 1. stderr — always, with the underlying API reason. The place an * operator greps; previously empty in headless mode. - * 2. chronicle marker — a `[inference-failed]` message so the agent itself - * learns its turn failed and why (otherwise it's an experiential blank, - * indistinguishable from "not addressed"). addMessage does NOT request - * inference, so this never causes a retry/wake loop. + * 2. chronicle marker — for a turn that got partway (noteFailedTurnEnd + * recorded it: a round ran, or a round's tool calls were cut off), one + * `[inference-failed]` message, so the agent learns how far the turn + * got, which of its calls ran or may have taken effect, and why it + * failed. A turn that did nothing gets none: the failure is + * telemetry (#979). addMessage does NOT request inference, so this + * never causes a retry/wake loop. * 3. escalation — after N consecutive failures the agent is hard-down; * log that loudly (a repeated identical failure is the textbook signal). * 4. breaker — when a failure at or past the hard-down threshold suggests @@ -32528,7 +32518,6 @@ export class AgentFramework { ): void { const ended = this.exhaustedTurns?.get(agentName); this.exhaustedTurns?.delete(agentName); - const rearmed = this.exhaustingRearms?.delete(agentName) === true; const madeAgain = this.freshCallsCut?.delete(agentName) === true; // The reason is the failure's own message, and a provider can echo the // whole rejected request in it: one household's [inference-failed] @@ -32583,9 +32572,9 @@ export class AgentFramework { // classification fields are additive. this.logFailure({ agent: agentName, consecutive: streak, reason, kind: 'inference-exhausted', ...classification, ...cutAt(reason) }); - // (2) Agent-facing chronicle marker (no inference triggered → no loop). + // (2) Agent-facing chronicle marker, for a turn that got partway only (no inference triggered → no loop). const agent = this.agents.get(agentName); - if (agent && !(rearmed && !ended) && process.env.SUPPRESS_INFERENCE_FAILED_MARKER !== '1') { + if (agent && ended && process.env.SUPPRESS_INFERENCE_FAILED_MARKER !== '1') { const timedOut = errorType === 'timeout'; const causeParts = [errorType, httpStatus !== undefined ? `HTTP ${httpStatus}` : undefined] .filter((part): part is string => part !== undefined); @@ -32596,18 +32585,14 @@ export class AgentFramework { [{ type: 'text', text: - (ended - ? `[${NOTICE_TAG.inferenceFailed}] Your previous turn did not complete: ` + - `${timedOut ? 'its last call timed out' : 'it failed'}${cause ? ` (${suppliedValue(cause)})` : ''}.` + - `${madeAgain ? ` ${MADE_AGAIN}` : ''}` + - `${ended.roundsRan ? ' Its earlier rounds ran, and their tool calls ran as their results show.' : ''}` + - `${ended.callsCutOff ? ` ${CALLS_CUT_OFF}` : ''}` + - `${ended.liveSpeech ? ` ${LIVE_SPEECH_UNRECEIPTED}` : ''}` + - `${ended.speechRouting ? ` ${SPEECH_STILL_ROUTING}` : ''} Reason: ` - : `[${NOTICE_TAG.inferenceFailed}] Your previous turn did not complete: ` + - `the model call ${timedOut ? 'timed out' : 'failed'}${cause ? ` (${suppliedValue(cause)})` : ''} ` + - `and produced no response, so nothing was sent.${madeAgain ? ` ${MADE_AGAIN}` : ''} Reason: `) + - `${failureShown(markerReason)}. ${timedOut ? TIMEOUT_ADVICE : FAILURE_ADVICE}`, + `[${NOTICE_TAG.inferenceFailed}] Your previous turn did not complete: ` + + `${timedOut ? 'its last call timed out' : 'it failed'}${cause ? ` (${suppliedValue(cause)})` : ''}.` + + `${madeAgain ? ` ${MADE_AGAIN}` : ''}` + + `${ended.roundsRan ? ' Its earlier rounds ran, and their tool calls ran as their results show.' : ''}` + + `${ended.callsCutOff ? ` ${CALLS_CUT_OFF}` : ''}` + + `${ended.liveSpeech ? ` ${LIVE_SPEECH_UNRECEIPTED}` : ''}` + + `${ended.speechRouting ? ` ${SPEECH_STILL_ROUTING}` : ''} Reason: ` + + `${failureShown(markerReason)}.${timedOut ? ` ${TIMEOUT_ADVICE}` : ''}`, }], { system: true, kind: 'inference-failed', reason: markerReason, consecutive: streak, ...classification, ...cutAt(markerReason) }, ); diff --git a/src/types/framework.ts b/src/types/framework.ts index cef25875d..3cb6ca877 100644 --- a/src/types/framework.ts +++ b/src/types/framework.ts @@ -393,10 +393,10 @@ export interface FrameworkConfig { * schedule, the heartbeat's tick or reminder, a self-wake timer it set, or a * script's wake. A notice a module or an MCPL server stores as a message * counts. A message in the residents' shared slot counts for each resident - * that reads it. Any other wake leaves the count going on. A re-armed turn's - * transient failure writes no `[inference-failed]` marker unless a round of - * it ran or had its tool calls cut off; any other failure of it writes one. - * Each counts toward the hard-down streak. Ephemeral runs and conversation + * that reads it. Any other wake leaves the count going on. A failure of a + * re-armed turn writes an `[inference-failed]` note only when a round of it + * ran or had its tool calls cut off, as any turn's failure does. Each + * counts toward the hard-down streak. Ephemeral runs and conversation * forks are never re-armed. The wait and the count are kept in memory: * `stop()` drops them, and so does a restart. The wait isn't a turn, so * `abortInference()` doesn't end it. diff --git a/test/exhausted-turn-rearm.test.ts b/test/exhausted-turn-rearm.test.ts index fc98f0cc5..cc277a90d 100644 --- a/test/exhausted-turn-rearm.test.ts +++ b/test/exhausted-turn-rearm.test.ts @@ -279,7 +279,7 @@ for (const failsAt of ['event', 'setup', 'throw'] as const) { await waitFor(() => r.count('inference:exhausted') === 4, 'the window and three re-arms to end exhausted'); assert.equal(r.admission().providerAdmission.heldRequests, 0, 'nothing is kept after the last re-arm'); assert.equal(membrane.sends.length, 3 + 3, 'each re-arm makes one send'); - assert.equal(r.markers(), 1, 'the agent meets the outage once'); + assert.equal(r.markers(), 0, 'an outage whose turns did nothing writes the agent no note'); assert.ok(membrane.sends.every((s) => s.texts.includes('zz-question')), 'every send is the same turn\'s'); const rearmGaps = gaps(membrane.sends).slice(2); assert.ok(rearmGaps[0]! >= 140 && rearmGaps[1]! >= 290 && rearmGaps[2]! >= 440, `re-arms waited each delay: ${rearmGaps.join(', ')}`); @@ -364,7 +364,7 @@ test("a re-armed turn's send is not retried, whatever its failure: an overload a for (const [name, fail, failsAt] of [['refused by the provider, at its start', invalidRequest, 'setup'], ['refused by the provider, by its stream', invalidRequest, 'event'], ['with no provider error, at its start', () => new Error('zz not a provider error'), 'setup'], ['with no provider error, by its stream', () => new Error('zz not a provider error'), 'event'], ['with no provider error, thrown by its stream', () => new Error('zz not a provider error'), 'throw'], ['aborted by its stream', 'aborted', 'event']] as const) { - test(`a re-armed turn that fails in a way that is not transient (${name}) makes its one send, writes a marker, and ends the re-arming`, async (t) => { + test(`a re-armed turn that fails in a way that is not transient (${name}) makes its one send and ends the re-arming, writing no marker since it did nothing`, async (t) => { const membrane = new ScriptedMembrane((n) => (n <= 3 ? serverError : fail), failsAt); const r = await resident(t, membrane); stderr.length = 0; @@ -374,7 +374,7 @@ for (const [name, fail, failsAt] of [['refused by the provider, at its start', i 'the operator is told why no re-send is coming'); assert.equal(r.admission().providerAdmission.heldRequests, 0, 'no re-arm follows'); assert.equal(membrane.sends.length, 4, 'no retry came'); - assert.equal(r.markers(), 2, 'the agent is told the re-armed turn failed another way'); + assert.equal(r.markers(), 0, 'neither the window nor the re-armed turn did anything, so neither writes a note'); }); } @@ -390,13 +390,13 @@ for (const failsAt of ['event', 'setup', 'throw'] as const) { await waitFor(() => r.count('inference:exhausted') === 2, 'the first re-armed send to end exhausted'); assert.equal(r.admission().providerAdmission.heldRequests, 1, "its chain's first deadline cut is re-armed, as a transient failure is"); assert.match(r.admission().providerAdmission.cooldownReason ?? '', /\(2 of 3\)/); - assert.equal(r.markers(), 1, 'the first cut writes no marker of its own'); + assert.equal(r.markers(), 0, 'the first cut writes no marker'); await waitFor(() => r.count('inference:exhausted') === 3, 'the second re-armed send to end exhausted'); assert.equal(r.admission().providerAdmission.heldRequests, 0, 'a second cut in the chain ends it'); assert.ok(stderr.some((line) => line.startsWith("[inference-rearm] agent=resident turn not re-armed: its failure isn't transient (timeout)")), 'the operator is told why no re-send is coming'); assert.equal(membrane.sends.length, 5, 'the window, then one send for each re-arm'); - assert.equal(r.markers(), 2, 'the cut that ends the chain writes its marker'); + assert.equal(r.markers(), 0, 'nor does the cut that ends the chain, since its turn did nothing'); const afterCut = gaps(membrane.sends)[3]!; assert.ok(afterCut >= 290 && afterCut < 890, `the send after the first cut waited the next delay: ${afterCut}ms`); }); @@ -429,7 +429,7 @@ for (const failsAt of ['event', 'setup'] as const) { assert.equal(r.admission().providerAdmission.heldRequests, 0, 'its second cut ends the re-arming'); assert.ok(stderr.some((line) => line.startsWith("[inference-rearm] agent=resident turn not re-armed: its failure isn't transient (timeout)")), 'the operator is told why no re-send is coming'); - assert.equal(r.markers(), 2, "the window's marker, and the one the partway turn's second cut writes"); + assert.equal(r.markers(), 1, "the one the partway turn's second cut writes: the window did nothing"); const markerTexts = r.fw.getAgent('resident')!.getContextManager().getAllMessages().flatMap((m) => m.content) .flatMap((b) => (b.type === 'text' && (b as { text: string }).text.startsWith('[inference-failed]') ? [(b as { text: string }).text] : [])); assert.match(markerTexts.at(-1) ?? '', /The call was made again, and it timed out again\./, "and that marker says the policy's retry was cut again"); @@ -491,7 +491,7 @@ test("under a host's policy that makes no fresh call for a deadline, a re-armed await waitFor(() => r.count('inference:exhausted') === 2, 'the re-armed turn to end exhausted on its first cut'); assert.equal(membrane.sends.length, 6, "the window, then the re-armed turn's send and the error policy's two retries"); assert.equal(r.admission().providerAdmission.heldRequests, 1, "its first cut is taken as a transient failure, so it is re-armed"); - assert.equal(r.markers(), 2, "the window's marker, and the one a re-armed turn that got partway writes"); + assert.equal(r.markers(), 1, "the one a re-armed turn that got partway writes: the window did nothing"); }); test("a deadline cut a host's provider hold takes in a re-armed turn counts, so the held send's next cut ends the re-arming", async (t) => { @@ -573,12 +573,12 @@ test("a stated wait on a re-armed turn's send holds it as it holds any turn, and assert.ok(gaps(membrane.sends)[4]! >= 290, 'the second delay followed its failure'); }); -test("one [inference-failed] marker for the window and every re-arm after it; each failure counts toward the hard-down streak, whose alert comes at the third", async (t) => { +test("no [inference-failed] marker for the window and every re-arm after it, which did nothing; each failure counts toward the hard-down streak, whose alert comes at the third", async (t) => { const membrane = new ScriptedMembrane(() => serverError); const r = await resident(t, membrane, { exhaustedTurnRearmMs: [50, 50, 50] }); r.say('zz-question'); await waitFor(() => r.count('inference:exhausted') === 4, 'the window and three re-arms to end exhausted'); - assert.equal(r.markers(), 1, 'the agent meets the failure once'); + assert.equal(r.markers(), 0, 'the agent meets no note of a failure whose turns did nothing'); assert.equal(r.admission().consecutiveInferenceFailures, 4); const firstAlert = r.traces.find((tr) => tr.type === 'ops:alert' && tr.kind === 'hard-down'); assert.ok(firstAlert, 'the hard-down alert came'); @@ -596,8 +596,8 @@ test(`a re-armed turn that got partway (${how}; later failures ${failsAt === 'se assert.equal(membrane.sends.length, 7, "the window, the re-armed turn's three sends, then the second re-arm's one"); const markers = r.fw.getAgent('resident')!.getContextManager().getAllMessages() .flatMap((m) => m.content).map((b) => (b as { text?: string }).text ?? '').filter((text) => text.startsWith('[inference-failed]')); - assert.equal(markers.length, 2); - assert.match(markers[1]!, expected); + assert.equal(markers.length, 1, 'the partway turn\'s: the window did nothing'); + assert.match(markers[0]!, expected); }); } @@ -738,7 +738,7 @@ test('with exhaustedTurnRearmMs false, a turn whose retries ran out is not sent await waitFor(() => r.count('inference:exhausted') === 1, 'the turn to end exhausted'); assert.equal(r.admission().providerAdmission.heldRequests, 0, 'nothing is kept to be sent again'); assert.equal(membrane.sends.length, 3); - assert.equal(r.markers(), 1); + assert.equal(r.markers(), 0); assert.ok(!stderr.some((line) => line.includes('[inference-rearm]')), 'with re-arming off, nothing is said of it'); }); @@ -935,7 +935,7 @@ test('a continuation whose turn never found a channel is not re-armed, rather th internal.pendingRequests.push({ agentName: 'resident', reason: 'context_budget_restart', source: 'framework', timestamp: Date.now() }); await waitFor(() => r.count('inference:exhausted') === 1, 'the restart to end exhausted'); assert.equal(r.fw.getHostModeStatus().gatedRequests, 0, 'nothing is kept to be sent again'); - assert.equal(r.markers(), 1, 'the agent meets the exhaustion\'s marker'); + assert.equal(r.markers(), 0, 'the restart did nothing, so the agent meets no note of it'); assert.equal(membrane.sends.length, 4); assert.equal(rearmLines('resident', 'not re-armed', 'guess a channel').length, 1, 'the operator is told why'); }); @@ -1146,7 +1146,7 @@ test("a silent turn's held retries keep one run", async (t) => { // The branch's (feat/dendrite): releaseAgentRuntime, the one release of an // ended agent that isn't a run (stopAgent, a cascaded end, a fork's dispose), // drops this per-name turn state, so a new agent under the name starts clean. -test("a resident stopped mid-turn takes its turn state with it: its run of stated waits ends at the stop, and a new agent under its name re-arms from the first delay with a plain marker", async (t) => { +test("a resident stopped mid-turn takes its turn state with it: its run of stated waits ends at the stop, and a new agent under its name re-arms from the first delay", async (t) => { const { workerSpec } = await import('../src/index.js'); // `second`'s window ends exhausted on server errors (sends 1 to 3); its // re-arm's send and the next are held by stated waits (4 and 5), and the @@ -1157,11 +1157,10 @@ test("a resident stopped mid-turn takes its turn state with it: its run of state const r = await resident(t, membrane, { exhaustedTurnRearmMs: [100, 100], agents: [ { name: 'resident', model: 'zz-model', systemPrompt: 'system' }, { name: 'second', model: 'zz-model', systemPrompt: 'system' }] }); const state = r.fw as unknown as { - turnRearms: Map; exhaustingRearms: Set; exhaustedTurns: Map; statedWaitRuns: Map; + turnRearms: Map; exhaustedTurns: Map; statedWaitRuns: Map; }; const kept = () => ({ - rearms: state.turnRearms.has('second'), exhaustingRearm: state.exhaustingRearms.has('second'), - exhaustedTurn: state.exhaustedTurns.has('second'), statedWaits: state.statedWaitRuns.has('second'), + rearms: state.turnRearms.has('second'), exhaustedTurn: state.exhaustedTurns.has('second'), statedWaits: state.statedWaitRuns.has('second'), }); const alerts = () => r.traces.filter((tr) => tr.type === 'ops:alert' && tr.kind === 'provider-wait'); const held = () => ((r.fw.healthSnapshot() as { agents: Array<{ name: string; providerAdmission: { heldRequests: number } }> }) @@ -1173,16 +1172,15 @@ test("a resident stopped mid-turn takes its turn state with it: its run of state await waitFor(() => membrane.sends.length === 5 && held() === 1, 'the next send to be held, 40 minutes on'); t.mock.timers.tick(40 * 60_000); await waitFor(() => membrane.sends.length === 6 && held() === 0, 'the send after it to be in flight, 80 minutes from the first hold'); - // Neither of these outlives a turn by itself: a failure sets each and the + // This doesn't outlive a turn by itself: a failure sets it and the // exhaustion it raises reads it at once. Set here as such a failure sets - // them, so the release's clear of each is pinned too. - state.exhaustingRearms.add('second'); + // it, so the release's clear of it is pinned too. state.exhaustedTurns.set('second', { roundsRan: true, callsCutOff: false, liveSpeech: false, speechRouting: false }); - assert.deepEqual(kept(), { rearms: true, exhaustingRearm: true, exhaustedTurn: true, statedWaits: true }, 'the premise: each is held for second'); + assert.deepEqual(kept(), { rearms: true, exhaustedTurn: true, statedWaits: true }, 'the premise: each is held for second'); assert.equal(alerts().length, 0, 'the premise: no hold came past the hour'); r.fw.stopAgent('second', { by: 'zz-operator' }); - assert.deepEqual(kept(), { rearms: false, exhaustingRearm: false, exhaustedTurn: false, statedWaits: false }, 'the release drops each'); + assert.deepEqual(kept(), { rearms: false, exhaustedTurn: false, statedWaits: false }, 'the release drops each'); assert.equal(alerts().length, 1, 'the run of stated waits ends at the stop, alerted as it spanned past the hour'); assert.equal(alerts()[0]!.data?.holds, 2); @@ -1200,8 +1198,7 @@ test("a resident stopped mid-turn takes its turn state with it: its run of state `its re-arm is the first: ${stderr.filter((line) => line.includes('[inference-rearm]')).join(' | ')}`); const markers = fresh.contextManager.getAllMessages().flatMap((m) => m.content) .map((b) => (b as { text?: string }).text ?? '').filter((text) => text.startsWith('[inference-failed]')); - assert.equal(markers.length, 1, 'it meets its outage with a marker'); - assert.match(markers[0]!, /the model call failed \(server, HTTP 502\) and produced no response, so nothing was sent/, 'one that says its own turn got nowhere'); + assert.deepEqual(markers, [], 'its outage did nothing, so it writes no note: in particular, none says how far the stopped turn got'); assert.equal(alerts().length, 1, 'and no run of stated waits is ended with it but its own'); }); @@ -1249,8 +1246,7 @@ test('a resident stopped with a failure streak takes its failure accounting with assert.equal(r.traces.filter((tr) => tr.type === 'ops:alert' && tr.kind === 'hard-down').length, 0, 'and no hard-down alert is raised'); const kept = fresh.contextManager.getAllMessages().flatMap((m) => m.content).map((b) => (b as { text?: string }).text ?? ''); assert.ok(kept.includes('zz-fresh'), 'and its own message is kept'); - assert.ok(kept.some((text) => text.startsWith('[inference-failed]')) && !kept.some((text) => text.includes('The call was made again')), - 'and its failure note says nothing of a call made again'); + assert.ok(!kept.some((text) => text.startsWith('[inference-failed]')), 'and its refused request, which did nothing, writes no note'); }); test("a job its own run ended keeps its failure streak when it is resumed under its name, with the same history", async (t) => { @@ -1350,7 +1346,7 @@ test("a resident stopped after a refusal takes its refusal streak with it: a new }); test("a job's own run's end takes its fresh-call mark with it, so a resume's first failure note says nothing of a call made again", async (t) => { - const membrane = new ScriptedMembrane((n) => (n === 1 ? undefined : invalidRequest)); + const membrane = new ScriptedMembrane((n) => (n === 1 ? undefined : { toolRoundThen: invalidRequest() })); const r = await resident(t, membrane, { exhaustedTurnRearmMs: false }); const config = { model: 'zz-model', systemPrompt: 'system' }; const first = await r.fw.createEphemeralAgent({ name: 'job', ...config }); @@ -1362,7 +1358,7 @@ test("a job's own run's end takes its fresh-call mark with it, so a resume's fir await stepping(r.fw.runEphemeralToCompletion(resumed.agent, resumed.contextManager).then(() => null, (error: unknown) => error), "the resume's run to end"); const notes = resumed.contextManager.getAllMessages().flatMap((m) => m.content) .map((b) => (b as { text?: string }).text ?? '').filter((text) => text.startsWith('[inference-failed]')); - assert.equal(notes.length, 1, "the resume's refused request gets its note"); + assert.equal(notes.length, 1, "the resume's turn, refused after a tool round, gets its note"); assert.ok(!notes[0]!.includes('The call was made again'), `which says nothing of a call made again: ${notes[0]}`); }); diff --git a/test/inference-bounds.test.ts b/test/inference-bounds.test.ts index ddc1425b3..781527ba5 100644 --- a/test/inference-bounds.test.ts +++ b/test/inference-bounds.test.ts @@ -406,8 +406,8 @@ describe('inference bounds: a stalled turn call ends at its bound', () => { }); it('a fresh call refused, sent again by membrane and cut is the same request\'s second cut, so the turn ends', async () => { - const t = await turn(['quiet-before-content', 'refusal', 'quiet-before-content', 'whole'], { agent: { refusalHandling: { retries: 1 } } }); - assert.equal(t.requests, 3); + const t = await turn(['tool-use', 'quiet-before-content', 'refusal', 'quiet-before-content', 'whole'], { agent: { refusalHandling: { retries: 1 } } }); + assert.equal(t.requests, 4); assert.equal(exhausted(t).length, 1); assert.equal(completed(t).length, 0); assert.equal(t.markers.length, 1); @@ -415,8 +415,8 @@ describe('inference bounds: a stalled turn call ends at its bound', () => { }); it('a cut counts among the turn\'s tries for its other failures, as every failure does', async () => { - const t = await turn(['quiet-before-content', 'error500', 'error500', 'whole']); - assert.equal(t.requests, 3); + const t = await turn(['tool-use', 'quiet-before-content', 'error500', 'error500', 'whole']); + assert.equal(t.requests, 4); assert.equal(exhausted(t).length, 1); assert.match(String(exhausted(t)[0]!.error), /stand-in internal error/); assert.equal(t.markers.length, 1); @@ -458,46 +458,46 @@ describe('inference bounds: a stalled turn call ends at its bound', () => { } }); - it('a turn its cuts end tells the agent the call timed out, that the call was made again and timed out again, why, the host setting for that bound, and that a reply still owed can be given now', async () => { + it('a turn its cuts end before it did anything writes the agent no note', async () => { const t = await turn(['quiet-before-content']); - assert.equal(t.markers.length, 1); - assert.match(t.markers[0]!, /^\[inference-failed\] Your previous turn did not complete: the model call timed out and produced no response, so nothing was sent\. The call was made again, and it timed out again\. Reason: No content within 0\.3s of the send/); - assert.match(t.markers[0]!, /\(the host's setting for this bound: `inferenceBounds\.progressBounds\.beforeContentMs`\)\. If a reply is still owed from that turn, you can give it now\.$/); + assert.equal(t.requests, 2); + assert.match(String(exhausted(t)[0]!.error), /^No content within 0\.3s of the send/); + assert.deepEqual(t.markers, []); }); it('a host schedule that gives a deadline expiry two fresh calls says the call was made again, with no count', async () => { const retries = { ...MEMBRANE_RETRY_SETTINGS, deadline: { maxAttempts: 3, firstDelayMs: 50, multiplier: 1, maxDelayMs: 50, statedWaitCeilingMs: null } } as RetrySettings; - const t = await turn(['quiet-before-content', 'quiet-before-content', 'quiet-before-content', 'whole'], { retries }); - assert.equal(t.requests, 3); + const t = await turn(['tool-use', 'quiet-before-content', 'quiet-before-content', 'quiet-before-content', 'whole'], { retries }); + assert.equal(t.requests, 4); assert.equal(t.markers.length, 1); - assert.match(t.markers[0]!, /so nothing was sent\. The call was made again, and it timed out again\. Reason: /); + assert.match(t.markers[0]!, /its last call timed out\. The call was made again, and it timed out again\. Its earlier rounds ran, and their tool calls ran as their results show\. Reason: /); assert.doesNotMatch(t.markers[0]!, /once more|more times/); }); it('a turn whose cuts come either side of another failure says the call was made again and timed out again, with no count', async () => { - const t = await turn(['quiet-before-content', 'error500', 'quiet-before-content', 'quiet-before-content', 'whole']); - assert.equal(t.requests, 4, 'a cut, its fresh call\'s 500, a retry cut, and that cut\'s fresh call cut too'); + const t = await turn(['tool-use', 'quiet-before-content', 'error500', 'quiet-before-content', 'quiet-before-content', 'whole']); + assert.equal(t.requests, 5, 'a tool round, then a cut, its fresh call\'s 500, a retry cut, and that cut\'s fresh call cut too'); assert.equal(t.markers.length, 1); - assert.match(t.markers[0]!, /so nothing was sent\. The call was made again, and it timed out again\. Reason: No content within 0\.3s of the send/); + assert.match(t.markers[0]!, /its last call timed out\. The call was made again, and it timed out again\. Its earlier rounds ran, and their tool calls ran as their results show\. Reason: No content within 0\.3s of the send/); assert.doesNotMatch(t.markers[0]!, /once more|more times/); }); it('a timeout that got no fresh call, such as an HTTP 408, says neither that it was sent again nor more than its cause', async () => { - const t = await turn(['error408']); - assert.equal(t.requests, 3); + const t = await turn(['tool-use', 'error408']); + assert.equal(t.requests, 4); assert.equal(t.markers.length, 1); - assert.match(t.markers[0]!, /^\[inference-failed\] Your previous turn did not complete: the model call timed out \(timeout, HTTP 408\) and produced no response, so nothing was sent\. Reason: /); + assert.match(t.markers[0]!, /^\[inference-failed\] Your previous turn did not complete: its last call timed out \(timeout, HTTP 408\)\. Its earlier rounds ran, and their tool calls ran as their results show\. Reason: /); assert.doesNotMatch(t.markers[0]!, /made again/); assert.match(t.markers[0]!, /\. If a reply is still owed from that turn, you can give it now\.$/); }); - it('a turn cut after a tool round tells the agent its last call timed out and its earlier rounds ran', async () => { + it('a turn cut after a tool round tells the agent its last call timed out, that the call was made again and timed out again, its earlier rounds ran, why, the host setting for that bound, and that a reply still owed can be given now', async () => { const t = await turn(['tool-use', 'quiet-before-content']); assert.equal(t.requests, 3); assert.equal(t.markers.length, 1); assert.match(t.markers[0]!, /^\[inference-failed\] Your previous turn did not complete: its last call timed out\. The call was made again, and it timed out again\. Its earlier rounds ran, and their tool calls ran as their results show\./); assert.match(t.markers[0]!, /Reason: No content within 0\.3s of the send/); - assert.match(t.markers[0]!, /\. If a reply is still owed from that turn, you can give it now\.$/); + assert.match(t.markers[0]!, /\(the host's setting for this bound: `inferenceBounds\.progressBounds\.beforeContentMs`\)\. If a reply is still owed from that turn, you can give it now\.$/); }); it('a stream that keeps sending content is not ended by any progress bound', async () => { diff --git a/test/inference-failed-telemetry.test.ts b/test/inference-failed-telemetry.test.ts new file mode 100644 index 000000000..7329691d4 --- /dev/null +++ b/test/inference-failed-telemetry.test.ts @@ -0,0 +1,212 @@ +import { test, type TestContext } from 'node:test'; +import assert from 'node:assert/strict'; +import { existsSync, mkdtempSync, readFileSync, rmSync } 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 { ErrorPolicy, EventResponse, Module, ModuleContext, ProcessEvent, ProcessState, ToolCall, ToolDefinition, ToolResult } from '../src/index.js'; +import { AgentFramework } from '../src/index.js'; +import { MockMembrane, MockYieldingStream, createMockResponse } from './helpers/mock-membrane.js'; + +class InputModule implements Module { + readonly name = 'input'; + async start(_ctx: ModuleContext): Promise {} + async stop(): Promise {} + getTools(): ToolDefinition[] { return [{ name: 'zz_look', description: 'zz look', inputSchema: { type: 'object', properties: {} } }]; } + async handleToolCall(_call: ToolCall): Promise { return { success: true, data: 'zz-looked' }; } + 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 ErrorStream 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 ToolRoundThenErrorStream implements YieldingStream { + isCancelled = false; + toolDepth = 0; + private waiting = true; + private resume?: () => void; + constructor(private readonly error: Error) {} + get isWaitingForTools() { return this.waiting; } + get pendingToolCallIds() { return this.waiting ? ['zz-call'] : []; } + provideToolResults(): void { this.waiting = false; this.toolDepth = 1; this.resume?.(); } + cancel(): void { this.isCancelled = true; this.waiting = false; this.resume?.(); } + async *[Symbol.asyncIterator](): AsyncIterator { + const call = { id: 'zz-call', name: 'input--zz_look', input: {} }; + yield { type: 'usage', usage: { inputTokens: 1, outputTokens: 1, cacheCreationTokens: 0, cacheReadTokens: 0 } } as StreamEvent; + yield { type: 'tool-calls', calls: [call], context: { rawText: '', preamble: '', depth: 0, previousResults: [], accumulated: '', + roundContent: [{ type: 'tool_use', ...call }], supportsInjectedMessages: true } } as StreamEvent; + if (this.waiting) await new Promise((resolve) => { this.resume = resolve; }); + if (this.isCancelled) return; + yield { type: 'error', error: this.error } as StreamEvent; + } +} + +const serverError = () => new MembraneError({ + type: 'server', retryable: true, httpStatus: 502, providerErrorCode: 'zz_bad_gateway', message: 'zz server failure', rawError: undefined, +} as never); +const timeoutError = () => new MembraneError({ type: 'timeout', retryable: true, message: 'zz call timed out', rawError: undefined } as never); + +type Send = 'fails' | 'tool round, then fails' | 'tool round, then times out' | 'answers'; + +class ScriptedMembrane extends MockMembrane { + readonly sends: NormalizedRequest[] = []; + constructor(private readonly script: (send: number) => Send) { super(); } + override streamYielding(request: NormalizedRequest): YieldingStream { + this.sends.push(request); + const send = this.script(this.sends.length); + if (send === 'fails') return new ErrorStream(serverError()); + if (send === 'tool round, then fails') return new ToolRoundThenErrorStream(serverError()); + if (send === 'tool round, then times out') return new ToolRoundThenErrorStream(timeoutError()); + return new MockYieldingStream([createMockResponse([{ type: 'text', text: `zz-answer-${this.sends.length}` }])]); + } +} + +const noRetry: ErrorPolicy = { maxRetries: 0, onInferenceError: () => ({ retry: false }) }; + +const texts = (request: NormalizedRequest) => + request.messages.flatMap((m) => m.content).map((b) => (b as { text?: string }).text ?? '').filter((t) => t !== ''); + +async function resident(t: TestContext, membrane: ScriptedMembrane, dir = mkdtempSync(join(tmpdir(), 'af-979-'))) { + const cwd = process.cwd(); + process.chdir(dir); + const stderr: string[] = []; + const consoleError = console.error; + console.error = (...a: unknown[]) => { stderr.push(a.map(String).join(' ')); }; + const open = () => AgentFramework.create({ + storePath: join(dir, 'store.chronicle'), membrane: membrane.asMembrane(), + agents: [{ name: 'resident', model: 'zz-model', systemPrompt: 'system' }], + modules: [new InputModule()], syncIntervalMs: 0, maintenanceIntervalMs: 0, + errorPolicy: noRetry, exhaustedTurnRearmMs: false, + }); + let fw = await open(); + const traces: Array<{ type: string }> = []; + const listen = () => fw.onTrace((e) => traces.push(e as unknown as { type: string })); + listen(); + t.after(async () => { + await fw.stop(); + console.error = consoleError; + process.chdir(cwd); + rmSync(dir, { recursive: true, force: true }); + }); + return { + get fw() { return fw; }, + stderr, traces, + async say(text: string) { + fw.pushEvent({ type: 'external-message', source: 'test', content: text, metadata: {} }); + await fw.runUntilIdle(); + }, + stored: () => fw.getAgent('resident')!.getContextManager().queryMessages({}).messages, + notes: () => fw.getAgent('resident')!.getContextManager().queryMessages({}).messages + .filter((m) => (m.metadata as { kind?: string } | undefined)?.kind === 'inference-failed') + .map((m) => (m.content[0] as { text: string }).text), + failures: () => { + const file = join(dir, 'logs', 'failures.log'); + return existsSync(file) ? readFileSync(file, 'utf-8').trim().split('\n').filter(Boolean).map((l) => JSON.parse(l) as Record) : []; + }, + async reopen() { + await fw.stop(); + fw = await open(); + listen(); + }, + }; +} + +test('three exhausted turns that did nothing: three failure records, and no row in the context but what was said', async (t) => { + const membrane = new ScriptedMembrane(() => 'fails'); + const r = await resident(t, membrane); + for (const n of [1, 2, 3]) await r.say(`zz-hello ${n}`); + assert.equal(r.traces.filter((e) => e.type === 'inference:exhausted').length, 3, 'premise: three turns exhausted'); + assert.deepEqual(r.notes(), []); + assert.deepEqual(r.stored().flatMap((m) => m.content).map((b) => (b as { text?: string }).text), ['zz-hello 1', 'zz-hello 2', 'zz-hello 3']); + const records = r.failures().filter((f) => f.kind === 'inference-exhausted'); + assert.deepEqual(records.map((f) => f.consecutive), [1, 2, 3]); + assert.equal(r.stderr.filter((l) => l.startsWith('[inference-failed] agent=resident consecutive=')).length, 3); +}); + +test('operators keep what a failure tells them: its category, status and provider code in failures.log and stderr, and its request id in the inference log', async (t) => { + const membrane = new ScriptedMembrane(() => 'fails'); + const r = await resident(t, membrane); + await r.say('zz-hello'); + const [record] = r.failures().filter((f) => f.kind === 'inference-exhausted'); + const { at, ...fields } = record!; + assert.equal(typeof at, 'string'); + assert.deepEqual(fields, { + agent: 'resident', consecutive: 1, reason: 'zz server failure', kind: 'inference-exhausted', + errorType: 'server', retryable: true, httpStatus: 502, providerErrorCode: 'zz_bad_gateway', + }); + assert.ok(r.stderr.includes('[inference-failed] agent=resident consecutive=1 type=server status=502 code=zz_bad_gateway: zz server failure'), r.stderr.join('\n')); + const logged = r.fw.queryInferenceLogs({}).entries.map(({ summary }) => summary); + assert.equal(logged.length, 1); + assert.equal(logged[0]!.success, false); + assert.match(logged[0]!.requestId ?? '', /^resident-\d+-[a-z0-9]+$/); +}); + +test('a framework reopened on the store after turns that did nothing holds none of them', async (t) => { + const membrane = new ScriptedMembrane(() => 'fails'); + const r = await resident(t, membrane); + for (const n of [1, 2, 3]) await r.say(`zz-hello ${n}`); + await r.reopen(); + assert.deepEqual(r.notes(), []); + assert.deepEqual(r.stored().flatMap((m) => m.content).map((b) => (b as { text?: string }).text), ['zz-hello 1', 'zz-hello 2', 'zz-hello 3']); +}); + +test('seventeen failures leave each next request as it would be without them: what was said before, and the new message', async (t) => { + const membrane = new ScriptedMembrane((n) => (n <= 17 ? 'fails' : 'answers')); + const r = await resident(t, membrane); + for (let n = 1; n <= 18; n++) await r.say(`zz-hello ${n}`); + assert.equal(membrane.sends.length, 18, 'premise: seventeen failed sends, then one that answered'); + assert.ok(r.stored().some((m) => m.content.some((b) => (b as { text?: string }).text === 'zz-answer-18')), 'premise: the eighteenth answered'); + for (let n = 1; n < 18; n++) { + assert.deepEqual(texts(membrane.sends[n]!), [...texts(membrane.sends[n - 1]!), `zz-hello ${n + 1}`], `send ${n + 1}`); + } + assert.equal(texts(membrane.sends[17]!).filter((text) => text.startsWith('zz-hello')).length, 18); +}); + +test('a turn that got partway leaves one note, saying how far it got and why, with no advice', async (t) => { + const membrane = new ScriptedMembrane(() => 'tool round, then fails'); + const r = await resident(t, membrane); + await r.say('zz-hello'); + assert.deepEqual(r.notes(), [ + '[inference-failed] Your previous turn did not complete: it failed (server, HTTP 502). ' + + 'Its earlier rounds ran, and their tool calls ran as their results show. Reason: zz server failure.', + ]); + assert.equal(r.failures().filter((f) => f.kind === 'inference-exhausted').length, 1); +}); + +test('a turn that got partway and timed out keeps its note telling the resident it can still reply', async (t) => { + const membrane = new ScriptedMembrane(() => 'tool round, then times out'); + const r = await resident(t, membrane); + await r.say('zz-hello'); + const notes = r.notes(); + assert.equal(notes.length, 1, notes.join('\n')); + assert.match(notes[0]!, /^\[inference-failed\] Your previous turn did not complete: its last call timed out\. Its earlier rounds ran, and their tool calls ran as their results show\. Reason: zz call timed out\. If a reply is still owed from that turn, you can give it now\.$/); +}); + +test('SUPPRESS_INFERENCE_FAILED_MARKER=1 leaves out the note for a turn that got partway', async (t) => { + const previous = process.env.SUPPRESS_INFERENCE_FAILED_MARKER; + process.env.SUPPRESS_INFERENCE_FAILED_MARKER = '1'; + t.after(() => { + if (previous === undefined) delete process.env.SUPPRESS_INFERENCE_FAILED_MARKER; + else process.env.SUPPRESS_INFERENCE_FAILED_MARKER = previous; + }); + const membrane = new ScriptedMembrane(() => 'tool round, then fails'); + const r = await resident(t, membrane); + await r.say('zz-hello'); + assert.equal(r.traces.filter((e) => e.type === 'inference:exhausted').length, 1, 'premise: the turn exhausted'); + assert.deepEqual(r.notes(), []); + assert.equal(r.failures().filter((f) => f.kind === 'inference-exhausted').length, 1); +}); diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index e3fac85e5..2ba9f2cff 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -48,8 +48,11 @@ function hugeProviderError(request?: NormalizedRequest): MembraneError { // inference-failure-observability.test.ts). // --------------------------------------------------------------------------- -function makeHarness(opts?: { tick?: () => Promise; addMessage?: (p: string, c: any[], m: any) => void }) { +const PARTWAY = { roundsRan: true, callsCutOff: false, liveSpeech: false, speechRouting: false }; + +function makeHarness(opts?: { tick?: () => Promise; addMessage?: (p: string, c: any[], m: any) => void; partway?: boolean }) { const fw = Object.create(FrameworkClass.prototype) as any; + fw.exhaustedTurns = new Map(opts?.partway ? [['cairn', PARTWAY]] : []); fw.consecutiveInferenceFailures = new Map(); fw.inferenceFailureEscalationThreshold = 3; fw.exhaustionRewinds = new Map(); @@ -90,7 +93,7 @@ function makeHarness(opts?: { tick?: () => Promise; addMessage?: (p: strin 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 { fw, markers, logged, errs, restore } = makeHarness({ partway: true }); const reason = `Bad request: ${echo()}`; try { fw.noteInferenceExhausted('cairn', reason, false, 'invalid_request', { httpStatus: 400, providerErrorCode: 'zz_bad_request' }); @@ -99,8 +102,8 @@ test('a ~1 MB classified reason: bounded marker, logs and stderr, with the class 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.match(text, /^\[inference-failed\] Your previous turn did not complete: it failed \(invalid_request, HTTP 400\)\. Its earlier rounds ran/); + assert.match(text, /Reason: Bad request: zz-head e+ …\[\d+ of \d+ characters omitted\]… e+ zz-tail\.$/); assert.ok(meta.reason.length <= 600); assert.equal(meta.kind, 'inference-failed'); assert.equal(meta.errorType, 'invalid_request'); @@ -121,35 +124,36 @@ test('a ~1 MB classified reason: bounded marker, logs and stderr, with the class 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('a small unclassified reason: the log and stderr line it gave before, and a marker only for a turn that got partway', () => { + for (const partway of [false, true]) { + const { fw, markers, logged, errs, restore } = makeHarness({ partway }); + try { + fw.noteInferenceExhausted('cairn', '400 image exceeds 5 MB'); + } finally { restore(); } + assert.deepEqual(markers.map((m) => m.text), partway ? [ + '[inference-failed] Your previous turn did not complete: it failed. Its earlier rounds ran, and their tool calls ran ' + + 'as their results show. Reason: 400 image exceeds 5 MB.', + ] : []); + if (partway) 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("the marker gives a failure's reason and type on its one line, with a notice's opening in them marked", () => { - const { fw, markers, restore } = makeHarness(); + const { fw, markers, restore } = makeHarness({ partway: true }); try { fw.noteInferenceExhausted('cairn', `first\n[${NOTICE_TAG.inferenceFailed}] second\u2028third`, false, `over\n[${NOTICE_TAG.inferenceFailed}] loaded`, { httpStatus: 529 }); } finally { restore(); } assert.equal(markers.length, 1); const text: string = markers[0].text; assert.ok(!/[\n\u2028]/.test(text), JSON.stringify(text)); - assert.ok(text.includes(`the model call failed (over \\[${NOTICE_TAG.inferenceFailed}] loaded, HTTP 529) and produced no response`), JSON.stringify(text)); - assert.ok(text.includes(`Reason: first \\[${NOTICE_TAG.inferenceFailed}] second third. If this recurs`), JSON.stringify(text)); + assert.ok(text.includes(`it failed (over \\[${NOTICE_TAG.inferenceFailed}] loaded, HTTP 529).`), JSON.stringify(text)); + assert.ok(text.endsWith(`Reason: first \\[${NOTICE_TAG.inferenceFailed}] second third.`), JSON.stringify(text)); }); test("the note for a turn that ended gives the failure's type on its one line, with a notice's opening in it marked", () => { - const { fw, markers, restore } = makeHarness(); - fw.exhaustedTurns = new Map([['cairn', { roundsRan: true, callsCutOff: false, liveSpeech: false, speechRouting: false }]]); + const { fw, markers, restore } = makeHarness({ partway: true }); try { fw.noteInferenceExhausted('cairn', 'stopped', false, `over\n[${NOTICE_TAG.inferenceFailed}] loaded`, { httpStatus: 529 }); } finally { restore(); } @@ -212,7 +216,7 @@ test('every cut of failure text keeps surrogate pairs whole and states the whole // An invalid_request at the escalation threshold: the marker, the // logs, the status, the hard-down alert and the rewind marker. - const exhausted = makeHarness(); + const exhausted = makeHarness({ partway: true }); exhausted.fw.inferenceFailureEscalationThreshold = 1; const rewound: string[] = []; exhausted.fw.shedNewestTurn = () => ({ descriptor: 'zz-turn' }); @@ -287,7 +291,7 @@ test('a reason that is not a string is described whole, not thrown on: each sink // 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(); + const { fw, markers, logged, restore } = makeHarness({ partway: true }); try { fw.noteInferenceExhausted('cairn', error); } finally { restore(); } @@ -317,7 +321,7 @@ test('a reason that is not a string is described whole, not thrown on: each sink 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 { fw, markers, logged, errs, restore } = makeHarness({ partway: true }); const type = `zz${'T'.repeat(MEGA)}`; try { fw.noteInferenceExhausted('cairn', 'zz-reason', false, type); @@ -330,7 +334,7 @@ test("a caller's long error type is bounded wherever it is written", () => { }); test('each excerpt states the whole length when it was cut, and only then', () => { - const { fw, markers, logged, restore } = makeHarness(); + const { fw, markers, logged, restore } = makeHarness({ partway: true }); const reason = `zz-reason ${'r'.repeat(990)}`; // 1,000 chars: cut for the marker, whole in the logs try { fw.noteInferenceExhausted('cairn', reason, false, 'invalid_request'); @@ -371,7 +375,7 @@ test('failure logs print a bounded projection, never the error object with its r // 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; } }); + const refused = makeHarness({ addMessage: () => { throw error; }, partway: true }); try { refused.fw.noteInferenceExhausted('cairn', 'boom'); } finally { refused.restore(); } @@ -655,7 +659,7 @@ test('a failed maintenance pass logs and alerts a bounded reason', async () => { }); test('emitTrace: listeners get bounded error and stack; the marker still learns the full length', () => { - const { fw, traces, markers, restore } = makeHarness(); + const { fw, traces, markers, restore } = makeHarness({ partway: true }); 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' }); @@ -821,8 +825,8 @@ 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' }; } + getTools(): ToolDefinition[] { return [{ name: 'zz_look', description: 'zz look', inputSchema: { type: 'object', properties: {} } }]; } + async handleToolCall(_call: ToolCall): Promise { return { success: true, data: 'zz-looked' }; } 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 }; @@ -849,7 +853,27 @@ class ThrowingStream extends ErrorEventStream { } } -type Path = 'stream error event' | 'stream throws' | 'stream setup throws'; +class ToolRoundThenErrorStream implements YieldingStream { + isCancelled = false; + toolDepth = 0; + private waiting = true; + private resume?: () => void; + constructor(private readonly error: Error) {} + get isWaitingForTools() { return this.waiting; } + get pendingToolCallIds() { return this.waiting ? ['zz-call'] : []; } + provideToolResults(): void { this.waiting = false; this.toolDepth = 1; this.resume?.(); } + cancel(): void { this.isCancelled = true; this.waiting = false; this.resume?.(); } + async *[Symbol.asyncIterator](): AsyncIterator { + const call = { id: 'zz-call', name: 'input--zz_look', input: {} }; + yield { type: 'tool-calls', calls: [call], context: { rawText: '', preamble: '', depth: 0, previousResults: [], accumulated: '', + roundContent: [{ type: 'tool_use', ...call }], supportsInjectedMessages: true } } as StreamEvent; + if (this.waiting) await new Promise((resolve) => { this.resume = resolve; }); + if (this.isCancelled) return; + yield { type: 'error', error: this.error } as StreamEvent; + } +} + +type Path = 'stream error event' | 'stream throws' | 'stream setup throws' | 'tool round, then a stream error event'; class FailingMembrane extends MockMembrane { constructor(private readonly path: Path, private readonly make: (request: NormalizedRequest) => Error) { super(); } @@ -857,6 +881,7 @@ class FailingMembrane extends MockMembrane { this.calls.push(request); const error = this.make(request); if (this.path === 'stream setup throws') throw error; + if (this.path === 'tool round, then a stream error event') return new ToolRoundThenErrorStream(error); return this.path === 'stream throws' ? new ThrowingStream(error) : new ErrorEventStream(error); } } @@ -914,18 +939,22 @@ async function runFailingTurn(path: Path, make: (request: NormalizedRequest) => } } -for (const path of ['stream error event', 'stream throws', 'stream setup throws'] as const) { +for (const path of ['stream error event', 'stream throws', 'stream setup throws', 'tool round, then a stream error event'] as const) { test(`${path}: a ~1 MB provider error leaves a bounded, classified trail`, async () => { 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`); - 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); + if (path === 'tool round, then a stream error event') { + assert.equal(markers.length, 1, 'one failure marker, since the turn got partway'); + const text = (markers[0].content[0] as { text: string }).text; + assert.ok(text.length < 1_200, `marker is ${text.length} chars`); + assert.match(text, /it 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); + } else { + assert.deepEqual(markers, [], 'no failure marker, since the turn did nothing'); + } 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`); @@ -948,18 +977,16 @@ 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, rawArgs } = await runFailingTurn('stream throws', () => new Error(`socket said: ${echo()}`)); + const { markers, traces, 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); - assert.match(text, /model call failed and produced no response/); + assert.equal(traces.filter((t) => t.type === 'inference:exhausted').length, 1, 'premise: the turn failed'); + assert.deepEqual(markers, []); const longest = errs.reduce((max, e) => Math.max(max, e.length), 0); 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({ + const { markers, traces, failuresLog } = await runFailingTurn('tool round, then a 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 }, })); @@ -983,8 +1010,9 @@ test('a MembraneError from another copy of membrane is recognised by its name', // 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'); + assert.deepEqual(markers, [], 'the turn did nothing'); + const failed = traces.find((t) => t.type === 'inference:exhausted'); + assert.deepEqual({ errorType: failed.errorType, httpStatus: failed.httpStatus }, { errorType: 'invalid_request', httpStatus: 400 }); // 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); @@ -1010,7 +1038,8 @@ test('a MembraneError from another copy of membrane is recognised by its name', 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 oddRecord = odd.failuresLog.trim().split('\n').map((l) => JSON.parse(l)).find((r) => r.kind === 'inference-exhausted'); + assert.ok(oddRecord.errorType.length <= 128, `failures.log type is ${oddRecord.errorType.length} chars`); const line = odd.errs.find((e) => e.startsWith('[inference-failed] agent=resident'))!; assert.ok(line.length < 2_500, `stderr line is ${line.length} chars`); @@ -1089,8 +1118,8 @@ test('the breaker reads the status a real failure carries: a 404 never sheds; a } else { assert.equal(shed.length, 0, `${label} sheds nothing`); assert.deepEqual(kept, ['hello 0', 'hello 1', 'hello 2'], `${label}: the history still holds every exchange`); - // Only the shed is gated: each failure is still marked and logged. - assert.equal(markers.length, 3, `${label}: an [inference-failed] marker per failure`); + // Only the shed is gated: each failure is still logged, and, since each turn did nothing, none is marked. + assert.deepEqual(markers, [], `${label}: no [inference-failed] marker`); const records = failuresLog.trim().split('\n').filter(Boolean).map((line) => JSON.parse(line)) .filter((record) => record.kind === 'inference-exhausted'); assert.deepEqual(records.map((record) => record.httpStatus), [404, 404, 404], `${label}: a failures.log record per failure`); diff --git a/test/inference-failure-observability.test.ts b/test/inference-failure-observability.test.ts index d589610e8..74517d71b 100644 --- a/test/inference-failure-observability.test.ts +++ b/test/inference-failure-observability.test.ts @@ -14,6 +14,7 @@ function makeHarness() { fw.exhaustionRewinds = new Map(); fw.rewindEpisode = new Map(); fw.lastInferenceAt = new Map(); // upstream last-inference tracking; noteInferenceExhausted writes it + fw.exhaustedTurns = new Map(); fw.pendingRequests = []; // opsAlert plumbing (hard-down now routes through it): trace fan-out + // webhook cooldown state. No CONNECTOME_OPS_WEBHOOK in env → no fetch. @@ -38,16 +39,26 @@ function makeHarness() { return { fw, markers, errs, restore }; } -test('exhausted inference: stderr line + [inference-failed] chronicle marker', () => { +test('exhausted inference of a turn that did nothing: a stderr line with the reason, and no chronicle marker', () => { const { fw, markers, errs, restore } = makeHarness(); try { fw.noteInferenceExhausted('cairn', '400 image exceeds 5 MB'); } finally { restore(); } - // (1) stderr, with the underlying reason assert.ok(errs.some(e => e.includes('[inference-failed]') && e.includes('image exceeds 5 MB')), 'should log the failure + reason to stderr'); - // (2) agent-facing chronicle marker carrying the reason, tagged for filtering + assert.deepEqual(markers, []); +}); + +test('exhausted inference of a turn that got partway: one [inference-failed] chronicle marker with the reason', () => { + const { fw, markers, errs, restore } = makeHarness(); + fw.exhaustedTurns.set('cairn', { roundsRan: true, callsCutOff: false, liveSpeech: false, speechRouting: false }); + try { + fw.noteInferenceExhausted('cairn', '400 image exceeds 5 MB'); + } finally { restore(); } + + assert.ok(errs.some(e => e.includes('[inference-failed]') && e.includes('image exceeds 5 MB')), + 'should log the failure + reason to stderr'); assert.equal(markers.length, 1); assert.match(markers[0].text, /\[inference-failed\]/); assert.match(markers[0].text, /image exceeds 5 MB/); diff --git a/test/prose-drafts.test.ts b/test/prose-drafts.test.ts index d025d20b8..7e6507fe4 100644 --- a/test/prose-drafts.test.ts +++ b/test/prose-drafts.test.ts @@ -4198,13 +4198,15 @@ describe('a turn whose stream fails or is stopped after a tool round', () => { } }); - it('a failure with no round keeps the marker saying nothing was sent', async () => { + it('a failure with no round writes no marker, since the turn did nothing', async () => { const h = await harness({ retries: 0 }); try { + const exhausted: unknown[] = []; + h.framework.onTrace((event) => { if ((event as { type: string }).type === 'inference:exhausted') exhausted.push(event); }); breakAfterToolRound(h.membrane, 'error', { fromStart: true }); await h.turn([]); - assert.equal(markers(h).length, 1); - assert.match(markers(h)[0]!, /the model call failed( \([^)]*\))? and produced no response, so nothing was sent/); + assert.equal(exhausted.length, 1, 'premise: the turn failed'); + assert.deepEqual(markers(h), []); } finally { await h.close(); } diff --git a/test/provider-waits.test.ts b/test/provider-waits.test.ts index 12be69edf..220aa2b2c 100644 --- a/test/provider-waits.test.ts +++ b/test/provider-waits.test.ts @@ -762,9 +762,8 @@ test("a non-retryable failure worded as organization acceleration keeps its term try { fw.pushEvent({ type: 'external-message', source: 'test', content: 'zz-first', metadata: {} }); await fw.runUntilIdle(); - const markers = fw.getAgent('resident')!.getContextManager().queryMessages({}).messages - .filter((m) => (m.metadata as { kind?: string } | undefined)?.kind === 'inference-failed'); - assert.equal(markers.length, 1, 'terminal: its marker is written'); + assert.equal(log.lines.filter((l) => l.startsWith('[inference-failed] agent=resident consecutive=1 ')).length, 1, + 'terminal: the turn ends exhausted'); assert.equal(internal.providerAccelerationCooldowns.get('resident')?.heldRequests.length ?? 0, 0, 'not retained for retry'); } finally { await fw.stop(); log.restore(); } }); @@ -1067,9 +1066,8 @@ test('a non-retryable failure with a stated wait keeps its terminal disposition; fw.pushEvent({ type: 'external-message', source: 'test', content: 'zz-first', metadata: {} }); await fw.runUntilIdle(); assert.equal(membrane.primary, 1); - const markers = () => fw.getAgent('resident')!.getContextManager().queryMessages({}).messages - .filter((m) => (m.metadata as { kind?: string } | undefined)?.kind === 'inference-failed'); - assert.equal(markers().length, 1, 'the failure is terminal: its marker is written'); + const exhausted = () => log.lines.filter((l) => l.startsWith('[inference-failed] agent=resident consecutive=')).length; + assert.equal(exhausted(), 1, 'the failure is terminal: the turn ends exhausted'); assert.equal(internal.providerAccelerationCooldowns.get('resident')?.heldRequests.length ?? 0, 0, 'the failed request is not retained for retry'); // Real time passes the wait before the later wake, as on a loaded host. diff --git a/test/turn-inputs-pin.test.ts b/test/turn-inputs-pin.test.ts index c6e5b5331..51d3c971d 100644 --- a/test/turn-inputs-pin.test.ts +++ b/test/turn-inputs-pin.test.ts @@ -425,10 +425,11 @@ test('when the compile refuses without the pin too, the pin is dropped once and } }; ask(framework); - await waitUntil('the turn to end', () => failureRows(framework).length > 0 || storedText(framework).includes(FINAL)); + const failed = () => logged.filter((line) => line.startsWith('[inference-failed] agent=prime consecutive=')); + await waitUntil('the turn to end', () => failed().length > 0 || storedText(framework).includes(FINAL)); assert.deepEqual(refusals, [{ pinned: 1, name: 'OverBudgetError' }, { pinned: 0, name: 'OverBudgetError' }], 'the compile refused with the pin, then once more without it'); - assert.equal(failureRows(framework)[0]?.errorType, 'over_budget', "the turn ended with the compile's refusal"); + assert.match(failed()[0] ?? '', / type=over_budget[ :]/, "the turn ended with the compile's refusal"); assert.equal(membrane.streams.length, 0, 'no request was sent'); assert.deepEqual(inputPins(framework), [], 'no pin is left'); }, { errorPolicy }); From ac5117f832d043c3a2e29fbeecb3d66dee4cca47 Mon Sep 17 00:00:00 2001 From: Alfred-2451 Date: Thu, 5 Nov 2026 19:40:53 -0500 Subject: [PATCH 2/6] fix(framework): answer #985's first automatic review The automatic review of 227878ad5 (12 findings) is answered here where a change was called for: - noteFailedTurnEnd now deletes the agent's exhaustedTurns entry when the failed turn didn't get partway, so each failed turn's end sets its own entry. Before, an entry left behind by a throw between noteFailedTurnEnd and noteInferenceExhausted (in settleAgent or the error's classification) would have given a later turn that did nothing a note with the earlier turn's rounds. (12) - The [assistant-persist] stderr line for a thinking-only reply now ends "If it was refused, see its [inference-refusal] line and failures.log record." rather than promising that they say why: with no category and no explanation from the provider, neither does. (9) - README and the changelog fragment no longer say a did-nothing turn's failure goes to operators alone: when the poison-history breaker sheds history, its [refusal-rewind] note carries the failure's reason, as before. README no longer says the message that woke such a turn is in the agent's context, which a silent heartbeat's prompt and a message the breaker shed are not. (2, 5) - The fragment says the reply judge, which reads the agent's context, no longer sees that a turn which did nothing failed (1), and names two more published sentences beside what's true now: 0.22.1's "a non-retryable failure that states a wait keeps its terminal disposition (its marker and failure count)" (3), and the reworded [assistant-persist] line. - Comments this change had reworded with new words are cut back to deletions: the refusal guard's parenthetical, "(streak, failures.log)", the (2) marker comment as on main, the noteInferenceExhausted doc's item 2, and a test comment. (10) - Test premises: the reopen and seventeen-turn tests check that their turns exhausted (3 and 17 inference:exhausted traces), and the SUPPRESS_INFERENCE_FAILED_MARKER test checks that its turn got partway, its tool's result being in the stored context. (7, 8) Checks at this tree: npx tsc --noEmit clean; the 15 test files that name the note, 633 of 633 pass. --- README.md | 2 +- .../979-inference-failed-telemetry.changed.md | 19 +++++++++++++++---- src/agent.ts | 7 +++---- src/framework.ts | 17 ++++++++--------- test/inference-failed-telemetry.test.ts | 3 +++ test/inference-failure-bounds.test.ts | 2 +- 6 files changed, 31 insertions(+), 19 deletions(-) diff --git a/README.md b/README.md index cfef37dbf..81161756a 100644 --- a/README.md +++ b/README.md @@ -806,7 +806,7 @@ A caller's stop and an operator's quiesce abandon also reach a turn that has no In XML tool mode, or with a membrane that gives a tool round no `roundContent`, such a round's speech reaches a channel only when its stream completes. When the stream ends any other way (a failure, a stop, a tool that ends the turn, an error policy's retry, a context-budget or tool-result-guard restart, a quiesce abandon or `stop()`), the rounds' words are already in the agent's context, and a `[speech-not-posted]` notice tells the agent that nothing it wrote before its tool calls in those rounds was posted, so it can send what should go out again. It's written once for those rounds: where the turn ends, or before a retry's or a restart's request is sent. A turn its own `skip_reply` ends, a silent turn, a round still waiting on its tools when its stream ends (which never reaches the context) and the rounds of a stream that completes get none. In XML tool mode with thinking on, a round whose text was only thinking gets the notice too, since the framework has only the round's raw text there. A failed turn's `[inference-failed]` note says that its earlier rounds ran when any round reached the context with its results, and that a round's tool calls were started and may have taken effect when any of its streams ended before that round's results came back; a caller's stop says the latter in its `[turn-interrupted]` note too. A turn that fails, or that a caller stops, writes no `[delivered]` receipt, so when its rounds' plain speech was delivered live (native tool mode, in locus or hybrid routing), its `[inference-failed]` note, or the stop's `[turn-interrupted]` note, says that speech was handed on for delivery as written and that no `[delivered]` line was written for it. When some of its speech was still being routed as the turn ended, the note also says it may yet be posted and to check the channel before sending it again. A delivery that finished undelivered gets neither: a channel delivery's `[discord-send-failed]` note, or a refused `>>>` envelope's bounce, already says what happened. A quiesce abandon and `stop()` write neither note. -A failed turn writes its `[inference-failed]` note only when it got partway: when one of its rounds reached the agent's context with its results, or had its tool calls started and cut off. A turn that failed before either writes no note: its failure goes to operators alone, as before, in stderr's `[inference-failed] agent=…` line, `failures.log`'s `inference-exhausted` record and the `inference:exhausted` trace, and a message that woke it is already in the agent's context. So a failure that comes back at every turn's first call, such as a provider that's down or a context that's too long, no longer grows the agent's context. A turn that got partway gets one note, which says how far it got and the reason, and, when its last call timed out, that a reply still owed can be given now. `SUPPRESS_INFERENCE_FAILED_MARKER=1` leaves that note out. Notes already in a store stay. +A failed turn writes its `[inference-failed]` note only when it got partway: when one of its rounds reached the agent's context with its results, or had its tool calls started and cut off. A turn that failed before either writes no note. Everything else its failure does is as before: stderr's `[inference-failed] agent=…` line, `failures.log`'s `inference-exhausted` record, the consecutive-failure streak, the `inference:exhausted` trace, the hard-down alert, and, when the poison-history breaker sheds history, its `[refusal-rewind]` note, which carries the failure's reason. So a failure that comes back at every turn's first call, such as a provider that's down or a context that's too long, no longer grows the agent's context. A turn that got partway gets one note, which says how far it got and the reason, and, when its last call timed out, that a reply still owed can be given now. `SUPPRESS_INFERENCE_FAILED_MARKER=1` leaves that note out. Notes already in a store stay. ## API Server diff --git a/changelog.d/979-inference-failed-telemetry.changed.md b/changelog.d/979-inference-failed-telemetry.changed.md index 3d32d4381..5865b7afe 100644 --- a/changelog.d/979-inference-failed-telemetry.changed.md +++ b/changelog.d/979-inference-failed-telemetry.changed.md @@ -1,11 +1,12 @@ - **Residents:** a turn whose inference is exhausted before it got partway writes no `[inference-failed]` note into the agent's context. Partway means one of its rounds reached the context with its results, or had its tool - calls started and cut off. Its failure goes to operators alone: - stderr's `[inference-failed] agent=…` line, `failures.log`'s + calls started and cut off. Everything else its failure does is as + before: stderr's `[inference-failed] agent=…` line, `failures.log`'s `inference-exhausted` record, the consecutive-failure streak, the - `inference:exhausted` trace, the hard-down alert and the poison-history - breaker, each as before. So a failure that comes back at every turn's first + `inference:exhausted` trace, the hard-down alert, and the poison-history + breaker, whose `[refusal-rewind]` note carries the failure's reason when + it sheds history. So a failure that comes back at every turn's first call, such as a provider that's down or a context that's too long, no longer adds a note per turn to the context it's sent with (#979). - A turn that got partway still gets one note, which says how far it got @@ -15,6 +16,8 @@ identically (e.g. drop an oversized attachment or an unsupported setting)." A timed-out turn's note keeps "If a reply is still owed from that turn, you can give it now." + - The reply judge reads the agent's context, so it no longer sees that a + turn which did nothing failed. - `SUPPRESS_INFERENCE_FAILED_MARKER=1` now leaves out only that note, since no other is written. - Notes already in a store stay as they are. @@ -31,6 +34,9 @@ of it ran or had its tool calls cut off; any other failure of it writes one." Now a failure of a re-armed turn writes a note only when a round of it ran or had its tool calls cut off, as any turn's failure does. + - 0.22.1: "a non-retryable failure that states a wait keeps its terminal + disposition (its marker and failure count)". Now such a failure keeps + its failure count, and its marker only when its turn got partway. - 0.29.0: "A re-armed turn's transient failure writes no `[inference-failed]` marker unless it got partway, so the agent's context keeps the one the first exhaustion wrote; a failure of another @@ -41,6 +47,11 @@ did … Other failures keep their wording and advice." Now only a turn that got partway has the note, which says its last call timed out, and no failure's note carries the advice. + - The `[assistant-persist]` stderr line for a thinking-only reply the + store refuses ended "See the refusal/inference-failed record for why.", + though a refusal never wrote an `[inference-failed]` note. It now + ends "If it was refused, see its [inference-refusal] line and + failures.log record." - Earlier entries' wording of the note for a turn that did nothing ("the model call failed … and produced no response, so nothing was sent") describes only notes already in stores. diff --git a/src/agent.ts b/src/agent.ts index 0b2b81d42..30592ae19 100644 --- a/src/agent.ts +++ b/src/agent.ts @@ -2371,16 +2371,15 @@ export class Agent { // in the latest assistant message cannot be modified", unrecoverable by // retry (labclaude, 2026-07-27: hard down ~4h on exactly this pair). // - // Refused turns are surfaced by the refusal path (stderr's - // [inference-refusal] line and failures.log's refusal record); the store - // does not also need a content-free artifact of them. Loud, never silent. + // Refused turns are surfaced by the refusal path; the store does not + // also need a content-free artifact of them. Loud, never silent. if (content.length > 0 && content.every( (b) => b.type === 'thinking' || b.type === 'redacted_thinking', )) { console.error( `[assistant-persist] agent=${this.name}: refusing to store a thinking-only assistant ` + `message (${content.length} block(s), no text and no tool_use) — the turn produced no ` + - `output. If it was refused, its [inference-refusal] line and failures.log record say why.`, + `output. If it was refused, see its [inference-refusal] line and failures.log record.`, ); return undefined; } diff --git a/src/framework.ts b/src/framework.ts index 7e5501dd7..4c03002c7 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -7767,7 +7767,7 @@ export class AgentFramework { error: 'Stream cancelled', }, closes, stream); // Distinct trace type: emitTrace funnels every inference:exhausted into - // noteInferenceExhausted (streak, failures.log, a partway turn's note); inference:aborted + // noteInferenceExhausted (streak, failures.log); inference:aborted // carries the honest cause without any of that. this.emitTrace({ type: 'inference:aborted', @@ -21544,6 +21544,8 @@ export class AgentFramework { roundsRan: routing.roundsRan === true, callsCutOff, liveSpeech: routing.liveSpeech === true, speechRouting: (routing.speechRouting ?? 0) > 0, }); + } else { + this.exhaustedTurns?.delete(agent.name); } } @@ -32153,13 +32155,10 @@ export class AgentFramework { * * 1. stderr — always, with the underlying API reason. The place an * operator greps; previously empty in headless mode. - * 2. chronicle marker — for a turn that got partway (noteFailedTurnEnd - * recorded it: a round ran, or a round's tool calls were cut off), one - * `[inference-failed]` message, so the agent learns how far the turn - * got, which of its calls ran or may have taken effect, and why it - * failed. A turn that did nothing gets none: the failure is - * telemetry (#979). addMessage does NOT request inference, so this - * never causes a retry/wake loop. + * 2. chronicle marker — for a turn that got partway, a `[inference-failed]` + * message so the agent itself learns its turn failed and why. + * addMessage does NOT request inference, so this never causes a + * retry/wake loop. * 3. escalation — after N consecutive failures the agent is hard-down; * log that loudly (a repeated identical failure is the textbook signal). * 4. breaker — when a failure at or past the hard-down threshold suggests @@ -32572,7 +32571,7 @@ export class AgentFramework { // classification fields are additive. this.logFailure({ agent: agentName, consecutive: streak, reason, kind: 'inference-exhausted', ...classification, ...cutAt(reason) }); - // (2) Agent-facing chronicle marker, for a turn that got partway only (no inference triggered → no loop). + // (2) Agent-facing chronicle marker (no inference triggered → no loop). const agent = this.agents.get(agentName); if (agent && ended && process.env.SUPPRESS_INFERENCE_FAILED_MARKER !== '1') { const timedOut = errorType === 'timeout'; diff --git a/test/inference-failed-telemetry.test.ts b/test/inference-failed-telemetry.test.ts index 7329691d4..887c850ff 100644 --- a/test/inference-failed-telemetry.test.ts +++ b/test/inference-failed-telemetry.test.ts @@ -159,6 +159,7 @@ test('a framework reopened on the store after turns that did nothing holds none const membrane = new ScriptedMembrane(() => 'fails'); const r = await resident(t, membrane); for (const n of [1, 2, 3]) await r.say(`zz-hello ${n}`); + assert.equal(r.traces.filter((e) => e.type === 'inference:exhausted').length, 3, 'premise: three turns exhausted'); await r.reopen(); assert.deepEqual(r.notes(), []); assert.deepEqual(r.stored().flatMap((m) => m.content).map((b) => (b as { text?: string }).text), ['zz-hello 1', 'zz-hello 2', 'zz-hello 3']); @@ -169,6 +170,7 @@ test('seventeen failures leave each next request as it would be without them: wh const r = await resident(t, membrane); for (let n = 1; n <= 18; n++) await r.say(`zz-hello ${n}`); assert.equal(membrane.sends.length, 18, 'premise: seventeen failed sends, then one that answered'); + assert.equal(r.traces.filter((e) => e.type === 'inference:exhausted').length, 17, 'premise: seventeen turns exhausted'); assert.ok(r.stored().some((m) => m.content.some((b) => (b as { text?: string }).text === 'zz-answer-18')), 'premise: the eighteenth answered'); for (let n = 1; n < 18; n++) { assert.deepEqual(texts(membrane.sends[n]!), [...texts(membrane.sends[n - 1]!), `zz-hello ${n + 1}`], `send ${n + 1}`); @@ -207,6 +209,7 @@ test('SUPPRESS_INFERENCE_FAILED_MARKER=1 leaves out the note for a turn that got const r = await resident(t, membrane); await r.say('zz-hello'); assert.equal(r.traces.filter((e) => e.type === 'inference:exhausted').length, 1, 'premise: the turn exhausted'); + assert.ok(r.stored().some((m) => JSON.stringify(m.content).includes('zz-looked')), 'premise: the turn got partway, its round in the context with its result'); assert.deepEqual(r.notes(), []); assert.equal(r.failures().filter((f) => f.kind === 'inference-exhausted').length, 1); }); diff --git a/test/inference-failure-bounds.test.ts b/test/inference-failure-bounds.test.ts index 2ba9f2cff..e9b3f2553 100644 --- a/test/inference-failure-bounds.test.ts +++ b/test/inference-failure-bounds.test.ts @@ -1118,7 +1118,7 @@ test('the breaker reads the status a real failure carries: a 404 never sheds; a } else { assert.equal(shed.length, 0, `${label} sheds nothing`); assert.deepEqual(kept, ['hello 0', 'hello 1', 'hello 2'], `${label}: the history still holds every exchange`); - // Only the shed is gated: each failure is still logged, and, since each turn did nothing, none is marked. + // Only the shed is gated: each failure is still logged. assert.deepEqual(markers, [], `${label}: no [inference-failed] marker`); const records = failuresLog.trim().split('\n').filter(Boolean).map((line) => JSON.parse(line)) .filter((record) => record.kind === 'inference-exhausted'); From 098e635e23196dd66c4928752ef3d1fcbe9828a5 Mon Sep 17 00:00:00 2001 From: Alfred-2451 Date: Thu, 5 Nov 2026 20:00:01 -0500 Subject: [PATCH 3/6] docs(changelog): the reply judge loses the note, not every sign of a failure The fragment said the reply judge no longer sees that a turn which did nothing failed. When the poison-history breaker sheds history, its [refusal-rewind] note in the agent's context carries the failure's reason, and the judge reads that context, so it can still see such a failure there. What it loses is the [inference-failed] note for that turn, which the fragment now says. --- changelog.d/979-inference-failed-telemetry.changed.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/changelog.d/979-inference-failed-telemetry.changed.md b/changelog.d/979-inference-failed-telemetry.changed.md index 5865b7afe..74e498adb 100644 --- a/changelog.d/979-inference-failed-telemetry.changed.md +++ b/changelog.d/979-inference-failed-telemetry.changed.md @@ -16,8 +16,8 @@ identically (e.g. drop an oversized attachment or an unsupported setting)." A timed-out turn's note keeps "If a reply is still owed from that turn, you can give it now." - - The reply judge reads the agent's context, so it no longer sees that a - turn which did nothing failed. + - The reply judge reads the agent's context, so it no longer sees an + `[inference-failed]` note for a turn that did nothing. - `SUPPRESS_INFERENCE_FAILED_MARKER=1` now leaves out only that note, since no other is written. - Notes already in a store stay as they are. From c029911dfd4f8de9c88cc715770640ecdc75f426 Mon Sep 17 00:00:00 2001 From: Alfred-2451 Date: Thu, 5 Nov 2026 20:28:04 -0500 Subject: [PATCH 4/6] fix(framework): answer #985's second automatic review - README's paragraph on when the note is written said a failure at every turn's first call "no longer grows the agent's context". When the poison-history breaker sheds history, its rewind note can be longer than the exchange it replaces, so it now says such a failure no longer adds a note per turn to the agent's context, as the changelog fragment does. (1) - The [assistant-persist] stderr line for a thinking-only reply the store refuses no longer says "the turn produced no output": a turn whose earlier rounds ran and whose final response is thinking-only did produce output. "(N block(s), no text and no tool_use)" already says what the response lacked. The fragment quotes the line's old ending beside the new one with both changes. (2) In src only that log line's text changes, and no test reads it. --- README.md | 2 +- changelog.d/979-inference-failed-telemetry.changed.md | 10 ++++++---- src/agent.ts | 4 ++-- 3 files changed, 9 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index 81161756a..f4a061e56 100644 --- a/README.md +++ b/README.md @@ -806,7 +806,7 @@ A caller's stop and an operator's quiesce abandon also reach a turn that has no In XML tool mode, or with a membrane that gives a tool round no `roundContent`, such a round's speech reaches a channel only when its stream completes. When the stream ends any other way (a failure, a stop, a tool that ends the turn, an error policy's retry, a context-budget or tool-result-guard restart, a quiesce abandon or `stop()`), the rounds' words are already in the agent's context, and a `[speech-not-posted]` notice tells the agent that nothing it wrote before its tool calls in those rounds was posted, so it can send what should go out again. It's written once for those rounds: where the turn ends, or before a retry's or a restart's request is sent. A turn its own `skip_reply` ends, a silent turn, a round still waiting on its tools when its stream ends (which never reaches the context) and the rounds of a stream that completes get none. In XML tool mode with thinking on, a round whose text was only thinking gets the notice too, since the framework has only the round's raw text there. A failed turn's `[inference-failed]` note says that its earlier rounds ran when any round reached the context with its results, and that a round's tool calls were started and may have taken effect when any of its streams ended before that round's results came back; a caller's stop says the latter in its `[turn-interrupted]` note too. A turn that fails, or that a caller stops, writes no `[delivered]` receipt, so when its rounds' plain speech was delivered live (native tool mode, in locus or hybrid routing), its `[inference-failed]` note, or the stop's `[turn-interrupted]` note, says that speech was handed on for delivery as written and that no `[delivered]` line was written for it. When some of its speech was still being routed as the turn ended, the note also says it may yet be posted and to check the channel before sending it again. A delivery that finished undelivered gets neither: a channel delivery's `[discord-send-failed]` note, or a refused `>>>` envelope's bounce, already says what happened. A quiesce abandon and `stop()` write neither note. -A failed turn writes its `[inference-failed]` note only when it got partway: when one of its rounds reached the agent's context with its results, or had its tool calls started and cut off. A turn that failed before either writes no note. Everything else its failure does is as before: stderr's `[inference-failed] agent=…` line, `failures.log`'s `inference-exhausted` record, the consecutive-failure streak, the `inference:exhausted` trace, the hard-down alert, and, when the poison-history breaker sheds history, its `[refusal-rewind]` note, which carries the failure's reason. So a failure that comes back at every turn's first call, such as a provider that's down or a context that's too long, no longer grows the agent's context. A turn that got partway gets one note, which says how far it got and the reason, and, when its last call timed out, that a reply still owed can be given now. `SUPPRESS_INFERENCE_FAILED_MARKER=1` leaves that note out. Notes already in a store stay. +A failed turn writes its `[inference-failed]` note only when it got partway: when one of its rounds reached the agent's context with its results, or had its tool calls started and cut off. A turn that failed before either writes no note. Everything else its failure does is as before: stderr's `[inference-failed] agent=…` line, `failures.log`'s `inference-exhausted` record, the consecutive-failure streak, the `inference:exhausted` trace, the hard-down alert, and, when the poison-history breaker sheds history, its `[refusal-rewind]` note, which carries the failure's reason. So a failure that comes back at every turn's first call, such as a provider that's down or a context that's too long, no longer adds a note per turn to the agent's context. A turn that got partway gets one note, which says how far it got and the reason, and, when its last call timed out, that a reply still owed can be given now. `SUPPRESS_INFERENCE_FAILED_MARKER=1` leaves that note out. Notes already in a store stay. ## API Server diff --git a/changelog.d/979-inference-failed-telemetry.changed.md b/changelog.d/979-inference-failed-telemetry.changed.md index 74e498adb..cdda32f6e 100644 --- a/changelog.d/979-inference-failed-telemetry.changed.md +++ b/changelog.d/979-inference-failed-telemetry.changed.md @@ -48,10 +48,12 @@ that got partway has the note, which says its last call timed out, and no failure's note carries the advice. - The `[assistant-persist]` stderr line for a thinking-only reply the - store refuses ended "See the refusal/inference-failed record for why.", - though a refusal never wrote an `[inference-failed]` note. It now - ends "If it was refused, see its [inference-refusal] line and - failures.log record." + store refuses ended "— the turn produced no output. See the + refusal/inference-failed record for why.", though a turn whose earlier + rounds ran produced output, and a refusal never wrote an + `[inference-failed]` note. It now ends "(… no text and no tool_use). + If it was refused, see its [inference-refusal] line and failures.log + record." - Earlier entries' wording of the note for a turn that did nothing ("the model call failed … and produced no response, so nothing was sent") describes only notes already in stores. diff --git a/src/agent.ts b/src/agent.ts index 30592ae19..06f666c93 100644 --- a/src/agent.ts +++ b/src/agent.ts @@ -2378,8 +2378,8 @@ export class Agent { )) { console.error( `[assistant-persist] agent=${this.name}: refusing to store a thinking-only assistant ` + - `message (${content.length} block(s), no text and no tool_use) — the turn produced no ` + - `output. If it was refused, see its [inference-refusal] line and failures.log record.`, + `message (${content.length} block(s), no text and no tool_use). If it was refused, see ` + + `its [inference-refusal] line and failures.log record.`, ); return undefined; } From 4a367ba80d0a0b851678c922ca3a94fc8ab5c6f2 Mon Sep 17 00:00:00 2001 From: Alfred-2451 Date: Sun, 8 Nov 2026 00:24:43 -0500 Subject: [PATCH 5/6] test(framework): a turn that streams plain speech with no tool round, then fails, posts nothing (R1-3) #985 drops the [inference-failed] note for a turn that didn't get partway. That's safe only while such a turn has posted nothing. Under locus and hybrid routing, native tool mode routes a round's plain speech live at its tool-calls event, and a round without tool calls is delivered when its stream completes. The new test pins that: a text-only turn whose stream fails where it would have completed posts nothing and writes no note, and the same turn, completing, posts its speech once. Until now only a probe outside the suite checked this. breakAfterToolRound's new atCompletion option fails a stream at its complete event, after beforeFailure. --- test/prose-drafts.test.ts | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) diff --git a/test/prose-drafts.test.ts b/test/prose-drafts.test.ts index c3d4047ba..868e3d052 100644 --- a/test/prose-drafts.test.ts +++ b/test/prose-drafts.test.ts @@ -282,6 +282,7 @@ function breakAfterToolRound( how: 'error' | 'throw' | 'abort' | 'stop', opts: { fromStart?: boolean; + atCompletion?: boolean; stopEnds?: 'aborted' | 'error' | 'silent' | 'throw'; stream?: number; failure?: () => Error; @@ -309,6 +310,7 @@ function breakAfterToolRound( }) as unknown as StreamEvent; if (opts.fromStart) { yield failure(); return; } for await (const event of inner) { + if (opts.atCompletion && event.type === 'complete') { await opts.beforeFailure?.(); yield failure(); return; } yield event; if (event.type !== 'tool-calls') continue; while (!resultsGiven && !cancelled) await new Promise((resolve) => { wake = resolve; }); @@ -4338,6 +4340,29 @@ describe('a turn whose stream fails or is stopped after a tool round', () => { } }); + it('locus and hybrid: plain speech streamed with no tool round, then a failure, posts nothing and writes no marker; the same turn completing posts it once', async () => { + for (const proseRouting of ['locus', 'hybrid'] as const) { + for (const fails of [true, false]) { + const at = `${proseRouting}, ${fails ? 'failing' : 'completing'}`; + const h = await harness({ agents: [{ name: 'scout', proseRouting }], retries: 0 }); + try { + const exhausted: unknown[] = []; + h.framework.onTrace((event) => { if ((event as { type: string }).type === 'inference:exhausted') exhausted.push(event); }); + if (fails) breakAfterToolRound(h.membrane, 'error', { atCompletion: true, beforeFailure: () => speechSettled(h) }); + await h.turn([createMockResponse([text(SPEECH)])]); + if (!fails) await h.until(() => published(h, SPEECH).length === 1, `${at}: the speech is posted`); + await speechSettled(h); + assert.equal(exhausted.length, fails ? 1 : 0, `premise, ${at}: the turn ${fails ? 'failed' : 'completed'}`); + if (fails) assert.deepEqual(h.publishes().filter((p) => p.event === 'publish').map((p) => p.text), [], at); + else assert.equal(published(h, SPEECH).length, 1, at); + assert.deepEqual(markers(h), [], at); + } finally { + await h.close(); + } + } + } + }); + it('a retry that succeeds writes one receipt, at the end of the turn, and no failure note', async () => { const h = await harness({ retries: 1 }); try { From c7a7956f59e79ac3ea66ee2dea7515ff16437acd Mon Sep 17 00:00:00 2001 From: Alfred-2451 Date: Sun, 8 Nov 2026 05:25:11 -0500 Subject: [PATCH 6/6] fix(framework): drop noteFailedTurnEnd's branch that no path reaches noteFailedTurnEnd deleted the agent's exhaustedTurns entry when a failed turn didn't get partway. It was there for an entry left behind by a throw between noteFailedTurnEnd and noteInferenceExhausted. At each of the four sites, nothing that runs between them throws: - one site first deletes the turn's token and trigger from their maps; - settleAgent's steps are map and set updates, catch their own failures (nameUnpostedSpeech, unpinTurnInputs), only start asynchronous work (a script's stop), or settle a promise; - statedWaitNotSlept builds a string; - classifyInferenceError reads an Error's fields. emitTrace hands inference:exhausted to noteInferenceExhausted first, and that takes the entry and deletes it before anything else. So no entry outlives the turn that set it, and the branch had nothing to clear. --- src/framework.ts | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/framework.ts b/src/framework.ts index 751f92882..cef7e339f 100644 --- a/src/framework.ts +++ b/src/framework.ts @@ -23786,8 +23786,6 @@ export class AgentFramework { roundsRan: routing.roundsRan === true, callsCutOff, liveSpeech: routing.liveSpeech === true, speechRouting: (routing.speechRouting ?? 0) > 0, }); - } else { - this.exhaustedTurns?.delete(agent.name); } }