Skip to content

test(core): measure ref'd-timer leaks on the subject's own handles, not on the process#10786

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
os-zhuang merged 1 commit into from
Aug 21, 2026
Merged

test(core): measure ref'd-timer leaks on the subject's own handles, not on the process #10786

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
74 changes: 18 additions & 56 deletions packages/core/src/health-monitor.test.ts
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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;
Expand DownExpand Up@@ -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<void>
): Promise<NodeJS.Timeout[]> => {
const guards: NodeJS.Timeout[] = [];
const real = globalThis.setTimeout;
const recording = ((...args: Parameters<typeof globalThis.setTimeout>) => {
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.
Expand All@@ -193,23 +156,22 @@ 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);

// 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 () => {
Expand Down
41 changes: 23 additions & 18 deletions packages/core/src/hot-reload.test.ts
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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 {
Expand DownExpand Up@@ -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 = {
Expand All@@ -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 () => {
Expand Down
45 changes: 26 additions & 19 deletions packages/core/src/kernel.test.ts
View file
Open in desktop
Original file line numberDiff line numberDiff line change
Expand Up@@ -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;
Expand DownExpand Up@@ -240,34 +241,36 @@ 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 = {
name: 'fast-plugin-long-guard',
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();
});
Expand All@@ -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();
});
Expand Down
Loading
Loading