From 26e2b192f126d4c0e578f142b39f6ba88af04a67 Mon Sep 17 00:00:00 2001 From: Claude Date: Mon, 3 Aug 2026 18:24:00 +0000 Subject: [PATCH] fix(service-automation,core): clear the node-execution and shutdown timeout guards when the race settles (#4952) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two remaining production instances of the leak #4813 (PR #4874, kernel init/start) and #4875 (PR #4950, periodic health checks) already fixed: a timeout guard armed and then abandoned. When the guarded side won the race, its `setTimeout` was neither cleared nor unref'd, so it stayed ref'd and pinned the event loop for the whole timeout budget. - `AutomationEngine.executeWithTimeout()` — the widest of the three: one guard per flow node that declares `timeoutMs`, per run, so the orphan count scales with flow size x trigger frequency. A one-shot process (`os` CLI running a flow) idles for the longest armed budget after its work is done. - `HotReloadManager.reloadPlugin()` — the plugin `destroy()` shutdown guard, byte-for-byte the shape #4813 fixed. Both follow #4874 / #4950 exactly — a private helper plus `try { return await Promise.race([...]) } finally { clearTimeout(guard) }`. No new variant, no `unref()`. hot-reload's helper widens its input to `T | PromiseLike` (the Plugin contract permits a synchronous `destroy()`); engine's does not (`NodeExecutor.execute` is declared Promise-returning). `unref()` would stop the pinning but also stop the guard being a guard: if the guarded side never settles and nothing else keeps the loop alive, Node exits before the timer fires and the timeout is never reported. Regression tests therefore assert both directions per site, following #4950: no ref'd timer left under real timers, no accumulation across rounds under fake timers (that count still sees an unref'd timer, so it catches an unref()-style fake fix), and the timeout still reported when the guarded side genuinely hangs. Timeout durations are untouched — the defect was never the duration. B1 (kernel.ts `shutdown()`) and B2 (objectql `checkDriversHealth()`) are deliberately out of scope per the PM ruling on #4952: both are documented deliberate `unref()` semantics. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01NrmBxj8rK2uGCnh9aipjwX --- ...ode-and-shutdown-timeout-guards-cleared.md | 30 +++ packages/core/src/hot-reload.test.ts | 205 ++++++++++++++++++ packages/core/src/hot-reload.ts | 53 ++++- .../service-automation/src/engine.test.ts | 144 +++++++++++- .../services/service-automation/src/engine.ts | 44 +++- 5 files changed, 461 insertions(+), 15 deletions(-) create mode 100644 .changeset/node-and-shutdown-timeout-guards-cleared.md create mode 100644 packages/core/src/hot-reload.test.ts 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); + } } /**