mirror of
https://github.com/mauriceboe/TREK.git
synced 2026-10-19 05:26:47 +00:00
5cb87a4df5
Three small gaps in how the process behaves at its edges: - An unhandled rejection or uncaught exception crashed the process with the stack on stderr only. index.ts now logs it to trek.log and runs the same orderly shutdown a SIGTERM gets, exiting with 1; a second fatal error during that shutdown exits at once. - /api/health/ready kept answering 200 while a SIGTERM was draining the process, so an orchestrator sent traffic for another probe period. A shutdown now marks the new ReadinessService first (and Nest's own shutdown hook marks it too), and the probe answers 503 from then on. - Node closes an idle keep-alive connection after 5 seconds while reverse proxies keep upstream connections for about a minute, which shows up as intermittent 502s. The server now keeps them for 65 seconds, configurable through HTTP_KEEP_ALIVE_TIMEOUT_MS (owned by the httpConfig token), with the headers timeout one second above.
262 lines
11 KiB
TypeScript
262 lines
11 KiB
TypeScript
/**
|
|
* 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, createFatalHandler, 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. Deliberately
|
|
// not awaited, so the rejection path is logged rather than left unobserved.
|
|
void runShutdown('SIGTERM', deps).catch((err: unknown) => console.error(err));
|
|
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>(() => {})) });
|
|
|
|
// Deliberately not awaited: the close callback never fires, so this promise
|
|
// only settles through the forced exit below.
|
|
void runShutdown('SIGTERM', deps).catch((err: unknown) => console.error(err));
|
|
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-010 says so when Nest teardown fails, and still exits cleanly', async () => {
|
|
// allSettled absorbs the rejection; without an explicit report the operator
|
|
// would read "Shutdown complete" and exit 0 while the crons and the plugin
|
|
// children were never torn down.
|
|
const deps = makeDeps({ closeNestApp: vi.fn(async () => { throw new Error('hook boom'); }) });
|
|
|
|
const run = runShutdown('SIGTERM', deps);
|
|
(deps.server as unknown as ReturnType<typeof makeServer>).finishClose();
|
|
await run;
|
|
|
|
expect(deps.logError).toHaveBeenCalledWith(expect.stringContaining('hook boom'));
|
|
expect(deps.exit).toHaveBeenCalledWith(0);
|
|
});
|
|
|
|
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);
|
|
});
|
|
});
|
|
|
|
describe('runShutdown: readiness and the exit code', () => {
|
|
it('SHUTDOWN-020 marks the process as draining before anything else happens', async () => {
|
|
const order: string[] = [];
|
|
const deps = makeDeps({
|
|
markDraining: vi.fn(() => { order.push('draining'); }),
|
|
closeMcpSessions: vi.fn(() => { order.push('mcp'); }),
|
|
getWsClients: () => { order.push('ws'); return null; },
|
|
});
|
|
const run = runShutdown('SIGTERM', deps);
|
|
(deps.server as unknown as ReturnType<typeof makeServer>).finishClose();
|
|
await run;
|
|
expect(order[0]).toBe('draining');
|
|
expect(order).toEqual(['draining', 'mcp', 'ws']);
|
|
});
|
|
|
|
it('SHUTDOWN-021 a readiness flag that cannot be set is logged and the shutdown goes on', async () => {
|
|
const deps = makeDeps({ markDraining: () => { throw new Error('no app yet'); } });
|
|
const run = runShutdown('SIGTERM', deps);
|
|
(deps.server as unknown as ReturnType<typeof makeServer>).finishClose();
|
|
await run;
|
|
expect(deps.logError).toHaveBeenCalledWith('markDraining failed during shutdown: no app yet');
|
|
expect(deps.exit).toHaveBeenCalledWith(0);
|
|
});
|
|
|
|
it('SHUTDOWN-022 a shutdown started by a fatal error exits with its code', async () => {
|
|
const deps = makeDeps({ exitCode: 1 });
|
|
const run = runShutdown('Uncaught exception', deps);
|
|
(deps.server as unknown as ReturnType<typeof makeServer>).finishClose();
|
|
await run;
|
|
expect(deps.closeDb).toHaveBeenCalledTimes(1);
|
|
expect(deps.exit).toHaveBeenCalledWith(1);
|
|
});
|
|
});
|
|
|
|
describe('createFatalHandler', () => {
|
|
function fatalDeps() {
|
|
return { logError: vi.fn(), shutdown: vi.fn(), exit: vi.fn() };
|
|
}
|
|
|
|
it('FATAL-001 logs the stack and starts the orderly shutdown with exit code 1', () => {
|
|
const deps = fatalDeps();
|
|
const onFatal = createFatalHandler(deps);
|
|
const error = new Error('boom');
|
|
onFatal('Uncaught exception', error);
|
|
expect(deps.logError).toHaveBeenCalledWith(`Uncaught exception: ${error.stack}`);
|
|
expect(deps.shutdown).toHaveBeenCalledWith('Uncaught exception', 1);
|
|
expect(deps.exit).not.toHaveBeenCalled();
|
|
});
|
|
|
|
it('FATAL-002 a rejection with a non-error reason is logged as text', () => {
|
|
const deps = fatalDeps();
|
|
createFatalHandler(deps)('Unhandled promise rejection', 'plain reason');
|
|
expect(deps.logError).toHaveBeenCalledWith('Unhandled promise rejection: plain reason');
|
|
});
|
|
|
|
it('FATAL-003 a second fatal error during the shutdown exits at once', () => {
|
|
const deps = fatalDeps();
|
|
const onFatal = createFatalHandler(deps);
|
|
onFatal('Uncaught exception', new Error('first'));
|
|
onFatal('Unhandled promise rejection', new Error('second'));
|
|
expect(deps.shutdown).toHaveBeenCalledTimes(1);
|
|
expect(deps.exit).toHaveBeenCalledWith(1);
|
|
expect(deps.logError).toHaveBeenCalledTimes(2);
|
|
});
|
|
|
|
it('FATAL-004 a logger that throws does not stop the shutdown', () => {
|
|
const deps = fatalDeps();
|
|
deps.logError.mockImplementation(() => { throw new Error('disk gone'); });
|
|
createFatalHandler(deps)('Uncaught exception', new Error('boom'));
|
|
expect(deps.shutdown).toHaveBeenCalledWith('Uncaught exception', 1);
|
|
});
|
|
});
|