Skip to main content
Node.js · lesson 7 of 20

Beginner

6

Intermediate

10

Advanced

4

Also part of Node.js

10
Open the Node.js page →
Node.js intermediate Lesson 7 of 20

Structured Logging with Pino

Replace console.log with Pino, attach a request id to every log line through pino-http's child logger, and read the one-line JSON it prints per request.

By SkillByExample · Updated

nodejs express pino logging

Pino prints one JSON object per log line instead of a formatted string, and pino-http attaches a per-request child logger that already carries that request’s id.

A Logger, and a Child Logger Per Request

// logger.js
import pino from "pino";

export const logger = pino({
  level: process.env.LOG_LEVEL ?? "info",
});
// server.js
import express from "express";
import { randomUUID } from "node:crypto";
import pinoHttp from "pino-http";
import { logger } from "./logger.js";

const app = express();

app.use(
  pinoHttp({
    logger,
    genReqId: (req) => req.headers["x-request-id"] ?? randomUUID().slice(0, 8),
  })
);
app.use(express.json());

const users = [{ id: 1, name: "Alice" }];

app.get("/users/:id", (req, res) => {
  const user = users.find((u) => u.id === Number(req.params.id));
  // req.log is a pino child logger with this request's id baked in already.
  if (!user) {
    req.log.warn({ userId: req.params.id }, "user lookup missed");
    res.status(404).json({ error: "not found" });
    return;
  }
  req.log.info({ userId: user.id }, "user lookup hit");
  res.json(user);
});

app.listen(3000, () => logger.info("listening on http://localhost:3000"));

"pid":1 below is real, not a placeholder — it’s only true because the server is started as the container’s own entrypoint process, not backgrounded inside a shell:

$ docker run -d --name pino-demo -v "$(pwd)":/root/node-api -w /root/node-api node:26 node server.js
d5595da6793af74c5a697a6519e349db2a430d41a5be3a3155d85606a616d9d0
$ docker exec pino-demo curl -s -H 'x-request-id: req-42' http://localhost:3000/users/1
{"id":1,"name":"Alice"}
$ docker exec pino-demo curl -s http://localhost:3000/users/99
{"error":"not found"}
$ docker logs pino-demo
{"level":30,"time":1793212492427,"pid":1,"hostname":"d5595da6793a","msg":"listening on http://localhost:3000"}
{"level":30,"time":1793212495739,"pid":1,"hostname":"d5595da6793a","req":{"id":"req-42","method":"GET","url":"/users/1","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*","x-request-id":"req-42"},"remoteAddress":"::1","remotePort":50166},"userId":1,"msg":"user lookup hit"}
{"level":30,"time":1793212495744,"pid":1,"hostname":"d5595da6793a","req":{"id":"req-42","method":"GET","url":"/users/1","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*","x-request-id":"req-42"},"remoteAddress":"::1","remotePort":50166},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"23","etag":"W/\"17-DSk1+U+0tpNEe1rQBEs8l28OulM\""}},"responseTime":6,"msg":"request completed"}
{"level":40,"time":1793212499669,"pid":1,"hostname":"d5595da6793a","req":{"id":"42f0bf02","method":"GET","url":"/users/99","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":50174},"userId":"99","msg":"user lookup missed"}
{"level":30,"time":1793212499669,"pid":1,"hostname":"d5595da6793a","req":{"id":"42f0bf02","method":"GET","url":"/users/99","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":50174},"res":{"statusCode":404,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"21","etag":"W/\"15-3jlv4LtvSUoQruAmr3ef7Px06u0\""}},"responseTime":0,"msg":"request completed"}

Every line is a single JSON object (time, pid, and hostname will differ on your machine). The req.id on the first two lines is "req-42" — the value we sent in x-request-id — while the last two show a generated "42f0bf02", because the second request sent no header at all. req.log.warn on a miss produced "level":40; req.log.info on a hit produced "level":30 — both lines still carry the same request’s req.id as the "request completed" line pino-http logs automatically right after, which is what makes it possible to grep one request’s whole story out of a log stream by its id alone.

Practice

1. Add a req.log.error call in a new route that always fails, and read the err object pino attaches.

