From f62e624a25f19f5b3fca8f65b6a326bf0470e3fd Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 4 Aug 2026 15:31:21 +0000 Subject: [PATCH] fix(core): isolate kernel:shutdown dispatch and stop reporting handler throws as timeouts (#5274) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `ObjectKernel.performShutdown()` dispatched `kernel:shutdown` through `context.trigger` — a bare awaited loop that never catches — so the first handler that threw propagated out to `shutdown()`'s `Promise.race` catch. That catch was written for the timeout race alone and treated every exception as one, so a single bad subscriber produced three consequences at once: the remaining `kernel:shutdown` handlers never ran, EVERY plugin's `destroy()` was skipped (the reverse-order pass sits after the trigger), and the host process was killed by `process.exit(1)` under the log line `Shutdown timed out — forcing exit` while nothing had timed out. Two changes, matching the reasoning #5257 recorded at LiteKernel's shutdown dispatch site: - `kernel:shutdown` now dispatches ISOLATING on ObjectKernel too. A throwing handler is logged as `Hook handler failed: kernel:shutdown` and the remaining handlers still run, followed by the reverse-order `destroy()` pass and the `onShutdown()` handlers — both of which already isolated per plugin and per handler. What is queued behind a failing shutdown handler is the cleanup that flushes buffers, closes connections and releases locks, so one bad handler must not amplify into leaks and unflushed writes. The boot-path hooks are untouched: `kernel:ready`, `kernel:bootstrapped` and `kernel:listening` still propagate and still fail the boot (#5170, #5257). ObjectKernel does not extend ObjectKernelBase (only LiteKernel does) and owns its own `hooks` map, so `triggerHook` is not reachable from it; the semantics are mirrored in a private dispatcher that logs the identical line, with the reason recorded at the method. - The timeout catch now handles ONLY a genuine timeout, discriminated by identity on the timer's own rejection — not by message, not by `instanceof`, so nothing a plugin throws can impersonate it. A genuine `shutdownTimeout` overrun is unchanged: still logs `Shutdown timed out — forcing exit`, still calls `process.exit(1)`, because teardown really is hung. Any other exception is logged at `error` and follows the normal path (`state = 'stopped'`, return) with no `process.exit`, leaving an embedding host its own chance to finish cleanly. `shutdown()` still never rejects, so no caller changes. Three named per-behavior tests: the issue's reproduction (remaining handlers, destroy() and onShutdown all run; process not exited; state `stopped`), the false-timeout report, and the genuine timeout still exiting 1. `process.exit` is intercepted with `vi.spyOn` — the reason this pin could not land in #5257. The first two fail on the pre-change kernel with exactly the issue's probe output; the third passes on both sides, which is what makes it a pin on unchanged behaviour. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01Pbu27iNUfQCHeuS551Rqo7 --- ...nel-shutdown-isolate-and-honest-timeout.md | 44 ++++++ content/docs/kernel/events.mdx | 2 +- packages/core/src/kernel.test.ts | 140 ++++++++++++++++++ packages/core/src/kernel.ts | 92 +++++++++++- 4 files changed, 270 insertions(+), 8 deletions(-) create mode 100644 .changeset/kernel-shutdown-isolate-and-honest-timeout.md diff --git a/.changeset/kernel-shutdown-isolate-and-honest-timeout.md b/.changeset/kernel-shutdown-isolate-and-honest-timeout.md new file mode 100644 index 0000000000..f528842dfb --- /dev/null +++ b/.changeset/kernel-shutdown-isolate-and-honest-timeout.md @@ -0,0 +1,44 @@ +--- +"@objectstack/core": patch +--- + +fix(core): one throwing `kernel:shutdown` handler no longer skips every plugin `destroy()` and kills the process under a false "Shutdown timed out" (#5274) + +**On `ObjectKernel`, a single bad shutdown subscriber used to end the entire teardown +and `process.exit(1)` the host — reporting a timeout that never happened.** + +`performShutdown()` dispatched `kernel:shutdown` through `context.trigger` (a bare +awaited loop that never catches), so the first handler that threw propagated out to +`shutdown()`'s `Promise.race` catch. That catch was written for the timeout race alone +and treated every exception as one, producing three consequences at once: + +1. the remaining `kernel:shutdown` handlers never ran; +2. **every** plugin's `destroy()` was skipped — the reverse-order destroy pass sits + after the trigger in `performShutdown()`, so it was never reached; +3. the process was killed by `process.exit(1)` under the log line + `Shutdown timed out — forcing exit`, while nothing had timed out — sending whoever + read it to the `shutdownTimeout` config for a handler bug. + +Two changes, matching the reasoning #5257 recorded at `LiteKernel`'s shutdown dispatch +site: + +- **`kernel:shutdown` now dispatches ISOLATING on `ObjectKernel` too.** A handler that + throws is logged as `Hook handler failed: kernel:shutdown` and the remaining handlers + still run, followed by the reverse-order `destroy()` pass and the `onShutdown()` + handlers — both of which already isolated per plugin and per handler. What is queued + behind a failing shutdown handler is the cleanup that flushes buffers, closes + connections and releases locks, so one bad handler must not amplify into leaks and + unflushed writes. The BOOT-path hooks are untouched: `kernel:ready`, + `kernel:bootstrapped` and `kernel:listening` still propagate and still fail the boot + (#5170, #5257). +- **The timeout catch now handles only a genuine timeout**, discriminated by identity on + the timer's own rejection — not by message, not by type, so nothing a plugin throws + can impersonate it. A genuine `shutdownTimeout` overrun is **unchanged**: it still + logs `Shutdown timed out — forcing exit` and still calls `process.exit(1)`, because + teardown really is hung and the process would otherwise hold what it failed to + release. Any other exception is logged at `error` and follows the normal path — + `state = 'stopped'`, return — with no `process.exit`, leaving an embedding host + (cloud auth-proxy, CLI, a test runner) its own chance to finish cleanly. + +`shutdown()` still never rejects, so no existing caller changes. Telling the two paths +apart is the point of the fix, and both are pinned by named tests. diff --git a/content/docs/kernel/events.mdx b/content/docs/kernel/events.mdx index 7c8e9fbf43..f119cd3f43 100644 --- a/content/docs/kernel/events.mdx +++ b/content/docs/kernel/events.mdx @@ -37,7 +37,7 @@ A handler on any of the three **boot-path** hooks — `kernel:ready`, `kernel:bo `kernel:ready` is still the right place for **boot assertions** specifically — the service registry is only finished filling by then, so nothing earlier can judge whether a precondition your plugin *declared* was actually met, and a deployment that cannot honour what it announced must refuse to start rather than serve without the guarantee. -`kernel:shutdown` is the deliberate exception: on `LiteKernel` a failing shutdown handler is logged and the remaining cleanup still runs, because the handlers queued behind it — and the `destroy()` pass after them — are what flush buffers and release resources, so aborting teardown only leaks what they were about to release. `ObjectKernel`'s shutdown path does not yet match that (tracked in [#5274](https://github.com/objectstack-ai/objectstack/issues/5274)); write shutdown handlers that handle their own errors either way. +`kernel:shutdown` is the deliberate exception, on **both** kernels: a failing shutdown handler is logged (`Hook handler failed: kernel:shutdown`) and the remaining cleanup still runs, because the handlers queued behind it — and the `destroy()` pass after them — are what flush buffers and release resources, so aborting teardown only leaks what they were about to release. On `ObjectKernel` this also means a throwing shutdown handler no longer kills the host process: `shutdown()` still never rejects, the kernel still ends `stopped`, and `process.exit(1)` is reserved for a genuine `shutdownTimeout` overrun — the one case where teardown really is hung ([#5274](https://github.com/objectstack-ai/objectstack/issues/5274)). Write shutdown handlers that handle their own errors either way. ### Emitting Custom Events diff --git a/packages/core/src/kernel.test.ts b/packages/core/src/kernel.test.ts index fca8f42bbc..5782e31c6c 100644 --- a/packages/core/src/kernel.test.ts +++ b/packages/core/src/kernel.test.ts @@ -728,6 +728,146 @@ describe('ObjectKernel', () => { expect(handlerCalled).toBe(true); }); + + // #5274. `process.exit` is intercepted in all three tests below — the + // behaviour under test is precisely whether the kernel kills the host + // process, and an unintercepted `exit(1)` takes the vitest worker with + // it (which is why this pin could not land in #5257). + const spyOnExit = () => + vi.spyOn(process, 'exit').mockImplementation((() => undefined) as never); + + const spyOnLog = (k: ObjectKernel, level: 'error' | 'info') => + vi.spyOn( + (k as unknown as { logger: Record<'error' | 'info', (...a: unknown[]) => void> }).logger, + level, + ); + + // The issue's reproduction, inverted into a pin. Before this, the first + // throwing `kernel:shutdown` handler ended the entire teardown: the + // probe recorded `reached=["process.exit(1)"]` — neither the second + // handler nor the plugin's destroy() ever ran. What is queued behind a + // failing shutdown handler is the rest of the cleanup (flush buffers, + // close connections, release locks), so one bad handler must not + // amplify into leaks and unflushed writes. + it('runs the remaining kernel:shutdown handlers, every destroy() and every onShutdown handler when one handler throws (#5274)', async () => { + const reached: string[] = []; + const exitSpy = spyOnExit(); + + const plugin: Plugin = { + name: 'shutdown-thrower', + version: '1.0.0', + init: async (ctx) => { + ctx.hook('kernel:shutdown', async () => { + throw new Error('shutdown boom'); + }); + ctx.hook('kernel:shutdown', async () => { reached.push('later-shutdown'); }); + }, + destroy: async () => { reached.push('plugin-destroy'); }, + }; + + try { + await kernel.use(plugin); + kernel.onShutdown(async () => { reached.push('shutdown-handler'); }); + await kernel.bootstrap(); + await kernel.shutdown(); + + // Every teardown step behind the failing handler still ran, in + // order: remaining subscribers → reverse-order destroy() → + // custom shutdown handlers. + expect(reached).toEqual(['later-shutdown', 'plugin-destroy', 'shutdown-handler']); + // …and the host process was left alone. + expect(exitSpy).not.toHaveBeenCalled(); + expect(kernel.getState()).toBe('stopped'); + } finally { + exitSpy.mockRestore(); + } + }); + + // The second half of the same defect, pinned separately because it can + // regress on its own: the outer catch was written only for the timeout + // race, so a handler throw was reported as `Shutdown timed out — + // forcing exit` when nothing had timed out — sending whoever read that + // line straight to the `shutdownTimeout` config. + it('names the failing handler and never reports a timeout that did not happen (#5274)', async () => { + const exitSpy = spyOnExit(); + const errorSpy = spyOnLog(kernel, 'error'); + const infoSpy = spyOnLog(kernel, 'info'); + + const plugin: Plugin = { + name: 'shutdown-thrower-logs', + version: '1.0.0', + init: async (ctx) => { + ctx.hook('kernel:shutdown', async () => { + throw new Error('shutdown boom'); + }); + }, + }; + + try { + await kernel.use(plugin); + await kernel.bootstrap(); + await kernel.shutdown(); + + const errors = errorSpy.mock.calls.map((c) => String(c[0])); + // The failure is reported where it happened, naming the hook — + // same line LiteKernel's isolating dispatcher logs. + expect(errors).toContain('Hook handler failed: kernel:shutdown'); + // …and NOT as a timeout. + expect(errors.some((m) => m.includes('Shutdown timed out'))).toBe(false); + expect(exitSpy).not.toHaveBeenCalled(); + + // Teardown really did complete, so it says so. + const infos = infoSpy.mock.calls.map((c) => String(c[0])); + expect(infos.some((m) => m.includes('Graceful shutdown complete'))).toBe(true); + } finally { + exitSpy.mockRestore(); + errorSpy.mockRestore(); + infoSpy.mockRestore(); + } + }); + + // The other side of the discrimination, and the reason it is drawn by + // identity on the timer's own rejection: a GENUINE timeout keeps the + // hard exit. `performShutdown()` is still running and has stopped + // making progress, so the process would hang holding whatever it failed + // to release. This behaviour is unchanged by #5274 — pinned so the + // narrowing of the catch cannot quietly take it along. + it('still logs the timeout and still forces exit(1) when shutdown genuinely times out (#5274)', async () => { + const slowKernel = new ObjectKernel({ + logger: { level: 'error' }, + gracefulShutdown: false, + skipSystemValidation: true, + shutdownTimeout: 20, + }); + + const exitSpy = spyOnExit(); + const errorSpy = spyOnLog(slowKernel, 'error'); + + const plugin: Plugin = { + name: 'hanging-shutdown-plugin', + version: '1.0.0', + init: async (ctx) => { + // Never settles — the actual shape of a hung teardown. + // Deliberately left pending: resolving it later would let + // the teardown resume after the test had finished. + ctx.hook('kernel:shutdown', () => new Promise(() => {})); + }, + }; + + try { + await slowKernel.use(plugin); + await slowKernel.bootstrap(); + await slowKernel.shutdown(); + + const errors = errorSpy.mock.calls.map((c) => String(c[0])); + expect(errors).toContain('Shutdown timed out — forcing exit'); + expect(exitSpy).toHaveBeenCalledWith(1); + expect(slowKernel.getState()).toBe('stopped'); + } finally { + exitSpy.mockRestore(); + errorSpy.mockRestore(); + } + }, 5000); }); describe('Dependency Resolution', () => { diff --git a/packages/core/src/kernel.ts b/packages/core/src/kernel.ts index f51a235c53..5a07c583c3 100644 --- a/packages/core/src/kernel.ts +++ b/packages/core/src/kernel.ts @@ -425,11 +425,22 @@ export class ObjectKernel { this.state = 'stopping'; this.logger.info('Graceful shutdown started'); + // The ONE rejection that means "teardown hung". Created here so the + // catch below can discriminate by IDENTITY (#5274): only this + // `setTimeout` can produce this exact object, so no message match, no + // `instanceof`, and nothing a plugin throws can ever impersonate it — + // not even a handler throwing `new Error('Shutdown timeout exceeded')`. + // That discrimination is the whole point: the catch used to be reached + // by BOTH the timer and any exception escaping `performShutdown()`, and + // it treated them identically — `process.exit(1)` under a log line + // reading "Shutdown timed out" when nothing had timed out. + const shutdownTimeoutError = new Error('Shutdown timeout exceeded'); + try { const shutdownPromise = this.performShutdown(); const timeoutPromise = new Promise((_, reject) => { const t = setTimeout(() => { - reject(new Error('Shutdown timeout exceeded')); + reject(shutdownTimeoutError); }, this.config.shutdownTimeout); // Don't let this timer keep the event loop alive if (t.unref) t.unref(); @@ -440,11 +451,32 @@ export class ObjectKernel { this.state = 'stopped'; this.logger.info('✅ Graceful shutdown complete'); } catch (error) { - this.logger.error('Shutdown timed out — forcing exit', error as Error); this.state = 'stopped'; - // Flush logger then hard-exit; the process would otherwise hang - await this.logger.destroy(); - process.exit(1); + + if (error === shutdownTimeoutError) { + // GENUINE timeout: `performShutdown()` is still running and has + // stopped making progress, so the process would otherwise hang + // holding whatever it failed to release. Hard-exit stays — it + // is the only branch it was ever right for. + this.logger.error('Shutdown timed out — forcing exit', error as Error); + // Flush logger then hard-exit; the process would otherwise hang + await this.logger.destroy(); + process.exit(1); + } else { + // NOT a timeout. `performShutdown()` isolates every teardown + // step it owns (hook dispatch, each destroy(), each shutdown + // handler), so reaching here means something outside those + // loops failed — the teardown is over either way, and there is + // nothing hung to escape from. Killing the host process here + // would take away the embedding host's (cloud auth-proxy, CLI, + // a test runner) chance to do its own cleanup, over a fault + // that did not require it. Log and return down the normal + // path; `shutdown()` still never rejects. + this.logger.error( + 'Shutdown finished with an unexpected teardown error — the kernel is stopped and the process is NOT being exited; some cleanup may not have run', + error as Error, + ); + } } finally { await this.logger.destroy(); } @@ -673,9 +705,55 @@ export class ObjectKernel { this.startedPlugins.clear(); } + /** + * Dispatch `kernel:shutdown`, ISOLATING failures: a handler that throws is + * logged and the remaining handlers still run (#5274). + * + * This is a per-hook judgement, deliberately NOT the bare awaited loop + * `context.trigger` runs for every other hook — the boot-path hooks + * (`kernel:ready`, `kernel:bootstrapped`, `kernel:listening`) keep + * propagating, because everything dispatched before "✅ Bootstrap complete" + * is a precondition of that claim and swallowing a throw there only hides + * the failure behind a process reporting success (#5170, #5257). + * + * On the teardown path there is no "refuse to proceed" left to buy. What is + * queued behind a failing shutdown handler is the rest of the cleanup — + * every other subscriber, then each plugin's `destroy()` in reverse order — + * which is what flushes buffers, closes connections and releases locks. So + * one bad handler must not amplify into leaked resources and unflushed + * writes. Same reasoning, same wording, same `Hook handler failed: + * kernel:shutdown` log line as `LiteKernel`'s dispatch site, which reaches + * the shared isolating dispatcher `ObjectKernelBase.triggerHook` (#5257). + * + * `ObjectKernel` cannot call that dispatcher: it does not extend + * `ObjectKernelBase` (only `LiteKernel` does) and owns its own `hooks` map, + * so the semantics are mirrored here rather than shared. One hook name + * meaning two opposite things across the two kernels is exactly the bug + * #5170/#5257 closed, so the pin for this one lives on both sides too. + */ + private async triggerShutdownHookIsolating(): Promise { + const handlers = this.hooks.get('kernel:shutdown') || []; + this.logger.debug('Triggering hook: kernel:shutdown', { + hook: 'kernel:shutdown', + handlerCount: handlers.length, + }); + + for (const handler of handlers) { + try { + await handler(); + } catch (error) { + this.logger.error('Hook handler failed: kernel:shutdown', error as Error); + // Continue with other handlers even if one fails + } + } + } + private async performShutdown(): Promise { - // Trigger shutdown hook - await this.context.trigger('kernel:shutdown'); + // Trigger shutdown hook — ISOLATING dispatch, see the method's own + // rationale. The two loops below already isolate per plugin and per + // handler; before #5274 this line was the one teardown step that did + // not, so a single throwing subscriber skipped BOTH of them. + await this.triggerShutdownHookIsolating(); // Destroy plugins in reverse order const orderedPlugins = Array.from(this.plugins.values()).reverse();