Request Logging and Operational vs Programmer Errors

Objectives

By the end of this lesson, you should be able to:

• Add request logging middleware to an Express app with pino-http
• Log within a route using req.log, tied to that specific request
• Distinguish operational errors from programmer errors in an error handler, and log each differently

💡 Why this matters: A logger that isn’t wired into the request lifecycle can’t answer “which request caused this error?”, pino-http ties every log line to the request it came from, and the error handler is where operational and programmer errors, a distinction from Node.js & Express Foundations, finally matter for logging specifically.

⚠️ A note on verification: every snippet and every output in this lesson was actually run.

Installing pino-http

npm install pino-http

Wiring It Into Express

const express = require('express');
const pino = require('pino');
const pinoHttp = require('pino-http');

const logger = pino();
const app = express();
app.use(express.json());
app.use(pinoHttp({ logger }));

app.get('/api/v1/health', (req, res) => {
  req.log.info('Health check requested');
  res.json({ status: 'ok' });
});

pinoHttp({ logger }) adds req.log, a Pino logger already tagged with information about the current request, and automatically logs one line when the request completes. Inside a route, req.log.info(...) (rather than the plain logger from the last lesson) is what ties a log line to the specific request that produced it.

What a Request Actually Logs

{"level":30,"req":{"id":1,"method":"GET","url":"/api/v1/health"},"msg":"Health check requested"}
{"level":30,"req":{"id":1,"method":"GET","url":"/api/v1/health"},"res":{"statusCode":200},"responseTime":5,"msg":"request completed"}

Two lines for one request, the explicit req.log.info(...) call inside the route, and an automatic “request completed” summary line from pino-http itself, both share the same req.id, in a real log aggregation tool, filtering by that id shows every line that request produced, exactly the “tie logs to a request” problem the first lesson raised.

Operational vs Programmer Errors, Logged Differently

class AppError extends Error {
  constructor(message, status) {
    super(message);
    this.status = status;
    this.isOperational = true;
  }
}

app.get('/api/v1/items/:id', (req, res, next) => {
  if (req.params.id === '404') {
    return next(new AppError('Item not found', 404));
  }
  if (req.params.id === 'crash') {
    return next(new Error('Unexpected null reference'));
  }
  res.json({ id: req.params.id });
});

app.use((err, req, res, next) => {
  const status = err.status || 500;
  if (err.isOperational) {
    req.log.warn({ status, err: err.message }, 'Operational error handled');
  } else {
    req.log.error({ status, err }, 'Unexpected error, not marked operational');
  }
  res.status(status).json({ error: err.isOperational ? err.message : 'Internal server error' });
});

An operational error, a 404 for a missing item, a validation failure, is an expected, routine outcome, logged at warn, without a full stack trace cluttering the log, since there’s nothing to fix in the code. A programmer error, a bug, an unhandled null reference, is unexpected, logged at error, with the full error object, including its stack, since this is exactly the kind of thing someone needs to actually go fix.

The Output for Each Case

{"level":40,"status":404,"err":"Item not found","msg":"Operational error handled"}

{"level":50,"status":500,"err":{"type":"Error","message":"Unexpected null reference","stack":"Error: Unexpected null reference\n    at ..."},"msg":"Unexpected error, not marked operational"}

level: 40 (warn) for the expected 404, a short message, no stack trace needed. level: 50 (error) for the unexpected crash, the full error object attached, this is the line a real monitoring system would alert on, the 404 line, correctly, wouldn’t trigger anything.

Why This Distinction Matters for Monitoring

A production monitoring system typically alerts on error-level logs, if every error, expected 404s included, logged at error, alerts would fire constantly for routine, harmless events, and the team would eventually start ignoring them entirely. Logging operational errors at warn and reserving error for genuine, unexpected failures is what keeps error-level alerts meaningful.

Try It

1. Wire pinoHttp into an Express app, add a route logging with req.log, and confirm the request-completion line and your explicit log line share the same req.id.
2. Build the AppError class and the error handler above, and confirm a 404 logs at warn while an unmarked error logs at error.
3. Add a third case, an authentication failure (401, isOperational: true), and confirm it logs at warn, not error.
4. Explain, in one or two sentences, what would go wrong for a team relying on error-level alerts if every 404 in the application logged at error instead of warn.

Recap

• pinoHttp({ logger }) adds req.log and automatic request-completion logging, tying every log line to the request that produced it via a shared req.id.
• Operational errors, expected, routine failures, log at warn, programmer errors, unexpected bugs, log at error with the full stack trace.
• This distinction is what keeps error-level alerts meaningful, reserved for failures that genuinely need someone’s attention.

Next lesson: exercises, building complete request and error logging for a route combining authentication, validation, and rate limiting.