Solution 
// server.js (added route)
app.get("/boom", (req, res) => {
  try {
    throw new Error("kaboom");
  } catch (err) {
    req.log.error({ err }, "handled boom");
    res.status(500).json({ error: "internal error" });
  }
});
$ docker restart pino-demo
pino-demo
$ docker exec pino-demo curl -s http://localhost:3000/boom
{"error":"internal error"}
$ docker logs --tail 2 pino-demo
{"level":50,"time":1793212541887,"pid":1,"hostname":"d5595da6793a","req":{"id":"ece9594c","method":"GET","url":"/boom","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":39412},"err":{"type":"Error","message":"kaboom","stack":"Error: kaboom\n    at file:///root/node-api/server.js:33:11\n    at Layer.handleRequest (/root/node-api/node_modules/router/lib/layer.js:152:17)\n    at next (/root/node-api/node_modules/router/lib/route.js:157:13)\n    at Route.dispatch (/root/node-api/node_modules/router/lib/route.js:117:3)\n    at handle (/root/node-api/node_modules/router/index.js:435:11)\n    at Layer.handleRequest (/root/node-api/node_modules/router/lib/layer.js:152:17)\n    at /root/node-api/node_modules/router/index.js:295:15\n    at processParams (/root/node-api/node_modules/router/index.js:582:12)\n    at next (/root/node-api/node_modules/router/index.js:291:5)\n    at read (/root/node-api/node_modules/body-parser/lib/read.js:59:5)"},"msg":"handled boom"}
{"level":30,"time":1793212541891,"pid":1,"hostname":"d5595da6793a","req":{"id":"ece9594c","method":"GET","url":"/boom","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":39412},"res":{"statusCode":500,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"26","etag":"W/\"1a-nO1SMtFqjAylRZvcD/JJ2LGv/qs\""}},"err":{"type":"Error","message":"failed with status code 500","stack":"Error: failed with status code 500\n    at onResFinished (/root/node-api/node_modules/pino-http/logger.js:115:39)\n    at ServerResponse.onResponseComplete (/root/node-api/node_modules/pino-http/logger.js:178:14)\n    at ServerResponse.emit (node:events:526:24)\n    at onFinish (node:_http_outgoing:1275:10)\n    at callback (node:internal/streams/writable:805:21)\n    at afterWrite (node:internal/streams/writable:749:5)\n    at afterWriteTick (node:internal/streams/writable:735:10)\n    at process.processTicksAndRejections (node:internal/process/task_queues:89:21)"},"responseTime":4,"msg":"request errored"}

Adding the route means the running server needs its file re-read, hence docker restart (the mounted file already has the new route; restart just re-execs node server.js), and --tail 2 here only grabs the two new lines instead of this container’s whole history. Passing { err } as the first argument gives Pino’s standard serializers a chance to expand the Error into type, message, and stack fields instead of logging an opaque [object Object] or losing the stack entirely. There’s a second line here too: pino-http’s own completion log isn’t always "msg":"request completed" — once the status code is 500 or higher it logs "msg":"request errored" instead, with its own synthetic err describing the failed response, not the original kaboom.

2. Set LOG_LEVEL=warn and confirm the “user lookup hit” info-level line disappears while the warn-level miss still logs.

Solution 
$ docker run -d --name pino-warn-demo -e LOG_LEVEL=warn -v "$(pwd)":/root/node-api -w /root/node-api node:26 node server.js
602c8855cc1a53a4f1ef55a50c631214b12126f883e982f38bdacbb48b6c1d4b
$ docker exec pino-warn-demo curl -s -o /dev/null http://localhost:3000/users/1
$ docker exec pino-warn-demo curl -s -o /dev/null http://localhost:3000/users/99
$ docker logs pino-warn-demo
{"level":40,"time":1793212280848,"pid":1,"hostname":"602c8855cc1a","req":{"id":"e5ecd3bb","method":"GET","url":"/users/99","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":52564},"userId":"99","msg":"user lookup missed"}

No "msg":"user lookup hit" line, no "msg":"listening on..." line (that’s info, level 30, now below the warn threshold of 40), and no "request completed" lines either — pino-http’s own completion log defaults to info. Only the one warn-level line survives the filter.

3. Add a child logger bound to a fixed { service: "users-api" } field at startup, and confirm every log line includes it.

Solution 
// logger.js (bound child logger)
import pino from "pino";

const baseLogger = pino({ level: process.env.LOG_LEVEL ?? "info" });
export const logger = baseLogger.child({ service: "users-api" });
$ docker run -d --name pino-service-demo -v "$(pwd)":/root/node-api -w /root/node-api node:26 node server.js
054c41483530ada6927db010727d49b492929fe07e12ab0930b9b39545629523
$ docker exec pino-service-demo curl -s -o /dev/null http://localhost:3000/users/1
$ docker logs pino-service-demo
{"level":30,"time":1793212312420,"pid":1,"hostname":"054c41483530","service":"users-api","msg":"listening on http://localhost:3000"}
{"level":30,"time":1793212315253,"pid":1,"hostname":"054c41483530","service":"users-api","req":{"id":"d9c5fe05","method":"GET","url":"/users/1","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":41126},"userId":1,"msg":"user lookup hit"}
{"level":30,"time":1793212315257,"pid":1,"hostname":"054c41483530","service":"users-api","req":{"id":"d9c5fe05","method":"GET","url":"/users/1","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":41126},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"23","etag":"W/\"17-DSk1+U+0tpNEe1rQBEs8l28OulM\""}},"responseTime":4,"msg":"request completed"}

