Node.js REST API · Delivery

Logging

When LearnHub misbehaves in production, logs must answer: which request, which user, how long, what failed? A per-request logger that records every request with its id, status and duration gives you that.

Advanced 6 min Lesson 21 of 25
0/25 in Node.js REST API
On this page · 6 min · Advanced

Learning objectives#

  • Create a child logger per request with a request id
  • Log one summary line per request with status and duration
  • Choose log levels from status codes
  • Log business events and errors without secrets

Explanation#

A middleware creates req.log = logger.child({ requestId }). Every log line written during that request — in controllers, services, the error handler — carries the request id automatically.

On res "finish", write one summary line: method, URL, status, durationMs. Level by outcome: 5xx → error, 4xx → warn, others → info. Dashboards and alerts build on these lines.

Log business events at info with structured fields (“enrollment created” { courseId, userId }) — they are invaluable when a customer asks “did my enrolment go through?”.

The error handler logs unexpected errors with req.log.error, including the stack in real apps.

Use redaction for authorization headers, passwords and tokens. The pino-http package provides a ready-made version of this middleware.

Syntax#

JavaScript Illustrative
app.use((req, res, next) => {
  req.log = logger.child({ requestId: req.get('x-request-id') ?? randomUUID() });
  const start = performance.now();
  res.on('finish', () => req.log.info({ status: res.statusCode, durationMs: Math.round(performance.now() - start) }, 'request completed'));
  next();
});

Code example: One logger per request#

JavaScriptrequest-logging.js Illustrative
import express from 'express';
import pino from 'pino';


const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  base: { service: 'learnhub-api' },
  timestamp: false,                                   // removed only to keep this demo short
  redact: ['headers.authorization'],
});


let counter = 0;                                       // real apps: incoming X-Request-Id or randomUUID()
function requestLogger(req, res, next) {
  req.id = req.get('x-request-id') ?? `req-${++counter}`;
  req.log = logger.child({ requestId: req.id });
  const start = performance.now();
  res.on('finish', () => {
    const level = res.statusCode >= 500 ? 'error' : res.statusCode >= 400 ? 'warn' : 'info';
    req.log[level]({ method: req.method, url: req.originalUrl, status: res.statusCode, durationMs: Math.round(performance.now() - start) }, 'request completed');
  });
  next();
}


const app = express();
app.use(express.json());
app.use(requestLogger);


app.get('/api/courses', (req, res) => {
  req.log.debug('loading courses from cache');        // hidden at level "info"
  res.json([{ id: 1 }]);
});
app.post('/api/courses/:id/enrollments', (req, res) => {
  req.log.info({ courseId: Number(req.params.id), userId: 7, headers: { authorization: req.get('authorization') } }, 'enrollment created');
  res.status(201).json({ ok: true });
});
app.get('/api/courses/:id', (req, res) => res.status(404).json({ error: 'Course not found' }));
app.get('/api/reports', () => { throw new Error('Report service timed out'); });


app.use((err, req, res, next) => {
  req.log.error({ error: err.message }, 'unhandled error');
  res.status(500).json({ error: 'Internal Server Error' });
});


const server = app.listen(3117, async () => {
  const base = 'http://localhost:3117/api';
  await fetch(base + '/courses');
  await fetch(base + '/courses/1/enrollments', { method: 'POST', headers: { Authorization: 'Bearer secret.jwt.token' } });
  await fetch(base + '/courses/99', { headers: { 'X-Request-Id': 'from-browser-42' } });
  await fetch(base + '/reports');
  server.close();
});
Expected output
{"level":30,"service":"learnhub-api","requestId":"req-1","method":"GET","url":"/api/courses","status":200,"durationMs":2,"msg":"request completed"}
{"level":30,"service":"learnhub-api","requestId":"req-2","courseId":1,"userId":7,"headers":{"authorization":"[Redacted]"},"msg":"enrollment created"}
{"level":30,"service":"learnhub-api","requestId":"req-2","method":"POST","url":"/api/courses/1/enrollments","status":201,"durationMs":1,"msg":"request completed"}
{"level":40,"service":"learnhub-api","requestId":"from-browser-42","method":"GET","url":"/api/courses/99","status":404,"durationMs":0,"msg":"request completed"}
{"level":50,"service":"learnhub-api","requestId":"req-3","error":"Report service timed out","msg":"unhandled error"}
{"level":50,"service":"learnhub-api","requestId":"req-3","method":"GET","url":"/api/reports","status":500,"durationMs":1,"msg":"request completed"}
(durationMs varies from run to run)

This example is illustrative. Copy or download it and run it in your own environment; the expected output is shown above.

Step-by-step explanation#

  1. requestLogger reuses an incoming X-Request-Id or creates one, and attaches a child logger as req.log.
  2. The debug line is filtered out at level info.
  3. The business event and the summary for request 2 share requestId req-2; the Authorization header is redacted.
  4. The 404 is logged at warn (40) with the browser’s request id.
  5. The crash logs an error line and a 500 summary at error (50), both linked by req-3.

Real-world use case#

An alert fires when more than 1% of LearnHub’s summary lines in five minutes are level 50. The on-call engineer filters by one requestId and sees the whole story of a failing request in order.

Common mistakes#

console.log in handlers

Unstructured lines without request ids cannot be correlated or filtered at scale.

Logging full request bodies

Bodies contain passwords, tokens and personal data. Log selected fields and redact the rest.

Everything at info

Without warn/error levels from status codes, alerting has nothing to key on.

Best practices#

  • Child logger per request with a request id
  • One summary line per request with duration
  • Level from status code
  • Redact secrets; log business events with ids

Remember this#

req.log = logger.child({ requestId }).

5xx → error · 4xx → warn · rest → info.

Same requestId on every line of one request.

Practice exercise#

Your task: Write levelFor(status, durationMs) that returns "error" for 5xx, "warn" for 4xx or any request slower than 1000 ms, and "info" otherwise.

Need a hint?
Check 5xx first, then 4xx or slowness.
Show solution
JavaScript Illustrative
const levelFor = (status, durationMs) =>
  status >= 500 ? 'error' : status >= 400 || durationMs > 1000 ? 'warn' : 'info';


console.log(levelFor(200, 35));     // info
console.log(levelFor(200, 2400));   // warn
console.log(levelFor(404, 5));      // warn
console.log(levelFor(503, 5));      // error

Mini quiz#

Logging quizMultiple choice Question 1 of 3

What does logger.child({ requestId }) give you?

Score so far: 0/0

Want more? Practise all Node.js REST API MCQs · Node.js REST API interview questions

My notes#

Saved in this browser.

Progress is saved in this browser. Sign in to sync.