diff --git a/.changeset/node-and-shutdown-timeout-guards-cleared.md b/.changeset/node-and-shutdown-timeout-guards-cleared.md new file mode 100644 index 0000000000..80ab767fb2 --- /dev/null +++ b/.changeset/node-and-shutdown-timeout-guards-cleared.md @@ -0,0 +1,30 @@ +--- +'@objectstack/service-automation': patch +'@objectstack/core': patch +--- + +fix: 节点执行与热重载 shutdown 的超时守卫在 race 落定时被清除,不再留下孤儿定时器 (#4952) + +#4813(PR #4874,内核 init/start)与 #4875(PR #4950,周期性健康检查)修掉的是同一种漏法: +守卫 armed 之后就被扔掉 —— 被守护的一方赢下 race 之后,那根 `setTimeout` 既没 `clearTimeout` +也没 `unref()`,带着 ref 一直把事件循环钉满整个超时预算。本次清仓剩下的两处生产实例: + +- **`AutomationEngine.executeWithTimeout()`**(`service-automation`)—— 三处里量级最大的一处: + **每个声明了 `timeoutMs` 的流程节点各一根**,孤儿数随流程节点数 × 触发频率线性增长;一次性进程 + (`os` CLI 跑到 flow 的路径)干完活之后还会被最长的那根守卫按住到超时才退出。 +- **`HotReloadManager.reloadPlugin()`**(`core`)—— 插件 `destroy()` 的 shutdown 守卫,与 #4813 + 修掉的两处一字不差:一次毫秒级完成的热重载,照样把循环钉满 `shutdownTimeout`。 + +两处修法与 #4874 / #4950 同形,不新造变体:私有 helper + +`try { return await Promise.race([...]) } finally { clearTimeout(guard) }`。`hot-reload.ts` 的 +helper 把入参放宽到 `T | PromiseLike`(Plugin 契约允许同步 `destroy()`);`engine.ts` 的不放宽 +(`NodeExecutor.execute` 声明返回 `Promise`)。 + +**为什么是 `clearTimeout` 而不是 `unref()`。** `unref()` 让定时器不再钉住事件循环的同时,也让它 +不再是一个守卫 —— 若被守护的一方永不 settle 且没有别的东西撑着事件循环,Node 会在定时器触发之前 +退出,超时被静默吞掉。守卫必须在 race 未决期间保持 ref'd、在落定那一刻被回收,这正是 +`finally { clearTimeout(guard) }` 表达的语义。两处的回归测试各自沿用 #4950 的双向写法: +真实定时器下不留 ref'd 定时器、fake timers 下连跑多轮不累积(计数能看见 `unref()` 过的定时器, +因此识破 `unref()` 式的假修复)、以及被守护方真的挂住时超时照常上报。 + +超时时长(`timeoutMs` / `shutdownTimeout`)一个都没动 —— 问题从来不在时长,而在没人回收。 diff --git a/packages/core/src/hot-reload.test.ts b/packages/core/src/hot-reload.test.ts new file mode 100644 index 0000000000..683ad37699 --- /dev/null +++ b/packages/core/src/hot-reload.test.ts @@ -0,0 +1,205 @@ +// Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. + +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; +import { HotReloadManager } from './hot-reload.js'; +import type { ObjectLogger } from './logger.js'; +import type { Plugin } from './types.js'; +import type { HotReloadConfig } from '@objectstack/spec/kernel'; + +/** Records `error` reports; every other level is dropped. `child()` is self. */ +function createRecordingLogger(errors: { message: string; error?: unknown }[]): ObjectLogger { + const logger = { + debug: () => {}, + info: () => {}, + warn: () => {}, + trace: () => {}, + fatal: () => {}, + error: (message: string, meta?: Record) => { + errors.push({ message, error: meta?.error }); + }, + child: () => logger, + }; + return logger as unknown as ObjectLogger; +} + +describe('HotReloadManager', () => { + let errors: { message: string; error?: unknown }[]; + let manager: HotReloadManager; + + beforeEach(() => { + errors = []; + manager = new HotReloadManager(createRecordingLogger(errors)); + }); + + // #4952 — the shutdown timeout guard must not outlive the race it guards. + // + // Byte-for-byte the leak #4813 fixed in the kernel's startup guards + // (PR #4874) and #4875 fixed in the periodic health checks (PR #4950): the + // guard was armed and then abandoned, so a `destroy()` that finished in + // milliseconds still pinned the event loop for the whole `shutdownTimeout` + // — once per reload, per plugin. + // + // Everything below asserts the observable consequence, never the source: + // "hot-reload.ts calls clearTimeout" is a tautology any refactor could + // satisfy while still leaving the loop pinned. + describe('Shutdown timeout guard does not outlive the race (#4952)', () => { + /** A guard long enough that a single orphan is unmistakable. */ + const guardedConfig = (overrides: Partial = {}): HotReloadConfig => + ({ + enabled: true, + debounceDelay: 1000, + preserveState: false, + stateStrategy: 'none', + shutdownTimeout: 120_000, + ...overrides, + }) as HotReloadConfig; + + const noState = () => ({}); + const noRestore = () => {}; + + /** + * 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 destroy() wins the race", async () => { + const calls = { count: 0 }; + const plugin = { + name: 'guarded-plugin', + version: '1.0.0', + init: () => {}, + destroy: async () => { + calls.count++; + }, + } as unknown as Plugin; + + manager.registerPlugin('guarded-plugin', guardedConfig()); + + const before = refdTimers(); + const reloaded = await manager.reloadPlugin( + 'guarded-plugin', + plugin, + '1.0.0', + noState, + noRestore + ); + + expect(reloaded).toBe(true); + expect(calls.count).toBe(1); + expect(refdTimers()).toBe(before); + }); + + it('still reports the timeout when destroy() 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, and a plugin that hangs on shutdown + // is exactly the case this guard exists for. 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: () => {}, + destroy: () => + new Promise(resolve => { + release = resolve; + }), + } as unknown as Plugin; + + manager.registerPlugin('hanging-plugin', guardedConfig({ shutdownTimeout: 50 })); + + const reloaded = await manager.reloadPlugin( + 'hanging-plugin', + hangingPlugin, + '1.0.0', + noState, + noRestore + ); + + expect(reloaded).toBe(false); + expect(errors).toHaveLength(1); + expect(errors[0]?.message).toBe('Hot reload failed'); + expect((errors[0]?.error as Error).message).toBe('Shutdown timeout'); + + release(); + }); + + describe('under fake timers', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it('accumulates no guard across repeated reloads', async () => { + const calls = { count: 0 }; + const plugin = { + name: 'guarded-plugin', + version: '1.0.0', + init: () => {}, + destroy: async () => { + calls.count++; + }, + } as unknown as Plugin; + + manager.registerPlugin('guarded-plugin', guardedConfig()); + + // 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", the + // fake fix that keeps the leak and loses the report above. + const before = vi.getTimerCount(); + + for (let round = 0; round < 4; round++) { + const reloaded = await manager.reloadPlugin( + 'guarded-plugin', + plugin, + '1.0.0', + noState, + noRestore + ); + expect(reloaded).toBe(true); + // Nothing armed survives the reload that armed it — no drift. + expect(vi.getTimerCount()).toBe(before); + } + + expect(calls.count).toBe(4); + }); + + it('reclaims the guard on the same turn for a synchronous destroy()', async () => { + // The Plugin contract permits `destroy(): void` — the reason the helper + // is widened to `T | PromiseLike`. A sync hook wins the race + // immediately, and the guard must go with it. + const calls = { count: 0 }; + const syncPlugin = { + name: 'sync-plugin', + version: '1.0.0', + init: () => {}, + destroy: () => { + calls.count++; + }, + } as unknown as Plugin; + + manager.registerPlugin('sync-plugin', guardedConfig()); + + const before = vi.getTimerCount(); + const reloaded = await manager.reloadPlugin( + 'sync-plugin', + syncPlugin, + '1.0.0', + noState, + noRestore + ); + + expect(reloaded).toBe(true); + expect(calls.count).toBe(1); + expect(vi.getTimerCount()).toBe(before); + }); + }); + }); +}); diff --git a/packages/core/src/hot-reload.ts b/packages/core/src/hot-reload.ts index d078ec6a15..fc1d07acdf 100644 --- a/packages/core/src/hot-reload.ts +++ b/packages/core/src/hot-reload.ts @@ -270,12 +270,11 @@ export class HotReloadManager { if (plugin.destroy) { this.logger.debug('Destroying plugin', { plugin: pluginName }); - const shutdownPromise = plugin.destroy(); - const timeoutPromise = new Promise((_, reject) => { - setTimeout(() => reject(new Error('Shutdown timeout')), config.shutdownTimeout); - }); - - await Promise.race([shutdownPromise, timeoutPromise]); + await this.raceShutdownTimeout( + plugin.destroy(), + config.shutdownTimeout, + 'Shutdown timeout' + ); this.logger.debug('Plugin destroyed successfully', { plugin: pluginName }); } @@ -312,6 +311,48 @@ export class HotReloadManager { } } + /** + * Race a plugin's `destroy()` against its shutdown-timeout guard, and + * reclaim the guard the moment the race settles (#4952). + * + * The guard used to be armed and then abandoned — byte-for-byte the leak + * #4813 fixed in the kernel's startup guards (PR #4874) and #4875 fixed in + * the periodic health checks (PR #4950): when `destroy()` won the race, its + * `setTimeout` stayed ref'd in the event loop for the full + * `shutdownTimeout`, so a hot reload that finished in milliseconds still + * pinned the loop for the whole budget — once per reload, per plugin. + * + * 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 `destroy()` 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. + * + * `shutdown` is widened to `T | PromiseLike` because the Plugin contract + * permits a synchronous `destroy()` (`Promise | void`); such a hook + * wins the race immediately and the guard is reclaimed on the same turn. + */ + private async raceShutdownTimeout( + shutdown: 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([shutdown, timeoutPromise]); + } finally { + clearTimeout(guard); + } + } + /** * Schedule a reload with debouncing */ diff --git a/packages/services/service-automation/src/engine.test.ts b/packages/services/service-automation/src/engine.test.ts index 7dd98b1b09..8ec5a90e71 100644 --- a/packages/services/service-automation/src/engine.test.ts +++ b/packages/services/service-automation/src/engine.test.ts @@ -1,6 +1,6 @@ // Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. -import { describe, it, expect, beforeEach } from 'vitest'; +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; import { LiteKernel } from '@objectstack/core'; import { AutomationEngine, DEFAULT_MAX_EXECUTION_LOG_SIZE } from './engine.js'; import { AutomationServicePlugin, parseObjectFieldSchema } from './plugin.js'; @@ -1855,6 +1855,148 @@ describe('AutomationEngine - Node Timeout', () => { const result = await engine.execute('fast_flow'); expect(result.success).toBe(true); }); + + // #4952 — the node-execution timeout guard must not outlive the race it + // guards. Same shape as the kernel's startup guards (#4813, PR #4874) and + // the periodic health checks (#4875, PR #4950), on the widest surface of + // the three: one guard per node that declares `timeoutMs`, per run, so the + // orphan count scales with flow size × trigger frequency and a one-shot + // process (`os` CLI running a flow) idles for the longest armed budget + // after its work is done. + // + // Everything below asserts the observable consequence, never the source: + // "engine.ts calls clearTimeout" is a tautology any refactor could satisfy + // while still leaving the loop pinned. + describe('Node timeout guard does not outlive the race (#4952)', () => { + /** A guard long enough that a single orphan is unmistakable. */ + const GUARD_MS = 120_000; + + /** A script executor that answers immediately (wins every race). */ + const registerInstantScript = (target: AutomationEngine, calls: { count: number }) => { + target.registerNodeExecutor({ + type: 'script', + async execute() { + calls.count++; + return { success: true }; + }, + }); + }; + + /** `count` guarded script nodes in series — one guard armed per node. */ + const registerGuardedFlow = (target: AutomationEngine, flowName: string, count: number) => { + const nodes = [ + { id: 'start', type: 'start', label: 'Start' }, + ...Array.from({ length: count }, (_, i) => ({ + id: `n${i}`, + type: 'script', + label: `Guarded ${i}`, + timeoutMs: GUARD_MS, + })), + { id: 'end', type: 'end', label: 'End' }, + ]; + const ids = nodes.map(n => n.id); + target.registerFlow(flowName, { + name: flowName, + label: 'Guarded Flow', + type: 'autolaunched', + nodes, + edges: ids.slice(0, -1).map((source, i) => ({ + id: `e${i}`, + source, + target: ids[i + 1]!, + })), + }); + }; + + /** + * 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 nodes win the race", async () => { + const calls = { count: 0 }; + registerInstantScript(engine, calls); + registerGuardedFlow(engine, 'guarded_flow', 3); + + const before = refdTimers(); + const result = await engine.execute('guarded_flow'); + + expect(result.success).toBe(true); + expect(calls.count).toBe(3); + expect(refdTimers()).toBe(before); + }); + + it('still reports the timeout when a node 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 = () => {}; + engine.registerNodeExecutor({ + type: 'script', + execute: () => + new Promise(resolve => { + release = () => resolve({ success: true }); + }), + }); + + engine.registerFlow('hanging_flow', { + name: 'hanging_flow', + label: 'Hanging Flow', + type: 'autolaunched', + nodes: [ + { id: 'start', type: 'start', label: 'Start' }, + { id: 'hangs', type: 'script', label: 'Hangs', timeoutMs: 50 }, + { id: 'end', type: 'end', label: 'End' }, + ], + edges: [ + { id: 'e1', source: 'start', target: 'hangs' }, + { id: 'e2', source: 'hangs', target: 'end' }, + ], + }); + + const result = await engine.execute('hanging_flow'); + expect(result.success).toBe(false); + expect(result.error).toBe("Node 'hangs' timed out after 50ms"); + + release(); + }); + + describe('under fake timers', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it('accumulates no guard across nodes and runs', async () => { + const calls = { count: 0 }; + registerInstantScript(engine, calls); + registerGuardedFlow(engine, 'guarded_flow', 3); + + // 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", the fake fix that keeps the leak and loses the report. + const before = vi.getTimerCount(); + + for (let run = 0; run < 4; run++) { + const result = await engine.execute('guarded_flow'); + expect(result.success).toBe(true); + // Nothing armed survives the run that armed it — no drift. + expect(vi.getTimerCount()).toBe(before); + } + + expect(calls.count).toBe(12); + }); + }); + }); }); // ─── Safe Expression Evaluation Tests ──────────────────────────────── diff --git a/packages/services/service-automation/src/engine.ts b/packages/services/service-automation/src/engine.ts index 0d56bc3bcb..950c1f02b9 100644 --- a/packages/services/service-automation/src/engine.ts +++ b/packages/services/service-automation/src/engine.ts @@ -4291,19 +4291,47 @@ export class AutomationEngine implements IAutomationService { } /** - * Execute a promise with timeout using Promise.race. + * Race a node's execution against its `timeoutMs` guard, and reclaim the + * guard the moment the race settles (#4952). + * + * The guard used to be armed and then abandoned: when the node won the + * race, its `setTimeout` stayed ref'd in the event loop for the full + * `timeoutMs`. Same leak as the kernel's startup guards (#4813, PR #4874) + * and the health checks (#4875, PR #4950), with the widest blast radius of + * the three — this is the per-node hot path, so the orphan count grows with + * flow size × trigger frequency, and a one-shot process (`os` CLI running a + * flow) idles for the longest `timeoutMs` it happened to arm after its work + * is done. + * + * 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 node 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. + * + * No `T | PromiseLike` widening here (unlike the kernel and + * health-monitor helpers, whose hooks may be synchronous): + * `NodeExecutor.execute` is declared `Promise`-returning. */ - private executeWithTimeout( + private async executeWithTimeout( promise: Promise, timeoutMs: number, nodeId: string, ): Promise { - return Promise.race([ - promise, - new Promise((_, reject) => - setTimeout(() => reject(new Error(`Node '${nodeId}' timed out after ${timeoutMs}ms`)), timeoutMs), - ), - ]); + let guard: ReturnType | undefined; + + const timeoutPromise = new Promise((_, reject) => { + guard = setTimeout(() => { + reject(new Error(`Node '${nodeId}' timed out after ${timeoutMs}ms`)); + }, timeoutMs); + }); + + try { + return await Promise.race([promise, timeoutPromise]); + } finally { + clearTimeout(guard); + } } /**