From faa17eb51b2a7f49ce7a8fef459f49c082b69d77 Mon Sep 17 00:00:00 2001 From: Mickael Coquer Date: Wed, 23 Sep 2026 09:17:36 +0200 Subject: [PATCH 1/3] =?UTF-8?q?feat(server):=20arr=C3=AAt=20propre=20sur?= =?UTF-8?q?=20SIGTERM=20et=20SIGINT?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Pose un gestionnaire unique sur SIGTERM et SIGINT, installé par app.run(). Le vide laissé jusqu'ici conduisait les projets à poser le leur depuis un module utilitaire, dont le process.exit() emportait le reste de l'arrêt — et empêchait tout exportateur de télémétrie de vider son tampon. L'arrêt se déroule dans cet ordre : readiness à 503 puis attente de config.shutdownDelay pour laisser un load balancer sortir l'instance, fermeture du serveur HTTP, config.onShutdown(), puis la base et le cache. config.shutdownTimeout plafonne l'ensemble, un second signal sort immédiatement. Rien n'est installé en environnement de test. config.onShutdown est le point d'accroche unique du projet : il s'exécute après la fermeture du serveur, donc plus aucune requête n'est en cours, et avant la base et le cache, qu'il peut encore vouloir utiliser. Un rejet est journalisé et l'arrêt se poursuit — un pool qui n'a pas pu se vider n'est pas une raison de perdre les connexions qu'on allait rendre. app.shutdown() est exportée pour un cron ou un script, qui n'a aucun signal à attendre mais dont le pool maintient le processus en vie. Côté db, dbs.close() et Db.close() rendent les pools via un closePool ajouté aux deux drivers. query() sur une base fermée lève au lieu de recréer le pool : une requête tardive rouvrirait ce qu'on vient de fermer. app.server et les nouveaux réglages sont enfin déclarés dans index.d.ts. Co-Authored-By: Claude Opus 5 (1M context) --- CHANGELOG.md | 14 ++ docs/.vitepress/config.mjs | 1 + docs/server/shutdown.md | 108 +++++++++++++++ packages/db/src/Db.js | 20 +++ packages/db/src/dbs.js | 16 +++ packages/db/src/drivers/mysql.js | 5 + packages/db/src/drivers/postgresql.js | 5 + packages/server/index.d.ts | 23 +++ packages/server/src/app.js | 79 ++++++++++- packages/server/src/cache.js | 27 +++- packages/server/src/config.js | 11 ++ packages/server/src/connect/health.js | 14 +- packages/server/test/ShutdownTest.js | 154 +++++++++++++++++++++ packages/server/test/fixtures/shutdown.cjs | 60 ++++++++ 14 files changed, 534 insertions(+), 3 deletions(-) create mode 100644 docs/server/shutdown.md create mode 100644 packages/server/test/ShutdownTest.js create mode 100644 packages/server/test/fixtures/shutdown.cjs diff --git a/CHANGELOG.md b/CHANGELOG.md index 4e44b862..2a60caac 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,19 @@ # Changelog +## Unreleased + +### @igojs/server + +- **Added**: ordered shutdown on `SIGTERM` and `SIGINT`, installed by `app.run()`. Readiness answers 503 and igo waits `config.shutdownDelay` (`0` by default) so a load balancer can take the instance out, then the HTTP server closes while the requests in flight finish, then `config.onShutdown()` runs, then the databases and the cache are released. `config.shutdownTimeout` (10s) caps the whole thing, and a second signal exits immediately. Nothing is installed when `config.env === 'test'`. +- **Added**: `config.onShutdown`, an async callback invoked between the server closing and the database being released — the single place for a project to drain its own pools and flush its telemetry exporters, instead of a second `process.on('SIGTERM')` racing igo's. A rejection is logged and the shutdown carries on. +- **Added**: `app.shutdown()`, exported so a cron or a script, which has no signal to wait for, can release the pools when its work is done. Runs once, never rejects. +- **Added**: `app.server` and the new settings are declared in `index.d.ts`; `app.server` previously had no type at all. + +### @igojs/db + +- **Added**: `dbs.close()` and `Db.close()` release the connection pools, through a new `closePool` on the MySQL and PostgreSQL drivers. +- **Changed**: `query()` on a closed database throws instead of recreating the pool. A query arriving after the shutdown — a forgotten timer, a late callback — would otherwise reopen what was just closed and keep the process alive. + ## 6.2.5 - 2026-08-31 ### @igojs/server diff --git a/docs/.vitepress/config.mjs b/docs/.vitepress/config.mjs index ff1467b3..df4529fe 100644 --- a/docs/.vitepress/config.mjs +++ b/docs/.vitepress/config.mjs @@ -72,6 +72,7 @@ export default defineConfig({ { text: 'i18n', link: '/server/i18n' }, { text: 'Error handling', link: '/server/errors' }, { text: 'Logging', link: '/server/logging' }, + { text: 'Shutdown', link: '/server/shutdown' }, ], }, ], diff --git a/docs/server/shutdown.md b/docs/server/shutdown.md new file mode 100644 index 00000000..271f51f0 --- /dev/null +++ b/docs/server/shutdown.md @@ -0,0 +1,108 @@ +# Shutdown + +On `SIGTERM` and `SIGINT`, igo closes what the application holds instead of +letting the process die where it stands: the requests being served finish, the +database pools are released, and the project gets a callback to close its own +resources. + +`app.run()` installs the handlers. Nothing else does — a CLI command or a +script has nothing to keep alive, and the test environment installs none at all, +or mocha would never get its hand back. + +## Order + +``` +SIGTERM / SIGINT + 1. readiness answers 503 the load balancer stops routing here + wait config.shutdownDelay + 2. HTTP server closes no new connection, the current ones finish + 3. config.onShutdown() the project's own shutdown + 4. databases released + 5. cache disconnected +``` + +The project callback runs **after** the server, so nothing is still being +served once it starts releasing what a request might need, and **before** the +database and the cache, which it may still want to use. + +## The project callback + +```js +// app/config.js +module.exports.init = (config) => { + config.onShutdown = async () => { + await browserPool.drain(); + await stopTelemetry(); + }; +}; +``` + +This is the single hook. A module with its own resources to release is called +from here rather than adding its own `process.on('SIGTERM')` — two handlers on +the same signal do not wait for each other, and whichever calls `process.exit()` +first takes the rest of the shutdown with it. + +A rejection is logged and the shutdown carries on to the database and the cache: +a pool that failed to drain is no reason to lose the connections that would have +been released next. + +## Settings + +| | Default | | +|---|---|---| +| `config.shutdownDelay` | `0` | Between readiness answering 503 and the socket closing | +| `config.shutdownTimeout` | `10000` | Ceiling on the whole shutdown, after which the process exits 1 | + +`shutdownDelay` is what gives a load balancer time to take the instance out +before it stops accepting connections. Without one it is dead time, hence the +`0` default; behind one, set it above the health check interval: + +```js +config.shutdownDelay = 5000; +``` + +Both delays are spent before the process manager's own patience runs out, so +its kill timeout has to exceed their sum — pm2 defaults to 1600 ms, which is +below both: + +```js +// ecosystem.config.js +module.exports = { + apps: [{ + name: 'myapp', + kill_timeout: 20000, // > shutdownDelay + shutdownTimeout + }], +}; +``` + +A second signal exits immediately with code 1, which is what a second `Ctrl-C` +is asking for. + +## Without a server + +A cron or a script that calls `app.configure()` has no signal to wait for, and +the database pool keeps the process alive once the work is done. Close it +explicitly: + +```js +const { app } = require('@igojs/server'); + +await app.configure(); +await doTheWork(); +await app.shutdown(); +``` + +`app.shutdown()` never rejects and runs once, whatever calls it. + +## After the shutdown + +A query issued after the databases are released — a forgotten `setInterval`, a +callback arriving late — is rejected rather than reopening the pool: + +``` +Error: Db 'main' is closed: the application is shutting down. +``` + +Reopening would keep the process alive past the shutdown that just closed it. +The error names the database, which is usually enough to find the timer nobody +cleared. diff --git a/packages/db/src/Db.js b/packages/db/src/Db.js index 21738dfc..7f2510d1 100644 --- a/packages/db/src/Db.js +++ b/packages/db/src/Db.js @@ -35,6 +35,7 @@ class Db { } this.driver = getDriver(this.config.driver); this.connection = null; + this.closed = false; this.config.migrations_dir = `sql/${this.name}`; } @@ -42,9 +43,24 @@ class Db { const { config } = dependencies; this.pool = await this.driver.createPool(this.config); this.connection = null; + this.closed = false; this.TEST_ENV = config.env === 'test'; } + async close() { + if (this.closed) { + return; + } + // before awaiting the drain: query() must not reopen the pool in between + this.closed = true; + const { pool } = this; + this.pool = null; + this.connection = null; + if (pool) { + await this.driver.closePool(pool); + } + } + // async getConnection() { const { driver, pool, TEST_ENV } = this; @@ -102,6 +118,10 @@ class Db { return await runquery(); } + if (this.closed) { + throw new Error(`Db '${this.name}' is closed: the application is shutting down.`); + } + logger.info('Db.query: Trying to reinitialize db connection pool'); await this.init(); if (!this.pool) { diff --git a/packages/db/src/dbs.js b/packages/db/src/dbs.js index 61d9497c..287e0bfb 100644 --- a/packages/db/src/dbs.js +++ b/packages/db/src/dbs.js @@ -22,3 +22,19 @@ module.exports.init = async () => { // main is first database module.exports.main = module.exports[config.databases[0]]; }; + +// close databases connections +module.exports.close = async () => { + const { config, logger } = dependencies; + for (const database of config.databases) { + const db = module.exports[database]; + if (!db) { + continue; + } + try { + await db.close(); + } catch (err) { + logger.error(`Could not close database '${database}': ${err.message}`); + } + } +}; diff --git a/packages/db/src/drivers/mysql.js b/packages/db/src/drivers/mysql.js index 5c1c9f05..1b080ca6 100644 --- a/packages/db/src/drivers/mysql.js +++ b/packages/db/src/drivers/mysql.js @@ -12,6 +12,11 @@ module.exports.createPool = (dbconfig) => { return mysql.createPool(_.pick(dbconfig, OPTIONS)); }; +// close pool +module.exports.closePool = async (pool) => { + await pool.end(); +}; + // get connection module.exports.getConnection = async (pool) => { return await pool.getConnection(); diff --git a/packages/db/src/drivers/postgresql.js b/packages/db/src/drivers/postgresql.js index a0891ade..f235db60 100644 --- a/packages/db/src/drivers/postgresql.js +++ b/packages/db/src/drivers/postgresql.js @@ -7,6 +7,11 @@ module.exports.createPool = (dbconfig) => { return new Pool(dbconfig); }; +// close pool +module.exports.closePool = async (pool) => { + await pool.end(); +}; + // get connection module.exports.getConnection = async (pool) => { return await pool.connect(); diff --git a/packages/server/index.d.ts b/packages/server/index.d.ts index 061dd411..47bf6f01 100644 --- a/packages/server/index.d.ts +++ b/packages/server/index.d.ts @@ -94,6 +94,21 @@ export interface Config { mailcrashto?: string | string[]; /** false keeps the server alive after an uncaught exception a request already answered. */ exitOnUncaughtException: boolean; + /** + * Milliseconds between readiness answering 503 and the HTTP server closing, + * so a load balancer takes the instance out before it stops accepting + * connections. 0 by default; behind a load balancer, set it above its check + * interval. + */ + shutdownDelay: number; + /** Ceiling on the whole shutdown, after which the process exits anyway. */ + shutdownTimeout: number; + /** + * Invoked once the HTTP server is closed and before the database and the + * cache are released — drain your own pools and flush your exporters here. + * A rejection is logged and the shutdown carries on. + */ + onShutdown?: (() => void | Promise) | null; loglevel: string; /** 'json' for log collectors, 'human' for a terminal. */ logformat: 'json' | 'human'; @@ -115,6 +130,14 @@ export interface Config { export declare const app: Express & { configure(): Promise; run(configured?: () => void, started?: () => void): Promise; + /** + * Closes the HTTP server, then config.onShutdown, then the databases and the + * cache. run() binds it to SIGTERM and SIGINT; call it directly from a script + * or a cron, which has no signal to wait for. Never rejects. + */ + shutdown(): Promise; + /** Set by run() once the server is listening. */ + server?: import('http').Server; }; export declare const config: Config; diff --git a/packages/server/src/app.js b/packages/server/src/app.js index 706a8f15..1e3d1f54 100644 --- a/packages/server/src/app.js +++ b/packages/server/src/app.js @@ -117,7 +117,7 @@ module.exports.configure = async () => { // before the request logger: probed every few seconds, these routes would // otherwise be most of the request log - health(app); + health.init(app); app.use(requestLogger); app.use(unlessApi(flash)); @@ -153,6 +153,76 @@ module.exports.configure = async () => { } }; +const closeServer = () => new Promise((resolve) => { + if (!app.server?.listening) { + return resolve(); + } + // resolves once the connections still being served are done + app.server.close(() => resolve()); +}); + +const step = async (what, fn) => { + try { + await fn(); + } catch (err) { + // one failed step must not keep the next from running + logger.warn(`Shutdown: ${what} failed: ${err.message}`, { stack: err.stack }); + } +}; + +let shuttingDown = false; + +// Closes what the application holds, in the order that lets each step still use +// what the next one closes. Exported so a script or a cron, which has no signal +// to wait for, can call it when its work is done. +module.exports.shutdown = async () => { + if (shuttingDown) { + return; + } + shuttingDown = true; + logger.info('Shutdown: starting'); + + // readiness answers 503 from here on, and config.shutdownDelay leaves the load + // balancer time to see it before the socket stops accepting connections + health.drain(); + if (config.shutdownDelay) { + await new Promise(resolve => setTimeout(resolve, config.shutdownDelay)); + } + + await step('closing server', closeServer); + await step('onShutdown', async () => await config.onShutdown?.()); + await step('closing databases', db.dbs.close); + await step('closing cache', cache.close); + + logger.info('Shutdown: done'); +}; + +// its own flag, not shutdown()'s: that one also guards a script calling +// shutdown() on its own, which is not a signal anyone is waiting on +let signalled = false; + +const onSignal = (signal) => async () => { + // a second Ctrl-C is someone asking to stop waiting + if (signalled) { + logger.warn(`${signal} received again: exiting now`); + return process.exit(1); + } + signalled = true; + logger.info(`${signal} received`); + + // a shutdown that hangs is worse than an abrupt one: the process manager sends + // SIGKILL in the end anyway, and this at least leaves a log saying where it hung + const timer = setTimeout(() => { + logger.error(`Shutdown: still running after ${config.shutdownTimeout}ms, exiting`); + process.exit(1); + }, config.shutdownTimeout); + timer.unref(); + + await module.exports.shutdown(); + clearTimeout(timer); + process.exit(0); +}; + // configured: function invoked when app is configured // started: function invoked when server is started module.exports.run = async (configured, started) => { @@ -160,6 +230,13 @@ module.exports.run = async (configured, started) => { await module.exports.configure(); configured && configured(); + // only run() installs them: a CLI command or a script has nothing to keep + // alive, and mocha would never get its hand back + if (config.env !== 'test') { + process.on('SIGTERM', onSignal('SIGTERM')); + process.on('SIGINT', onSignal('SIGINT')); + } + app.server = app.listen(config.httpport, function() { logger.info('Listening to port %s', config.httpport); started && started(); diff --git a/packages/server/src/cache.js b/packages/server/src/cache.js index 1e66e5e0..87a8ff3c 100644 --- a/packages/server/src/cache.js +++ b/packages/server/src/cache.js @@ -15,13 +15,14 @@ let logged = false; let degraded = false; let flushing = false; let disabled = false; +let closing = false; const key = (namespace, id) => `${namespace}/${id}`; // false when redis is disabled, unreachable, reconnecting, or flushing after a reconnection: // every command below then returns a miss instead of throwing, so the app runs without it -module.exports.isAvailable = () => !!client?.isReady && !flushing; +module.exports.isAvailable = () => !!client?.isReady && !flushing && !closing; // indirection on purpose: tests stub the exported isAvailable() const available = () => module.exports.isAvailable(); @@ -44,6 +45,9 @@ module.exports.init = async () => { // node-redis reconnects on its own, indefinitely: log the first failure of a window, not each retry client.on('error', (err) => { + if (closing) { + return; + } degraded = true; if (!logged) { logged = true; @@ -241,6 +245,27 @@ module.exports.flush = async (pattern) => { }); }; +// closes the connection, letting the commands already sent finish. The client is +// dropped, so a later init() — a script closing and reopening — starts a new one. +module.exports.close = async () => { + if (!client) { + return; + } + closing = true; + const closed = client; + client = null; + buffers = null; + try { + await closed.quit(); + } catch (err) { + // redis already gone: nothing left to close, and the socket dies with the process + logger.warn(`Cache: ${err.message}`); + closed.destroy(); + } finally { + closing = false; + } +}; + // v8 structured clone: Date, Buffer, Map, Set and falsy values keep their type, // so there is nothing to revive on the way out const serialize = (k, value) => { diff --git a/packages/server/src/config.js b/packages/server/src/config.js index 33c6e6ea..9f13941e 100644 --- a/packages/server/src/config.js +++ b/packages/server/src/config.js @@ -127,6 +127,17 @@ module.exports.init = function() { // already answered — only once alerting no longer relies on the crash email config.exitOnUncaughtException = true; + // On SIGTERM/SIGINT: readiness answers 503, then igo waits shutdownDelay before + // closing the socket, so a load balancer stops routing here first. 0 by default + // because that wait is dead time without one; behind a load balancer, set it + // above its check interval. shutdownTimeout is the ceiling on the whole + // shutdown, and the process manager's own kill timeout has to exceed their sum. + config.shutdownDelay = 0; + config.shutdownTimeout = 10000; + // async function invoked between the server closing and the database and cache + // being released: where a project drains its own pools and flushes its exporters + config.onShutdown = null; + config.i18n = { whitelist: [ 'en', 'fr' ], preload: [ 'en', 'fr' ], diff --git a/packages/server/src/connect/health.js b/packages/server/src/connect/health.js index c039be13..755cb1ff 100644 --- a/packages/server/src/connect/health.js +++ b/packages/server/src/connect/health.js @@ -9,6 +9,14 @@ const logger = require('../logger'); const UP = 'UP'; const DOWN = 'DOWN'; +// Set at the first step of the shutdown, before the socket is closed, so a load +// balancer reading readiness takes the instance out while it can still serve. +let draining = false; + +module.exports.drain = (value = true) => { + draining = value; +}; + // A probe that hangs must not hold the answer: an orchestrator that waits is an // orchestrator that keeps routing traffic to an instance already in trouble. const withTimeout = (promise, ms) => Promise.race([ @@ -77,6 +85,10 @@ const liveness = (req, res) => { const isOptional = (setting) => setting === 'optional'; const readiness = (settings) => async (req, res) => { + if (draining) { + return send(res, 503, { status: DOWN, components: {} }); + } + const names = Object.keys(PROBES).filter(name => settings[name]); const states = await Promise.all( names.map(name => runProbe(name, settings[name], settings.timeout))); @@ -97,7 +109,7 @@ const readiness = (settings) => async (req, res) => { // Mounted by igo before the request logger, which is what keeps these routes // out of the request log: probed every few seconds, they would otherwise be // most of it. -module.exports = (app) => { +module.exports.init = (app) => { const settings = config.health; if (!settings) { return; diff --git a/packages/server/test/ShutdownTest.js b/packages/server/test/ShutdownTest.js new file mode 100644 index 00000000..68ac1710 --- /dev/null +++ b/packages/server/test/ShutdownTest.js @@ -0,0 +1,154 @@ +require('./init'); + +const assert = require('assert'); +const path = require('path'); +const { execFileSync } = require('child_process'); + +const cache = require('../src/cache'); +const config = require('../src/config'); +const db = require('@igojs/db'); +const health = require('../src/connect/health'); + +// .cjs, outside the test glob: mocha would otherwise load it as a test file +// and the script would exit the runner itself. +const SCRIPT = path.join(__dirname, 'fixtures', 'shutdown.cjs'); + +// several scenarios exit non-zero on purpose, which makes execFileSync throw: +// the output is on the error either way +const run = (mode) => { + try { + const out = execFileSync(process.execPath, [SCRIPT, mode], { encoding: 'utf8', stdio: 'pipe' }); + return out.trim().split('\n'); + } catch (err) { + return err.stdout.trim().split('\n'); + } +}; + +// shutdown() is one-shot on purpose, so each test drives a freshly required +// copy of the module rather than the one the suite booted. +const freshApp = () => { + const appPath = require.resolve('../src/app'); + delete require.cache[appPath]; + return require(appPath); +}; + +describe('Shutdown', function() { + this.timeout(20000); + + describe('app.shutdown()', function() { + + let dbsClose, cacheClose, onShutdown; + + beforeEach(() => { + dbsClose = db.dbs.close; + cacheClose = cache.close; + onShutdown = config.onShutdown; + db.dbs.close = async () => {}; + cache.close = async () => {}; + }); + + afterEach(() => { + db.dbs.close = dbsClose; + cache.close = cacheClose; + config.onShutdown = onShutdown; + }); + + // the one ordering that protects from a visible failure: a request still + // being served once the project drained the pools it needs would fail + it('should close the server before the project callback', async () => { + const order = []; + const instance = freshApp(); + instance.server = { listening: true, close: (cb) => { order.push('server'); cb(); } }; + config.onShutdown = async () => order.push('onShutdown'); + + await instance.shutdown(); + + assert.deepStrictEqual(order, ['server', 'onShutdown']); + }); + + it('should release the databases and the cache', async () => { + const closed = new Set(); + const instance = freshApp(); + db.dbs.close = async () => closed.add('dbs'); + cache.close = async () => closed.add('cache'); + + await instance.shutdown(); + + assert.deepStrictEqual(closed, new Set(['dbs', 'cache'])); + }); + + it('should carry on when the project callback rejects', async () => { + const closed = new Set(); + const instance = freshApp(); + config.onShutdown = async () => { throw new Error('puppeteer pool is already gone'); }; + db.dbs.close = async () => closed.add('dbs'); + cache.close = async () => closed.add('cache'); + + await instance.shutdown(); + + assert.deepStrictEqual(closed, new Set(['dbs', 'cache'])); + }); + + it('should run once, however many times it is called', async () => { + let calls = 0; + const instance = freshApp(); + config.onShutdown = async () => calls++; + + await instance.shutdown(); + await instance.shutdown(); + + assert.strictEqual(calls, 1); + }); + + it('should work without a server, as a cron or a script has none', async () => { + let called = false; + const instance = freshApp(); + config.onShutdown = async () => { called = true; }; + + await instance.shutdown(); + + assert.ok(called); + }); + }); + + describe('readiness while draining', function() { + + // the shutdown tests above drained the shared module + beforeEach(() => health.drain(false)); + + it('should answer 503 so the load balancer takes the instance out', async () => { + const agent = require('@igojs/server').dev.agent; + const before = await agent.get('/health/ready'); + assert.strictEqual(before.statusCode, 200); + + health.drain(); + + const during = await agent.get('/health/ready'); + assert.strictEqual(during.statusCode, 503); + assert.strictEqual(during.data.status, 'DOWN'); + }); + }); + + describe('signals', function() { + + it('should shut down on SIGTERM and exit 0', () => { + assert.deepStrictEqual(run('sigterm'), ['shutdown', 'exit:0']); + }); + + it('should shut down on SIGINT and exit 0', () => { + assert.deepStrictEqual(run('sigint'), ['shutdown', 'exit:0']); + }); + + it('should exit 1 on a second signal rather than keep waiting', () => { + assert.deepStrictEqual(run('twice'), ['shutdown', 'exit:1']); + }); + + it('should exit 1 when the shutdown outlives config.shutdownTimeout', () => { + assert.deepStrictEqual(run('hang'), ['shutdown', 'exit:1']); + }); + + it('should install no handler in test env, or mocha would never return', () => { + assert.deepStrictEqual(run('test-env'), ['handlers:0']); + }); + }); +}); diff --git a/packages/server/test/fixtures/shutdown.cjs b/packages/server/test/fixtures/shutdown.cjs new file mode 100644 index 00000000..ba719ef3 --- /dev/null +++ b/packages/server/test/fixtures/shutdown.cjs @@ -0,0 +1,60 @@ +// Driven by ShutdownTest: signals and exit codes cannot be observed from +// inside the test process, so each scenario runs here and prints what it did. +const mode = process.argv[2]; + +// 'test' would keep run() from installing the handlers, which is what most of +// these scenarios exercise. +process.env.NODE_ENV = mode === 'test-env' ? 'test' : 'dev'; +process.env.HTTP_PORT = '0'; + +const config = require('../../src/config'); +config.init(); +config.shutdownTimeout = mode === 'hang' ? 300 : 10000; + +const logger = require('../../src/logger'); +logger.info = logger.warn = logger.error = () => {}; + +const say = (line) => process.stdout.write(`${line}\n`); + +const exit = process.exit.bind(process); +process.exit = (code) => { + say(`exit:${code}`); + exit(code); +}; + +const app = require('../../src/app'); + +// configure() would need a database and a redis: this fixture is about the +// signal wiring, so the steps it orchestrates are stubbed out. +app.configure = async () => {}; +app.shutdown = async () => { + say('shutdown'); + if (mode === 'hang') { + await new Promise(() => {}); + } + // long enough that the second signal of the 'twice' scenario lands while + // this one is still running + if (mode === 'twice') { + await new Promise(resolve => setTimeout(resolve, 5000)); + } +}; + +const send = (signal) => process.kill(process.pid, signal); + +app.run(null, () => { + if (mode === 'test-env') { + say(`handlers:${process.listenerCount('SIGTERM')}`); + return exit(0); + } + + if (mode === 'sigint') { + return send('SIGINT'); + } + + send('SIGTERM'); + + // the second one has to land while the first shutdown is still running + if (mode === 'twice') { + setTimeout(() => send('SIGTERM'), 50); + } +}); From 1414ac94aee90dcce6115e87f14d7fbef31ec480 Mon Sep 17 00:00:00 2001 From: Mickael Coquer Date: Wed, 23 Sep 2026 10:14:44 +0200 Subject: [PATCH 2/3] =?UTF-8?q?fix(server):=20une=20requ=C3=AAte=20en=20er?= =?UTF-8?q?reur=20tient=20sur=20une=20seule=20ligne=20de=20log?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Un incident produisait deux lignes : l'une portait le message et la pile, l'autre la méthode, le chemin, le corps et la réponse. Aucune n'était complète, et les deux se corrélaient par le trace_id. L'erreur est désormais attachée à la ligne « request » : le message devient l'erreur, et la pile l'accompagne. Une route rendue en HTML se journalise comme une route JSON — l'attachement se fait avant l'aiguillage sur isApi. Gardent une ligne à part les deux cas qui n'ont rien où se greffer : une erreur levée après l'envoi de la réponse, et une erreur hors requête (uncaughtException, commande CLI). La cause d'une 500 n'est plus perdue en production. Le corps de la réponse y est volontairement vidé, et le log enregistrait ce vide ; le message porte maintenant l'erreur, quoi que le client ait reçu. body, query, params et response sont journalisés en chaînes JSON plutôt qu'en objets imbriqués : un collecteur qui aplatit les champs imbriqués éclatait un document problème en response_status, response_title et response_type. query et params sont journalisés quel que soit le statut, quand ils ne sont pas vides — ce qui a été demandé fait partie de la lecture d'une ligne, et ni l'un ni l'autre ne pèse comme un corps. body et response restent réservés aux lignes en erreur. Co-Authored-By: Claude Opus 5 (1M context) --- CHANGELOG.md | 4 + docs/server/logging.md | 37 ++- packages/server/src/connect/errorhandler.js | 15 +- packages/server/src/connect/requestlogger.js | 54 ++-- packages/server/test/ErrorHandlerTest.js | 5 +- packages/server/test/RequestLoggerTest.js | 256 +++++++++++-------- 6 files changed, 245 insertions(+), 126 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2a60caac..50dd0318 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,10 @@ - **Added**: `config.onShutdown`, an async callback invoked between the server closing and the database being released — the single place for a project to drain its own pools and flush its telemetry exporters, instead of a second `process.on('SIGTERM')` racing igo's. A rejection is logged and the shutdown carries on. - **Added**: `app.shutdown()`, exported so a cron or a script, which has no signal to wait for, can release the pools when its work is done. Runs once, never rejects. - **Added**: `app.server` and the new settings are declared in `index.d.ts`; `app.server` previously had no type at all. +- **Changed**: a failed request is one log line, not two. The error lands on the `request` line — `message` becomes the error and `stack` comes with it — instead of a separate line carrying the stack while the other carried the body and the response. Neither told the whole story. Applies to server-rendered routes as well as JSON ones. An error raised after the response was sent, or outside any request (`uncaughtException`, a CLI command), still gets its own line: there is no request line left to join. +- **Fixed**: the reason a 500 failed is no longer lost in production. The response body is deliberately emptied there, and the log recorded that empty body; `message` now carries the error itself, whatever the client was told. +- **Changed**: `body`, `query`, `params` and `response` are logged as JSON strings rather than nested objects. A collector that flattens nested fields turned one problem document into `response_status`, `response_title` and `response_type`, scattering it over as many columns as it had keys. +- **Changed**: `query` and `params` are logged whatever the status, when not empty — what was asked is part of reading a successful line, and neither weighs on the volume the way a body does. `body` and `response` remain on error lines only. ### @igojs/db diff --git a/docs/server/logging.md b/docs/server/logging.md index d7c11723..7f11502d 100644 --- a/docs/server/logging.md +++ b/docs/server/logging.md @@ -67,8 +67,41 @@ Every request is logged once it completes: ``` The level follows the status: `error` at 5xx, `warn` at 4xx, `info` otherwise. -An error line also carries what the call failed with — `body`, `query`, `params` -and the `response` sent — redacted and truncated. A successful line does not. +`query` and `params` are there whenever they are not empty, whatever the status: +what was asked is part of reading a line, and neither weighs much. + +An error line also carries `body` and the `response` sent, redacted and +truncated — a diagnosis needs the shape of an import, not its content. A +successful line carries neither, which would multiply the volume for little. + +These four are logged as **JSON strings**, not nested objects, so a collector +that flattens nested fields cannot scatter one document over `response_status`, +`response_title` and `response_type`. + +### An error is one line, not two + +When a request fails, the error lands on that same line: the message becomes +the error, and `stack` comes with it. + +```json +{"level":"error","message":"Error: connection refused to 10.0.0.5:3306", + "method":"POST","path":"/api/books","status":500,"duration_ms":7.2, + "body":"{\"title\":\"Dune\"}", + "response":"{\"type\":\"about:blank\",\"title\":\"Internal Server Error\",\"status\":500}", + "stack":"Error: connection refused…","trace_id":"4bf92f35…"} +``` + +One incident, one line, whether the route answers JSON or renders a page. The +stack and the body used to sit on separate lines, so neither told the whole +story. + +`message` carries the error rather than the response body, which a 500 in +production deliberately empties: what the client is told is not what the log +needs. + +Two cases still get a line of their own — an error raised after the response +was sent, since the request line is already written, and an error outside any +request (`uncaughtException`, a CLI command), which has no line to join. `config.logrequests` takes `true`, `false`, or a **status floor**: `400` keeps the errors and drops the successes. One line per request is the largest item in diff --git a/packages/server/src/connect/errorhandler.js b/packages/server/src/connect/errorhandler.js index c134a156..5c4fd5bd 100644 --- a/packages/server/src/connect/errorhandler.js +++ b/packages/server/src/connect/errorhandler.js @@ -47,6 +47,7 @@ const logger = require('../logger'); const mailer = require('../mailer'); const problem = require('../api/problem'); const { isApiRequest } = require('../api/request'); +const requestLogger = require('./requestlogger'); const asyncLocalStorage = new AsyncLocalStorage(); @@ -201,13 +202,21 @@ const handle = (err, req, res) => { } if (res.headersSent) { - logger.error(`${req.method} ${getURL(req)} : ${err} (response already sent)`, - { stack: err.stack }); + // the request line is already written: nothing left to attach this to + logger.error(`${err} (response already sent)`, + { + method: req.method, + path: (req.originalUrl || req.url || '').split('?')[0], + stack: err.stack, + }); sendCrashEmail(`Crash (response sent): ${err}`, formatMessage(req, err), String(err)); return; } - logger.error(`${req.method} ${getURL(req)} : ${err}`, { stack: err.stack }); + // no line of its own: the request logger writes one per request, and the + // error belongs on it — with the body, the response and the trace id that + // a second line would not have + requestLogger.logError(res, err); sendCrashEmail(`Crash: ${err}`, formatMessage(req, err), String(err)); diff --git a/packages/server/src/connect/requestlogger.js b/packages/server/src/connect/requestlogger.js index fae2df96..af03c8ef 100644 --- a/packages/server/src/connect/requestlogger.js +++ b/packages/server/src/connect/requestlogger.js @@ -56,18 +56,23 @@ const traceIdFromHeader = (value) => { return /^0+$/.test(match[1]) ? null : match[1]; }; -// An error line carries what the call failed with — body, query, params, and -// the response sent — redacted, and truncated: a diagnosis needs the shape of -// an import or an attachment, not its content. A successful line carries none -// of it, which would multiply the volume without teaching anything. +// An error line carries what the call failed with — the body sent and the +// response returned — redacted, and truncated: a diagnosis needs the shape of +// an import or an attachment, not its content. A successful line carries +// neither, which would multiply the volume without teaching anything. const MAX_LENGTH = 2000; -const truncate = (value) => { - const text = JSON.stringify(value); - if (!text || text.length <= MAX_LENGTH) { - return value; +// A string, not an object: a log pipeline that flattens nested fields would +// turn { title, status } into response_title and response_status, scattering +// one document over several columns. +const asJson = (value) => { + const text = JSON.stringify(redact(value)); + if (!text) { + return text; } - return `${text.slice(0, MAX_LENGTH)}… (${text.length} chars)`; + return text.length <= MAX_LENGTH + ? text + : `${text.slice(0, MAX_LENGTH)}… (${text.length} chars)`; }; const isEmpty = (value) => @@ -76,20 +81,25 @@ const isEmpty = (value) => const failureContext = (req, res) => { const context = {}; if (!isEmpty(req.body)) { - context.body = truncate(redact(req.body)); - } - if (!isEmpty(req.query)) { - context.query = truncate(redact(req.query)); - } - if (!isEmpty(req.params)) { - context.params = redact(req.params); + context.body = asJson(req.body); } if (res._loggedBody !== undefined) { - context.response = truncate(redact(res._loggedBody)); + context.response = asJson(res._loggedBody); + } + // What the client is told is not what the log needs: a 500 answers with an + // empty problem body in production, on purpose, and the reason would be lost. + if (res._loggedError?.stack) { + context.stack = res._loggedError.stack; } return context; }; +// The message of a line is what that line has worth reading. A served request +// has nothing its fields do not already say; a failed one has the reason, which +// is nowhere else in readable form. +const messageFor = (res) => + res._loggedError ? String(res._loggedError) : 'request'; + // A response body cannot be read back off `res`: res.json, which every JSON // answer goes through, keeps it for the error line. const captureResponseBody = (res) => { @@ -151,12 +161,15 @@ module.exports = (req, res, next) => { return; } const duration = Number(process.hrtime.bigint() - start) / 1e6; - logger.log(levelFor(res.statusCode), 'request', { + logger.log(levelFor(res.statusCode), messageFor(res), { method: req.method, // req.path is rewritten to the router-relative path once mounted path: (req.originalUrl || req.url || '').split('?')[0], status: res.statusCode, duration_ms: Math.round(duration * 10) / 10, + // on every line: what was addressed is part of reading a successful one + ...(isEmpty(req.query) ? {} : { query: asJson(req.query) }), + ...(isEmpty(req.params) ? {} : { params: asJson(req.params) }), ...(res.statusCode >= 400 ? failureContext(req, res) : {}), }); }); @@ -166,3 +179,8 @@ module.exports = (req, res, next) => { }; module.exports.traceId = () => storage.getStore()?.traceId; + +// Called by the error handler, which knows the error the response hides. +module.exports.logError = (res, err) => { + res._loggedError = err; +}; diff --git a/packages/server/test/ErrorHandlerTest.js b/packages/server/test/ErrorHandlerTest.js index 9f5b1608..9983eb3f 100644 --- a/packages/server/test/ErrorHandlerTest.js +++ b/packages/server/test/ErrorHandlerTest.js @@ -49,6 +49,9 @@ describe('ErrorHandler', function() { }); describe('SyntaxError classification', function() { + // A server error is reported by being attached to the request line, which + // the request logger writes once the response is done; a client error is + // answered and left out of it. const runWithSpiedLogger = (err) => { const orig = logger.error; let logged = false; @@ -59,7 +62,7 @@ describe('ErrorHandler', function() { } finally { logger.error = orig; } - return { res, logged }; + return { res, logged: logged || !!res._loggedError }; }; it('treats malformed JSON body as a client error (not logged)', () => { diff --git a/packages/server/test/RequestLoggerTest.js b/packages/server/test/RequestLoggerTest.js index 8f3338a5..532ede3f 100644 --- a/packages/server/test/RequestLoggerTest.js +++ b/packages/server/test/RequestLoggerTest.js @@ -7,7 +7,9 @@ const { config, logger } = require('@igojs/server'); const middleware = require('../src/connect/requestlogger'); // Drives the middleware with a fake response, and returns what got logged. -const run = (status, extra = {}) => { +// `sent` is the body the route answers with, `err` an error the handler +// attaches, and `render: true` a page route, which never calls res.json. +const run = (status, { sent, err, render, ...extra } = {}) => { const lines = []; const log = logger.log; logger.log = (level, message, meta) => lines.push({ level, message, meta }); @@ -15,14 +17,24 @@ const run = (status, extra = {}) => { let finish; const req = { method: 'GET', originalUrl: '/api/books', headers: {}, ...extra }; const res = { - statusCode: status, + // the status is set once the route answered, as express does + statusCode: 200, setHeader: () => {}, on: (_e, cb) => { finish = cb; }, - json: (body) => { res.sent = body; return res; }, + ...(render + ? { render: () => res } + : { json: (body) => { res.sent = body; return res; } }), }; try { middleware(req, res, () => {}); + res.statusCode = status; + if (err) { + middleware.logError(res, err); + } + if (sent) { + res.json(sent); + } finish(); } finally { logger.log = log; @@ -36,111 +48,151 @@ describe('request logger', function() { config.logrequests = config.env !== 'test'; }); - it('should log every request when true', () => { - config.logrequests = true; - assert.strictEqual(run(200).length, 1); - assert.strictEqual(run(500).length, 1); - }); - - it('should log nothing when false', () => { - config.logrequests = false; - assert.strictEqual(run(200).length, 0); - assert.strictEqual(run(500).length, 0); - }); - - // The point of the floor: successes are the volume, errors are the signal. - it('should keep only the errors above a status floor', () => { - config.logrequests = 400; - assert.strictEqual(run(200).length, 0); - assert.strictEqual(run(304).length, 0); - assert.strictEqual(run(400).length, 1); - assert.strictEqual(run(500).length, 1); - }); - - it('should pick the level from the status', () => { - config.logrequests = true; - assert.strictEqual(run(200)[0].level, 'info'); - assert.strictEqual(run(404)[0].level, 'warn'); - assert.strictEqual(run(500)[0].level, 'error'); - }); - - // A 400 without its body is diagnosed by guesswork, and a 500 rarely - // reproduces on demand. - it('should carry the request context when the response is an error', () => { - config.logrequests = true; - const { meta } = run(500, { body: { title: 'Dune' }, query: { page: '2' } })[0]; - assert.deepStrictEqual(meta.body, { title: 'Dune' }); - assert.deepStrictEqual(meta.query, { page: '2' }); - }); - - it('should carry no context on a successful response', () => { - config.logrequests = true; - const { meta } = run(200, { body: { title: 'Dune' } })[0]; - assert.strictEqual(meta.body, undefined); - }); - - // The point of going through redact(): a failed sign-in must not drop a - // password into the logs, where it would be kept and searchable. - it('should redact sensitive fields of the body', () => { - config.logrequests = true; - const { meta } = run(401, { - body: { email: 'a@b.c', motDePasse: 'sup3rS3cret', password: 'other' }, - })[0]; - assert.strictEqual(meta.body.motDePasse, '[redacted]'); - assert.strictEqual(meta.body.password, '[redacted]'); - assert.strictEqual(meta.body.email, 'a@b.c'); + describe('what a line carries', function() { + + beforeEach(function() { + config.logrequests = true; + }); + + // query and params are on a successful line too: what was asked is part of + // reading it, and neither weighs on the volume the way a body does. + it('should carry the request, what it asked and how long it took', () => { + const { message, meta } = run(200, { + query: { page: '2' }, + params: { id: '42' }, + })[0]; + assert.strictEqual(message, 'request'); + assert.strictEqual(meta.method, 'GET'); + assert.strictEqual(meta.path, '/api/books'); + assert.strictEqual(meta.status, 200); + assert.strictEqual(typeof meta.duration_ms, 'number'); + assert.strictEqual(meta.query, '{"page":"2"}'); + assert.strictEqual(meta.params, '{"id":"42"}'); + }); + + it('should pick the level from the status', () => { + assert.strictEqual(run(200)[0].level, 'info'); + assert.strictEqual(run(404)[0].level, 'warn'); + assert.strictEqual(run(500)[0].level, 'error'); + }); + + it('should carry no query or params when they are empty', () => { + const { meta } = run(200)[0]; + assert.strictEqual(meta.query, undefined); + assert.strictEqual(meta.params, undefined); + }); + + // The body and the response are the volume: a served request has nothing + // to explain, so it carries neither. + it('should carry no body, response or stack on success', () => { + const { meta } = run(200, { body: { title: 'Dune' }, sent: { id: 1 } })[0]; + assert.strictEqual(meta.body, undefined); + assert.strictEqual(meta.response, undefined); + assert.strictEqual(meta.stack, undefined); + }); + + // A 400 without its body is diagnosed by guesswork, and a 500 rarely + // reproduces on demand. + it('should carry the body and the response of an error', () => { + const { meta } = run(422, { + body: { title: 'Dune' }, + sent: { type: 'urn:igo:validation-failed', status: 422 }, + })[0]; + assert.strictEqual(meta.body, '{"title":"Dune"}'); + assert.strictEqual(meta.response, + '{"type":"urn:igo:validation-failed","status":422}'); + }); }); - it('should truncate an oversized body', () => { - config.logrequests = true; - const { meta } = run(400, { body: { blob: 'x'.repeat(5000) } })[0]; - assert.strictEqual(typeof meta.body, 'string'); - assert.match(meta.body, /chars\)$/); - }); - - // The response is what the client was actually answered: without it, a - // problem document has to be inferred from the status alone. - it('should carry the response body of an error', () => { - config.logrequests = true; - const lines = []; - const log = logger.log; - logger.log = (level, message, meta) => lines.push({ level, message, meta }); - - let finish; - const req = { method: 'POST', originalUrl: '/api/books', headers: {} }; - const res = { - statusCode: 200, - setHeader: () => {}, - on: (_e, cb) => { finish = cb; }, - json: (body) => { res.sent = body; return res; }, - }; - - try { - middleware(req, res, () => {}); - res.statusCode = 422; - res.json({ type: 'urn:igo:validation-failed', status: 422 }); - finish(); - } finally { - logger.log = log; - } - - assert.deepStrictEqual(lines[0].meta.response, - { type: 'urn:igo:validation-failed', status: 422 }); + describe('config.logrequests', function() { + + it('should log every request when true', () => { + config.logrequests = true; + assert.strictEqual(run(200).length, 1); + assert.strictEqual(run(500).length, 1); + }); + + it('should log nothing when false', () => { + config.logrequests = false; + assert.strictEqual(run(200).length, 0); + assert.strictEqual(run(500).length, 0); + }); + + // The point of the floor: successes are the volume, errors are the signal. + it('should keep only the errors above a status floor', () => { + config.logrequests = 400; + assert.strictEqual(run(200).length, 0); + assert.strictEqual(run(304).length, 0); + assert.strictEqual(run(400).length, 1); + assert.strictEqual(run(500).length, 1); + }); }); - it('should carry no response body on success', () => { - config.logrequests = true; - const { meta } = run(200)[0]; - assert.strictEqual(meta.response, undefined); + describe('a failed request is one line', function() { + + beforeEach(function() { + config.logrequests = true; + }); + + it('should make the error the message, and carry its stack', () => { + const { message, meta } = run(500, { + err: new Error('connection refused to 10.0.0.5:3306'), + sent: { type: 'about:blank', title: 'Internal Server Error', status: 500 }, + })[0]; + assert.strictEqual(message, 'Error: connection refused to 10.0.0.5:3306'); + assert.match(meta.stack, /^Error: connection refused/); + }); + + // A 500 answers with an empty problem body in production, on purpose: the + // reason it failed would be nowhere if the log followed suit. + it('should name the error a censored response does not', () => { + const { message, meta } = run(500, { + err: new Error('connection refused to 10.0.0.5:3306'), + sent: { type: 'about:blank', title: 'Internal Server Error', status: 500 }, + })[0]; + assert.match(message, /connection refused/); + // what the client got stays what the client got + assert.strictEqual(JSON.parse(meta.response).detail, undefined); + }); + + // logError is called before the handler branches on the request being an + // API one: a server-rendered route reports the same way, minus the JSON + // response it never sent. + it('should report a page route the same way', () => { + const { message, meta } = run(500, { + originalUrl: '/dossiers/42/valider', + err: new Error('ECONNREFUSED mysql'), + render: true, + })[0]; + assert.strictEqual(message, 'Error: ECONNREFUSED mysql'); + assert.match(meta.stack, /^Error: ECONNREFUSED mysql/); + assert.strictEqual(meta.response, undefined); + }); }); - it('should carry method, path, status and duration', () => { - config.logrequests = true; - const { meta } = run(200)[0]; - assert.strictEqual(meta.method, 'GET'); - assert.strictEqual(meta.path, '/api/books'); - assert.strictEqual(meta.status, 200); - assert.strictEqual(typeof meta.duration_ms, 'number'); + describe('what never reaches the logs', function() { + + beforeEach(function() { + config.logrequests = true; + }); + + // The point of going through redact(): a failed sign-in must not drop a + // password into the logs, where it would be kept and searchable. + it('should redact sensitive fields of the body', () => { + const { meta } = run(401, { + body: { email: 'a@b.c', motDePasse: 'sup3rS3cret', password: 'other' }, + })[0]; + const body = JSON.parse(meta.body); + assert.strictEqual(body.motDePasse, '[redacted]'); + assert.strictEqual(body.password, '[redacted]'); + assert.strictEqual(body.email, 'a@b.c'); + }); + + it('should truncate an oversized body', () => { + const { meta } = run(400, { body: { blob: 'x'.repeat(5000) } })[0]; + assert.strictEqual(typeof meta.body, 'string'); + assert.match(meta.body, /chars\)$/); + }); }); }); From df4158f5844e5081c83db815487b42390a2ac707 Mon Sep 17 00:00:00 2001 From: Mickael Coquer Date: Wed, 23 Sep 2026 11:21:16 +0200 Subject: [PATCH 3/3] =?UTF-8?q?fix(server):=20corrections=20issues=20de=20?= =?UTF-8?q?la=20revue=20de=20l'arr=C3=AAt=20propre=20et=20des=20logs?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Le garde-fou d'arrêt était désarmé par son propre unref(). Une fois le serveur HTTP fermé, plus aucun handle ne maintenait la boucle : un arrêt bloqué la laissait se vider et sortait en 0, silencieusement, en se faisant passer pour un arrêt réussi. Le minuteur reste désormais référencé et est annulé dans un finally. La fixture « hang » ne voyait rien parce qu'elle laissait le serveur à l'écoute ; elle le ferme maintenant avant de bloquer, et le test échoue bien sans le correctif. Une 500 disparaissait entièrement sous LOG_REQUESTS=false. Depuis que l'erreur voyage sur la ligne « request », son écriture passait par shouldLog(), là où l'ancien logger.error était inconditionnel. Le réglage coupe le journal d'accès, pas le signalement d'un plantage. Db.close() pouvait ne jamais rendre la main : la connexion gardée d'un test restait empruntée, et pool.end() l'attendait. Elle est rendue avant le drain. getConnection() vérifie aussi closed, pour les helpers de transaction qui ne passent pas par query() ; et query() teste closed avant pool, sans quoi un pool nul menait à init(), qui rouvrait la base et remettait closed à false. cache.scan() et flush() déréférençaient un client que close() venait de nuller : le contrat est un miss, pas un TypeError. La disponibilité est revérifiée à chaque aller-retour. closing reste levé après close() pour faire taire le listener du client démonté, et init() l'abaisse. ShutdownTest ne dépend plus de l'ordre alphabétique des fichiers pour rendre une readiness propre. Co-Authored-By: Claude Opus 5 (1M context) --- packages/db/src/Db.js | 19 +++++++++++++------ packages/server/src/app.js | 10 ++++++---- packages/server/src/cache.js | 15 ++++++++++----- packages/server/src/connect/requestlogger.js | 9 +++++++-- packages/server/test/RequestLoggerTest.js | 13 +++++++++++++ packages/server/test/ShutdownTest.js | 7 ++++--- packages/server/test/fixtures/shutdown.cjs | 2 ++ 7 files changed, 55 insertions(+), 20 deletions(-) diff --git a/packages/db/src/Db.js b/packages/db/src/Db.js index 7f2510d1..d1adf67a 100644 --- a/packages/db/src/Db.js +++ b/packages/db/src/Db.js @@ -51,11 +51,15 @@ class Db { if (this.closed) { return; } - // before awaiting the drain: query() must not reopen the pool in between this.closed = true; - const { pool } = this; + const { pool, connection } = this; this.pool = null; this.connection = null; + // a connection kept across queries is still checked out, and + // the pool would wait for it to come back before ending + if (connection) { + this.driver.release(connection); + } if (pool) { await this.driver.closePool(pool); } @@ -64,6 +68,9 @@ class Db { // async getConnection() { const { driver, pool, TEST_ENV } = this; + if (this.closed) { + throw new Error(`Db '${this.name}' is closed: the application is shutting down.`); + } // if connection is in local storage if (TEST_ENV && this.connection) { // console.log('keep same connection'); @@ -114,14 +121,14 @@ class Db { } }; - if (this.pool) { - return await runquery(); - } - if (this.closed) { throw new Error(`Db '${this.name}' is closed: the application is shutting down.`); } + if (this.pool) { + return await runquery(); + } + logger.info('Db.query: Trying to reinitialize db connection pool'); await this.init(); if (!this.pool) { diff --git a/packages/server/src/app.js b/packages/server/src/app.js index 1e3d1f54..9eec74a3 100644 --- a/packages/server/src/app.js +++ b/packages/server/src/app.js @@ -211,15 +211,17 @@ const onSignal = (signal) => async () => { logger.info(`${signal} received`); // a shutdown that hangs is worse than an abrupt one: the process manager sends - // SIGKILL in the end anyway, and this at least leaves a log saying where it hung + // SIGKILL in the end anyway, and this at least leaves a log saying where it hung. const timer = setTimeout(() => { logger.error(`Shutdown: still running after ${config.shutdownTimeout}ms, exiting`); process.exit(1); }, config.shutdownTimeout); - timer.unref(); - await module.exports.shutdown(); - clearTimeout(timer); + try { + await module.exports.shutdown(); + } finally { + clearTimeout(timer); + } process.exit(0); }; diff --git a/packages/server/src/cache.js b/packages/server/src/cache.js index 87a8ff3c..fe6ac1a8 100644 --- a/packages/server/src/cache.js +++ b/packages/server/src/cache.js @@ -38,6 +38,7 @@ module.exports.init = async () => { return; } options = config.redis; + closing = false; client = redis.createClient(options); // reads go through a buffer-typed view of the same connection: values are binary @@ -217,12 +218,15 @@ module.exports.flushall = async () => { // scan keys // - fn is invoked with (key) parameter for each key matching the pattern module.exports.scan = async (pattern, fn) => { - if (!available()) { - return; - } let cursor = '0'; do { + // checked every round trip, not once: a shutdown can close the client + // mid-scan, and a miss is the contract here, not a TypeError on a + // dropped one + if (!available()) { + return; + } const result = await client.scan(cursor, { MATCH: pattern, COUNT: 100, @@ -241,6 +245,9 @@ module.exports.scan = async (pattern, fn) => { module.exports.flush = async (pattern) => { await module.exports.scan(pattern, async (key) => { // console.log('DEL: ' + key); + if (!available()) { + return; + } await client.del(key); }); }; @@ -261,8 +268,6 @@ module.exports.close = async () => { // redis already gone: nothing left to close, and the socket dies with the process logger.warn(`Cache: ${err.message}`); closed.destroy(); - } finally { - closing = false; } }; diff --git a/packages/server/src/connect/requestlogger.js b/packages/server/src/connect/requestlogger.js index af03c8ef..63dd6dac 100644 --- a/packages/server/src/connect/requestlogger.js +++ b/packages/server/src/connect/requestlogger.js @@ -124,7 +124,12 @@ const levelFor = (status) => { // config.logrequests: a boolean, or a status floor — 400 keeps the errors, // which are worth every byte, and drops the successes metrics already cover. -const shouldLog = (status) => { +// An error the handler caught is never dropped: the setting turns off the +// access log, not the reporting of a crash, whose line is the only trace left. +const shouldLog = (status, failed) => { + if (failed) { + return true; + } const setting = config.logrequests; if (setting === false) { return false; @@ -157,7 +162,7 @@ module.exports = (req, res, next) => { // mock responses in tests are plain objects, with no events to listen to if (typeof res.on === 'function') { res.on('finish', () => { - if (!shouldLog(res.statusCode)) { + if (!shouldLog(res.statusCode, !!res._loggedError)) { return; } const duration = Number(process.hrtime.bigint() - start) / 1e6; diff --git a/packages/server/test/RequestLoggerTest.js b/packages/server/test/RequestLoggerTest.js index 532ede3f..5305de69 100644 --- a/packages/server/test/RequestLoggerTest.js +++ b/packages/server/test/RequestLoggerTest.js @@ -126,6 +126,19 @@ describe('request logger', function() { assert.strictEqual(run(400).length, 1); assert.strictEqual(run(500).length, 1); }); + + // The setting turns off the access log, not the reporting of a crash: + // since the error rides on this line, dropping it would lose the only + // trace of what failed. + it('should log a caught error whatever the setting says', () => { + config.logrequests = false; + const lines = run(500, { err: new Error('boom') }); + assert.strictEqual(lines.length, 1); + assert.strictEqual(lines[0].message, 'Error: boom'); + + config.logrequests = 599; + assert.strictEqual(run(500, { err: new Error('boom') }).length, 1); + }); }); describe('a failed request is one line', function() { diff --git a/packages/server/test/ShutdownTest.js b/packages/server/test/ShutdownTest.js index 68ac1710..7a1c6a68 100644 --- a/packages/server/test/ShutdownTest.js +++ b/packages/server/test/ShutdownTest.js @@ -35,6 +35,10 @@ const freshApp = () => { describe('Shutdown', function() { this.timeout(20000); + // every shutdown() drains readiness, so each test leaves it raised — for the + // next one, and for whatever file runs after this one + afterEach(() => health.drain(false)); + describe('app.shutdown()', function() { let dbsClose, cacheClose, onShutdown; @@ -113,9 +117,6 @@ describe('Shutdown', function() { describe('readiness while draining', function() { - // the shutdown tests above drained the shared module - beforeEach(() => health.drain(false)); - it('should answer 503 so the load balancer takes the instance out', async () => { const agent = require('@igojs/server').dev.agent; const before = await agent.get('/health/ready'); diff --git a/packages/server/test/fixtures/shutdown.cjs b/packages/server/test/fixtures/shutdown.cjs index ba719ef3..81c37a16 100644 --- a/packages/server/test/fixtures/shutdown.cjs +++ b/packages/server/test/fixtures/shutdown.cjs @@ -29,7 +29,9 @@ const app = require('../../src/app'); app.configure = async () => {}; app.shutdown = async () => { say('shutdown'); + // closes the last handle before hanging, as the real shutdown does if (mode === 'hang') { + await new Promise(resolve => app.server.close(resolve)); await new Promise(() => {}); } // long enough that the second signal of the 'twice' scenario lands while