From 157ad9f7aded36a1d3ce291e7840e3d71d046168 Mon Sep 17 00:00:00 2001 From: Abigail-2459 Date: Sat, 17 Oct 2026 09:07:31 -0400 Subject: [PATCH 1/3] fix(tune-out): a duration or cadence past 24.8 days holds, and enter refuses an option that gives no finite number Node fires a setTimeout longer than 2^31 - 1 ms (about 24.8 days) almost at once. On main at 7125cb866, on Node 24.22.0: - a durationSeconds over 2147483 ended the tune-out 1 to 4 ms after it began, as "duration elapsed", which delivers the backlog to the resident and wakes it; - a cadenceSeconds over 2147483 re-armed the cadence timer about every 1.3 ms, so the subconscious got a turn as soon as anything was diverted; - an option that gives no finite number ("abc", NaN, Infinity) made the store's append throw "Failed to convert js number to serde_json::Number" after ChannelRegistry.enterTuneOut had marked the channel tuned out in memory, so enter threw with no timer armed, and the channel's messages were diverted until the next restart; - a null durationSeconds gave a tune-out of 60 seconds. armAt (src/deadline-timer.ts) calls back once the clock reaches a deadline, through timers of at most 2^31 - 1 ms. When each timer fires, it reads the clock against the deadline and arms the next for what's left. The end time steps toward the stored expiresAtMs, and the cadence toward each tick's next time. Each timer goes into the coordinator's existing maps, so cancel and stop clear the pending one. armAt is a module of its own because nothing in it is about tune-outs. enter reads its four numeric options with Number() before anything changes, as the sleep tool reads its seconds, so a numeric string still works. It reads null as left out, as ?? already did for the three options with defaults. It refuses a value that gives no finite number, naming the option and the value, and a duration whose end time isn't finite (above about 1.8e305 seconds), which the store can't keep. The tests, in test/tune-out-timers.test.ts, mock Date and setTimeout and record each delay asked of setTimeout: a 30-day duration ends at its end and not before; a restart with more than one timer left reads the stored end time at each step; a cancel stops the end time's later steps; stop clears both timers' pending steps; a 30-day cadence gives one turn at the cadence; the refusals; null as left out. The numeric-string test is a control: it passes on main. Co-Authored-By: Claude Opus 5.5 --- changelog.d/tune-out-long-timers.fixed.md | 20 +++ src/deadline-timer.ts | 26 +++ src/tune-out/coordinator.ts | 62 +++++-- test/tune-out-timers.test.ts | 200 ++++++++++++++++++++++ 4 files changed, 296 insertions(+), 12 deletions(-) create mode 100644 changelog.d/tune-out-long-timers.fixed.md create mode 100644 src/deadline-timer.ts create mode 100644 test/tune-out-timers.test.ts diff --git a/changelog.d/tune-out-long-timers.fixed.md b/changelog.d/tune-out-long-timers.fixed.md new file mode 100644 index 000000000..b72f454ec --- /dev/null +++ b/changelog.d/tune-out-long-timers.fixed.md @@ -0,0 +1,20 @@ +- A tune-out's `durationSeconds` or `cadenceSeconds` longer than about 24.8 + days (2^31 - 1 ms, the longest delay one Node timer holds) now holds. + Before, Node fired the timer almost at once, so such a tune-out ended as + "duration elapsed" moments after it began, waking the resident with its + backlog, and such a cadence re-armed about every millisecond, giving the + subconscious a turn as soon as anything was diverted, after every restart + too. Both timers now re-arm in steps no longer than one timer, each step + reading the clock against its deadline; the end time's deadline is the + stored one, so a host that runs through it and one that restarts end the + tune-out at the same time. +- `tune_out` refuses a `durationSeconds`, `cadenceSeconds`, `backlogCap` or + `maxWakes` that gives no finite number, such as `"abc"`, and a duration + whose end time is too far off to store, naming the option and saying + nothing was tuned out, before anything changes. Before, the store's write + threw after the channel had been marked tuned out in memory, so the call + failed and left the channel diverted with no cadence or end timer until + the next restart. A numeric string such as `"3600"` is still read as its + number. +- A `null` `durationSeconds` now means no end time, as leaving it out does. + Before, it gave a tune-out of 60 seconds, the shortest duration. diff --git a/src/deadline-timer.ts b/src/deadline-timer.ts new file mode 100644 index 000000000..77973a208 --- /dev/null +++ b/src/deadline-timer.ts @@ -0,0 +1,26 @@ +/** The longest delay one setTimeout holds (2^31 - 1 ms, about 24.8 days). + * Node fires a longer one almost at once, with a TimeoutOverflowWarning. */ +const MAX_TIMER_MS = 2_147_483_647; + +/** + * Call `fire` once the clock reaches `deadlineMs` (epoch ms), through timers + * no longer than one holds, so a deadline weeks away fires then rather than + * at once. Each step reads the clock against the deadline and re-arms for + * what's left, so a deadline kept in storage ends at the same time whether + * the process runs through it or restarts and arms it again. `hold` gets each + * step's timer: clearing the latest one stops the rest. + */ +export function armAt( + deadlineMs: number, + hold: (timer: ReturnType) => void, + fire: () => void, +): void { + const arm = (): void => { + hold(setTimeout(step, Math.min(Math.max(0, deadlineMs - Date.now()), MAX_TIMER_MS))); + }; + const step = (): void => { + if (deadlineMs - Date.now() > 0) arm(); + else fire(); + }; + arm(); +} diff --git a/src/tune-out/coordinator.ts b/src/tune-out/coordinator.ts index dbfee7013..2ae4309ba 100644 --- a/src/tune-out/coordinator.ts +++ b/src/tune-out/coordinator.ts @@ -21,6 +21,7 @@ import type { StoredMessage } from '@animalabs/context-manager'; import type { ChannelRegistry, TuneOutParams } from '../mcpl/channel-registry.js'; import type { McplServerRegistry } from '../mcpl/server-registry.js'; import { CapabilityGrant } from '../mcpl/capability-grant.js'; +import { armAt } from '../deadline-timer.js'; /** Defaults for tune_out tool params. */ export const TUNE_OUT_DEFAULTS = { @@ -64,7 +65,7 @@ export interface TuneOutFrameworkHooks { export class TuneOutCoordinator { private cadenceTimers = new Map>(); - /** Duration-expiry timers (params.expiresAtMs); cleared on any cancel. */ + /** Each duration's pending expiry step (params.expiresAtMs); cleared on any cancel. */ private expiryTimers = new Map>(); /** Channels with a wake invocation pending inside the coalescing window. */ private pendingWakes = new Map }>(); @@ -108,11 +109,10 @@ export class TuneOutCoordinator { const key = this.key(serverId, channelId); const existing = this.expiryTimers.get(key); if (existing) clearTimeout(existing); - const remaining = Math.max(0, params.expiresAtMs - Date.now()); - this.expiryTimers.set(key, setTimeout(() => { + armAt(params.expiresAtMs, (timer) => { this.expiryTimers.set(key, timer); }, () => { this.expiryTimers.delete(key); this.cancel(serverId, channelId, 'duration', 'duration elapsed'); - }, remaining)); + }); } private listActive(): Array<{ serverId: string; channelId: string; params: TuneOutParams }> { @@ -145,15 +145,52 @@ export class TuneOutCoordinator { if (this.channelRegistry.getTuneOutState(serverId, channelId)) { return { ok: false, error: `channel ${channelId} is already tuned out (cancel first to change params)` }; } + // A tool's input reaches here as the model wrote it, and the store can't + // keep a NaN or an Infinity: its append would throw after the registry + // had marked the channel tuned out. So each option is read as a number + // before anything changes, a numeric string included, as the sleep tool + // reads its seconds; null counts as left out. A value that gives no + // finite number is refused. + const leftOut = { + durationSeconds: 'to stay tuned out until you cancel', + cadenceSeconds: `for the default, ${TUNE_OUT_DEFAULTS.cadenceSeconds}`, + backlogCap: `for the default, ${TUNE_OUT_DEFAULTS.backlogCap}`, + maxWakes: `for the default, ${TUNE_OUT_DEFAULTS.maxWakes}`, + } as const; + const given: Partial> = {}; + for (const name of Object.keys(leftOut) as Array) { + const value: unknown = opts[name]; + if (value == null) continue; + const n = Number(value); + if (!Number.isFinite(n)) { + const got = typeof value === 'number' + ? String(value) + : `${typeof value === 'string' ? 'the string' : 'the value'} ${JSON.stringify(value)}`; + return { + ok: false, + error: `Nothing was tuned out: ${name} must be a finite number${name.endsWith('Seconds') ? ' of seconds' : ''}, ` + + `and it was ${got}. Leave it out ${leftOut[name]}.`, + }; + } + given[name] = n; + } + const expiresAtMs = given.durationSeconds === undefined + ? undefined + : Date.now() + Math.max(60, given.durationSeconds) * 1000; + if (expiresAtMs !== undefined && !Number.isFinite(expiresAtMs)) { + return { + ok: false, + error: `Nothing was tuned out: durationSeconds ${given.durationSeconds} is longer than an end time can be kept. ` + + `Leave it out ${leftOut.durationSeconds}.`, + }; + } const params: TuneOutParams = { epochId: randomUUID(), - cadenceSeconds: Math.max(30, opts.cadenceSeconds ?? TUNE_OUT_DEFAULTS.cadenceSeconds), - backlogCap: Math.max(0, opts.backlogCap ?? TUNE_OUT_DEFAULTS.backlogCap), - maxWakes: Math.max(1, opts.maxWakes ?? TUNE_OUT_DEFAULTS.maxWakes), + cadenceSeconds: Math.max(30, given.cadenceSeconds ?? TUNE_OUT_DEFAULTS.cadenceSeconds), + backlogCap: Math.max(0, given.backlogCap ?? TUNE_OUT_DEFAULTS.backlogCap), + maxWakes: Math.max(1, given.maxWakes ?? TUNE_OUT_DEFAULTS.maxWakes), startedAtSequence: this.hooks.currentSequence(), - ...(opts.durationSeconds !== undefined - ? { expiresAtMs: Date.now() + Math.max(60, opts.durationSeconds) * 1000 } - : {}), + ...(expiresAtMs !== undefined ? { expiresAtMs } : {}), }; this.channelRegistry.enterTuneOut(serverId, channelId, params, source); this.armExpiry(serverId, channelId, params); @@ -342,6 +379,7 @@ export class TuneOutCoordinator { private startCadence(serverId: string, channelId: string, cadenceSeconds: number): void { this.stopCadence(serverId, channelId); 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 @@ -350,9 +388,9 @@ export class TuneOutCoordinator { if (diverted > 0) { this.invokeSubconscious(serverId, channelId, 'cadence', diverted); } - this.cadenceTimers.set(key, setTimeout(tick, cadenceSeconds * 1000)); + armAt(Date.now() + cadenceSeconds * 1000, hold, tick); }; - this.cadenceTimers.set(key, setTimeout(tick, cadenceSeconds * 1000)); + armAt(Date.now() + cadenceSeconds * 1000, hold, tick); } private stopCadence(serverId: string, channelId: string): void { diff --git a/test/tune-out-timers.test.ts b/test/tune-out-timers.test.ts new file mode 100644 index 000000000..6ba61e6f3 --- /dev/null +++ b/test/tune-out-timers.test.ts @@ -0,0 +1,200 @@ +/** + * 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). + * + * 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, + * and re-armed a longer cadence every millisecond. node:test's mock timers + * fire an overflowing timeout early too (Node 24), and the harness records + * each delay asked of setTimeout, so the timer tests also check that no step + * is longer than one timer holds, whatever the runtime's mock does. + */ +import { it, type TestContext } from 'node:test'; +import assert from 'node:assert/strict'; +import { TuneOutCoordinator, type TuneOutFrameworkHooks } from '../src/tune-out/coordinator.js'; +import type { ChannelRegistry, TuneOutParams } from '../src/mcpl/channel-registry.js'; +import type { McplServerRegistry } from '../src/mcpl/server-registry.js'; + +/** The longest delay one setTimeout holds. */ +const ONE_TIMER_MS = 2_147_483_647; +const DAY_MS = 86_400_000; +const NOW = Date.UTC(2026, 9, 17); + +/** + * A coordinator over an in-memory registry for one channel, `disc` `#a`, + * with the clock and setTimeout mocked and each delay asked of setTimeout + * recorded. `stored` is a tune-out the registry already holds, as after a + * restart. + */ +function harness(t: TestContext, stored?: TuneOutParams) { + t.mock.timers.enable({ apis: ['Date', 'setTimeout'], now: NOW }); + const mocked = globalThis.setTimeout; + const delays: number[] = []; + globalThis.setTimeout = ((fn: (...args: unknown[]) => void, ms?: number, ...rest: unknown[]) => { + delays.push(ms ?? 0); + return mocked(fn, ms, ...rest); + }) as unknown as typeof setTimeout; + + let state: { params: TuneOutParams; wakeCount: number } | null = stored ? { params: stored, wakeCount: 0 } : null; + const entered: TuneOutParams[] = []; + /** The source of each cancel that ended a tune-out: 'duration' for an end time. */ + const cancels: string[] = []; + /** The reason of each inference requested, the subconscious's turns among them. */ + const inferences: string[] = []; + const registry = { + listChannelsRaw: () => (state ? [{ serverId: 'disc', descriptor: { id: '#a' } }] : []), + getTuneOutState: () => state, + enterTuneOut: (_s: string, _c: string, params: TuneOutParams) => { + entered.push(params); + state = { params, wakeCount: 0 }; + }, + cancelTuneOut: (_s: string, _c: string, _next: string, source: string) => { + const ended = state; + state = null; + if (ended) cancels.push(source); + return ended; + }, + recordTuneOutWake: () => (state ? { params: state.params, wakeCount: ++state.wakeCount } : null), + } as unknown as ChannelRegistry; + const hooks = { + addMessage: () => '', + requestInference: (_agent: string, reason: string) => { inferences.push(reason); }, + subconsciousName: () => 'Subconscious', + primaryName: () => 'scout', + getStoredMessages: () => [], + currentSequence: () => 1, + setSubconsciousAnchor: () => {}, + isForkBound: () => false, + isPrivilegedAuthor: () => false, + allowChannelSpeech: () => false, + emitTrace: () => {}, + } as unknown as TuneOutFrameworkHooks; + const coordinator = new TuneOutCoordinator(registry, {} as McplServerRegistry, hooks); + t.after(() => { + coordinator.stop(); + globalThis.setTimeout = mocked; + t.mock.timers.reset(); + }); + const cadenceTurns = () => inferences.filter((r) => r.startsWith('tune-out cadence')); + const noTimerPastOne = () => assert.ok( + delays.every((ms) => ms <= ONE_TIMER_MS), + `no timer longer than one holds (${delays.filter((ms) => !(ms <= ONE_TIMER_MS)).join(', ')})`, + ); + return { coordinator, entered, cancels, cadenceTurns, delays, noTimerPastOne }; +} + +it('a duration past one timer ends at its end time and not before', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 30 * 86_400 }, 'agent-tool').ok, true); + t.mock.timers.tick(ONE_TIMER_MS); + assert.deepEqual(h.cancels, [], "still tuned out after one timer's worth"); + t.mock.timers.tick(30 * DAY_MS - ONE_TIMER_MS - 1); + assert.deepEqual(h.cancels, [], 'still tuned out 1 ms before its end'); + t.mock.timers.tick(1); + assert.deepEqual(h.cancels, ['duration'], 'ended once, at its end time'); + h.noTimerPastOne(); +}); + +it('a restart with more than one timer left reads the stored end time at each step', (t) => { + const h = harness(t, { + epochId: 'e1', cadenceSeconds: 1800, backlogCap: 200, maxWakes: 5, startedAtSequence: 1, + expiresAtMs: NOW + 30 * DAY_MS, + }); + h.coordinator.resumeActiveEpochs(); + t.mock.timers.tick(DAY_MS); + assert.deepEqual(h.cancels, [], 'still tuned out a day after the restart'); + // The wall clock reaches the stored end while a step waits, as after a + // host's suspend or a clock correction: the step that runs next reads it. + t.mock.timers.setTime(NOW + 30 * DAY_MS); + t.mock.timers.tick(ONE_TIMER_MS); + assert.deepEqual(h.cancels, ['duration'], 'the next step found the stored end time passed and ended it'); + h.noTimerPastOne(); +}); + +it("a cancel stops the end time's later steps, so a new tune-out on the channel isn't ended at the old one's end", (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 30 * 86_400 }, 'agent-tool').ok, true); + t.mock.timers.tick(ONE_TIMER_MS); + assert.equal(h.coordinator.cancel('disc', '#a', 'agent-tool', 'agent request').ok, true); + assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true, 'a new tune-out, until cancelled'); + t.mock.timers.tick(30 * DAY_MS); + assert.deepEqual(h.cancels, ['agent-tool'], 'only the cancel asked for: the new tune-out runs on'); +}); + +it("stop clears both timers' pending steps: neither fires after it", (t) => { + const h = harness(t); + const opts = { durationSeconds: 30 * 86_400, cadenceSeconds: 30 * 86_400 }; + assert.equal(h.coordinator.enter('disc', '#a', opts, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + t.mock.timers.tick(ONE_TIMER_MS); + h.coordinator.stop(); + t.mock.timers.tick(60 * DAY_MS); + assert.deepEqual(h.cancels, [], 'no end after stop'); + assert.deepEqual(h.cadenceTurns(), [], 'no cadence turn after stop'); +}); + +it('a cadence past one timer gives the subconscious one turn at the cadence: none before it, none after a cancel', (t) => { + const h = harness(t); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 30 * 86_400 }, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + t.mock.timers.tick(30 * DAY_MS - 1); + assert.deepEqual(h.cadenceTurns(), [], 'no turn before the cadence'); + t.mock.timers.tick(1); + assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'one turn at the cadence'); + h.coordinator.onIncoming('disc', '#a', 'm2', undefined); + assert.equal(h.coordinator.cancel('disc', '#a', 'agent-tool', 'agent request').ok, true); + t.mock.timers.tick(30 * DAY_MS); + assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'no turn after the cancel'); + h.noTimerPastOne(); +}); + +it("enter refuses an option that gives no finite number, before anything changes", (t) => { + const h = harness(t); + const refusals: Array<[Record, RegExp | string]> = [ + [{ durationSeconds: 'abc' }, + 'Nothing was tuned out: durationSeconds must be a finite number of seconds, and it was the string "abc". ' + + 'Leave it out to stay tuned out until you cancel.'], + [{ maxWakes: NaN }, + 'Nothing was tuned out: maxWakes must be a finite number, and it was NaN. Leave it out for the default, 5.'], + [{ durationSeconds: 1e306 }, + 'Nothing was tuned out: durationSeconds 1e+306 is longer than an end time can be kept. ' + + 'Leave it out to stay tuned out until you cancel.'], + [{ durationSeconds: Infinity }, /^Nothing was tuned out: durationSeconds must be a finite number of seconds, and it was Infinity\. /], + [{ cadenceSeconds: 'every hour' }, /^Nothing was tuned out: cadenceSeconds must be a finite number of seconds, and it was the string "every hour"\. Leave it out for the default, 1800\.$/], + [{ cadenceSeconds: Infinity }, /^Nothing was tuned out: cadenceSeconds must be a finite number of seconds, and it was Infinity\. /], + [{ backlogCap: 'all' }, /^Nothing was tuned out: backlogCap must be a finite number, and it was the string "all"\. Leave it out for the default, 200\.$/], + [{ maxWakes: [1, 2] }, /^Nothing was tuned out: maxWakes must be a finite number, and it was the value \[1,2\]\. /], + ]; + for (const [opts, expected] of refusals) { + const r = h.coordinator.enter('disc', '#a', opts as never, 'agent-tool'); + assert.equal(r.ok, false, `${JSON.stringify(opts)} refused`); + if (!r.ok) { + if (typeof expected === 'string') assert.equal(r.error, expected); + else assert.match(r.error, expected); + } + } + assert.deepEqual(h.entered, [], 'nothing entered'); + assert.deepEqual(h.delays, [], 'no timer armed'); +}); + +it('a null option counts as left out: a null duration has no end time', (t) => { + const h = harness(t); + const nulls = { durationSeconds: null, cadenceSeconds: null, backlogCap: null, maxWakes: null }; + assert.equal(h.coordinator.enter('disc', '#a', nulls as never, 'agent-tool').ok, true); + assert.equal(h.entered[0].expiresAtMs, undefined, 'until cancelled, not 60 s'); + assert.deepEqual( + [h.entered[0].cadenceSeconds, h.entered[0].backlogCap, h.entered[0].maxWakes], + [1800, 200, 5], + 'the defaults', + ); +}); + +it('a numeric string is read as its number, as it was before the refusals', (t) => { + const h = harness(t); + const strings = { durationSeconds: '3600', cadenceSeconds: '600', backlogCap: '50', maxWakes: '3' }; + assert.equal(h.coordinator.enter('disc', '#a', strings as never, 'agent-tool').ok, true); + assert.deepEqual( + [h.entered[0].expiresAtMs, h.entered[0].cadenceSeconds, h.entered[0].backlogCap, h.entered[0].maxWakes], + [NOW + 3_600_000, 600, 50, 3], + ); +}); From e69bfaae9478d111ce06aa6d3360f39e7b63f51a Mon Sep 17 00:00:00 2001 From: Abigail-2459 Date: Sat, 17 Oct 2026 09:42:42 -0400 Subject: [PATCH 2/3] fix(tune-out): the cadence counts its period on its timers, and the next enter clears an old end time's step From our internal review of the previous commit: - The cadence read the wall clock at each step (armAt toward Date.now() + period), so setting the clock back lengthened the period, where main's single setTimeout counted the period on the timer. armAfter (src/deadline-timer.ts) counts a delay on timers of at most 2^31 - 1 ms each, and the cadence now uses it. The end time keeps armAt, since it's a stored instant, so a running host and a restarted one aim at the same end. - armExpiry returned for a tune-out with no duration before it cleared the channel's pending end-time step. A tune-out can end in the registry without cancel, since a send into the channel or a close sets its state there, so its step stayed armed and ended the channel's next, open-ended tune-out at the old end time. armExpiry now clears first. main has the same defect with its single timer, for a duration short enough for one timer, which is what the new test uses (two days). - New tests: a restart ends the tune-out at its stored end time and not before, on a clock that runs normally; a cadence gives a second turn a period later; a restart re-arms a stored cadence past one timer; options below their floors are raised to them; armAt arms a deadline that has passed without a TimeoutNegativeWarning, which Node 23 and later give for a negative delay; the stop test shows both second steps armed before stop runs; a tune-out ended in the registry leaves no step to end the next one; and the cadence's turn comes on its timers while the wall clock moves only milliseconds. - The armAt doc now says a restarted process aims at the same time rather than that it ends at it, since each step's wait is a Node timer, which counts on a monotonic clock. - The changelog fragment says the same, and names the stale-step fix. Co-Authored-By: Claude Opus 5.5 --- changelog.d/tune-out-long-timers.fixed.md | 20 ++-- src/deadline-timer.ts | 38 +++++--- src/tune-out/coordinator.ts | 15 ++- test/tune-out-timers.test.ts | 114 +++++++++++++++++++--- 4 files changed, 149 insertions(+), 38 deletions(-) diff --git a/changelog.d/tune-out-long-timers.fixed.md b/changelog.d/tune-out-long-timers.fixed.md index b72f454ec..b1cf78896 100644 --- a/changelog.d/tune-out-long-timers.fixed.md +++ b/changelog.d/tune-out-long-timers.fixed.md @@ -3,11 +3,16 @@ Before, Node fired the timer almost at once, so such a tune-out ended as "duration elapsed" moments after it began, waking the resident with its backlog, and such a cadence re-armed about every millisecond, giving the - subconscious a turn as soon as anything was diverted, after every restart - too. Both timers now re-arm in steps no longer than one timer, each step - reading the clock against its deadline; the end time's deadline is the - stored one, so a host that runs through it and one that restarts end the - tune-out at the same time. + subconscious a turn as soon as anything was diverted. Both timers now + wait in steps no longer than one timer. The cadence counts its period on + those timers, as it did before, so setting the wall clock doesn't move + it. The end time reads the wall clock against the stored end at each + step, so a host that runs through a long tune-out and one that restarts + during it aim at the same end. +- A tune-out that ends without a cancel, as a send into its channel or a + close of the channel ends it, no longer leaves its end time armed to end + the channel's next tune-out. Before, when the next tune-out had no + `durationSeconds`, the old end time ended it as "duration elapsed". - `tune_out` refuses a `durationSeconds`, `cadenceSeconds`, `backlogCap` or `maxWakes` that gives no finite number, such as `"abc"`, and a duration whose end time is too far off to store, naming the option and saying @@ -16,5 +21,6 @@ failed and left the channel diverted with no cadence or end timer until the next restart. A numeric string such as `"3600"` is still read as its number. -- A `null` `durationSeconds` now means no end time, as leaving it out does. - Before, it gave a tune-out of 60 seconds, the shortest duration. +- A `null` `durationSeconds` now means the tune-out lasts until cancelled, + as leaving it out does. Before, it gave a tune-out of 60 seconds, the + shortest duration. diff --git a/src/deadline-timer.ts b/src/deadline-timer.ts index 77973a208..64d67e1f7 100644 --- a/src/deadline-timer.ts +++ b/src/deadline-timer.ts @@ -2,20 +2,20 @@ * Node fires a longer one almost at once, with a TimeoutOverflowWarning. */ const MAX_TIMER_MS = 2_147_483_647; +type Hold = (timer: ReturnType) => void; + /** - * Call `fire` once the clock reaches `deadlineMs` (epoch ms), through timers - * no longer than one holds, so a deadline weeks away fires then rather than - * at once. Each step reads the clock against the deadline and re-arms for - * what's left, so a deadline kept in storage ends at the same time whether - * the process runs through it or restarts and arms it again. `hold` gets each - * step's timer: clearing the latest one stops the rest. + * Call `fire` once the wall clock reaches `deadlineMs` (epoch ms), through + * timers no longer than one holds, so a deadline weeks away fires then rather + * than at once. Each step reads the wall clock against the deadline and arms + * the next for what's left, so the steps' own delays don't add up, and a + * process that restarts and arms the same stored deadline aims at the same + * time. `hold` gets each step's timer: clearing the latest one stops the rest. */ -export function armAt( - deadlineMs: number, - hold: (timer: ReturnType) => void, - fire: () => void, -): void { +export function armAt(deadlineMs: number, hold: Hold, fire: () => void): void { const arm = (): void => { + // A deadline that has just passed arms a 0 ms step rather than a negative + // one, which Node 23 and later warn about. hold(setTimeout(step, Math.min(Math.max(0, deadlineMs - Date.now()), MAX_TIMER_MS))); }; const step = (): void => { @@ -24,3 +24,19 @@ export function armAt( }; arm(); } + +/** + * Call `fire` after `delayMs`, counted on timers no longer than one holds, so + * a delay weeks long fires then rather than at once. The timers count the + * time, so setting the wall clock doesn't move it. `hold` gets each step's + * timer: clearing the latest one stops the rest. + */ +export function armAfter(delayMs: number, hold: Hold, fire: () => void): void { + let left = delayMs; + const arm = (): void => { + const step = Math.min(left, MAX_TIMER_MS); + left -= step; + hold(setTimeout(left > 0 ? arm : fire, step)); + }; + arm(); +} diff --git a/src/tune-out/coordinator.ts b/src/tune-out/coordinator.ts index 2ae4309ba..076c40f9d 100644 --- a/src/tune-out/coordinator.ts +++ b/src/tune-out/coordinator.ts @@ -21,7 +21,7 @@ import type { StoredMessage } from '@animalabs/context-manager'; import type { ChannelRegistry, TuneOutParams } from '../mcpl/channel-registry.js'; import type { McplServerRegistry } from '../mcpl/server-registry.js'; import { CapabilityGrant } from '../mcpl/capability-grant.js'; -import { armAt } from '../deadline-timer.js'; +import { armAfter, armAt } from '../deadline-timer.js'; /** Defaults for tune_out tool params. */ export const TUNE_OUT_DEFAULTS = { @@ -65,7 +65,8 @@ export interface TuneOutFrameworkHooks { export class TuneOutCoordinator { private cadenceTimers = new Map>(); - /** Each duration's pending expiry step (params.expiresAtMs); cleared on any cancel. */ + /** Each duration's pending expiry step (params.expiresAtMs); cleared by + * cancel, stop, and the channel's next enter. */ private expiryTimers = new Map>(); /** Channels with a wake invocation pending inside the coalescing window. */ private pendingWakes = new Map }>(); @@ -105,10 +106,14 @@ export class TuneOutCoordinator { } private armExpiry(serverId: string, channelId: string, params: TuneOutParams): void { - if (params.expiresAtMs === undefined) return; const key = this.key(serverId, channelId); + // An earlier tune-out on this channel can end in the registry without + // cancel (a send or a close sets the channel's state there), leaving its + // end time's step armed. Clear it first, so it can't end this one. const existing = this.expiryTimers.get(key); if (existing) clearTimeout(existing); + this.expiryTimers.delete(key); + if (params.expiresAtMs === undefined) return; armAt(params.expiresAtMs, (timer) => { this.expiryTimers.set(key, timer); }, () => { this.expiryTimers.delete(key); this.cancel(serverId, channelId, 'duration', 'duration elapsed'); @@ -388,9 +393,9 @@ export class TuneOutCoordinator { if (diverted > 0) { this.invokeSubconscious(serverId, channelId, 'cadence', diverted); } - armAt(Date.now() + cadenceSeconds * 1000, hold, tick); + armAfter(cadenceSeconds * 1000, hold, tick); }; - armAt(Date.now() + cadenceSeconds * 1000, hold, tick); + armAfter(cadenceSeconds * 1000, hold, tick); } private stopCadence(serverId: string, channelId: string): void { diff --git a/test/tune-out-timers.test.ts b/test/tune-out-timers.test.ts index 6ba61e6f3..fe353f337 100644 --- a/test/tune-out-timers.test.ts +++ b/test/tune-out-timers.test.ts @@ -8,10 +8,14 @@ * fire an overflowing timeout early too (Node 24), and the harness records * each delay asked of setTimeout, so the timer tests also check that no step * is longer than one timer holds, whatever the runtime's mock does. + * + * The mock runs a tick's due timers with the clock already at the tick's + * end, so tests that follow a timer step by step tick to each step's end. */ import { it, type TestContext } from 'node:test'; import assert from 'node:assert/strict'; import { TuneOutCoordinator, type TuneOutFrameworkHooks } from '../src/tune-out/coordinator.js'; +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'; @@ -19,15 +23,17 @@ import type { McplServerRegistry } from '../src/mcpl/server-registry.js'; const ONE_TIMER_MS = 2_147_483_647; const DAY_MS = 86_400_000; const NOW = Date.UTC(2026, 9, 17); +const STORED: TuneOutParams = { epochId: 'e1', cadenceSeconds: 1800, backlogCap: 200, maxWakes: 5, startedAtSequence: 1 }; /** - * A coordinator over an in-memory registry for one channel, `disc` `#a`, - * with the clock and setTimeout mocked and each delay asked of setTimeout - * recorded. `stored` is a tune-out the registry already holds, as after a - * restart. + * 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. */ -function harness(t: TestContext, stored?: TuneOutParams) { - t.mock.timers.enable({ apis: ['Date', 'setTimeout'], now: NOW }); +function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = {}) { + if (wallClock) t.mock.timers.enable({ apis: ['Date', 'setTimeout'], now: NOW }); + else t.mock.timers.enable({ apis: ['setTimeout'] }); const mocked = globalThis.setTimeout; const delays: number[] = []; globalThis.setTimeout = ((fn: (...args: unknown[]) => void, ms?: number, ...rest: unknown[]) => { @@ -80,7 +86,10 @@ function harness(t: TestContext, stored?: TuneOutParams) { delays.every((ms) => ms <= ONE_TIMER_MS), `no timer longer than one holds (${delays.filter((ms) => !(ms <= ONE_TIMER_MS)).join(', ')})`, ); - return { coordinator, entered, cancels, cadenceTurns, delays, noTimerPastOne }; + /** 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, delays, noTimerPastOne, endInRegistry, active }; } it('a duration past one timer ends at its end time and not before', (t) => { @@ -95,11 +104,20 @@ it('a duration past one timer ends at its end time and not before', (t) => { h.noTimerPastOne(); }); -it('a restart with more than one timer left reads the stored end time at each step', (t) => { - const h = harness(t, { - epochId: 'e1', cadenceSeconds: 1800, backlogCap: 200, maxWakes: 5, startedAtSequence: 1, - expiresAtMs: NOW + 30 * DAY_MS, - }); +it('a restart with more than one timer left ends the tune-out at its stored end time and not before', (t) => { + const h = harness(t, { ...STORED, expiresAtMs: NOW + 30 * DAY_MS }); + h.coordinator.resumeActiveEpochs(); + t.mock.timers.tick(ONE_TIMER_MS); + assert.deepEqual(h.cancels, [], "still tuned out after one timer's worth"); + t.mock.timers.tick(30 * DAY_MS - ONE_TIMER_MS - 1); + assert.deepEqual(h.cancels, [], 'still tuned out 1 ms before its stored end'); + t.mock.timers.tick(1); + assert.deepEqual(h.cancels, ['duration'], 'ended once, at its stored end time'); + h.noTimerPastOne(); +}); + +it('after a restart, each step reads the stored end time again', (t) => { + const h = harness(t, { ...STORED, expiresAtMs: NOW + 30 * DAY_MS }); h.coordinator.resumeActiveEpochs(); t.mock.timers.tick(DAY_MS); assert.deepEqual(h.cancels, [], 'still tuned out a day after the restart'); @@ -121,30 +139,73 @@ it("a cancel stops the end time's later steps, so a new tune-out on the channel assert.deepEqual(h.cancels, ['agent-tool'], 'only the cancel asked for: the new tune-out runs on'); }); +it("a tune-out that ends in the registry, as a send or a close ends it, leaves no step to end the channel's next one", (t) => { + const h = harness(t); + // Two days, one timer's worth, so main's single timer shows the same case. + assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 2 * 86_400 }, 'agent-tool').ok, true); + t.mock.timers.tick(DAY_MS); + h.endInRegistry(); + assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true, 'a new tune-out, until cancelled'); + t.mock.timers.tick(2 * DAY_MS); + assert.deepEqual(h.cancels, [], "the old end time didn't end the new tune-out"); + assert.equal(h.active(), true); +}); + it("stop clears both timers' pending steps: neither fires after it", (t) => { const h = harness(t); const opts = { durationSeconds: 30 * 86_400, cadenceSeconds: 30 * 86_400 }; assert.equal(h.coordinator.enter('disc', '#a', opts, 'agent-tool').ok, true); h.coordinator.onIncoming('disc', '#a', 'm1', undefined); t.mock.timers.tick(ONE_TIMER_MS); + assert.equal( + h.delays.filter((ms) => ms === 30 * DAY_MS - ONE_TIMER_MS).length, + 2, + "both timers' second steps are armed when stop runs", + ); h.coordinator.stop(); t.mock.timers.tick(60 * DAY_MS); assert.deepEqual(h.cancels, [], 'no end after stop'); assert.deepEqual(h.cadenceTurns(), [], 'no cadence turn after stop'); }); -it('a cadence past one timer gives the subconscious one turn at the cadence: none before it, none after a cancel', (t) => { +it('a cadence past one timer gives the subconscious a turn each period: none before the first, none after a cancel', (t) => { const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 30 * 86_400 }, 'agent-tool').ok, true); h.coordinator.onIncoming('disc', '#a', 'm1', undefined); - t.mock.timers.tick(30 * DAY_MS - 1); + t.mock.timers.tick(ONE_TIMER_MS); + t.mock.timers.tick(30 * DAY_MS - ONE_TIMER_MS - 1); assert.deepEqual(h.cadenceTurns(), [], 'no turn before the cadence'); t.mock.timers.tick(1); assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'one turn at the cadence'); h.coordinator.onIncoming('disc', '#a', 'm2', undefined); + t.mock.timers.tick(ONE_TIMER_MS); + t.mock.timers.tick(30 * DAY_MS - ONE_TIMER_MS); + assert.equal(h.cadenceTurns().length, 2, 'a second turn a period later'); + h.coordinator.onIncoming('disc', '#a', 'm3', undefined); assert.equal(h.coordinator.cancel('disc', '#a', 'agent-tool', 'agent request').ok, true); + t.mock.timers.tick(ONE_TIMER_MS); t.mock.timers.tick(30 * DAY_MS); - assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'no turn after the cancel'); + assert.equal(h.cadenceTurns().length, 2, 'no turn after the cancel'); + h.noTimerPastOne(); +}); + +it("the cadence counts its period on its timers, so the wall clock doesn't move its turn", (t) => { + // Only setTimeout is mocked: the wall clock stands still while the timers run. + const h = harness(t, undefined, { wallClock: false }); + assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + t.mock.timers.tick(1_800_000); + assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'the turn came after the default 1800 s on the timers'); +}); + +it('a restart re-arms a stored cadence past one timer: the turn comes at the cadence', (t) => { + const h = harness(t, { ...STORED, cadenceSeconds: 30 * 86_400 }); + h.coordinator.resumeActiveEpochs(); + h.coordinator.onIncoming('disc', '#a', 'm1', undefined); + t.mock.timers.tick(ONE_TIMER_MS); + assert.deepEqual(h.cadenceTurns(), [], "no turn after one timer's worth"); + t.mock.timers.tick(30 * DAY_MS - ONE_TIMER_MS); + assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'one turn at the cadence'); h.noTimerPastOne(); }); @@ -198,3 +259,26 @@ it('a numeric string is read as its number, as it was before the refusals', (t) [NOW + 3_600_000, 600, 50, 3], ); }); + +it('an option below its floor is raised to it, as before', (t) => { + const h = harness(t); + const below = { durationSeconds: 5, cadenceSeconds: 1, backlogCap: -3, maxWakes: 0 }; + assert.equal(h.coordinator.enter('disc', '#a', below, 'agent-tool').ok, true); + assert.deepEqual( + [h.entered[0].expiresAtMs, h.entered[0].cadenceSeconds, h.entered[0].backlogCap, h.entered[0].maxWakes], + [NOW + 60_000, 30, 0, 1], + ); +}); + +it('armAt arms a deadline that has passed for the next turn of the loop, with no negative-delay warning', async () => { + // Real timers: Node 23 and later warn about a negative delay. + const warnings: string[] = []; + const onWarning = (w: Error) => { warnings.push(w.name); }; + process.on('warning', onWarning); + try { + await new Promise((resolve) => { armAt(Date.now() - 5, () => {}, resolve); }); + assert.deepEqual(warnings.filter((name) => name === 'TimeoutNegativeWarning'), []); + } finally { + process.off('warning', onWarning); + } +}); From fa7335303a87880cb2a3de020af277c10c69de18 Mon Sep 17 00:00:00 2001 From: Abigail-2459 Date: Sat, 17 Oct 2026 10:41:24 -0400 Subject: [PATCH 3/3] fix(tune-out): enter clears every timer an earlier tune-out left on the channel From our internal review of the previous commit: - A tune-out that ends in the registry without cancel, as a send into the channel or a close ends it, left all three of its timers armed. The previous commit cleared the end time at the next enter, and startCadence already stopped the cadence, but a wake still in its 2-second coalescing window fired into the next tune-out. It counted a wake against that tune-out and gave the subconscious a turn for the old message. clearTimers clears the cadence, the end time and a coalescing wake together. cancel uses it in place of its own three clears, and enter calls it before the registry write. armExpiry is back to main's shape, since enter clears for it. - armAt's doc says when it sees a change to the wall clock. Each step's wait is a Node timer, which counts on a monotonic clock, so armAt sees a change made during a step when that step ends. - The expiryTimers comment says cancel clears the end time only while the registry still holds the tune-out, and the next enter clears it in any case. - The changelog fragment names the coalescing wake beside the end time. - The tests: the registry-ended test now covers all three timers, with a wake still coalescing and a new tune-out on another cadence, and it fails at the previous commit on the wake. Every test that arms a timer now checks that none is longer than one timer holds. The cancel test's title says what it shows, and two comments say what the mock clock does. Co-Authored-By: Claude Opus 5.5 --- changelog.d/tune-out-long-timers.fixed.md | 10 +++--- src/deadline-timer.ts | 12 ++++--- src/tune-out/coordinator.ts | 40 +++++++++++++---------- test/tune-out-timers.test.ts | 33 ++++++++++++++----- 4 files changed, 60 insertions(+), 35 deletions(-) diff --git a/changelog.d/tune-out-long-timers.fixed.md b/changelog.d/tune-out-long-timers.fixed.md index b1cf78896..62de70cd4 100644 --- a/changelog.d/tune-out-long-timers.fixed.md +++ b/changelog.d/tune-out-long-timers.fixed.md @@ -9,10 +9,12 @@ it. The end time reads the wall clock against the stored end at each step, so a host that runs through a long tune-out and one that restarts during it aim at the same end. -- A tune-out that ends without a cancel, as a send into its channel or a - close of the channel ends it, no longer leaves its end time armed to end - the channel's next tune-out. Before, when the next tune-out had no - `durationSeconds`, the old end time ended it as "duration elapsed". +- A tune-out that ends in the channel registry without a cancel (the send + path and the close tool set the channel's state there directly) no + longer leaves its timers to act on the channel's next tune-out. Before, + when the next tune-out had no `durationSeconds`, the old end time ended + it as "duration elapsed", and a wake still in its 2-second coalescing + window counted against it and gave the subconscious a turn. - `tune_out` refuses a `durationSeconds`, `cadenceSeconds`, `backlogCap` or `maxWakes` that gives no finite number, such as `"abc"`, and a duration whose end time is too far off to store, naming the option and saying diff --git a/src/deadline-timer.ts b/src/deadline-timer.ts index 64d67e1f7..3c477afd1 100644 --- a/src/deadline-timer.ts +++ b/src/deadline-timer.ts @@ -5,12 +5,14 @@ const MAX_TIMER_MS = 2_147_483_647; type Hold = (timer: ReturnType) => void; /** - * Call `fire` once the wall clock reaches `deadlineMs` (epoch ms), through - * timers no longer than one holds, so a deadline weeks away fires then rather - * than at once. Each step reads the wall clock against the deadline and arms - * the next for what's left, so the steps' own delays don't add up, and a + * Call `fire` at `deadlineMs` (epoch ms) by the wall clock, through timers no + * longer than one holds, so a deadline weeks away fires then rather than at + * once. When a step ends, it reads the wall clock against the deadline and + * arms the next for what's left, so the steps' own delays don't add up, and a * process that restarts and arms the same stored deadline aims at the same - * time. `hold` gets each step's timer: clearing the latest one stops the rest. + * time. A step's own wait runs on Node's monotonic clock, so a change to the + * wall clock during a step is seen when that step ends. `hold` gets each + * step's timer: clearing the latest one stops the rest. */ export function armAt(deadlineMs: number, hold: Hold, fire: () => void): void { const arm = (): void => { diff --git a/src/tune-out/coordinator.ts b/src/tune-out/coordinator.ts index 076c40f9d..021610336 100644 --- a/src/tune-out/coordinator.ts +++ b/src/tune-out/coordinator.ts @@ -65,8 +65,9 @@ export interface TuneOutFrameworkHooks { export class TuneOutCoordinator { private cadenceTimers = new Map>(); - /** Each duration's pending expiry step (params.expiresAtMs); cleared by - * cancel, stop, and the channel's next enter. */ + /** Each duration's pending expiry step (params.expiresAtMs). stop clears + * it, cancel does while the registry still holds the tune-out, and the + * channel's next enter does in any case. */ private expiryTimers = new Map>(); /** Channels with a wake invocation pending inside the coalescing window. */ private pendingWakes = new Map }>(); @@ -106,14 +107,10 @@ export class TuneOutCoordinator { } private armExpiry(serverId: string, channelId: string, params: TuneOutParams): void { + if (params.expiresAtMs === undefined) return; const key = this.key(serverId, channelId); - // An earlier tune-out on this channel can end in the registry without - // cancel (a send or a close sets the channel's state there), leaving its - // end time's step armed. Clear it first, so it can't end this one. const existing = this.expiryTimers.get(key); if (existing) clearTimeout(existing); - this.expiryTimers.delete(key); - if (params.expiresAtMs === undefined) return; armAt(params.expiresAtMs, (timer) => { this.expiryTimers.set(key, timer); }, () => { this.expiryTimers.delete(key); this.cancel(serverId, channelId, 'duration', 'duration elapsed'); @@ -197,6 +194,10 @@ export class TuneOutCoordinator { startedAtSequence: this.hooks.currentSequence(), ...(expiresAtMs !== undefined ? { expiresAtMs } : {}), }; + // A tune-out can end in the registry without cancel (a send into the + // channel or a close sets its state there), leaving its timers armed: + // clear them, so none of them acts on this one. + this.clearTimers(serverId, channelId); this.channelRegistry.enterTuneOut(serverId, channelId, params, source); this.armExpiry(serverId, channelId, params); @@ -232,17 +233,7 @@ export class TuneOutCoordinator { if (!ended) { return { ok: false, error: `channel ${channelId} is not tuned out` }; } - this.stopCadence(serverId, channelId); - const expiry = this.expiryTimers.get(this.key(serverId, channelId)); - if (expiry) { - clearTimeout(expiry); - this.expiryTimers.delete(this.key(serverId, channelId)); - } - const pending = this.pendingWakes.get(this.key(serverId, channelId)); - if (pending) { - clearTimeout(pending.timer); - this.pendingWakes.delete(this.key(serverId, channelId)); - } + this.clearTimers(serverId, channelId); this.divertedSinceInvocation.delete(this.key(serverId, channelId)); // Backlog: every message stamped with this epoch, oldest first. @@ -398,6 +389,19 @@ export class TuneOutCoordinator { armAfter(cadenceSeconds * 1000, hold, tick); } + /** Clear a channel's tune-out timers: its cadence, its end time and a wake + * still coalescing. */ + private clearTimers(serverId: string, channelId: string): void { + const key = this.key(serverId, channelId); + this.stopCadence(serverId, channelId); + const expiry = this.expiryTimers.get(key); + if (expiry) clearTimeout(expiry); + this.expiryTimers.delete(key); + const pending = this.pendingWakes.get(key); + if (pending) clearTimeout(pending.timer); + this.pendingWakes.delete(key); + } + private stopCadence(serverId: string, channelId: string): void { const key = this.key(serverId, channelId); const timer = this.cadenceTimers.get(key); diff --git a/test/tune-out-timers.test.ts b/test/tune-out-timers.test.ts index fe353f337..5ffc6e59c 100644 --- a/test/tune-out-timers.test.ts +++ b/test/tune-out-timers.test.ts @@ -82,6 +82,7 @@ function harness(t: TestContext, stored?: TuneOutParams, { wallClock = true } = t.mock.timers.reset(); }); const cadenceTurns = () => inferences.filter((r) => r.startsWith('tune-out cadence')); + const wakeTurns = () => inferences.filter((r) => r.startsWith('tune-out wake')); const noTimerPastOne = () => assert.ok( delays.every((ms) => ms <= ONE_TIMER_MS), `no timer longer than one holds (${delays.filter((ms) => !(ms <= ONE_TIMER_MS)).join(', ')})`, @@ -89,7 +90,7 @@ 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, delays, noTimerPastOne, endInRegistry, active }; + return { coordinator, entered, cancels, cadenceTurns, wakeTurns, delays, noTimerPastOne, endInRegistry, active }; } it('a duration past one timer ends at its end time and not before', (t) => { @@ -122,14 +123,15 @@ it('after a restart, each step reads the stored end time again', (t) => { t.mock.timers.tick(DAY_MS); assert.deepEqual(h.cancels, [], 'still tuned out a day after the restart'); // The wall clock reaches the stored end while a step waits, as after a - // host's suspend or a clock correction: the step that runs next reads it. + // host's suspend or a clock correction: when that step runs, it reads the + // stored end time again and ends the tune-out. t.mock.timers.setTime(NOW + 30 * DAY_MS); t.mock.timers.tick(ONE_TIMER_MS); assert.deepEqual(h.cancels, ['duration'], 'the next step found the stored end time passed and ended it'); h.noTimerPastOne(); }); -it("a cancel stops the end time's later steps, so a new tune-out on the channel isn't ended at the old one's end", (t) => { +it("after a cancel, a new tune-out on the channel isn't ended at the old one's end time", (t) => { const h = harness(t); assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 30 * 86_400 }, 'agent-tool').ok, true); t.mock.timers.tick(ONE_TIMER_MS); @@ -137,18 +139,29 @@ it("a cancel stops the end time's later steps, so a new tune-out on the channel assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true, 'a new tune-out, until cancelled'); t.mock.timers.tick(30 * DAY_MS); assert.deepEqual(h.cancels, ['agent-tool'], 'only the cancel asked for: the new tune-out runs on'); + h.noTimerPastOne(); }); -it("a tune-out that ends in the registry, as a send or a close ends it, leaves no step to end the channel's next one", (t) => { +it("a tune-out that ends in the registry, as a send or a close ends it, leaves none of its timers to act on the channel's next one", (t) => { const h = harness(t); - // Two days, one timer's worth, so main's single timer shows the same case. + // A two-day end time (short enough for one timer, so main's single timer + // shows the same case), the default 1800 s cadence, and a wake coalescing + // for 2 s. assert.equal(h.coordinator.enter('disc', '#a', { durationSeconds: 2 * 86_400 }, 'agent-tool').ok, true); - t.mock.timers.tick(DAY_MS); + h.coordinator.onIncoming('disc', '#a', 'm1', ['chat:addressed']); h.endInRegistry(); - assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true, 'a new tune-out, until cancelled'); + assert.equal(h.coordinator.enter('disc', '#a', { cadenceSeconds: 3600 }, 'agent-tool').ok, true, 'a new tune-out, until cancelled'); + h.coordinator.onIncoming('disc', '#a', 'm2', undefined); + t.mock.timers.tick(2_000); + assert.deepEqual(h.wakeTurns(), [], "the old wake didn't count against the new tune-out"); + t.mock.timers.tick(1_800_000 - 2_000); + assert.deepEqual(h.cadenceTurns(), [], 'the old cadence gave the new tune-out no turn'); + t.mock.timers.tick(1_800_000); + assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'the new cadence gave its turn at 3600 s'); t.mock.timers.tick(2 * DAY_MS); assert.deepEqual(h.cancels, [], "the old end time didn't end the new tune-out"); assert.equal(h.active(), true); + h.noTimerPastOne(); }); it("stop clears both timers' pending steps: neither fires after it", (t) => { @@ -166,6 +179,7 @@ it("stop clears both timers' pending steps: neither fires after it", (t) => { t.mock.timers.tick(60 * DAY_MS); assert.deepEqual(h.cancels, [], 'no end after stop'); assert.deepEqual(h.cadenceTurns(), [], 'no cadence turn after stop'); + h.noTimerPastOne(); }); it('a cadence past one timer gives the subconscious a turn each period: none before the first, none after a cancel', (t) => { @@ -190,12 +204,15 @@ it('a cadence past one timer gives the subconscious a turn each period: none bef }); it("the cadence counts its period on its timers, so the wall clock doesn't move its turn", (t) => { - // Only setTimeout is mocked: the wall clock stands still while the timers run. + // Only setTimeout is mocked: the real wall clock moves a few milliseconds + // while the mocked timers run 30 minutes, so a cadence that read the wall + // clock wouldn't come due. const h = harness(t, undefined, { wallClock: false }); assert.equal(h.coordinator.enter('disc', '#a', {}, 'agent-tool').ok, true); h.coordinator.onIncoming('disc', '#a', 'm1', undefined); t.mock.timers.tick(1_800_000); assert.deepEqual(h.cadenceTurns(), ['tune-out cadence: #a'], 'the turn came after the default 1800 s on the timers'); + h.noTimerPastOne(); }); it('a restart re-arms a stored cadence past one timer: the turn comes at the cadence', (t) => {