Skip to content

Commit f4e5d91

Browse files
claude[bot]claude
andauthored
test(core): measure ref'd-timer leaks on the subject's own handles (#10786)
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 Co-authored-by: Claude <noreply@anthropic.com>
1 parent 4fef302 commit f4e5d91

4 files changed

Lines changed: 217 additions & 93 deletions

File tree

packages/core/src/health-monitor.test.ts

Lines changed: 18 additions & 56 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,11 @@ import { PluginHealthMonitor } from './health-monitor.js';
33
import { createLogger } from './logger.js';
44
import type { Plugin } from './types.js';
55
import type { PluginHealthCheckParsed } from '@objectstack/spec/kernel';
6+
import {
7+
recordGuards,
8+
refdTimeouts,
9+
stillPinningTheLoop,
10+
} from './refd-timer-probe.testkit.js';
611

712
describe('PluginHealthMonitor', () => {
813
let monitor: PluginHealthMonitor;
@@ -117,64 +122,22 @@ describe('PluginHealthMonitor', () => {
117122
}) as unknown as Plugin;
118123

119124
/**
120-
* Ref'd `Timeout` handles — `getActiveResourcesInfo()` reports only
121-
* resources currently keeping the event loop alive, which is exactly the
122-
* property that made `os migrate` idle ~120s in #4813.
123-
*
124-
* The count is *process*-global, so it is only ever read here in
125-
* synchronously adjacent pairs (see below). Comparing two reads separated
126-
* by an `await` is what made this suite flaky in the merge queue (#6329):
127-
* the runner shares this loop and keeps a **non-unref'd 100ms** timer on it
128-
* (`throttle(sendTasksUpdate, 100)` in `@vitest/runner`), so once the
129-
* window between the reads stretched past 100ms under full concurrent load
130-
* — the failing run measured 105ms — that timer fired inside the window and
131-
* the count fell by one for a reason that had nothing to do with the
132-
* monitor. Between two adjacent synchronous statements no timer callback
133-
* can run at all, so a difference measured that way is the monitor's doing
134-
* and nobody else's.
125+
* The instrument these pins measure with lives in
126+
* `refd-timer-probe.testkit.ts`, together with the argument for its shape:
127+
* `getActiveResourcesInfo()` is PROCESS-global, so two readings are only
128+
* comparable across a window that crosses no event-loop turn — the very
129+
* property this suite states below and the one three sibling pins were
130+
* relying on without saying so (#10685). `stillPinningTheLoop()` is the
131+
* synchronous form of that window; `refdTimeouts()` is the raw reading,
132+
* used here only in synchronously adjacent pairs.
135133
*/
136-
const refdTimers = () =>
137-
process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length;
138-
139-
/**
140-
* Run `body` while recording the `Timeout` handles `setTimeout` hands out,
141-
* and return those armed with `delay` — the monitor's health-check guards,
142-
* told apart from every other timer on the shared loop by the very timeout
143-
* they were configured with.
144-
*
145-
* Holding the handles is what lets the assertion below name the guard
146-
* instead of counting the world. It records where the guard came from; what
147-
* it then asserts is still the observable consequence — whether that handle
148-
* is keeping the event loop alive — never that `clearTimeout` was called.
149-
*/
150-
const recordingGuards = async (
151-
delay: number,
152-
body: () => Promise<void>
153-
): Promise<NodeJS.Timeout[]> => {
154-
const guards: NodeJS.Timeout[] = [];
155-
const real = globalThis.setTimeout;
156-
const recording = ((...args: Parameters<typeof globalThis.setTimeout>) => {
157-
const handle = real(...args);
158-
if (args[1] === delay) guards.push(handle);
159-
return handle;
160-
}) as typeof globalThis.setTimeout;
161-
Object.assign(recording, real);
162-
163-
globalThis.setTimeout = recording;
164-
try {
165-
await body();
166-
} finally {
167-
globalThis.setTimeout = real;
168-
}
169-
return guards;
170-
};
171134

172135
it("leaves no ref'd timer behind when the health check wins the race", async () => {
173136
const calls = { count: 0 };
174137
const config = guardedConfig();
175138
monitor.registerPlugin('guarded-plugin', config);
176139

177-
const guards = await recordingGuards(config.timeout, async () => {
140+
const guards = await recordGuards(config.timeout, async () => {
178141
monitor.startMonitoring('guarded-plugin', healthyPlugin(calls));
179142

180143
// The initial check runs immediately; wait for its report to land.
@@ -193,23 +156,22 @@ describe('PluginHealthMonitor', () => {
193156

194157
// Everything from here to the last assertion runs in one uninterrupted
195158
// synchronous turn, so each difference is attributable.
196-
const whileMonitoring = refdTimers();
159+
const whileMonitoring = refdTimeouts();
197160

198161
// Drop the monitoring interval — whatever is left is the guard's doing.
199162
monitor.stopMonitoring('guarded-plugin');
200-
const afterStop = refdTimers();
163+
const afterStop = refdTimeouts();
201164

202165
// The interval was pinning the loop and is now reclaimed. This also keeps
203-
// the instrument honest: `refdTimers()` demonstrably observes *this*
166+
// the instrument honest: `refdTimeouts()` demonstrably observes *this*
204167
// monitor's timers on *this* loop, so the guard's zero below is a real
205168
// reading and not a blind one.
206169
expect(whileMonitoring - afterStop).toBe(1);
207170

208171
// The guard is not pinning the loop: reclaiming it a second time is a
209172
// no-op. Had it outlived the race it would still be armed and ref'd, and
210173
// this reclaim would drop the count by one.
211-
for (const guard of guards) clearTimeout(guard);
212-
expect(refdTimers()).toBe(afterStop);
174+
expect(stillPinningTheLoop(guards)).toBe(0);
213175
});
214176

215177
it('still reports the timeout when the check never answers', async () => {

packages/core/src/hot-reload.test.ts

Lines changed: 23 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import { HotReloadManager } from './hot-reload.js';
55
import type { ObjectLogger } from './logger.js';
66
import type { Plugin } from './types.js';
77
import type { HotReloadConfigParsed } from '@objectstack/spec/kernel';
8+
import { recordGuards, stillPinningTheLoop } from './refd-timer-probe.testkit.js';
89

910
/** Records `error` reports; every other level is dropped. `child()` is self. */
1011
function createRecordingLogger(errors: { message: string; error?: unknown }[]): ObjectLogger {
@@ -57,13 +58,6 @@ describe('HotReloadManager', () => {
5758
const noState = () => ({});
5859
const noRestore = () => {};
5960

60-
/**
61-
* Ref'd `Timeout` handles — `getActiveResourcesInfo()` reports only
62-
* resources currently keeping the event loop alive, which is exactly the
63-
* property that made `os migrate` idle ~120s in #4813.
64-
*/
65-
const refdTimers = () => process.getActiveResourcesInfo().filter(r => r === 'Timeout').length;
66-
6761
it("leaves no ref'd timer behind when destroy() wins the race", async () => {
6862
const calls = { count: 0 };
6963
const plugin = {
@@ -75,20 +69,31 @@ describe('HotReloadManager', () => {
7569
},
7670
} as unknown as Plugin;
7771

78-
manager.registerPlugin('guarded-plugin', guardedConfig());
79-
80-
const before = refdTimers();
81-
const reloaded = await manager.reloadPlugin(
82-
'guarded-plugin',
83-
plugin,
84-
'1.0.0',
85-
noState,
86-
noRestore
87-
);
72+
const config = guardedConfig();
73+
manager.registerPlugin('guarded-plugin', config);
74+
75+
// The guard is named by the timeout it was armed with rather than
76+
// counted out of the process — `refd-timer-probe.testkit.ts` explains
77+
// why `reloadPlugin()`'s `await` makes an absolute count unsound (#10685).
78+
let reloaded = false;
79+
const guards = await recordGuards(config.shutdownTimeout, async () => {
80+
reloaded = await manager.reloadPlugin(
81+
'guarded-plugin',
82+
plugin,
83+
'1.0.0',
84+
noState,
85+
noRestore
86+
);
87+
});
8888

8989
expect(reloaded).toBe(true);
9090
expect(calls.count).toBe(1);
91-
expect(refdTimers()).toBe(before);
91+
92+
// The reload armed exactly one shutdown guard. Without this the reclaim
93+
// below would be vacuously green — a zero because nothing was measured,
94+
// rather than because nothing was left behind.
95+
expect(guards).toHaveLength(1);
96+
expect(stillPinningTheLoop(guards)).toBe(0);
9297
});
9398

9499
it('still reports the timeout when destroy() never answers', async () => {

packages/core/src/kernel.test.ts

Lines changed: 26 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@ import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest';
22
import { ObjectKernel } from './kernel';
33
import { ServiceLifecycle, PluginMetadata } from './plugin-loader';
44
import type { Plugin, PluginContext } from './types';
5+
import { recordGuards, stillPinningTheLoop } from './refd-timer-probe.testkit.js';
56

67
describe('ObjectKernel', () => {
78
let kernel: ObjectKernel;
@@ -240,34 +241,36 @@ describe('ObjectKernel', () => {
240241
// guards armed is still holding the loop open.
241242
describe('Startup timeout guards do not outlive the race (#4813)', () => {
242243
/**
243-
* Ref'd `Timeout` handles — `getActiveResourcesInfo()` reports only
244-
* resources that are *currently keeping the event loop alive*, which
245-
* is precisely the property that made `os migrate` hang ~120s after
246-
* printing `✅ Graceful shutdown complete`.
244+
* The real value that hung one-shot CLI processes: ObjectQLPlugin's.
245+
* It is also what tells these guards apart from every other timer on
246+
* the shared loop — see `refd-timer-probe.testkit.ts`, which explains
247+
* why these pins name their guards instead of counting the process
248+
* (#10685).
247249
*/
248-
const refdTimers = () =>
249-
process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length;
250+
const STARTUP_TIMEOUT = 120_000;
250251

251252
it('leaves no ref\'d timer behind after the plugin wins the race', async () => {
252253
const plugin: PluginMetadata = {
253254
name: 'fast-plugin-long-guard',
254255
version: '1.0.0',
255256
init: async () => {},
256257
start: async () => {},
257-
// The real value that hung one-shot CLI processes: ObjectQLPlugin.
258-
startupTimeout: 120_000,
258+
startupTimeout: STARTUP_TIMEOUT,
259259
};
260260

261261
await kernel.use(plugin);
262262

263-
const before = refdTimers();
264-
await kernel.bootstrap();
265-
const after = refdTimers();
263+
const guards = await recordGuards(STARTUP_TIMEOUT, () => kernel.bootstrap());
266264

267265
// Two guards were armed (init + start) and both lost their race.
266+
// Pinning the arming keeps the reclaim assertion from passing
267+
// vacuously — a zero because nothing was measured rather than
268+
// because nothing was left behind.
269+
expect(guards).toHaveLength(2);
270+
268271
// While either is still ref'd the process cannot exit for up to
269272
// `startupTimeout` — 120s of idling after a 3s job.
270-
expect(after).toBe(before);
273+
expect(stillPinningTheLoop(guards)).toBe(0);
271274

272275
await kernel.shutdown();
273276
});
@@ -278,20 +281,24 @@ describe('ObjectKernel', () => {
278281
version: '1.0.0',
279282
init: async () => {},
280283
start: async () => {},
281-
startupTimeout: 120_000,
284+
startupTimeout: STARTUP_TIMEOUT,
282285
});
283286

284287
for (let n = 0; n < 4; n++) {
285288
await kernel.use(makePlugin(n));
286289
}
287290

288-
const before = refdTimers();
289-
await kernel.bootstrap();
291+
const guards = await recordGuards(STARTUP_TIMEOUT, () => kernel.bootstrap());
292+
293+
// The issue's probe caught exactly this shape: 8 ref'd Timeouts for
294+
// 4 plugins (4 init + 4 start). One guard per hook is what the
295+
// kernel is SUPPOSED to arm — asserting the arming scales is what
296+
// makes the reclaim below mean anything for the fourth plugin.
297+
expect(guards).toHaveLength(8);
290298

291-
// The issue's probe caught exactly this shape: 8 ref'd Timeouts
292-
// for 4 plugins (4 init + 4 start). The count must not scale with
293-
// the plugin list — it must not grow at all.
294-
expect(refdTimers()).toBe(before);
299+
// What must not scale with the plugin list is what survives the
300+
// race: not one of the eight is still holding the loop open.
301+
expect(stillPinningTheLoop(guards)).toBe(0);
295302

296303
await kernel.shutdown();
297304
});

0 commit comments

Comments
 (0)