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);