Node.js In-Depth
Module P-8·26 min read

Structured logging with Pino, correlation IDs, multi-stage Docker builds, docker-compose for local dev, PM2 cluster mode, and GitHub Actions CI/CD.

Written by Jatin Jain Saraf · Architect of SupraScan

Module P-8 — Logging, Observability Basics, and Deployment

What this module covers: console.log doesn't scale. When your API handles thousands of requests per second across multiple servers, you need structured logs you can query, correlation IDs that link a request across every log line, metrics that tell you how the system is doing in aggregate, and a deployment pipeline that gets code to production without manual steps. This module covers structured logging with Pino, AsyncLocalStorage-based correlation IDs, RED/USE application metrics with prom-client, multi-stage Docker builds that produce lean production images, docker-compose for local development, PM2 for running Node.js processes in production (with log rotation), and a GitHub Actions pipeline that tests, builds, and deploys on every push to main.

Why Structured Logging

console.log('User logged in: ' + userId) produces a string. You can't query it, you can't filter it, you can't aggregate it. Structured logging produces JSON:

{
  "level": "info",
  "time": "2024-05-22T14:32:01.123Z",
  "msg": "User logged in",
  "userId": 42,
  "requestId": "f8a2e9c1-4b5d-4f3a-8e6c-2d1a7b3f9e4c",
  "ip": "203.0.113.42",
  "durationMs": 183
}

Now you can run WHERE msg = 'User logged in' AND durationMs > 500 to find slow logins. You can group by userId to see all activity for a user. You can set up alerts on level = 'error'.

Structured logs are console.log wearing a lab coat and carrying a barcode scanner — every entry can be scanned, sorted, and cross-referenced instead of read one at a time under a flashlight.

Pino: Fast Structured Logging

Pino is the fastest JSON logger for Node.js. It is designed to minimise work on the hot path — log entries are serialised asynchronously.

npm install pino pino-pretty
npm install -D @types/pino

Logger singleton

// src/utils/logger.ts
import pino from 'pino';
import { env } from '../config/env.js';
 
const logger = pino({
  level: env.LOG_LEVEL ?? 'info',
 
  // In development: pretty-print for readability
  // In production: raw JSON for log aggregators (Datadog, Loki, CloudWatch)
  transport: env.NODE_ENV === 'development'
    ? {
        target: 'pino-pretty',
        options: {
          colorize: true,
          translateTime: 'HH:MM:ss.l',
          ignore: 'pid,hostname',
        },
      }
    : undefined,
 
  // Redact sensitive fields from all log entries
  redact: {
    paths: ['req.headers.authorization', 'body.password', 'body.passwordHash'],
    censor: '[REDACTED]',
  },
 
  // Base fields added to every log entry
  base: {
    env: env.NODE_ENV,
    version: process.env.npm_package_version,
  },
 
  // Serialisers — control how objects are formatted
  serializers: {
    err: pino.stdSerializers.err,  // properly serialise Error objects
    req: pino.stdSerializers.req,
    res: pino.stdSerializers.res,
  },
});
 
export default logger;

Using the logger

import logger from '../utils/logger.js';
 
// Info — normal operations
logger.info({ userId: 42, orderId: 7 }, 'Order created');
 
// Warn — unexpected but recoverable
logger.warn({ attemptCount: 3, ip: req.ip }, 'Failed login attempt');
 
// Error — errors that need attention
logger.error({ err, orderId: 7 }, 'Failed to send order confirmation email');
 
// Debug — verbose, off in production
logger.debug({ query: sql, params }, 'Executing query');
 
// Child loggers — add context for a specific scope
const requestLogger = logger.child({ requestId: req.requestId });
requestLogger.info('Processing payment');
requestLogger.info({ chargeId: 'ch_xxx' }, 'Payment succeeded');
// Both entries have requestId set automatically

Seeing Redaction Actually Work

The redact config on the logger above targets req.headers.authorization, body.password, and body.passwordHash — but that only does anything if a logged object is actually shaped that way. Logging the request and body on a login attempt is a realistic place this matters:

// src/controllers/auth.controller.ts
export const login = asyncHandler(async (req: Request, res: Response) => {
  logger.info({ req, body: req.body }, 'Login attempt');
  // ...
});
{
  "level": "info",
  "msg": "Login attempt",
  "req": { "headers": { "authorization": "[REDACTED]", "host": "api.myapp.com" } },
  "body": { "email": "user@example.com", "password": "[REDACTED]" }
}

email passes through untouched — only the paths named in redact.paths are censored. Without logging something shaped like { req, body }, the redact config is dead configuration that never runs against a matching field.

HTTP Request Logging Middleware

Log every incoming request with timing:

// src/middleware/httpLogger.ts
import { Request, Response, NextFunction } from 'express';
import logger from '../utils/logger.js';
 
