From 6b4f9a54bbc6dcdc815f1cce1c94465edf46f866 Mon Sep 17 00:00:00 2001 From: Abigail-2459 Date: Sat, 17 Oct 2026 11:57:06 -0400 Subject: [PATCH 1/5] fix(tune-out): a timer whose work throws reports it, and the cadence arms before its turn On main at 3adbdb869, on Node 24.22.0 with real timers, a subconscious turn that threw inside a cadence tick (the coordinator's addMessage hook throwing once) left the timer callback as an uncaughtException, and the cadence never armed again: with another message diverted, no turn came in the next six periods. An exception thrown in a timer callback ends the process on Node and on Bun. The cadence tick now arms its next period before its turn, so a turn that fails can't end the cadence. Each of the coordinator's three timer callbacks, the cadence tick, the coalesced wake and the end time's cancel, catches what its work throws and reports it in a tune-out:timer-failed trace that names the timer and the error, as acknowledgeSuppressed reports tune-out:ack-failed. The tests make the addMessage hook throw once: in a cadence turn, in a coalesced wake's turn and in the end time's cancel. Each asserts that nothing leaves the mock timers' tick(), since node:test's mock runs a callback that threw once more at its next tick, and that the trace names the timer. After the cadence's failed turn, the next period's turn comes. A thrown string is reported as itself. The test file's header now says what it covers without an internal tracking number. Co-Authored-By: Claude Opus 5.5 --- changelog.d/tune-out-timer-failures.fixed.md | 6 ++ src/tune-out/coordinator.ts | 72 ++++++++++++------ test/tune-out-timers.test.ts | 77 ++++++++++++++++++-- 3 files changed, 127 insertions(+), 28 deletions(-) create mode 100644 changelog.d/tune-out-timer-failures.fixed.md diff --git a/changelog.d/tune-out-timer-failures.fixed.md b/changelog.d/tune-out-timer-failures.fixed.md new file mode 100644 index 000000000..5eef61a91 --- /dev/null +++ b/changelog.d/tune-out-timer-failures.fixed.md @@ -0,0 +1,6 @@ +- A tune-out's cadence, coalesced wake or end time whose work throws, such + as a store write that fails during the subconscious's turn, no longer + throws into the event loop, where an uncaught exception ends the host + process. The coordinator reports it as a `tune-out:timer-failed` trace + naming the timer and the error. Before, a cadence whose turn threw also + never armed again; now it arms its next period before the turn. diff --git a/src/tune-out/coordinator.ts b/src/tune-out/coordinator.ts index 021610336..9ae8c6369 100644 --- a/src/tune-out/coordinator.ts +++ b/src/tune-out/coordinator.ts @@ -112,8 +112,24 @@ export class TuneOutCoordinator { const existing = this.expiryTimers.get(key); if (existing) clearTimeout(existing); armAt(params.expiresAtMs, (timer) => { this.expiryTimers.set(key, timer); }, () => { - this.expiryTimers.delete(key); - this.cancel(serverId, channelId, 'duration', 'duration elapsed'); + try { + this.expiryTimers.delete(key); + this.cancel(serverId, channelId, 'duration', 'duration elapsed'); + } catch (err) { + this.timerFailed('expiry', serverId, channelId, err); + } + }); + } + + /** A timer callback's work threw. Report it rather than throw it into the + * event loop, where an uncaught exception ends the host process. */ + private timerFailed(timer: 'cadence' | 'wake' | 'expiry', serverId: string, channelId: string, err: unknown): void { + this.hooks.emitTrace({ + type: 'tune-out:timer-failed', + timer, + serverId, + channelId, + error: err instanceof Error ? err.message : String(err), }); } @@ -377,14 +393,20 @@ export class TuneOutCoordinator { const key = this.key(serverId, channelId); const hold = (timer: ReturnType): void => { this.cadenceTimers.set(key, timer); }; const tick = () => { - const state = this.channelRegistry.getTuneOutState(serverId, channelId); - if (!state) return; // cancelled meanwhile - const diverted = this.divertedSinceInvocation.get(key) ?? 0; - // An empty period needs no turn at all — skip silently. - if (diverted > 0) { - this.invokeSubconscious(serverId, channelId, 'cadence', diverted); + try { + const state = this.channelRegistry.getTuneOutState(serverId, channelId); + if (!state) return; // cancelled meanwhile + // The next period is armed before this one's turn, so a turn that + // fails can't end the cadence. + armAfter(cadenceSeconds * 1000, hold, tick); + const diverted = this.divertedSinceInvocation.get(key) ?? 0; + // An empty period needs no turn at all — skip silently. + if (diverted > 0) { + this.invokeSubconscious(serverId, channelId, 'cadence', diverted); + } + } catch (err) { + this.timerFailed('cadence', serverId, channelId, err); } - armAfter(cadenceSeconds * 1000, hold, tick); }; armAfter(cadenceSeconds * 1000, hold, tick); } @@ -417,21 +439,25 @@ export class TuneOutCoordinator { return; } const timer = setTimeout(() => { - const entry = this.pendingWakes.get(key); - this.pendingWakes.delete(key); - // Count ONE durable wake per coalesced invocation. - const counted = this.channelRegistry.recordTuneOutWake(serverId, channelId); - if (!counted) return; // cancelled inside the window - if (counted.wakeCount > counted.params.maxWakes) { - this.cancel( - serverId, - channelId, - 'tune-out-max-wakes', - `wake budget exhausted (${counted.params.maxWakes})`, - ); - return; + try { + const entry = this.pendingWakes.get(key); + this.pendingWakes.delete(key); + // Count ONE durable wake per coalesced invocation. + const counted = this.channelRegistry.recordTuneOutWake(serverId, channelId); + if (!counted) return; // cancelled inside the window + if (counted.wakeCount > counted.params.maxWakes) { + this.cancel( + serverId, + channelId, + 'tune-out-max-wakes', + `wake budget exhausted (${counted.params.maxWakes})`, + ); + return; + } + this.invokeSubconscious(serverId, channelId, 'wake', entry?.count ?? 1); + } catch (err) { + this.timerFailed('wake', serverId, channelId, err); } - this.invokeSubconscious(serverId, channelId, 'wake', entry?.count ?? 1); }, WAKE_COALESCE_MS); this.pendingWakes.set(key, { count: 1, timer }); } diff --git a/test/tune-out-timers.test.ts b/test/tune-out-timers.test.ts index 5ffc6e59c..0c696cc41 100644 --- a/test/tune-out-timers.test.ts +++ b/test/tune-out-timers.test.ts @@ -1,6 +1,7 @@ /** - * A tune-out's timers hold any length the resident asks for, and enter() - * refuses an option it can't use before anything changes (F76). + * A tune-out's timers hold any length the resident asks for, enter() + * refuses an option it can't use before anything changes, and a timer whose + * work throws reports it rather than throwing it into the event loop. * * Node fires a setTimeout longer than 2^31 - 1 ms (about 24.8 days) almost * at once, so a single timer ended a longer tune-out as soon as it began, @@ -42,6 +43,9 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = }) as unknown as typeof setTimeout; let state: { params: TuneOutParams; wakeCount: number } | null = stored ? { params: stored, wakeCount: 0 } : null; + /** What addMessage throws on its next call, as a failed store write would; null to succeed. */ + let addMessageThrows: unknown = null; + const traces: Array> = []; const entered: TuneOutParams[] = []; /** The source of each cancel that ended a tune-out: 'duration' for an end time. */ const cancels: string[] = []; @@ -63,7 +67,14 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = recordTuneOutWake: () => (state ? { params: state.params, wakeCount: ++state.wakeCount } : null), } as unknown as ChannelRegistry; const hooks = { - addMessage: () => '', + addMessage: () => { + if (addMessageThrows !== null) { + const thrown = addMessageThrows; + addMessageThrows = null; + throw thrown; + } + return ''; + }, requestInference: (_agent: string, reason: string) => { inferences.push(reason); }, subconsciousName: () => 'Subconscious', primaryName: () => 'scout', @@ -73,7 +84,7 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = isForkBound: () => false, isPrivilegedAuthor: () => false, allowChannelSpeech: () => false, - emitTrace: () => {}, + emitTrace: (event: Record) => { traces.push(event); }, } as unknown as TuneOutFrameworkHooks; const coordinator = new TuneOutCoordinator(registry, {} as McplServerRegistry, hooks); t.after(() => { @@ -90,7 +101,13 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = /** End the tune-out in the registry alone, as a send into the channel or a close does. */ const endInRegistry = () => { state = null; }; const active = () => state !== null; - return { coordinator, entered, cancels, cadenceTurns, wakeTurns, delays, noTimerPastOne, endInRegistry, active }; + /** Make addMessage's next call throw `thrown`. */ + const failNextAddMessage = (thrown: unknown = new Error('store write failed')) => { addMessageThrows = thrown; }; + const timerFailures = () => traces.filter((e) => e.type === 'tune-out:timer-failed'); + return { + coordinator, entered, cancels, cadenceTurns, wakeTurns, delays, noTimerPastOne, endInRegistry, active, + failNextAddMessage, timerFailures, + }; } it('a duration past one timer ends at its end time and not before', (t) => { @@ -299,3 +316,53 @@ it('armAt arms a deadline that has passed for the next turn of the loop, with no process.off('warning', onWarning); } }); + +// A timer callback's work can throw, as a failed store write in a subconscious +// turn would. Thrown into the event loop, it's an uncaught exception, which +// ends the host process. Under node:test's mock timers a throw also comes out +// of tick(), and the mock then runs that callback once more at its next tick, +// so these tests assert that nothing leaves tick(), not only what comes after. + +it("a cadence turn that throws stays in its timer, is reported, and the next period's turn comes", (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + h.failNextAddMessage(); + assert.doesNotThrow(() => t.mock.timers.tick(60_000), "the turn's error stays in the timer"); + assert.deepEqual(h.timerFailures(), [ + { type: 'tune-out:timer-failed', timer: 'cadence', serverId: 'disc', channelId: '#a', error: 'store write failed' }, + ]); + assert.deepEqual(h.cadenceTurns(), [], 'the failed turn requested nothing'); + h.coordinator.onIncoming('disc', '#a', 'm2', undefined); + t.mock.timers.tick(60_000); + assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], "the next period's turn comes"); +}); + +it('a coalesced wake whose turn throws stays in its timer and is reported', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', ['chat:addressed']); + h.failNextAddMessage(); + assert.doesNotThrow(() => t.mock.timers.tick(2_000), "the turn's error stays in the timer"); + assert.deepEqual(h.timerFailures().map((e) => [e.timer, e.error]), [['wake', 'store write failed']]); + h.coordinator.onIncoming('disc', '#a', 'm2', ['chat:addressed']); + t.mock.timers.tick(2_000); + assert.deepEqual(h.wakeTurns(), ['tune-out wake: #a'], "the next wake's turn comes"); +}); + +it('an end time whose cancel throws stays in its timer and is reported', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 120 }, 'agent-tool').ok, true); + h.failNextAddMessage(); + assert.doesNotThrow(() => t.mock.timers.tick(120_000), "the cancel's error stays in the timer"); + assert.deepEqual(h.timerFailures().map((e) => [e.timer, e.error]), [['expiry', 'store write failed']]); +}); + +it('a throw that is not an Error is reported as its string', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + h.failNextAddMessage('disk full'); + assert.doesNotThrow(() => t.mock.timers.tick(60_000)); + assert.deepEqual(h.timerFailures().map((e) => e.error), ['disk full']); +}); From 1993af42c02d33dc133f023fd18ee0eb42e29c8b Mon Sep 17 00:00:00 2001 From: Abigail-2459 Date: Sat, 17 Oct 2026 12:17:30 -0400 Subject: [PATCH 2/5] fix(tune-out): a failed turn keeps its count, and a timer failure is written to stderr From our internal review of the previous commit: - invokeSubconscious reset the channel's diverted count before its addMessage, so a cadence turn that threw lost the count, and with no new traffic the next period gave no turn. It now resets the count once the turn has been asked for, so the next period's turn comes and counts the failed turn's messages. - timerFailed wrote only a trace, which reaches nothing on a host with no trace listener, where before the process exited and printed the error. It now also writes the error to stderr, as the framework's other background catches do. - String() of a thrown value can itself throw, for an object with no prototype, which would leave the timer from inside the catch. describeThrown falls back to Object.prototype.toString for such a value. - The expiryTimers comment says cancel clears the end time when it finds the tune-out in the registry. - Tests: the cadence test no longer diverts a second message, and checks the next notice's count. New tests: a stderr line; a cadence tick that finds the tune-out ended in the registry arms nothing; a quiet period arms the next; a wake whose count can't be recorded, and an end time whose registry cancel throws, are reported. The wake and end-time tests compare the whole trace, and an object with no prototype is reported as [object Object]. Co-Authored-By: Claude Opus 5.5 --- changelog.d/tune-out-timer-failures.fixed.md | 7 +- src/tune-out/coordinator.ts | 25 +++- test/tune-out-timers.test.ts | 130 ++++++++++++++----- 3 files changed, 124 insertions(+), 38 deletions(-) diff --git a/changelog.d/tune-out-timer-failures.fixed.md b/changelog.d/tune-out-timer-failures.fixed.md index 5eef61a91..2f5bf0f23 100644 --- a/changelog.d/tune-out-timer-failures.fixed.md +++ b/changelog.d/tune-out-timer-failures.fixed.md @@ -1,6 +1,7 @@ - A tune-out's cadence, coalesced wake or end time whose work throws, such as a store write that fails during the subconscious's turn, no longer throws into the event loop, where an uncaught exception ends the host - process. The coordinator reports it as a `tune-out:timer-failed` trace - naming the timer and the error. Before, a cadence whose turn threw also - never armed again; now it arms its next period before the turn. + process. The coordinator writes the error to stderr and reports a + `tune-out:timer-failed` trace naming the timer. Before, a cadence whose + turn threw also never armed again. Now it arms its next period before + the turn, and that next turn counts the failed turn's messages. diff --git a/src/tune-out/coordinator.ts b/src/tune-out/coordinator.ts index 9ae8c6369..80d7e1aec 100644 --- a/src/tune-out/coordinator.ts +++ b/src/tune-out/coordinator.ts @@ -34,6 +34,17 @@ export const TUNE_OUT_DEFAULTS = { * subconscious turn, and max-wakes counts invocations, not messages. */ const WAKE_COALESCE_MS = 2_000; +/** What a caught value says: an Error's message, or the value as a string. */ +function describeThrown(err: unknown): string { + if (err instanceof Error) return err.message; + try { + return String(err); + } catch { + // A value with no string form, such as an object with no prototype. + return Object.prototype.toString.call(err); + } +} + export interface TuneOutFrameworkHooks { /** Deliver a message into an agent's window (per-agent seam). */ addMessage: ( @@ -66,7 +77,7 @@ export interface TuneOutFrameworkHooks { export class TuneOutCoordinator { private cadenceTimers = new Map>(); /** Each duration's pending expiry step (params.expiresAtMs). stop clears - * it, cancel does while the registry still holds the tune-out, and the + * it, cancel does when it finds the tune-out in the registry, and the * channel's next enter does in any case. */ private expiryTimers = new Map>(); /** Channels with a wake invocation pending inside the coalescing window. */ @@ -121,15 +132,17 @@ export class TuneOutCoordinator { }); } - /** A timer callback's work threw. Report it rather than throw it into the - * event loop, where an uncaught exception ends the host process. */ + /** A timer callback's work threw. Report it on stderr and as a trace rather + * than throw it into the event loop, where an uncaught exception ends the + * host process. */ private timerFailed(timer: 'cadence' | 'wake' | 'expiry', serverId: string, channelId: string, err: unknown): void { + console.error(`[tune-out] the ${timer} timer for ${channelId} failed:`, err); this.hooks.emitTrace({ type: 'tune-out:timer-failed', timer, serverId, channelId, - error: err instanceof Error ? err.message : String(err), + error: describeThrown(err), }); } @@ -476,7 +489,6 @@ export class TuneOutCoordinator { const subName = this.hooks.subconsciousName(); if (!subName) return; const key = this.key(serverId, channelId); - this.divertedSinceInvocation.set(key, 0); const notice = trigger === 'wake' ? `[Tune-out wake: ${channelId} — ${count} addressed message${count === 1 ? '' : 's'}]` @@ -488,6 +500,9 @@ export class TuneOutCoordinator { subName, ); this.hooks.requestInference(subName, `tune-out ${trigger}: ${channelId}`, 'tune-out'); + // Counted from here only once the turn has been asked for, so a turn that + // throws leaves its messages for the next period's turn. + this.divertedSinceInvocation.set(key, 0); } // ========================================================================== diff --git a/test/tune-out-timers.test.ts b/test/tune-out-timers.test.ts index 0c696cc41..aceb508f2 100644 --- a/test/tune-out-timers.test.ts +++ b/test/tune-out-timers.test.ts @@ -43,9 +43,19 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = }) as unknown as typeof setTimeout; let state: { params: TuneOutParams; wakeCount: number } | null = stored ? { params: stored, wakeCount: 0 } : null; - /** What addMessage throws on its next call, as a failed store write would; null to succeed. */ - let addMessageThrows: unknown = null; + /** What each step throws on its next call, as a failed store write would. */ + const throwsNext = new Map<'addMessage' | 'recordTuneOutWake' | 'cancelTuneOut', unknown>(); + const throwIfSet = (step: 'addMessage' | 'recordTuneOutWake' | 'cancelTuneOut') => { + if (!throwsNext.has(step)) return; + const thrown = throwsNext.get(step); + throwsNext.delete(step); + throw thrown; + }; const traces: Array> = []; + /** The text of each message added: the subconscious's notices among them. */ + const notices: string[] = []; + /** What the coordinator writes to stderr. */ + const stderr = t.mock.method(console, 'error', () => {}); const entered: TuneOutParams[] = []; /** The source of each cancel that ended a tune-out: 'duration' for an end time. */ const cancels: string[] = []; @@ -59,20 +69,21 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = state = { params, wakeCount: 0 }; }, cancelTuneOut: (_s: string, _c: string, _next: string, source: string) => { + throwIfSet('cancelTuneOut'); const ended = state; state = null; if (ended) cancels.push(source); return ended; }, - recordTuneOutWake: () => (state ? { params: state.params, wakeCount: ++state.wakeCount } : null), + recordTuneOutWake: () => { + throwIfSet('recordTuneOutWake'); + return state ? { params: state.params, wakeCount: ++state.wakeCount } : null; + }, } as unknown as ChannelRegistry; const hooks = { - addMessage: () => { - if (addMessageThrows !== null) { - const thrown = addMessageThrows; - addMessageThrows = null; - throw thrown; - } + addMessage: (_participant: string, content: Array<{ text: string }>) => { + throwIfSet('addMessage'); + notices.push(content[0]?.text ?? ''); return ''; }, requestInference: (_agent: string, reason: string) => { inferences.push(reason); }, @@ -101,12 +112,17 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = /** End the tune-out in the registry alone, as a send into the channel or a close does. */ const endInRegistry = () => { state = null; }; const active = () => state !== null; - /** Make addMessage's next call throw `thrown`. */ - const failNextAddMessage = (thrown: unknown = new Error('store write failed')) => { addMessageThrows = thrown; }; + /** Make the step's next call throw `thrown`. */ + const failNext = ( + step: 'addMessage' | 'recordTuneOutWake' | 'cancelTuneOut' = 'addMessage', + thrown: unknown = new Error('store write failed'), + ) => { throwsNext.set(step, thrown); }; const timerFailures = () => traces.filter((e) => e.type === 'tune-out:timer-failed'); + /** The arguments of each line written to stderr. */ + const stderrLines = () => stderr.mock.calls.map((c) => c.arguments as unknown[]); return { coordinator, entered, cancels, cadenceTurns, wakeTurns, delays, noTimerPastOne, endInRegistry, active, - failNextAddMessage, timerFailures, + failNext, timerFailures, notices, stderrLines, }; } @@ -317,23 +333,56 @@ it('armAt arms a deadline that has passed for the next turn of the loop, with no } }); -// A timer callback's work can throw, as a failed store write in a subconscious -// turn would. Thrown into the event loop, it's an uncaught exception, which -// ends the host process. Under node:test's mock timers a throw also comes out -// of tick(), and the mock then runs that callback once more at its next tick, -// so these tests assert that nothing leaves tick(), not only what comes after. +// A timer callback's work can throw, as a failed store write would. Thrown into +// the event loop, it's an uncaught exception, which ends the host process. +// Under node:test's mock timers a throw also comes out of tick(), and the mock +// then runs that callback once more at its next tick, so these tests assert +// that nothing leaves tick(), not only what comes after. + +const failure = (timer: string, error = 'store write failed') => + ({ type: 'tune-out:timer-failed', timer, serverId: 'disc', channelId: '#a', error }); -it("a cadence turn that throws stays in its timer, is reported, and the next period's turn comes", (t) => { +it("a cadence turn that throws stays in its timer, is reported, and the next period's turn counts its messages", (t) => { const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); h.coordinator.onIncoming('disc', '#a', 'm1', undefined); - h.failNextAddMessage(); + h.failNext(); assert.doesNotThrow(() => t.mock.timers.tick(60_000), "the turn's error stays in the timer"); - assert.deepEqual(h.timerFailures(), [ - { type: 'tune-out:timer-failed', timer: 'cadence', serverId: 'disc', channelId: '#a', error: 'store write failed' }, - ]); + assert.deepEqual(h.timerFailures(), [failure('cadence')]); assert.deepEqual(h.cadenceTurns(), [], 'the failed turn requested nothing'); - h.coordinator.onIncoming('disc', '#a', 'm2', undefined); + // No new traffic: the next period's turn is for m1. + t.mock.timers.tick(60_000); + assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], "the next period's turn comes"); + assert.match(h.notices.at(-1) ?? '', /— 1 diverted message since your last look\]$/); +}); + +it('a timer failure is written to stderr with the error', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + const thrown = new Error('store write failed'); + h.failNext('addMessage', thrown); + t.mock.timers.tick(60_000); + assert.deepEqual(h.stderrLines(), [['[tune-out] the cadence timer for #a failed:', thrown]]); +}); + +it("a cadence tick that finds the tune-out ended in the registry arms nothing and gives no turn", (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + h.endInRegistry(); + t.mock.timers.tick(60_000); + t.mock.timers.tick(60_000); + assert.deepEqual(h.cadenceTurns(), [], 'no turn for an ended tune-out'); + assert.equal(h.delays.filter((ms) => ms === 60_000).length, 1, 'only the first period was armed'); +}); + +it("a quiet cadence period arms the next, whose turn comes when a message is diverted", (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); + t.mock.timers.tick(60_000); + assert.deepEqual(h.cadenceTurns(), [], 'a quiet period gives no turn'); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); t.mock.timers.tick(60_000); assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], "the next period's turn comes"); }); @@ -342,27 +391,48 @@ it('a coalesced wake whose turn throws stays in its timer and is reported', (t) const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true); h.coordinator.onIncoming('disc', '#a', 'm1', ['chat:addressed']); - h.failNextAddMessage(); + h.failNext(); assert.doesNotThrow(() => t.mock.timers.tick(2_000), "the turn's error stays in the timer"); - assert.deepEqual(h.timerFailures().map((e) => [e.timer, e.error]), [['wake', 'store write failed']]); + assert.deepEqual(h.timerFailures(), [failure('wake')]); h.coordinator.onIncoming('disc', '#a', 'm2', ['chat:addressed']); t.mock.timers.tick(2_000); assert.deepEqual(h.wakeTurns(), ['tune-out wake: #a'], "the next wake's turn comes"); }); +it("a coalesced wake whose count can't be recorded stays in its timer and is reported", (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', ['chat:addressed']); + h.failNext('recordTuneOutWake'); + assert.doesNotThrow(() => t.mock.timers.tick(2_000), "the error stays in the timer"); + assert.deepEqual(h.timerFailures(), [failure('wake')]); + assert.deepEqual(h.wakeTurns(), [], 'no turn for the wake it could not count'); +}); + it('an end time whose cancel throws stays in its timer and is reported', (t) => { const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 120 }, 'agent-tool').ok, true); - h.failNextAddMessage(); + h.failNext(); assert.doesNotThrow(() => t.mock.timers.tick(120_000), "the cancel's error stays in the timer"); - assert.deepEqual(h.timerFailures().map((e) => [e.timer, e.error]), [['expiry', 'store write failed']]); + assert.deepEqual(h.timerFailures(), [failure('expiry')]); }); -it('a throw that is not an Error is reported as its string', (t) => { +it("an end time whose registry cancel throws stays in its timer and is reported", (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 120 }, 'agent-tool').ok, true); + h.failNext('cancelTuneOut'); + assert.doesNotThrow(() => t.mock.timers.tick(120_000), "the cancel's error stays in the timer"); + assert.deepEqual(h.timerFailures(), [failure('expiry')]); +}); + +it('a thrown value that is not an Error is reported as a string, even one with no string form', (t) => { const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); h.coordinator.onIncoming('disc', '#a', 'm1', undefined); - h.failNextAddMessage('disk full'); + h.failNext('addMessage', 'disk full'); + assert.doesNotThrow(() => t.mock.timers.tick(60_000)); + // String() throws for an object with no prototype. + h.failNext('addMessage', Object.create(null)); assert.doesNotThrow(() => t.mock.timers.tick(60_000)); - assert.deepEqual(h.timerFailures().map((e) => e.error), ['disk full']); + assert.deepEqual(h.timerFailures().map((e) => e.error), ['disk full', '[object Object]']); }); From 86624684372cfba61ebc23e556ab7cd7584a759b Mon Sep 17 00:00:00 2001 From: Abigail-2459 Date: Sat, 17 Oct 2026 12:53:45 -0400 Subject: [PATCH 3/5] fix(tune-out): the suppressed-mention acknowledgement reports its failure the same way, and stderr names the server From our internal review of the previous commit: - acknowledgeSuppressed's catch read (err as Error).message, which throws for a rejection with undefined or null, inside the catch, and onIncoming discards its promise. It now writes a stderr line and uses describeThrown, as timerFailed does. - The stderr lines name the server as well as the channel, since a channel id can repeat across servers. - The expiryTimers comment says the channel's next accepted enter clears the end time; a refused enter returns before it. - New tests: after a successful turn the count starts again, so a quiet period gives no turn and the next notice counts only new messages; a wake turn that throws leaves its message for the next cadence turn; a wake for a tune-out the registry ended inside the coalescing window gives no turn and reports nothing; a failed acknowledgement that rejects with undefined is written to stderr and traced. The harness's server registry holds no servers unless a test gives it one. Co-Authored-By: Claude Opus 5.5 --- src/tune-out/coordinator.ts | 7 ++-- test/tune-out-timers.test.ts | 71 +++++++++++++++++++++++++++++++++--- 2 files changed, 70 insertions(+), 8 deletions(-) diff --git a/src/tune-out/coordinator.ts b/src/tune-out/coordinator.ts index 80d7e1aec..acf1adcab 100644 --- a/src/tune-out/coordinator.ts +++ b/src/tune-out/coordinator.ts @@ -78,7 +78,7 @@ export class TuneOutCoordinator { private cadenceTimers = new Map>(); /** Each duration's pending expiry step (params.expiresAtMs). stop clears * it, cancel does when it finds the tune-out in the registry, and the - * channel's next enter does in any case. */ + * channel's next accepted enter does in any case. */ private expiryTimers = new Map>(); /** Channels with a wake invocation pending inside the coalescing window. */ private pendingWakes = new Map }>(); @@ -136,7 +136,7 @@ export class TuneOutCoordinator { * than throw it into the event loop, where an uncaught exception ends the * host process. */ private timerFailed(timer: 'cadence' | 'wake' | 'expiry', serverId: string, channelId: string, err: unknown): void { - console.error(`[tune-out] the ${timer} timer for ${channelId} failed:`, err); + console.error(`[tune-out] the ${timer} timer for ${channelId} on ${serverId} failed:`, err); this.hooks.emitTrace({ type: 'tune-out:timer-failed', timer, @@ -388,11 +388,12 @@ export class TuneOutCoordinator { intent: 'suppressed-tuned-out', }); } catch (err) { + console.error(`[tune-out] acknowledging ${messageId} in ${channelId} on ${serverId} failed:`, err); this.hooks.emitTrace({ type: 'tune-out:ack-failed', serverId, channelId, - error: (err as Error).message, + error: describeThrown(err), }); } } diff --git a/test/tune-out-timers.test.ts b/test/tune-out-timers.test.ts index aceb508f2..d01c16ab8 100644 --- a/test/tune-out-timers.test.ts +++ b/test/tune-out-timers.test.ts @@ -19,6 +19,7 @@ import { TuneOutCoordinator, type TuneOutFrameworkHooks } from '../src/tune-out/ import { armAt } from '../src/deadline-timer.js'; import type { ChannelRegistry, TuneOutParams } from '../src/mcpl/channel-registry.js'; import type { McplServerRegistry } from '../src/mcpl/server-registry.js'; +import { CapabilityGrant } from '../src/mcpl/capability-grant.js'; /** The longest delay one setTimeout holds. */ const ONE_TIMER_MS = 2_147_483_647; @@ -30,9 +31,14 @@ const STORED: TuneOutParams = { epochId: 'e1', cadenceSeconds: 1800, backlogCap: * A coordinator over an in-memory registry for one channel, `disc` `#a`, with * setTimeout mocked and each delay asked of it recorded, and the wall clock * mocked unless `wallClock` is false. `stored` is a tune-out the registry - * already holds, as after a restart. + * already holds, as after a restart. `servers` is the MCPL server registry, + * by default one with no servers. */ -function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = {}) { +function harness( + t: TestContext, + stored?: TuneOutParams, + { wallClock = true, servers = { getServer: () => undefined } as unknown as McplServerRegistry } = {}, +) { if (wallClock) t.mock.timers.enable({ apis: ['Date', 'setTimeout'], now: NOW }); else t.mock.timers.enable({ apis: ['setTimeout'] }); const mocked = globalThis.setTimeout; @@ -97,7 +103,7 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = allowChannelSpeech: () => false, emitTrace: (event: Record) => { traces.push(event); }, } as unknown as TuneOutFrameworkHooks; - const coordinator = new TuneOutCoordinator(registry, {} as McplServerRegistry, hooks); + const coordinator = new TuneOutCoordinator(registry, servers, hooks); t.after(() => { coordinator.stop(); globalThis.setTimeout = mocked; @@ -118,11 +124,12 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = thrown: unknown = new Error('store write failed'), ) => { throwsNext.set(step, thrown); }; const timerFailures = () => traces.filter((e) => e.type === 'tune-out:timer-failed'); + const ackFailures = () => traces.filter((e) => e.type === 'tune-out:ack-failed'); /** The arguments of each line written to stderr. */ const stderrLines = () => stderr.mock.calls.map((c) => c.arguments as unknown[]); return { coordinator, entered, cancels, cadenceTurns, wakeTurns, delays, noTimerPastOne, endInRegistry, active, - failNext, timerFailures, notices, stderrLines, + failNext, timerFailures, ackFailures, notices, stderrLines, }; } @@ -363,7 +370,34 @@ it('a timer failure is written to stderr with the error', (t) => { const thrown = new Error('store write failed'); h.failNext('addMessage', thrown); t.mock.timers.tick(60_000); - assert.deepEqual(h.stderrLines(), [['[tune-out] the cadence timer for #a failed:', thrown]]); + assert.deepEqual(h.stderrLines(), [['[tune-out] the cadence timer for #a on disc failed:', thrown]]); +}); + +it('after a turn, the count starts again: a quiet period gives no turn, and the next notice counts only new messages', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + h.coordinator.onIncoming('disc', '#a', 'm2', undefined); + t.mock.timers.tick(60_000); + assert.match(h.notices.at(-1) ?? '', /— 2 diverted messages since your last look\]$/); + t.mock.timers.tick(60_000); + assert.equal(h.cadenceTurns().length, 1, 'no turn for a quiet period after a turn'); + h.coordinator.onIncoming('disc', '#a', 'm3', undefined); + t.mock.timers.tick(60_000); + assert.equal(h.cadenceTurns().length, 2); + assert.match(h.notices.at(-1) ?? '', /— 1 diverted message since your last look\]$/); +}); + +it("a wake turn that throws leaves its message for the next cadence turn", (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 60 }, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', ['chat:addressed']); + h.failNext(); + t.mock.timers.tick(2_000); + assert.deepEqual(h.wakeTurns(), [], 'the wake turn failed'); + t.mock.timers.tick(58_000); + assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'the cadence turn comes'); + assert.match(h.notices.at(-1) ?? '', /— 1 diverted message since your last look\]$/); }); it("a cadence tick that finds the tune-out ended in the registry arms nothing and gives no turn", (t) => { @@ -409,6 +443,33 @@ it("a coalesced wake whose count can't be recorded stays in its timer and is rep assert.deepEqual(h.wakeTurns(), [], 'no turn for the wake it could not count'); }); +it('a coalesced wake for a tune-out the registry ended in its window gives no turn and reports nothing', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', ['chat:addressed']); + h.endInRegistry(); + t.mock.timers.tick(2_000); + assert.deepEqual(h.wakeTurns(), []); + assert.deepEqual(h.timerFailures(), []); +}); + +it('a failed acknowledgement is written to stderr and traced, whatever it rejects with', async (t) => { + const servers = { + getServer: () => ({ + grant: new CapabilityGrant(new Set(['channels.acknowledge']), []), + sendChannelsAcknowledge: async () => { throw undefined; }, + }), + } as unknown as McplServerRegistry; + const h = harness(t, undefined, { servers }); + assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', ['chat:addressed']); + await new Promise((resolve) => setImmediate(resolve)); + assert.deepEqual(h.ackFailures(), [ + { type: 'tune-out:ack-failed', serverId: 'disc', channelId: '#a', error: 'undefined' }, + ]); + assert.deepEqual(h.stderrLines(), [['[tune-out] acknowledging m1 in #a on disc failed:', undefined]]); +}); + it('an end time whose cancel throws stays in its timer and is reported', (t) => { const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 120 }, 'agent-tool').ok, true); From 05991598e036450d6e8dce0236202e07a46b2d4e Mon Sep 17 00:00:00 2001 From: Abigail-2459 Date: Sat, 17 Oct 2026 12:57:07 -0400 Subject: [PATCH 4/5] fix(tune-out): an end time whose cancel throws tries the cancel again a minute later From our internal review of the change: when the end time's cancel threw, nothing tried again, so the end was lost until a restart. Without the change, the throw ends the process instead, and a supervised host's restart then cancels the expired tune-out. The end time now arms a retry a minute later before it cancels, as the cadence arms its next period before its turn. A cancel that ends the tune-out clears the retry with the channel's other timers, and so does a cancel that finds the tune-out already ended. A cancel that keeps throwing is tried every minute, and each attempt is reported. Tests: an end time whose registry cancel throws is reported and ends the tune-out a minute later, not before; one whose cancel throws after the registry ended the tune-out tries no more; one that finds the tune-out already ended tries no more. The changelog fragment names the retry and the acknowledgement's report. Co-Authored-By: Claude Opus 5.5 --- changelog.d/tune-out-timer-failures.fixed.md | 7 ++++- src/tune-out/coordinator.ts | 19 ++++++++++--- test/tune-out-timers.test.ts | 28 +++++++++++++++++--- 3 files changed, 46 insertions(+), 8 deletions(-) diff --git a/changelog.d/tune-out-timer-failures.fixed.md b/changelog.d/tune-out-timer-failures.fixed.md index 2f5bf0f23..8f5ed8076 100644 --- a/changelog.d/tune-out-timer-failures.fixed.md +++ b/changelog.d/tune-out-timer-failures.fixed.md @@ -4,4 +4,9 @@ process. The coordinator writes the error to stderr and reports a `tune-out:timer-failed` trace naming the timer. Before, a cadence whose turn threw also never armed again. Now it arms its next period before - the turn, and that next turn counts the failed turn's messages. + the turn, and that next turn counts the failed turn's messages. An end + time whose cancel throws tries the cancel again a minute later, until + it succeeds. +- A failed acknowledgement of a suppressed mention is written to stderr + as well as traced, and a rejection with `undefined` or `null` no + longer throws inside its handler. diff --git a/src/tune-out/coordinator.ts b/src/tune-out/coordinator.ts index acf1adcab..36305ebda 100644 --- a/src/tune-out/coordinator.ts +++ b/src/tune-out/coordinator.ts @@ -34,6 +34,9 @@ export const TUNE_OUT_DEFAULTS = { * subconscious turn, and max-wakes counts invocations, not messages. */ const WAKE_COALESCE_MS = 2_000; +/** How long after an end time whose cancel threw the cancel is tried again. */ +const EXPIRY_RETRY_MS = 60_000; + /** What a caught value says: an Error's message, or the value as a string. */ function describeThrown(err: unknown): string { if (err instanceof Error) return err.message; @@ -122,14 +125,22 @@ export class TuneOutCoordinator { const key = this.key(serverId, channelId); const existing = this.expiryTimers.get(key); if (existing) clearTimeout(existing); - armAt(params.expiresAtMs, (timer) => { this.expiryTimers.set(key, timer); }, () => { + const hold = (timer: ReturnType): void => { this.expiryTimers.set(key, timer); }; + const end = (): void => { try { - this.expiryTimers.delete(key); - this.cancel(serverId, channelId, 'duration', 'duration elapsed'); + // The retry is armed before the cancel, as the cadence arms its next + // period before its turn, so a cancel that throws is tried again. A + // cancel that ends the tune-out clears it with the channel's other + // timers, and so does finding the tune-out already ended. + hold(setTimeout(end, EXPIRY_RETRY_MS)); + if (!this.cancel(serverId, channelId, 'duration', 'duration elapsed').ok) { + this.clearTimers(serverId, channelId); + } } catch (err) { this.timerFailed('expiry', serverId, channelId, err); } - }); + }; + armAt(params.expiresAtMs, hold, end); } /** A timer callback's work threw. Report it on stderr and as a trace rather diff --git a/test/tune-out-timers.test.ts b/test/tune-out-timers.test.ts index d01c16ab8..f60df395e 100644 --- a/test/tune-out-timers.test.ts +++ b/test/tune-out-timers.test.ts @@ -65,6 +65,8 @@ function harness( const entered: TuneOutParams[] = []; /** The source of each cancel that ended a tune-out: 'duration' for an end time. */ const cancels: string[] = []; + /** Every call to the registry's cancel, whatever came of it. */ + let cancelCalls = 0; /** The reason of each inference requested, the subconscious's turns among them. */ const inferences: string[] = []; const registry = { @@ -75,6 +77,7 @@ function harness( state = { params, wakeCount: 0 }; }, cancelTuneOut: (_s: string, _c: string, _next: string, source: string) => { + cancelCalls++; throwIfSet('cancelTuneOut'); const ended = state; state = null; @@ -129,7 +132,7 @@ function harness( const stderrLines = () => stderr.mock.calls.map((c) => c.arguments as unknown[]); return { coordinator, entered, cancels, cadenceTurns, wakeTurns, delays, noTimerPastOne, endInRegistry, active, - failNext, timerFailures, ackFailures, notices, stderrLines, + failNext, timerFailures, ackFailures, notices, stderrLines, cancelCalls: () => cancelCalls, }; } @@ -470,20 +473,39 @@ it('a failed acknowledgement is written to stderr and traced, whatever it reject assert.deepEqual(h.stderrLines(), [['[tune-out] acknowledging m1 in #a on disc failed:', undefined]]); }); -it('an end time whose cancel throws stays in its timer and is reported', (t) => { +it('an end time whose cancel throws after the registry ended the tune-out stays in its timer, is reported, and tries no more', (t) => { const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 120 }, 'agent-tool').ok, true); h.failNext(); assert.doesNotThrow(() => t.mock.timers.tick(120_000), "the cancel's error stays in the timer"); assert.deepEqual(h.timerFailures(), [failure('expiry')]); + t.mock.timers.tick(10 * 60_000); + assert.equal(h.cancelCalls(), 1, 'the registry ended it, so nothing tries again'); }); -it("an end time whose registry cancel throws stays in its timer and is reported", (t) => { +it('an end time whose registry cancel throws is reported, and the cancel is tried again a minute later', (t) => { const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 120 }, 'agent-tool').ok, true); h.failNext('cancelTuneOut'); assert.doesNotThrow(() => t.mock.timers.tick(120_000), "the cancel's error stays in the timer"); assert.deepEqual(h.timerFailures(), [failure('expiry')]); + assert.equal(h.active(), true, 'still tuned out after the failed cancel'); + t.mock.timers.tick(60_000 - 1); + assert.deepEqual(h.cancels, [], 'not before the minute'); + t.mock.timers.tick(1); + assert.deepEqual(h.cancels, ['duration'], 'ended a minute later'); + t.mock.timers.tick(10 * 60_000); + assert.equal(h.cancelCalls(), 2, 'and nothing tries again after it ended'); +}); + +it('an end time that finds the tune-out already ended in the registry tries no more', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 120 }, 'agent-tool').ok, true); + h.endInRegistry(); + t.mock.timers.tick(120_000); + t.mock.timers.tick(10 * 60_000); + assert.equal(h.cancelCalls(), 1); + assert.deepEqual(h.timerFailures(), []); }); it('a thrown value that is not an Error is reported as a string, even one with no string form', (t) => { From 10b623789f5fe3c259fb99207c11b99c9d0bb5a8 Mon Sep 17 00:00:00 2001 From: Abigail-2459 Date: Sat, 17 Oct 2026 13:10:40 -0400 Subject: [PATCH 5/5] docs(tune-out): say which registry order the end time's retry relies on From review: the retry ends a tune-out whose cancel threw before the channel registry changed anything. That's how the registry's cancel fails since #446, which writes its record before it changes memory. Before #446, its cancel could throw only at the store append, after the tune-out had ended in memory, so a retry would have found the tune-out ended. The changelog's retry sentence now says so. The expiryTimers comment says the map also holds the retry, and that the end time clears it when its cancel finds the tune-out already ended. The retry test says its stand-in throws before it changes anything. Co-Authored-By: Claude Opus 5.5 --- changelog.d/tune-out-timer-failures.fixed.md | 4 ++-- src/tune-out/coordinator.ts | 8 +++++--- test/tune-out-timers.test.ts | 2 ++ 3 files changed, 9 insertions(+), 5 deletions(-) diff --git a/changelog.d/tune-out-timer-failures.fixed.md b/changelog.d/tune-out-timer-failures.fixed.md index 8f5ed8076..6660857b8 100644 --- a/changelog.d/tune-out-timer-failures.fixed.md +++ b/changelog.d/tune-out-timer-failures.fixed.md @@ -5,8 +5,8 @@ `tune-out:timer-failed` trace naming the timer. Before, a cadence whose turn threw also never armed again. Now it arms its next period before the turn, and that next turn counts the failed turn's messages. An end - time whose cancel throws tries the cancel again a minute later, until - it succeeds. + time whose cancel throws before the channel registry has changed + anything tries the cancel again a minute later, until it succeeds. - A failed acknowledgement of a suppressed mention is written to stderr as well as traced, and a rejection with `undefined` or `null` no longer throws inside its handler. diff --git a/src/tune-out/coordinator.ts b/src/tune-out/coordinator.ts index 36305ebda..d3215d480 100644 --- a/src/tune-out/coordinator.ts +++ b/src/tune-out/coordinator.ts @@ -79,9 +79,11 @@ export interface TuneOutFrameworkHooks { export class TuneOutCoordinator { private cadenceTimers = new Map>(); - /** Each duration's pending expiry step (params.expiresAtMs). stop clears - * it, cancel does when it finds the tune-out in the registry, and the - * channel's next accepted enter does in any case. */ + /** Each duration's pending timer: a step toward its end time + * (params.expiresAtMs), or the retry of an end-time cancel that threw. + * stop clears it, cancel does when it finds the tune-out in the registry, + * the end time does when its cancel finds the tune-out already ended, + * and the channel's next accepted enter does in any case. */ private expiryTimers = new Map>(); /** Channels with a wake invocation pending inside the coalescing window. */ private pendingWakes = new Map }>(); diff --git a/test/tune-out-timers.test.ts b/test/tune-out-timers.test.ts index f60df395e..f71d4d680 100644 --- a/test/tune-out-timers.test.ts +++ b/test/tune-out-timers.test.ts @@ -484,6 +484,8 @@ it('an end time whose cancel throws after the registry ended the tune-out stays }); it('an end time whose registry cancel throws is reported, and the cancel is tried again a minute later', (t) => { + // The stand-in's cancel throws before it changes anything, as a registry + // that writes its record before it changes memory does when the write fails. const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 120 }, 'agent-tool').ok, true); h.failNext('cancelTuneOut');