mirror of
https://github.com/mauriceboe/TREK.git
synced 2026-10-18 21:16:47 +00:00
fix(server): release sockets on shutdown so docker stop no longer ends in SIGKILL
Every `docker stop` of a TREK instance with a browser attached exited 137, exactly ten seconds after the stop. `http.Server.close()` stops new connections and then waits for the open ones to end by themselves — and a WebSocket never does. TREK holds one per open tab, so the close callback never ran. `closeDb()` and `process.exit(0)` lived inside that callback, which left the only remaining exit a fallback timer set to 10000ms: exactly when 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. Waiting for Nest was not an option 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 SIGTERM grace for its forked children. The sockets holding the server open would be hostage to the slowest hook in the container. So the sockets are now released deliberately: ws clients get 1001 "going away", idle keep-alive sockets are dropped at once, and anything still attached after a 2s drain is destroyed. Nest is closed alongside that, the database is closed on both exit paths rather than only the unreachable one, and the fallback fires at 5s — inside Docker's grace, so a forced exit is still ours. The sequence moved into src/shutdown.ts behind injected dependencies. It was untestable by construction before, which is part of why this went unnoticed; it now has nine tests, including the signal that beats the bootstrap. Closes #2193 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01S5VwmiBQ9sPCJwfmpv64r3
This commit is contained in:
Claude
+31
-14
@@ -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'));
|
||||
|
||||
@@ -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<HttpServer, 'close' | 'closeIdleConnections' | 'closeAllConnections'> | undefined;
|
||||
/** Runs every onModuleDestroy hook — crons, plugin supervisor, ws adapter. */
|
||||
closeNestApp: () => Promise<void>;
|
||||
/** The live ws clients, or null once the adapter has torn the server down. */
|
||||
getWsClients: () => Iterable<ClosableSocket> | 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<void> {
|
||||
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<void>((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');
|
||||
}
|
||||
@@ -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<typeof runShutdown>[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> = {}): Deps & { exit: ReturnType<typeof vi.fn>; closeDb: ReturnType<typeof vi.fn> } {
|
||||
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<typeof makeServer>).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<typeof makeServer>;
|
||||
|
||||
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<typeof makeServer>;
|
||||
|
||||
// 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<typeof makeServer>).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<void>(() => {})) });
|
||||
|
||||
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<typeof makeServer>).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<typeof makeServer>).finishClose();
|
||||
await run;
|
||||
|
||||
// A failing step is logged, never a reason to strand the process.
|
||||
expect(deps.logError).toHaveBeenCalled();
|
||||
expect(deps.exit).toHaveBeenCalledWith(0);
|
||||
});
|
||||
});
|
||||
Reference in New Issue
Block a user