"service":"users-api" appears on every line, including the ones produced through pinoHttp’s own req.log and its own "request completed" line, because pino-http was configured with this already-bound logger and every child logger it creates inherits the bindings of its parent.

4. Compare a request through curl with -H 'x-request-id;' (curl’s syntax for sending a header with a genuinely empty value) to one with no header at all.

Solution 
$ docker run -d --name pino-demo2 -v "$(pwd)":/root/node-api -w /root/node-api node:26 node server.js
f89e0152516a4293f1a47e6b27aa74457389f358eccfb9fdc9bf31ba60d72522
$ docker exec pino-demo2 curl -s -H 'x-request-id;' -o /dev/null http://localhost:3000/users/1
$ docker exec pino-demo2 curl -s -o /dev/null http://localhost:3000/users/1
$ docker logs pino-demo2
{"level":30,"time":1793281223884,"pid":1,"hostname":"f89e0152516a","msg":"listening on http://localhost:3000"}
{"level":30,"time":1793281225709,"pid":1,"hostname":"f89e0152516a","req":{"method":"GET","url":"/users/1","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*","x-request-id":""},"remoteAddress":"::1","remotePort":56552},"userId":1,"msg":"user lookup hit"}
{"level":30,"time":1793281225713,"pid":1,"hostname":"f89e0152516a","req":{"method":"GET","url":"/users/1","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*","x-request-id":""},"remoteAddress":"::1","remotePort":56552},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"23","etag":"W/\"17-DSk1+U+0tpNEe1rQBEs8l28OulM\""}},"responseTime":5,"msg":"request completed"}
{"level":30,"time":1793281229897,"pid":1,"hostname":"f89e0152516a","req":{"id":"f548d637","method":"GET","url":"/users/1","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":56564},"userId":1,"msg":"user lookup hit"}
{"level":30,"time":1793281229897,"pid":1,"hostname":"f89e0152516a","req":{"id":"f548d637","method":"GET","url":"/users/1","query":{},"params":{},"headers":{"host":"localhost:3000","user-agent":"curl/8.14.1","accept":"*/*"},"remoteAddress":"::1","remotePort":56564},"res":{"statusCode":200,"headers":{"x-powered-by":"Express","content-type":"application/json; charset=utf-8","content-length":"23","etag":"W/\"17-DSk1+U+0tpNEe1rQBEs8l28OulM\""}},"responseTime":0,"msg":"request completed"}

This is a fresh container, so docker logs starts from its own first line, "msg":"listening on http://localhost:3000", not just the two requests below it. Two things are easy to get wrong here. First, curl -H 'x-request-id: ' (colon, then nothing) doesn’t send an empty header at all — curl treats that as “remove this header”; curl -H 'x-request-id;' (semicolon) is what actually sends it with an empty value, visible in the request’s own headers.x-request-id: "". Second, req.headers["x-request-id"] ?? randomUUID()... sees "", which isn’t undefined or null, so ?? doesn’t fall back — genReqId really does return "". But the first pair of log lines has no "id" key in req at all, not "id":"": pino-http’s own request serializer only includes id when it’s truthy, so an empty string id disappears from the log entirely, silently, rather than showing up as an empty value. Only the second, header-less request gets a visible generated id ("f548d637") on both its "user lookup hit" and "request completed" lines.

Frequently Asked Questions

Why not just use console.log with a template string?
console.log produces text meant for a human reading a terminal, not a machine. Pino prints one JSON object per line, which a log aggregator (or jq, or grep) can filter and query on a specific field — like finding every line with a given request id — without parsing free-form text.
What does req.log give you that the top-level logger doesn't?
pino-http attaches a child logger to req.log for the duration of one request, pre-bound with that request's id. Every req.log.info/warn/error call in that request's handlers includes the id automatically, without passing it as an argument through every function.
What are the numbers 30 and 40 in "level":30?
Pino's numeric log levels: 10 trace, 20 debug, 30 info, 40 warn, 50 error, 60 fatal. The numeric form sorts and filters cheaply; a human-readable label can be added with a transport like pino-pretty in development.
Does genReqId need to produce a UUID?
No — it just needs to be unique enough to correlate log lines for one request. This lesson reads an incoming x-request-id header when the client sent one (useful for tracing a request across services) and falls back to a short random id otherwise.
What versions does this lesson use?
Pino 10.4.0 and pino-http 11.0.0, on Express 5.3.0 and Node 26.12.1 (Docker's node:26 image).