Handbooks / Node.js / Chapter 10
Logging and Debugging
7 pages · ~5 min✓ Reviewed
Builds on Testing Node Apps.
Observability and Debugging: The Mental Model
1. Structured Logging
- One JSON object per line:
level,time,msgplus fields - Machine-searchable, not free-text strings
{"level":30,"time":1730000000000,"msg":"login ok","userId":42}filter by userId, level or time
2. Tools and Where Logs Go
| Tool | Job |
|---|---|
| Logs | What happened in prod |
| Inspector | Step through live code |
| Heap snapshots | Why memory grows |
- Log to stdout only
- Docker, systemd, k8s collect and ship the logs
- App never manages files or rotation
3. console.log vs pino
| console.log | pino | |
|---|---|---|
| Format | unstructured text | JSON |
| Levels | none |
Pino and Log Levels
1. Setup and Levels
const logger = require('pino')({ level: process.env.LOG_LEVEL || 'info' }) logger.info({ userId }, 'login ok')
object first, message second
| trace | debug | info | warn | error | fatal |
|---|---|---|---|---|---|
| 10 | 20 |
Request IDs and Child Loggers
1. Request ID
- Request ID = unique ID per request, on every log line
- Filter one request's logs across the whole flow
- Reuse incoming
x-request-id, elsecrypto.randomUUID() - Echo it back in the response header
const id = req.headers['x-request-id'] || crypto.randomUUID(); res.setHeader('x-request-id', id); req.log = logger.child({ reqId: id });
middleware: one child logger per request
node --inspect, DevTools and --watch
1. Starting the inspector
node --inspect app.js: V8 inspector on 127.0.0.1:9229--inspect-brk: pauses on the first line- Set breakpoints before startup code runs
2. Attach and step through
- Run--inspect
- chrome://inspectopen in Chrome
- Click inspecton the target
- Sources tabdebug
Diagnosing Memory Leaks and Graceful Shutdown
1. Hunting a Leak
- heapUsed from
process.memoryUsage()keeps climbing after GC - Healthy: a sawtooth that stays level
- Leak: the sawtooth floor never returns to baseline
- 1Snapshot 1
- 2Run workload
- 3Snapshot 2
- 4Run again
- 5Snapshot 3
Node Debugging and Shutdown Cheat Sheet
1. Logging with pino
| Level | trace | debug | info | warn | error | fatal |
|---|---|---|---|---|---|---|
| Number | 10 | 20 | 30 | 40 | 50 | 60 |
Check yourself
Logger level is info. Which of these lines print: debug, info, warn?
infoandwarnprint.- A level logs itself and everything above it;
debug(20) is belowinfo(30).
logger.debug('a') logger.info('b') logger.warn('c')
Spot the bug: why does this drop in-flight requests on deploy?
process.exit(0)runs first, so the process dies beforeserver.close()can finish anything.