Trust is earned, not given

A different perspective

2024-08-20 · Projects

Node.js, part 24: graceful shutdown, structured logs, and the end of console.log in production

Part 24from the Node.js series · 24 parts in all

A service is judged on its worst ten minutes, and the bugs that produce those ten minutes are almost never in your business logic. They are in shutdown, in logs that cannot be searched, and in an error handler that swallowed the stack. Part 24 closes the series with the operational floor every Node service should stand on.

Shutdown: the deploy that drops requests

const server = app.listen(3000);

let shuttingDown = false;
for (const signal of ['SIGTERM', 'SIGINT']) {
  process.on(signal, async () => {
    if (shuttingDown) return;        // a second Ctrl-C should not restart the dance
    shuttingDown = true;

    server.close();                  // stop accepting NEW connections
    await closeIdleConnections();    // your keep-alive sockets, if you hold them
    await drainInFlight();           // let the requests that are running finish
    await db.end();                  // release pooled resources

    // A hard deadline, or a stuck request keeps the process alive until the
    // orchestrator SIGKILLs it - worse than exiting early.
    setTimeout(() => process.exit(1), 10_000).unref();
    process.exit(0);
  });
}

server.close() is the important misunderstanding to fix: it stops new connections and waits for existing ones, so a naive handler that calls it and exits immediately still drops in-flight requests. The unref() on the deadline timer is the detail that makes it work — the timer must not itself hold the event loop open.

Logs: one JSON object per line, with the request id

function log(level, msg, extra = {}) {
  // AsyncLocalStorage carries the request id (part 10), so no call site
  // has to pass one in.
  const { requestId, userId } = store.getStore() || {};
  process.stdout.write(JSON.stringify({
    time: new Date().toISOString(), level, msg, requestId, userId, ...extra,
  }) + '\n');
}

app.use((req, res, next) => {
  const start = process.hrtime.bigint();
  res.on('finish', () => log('info', 'request', {
    method: req.method, path: req.path, status: res.statusCode,
    ms: Number(process.hrtime.bigint() - start) / 1e6,
  }));
  next();
});

Structured lines are searchable, aggregatable, and safe to ship to any collector. A console.log('user ' + id + ' failed') is none of those, and it is the single most common reason a production incident takes an hour instead of ten minutes.

The three rules this series keeps arriving at

  1. Measure before optimising. The profiler (part 14) and real timing beat intuition, which is wrong about Node's hot spots remarkably often.
  2. Prefer the platform to the package. Across 2018–2024 the platform absorbed promises, streams helpers, fetch, the test runner, the watcher, glob, WebSocket and the script runner, and every one of those was a dependency to audit and update.
  3. Handle the failure paths explicitly. The unhandled rejection, the unclosed stream, the shutdown that drops a request, the missing listener on 'error' — the difference between a service you can operate and one you merely deployed.

That is the series: twenty-four parts from the callback era to a runtime that ships its own test runner, HTTP client, and permission model. The code you write has not changed that much. What it can depend on has.