diff --git a/.changeset/kernel-timeout-guard-reclaim.md b/.changeset/kernel-timeout-guard-reclaim.md new file mode 100644 index 0000000000..561d0c8c1d --- /dev/null +++ b/.changeset/kernel-timeout-guard-reclaim.md @@ -0,0 +1,38 @@ +--- +"@objectstack/core": patch +--- + +The kernel's two `Promise.race` timeout guards — the startup guard around each +plugin's `init`/`start`, and the shutdown guard around `performShutdown()` — +now reclaim **both** halves of the guard when the race settles: the timer is +cleared *and* the losing promise is settled (#10604). + +Neither site settled its loser, so the timeout promise and the reaction +`Promise.race` held on it were retained for the life of the process — four +leaking promises per showcase test run under `vitest --detectAsyncLeaks`, now +zero. The two hand-rolled copies had also drifted into doing opposite halves of +the same cleanup: the startup site cleared its timer and never `unref`'d, the +shutdown site `unref`'d and never cleared. Both now go through one internal +`TimeoutGuard`, so they cannot drift apart again. No exported API changes. + +**Behaviour change, at the shutdown guard:** the shutdown timer is no longer +`unref()`d. Two consequences for an embedding host (CLI, auth-proxy, test +runner): + +- After a **successful** shutdown, no timer is left armed. Previously the guard + survived its own race and stayed scheduled to fire against a kernel already + `'stopped'`. That late rejection was *handled* — `Promise.race` had attached a + rejection handler to it — so this was never an unhandled-rejection risk; it + was retained work and a wakeup after teardown. +- When teardown **hangs**, the guard now actually fires. An unref'd timer does + not keep the event loop alive, so a process with nothing else to run could + exit silently — status 0, teardown incomplete — before `shutdownTimeout` + elapsed, leaving `Shutdown timed out — forcing exit` and its `exit(1)` + unreachable in exactly the case they exist for. Reclaiming on settle keeps the + guard ref'd exactly as long as the race is undecided, which is the guarantee + the startup guard already had (#4813). + +If your host relied on a hung `shutdown()` letting the process fall out of the +event loop on its own, it will now wait up to `shutdownTimeout` (default 60s) +and then hard-exit with status 1. Lower `shutdownTimeout` in the kernel config +to shorten that window. diff --git a/packages/core/src/kernel.test.ts b/packages/core/src/kernel.test.ts index 41f947a370..aed124f760 100644 --- a/packages/core/src/kernel.test.ts +++ b/packages/core/src/kernel.test.ts @@ -358,6 +358,54 @@ describe('ObjectKernel', () => { }); }); + describe('The shutdown guard is reclaimed on the same terms (#10604)', () => { + // The startup site cleared its timer and never unref'd; this one + // unref'd and never cleared. Two hand-rolled copies of one race, each + // doing the opposite half, and neither settling the promise the race + // still held a reaction on — four leaking promises per showcase run. + // Both sites now go through `TimeoutGuard`, so this pins the wiring. + // + // The companion assertion — that reclaiming the guard did not DISARM + // it — is 'still logs the timeout and still forces exit(1) when + // shutdown genuinely times out (#5274)' below, which hangs teardown + // past `shutdownTimeout` and is unchanged by this fix. + + it('leaves no timer armed once shutdown has settled', async () => { + vi.useFakeTimers(); + try { + const k = new ObjectKernel({ + logger: { level: 'error' }, + gracefulShutdown: false, + skipSystemValidation: true, + shutdownTimeout: 60_000, + }); + + await k.use({ + name: 'reclaimed-shutdown-guard', + version: '1.0.0', + init: async () => {}, + start: async () => {}, + destroy: async () => {}, + } as PluginMetadata); + + const before = vi.getTimerCount(); + await k.bootstrap(); + await k.shutdown(); + + // Before the fix this was `before + 1`: `performShutdown()` won + // the race and the 60s guard stayed armed, to fire later against + // a kernel already 'stopped'. `unref()` hid it from the event + // loop but not from here — which is the distinction this + // assertion exists to keep. + expect(vi.getTimerCount()).toBe(before); + } finally { + vi.useRealTimers(); + } + }); + + }); + + describe('Startup Failure Rollback', () => { it('should rollback started plugins on failure', async () => { let plugin1Destroyed = false; diff --git a/packages/core/src/kernel.ts b/packages/core/src/kernel.ts index 94c646f7b2..81a869b5f1 100644 --- a/packages/core/src/kernel.ts +++ b/packages/core/src/kernel.ts @@ -15,6 +15,7 @@ import { } from './plugin-order.js'; import { dispatchHookIsolating, dispatchHookPropagating } from './hook-dispatch.js'; import { registerPluginByName } from './plugin-registration.js'; +import { raceWithTimeout } from './timeout-guard.js'; /** * Enhanced Kernel Configuration @@ -457,16 +458,25 @@ export class ObjectKernel { const shutdownTimeoutError = new Error('Shutdown timeout exceeded'); try { - const shutdownPromise = this.performShutdown(); - const timeoutPromise = new Promise((_, reject) => { - const t = setTimeout(() => { - reject(shutdownTimeoutError); - }, this.config.shutdownTimeout); - // Don't let this timer keep the event loop alive - if (t.unref) t.unref(); - }); - - await Promise.race([shutdownPromise, timeoutPromise]); + // Same guard as the startup races (#10604). It used to be hand-rolled + // here, and the two copies had already drifted into doing opposite + // halves of the same job: this one `unref()`d its timer and never + // cleared it, so a won race left it armed to fire against a kernel + // that was already 'stopped', while the startup site cleared and + // never unref'd. `raceWithTimeout` does both halves, once. + // + // Dropping the `unref()` is the point, not a casualty of the merge: + // an unref'd guard stops being a guard (#4813). If `performShutdown()` + // hangs and nothing else keeps the loop alive, an unref'd timer lets + // Node exit *silently* — no 'Shutdown timed out', no `exit(1)`, the + // one branch that hard-exit was ever right for never reached. + // Clearing on settle keeps it ref'd exactly while the race is + // undecided, which is the property this timeout needs. + await raceWithTimeout( + this.performShutdown(), + this.config.shutdownTimeout!, + () => shutdownTimeoutError, + ); this.state = 'stopped'; this.logger.info('✅ Graceful shutdown complete'); @@ -619,31 +629,21 @@ export class ObjectKernel { * as well: if the hook never settles and nothing else keeps the loop alive, * Node exits before the timer can fire and the timeout is never reported. * The guard has to stay ref'd exactly as long as the race is undecided, - * which is what `clearTimeout` in a `finally` expresses. + * which is what clearing on settle expresses. * - * `operation` is widened to `T | PromiseLike` because the Plugin - * contract permits a synchronous hook (`init`/`start` return - * `void | Promise`); such a hook wins the race immediately and the - * guard is reclaimed on the same turn. + * Clearing the timer was only half of it, though (#10604): the promise the + * race still holds a reaction on has to SETTLE, or it and that reaction are + * retained past the end of the run — two leaking promises per boot, which + * is what `vitest --detectAsyncLeaks` names here. Both halves now live in + * `TimeoutGuard.reclaim()`, shared with `shutdown()`, so the two sites + * cannot drift into doing one half each again. */ private async raceStartupTimeout( operation: T | PromiseLike, timeout: number, message: string ): Promise { - let guard: ReturnType | undefined; - - const timeoutPromise = new Promise((_, reject) => { - guard = setTimeout(() => { - reject(new Error(message)); - }, timeout); - }); - - try { - return await Promise.race([operation, timeoutPromise]); - } finally { - clearTimeout(guard); - } + return raceWithTimeout(operation, timeout, () => new Error(message)); } /** diff --git a/packages/core/src/timeout-guard.test.ts b/packages/core/src/timeout-guard.test.ts new file mode 100644 index 0000000000..7211e00bf1 --- /dev/null +++ b/packages/core/src/timeout-guard.test.ts @@ -0,0 +1,180 @@ +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. + +import { describe, it, expect, afterEach, vi } from 'vitest'; +import { TimeoutGuard, raceWithTimeout } from './timeout-guard.js'; + +/** + * A guard has two reclaimable halves — the TIMER and the PROMISE — and the + * kernel's two race sites used to do one each (#10604). These pins hold both + * halves and the property that makes a guard a guard, so a future "cleanup" + * cannot buy leak-freedom by disarming it. + */ +describe('TimeoutGuard (#4813, #10604)', () => { + afterEach(() => { + vi.useRealTimers(); + }); + + const refdTimers = () => + process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length; + + /** + * Whether `expiry` has SETTLED, decided without hanging the suite: a + * settled promise runs its reaction in the current microtask drain, which + * is many orders of magnitude before a real 50ms timer. An unsettled + * guard — the leak — reports 'pending' in 50ms instead of timing the test + * out in five seconds. + */ + const settlementOf = (expiry: Promise) => + Promise.race([ + expiry.then(() => 'settled' as const, () => 'settled' as const), + new Promise<'pending'>((resolve) => setTimeout(() => resolve('pending'), 50)), + ]); + + describe('reclaim() does BOTH halves', () => { + it('clears the timer, so nothing is left armed against a phase that is over', () => { + vi.useFakeTimers(); + + const before = vi.getTimerCount(); + const guard = new TimeoutGuard(120_000, () => new Error('must not fire')); + expect(vi.getTimerCount()).toBe(before + 1); + + guard.reclaim(); + + // `vi.getTimerCount()` counts unref'd timers too, so this + // distinguishes "the guard was reclaimed" from "the guard was + // merely detached from the loop" — the shutdown site's old bug. + expect(vi.getTimerCount()).toBe(before); + }); + + it('settles `expiry`, so neither it nor the race\'s reaction on it is retained', async () => { + const guard = new TimeoutGuard(120_000, () => new Error('must not fire')); + + // The leak, stated directly: before #10604 the losing promise was + // never settled, so `Promise.race`'s reaction on it stayed pending + // for the life of the process. Clearing the timer does NOT do this. + guard.reclaim(); + + await expect(settlementOf(guard.expiry)).resolves.toBe('settled'); + }); + + it('is idempotent', async () => { + const guard = new TimeoutGuard(120_000, () => new Error('must not fire')); + + guard.reclaim(); + guard.reclaim(); + + await expect(settlementOf(guard.expiry)).resolves.toBe('settled'); + }); + }); + + describe('reclaiming must not mean disarming', () => { + it('still rejects with the caller\'s own error object when it is never reclaimed', async () => { + // Identity, not message: `shutdown()` discriminates a genuine + // timeout from any exception escaping teardown by comparing this + // exact object (#5274). + const timeoutError = new Error('Shutdown timeout exceeded'); + const guard = new TimeoutGuard(10, () => timeoutError); + + await expect(guard.expiry).rejects.toBe(timeoutError); + }); + + it('arms a REF\'D timer, so an otherwise-idle process cannot exit before it fires', () => { + // ⛔ The regression this forbids is `unref()` at arm time. It looks + // like a fix — no ref'd timer, no leak — and it silently removes + // the guarantee the guard exists for: with nothing else on the + // loop, Node exits before an unref'd guard can report the timeout + // (#4813). A leak-free kernel that no longer enforces its timeouts + // is strictly worse than the leak. + const before = refdTimers(); + const guard = new TimeoutGuard(120_000, () => new Error('must not fire')); + + expect(refdTimers()).toBe(before + 1); + + guard.reclaim(); + expect(refdTimers()).toBe(before); + }); + + it('builds the timeout error only when the guard actually fires', async () => { + let built = 0; + const guard = new TimeoutGuard(120_000, () => { + built++; + return new Error('must not fire'); + }); + + guard.reclaim(); + await settlementOf(guard.expiry); + + expect(built).toBe(0); + }); + }); +}); + +describe('raceWithTimeout (#10604)', () => { + it('returns the operation\'s value when the operation wins', async () => { + await expect( + raceWithTimeout(Promise.resolve('ok'), 120_000, () => new Error('must not fire')), + ).resolves.toBe('ok'); + }); + + it('accepts a synchronous operation, which wins on the same turn', async () => { + await expect( + raceWithTimeout('sync', 120_000, () => new Error('must not fire')), + ).resolves.toBe('sync'); + }); + + it('propagates the operation\'s own rejection unchanged', async () => { + const boom = new Error('operation failed'); + + await expect( + raceWithTimeout(Promise.reject(boom), 120_000, () => new Error('must not fire')), + ).rejects.toBe(boom); + }); + + it('rejects with the timeout error when the operation hangs', async () => { + const timeoutError = new Error('hung'); + + await expect( + raceWithTimeout(new Promise(() => {}), 10, () => timeoutError), + ).rejects.toBe(timeoutError); + }); + + /** + * ⚠️ `process.getActiveResourcesInfo()` is PROCESS-wide, and in CI this file + * shares one worker with three dozen others — so the absolute count is + * AMBIENT and this test does not own it. Foreign timers alive at the sample + * expire while this test awaits, pulling the reading DOWN: the shard read + * `expected 2 to be 4` on the third leg (#10661), the only one that spends + * real time on the loop (the first two settle on microtasks, where no timer + * phase can run and the reading cannot move under the test). + * + * A leak is a GROWTH, so the assertion is about the direction the SUBJECT + * can move the count, never the ambient value. Non-increase keeps every bit + * of the detection — an unreclaimed 120s guard is `+1` here, which is what + * ablating the `clearTimeout` half reds — and gives up only the decrease, + * which nothing `raceWithTimeout` does can cause. Each leg re-anchors on its + * own sample so a comparison spans one outcome instead of the whole test. + * + * ⛔ Do not "fix" the ambience by isolating this file or pinning the shard + * layout: that would make the pin's validity a property of the runner + * config rather than of its own assertion. + */ + it('leaves no ref\'d timer behind on any of the three outcomes', async () => { + const refd = () => process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length; + let before = refd(); + + await raceWithTimeout(Promise.resolve('ok'), 120_000, () => new Error('must not fire')); + expect(refd()).toBeLessThanOrEqual(before); + + before = refd(); + await expect( + raceWithTimeout(Promise.reject(new Error('x')), 120_000, () => new Error('must not fire')), + ).rejects.toThrow('x'); + expect(refd()).toBeLessThanOrEqual(before); + + before = refd(); + await expect( + raceWithTimeout(new Promise(() => {}), 10, () => new Error('hung')), + ).rejects.toThrow('hung'); + expect(refd()).toBeLessThanOrEqual(before); + }); +}); diff --git a/packages/core/src/timeout-guard.ts b/packages/core/src/timeout-guard.ts new file mode 100644 index 0000000000..1d15e38d74 --- /dev/null +++ b/packages/core/src/timeout-guard.ts @@ -0,0 +1,98 @@ +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * The one-shot timeout guard both kernel lifecycle races arm. + * + * A guard is a `setTimeout` plus the promise a `Promise.race` holds a reaction + * on. Reclaiming it after the race is decided therefore has TWO halves, and + * the kernel used to do exactly one of them at each site — a different one: + * + * - `raceStartupTimeout` cleared the timer and left the promise pending. + * - `shutdown()` `unref()`d the timer, never cleared it, and also left the + * promise pending. + * + * Clearing the timer reclaims the TIMER. It does not settle the PROMISE: the + * race attached `then(resolve, reject)` to that participant when it started, + * and a promise that never settles keeps both itself and that reaction alive + * for as long as anything can reach them. That is what + * `vitest --detectAsyncLeaks` reports as a leaking PROMISE — two frames per + * site, one for the guard promise and one for the race's reaction on it + * (#10604). So `reclaim()` clears the timer AND settles the promise. + * + * ⛔ The guard is deliberately NOT `unref()`ed at arm time (#4813). An unref'd + * guard also stops pinning the event loop, but it stops being a guard as well: + * if the operation never settles and nothing else keeps the loop alive, Node + * exits before the timer can fire and the timeout is never reported. The guard + * has to stay ref'd exactly as long as the race is undecided — which is what + * clearing on settle expresses and what `unref()` cannot. `unref()` is the + * failure mode this class exists to prevent, not a second belt to add. + */ +export class TimeoutGuard { + private timer: ReturnType | undefined; + + /** + * Settles `expiry` without a value. `Promise` has no resolvable + * value in the type system, but settling it is the entire point: it is + * only ever called from `reclaim()`, i.e. after the race it guarded has + * already been decided, so the resolution is discarded by construction and + * can never become a race winner. The cast localises that argument here + * rather than pushing a lie into every caller's return type. + */ + private settleExpiry: () => void = () => {}; + + /** + * The racing participant. Rejects with the caller's error when the guard + * expires; resolves — settles, harmlessly — once `reclaim()` runs. + */ + readonly expiry: Promise; + + constructor(timeoutMs: number, createTimeoutError: () => Error) { + this.expiry = new Promise((resolve, reject) => { + this.settleExpiry = resolve as unknown as () => void; + this.timer = setTimeout(() => reject(createTimeoutError()), timeoutMs); + }); + } + + /** + * Reclaim the guard once the race it protects has been decided. Both + * halves, always: the timer is cleared so it cannot fire against a + * lifecycle phase that is already over, and `expiry` is settled so neither + * it nor the race's reaction on it is retained. + * + * Idempotent — `clearTimeout` on a cleared handle and a second resolve on + * a settled promise are both no-ops. + */ + reclaim(): void { + clearTimeout(this.timer); + this.timer = undefined; + this.settleExpiry(); + } +} + +/** + * Race `operation` against a startup/shutdown timeout guard, reclaiming the + * guard the moment the race settles — whichever side won. + * + * `operation` is widened to `T | PromiseLike` because the Plugin contract + * permits a synchronous hook (`init`/`start` return `void | Promise`); + * such a hook wins the race immediately and the guard is reclaimed on the same + * turn. + * + * `createTimeoutError` is a factory rather than an `Error` so a caller that + * discriminates the timeout by IDENTITY (`shutdown()`, #5274) can hand back + * its own pre-built instance, while callers that only need a message pay for + * the `Error` — and its stack — only when the guard actually fires. + */ +export async function raceWithTimeout( + operation: T | PromiseLike, + timeoutMs: number, + createTimeoutError: () => Error, +): Promise { + const guard = new TimeoutGuard(timeoutMs, createTimeoutError); + + try { + return await Promise.race([operation, guard.expiry]); + } finally { + guard.reclaim(); + } +}