Structured Logging
Write every log line as one JSON object so a search tool can filter by field, and keep secrets out of them.
logger.info({ orderId, userId }, 'charge failed')A log line is text your program writes while it runs. Node writes it to stdout, the output stream every process is given for its normal output. In a terminal, stdout is your screen. On a server, the platform collects stdout and ships it to a log search tool. Your program does not open a log file. It writes to stdout and something else stores it.
Sentences are hard to search. console.log('user 7 signed in') gives a tool nothing to filter on. Write one JSON object per line instead, with the same field names every time, and the tool can answer "every error for user 7 in the last hour".
Levels
Each line carries a level: debug, info, warn, error. The level is a number behind a name (pino uses debug 20, info 30, warn 40, error 50). The logger drops anything below a configured threshold, so debug lines can stay in the code and be switched off in production through an environment variable, a named value the platform hands the process at startup.
What not to log
Passwords, tokens, card numbers, whole request bodies. Logs are copied, indexed and kept for months. Redact by field name once, in the logger, not at each call site.
Object shorthand keeps the fields short: { orderId } is the same thing as { orderId: orderId }.
Example
When to use it
- Find every log line belonging to one failed checkout, across a day of traffic.
- Turn debug logging on for one deployment by changing LOG_LEVEL, without a code change.
- Alert when the count of level=error lines for a route rises above its normal rate.
- Prove no authorization header was ever written to the log store.
More examples
One line per request
The access log most services want: method, path, status, duration, one JSON object per request. The work happens in the response's 'finish' event, so the status code is already known. Reach for this as the first thing you add to a new service, before any metrics.
const http = require('node:http');
function log(fields) {
console.log(JSON.stringify({ level: 'info', ...fields }));
}
http.createServer((req, res) => {
const started = process.hrtime.bigint(); // monotonic clock, in nanoseconds
res.on('finish', () => {
const ns = process.hrtime.bigint() - started;
log({
msg: 'request',
method: req.method,
path: req.url,
status: res.statusCode,
durationMs: Number(ns) / 1e6,
});
});
res.writeHead(200, { 'content-type': 'application/json' });
res.end('{"ok":true}');
}).listen(3000);pino configured once for the whole service
pino writes JSON at a speed that does not show up in request latency, and its argument order is object first, message second. Redaction configured here cannot be forgotten at a call site. Use this once a service has more than a handful of log calls.
// logger.js - imported everywhere, configured here only.
const pino = require('pino');
const logger = pino({
level: process.env.LOG_LEVEL ?? 'info',
// Paths whose values are replaced before the line is written.
redact: {
paths: ['req.headers.authorization', 'req.headers.cookie', '*.password', '*.token'],
censor: '[redacted]',
},
base: { service: 'orders' }, // added to every line
});
module.exports = logger;
// elsewhere: the merging object comes FIRST, the message second
logger.info({ orderId: 'A-1', amountCents: 2500 }, 'order created');
logger.error({ err, orderId: 'A-1' }, 'charge failed');A child logger that carries fixed fields
Without a child logger, every call in a function repeats the same two or three identifying fields and one of them eventually gets left out. Create a child at the top of a unit of work and use it for the rest of that work.
const logger = require('./logger');
function handleOrder(order) {
// A child logger repeats these fields on every line it writes.
const log = logger.child({ orderId: order.id, userId: order.userId });
log.info('validating');
log.info({ itemCount: order.items.length }, 'reserving stock');
log.warn({ retry: 1 }, 'warehouse slow');
}
Discussion