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.
On this page · 6 min · Advanced
On this page
- Learning objectives
- Explanation
- Syntax
- Code example
- Step by step
- Real-world use
- Common mistakes
- Best practices
- Remember this
- Practice exercise
- Mini quiz
- Related topics
- My notes
- Reading time
- 6 min
- Difficulty
- Advanced
- Updated
- Oct 28, 2026
Related tutorials
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#
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#
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();
});
{"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#
- requestLogger reuses an incoming X-Request-Id or creates one, and attaches a child logger as req.log.
- The debug line is filtered out at level info.
- The business event and the summary for request 2 share requestId req-2; the Authorization header is redacted.
- The 404 is logged at warn (40) with the browser’s request id.
- 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#
Unstructured lines without request ids cannot be correlated or filtered at scale.
Bodies contain passwords, tokens and personal data. Log selected fields and redact the rest.
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?
Show solution
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#
What does logger.child({ requestId }) give you?
Want more? Practise all Node.js REST API MCQs · Node.js REST API interview questions
My notes#
Saved in this browser.