fix(core): 插件 init/start 超时守卫在 race 落定时被清除 —— 进程不再空转 startupTimeout (#4813)

.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` 的取值一个都没动 —— 慢启动的插件需要那个上限,问题从来不在时长,而在
+没人回收。

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;

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<void>((_, 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<T>` because the Plugin
+     * contract permits a synchronous hook (`init`/`start` return
+     * `void | Promise<void>`); such a hook wins the race immediately and the
+     * guard is reclaimed on the same turn.
+     */
+    private async raceStartupTimeout<T>(
+        operation: T | PromiseLike<T>,
+        timeout: number,
+        message: string
+    ): Promise<T> {
+        let guard: ReturnType<typeof setTimeout> | undefined;
+
+        const timeoutPromise = new Promise<never>((_, 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<void>((_, 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);