From e303311cdf629f5a65d2370b26b1c0ef15a79081 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 21 Aug 2026 11:22:03 +0000 Subject: [PATCH] test(core): measure ref'd-timer leaks on the subject's own handles MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Four core pins counted ref'd timers with a PROCESS-global probe (`process.getActiveResourcesInfo().filter(r => r === 'Timeout').length`) and scored a subject against the absolute value. A `Test Core` shard runs ~37 core files in one worker, so that value is ambient: it belongs to every co-tenant file, not to the test reading it. Scoring it with `toBe` is sound only while the window crosses no event-loop turn. `health-monitor.test.ts` said so and held itself to it. Three others relied on the same property silently, with an `await` inside the measured window — green only because the plugin hooks they awaited settle on microtasks, a property of code they do not own and written down nowhere. Add a retry backoff to `bootstrap()` or a debounce to `reloadPlugin()` and the pins go intermittently red, pointing at the timer count instead of at the change. Rather than loosen the comparison, name the guards. The new `refd-timer-probe.testkit.ts` records the `Timeout` handles the subject arms (told apart by the timeout they were configured with) and reports how many are still holding the loop open — `stillPinningTheLoop()`, deliberately synchronous, so the invariant is structural instead of a comment. Every site now also pins how many guards were armed, which the absolute count could never distinguish from "nothing was measured". Refs #10685 --- packages/core/src/health-monitor.test.ts | 74 +++------ packages/core/src/hot-reload.test.ts | 41 ++--- packages/core/src/kernel.test.ts | 45 +++--- packages/core/src/refd-timer-probe.testkit.ts | 150 ++++++++++++++++++ 4 files changed, 217 insertions(+), 93 deletions(-) create mode 100644 packages/core/src/refd-timer-probe.testkit.ts diff --git a/packages/core/src/health-monitor.test.ts b/packages/core/src/health-monitor.test.ts index a69fd0e4dc..94b2c22f14 100644 --- a/packages/core/src/health-monitor.test.ts +++ b/packages/core/src/health-monitor.test.ts @@ -3,6 +3,11 @@ import { PluginHealthMonitor } from './health-monitor.js'; import { createLogger } from './logger.js'; import type { Plugin } from './types.js'; import type { PluginHealthCheckParsed } from '@objectstack/spec/kernel'; +import { + recordGuards, + refdTimeouts, + stillPinningTheLoop, +} from './refd-timer-probe.testkit.js'; describe('PluginHealthMonitor', () => { let monitor: PluginHealthMonitor; @@ -117,64 +122,22 @@ describe('PluginHealthMonitor', () => { }) as unknown as Plugin; /** - * Ref'd `Timeout` handles — `getActiveResourcesInfo()` reports only - * resources currently keeping the event loop alive, which is exactly the - * property that made `os migrate` idle ~120s in #4813. - * - * The count is *process*-global, so it is only ever read here in - * synchronously adjacent pairs (see below). Comparing two reads separated - * by an `await` is what made this suite flaky in the merge queue (#6329): - * the runner shares this loop and keeps a **non-unref'd 100ms** timer on it - * (`throttle(sendTasksUpdate, 100)` in `@vitest/runner`), so once the - * window between the reads stretched past 100ms under full concurrent load - * — the failing run measured 105ms — that timer fired inside the window and - * the count fell by one for a reason that had nothing to do with the - * monitor. Between two adjacent synchronous statements no timer callback - * can run at all, so a difference measured that way is the monitor's doing - * and nobody else's. + * The instrument these pins measure with lives in + * `refd-timer-probe.testkit.ts`, together with the argument for its shape: + * `getActiveResourcesInfo()` is PROCESS-global, so two readings are only + * comparable across a window that crosses no event-loop turn — the very + * property this suite states below and the one three sibling pins were + * relying on without saying so (#10685). `stillPinningTheLoop()` is the + * synchronous form of that window; `refdTimeouts()` is the raw reading, + * used here only in synchronously adjacent pairs. */ - const refdTimers = () => - process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length; - - /** - * Run `body` while recording the `Timeout` handles `setTimeout` hands out, - * and return those armed with `delay` — the monitor's health-check guards, - * told apart from every other timer on the shared loop by the very timeout - * they were configured with. - * - * Holding the handles is what lets the assertion below name the guard - * instead of counting the world. It records where the guard came from; what - * it then asserts is still the observable consequence — whether that handle - * is keeping the event loop alive — never that `clearTimeout` was called. - */ - const recordingGuards = async ( - delay: number, - body: () => Promise - ): Promise => { - const guards: NodeJS.Timeout[] = []; - const real = globalThis.setTimeout; - const recording = ((...args: Parameters) => { - const handle = real(...args); - if (args[1] === delay) guards.push(handle); - return handle; - }) as typeof globalThis.setTimeout; - Object.assign(recording, real); - - globalThis.setTimeout = recording; - try { - await body(); - } finally { - globalThis.setTimeout = real; - } - return guards; - }; it("leaves no ref'd timer behind when the health check wins the race", async () => { const calls = { count: 0 }; const config = guardedConfig(); monitor.registerPlugin('guarded-plugin', config); - const guards = await recordingGuards(config.timeout, async () => { + const guards = await recordGuards(config.timeout, async () => { monitor.startMonitoring('guarded-plugin', healthyPlugin(calls)); // The initial check runs immediately; wait for its report to land. @@ -193,14 +156,14 @@ describe('PluginHealthMonitor', () => { // Everything from here to the last assertion runs in one uninterrupted // synchronous turn, so each difference is attributable. - const whileMonitoring = refdTimers(); + const whileMonitoring = refdTimeouts(); // Drop the monitoring interval — whatever is left is the guard's doing. monitor.stopMonitoring('guarded-plugin'); - const afterStop = refdTimers(); + const afterStop = refdTimeouts(); // The interval was pinning the loop and is now reclaimed. This also keeps - // the instrument honest: `refdTimers()` demonstrably observes *this* + // the instrument honest: `refdTimeouts()` demonstrably observes *this* // monitor's timers on *this* loop, so the guard's zero below is a real // reading and not a blind one. expect(whileMonitoring - afterStop).toBe(1); @@ -208,8 +171,7 @@ describe('PluginHealthMonitor', () => { // The guard is not pinning the loop: reclaiming it a second time is a // no-op. Had it outlived the race it would still be armed and ref'd, and // this reclaim would drop the count by one. - for (const guard of guards) clearTimeout(guard); - expect(refdTimers()).toBe(afterStop); + expect(stillPinningTheLoop(guards)).toBe(0); }); it('still reports the timeout when the check never answers', async () => { diff --git a/packages/core/src/hot-reload.test.ts b/packages/core/src/hot-reload.test.ts index bf6b5b95ed..ea0db7d03d 100644 --- a/packages/core/src/hot-reload.test.ts +++ b/packages/core/src/hot-reload.test.ts @@ -5,6 +5,7 @@ import { HotReloadManager } from './hot-reload.js'; import type { ObjectLogger } from './logger.js'; import type { Plugin } from './types.js'; import type { HotReloadConfigParsed } from '@objectstack/spec/kernel'; +import { recordGuards, stillPinningTheLoop } from './refd-timer-probe.testkit.js'; /** Records `error` reports; every other level is dropped. `child()` is self. */ function createRecordingLogger(errors: { message: string; error?: unknown }[]): ObjectLogger { @@ -57,13 +58,6 @@ describe('HotReloadManager', () => { const noState = () => ({}); const noRestore = () => {}; - /** - * Ref'd `Timeout` handles — `getActiveResourcesInfo()` reports only - * resources currently keeping the event loop alive, which is exactly the - * property that made `os migrate` idle ~120s in #4813. - */ - const refdTimers = () => process.getActiveResourcesInfo().filter(r => r === 'Timeout').length; - it("leaves no ref'd timer behind when destroy() wins the race", async () => { const calls = { count: 0 }; const plugin = { @@ -75,20 +69,31 @@ describe('HotReloadManager', () => { }, } as unknown as Plugin; - manager.registerPlugin('guarded-plugin', guardedConfig()); - - const before = refdTimers(); - const reloaded = await manager.reloadPlugin( - 'guarded-plugin', - plugin, - '1.0.0', - noState, - noRestore - ); + const config = guardedConfig(); + manager.registerPlugin('guarded-plugin', config); + + // The guard is named by the timeout it was armed with rather than + // counted out of the process — `refd-timer-probe.testkit.ts` explains + // why `reloadPlugin()`'s `await` makes an absolute count unsound (#10685). + let reloaded = false; + const guards = await recordGuards(config.shutdownTimeout, async () => { + reloaded = await manager.reloadPlugin( + 'guarded-plugin', + plugin, + '1.0.0', + noState, + noRestore + ); + }); expect(reloaded).toBe(true); expect(calls.count).toBe(1); - expect(refdTimers()).toBe(before); + + // The reload armed exactly one shutdown guard. Without this the reclaim + // below would be vacuously green — a zero because nothing was measured, + // rather than because nothing was left behind. + expect(guards).toHaveLength(1); + expect(stillPinningTheLoop(guards)).toBe(0); }); it('still reports the timeout when destroy() never answers', async () => { diff --git a/packages/core/src/kernel.test.ts b/packages/core/src/kernel.test.ts index aed124f760..a638cfcca4 100644 --- a/packages/core/src/kernel.test.ts +++ b/packages/core/src/kernel.test.ts @@ -2,6 +2,7 @@ import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; import { ObjectKernel } from './kernel'; import { ServiceLifecycle, PluginMetadata } from './plugin-loader'; import type { Plugin, PluginContext } from './types'; +import { recordGuards, stillPinningTheLoop } from './refd-timer-probe.testkit.js'; describe('ObjectKernel', () => { let kernel: ObjectKernel; @@ -240,13 +241,13 @@ describe('ObjectKernel', () => { // guards armed is still holding the loop open. describe('Startup timeout guards do not outlive the race (#4813)', () => { /** - * Ref'd `Timeout` handles — `getActiveResourcesInfo()` reports only - * resources that are *currently keeping the event loop alive*, which - * is precisely the property that made `os migrate` hang ~120s after - * printing `✅ Graceful shutdown complete`. + * The real value that hung one-shot CLI processes: ObjectQLPlugin's. + * It is also what tells these guards apart from every other timer on + * the shared loop — see `refd-timer-probe.testkit.ts`, which explains + * why these pins name their guards instead of counting the process + * (#10685). */ - const refdTimers = () => - process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length; + const STARTUP_TIMEOUT = 120_000; it('leaves no ref\'d timer behind after the plugin wins the race', async () => { const plugin: PluginMetadata = { @@ -254,20 +255,22 @@ describe('ObjectKernel', () => { version: '1.0.0', init: async () => {}, start: async () => {}, - // The real value that hung one-shot CLI processes: ObjectQLPlugin. - startupTimeout: 120_000, + startupTimeout: STARTUP_TIMEOUT, }; await kernel.use(plugin); - const before = refdTimers(); - await kernel.bootstrap(); - const after = refdTimers(); + const guards = await recordGuards(STARTUP_TIMEOUT, () => kernel.bootstrap()); // Two guards were armed (init + start) and both lost their race. + // Pinning the arming keeps the reclaim assertion from passing + // vacuously — a zero because nothing was measured rather than + // because nothing was left behind. + expect(guards).toHaveLength(2); + // While either is still ref'd the process cannot exit for up to // `startupTimeout` — 120s of idling after a 3s job. - expect(after).toBe(before); + expect(stillPinningTheLoop(guards)).toBe(0); await kernel.shutdown(); }); @@ -278,20 +281,24 @@ describe('ObjectKernel', () => { version: '1.0.0', init: async () => {}, start: async () => {}, - startupTimeout: 120_000, + startupTimeout: STARTUP_TIMEOUT, }); for (let n = 0; n < 4; n++) { await kernel.use(makePlugin(n)); } - const before = refdTimers(); - await kernel.bootstrap(); + const guards = await recordGuards(STARTUP_TIMEOUT, () => kernel.bootstrap()); + + // The issue's probe caught exactly this shape: 8 ref'd Timeouts for + // 4 plugins (4 init + 4 start). One guard per hook is what the + // kernel is SUPPOSED to arm — asserting the arming scales is what + // makes the reclaim below mean anything for the fourth plugin. + expect(guards).toHaveLength(8); - // The issue's probe caught exactly this shape: 8 ref'd Timeouts - // for 4 plugins (4 init + 4 start). The count must not scale with - // the plugin list — it must not grow at all. - expect(refdTimers()).toBe(before); + // What must not scale with the plugin list is what survives the + // race: not one of the eight is still holding the loop open. + expect(stillPinningTheLoop(guards)).toBe(0); await kernel.shutdown(); }); diff --git a/packages/core/src/refd-timer-probe.testkit.ts b/packages/core/src/refd-timer-probe.testkit.ts new file mode 100644 index 0000000000..a8cc03c9c1 --- /dev/null +++ b/packages/core/src/refd-timer-probe.testkit.ts @@ -0,0 +1,150 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * The instrument the ref'd-timer leak pins measure with (#4813, #4952, #10604, + * #10685) — subject-scoped, so a co-tenant test file cannot move the reading. + * + * ## Why the obvious probe is not enough + * + * `process.getActiveResourcesInfo()` reports the WHOLE process, and a + * `Test Core` CI shard runs ~37 core test files in one worker. So the absolute + * `'Timeout'` count is AMBIENT: it belongs to every co-tenant file, not to the + * test reading it. Scoring a subject against it — + * + * ```ts + * const before = refdTimeouts(); + * await subject(); // ⛔ anything can happen in here + * expect(refdTimeouts()).toBe(before); + * ``` + * + * — is sound only while nothing else can move the count between the two + * samples, i.e. only when the window crosses no event-loop turn: timer + * callbacks run in the timers phase and a microtask drain never reaches it. + * Three pins depended on that silently (#10685) and passed only because the + * hooks they awaited happened to settle on microtasks — a property of code + * they did not own. `timeout-guard.test.ts`'s fourth pin had the same shape + * plus a leg that spends real time on the loop, and CI duly reddened it with + * `expected 2 to be 4`: two FOREIGN timers expired mid-test and pulled the + * reading DOWN, with a failure message pointing at the timer count rather than + * at anything the test was about. + * + * Co-tenant test files are not the only foreign source. The runner shares this + * loop too and keeps a **non-unref'd 100ms** timer on it + * (`throttle(sendTasksUpdate, 100)` in `@vitest/runner`), which is what made + * the health-monitor suite flaky in the merge queue (#6329): once the window + * between two reads stretched past 100ms under full concurrent load — the + * failing run measured 105ms — that timer fired inside the window and the + * count fell by one for a reason that had nothing to do with the subject. So + * "this file runs alone" is not a defence either. + * + * ## What this module does instead + * + * Name the guards, then ask about those handles only: + * + * ```ts + * const guards = await recordGuards(120_000, () => kernel.bootstrap()); + * expect(guards).toHaveLength(2); // the guards were really armed + * expect(stillPinningTheLoop(guards)).toBe(0); // and none outlived its race + * ``` + * + * `recordGuards` captures the `Timeout` handles the subject arms, told apart + * from every other timer on the shared loop by the very timeout they were + * configured with. `stillPinningTheLoop` then reports how many of THOSE are + * still holding the loop open — and it is deliberately a **synchronous** + * function, which is what makes the invariant structural instead of a comment: + * its two samples are adjacent statements, no `await` can be inserted between + * them without turning it into a different (and visibly `async`) function, and + * between two adjacent synchronous statements no timer callback can run at + * all. The ambient value cancels; what survives is the subject's own delta. + * + * ⛔ Do not "fix" the ambience by isolating a file or pinning the shard layout + * instead: that would make a pin's validity a property of the runner config + * rather than of its own assertion. + * + * `.testkit.ts`, not `.test.ts`: it holds no assertions and must not be + * collected as a suite. It is imported only by tests, so tsup (entries + * `src/index.ts` and `src/logger.ts`) never bundles it into `dist`. + * + * ⚠️ Real timers only. Under `vi.useFakeTimers()` the handles are fakes and + * `getActiveResourcesInfo()` cannot see them — use `vi.getTimerCount()` there, + * which is the complementary pin (it counts `unref()`'d timers too, so it tells + * "the guard was reclaimed" apart from "the guard was merely detached from the + * loop"). + */ + +/** + * Ref'd `Timeout` handles currently keeping THIS PROCESS's event loop alive — + * an ambient, process-global reading. + * + * ⚠️ Only ever compare two of these across a window that contains no `await` + * (see the module docblock). If you are about to write `const before = …` and + * then `await` something, you want {@link recordGuards} plus + * {@link stillPinningTheLoop} instead. + */ +export const refdTimeouts = (): number => + process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length; + +/** + * Run `body` while capturing the `Timeout` handles `setTimeout` hands out with + * exactly `delay` ms — the subject's guards, identified by the timeout they + * were configured with rather than by counting the world. + * + * The interception is installed around `body` only and restored in a `finally`, + * so a throwing subject cannot leave a patched global behind for the next test. + */ +export async function recordGuards( + delay: number, + body: () => Promise | unknown +): Promise { + const guards: NodeJS.Timeout[] = []; + const real = globalThis.setTimeout; + + const recording = ((...args: Parameters) => { + const handle = real(...args); + if (args[1] === delay) guards.push(handle); + return handle; + }) as typeof globalThis.setTimeout; + // Carry `setTimeout.__promisify__` & friends over, so anything reaching for + // them through the global while `body` runs still finds them. + Object.assign(recording, real); + + globalThis.setTimeout = recording; + try { + await body(); + } finally { + globalThis.setTimeout = real; + } + + return guards; +} + +/** + * How many of `handles` are STILL armed and pinning the event loop — the leak, + * measured on the subject's own handles and on nothing else. + * + * `clearTimeout` on a handle that was already reclaimed is a no-op, so the + * count only drops for a guard that really did outlive its race. Both samples + * are adjacent synchronous statements: no timer callback can run between them, + * so the ambient count cancels exactly and the difference is the subject's. + * + * ⚠️ Destructive by design — it reclaims whatever was still armed. Call it once, + * at the point where the guards are supposed to be gone already. + * + * Throws on an empty `handles`, because "nothing was armed" and "nothing was + * left behind" are different facts and a zero must never stand for both: the + * caller that recorded no guards has a broken instrument (wrong `delay`, or a + * subject that never armed one), not a clean subject. + */ +export function stillPinningTheLoop(handles: readonly NodeJS.Timeout[]): number { + if (handles.length === 0) { + throw new Error( + 'stillPinningTheLoop() got no handles: recordGuards() captured nothing, ' + + 'so this measurement would be vacuously 0. Check the `delay` it filters ' + + 'on still matches the timeout the subject arms its guard with.' + ); + } + + const before = refdTimeouts(); + for (const handle of handles) clearTimeout(handle); + return before - refdTimeouts(); +}