diff --git a/CHANGELOG.md b/CHANGELOG.md index 4e44b862..50dd0318 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,23 @@ # 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. +- **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 + +- **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/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/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..d1adf67a 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,12 +43,34 @@ 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; + } + this.closed = true; + 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); + } + } + // 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'); @@ -98,6 +121,10 @@ class Db { } }; + if (this.closed) { + throw new Error(`Db '${this.name}' is closed: the application is shutting down.`); + } + if (this.pool) { return await runquery(); } 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..9eec74a3 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,78 @@ 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); + + try { + await module.exports.shutdown(); + } finally { + 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 +232,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..fe6ac1a8 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(); @@ -37,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 @@ -44,6 +46,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; @@ -213,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, @@ -237,10 +245,32 @@ 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); }); }; +// 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(); + } +}; + // 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/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/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/src/connect/requestlogger.js b/packages/server/src/connect/requestlogger.js index fae2df96..63dd6dac 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) => { @@ -114,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; @@ -147,16 +162,19 @@ 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; - 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 +184,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..5305de69 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,164 @@ 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); + }); + + // 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); + }); }); - 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\)$/); + }); }); }); diff --git a/packages/server/test/ShutdownTest.js b/packages/server/test/ShutdownTest.js new file mode 100644 index 00000000..7a1c6a68 --- /dev/null +++ b/packages/server/test/ShutdownTest.js @@ -0,0 +1,155 @@ +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); + + // 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; + + 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() { + + 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..81c37a16 --- /dev/null +++ b/packages/server/test/fixtures/shutdown.cjs @@ -0,0 +1,62 @@ +// 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'); + // 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 + // 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); + } +});