export function httpLogger(req: Request, res: Response, next: NextFunction) {
  const start = Date.now();
 
  // Log when response finishes — not when request arrives
  res.on('finish', () => {
    const durationMs = Date.now() - start;
    const level = res.statusCode >= 500 ? 'error' : res.statusCode >= 400 ? 'warn' : 'info';
 
    logger[level]({
      requestId: req.requestId,
      method: req.method,
      url: req.originalUrl,
      statusCode: res.statusCode,
      durationMs,
      ip: req.ip,
      userAgent: req.headers['user-agent'],
      userId: req.user?.id,
    }, 'HTTP request');
  });
 
  next();
}
// src/app.ts
app.use(requestId);    // set req.requestId first
app.use(httpLogger);   // then log with the ID

Development output (pino-pretty):

14:32:01.123 INFO  HTTP request
    requestId: "f8a2e9c1"
    method: "POST"
    url: "/orders"
    statusCode: 201
    durationMs: 183
    userId: 42

Correlation IDs Across Services

When a request triggers calls to multiple services (or microservices), correlation IDs let you trace the full journey in logs:

// src/middleware/requestId.ts
import { randomUUID } from 'crypto';
 
export function requestId(req, res, next) {
  // Accept correlation ID from upstream (API gateway, frontend) or generate one
  req.requestId = req.headers['x-request-id'] as string ?? randomUUID();
  res.setHeader('x-request-id', req.requestId);
  next();
}

Pass the correlation ID when making outbound service calls:

export async function callPaymentService(orderId: number, requestId: string) {
  const response = await fetch(`${env.PAYMENT_SERVICE_URL}/charges`, {
    method: 'POST',
    headers: {
      'Content-Type': 'application/json',
      'X-Request-ID': requestId,  // propagate downstream
    },
    body: JSON.stringify({ orderId }),
  });
  return response.json();
}

Now grep requestId=f8a2e9c1 in your log aggregator shows every log line from every service for a single user request.

AsyncLocalStorage: Correlation IDs Without Manual Threading

callPaymentService(orderId, requestId) above works, but every function between the request handler and that call has to accept and forward a parameter that has nothing to do with its actual job. Add a second cross-cutting value (tenant ID, the acting user's ID for audit logs) and business logic starts carrying "plumbing" parameters it shouldn't need to know exist.

AsyncLocalStorage (built into Node's async_hooks module) fixes this: a value is attached to the current async execution context once, and anything called within that context — controllers, services, repositories, outbound fetch calls, arbitrarily deep — can read it back without it ever being passed as an argument.

// src/utils/context.ts
import { AsyncLocalStorage } from 'async_hooks';
 
interface RequestContext {
  requestId: string;
  userId?: number;
}
 
export const requestContext = new AsyncLocalStorage<RequestContext>();
 
export function getRequestId(): string | undefined {
  return requestContext.getStore()?.requestId;
}
// src/middleware/requestId.ts
import { randomUUID } from 'crypto';
import { requestContext } from '../utils/context.js';
 
export function requestId(req, res, next) {
  const id = (req.headers['x-request-id'] as string) ?? randomUUID();
  req.requestId = id;
  res.setHeader('x-request-id', id);
 
  // Everything downstream runs inside this callback and can read the
  // store without requestId being threaded through every signature
  requestContext.run({ requestId: id, userId: req.user?.id }, () => next());
}
// src/services/payments.service.ts — no requestId parameter anymore
import { getRequestId } from '../utils/context.js';
 
export async function callPaymentService(orderId: number) {
  const response = await fetch(`${env.PAYMENT_SERVICE_URL}/charges`, {
    method: 'POST',
    headers: {
      'Content-Type': 'application/json',
      'X-Request-ID': getRequestId() ?? 'unknown',
    },
    body: JSON.stringify({ orderId }),
  });
  return response.json();
}

The logger can read from the same store, so a request-scoped logger no longer needs requestId passed in explicitly either:

export function getRequestLogger() {
  const requestId = getRequestId();
  return requestId ? logger.child({ requestId }) : logger;
}

One important limit: AsyncLocalStorage context only survives within a single process's async call chain. It does not automatically cross a network hop or a job queue boundary — a BullMQ job runs in a separate worker process with its own (empty) ALS context, so the correlation ID has to be explicitly written into the job payload when enqueuing, then re-established with requestContext.run(...) at the top of the worker's processor function.

Production story: a UPI settlement flow crossed three hops — the merchant-facing API, a simulated NPCI switch call, and a BullMQ job that reconciled the settlement afterward. The correlation ID was threaded manually as a function parameter through the first two hops, but the code that enqueued the reconciliation job passed only the settlement payload — nobody remembered the request ID needed to travel with it too. When a settlement timed out, there was no single ID to grep for across all three log streams; the on-call engineer reconstructed what happened by eyeballing timestamps across the API logs, the switch simulator's logs, and the queue worker's logs, trying to guess which lines belonged to the same transaction. The fix wasn't AsyncLocalStorage by itself — it was making the correlation ID part of the job payload contract and re-entering requestContext.run() inside the worker, so the same ID that started the request was still attached to every log line the reconciliation job produced.

Multi-Stage Docker Build

Sign in to keep reading

The rest of this module is free — sign in with Google to unlock it and track your progress.

Sign in & Register
PreviousModule P-7: Connecting External Services and CachingNext Module P-9: WebSockets and Real-Time Communication

Discussion

0

Join the discussion

Loading comments...
PortfolioBlog

© 2026 Jatin Jain Saraf (JJS). All rights reserved.