DC-067: fix force-exit + listener exception handling per Codex D-grade feedback
- Force-exit timer now distinguishes serverClosed from managersStopped. Was: if (closed) return → suppressed timer when manager hung after server.close fired (the original bug). Now: if (managersStopped) return → timer fires only when full drain (HTTP close + all managers stopped) completes before the deadline. - Added _safeEmit() helper that wraps this.emit() so a buggy listener throwing during 'shutdown' or 'closed' doesn't abort the shutdown sequence. Each failed listener is logged via the structured logger. - Added 4 new tests covering: hung manager after HTTP close, throwing shutdown listener, throwing closed listener, and the fast-drain happy path that clears the timer cleanly.
This commit is contained in:
@@ -150,6 +150,45 @@ describe('ShutdownCoordinator (DC-067)', () => {
|
|||||||
expect(handler).toHaveBeenCalledWith('SIGTERM');
|
expect(handler).toHaveBeenCalledWith('SIGTERM');
|
||||||
});
|
});
|
||||||
|
|
||||||
|
test('swallows exceptions thrown by shutdown event listeners', () => {
|
||||||
|
const log = makeFakeLog();
|
||||||
|
const server = makeFakeServer();
|
||||||
|
const c = createShutdownCoordinator({
|
||||||
|
server,
|
||||||
|
log,
|
||||||
|
managers: [],
|
||||||
|
});
|
||||||
|
c.on('shutdown', () => { throw new Error('listener boom'); });
|
||||||
|
|
||||||
|
// shutdown() must NOT propagate the exception — that would abort
|
||||||
|
// the entire shutdown sequence before server.close is even called.
|
||||||
|
expect(() => c.shutdown('SIGTERM')).not.toThrow();
|
||||||
|
expect(log.error).toHaveBeenCalledWith(
|
||||||
|
'shutdown',
|
||||||
|
"event listener for 'shutdown' threw",
|
||||||
|
expect.objectContaining({ error: 'listener boom' }),
|
||||||
|
);
|
||||||
|
// server.close should still have been called.
|
||||||
|
expect(server.close).toHaveBeenCalledTimes(1);
|
||||||
|
});
|
||||||
|
|
||||||
|
test('swallows exceptions thrown by closed event listeners', async () => {
|
||||||
|
const log = makeFakeLog();
|
||||||
|
const server = makeFakeServer();
|
||||||
|
const c = createShutdownCoordinator({
|
||||||
|
server,
|
||||||
|
log,
|
||||||
|
managers: [],
|
||||||
|
});
|
||||||
|
c.on('closed', () => { throw new Error('closed listener boom'); });
|
||||||
|
|
||||||
|
// process.exit is mocked; we just verify the throw doesn't bubble.
|
||||||
|
c.shutdown('SIGTERM');
|
||||||
|
await new Promise((resolve) => setImmediate(resolve));
|
||||||
|
// The closed listener threw but the exit still got recorded.
|
||||||
|
expect(exitCalls).toEqual([0]);
|
||||||
|
});
|
||||||
|
|
||||||
test('calls server.close() once', () => {
|
test('calls server.close() once', () => {
|
||||||
const server = makeFakeServer();
|
const server = makeFakeServer();
|
||||||
const c = createShutdownCoordinator({
|
const c = createShutdownCoordinator({
|
||||||
@@ -289,36 +328,77 @@ describe('ShutdownCoordinator (DC-067)', () => {
|
|||||||
expect(exitCalls).toEqual([0]);
|
expect(exitCalls).toEqual([0]);
|
||||||
expect(log.warn).toHaveBeenCalledWith(
|
expect(log.warn).toHaveBeenCalledWith(
|
||||||
'shutdown',
|
'shutdown',
|
||||||
'drain timeout (1000ms) reached, force-exiting',
|
expect.stringContaining('drain timeout (1000ms) reached before HTTP server closed'),
|
||||||
);
|
);
|
||||||
} finally {
|
} finally {
|
||||||
jest.useRealTimers();
|
jest.useRealTimers();
|
||||||
}
|
}
|
||||||
});
|
});
|
||||||
|
|
||||||
test('clears force-exit timer when server.close fires first', () => {
|
test('force-exits after drainTimeoutMs if manager.stop() hangs after HTTP close', () => {
|
||||||
jest.useFakeTimers();
|
jest.useFakeTimers();
|
||||||
try {
|
try {
|
||||||
const server = makeFakeServer(); // calls back on the same tick
|
const server = makeFakeServer(); // calls back immediately
|
||||||
const log = makeFakeLog();
|
const log = makeFakeLog();
|
||||||
|
// Manager that NEVER resolves — simulates a hung cleanup.
|
||||||
|
const hungManager = {
|
||||||
|
name: 'hung',
|
||||||
|
stop: jest.fn(() => new Promise(() => {})), // never resolves
|
||||||
|
};
|
||||||
const c = createShutdownCoordinator({
|
const c = createShutdownCoordinator({
|
||||||
server,
|
server,
|
||||||
log,
|
log,
|
||||||
drainTimeoutMs: 1000,
|
drainTimeoutMs: 1000,
|
||||||
managers: [],
|
managers: [hungManager],
|
||||||
});
|
});
|
||||||
|
|
||||||
c.shutdown('SIGTERM');
|
c.shutdown('SIGTERM');
|
||||||
// The close callback is async (it awaits _stopManagersInOrder),
|
// After the synchronous shutdown() call: server.close has fired
|
||||||
// so the synchronous c.shutdown() returns BEFORE process.exit(0)
|
// (serverClosed=true), but hungManager.stop() has been called and
|
||||||
// is recorded. Flush pending timers + microtasks.
|
// its promise is pending. managersStopped is still false.
|
||||||
jest.runAllTimers();
|
// process.exit should NOT have been called yet.
|
||||||
// Flush microtasks queued by the async close callback.
|
expect(exitCalls).toEqual([]);
|
||||||
|
|
||||||
|
jest.advanceTimersByTime(1001);
|
||||||
|
// Now the safety-net timer fires — force-exit because manager hung.
|
||||||
|
expect(exitCalls).toEqual([0]);
|
||||||
|
expect(log.warn).toHaveBeenCalledWith(
|
||||||
|
'shutdown',
|
||||||
|
expect.stringContaining('after HTTP close (manager hung)'),
|
||||||
|
);
|
||||||
|
} finally {
|
||||||
|
jest.useRealTimers();
|
||||||
|
}
|
||||||
|
});
|
||||||
|
|
||||||
|
test('clears force-exit timer when manager drain completes promptly', () => {
|
||||||
|
jest.useFakeTimers();
|
||||||
|
try {
|
||||||
|
const server = makeFakeServer(); // calls back on the same tick
|
||||||
|
const log = makeFakeLog();
|
||||||
|
// Quick-stopping manager. The close callback awaits stop(),
|
||||||
|
// which resolves immediately, so managersStopped flips true
|
||||||
|
// and the safety-net timer is cleared before it can fire.
|
||||||
|
const fastManager = {
|
||||||
|
name: 'fast',
|
||||||
|
stop: jest.fn(() => Promise.resolve()),
|
||||||
|
};
|
||||||
|
const c = createShutdownCoordinator({
|
||||||
|
server,
|
||||||
|
log,
|
||||||
|
drainTimeoutMs: 1000,
|
||||||
|
managers: [fastManager],
|
||||||
|
});
|
||||||
|
|
||||||
|
c.shutdown('SIGTERM');
|
||||||
|
|
||||||
|
// Flush microtasks so the close callback's await stop() resolves,
|
||||||
|
// managersStopped flips true, the timer is cleared, and
|
||||||
|
// process.exit(0) is recorded exactly once.
|
||||||
return Promise.resolve().then(() => Promise.resolve()).then(() => {
|
return Promise.resolve().then(() => Promise.resolve()).then(() => {
|
||||||
expect(exitCalls).toEqual([0]);
|
expect(exitCalls).toEqual([0]);
|
||||||
|
|
||||||
// Advance well past the drain timeout — no extra exit should fire
|
// Advance well past the drain timeout — no extra exit should fire.
|
||||||
// because the close callback cleared the force-exit timer.
|
|
||||||
jest.advanceTimersByTime(5000);
|
jest.advanceTimersByTime(5000);
|
||||||
expect(exitCalls).toEqual([0]);
|
expect(exitCalls).toEqual([0]);
|
||||||
});
|
});
|
||||||
|
|||||||
@@ -71,6 +71,24 @@ class ShutdownCoordinator extends EventEmitter {
|
|||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
|
||||||
|
/**
|
||||||
|
* Emit an event but swallow listener exceptions so one bad listener
|
||||||
|
* can't abort the shutdown sequence. Logs each failure with the
|
||||||
|
* listener's name (set via `listener.name`) if available.
|
||||||
|
*/
|
||||||
|
_safeEmit(event, ...args) {
|
||||||
|
const listeners = this.listeners(event);
|
||||||
|
for (const listener of listeners) {
|
||||||
|
try {
|
||||||
|
listener.apply(this, args);
|
||||||
|
} catch (err) {
|
||||||
|
const name = listener.name || '<anonymous>';
|
||||||
|
this.log.error('shutdown', `event listener for '${event}' threw`,
|
||||||
|
{ listener: name, error: err.message });
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|
||||||
shutdown(signal) {
|
shutdown(signal) {
|
||||||
if (this._shuttingDown) {
|
if (this._shuttingDown) {
|
||||||
this.log.info('shutdown', `${signal || 'shutdown'} received — already shutting down, ignoring`);
|
this.log.info('shutdown', `${signal || 'shutdown'} received — already shutting down, ignoring`);
|
||||||
@@ -82,16 +100,19 @@ class ShutdownCoordinator extends EventEmitter {
|
|||||||
// Emit 'shutdown' event first so any listeners can observe the signal
|
// Emit 'shutdown' event first so any listeners can observe the signal
|
||||||
// before the drain begins. NOTE: listeners should NOT tear down their
|
// before the drain begins. NOTE: listeners should NOT tear down their
|
||||||
// state here — that happens in the 'closed' event after server.close.
|
// state here — that happens in the 'closed' event after server.close.
|
||||||
this.emit('shutdown', signal);
|
// _safeEmit swallows listener exceptions so a buggy listener can't
|
||||||
|
// abort the entire shutdown sequence.
|
||||||
|
this._safeEmit('shutdown', signal);
|
||||||
|
|
||||||
// Close the HTTP server FIRST. Stops accepting new connections, waits
|
// Close the HTTP server FIRST. Stops accepting new connections, waits
|
||||||
// for in-flight requests to complete naturally. Only AFTER close fires
|
// for in-flight requests to complete naturally. Only AFTER close fires
|
||||||
// do we tear down managers — otherwise in-flight requests could fail
|
// do we tear down managers — otherwise in-flight requests could fail
|
||||||
// when the services they call have already been stopped.
|
// when the services they call have already been stopped.
|
||||||
let closed = false;
|
let serverClosed = false;
|
||||||
|
let managersStopped = false;
|
||||||
try {
|
try {
|
||||||
this.server.close(async () => {
|
this.server.close(async () => {
|
||||||
closed = true;
|
serverClosed = true;
|
||||||
this.log.info('shutdown', 'HTTP server closed cleanly');
|
this.log.info('shutdown', 'HTTP server closed cleanly');
|
||||||
// Now that in-flight requests are done, stop managers in order.
|
// Now that in-flight requests are done, stop managers in order.
|
||||||
// We do NOT clear the force-exit timer yet — if a manager's stop()
|
// We do NOT clear the force-exit timer yet — if a manager's stop()
|
||||||
@@ -104,26 +125,31 @@ class ShutdownCoordinator extends EventEmitter {
|
|||||||
// throw (e.g. from the for-loop itself) is still possible.
|
// throw (e.g. from the for-loop itself) is still possible.
|
||||||
this.log.error('shutdown', 'manager shutdown loop threw', { error: err.message });
|
this.log.error('shutdown', 'manager shutdown loop threw', { error: err.message });
|
||||||
}
|
}
|
||||||
|
managersStopped = true;
|
||||||
// Manager drain complete — NOW we can clear the safety timer.
|
// Manager drain complete — NOW we can clear the safety timer.
|
||||||
if (this._forceTimer) {
|
if (this._forceTimer) {
|
||||||
clearTimeout(this._forceTimer);
|
clearTimeout(this._forceTimer);
|
||||||
this._forceTimer = null;
|
this._forceTimer = null;
|
||||||
}
|
}
|
||||||
this.emit('closed', signal);
|
this._safeEmit('closed', signal);
|
||||||
process.exit(0);
|
process.exit(0);
|
||||||
});
|
});
|
||||||
} catch (err) {
|
} catch (err) {
|
||||||
this.log.error('shutdown', 'server.close threw', { error: err.message });
|
this.log.error('shutdown', 'server.close threw', { error: err.message });
|
||||||
}
|
}
|
||||||
|
|
||||||
// Force-exit if drain doesn't complete in time. This is the safety
|
// Force-exit safety net. Fires when EITHER:
|
||||||
// net for the case where a long-polling request or a stuck handler
|
// (a) server.close never fires (HTTP server stuck draining), or
|
||||||
// never returns and the drain never finishes.
|
// (b) server.close fired but managers hung during stop()
|
||||||
|
// We only suppress when managersStopped === true (full drain complete).
|
||||||
|
// serverClosed alone is NOT enough — managers could still be running.
|
||||||
this._forceTimer = setTimeout(() => {
|
this._forceTimer = setTimeout(() => {
|
||||||
if (closed) return; // race: server.close fired AND timer fired
|
if (managersStopped) return; // full shutdown complete
|
||||||
this.log.warn('shutdown', `drain timeout (${this.drainTimeoutMs}ms) reached, force-exiting`);
|
if (!serverClosed) {
|
||||||
// On force-exit we don't run manager.stop() — the process is
|
this.log.warn('shutdown', `drain timeout (${this.drainTimeoutMs}ms) reached before HTTP server closed, force-exiting`);
|
||||||
// about to die anyway, and SIGKILL will be next if we don't exit.
|
} else {
|
||||||
|
this.log.warn('shutdown', `drain timeout (${this.drainTimeoutMs}ms) reached after HTTP close (manager hung), force-exiting`);
|
||||||
|
}
|
||||||
process.exit(0);
|
process.exit(0);
|
||||||
}, this.drainTimeoutMs);
|
}, this.drainTimeoutMs);
|
||||||
if (this._forceTimer && typeof this._forceTimer.unref === 'function') {
|
if (this._forceTimer && typeof this._forceTimer.unref === 'function') {
|
||||||
|
|||||||
Reference in New Issue
Block a user