From a919889405e8c884b38c191c851c91afa6667559 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 3 Aug 2026 11:37:13 +0000 Subject: [PATCH] fix(core): clear the plugin init/start timeout guards when the race settles (#4813) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `initPluginWithTimeout()` and `startPluginWithTimeout()` each armed a `setTimeout` guard and then abandoned it. When the plugin won the race the timer stayed ref'd in the event loop for the full `startupTimeout`, so every process idled that long after its work was finished — 120s for `ObjectQLPlugin`, held open by 8 orphaned guards (4 init + 4 start). Both guards now go through one private `raceStartupTimeout()` helper that clears the timer in a `finally`. Clearing on settle is deliberate rather than `unref()`-ing at arm time: an unref'd guard also stops pinning the loop, but it stops being a guard as well — if the hook never settles and nothing else keeps the loop alive, Node exits before the timer fires and the timeout is silently swallowed. The guard must stay ref'd exactly while the race is undecided. `operation` is typed `T | PromiseLike` because the Plugin contract permits a synchronous hook (`init`/`start` return `void | Promise`). No `startupTimeout` value changed — the problem was never the duration. Measured on examples/app-crm, same build chain, `migrate recorded-by --json`: 122.4s before, 3.1s after. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_015Br2xsJsczFsTR9bvbh2Ny --- .../kernel-startup-timeout-guard-cleared.md | 33 +++++ packages/core/src/kernel.test.ts | 129 +++++++++++++++++- packages/core/src/kernel.ts | 69 +++++++--- 3 files changed, 214 insertions(+), 17 deletions(-) create mode 100644 .changeset/kernel-startup-timeout-guard-cleared.md diff --git a/.changeset/kernel-startup-timeout-guard-cleared.md b/.changeset/kernel-startup-timeout-guard-cleared.md new file mode 100644 index 0000000000..685990fe30 --- /dev/null +++ b/.changeset/kernel-startup-timeout-guard-cleared.md @@ -0,0 +1,33 @@ +--- +'@objectstack/core': patch +--- + +fix(core): 插件 init/start 的超时守卫定时器在 race 结束时被清除,进程不再空转 `startupTimeout` (#4813) + +`ObjectKernel.initPluginWithTimeout()` / `startPluginWithTimeout()` 各自 `setTimeout` armed +一根超时守卫,然后**把它扔了**:插件赢下 race 之后,那根定时器既没 `clearTimeout` 也没 +`unref()`,带着 ref 一直挂到 `startupTimeout` 走完。于是每个进程在活干完之后还要空转整整 +一个 `startupTimeout` —— `ObjectQLPlugin` 是 120 秒。 + +实测(`examples/app-crm`,同一条 `migrate recorded-by --json`,同一个构建链,唯一差别是本 +改动): + +| | 墙钟 | +|:--|:--| +| 修复前 | 122.4s | +| 修复后 | 3.1s | + +JSON 与 `✅ Graceful shutdown complete` 两次都在 ~3 秒出现 —— 后面那 119 秒纯粹是 8 根 +孤儿定时器(4 个 init + 4 个 start)钉着事件循环。`os serve` 里同样漏,只是那里进程本来 +就长命,看不出来。 + +**为什么是 `clearTimeout` 而不是 `unref()`。** 隔壁 `shutdown()` 的守卫用的是 `unref()`, +但那个写法在这里是错的,而且不是风格问题:`unref()` 让定时器不再钉住事件循环,**同时也 +让它不再是一个守卫** —— 若 hook 永不 settle 且没有别的东西撑着事件循环,Node 会在定时器 +触发之前直接退出,超时被**静默吞掉**,谁也不会收到那个 error。守卫必须在 race 未决期间 +保持 ref'd,在 race 落定的那一刻被回收,这正是 `finally { clearTimeout(guard) }` 表达的 +语义。两个守卫合并为一个私有 helper `raceStartupTimeout()`,措辞与理由写在它的 doc +comment 里。 + +`startupTimeout` 的取值一个都没动 —— 慢启动的插件需要那个上限,问题从来不在时长,而在 +没人回收。 diff --git a/packages/core/src/kernel.test.ts b/packages/core/src/kernel.test.ts index 4e0960983f..1f023c5eb9 100644 --- a/packages/core/src/kernel.test.ts +++ b/packages/core/src/kernel.test.ts @@ -1,4 +1,4 @@ -import { describe, it, expect, beforeEach } from 'vitest'; +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; import { ObjectKernel } from './kernel'; import { ServiceLifecycle, PluginMetadata } from './plugin-loader'; import type { Plugin } from './types'; @@ -231,6 +231,133 @@ describe('ObjectKernel', () => { }); }); + // #4813 — the guard timer must not outlive the race it guards. + // + // These tests are about the *process*, not about the source: asserting + // "kernel.ts calls clearTimeout" would be a tautology that any refactor + // could satisfy while still pinning the event loop. What is asserted here + // is the observable consequence — after the work is done, nothing the + // 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`. + */ + const refdTimers = () => + process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length; + + 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, + }; + + await kernel.use(plugin); + + const before = refdTimers(); + await kernel.bootstrap(); + const after = refdTimers(); + + // Two guards were armed (init + start) and both lost their race. + // 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); + + await kernel.shutdown(); + }); + + it('reclaims one guard per lifecycle hook, for every plugin', async () => { + const makePlugin = (n: number): PluginMetadata => ({ + name: `guarded-plugin-${n}`, + version: '1.0.0', + init: async () => {}, + start: async () => {}, + startupTimeout: 120_000, + }); + + for (let n = 0; n < 4; n++) { + await kernel.use(makePlugin(n)); + } + + const before = refdTimers(); + await kernel.bootstrap(); + + // 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); + + await kernel.shutdown(); + }); + + it('still fires the guard when the plugin loses the race', async () => { + // The companion assertion to the two above: reclaiming the guard + // must not disarm it. `unref()` would satisfy "no ref'd timer" by + // detaching the guard from the loop — and 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. + const plugin: PluginMetadata = { + name: 'hanging-plugin', + version: '1.0.0', + init: async () => { + await new Promise((resolve) => setTimeout(resolve, 5000)); + }, + startupTimeout: 50, + }; + + await kernel.use(plugin); + + await expect(kernel.bootstrap()).rejects.toThrow( + 'Plugin hanging-plugin init timeout after 50ms' + ); + }, 1000); + }); + + describe('Startup timeout guards under fake timers (#4813)', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it('schedules no pending timer once bootstrap has settled', async () => { + const kernelWithFakeTimers = new ObjectKernel({ + logger: { level: 'error' }, + gracefulShutdown: false, + skipSystemValidation: true, + }); + + const plugin: PluginMetadata = { + name: 'fake-timer-plugin', + version: '1.0.0', + init: async () => {}, + start: async () => {}, + startupTimeout: 120_000, + }; + + await kernelWithFakeTimers.use(plugin); + + const before = vi.getTimerCount(); + await kernelWithFakeTimers.bootstrap(); + + // Unlike `getActiveResourcesInfo()`, the fake-timer count includes + // unref'd timers — so this one distinguishes "the guard was + // reclaimed" from "the guard was merely detached from the loop". + expect(vi.getTimerCount()).toBe(before); + + await kernelWithFakeTimers.shutdown(); + }); + }); + 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 664de065f0..f51a235c53 100644 --- a/packages/core/src/kernel.ts +++ b/packages/core/src/kernel.ts @@ -541,19 +541,59 @@ export class ObjectKernel { this.currentlyInitializing = plugin.name; try { - const initPromise = plugin.init(this.context); - const timeoutPromise = new Promise((_, reject) => { - setTimeout(() => { - reject(new Error(`Plugin ${plugin.name} init timeout after ${timeout}ms`)); - }, timeout); - }); - - await Promise.race([initPromise, timeoutPromise]); + await this.raceStartupTimeout( + plugin.init(this.context), + timeout, + `Plugin ${plugin.name} init timeout after ${timeout}ms` + ); } finally { this.currentlyInitializing = undefined; } } + /** + * Race a plugin lifecycle hook against its startup-timeout guard, and + * reclaim the guard the moment the race settles (#4813). + * + * The guard used to be armed and then abandoned: when the plugin won the + * race, its `setTimeout` stayed ref'd in the event loop for the full + * `startupTimeout`, so every process idled that long after its work was + * done. One `os migrate` finished in 3s and then sat for 120s + * (`ObjectQLPlugin.startupTimeout`), held open by 8 orphaned guards — one + * per init plus one per start. + * + * 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 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. + * + * `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. + */ + 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); + } + } + /** * Whether a service is resolvable on this kernel right now — direct * registration or a loader-registered factory. Backs the init-service @@ -584,15 +624,12 @@ export class ObjectKernel { this.logger.debug(`Start: ${plugin.name}`, { plugin: plugin.name }); try { - const startPromise = plugin.start(this.context); - const timeoutPromise = new Promise((_, reject) => { - setTimeout(() => { - reject(new Error(`Plugin ${plugin.name} start timeout after ${timeout}ms`)); - }, timeout); - }); + await this.raceStartupTimeout( + plugin.start(this.context), + timeout, + `Plugin ${plugin.name} start timeout after ${timeout}ms` + ); - await Promise.race([startPromise, timeoutPromise]); - const duration = Date.now() - startTime; this.startedPlugins.add(plugin.name); this.pluginStartTimes.set(plugin.name, duration);