From 9746fc08c82f2b65482f2da70f25db95dd0ae0d5 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 3 Aug 2026 17:02:40 +0000 Subject: [PATCH] fix(core): clear the health-check timeout guard when the race settles (#4875) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `PluginHealthMonitor.performHealthCheck()` armed its timeout guard via the private `timeout()` helper and then abandoned it: when the plugin's `checkMethod` won the race, the `setTimeout` stayed ref'd in the event loop for the full `config.timeout`. Same leak as the kernel's init/start guards (#4813, PR #4874), with one aggravating difference — health checks are periodic, so the orphans accumulate one per plugin per round instead of being a fixed cost paid once at boot. Replaces `timeout()` with `raceCheckTimeout()`, the same shape and the same reasoning as `ObjectKernel.raceStartupTimeout()`: `try { await Promise.race(...) } finally { clearTimeout(guard) }`. Not `unref()` — an unref'd guard stops pinning the loop but also stops being a guard, so a check that never settles is silently dropped instead of reported. Regression tests: no ref'd timer survives a check that wins the race, no guard accumulates across periodic rounds (counted under fake timers, which also sees an `unref()`'d timer and so rejects a fake fix), and the timeout is still reported when the check genuinely hangs. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01NrmBxj8rK2uGCnh9aipjwX --- .../health-monitor-timeout-guard-cleared.md | 28 ++++ packages/core/src/health-monitor.test.ts | 142 +++++++++++++++++- packages/core/src/health-monitor.ts | 48 +++++- 3 files changed, 209 insertions(+), 9 deletions(-) create mode 100644 .changeset/health-monitor-timeout-guard-cleared.md diff --git a/.changeset/health-monitor-timeout-guard-cleared.md b/.changeset/health-monitor-timeout-guard-cleared.md new file mode 100644 index 0000000000..24e44c10e2 --- /dev/null +++ b/.changeset/health-monitor-timeout-guard-cleared.md @@ -0,0 +1,28 @@ +--- +'@objectstack/core': patch +--- + +fix(core): 健康检查的超时守卫在 race 落定时被清除,周期性检查不再堆积孤儿定时器 (#4875) + +`PluginHealthMonitor.performHealthCheck()` 里那条 race 的守卫由 `timeout()` armed 之后就被 +扔掉:插件的 `checkMethod` 赢下 race 之后,那根 `setTimeout` 既没 `clearTimeout` 也没 +`unref()`,带着 ref 一直挂满整个 `config.timeout`。这与 #4813 修掉的两处(内核 init/start +守卫,PR #4874)是同一种漏法。 + +差别在于**健康检查是周期性的**:内核那两处是启动时一次性的固定份额(4 个插件 = 8 根),这里 +则是**每个插件每一轮各留一根**,`interval` 越密、`timeout` 越长,堆得越高 —— 一个 +`interval: 30s` / `timeout: 5s` 的插件在任意时刻都挂着若干根本该在毫秒级就回收的定时器。 +今天这条还没发作,只是因为 `startMonitoring()` 目前没有被内核启动流程调用;一旦健康监控被接进 +宿主,它就是 #4813 的放大版。 + +修法与 #4874 同形:`timeout()` 换成私有 helper `raceCheckTimeout()`,`try { await +Promise.race(...) } finally { clearTimeout(guard) }`。 + +**为什么是 `clearTimeout` 而不是 `unref()`。** `unref()` 让定时器不再钉住事件循环的同时, +也让它不再是一个守卫 —— 若检查永不 settle 且没有别的东西撑着事件循环,Node 会在定时器触发 +之前退出,超时被静默吞掉。守卫必须在 race 未决期间保持 ref'd、在落定那一刻被回收,这正是 +`finally { clearTimeout(guard) }` 表达的语义。回归测试因此是三条:守卫赢不了时不留 ref'd +定时器、连跑多轮不累积(fake timers 下计数,能识破 `unref()` 式的假修复)、以及检查真的挂住时 +超时照常上报。 + +超时时长(`config.timeout`)一个都没动 —— 问题从来不在时长,而在没人回收。 diff --git a/packages/core/src/health-monitor.test.ts b/packages/core/src/health-monitor.test.ts index 59b12049d4..cc3399a373 100644 --- a/packages/core/src/health-monitor.test.ts +++ b/packages/core/src/health-monitor.test.ts @@ -1,6 +1,7 @@ -import { describe, it, expect, beforeEach } from 'vitest'; +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; import { PluginHealthMonitor } from './health-monitor.js'; import { createLogger } from './logger.js'; +import type { Plugin } from './types.js'; import type { PluginHealthCheck } from '@objectstack/spec/kernel'; describe('PluginHealthMonitor', () => { @@ -75,7 +76,144 @@ describe('PluginHealthMonitor', () => { monitor.registerPlugin('test-plugin', config); monitor.shutdown(); - + expect(monitor.getAllHealthStatuses().size).toBe(0); }); + + // #4875 — the health-check timeout guard must not outlive the race it guards. + // + // Same shape as the kernel's startup guards (#4813, PR #4874), with one + // aggravating difference: health checks are *periodic*, so an abandoned + // guard is not a fixed cost paid once at boot — it is one orphaned timer per + // plugin per round, each pinning the event loop for a whole `config.timeout`. + // + // What follows asserts the observable consequence, never the source: + // "health-monitor.ts calls clearTimeout" is a tautology any refactor could + // satisfy while still leaving the loop pinned. + describe('Health-check timeout guard does not outlive the race (#4875)', () => { + /** A guard long enough that a single orphan is unmistakable. */ + const guardedConfig = (overrides: Partial = {}): PluginHealthCheck => ({ + interval: 30_000, + timeout: 120_000, + failureThreshold: 3, + successThreshold: 1, + autoRestart: false, + maxRestartAttempts: 3, + restartBackoff: 'fixed', + checkMethod: 'healthCheck', + ...overrides, + }); + + /** A plugin whose custom health check answers immediately (wins the race). */ + const healthyPlugin = (calls: { count: number }): Plugin => + ({ + name: 'guarded-plugin', + version: '1.0.0', + init: () => {}, + healthCheck: async () => { + calls.count++; + return true; + }, + }) 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. + */ + const refdTimers = () => + process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length; + + it("leaves no ref'd timer behind when the health check wins the race", async () => { + const calls = { count: 0 }; + monitor.registerPlugin('guarded-plugin', guardedConfig()); + + const before = refdTimers(); + monitor.startMonitoring('guarded-plugin', healthyPlugin(calls)); + + // The initial check runs immediately; wait for its report to land. + await vi.waitFor(() => { + expect(monitor.getHealthReport('guarded-plugin')).toBeDefined(); + }); + + // Drop the monitoring interval — whatever is left is the guard's doing. + monitor.stopMonitoring('guarded-plugin'); + + expect(calls.count).toBe(1); + expect(monitor.getHealthStatus('guarded-plugin')).toBe('healthy'); + expect(refdTimers()).toBe(before); + }); + + it('still reports the timeout when the check never answers', async () => { + // The companion assertion: reclaiming the guard must not disarm it. + // `unref()` would satisfy "no ref'd timer" by detaching the guard from + // the loop — a process with nothing else to run then exits *silently* + // instead of reporting the timeout. Clearing on settle keeps the guard + // armed exactly while the race is undecided. + let release: () => void = () => {}; + const hangingPlugin = { + name: 'hanging-plugin', + version: '1.0.0', + init: () => {}, + healthCheck: () => + new Promise((resolve) => { + release = () => resolve(true); + }), + } as unknown as Plugin; + + monitor.registerPlugin('hanging-plugin', guardedConfig({ timeout: 100 })); + monitor.startMonitoring('hanging-plugin', hangingPlugin); + + await vi.waitFor(() => { + expect(monitor.getHealthStatus('hanging-plugin')).toBe('failed'); + }); + + expect(monitor.getHealthReport('hanging-plugin')?.message).toBe( + 'Health check timeout after 100ms' + ); + + monitor.stopMonitoring('hanging-plugin'); + release(); + }); + + describe('under fake timers', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it('accumulates no guard across periodic rounds', async () => { + const calls = { count: 0 }; + const config = guardedConfig({ interval: 1_000 }); + monitor.registerPlugin('guarded-plugin', config); + + const before = vi.getTimerCount(); + monitor.startMonitoring('guarded-plugin', healthyPlugin(calls)); + + // Flush the initial check without letting the interval or the guard fire. + await vi.advanceTimersByTimeAsync(0); + expect(calls.count).toBe(1); + + // Unlike `getActiveResourcesInfo()`, the fake-timer count still sees + // an `unref()`'d timer — so this distinguishes "the guard was + // reclaimed" from "the guard was merely detached from the loop". + const settled = vi.getTimerCount(); + expect(settled).toBe(before + 1); // the monitoring interval, and nothing else + + // Periodic checks are where this leak compounds: one orphan per round. + for (let round = 0; round < 5; round++) { + await vi.advanceTimersByTimeAsync(config.interval); + } + + expect(calls.count).toBe(6); + expect(vi.getTimerCount()).toBe(settled); + + monitor.stopMonitoring('guarded-plugin'); + expect(vi.getTimerCount()).toBe(before); + }); + }); + }); }); diff --git a/packages/core/src/health-monitor.ts b/packages/core/src/health-monitor.ts index d546ddd683..59d8945e03 100644 --- a/packages/core/src/health-monitor.ts +++ b/packages/core/src/health-monitor.ts @@ -107,10 +107,11 @@ export class PluginHealthMonitor { try { // Check if plugin has a custom health check method if (config.checkMethod && typeof (plugin as any)[config.checkMethod] === 'function') { - const checkResult = await Promise.race([ + const checkResult = await this.raceCheckTimeout( (plugin as any)[config.checkMethod](), - this.timeout(config.timeout, `Health check timeout after ${config.timeout}ms`) - ]); + config.timeout, + `Health check timeout after ${config.timeout}ms` + ); if (checkResult === false || (checkResult && checkResult.status === 'unhealthy')) { status = 'unhealthy'; @@ -308,11 +309,44 @@ export class PluginHealthMonitor { } /** - * Timeout helper + * Race a plugin's custom health check against its timeout guard, and + * reclaim the guard the moment the race settles (#4875). + * + * Same shape, same reasoning as `ObjectKernel.raceStartupTimeout()` (#4813, + * PR #4874): the guard used to be armed and then abandoned — when the check + * won the race, its `setTimeout` stayed ref'd in the event loop for the full + * `config.timeout`. Health checks are *periodic*, so unlike the kernel's + * one-shot startup guards the orphans here accumulate: one per plugin per + * round, each pinning the loop for `config.timeout`. + * + * Clearing on settle rather than `unref()`-ing at arm time is deliberate. + * An unref'd guard also stops pinning the loop, but it stops being a guard + * as well: if the check 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. + * + * `check` is widened to `T | PromiseLike` because `checkMethod` is called + * dynamically off the plugin and may be synchronous; such a check wins the + * race immediately and the guard is reclaimed on the same turn. */ - private timeout(ms: number, message: string): Promise { - return new Promise((_, reject) => { - setTimeout(() => reject(new Error(message)), ms); + private async raceCheckTimeout( + check: T | PromiseLike, + ms: number, + message: string + ): Promise { + let guard: ReturnType | undefined; + + const timeoutPromise = new Promise((_, reject) => { + guard = setTimeout(() => { + reject(new Error(message)); + }, ms); }); + + try { + return await Promise.race([check, timeoutPromise]); + } finally { + clearTimeout(guard); + } } }