diff --git a/server/src/index.ts b/server/src/index.ts index f8d458883..198b07771 100644 --- a/server/src/index.ts +++ b/server/src/index.ts @@ -116,24 +116,41 @@ bootstrap().catch((err) => { }); // Graceful shutdown +// +// The sequence itself lives in ./shutdown so it can be tested without a process +// to exit; this is only the wiring. See that file for why the order matters — +// in short, #2193: nothing here could ever release a WebSocket, so `docker +// stop` always ended in SIGKILL and exit 137. +let shuttingDown = false; function shutdown(signal: string): void { + // A second signal — the SIGINT that follows a Ctrl-C, or an impatient + // orchestrator sending SIGTERM twice — must not start a second teardown on + // top of the first one. + if (shuttingDown) return; + shuttingDown = true; const { logInfo: sLogInfo, logError: sLogError } = require('./nest/audit/audit-log.logger'); const { closeMcpSessions } = require('./mcp'); - sLogInfo(`${signal} received — shutting down gracefully...`); - closeMcpSessions(); - // nestApp.close() stops every cron via the scheduling registrar's shutdown hook. - void nestApp?.close(); - server.close(() => { - sLogInfo('HTTP server closed'); - const { closeDb } = require('./db/database'); - closeDb(); - sLogInfo('Shutdown complete'); - process.exit(0); - }); - setTimeout(() => { - sLogError('Forced shutdown after timeout'); + const { getServer } = require('./nest/realtime/ws-state'); + const { runShutdown } = require('./shutdown'); + runShutdown(signal, { + // Both are still undefined if the signal beat bootstrap(); the sequence + // handles that and still exits rather than hanging or throwing. + server, + // nestApp.close() stops every cron via the scheduling registrar's shutdown + // hook, and tears the plugin supervisor's forked children down. + closeNestApp: async () => { await nestApp?.close(); }, + getWsClients: () => getServer()?.clients ?? null, + closeMcpSessions, + closeDb: () => { require('./db/database').closeDb(); }, + logInfo: sLogInfo, + logError: sLogError, + exit: (code: number) => process.exit(code), + }).catch((err: unknown) => { + // Fire-and-forget would make this an unhandled rejection, which on Node 22 + // is a crash — a worse ending than the one we are here to fix. + sLogError(`Shutdown failed: ${err instanceof Error ? err.message : String(err)}`); process.exit(1); - }, 10000); + }); } process.on('SIGTERM', () => shutdown('SIGTERM')); diff --git a/server/src/shutdown.ts b/server/src/shutdown.ts new file mode 100644 index 000000000..b93f731d8 --- /dev/null +++ b/server/src/shutdown.ts @@ -0,0 +1,165 @@ +import type { Server as HttpServer } from 'node:http'; + +/** + * A ws client, as much of one as the shutdown sequence needs. + * + * Typed structurally rather than as `ws`'s WebSocket so the sequence can be + * tested with plain objects — the point of this module is that the thing that + * kept #2193 alive is finally reachable from a test. + */ +export interface ClosableSocket { + close(code: number, reason: string): void; + terminate(): void; +} + +/** Everything a shutdown touches, handed in rather than imported. */ +export interface ShutdownDeps { + /** + * The http.Server this process listens on (bootstrap's, via getHttpServer). + * + * Undefined when the signal beats the bootstrap — an orchestrator that stops a + * container mid-boot, which is exactly the kind of deployment #2193 came from. + * There is nothing to drain in that case, and the shutdown must still reach + * process.exit rather than throwing into a fire-and-forget promise. + */ + server: Pick | undefined; + /** Runs every onModuleDestroy hook — crons, plugin supervisor, ws adapter. */ + closeNestApp: () => Promise; + /** The live ws clients, or null once the adapter has torn the server down. */ + getWsClients: () => Iterable | null; + closeMcpSessions: () => void; + closeDb: () => void; + logInfo: (message: string) => void; + logError: (message: string) => void; + exit: (code: number) => void; + /** How long a socket may take the polite way out before it is destroyed. */ + drainMs?: number; + /** Last-resort exit, deliberately below Docker's 10s stop grace. */ + forcedMs?: number; +} + +/** + * How long a client gets to answer the closing handshake before its socket is + * destroyed. Long enough for a browser on a bad connection to reply, short + * enough to leave the forced exit below plenty of room. + */ +export const SOCKET_DRAIN_MS = 2_000; + +/** + * The fallback exit, at half of Docker's default 10s stop grace. + * + * The old value was exactly 10_000 — the same moment Docker sends SIGKILL. + * Docker starts counting when it sends the signal and Node only once the + * handler is dispatched, so that timer started strictly later and could never + * win. It was unreachable code in every default deployment, which is why #2193 + * saw exit 137 rather than "Forced shutdown after timeout". + */ +export const FORCED_EXIT_MS = 5_000; + +/** + * Shut the process down in the order the runtime actually requires. + * + * #2193: every `docker stop` of a TREK instance with a browser attached ended + * in SIGKILL and exit 137. `http.Server.close()` stops NEW connections and then + * waits for the open ones to end by themselves — and a WebSocket never does. + * Node's own `closeAllConnections()` does not help either: an upgraded socket + * is no longer the http server's to destroy. So the close callback stayed + * pending forever, `closeDb()` (which lived inside it) never ran, and the only + * remaining exit was a timer set to the very second Docker fires SIGKILL. + * + * Waiting for Nest to do it does not work either: `WsAdapter.close()` is the + * one place that terminates clients, and Nest reaches it only after every + * `onModuleDestroy` hook has resolved — including the plugin supervisor's own + * SIGTERM grace for its forked children. The sockets holding the server open + * would be hostage to the slowest hook in the container. + * + * Hence this order, and it is the whole fix: + * + * 1. ws clients get 1001 "going away" first, so a browser sees a real close + * frame and reconnects the quiet way. The client ignores the code and + * reconnects on any close (client/src/api/websocket.ts), so this is a + * nicety, not a contract change. + * 2. `closeIdleConnections()` drops keep-alive sockets parked between + * requests — a reverse proxy always holds a few. + * 3. After `drainMs`, anything still attached is destroyed: `terminate()` for + * the ws clients that never answered the handshake, `closeAllConnections()` + * for requests still in flight. A shutdown that waits on an unbounded + * upload is the same hang somewhere else. + * + * Nest is closed alongside that, and the DB is closed exactly once on BOTH exit + * paths rather than only on the one that used to be unreachable. + */ +export async function runShutdown(signal: string, deps: ShutdownDeps): Promise { + const { + server, closeNestApp, getWsClients, closeMcpSessions, closeDb, + logInfo, logError, exit, + drainMs = SOCKET_DRAIN_MS, forcedMs = FORCED_EXIT_MS, + } = deps; + + logInfo(`${signal} received — shutting down gracefully...`); + + const guard = (what: string, fn: () => void): void => { + try { + fn(); + } catch (err) { + // One step failing must not strand the process in a half-shutdown: log it + // and carry on to the next, because the alternative is the SIGKILL again. + logError(`${what} failed during shutdown: ${err instanceof Error ? err.message : String(err)}`); + } + }; + + let finished = false; + /** The single exit path, so the DB is closed exactly once and never skipped. */ + const finish = (code: number, message: string): void => { + if (finished) return; + finished = true; + // WAL-mode SQLite recovers on the next boot, so a DB that refuses to close + // is worth a line in the log and nothing more — never a reason to hang. + guard('closeDb', closeDb); + logInfo(message); + exit(code); + }; + + // Armed first, so a hang anywhere below still ends in OUR exit rather than in + // Docker's SIGKILL. unref'd: it must never be why the loop stays alive. + const forced = setTimeout(() => { + logError('Forced shutdown after timeout'); + finish(1, 'Shutdown complete (forced)'); + }, forcedMs); + forced.unref?.(); + + guard('closeMcpSessions', closeMcpSessions); + + // Before Nest closes: its adapter's close() drops the server reference, and + // after that there is nothing left to say goodbye to. + const clients: ClosableSocket[] = []; + guard('ws teardown', () => { + for (const client of getWsClients() ?? []) clients.push(client); + }); + for (const client of clients) { + guard('ws close', () => client.close(1001, 'Server shutting down')); + } + + const httpClosed = server + ? new Promise((resolve) => { + server.close(() => { + logInfo('HTTP server closed'); + resolve(); + }); + }) + : Promise.resolve(); + if (server) guard('closeIdleConnections', () => server.closeIdleConnections()); + + const drain = setTimeout(() => { + // Whatever is still holding the server open at this point is not going to + // let go on its own. + for (const client of clients) guard('ws terminate', () => client.terminate()); + if (server) guard('closeAllConnections', () => server.closeAllConnections()); + }, drainMs); + drain.unref?.(); + + await Promise.allSettled([httpClosed, closeNestApp()]); + clearTimeout(drain); + clearTimeout(forced); + finish(0, 'Shutdown complete'); +} diff --git a/server/tests/unit/shutdown.test.ts b/server/tests/unit/shutdown.test.ts new file mode 100644 index 000000000..135c0377c --- /dev/null +++ b/server/tests/unit/shutdown.test.ts @@ -0,0 +1,171 @@ +/** + * Graceful shutdown sequence (#2193). + * + * The reported symptom was a container that exited 137 exactly ten seconds + * after every `docker stop`. The cause was that nothing in the shutdown path + * could release a WebSocket: `http.Server.close()` waits for open connections + * and an upgraded socket never ends on its own, so the close callback — which + * is where `closeDb()` and `process.exit(0)` lived — never ran, and the only + * remaining exit was a fallback timer set to the very second Docker sends + * SIGKILL. + * + * These tests pin the three things that fix required: the sockets are actively + * released, the database is closed on BOTH exit paths, and the fallback timer + * fires inside Docker's 10s grace rather than on top of it. + */ +import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest'; +import { runShutdown, SOCKET_DRAIN_MS, FORCED_EXIT_MS } from '../../src/shutdown'; + +type Deps = Parameters[1]; + +function makeSocket() { + return { close: vi.fn(), terminate: vi.fn() }; +} + +/** + * A server whose close callback only fires once told to — the whole point is + * that the real one does not fire while a socket is still attached. + */ +function makeServer() { + let done: (() => void) | undefined; + return { + close: vi.fn((cb: () => void) => { done = cb; }), + closeIdleConnections: vi.fn(), + closeAllConnections: vi.fn(), + /** Stand-in for the last connection going away. */ + finishClose: () => done?.(), + }; +} + +function makeDeps(over: Partial = {}): Deps & { exit: ReturnType; closeDb: ReturnType } { + const server = makeServer(); + return { + server: server as unknown as Deps['server'], + closeNestApp: vi.fn(async () => {}), + getWsClients: () => null, + closeMcpSessions: vi.fn(), + closeDb: vi.fn(), + logInfo: vi.fn(), + logError: vi.fn(), + exit: vi.fn(), + ...over, + } as never; +} + +beforeEach(() => { vi.useFakeTimers(); }); +afterEach(() => { vi.useRealTimers(); }); + +describe('runShutdown', () => { + it('SHUTDOWN-001 asks every ws client to go away before Nest tears the adapter down', async () => { + const a = makeSocket(); + const b = makeSocket(); + const order: string[] = []; + const deps = makeDeps({ + getWsClients: () => { order.push('ws'); return [a, b]; }, + closeNestApp: vi.fn(async () => { order.push('nest'); }), + }); + + const run = runShutdown('SIGTERM', deps); + (deps.server as unknown as ReturnType).finishClose(); + await run; + + expect(a.close).toHaveBeenCalledWith(1001, 'Server shutting down'); + expect(b.close).toHaveBeenCalledWith(1001, 'Server shutting down'); + // The adapter's own close() drops the server reference, so the clients have + // to be collected before Nest gets a chance to run. + expect(order).toEqual(['ws', 'nest']); + }); + + it('SHUTDOWN-002 drops idle keep-alive sockets immediately', async () => { + const deps = makeDeps(); + const server = deps.server as unknown as ReturnType; + + const run = runShutdown('SIGTERM', deps); + expect(server.closeIdleConnections).toHaveBeenCalled(); + // Nothing is destroyed yet — an in-flight request still has its drain window. + expect(server.closeAllConnections).not.toHaveBeenCalled(); + + server.finishClose(); + await run; + }); + + it('SHUTDOWN-003 destroys whatever is still attached after the drain window', async () => { + const socket = makeSocket(); + const deps = makeDeps({ getWsClients: () => [socket] }); + const server = deps.server as unknown as ReturnType; + + // Never resolves on its own: this is the hang #2193 died on. + runShutdown('SIGTERM', deps); + await vi.advanceTimersByTimeAsync(SOCKET_DRAIN_MS); + + expect(socket.terminate).toHaveBeenCalled(); + expect(server.closeAllConnections).toHaveBeenCalled(); + }); + + it('SHUTDOWN-004 closes the database and exits 0 once the server is down', async () => { + const deps = makeDeps(); + const run = runShutdown('SIGTERM', deps); + (deps.server as unknown as ReturnType).finishClose(); + await run; + + expect(deps.closeDb).toHaveBeenCalledTimes(1); + expect(deps.exit).toHaveBeenCalledWith(0); + }); + + it('SHUTDOWN-005 still closes the database when it has to force the exit', async () => { + // The close callback never fires — exactly the case that used to leave the + // WAL behind for boot-time recovery on every restart. + const deps = makeDeps({ closeNestApp: vi.fn(() => new Promise(() => {})) }); + + runShutdown('SIGTERM', deps); + await vi.advanceTimersByTimeAsync(FORCED_EXIT_MS); + + expect(deps.closeDb).toHaveBeenCalledTimes(1); + expect(deps.exit).toHaveBeenCalledWith(1); + }); + + it('SHUTDOWN-006 forces the exit inside Docker default 10s stop grace', () => { + // The old value was exactly 10_000 — the same moment Docker sends SIGKILL, + // and since Docker starts counting first that timer could never win. + expect(FORCED_EXIT_MS).toBeLessThan(10_000); + expect(SOCKET_DRAIN_MS).toBeLessThan(FORCED_EXIT_MS); + }); + + it('SHUTDOWN-007 exits once even if the forced timer and the clean path race', async () => { + const deps = makeDeps(); + const run = runShutdown('SIGTERM', deps); + (deps.server as unknown as ReturnType).finishClose(); + await run; + await vi.advanceTimersByTimeAsync(FORCED_EXIT_MS * 2); + + expect(deps.exit).toHaveBeenCalledTimes(1); + expect(deps.closeDb).toHaveBeenCalledTimes(1); + }); + + it('SHUTDOWN-009 still exits when the signal beats the bootstrap', async () => { + // An orchestrator stopping a container mid-boot: there is no http server yet. + // The old path called server.close() on undefined, and the fire-and-forget + // promise turned that into an unhandled rejection instead of an exit. + const deps = makeDeps({ server: undefined as never }); + + await runShutdown('SIGTERM', deps); + + expect(deps.closeDb).toHaveBeenCalledTimes(1); + expect(deps.exit).toHaveBeenCalledWith(0); + }); + + it('SHUTDOWN-008 carries on when a teardown step throws', async () => { + const deps = makeDeps({ + closeMcpSessions: vi.fn(() => { throw new Error('mcp boom'); }), + getWsClients: () => { throw new Error('ws boom'); }, + }); + + const run = runShutdown('SIGTERM', deps); + (deps.server as unknown as ReturnType).finishClose(); + await run; + + // A failing step is logged, never a reason to strand the process. + expect(deps.logError).toHaveBeenCalled(); + expect(deps.exit).toHaveBeenCalledWith(0); + }); +});