Module P-8·25 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.

JJS

Written by Jatin Jain Saraf · Senior Software Engineer

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

Q: Why is structured logging (e.g., using Pino to output JSON) strongly preferred over standard `console.log` in production environments?

It allows logs to be easily queried, filtered, and aggregated by log management tools like Datadog or Loki. — Structured logging outputs machine-readable JSON. This allows you to run precise queries (e.g., filtering by `userId` or `durationMs`) and set up alerts, which is impossible with plain string logs.

Q: What is the primary benefit of using a multi-stage Docker build for a Node.js TypeScript application?

It creates a much smaller and more secure production image by omitting TypeScript source files and development dependencies. — A multi-stage build uses an initial stage to install all dependencies and compile the TypeScript code. The final stage only copies the compiled JavaScript and installs production dependencies, resulting in a lean, fast-booting image.

Q: What does OpenTelemetry (OTel) auto-instrumentation provide for a Node.js application without requiring any changes to your business logic code?

It generates distributed traces with spans for Express requests, database queries, Redis commands, and outbound HTTP calls. — By simply requiring the OTel auto-instrumentation package at startup, it monkey-patches core libraries (like Express, pg, and http) to automatically generate rich distributed traces showing exactly where time is spent during a request.

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:

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.

bash

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

Logger singleton

typescript

// 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

typescript

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:

typescript

// src/controllers/auth.controller.ts
export const login = asyncHandler(async (req: Request, res: Response) => {
  logger.info({ req, body: req.body }, 'Login attempt');
  // ...
});

json

{
  "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:

typescript

// 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();
}

typescript

// src/app.ts
app.use(requestId);    // set req.requestId first
app.use(httpLogger);   // then log with the ID

Development output (pino-pretty):

text

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:

typescript

// 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:

typescript

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.

typescript

// 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;
}

typescript

// 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());
}

typescript

// 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:

typescript

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

A naive Docker build copies node_modules including all dev dependencies, making the image hundreds of megabytes unnecessarily. Multi-stage builds fix this.

dockerfile

# Dockerfile

# ─── Stage 1: Build ──────────────────────────────────────────────────────────
FROM node:22-alpine AS builder

WORKDIR /app

# Install ALL dependencies (including devDependencies for TypeScript)
COPY package*.json ./
RUN npm ci

# Copy source and compile
COPY tsconfig.json ./
COPY src ./src
RUN npm run build   # outputs to /app/dist


# ─── Stage 2: Production image ───────────────────────────────────────────────
FROM node:22-alpine AS production

WORKDIR /app

# Create non-root user — never run Node.js as root
RUN addgroup -g 1001 nodejs && \
    adduser -S -u 1001 -G nodejs nodeuser

# Install only production dependencies
COPY package*.json ./
RUN npm ci --omit=dev && npm cache clean --force

# Copy compiled output from builder stage — no TypeScript source
COPY --from=builder /app/dist ./dist

# Set ownership
RUN chown -R nodeuser:nodejs /app
USER nodeuser

# Document the port (doesn't actually publish it)
EXPOSE 3000

# Use exec form — PID 1 gets SIGTERM, enables graceful shutdown
CMD ["node", "dist/index.js"]

Build and run:

bash

docker build -t myapp:latest .
docker run -p 3000:3000 --env-file .env myapp:latest

Image size comparison:

Without multi-stage: ~800MB (with TypeScript, ts-node, test deps)
With multi-stage: ~150MB (only compiled JS + production deps)

Graceful shutdown in Node.js

typescript

// src/index.ts
import app from './app.js';
import prisma from './db/prisma.js';
import redis from './db/redis.js';
import logger from './utils/logger.js';
import { env } from './config/env.js';
// Same NodeSDK instance instrumentation.js started at process boot — imported
// here (not re-created) so this file can sequence its shutdown, see the
// OpenTelemetry section below for why the SDK doesn't manage its own SIGTERM.
import { sdk } from '../instrumentation.js';

const server = app.listen(env.PORT, () => {
  logger.info({ port: env.PORT }, 'Server started');
});

async function shutdown(signal: string) {
  logger.info({ signal }, 'Shutdown signal received');

  // Stop accepting new connections
  server.close(async () => {
    try {
      // Close database connections cleanly
      await prisma.$disconnect();
      redis.disconnect();
      // Flush any in-flight spans before exiting. This is one step of the
      // same sequence as the rest of shutdown — not a second, independent
      // SIGTERM handler racing this one to decide who exits the process first.
      await sdk.shutdown();
      logger.info('Graceful shutdown complete');
      process.exit(0);
    } catch (err) {
      logger.error({ err }, 'Error during shutdown');
      process.exit(1);
    }
  });

  // Force exit if graceful shutdown hangs
  setTimeout(() => {
    logger.error('Forced shutdown after timeout');
    process.exit(1);
  }, 10_000);
}

process.on('SIGTERM', () => shutdown('SIGTERM'));
process.on('SIGINT', () => shutdown('SIGINT'));
process.on('uncaughtException', (err) => {
  logger.fatal({ err }, 'Uncaught exception');
  process.exit(1);
});
process.on('unhandledRejection', (reason) => {
  logger.fatal({ reason }, 'Unhandled promise rejection');
  process.exit(1);
});

docker-compose for Local Development

docker-compose runs all your local dependencies (Postgres, Redis) with one command:

yaml

# docker-compose.yml
version: '3.9'

services:
  app:
    build:
      context: .
      target: builder   # use the builder stage — includes ts-node for dev
    ports:
      - '3000:3000'
    environment:
      NODE_ENV: development
      DATABASE_URL: postgresql://postgres:postgres@postgres:5432/myapp_dev
      REDIS_URL: redis://redis:6379
      JWT_ACCESS_SECRET: local-dev-secret-32-characters-minimum
      JWT_REFRESH_SECRET: local-dev-refresh-32-characters-min
    volumes:
      - ./src:/app/src   # hot reload — changes reflected instantly
    command: npm run dev
    depends_on:
      postgres:
        condition: service_healthy
      redis:
        condition: service_healthy

  postgres:
    image: postgres:16-alpine
    environment:
      POSTGRES_DB: myapp_dev
      POSTGRES_USER: postgres
      POSTGRES_PASSWORD: postgres
    ports:
      - '5432:5432'
    volumes:
      - postgres_data:/var/lib/postgresql/data
    healthcheck:
      test: ['CMD-SHELL', 'pg_isready -U postgres']
      interval: 5s
      timeout: 5s
      retries: 5

  redis:
    image: redis:7-alpine
    ports:
      - '6379:6379'
    healthcheck:
      test: ['CMD', 'redis-cli', 'ping']
      interval: 5s
      timeout: 5s
      retries: 5

volumes:
  postgres_data:

bash

docker-compose up -d          # start in background
docker-compose logs -f app    # tail logs
docker-compose down           # stop
docker-compose down -v        # stop and wipe data

PM2 for Production Process Management

When deploying to a bare VM or VPS (rather than a container orchestrator), PM2 manages your Node.js process:

bash

npm install -g pm2

javascript

// ecosystem.config.js
module.exports = {
  apps: [
    {
      name: 'myapp',
      script: 'dist/index.js',
      instances: 'max',     // one process per CPU core
      exec_mode: 'cluster', // cluster mode — all processes share port 3000
      max_memory_restart: '500M',

      env_production: {
        NODE_ENV: 'production',
        PORT: 3000,
      },

      // Logging
      out_file: '/var/log/myapp/out.log',
      error_file: '/var/log/myapp/error.log',
      merge_logs: true,
      log_date_format: 'YYYY-MM-DD HH:mm:ss',
    },
  ],
};

bash

pm2 start ecosystem.config.js --env production
pm2 save          # persist config — restart on system reboot
pm2 startup       # generate startup script for your OS
pm2 status        # check running processes
pm2 logs myapp    # tail logs
pm2 reload myapp  # zero-downtime reload (cluster mode)
pm2 monit         # real-time CPU/memory dashboard

Cluster mode vs worker threads: PM2 cluster mode forks multiple Node.js processes, each with their own event loop. This saturates all CPU cores. For CPU-bound work within a single request, worker threads (covered in the Architect phase) are the right tool. For most APIs (I/O bound), PM2 cluster mode is sufficient.

Log Rotation with pm2-logrotate

The ecosystem.config.js above writes straight to out_file/error_file with no rotation — left alone, those files grow forever until they fill the disk. pm2-logrotate is a PM2 module that rotates and compresses them automatically:

bash

pm2 install pm2-logrotate

pm2 set pm2-logrotate:max_size 50M               # rotate once a file hits 50MB
pm2 set pm2-logrotate:retain 14                  # keep 14 rotated files
pm2 set pm2-logrotate:compress true               # gzip rotated files
pm2 set pm2-logrotate:rotateInterval '0 0 * * *'  # also rotate daily at midnight

Confirm it's active with pm2 module:list. This should be configured before the first production deploy, not discovered after a disk-full incident takes the app down.

GitHub Actions CI/CD Pipeline

A pipeline that runs on every push: type-check → test → build Docker image → push to registry → deploy:

yaml

# .github/workflows/deploy.yml
name: Test, Build, Deploy

on:
  push:
    branches: [main]
  pull_request:
    branches: [main]

env:
  REGISTRY: ghcr.io
  IMAGE_NAME: ${{ github.repository }}

jobs:
  test:
    runs-on: ubuntu-latest

    services:
      postgres:
        image: postgres:16
        env:
          POSTGRES_DB: myapp_test
          POSTGRES_USER: postgres
          POSTGRES_PASSWORD: postgres
        ports: ['5432:5432']
        options: --health-cmd pg_isready --health-interval 10s

      redis:
        image: redis:7
        ports: ['6379:6379']
        options: --health-cmd "redis-cli ping" --health-interval 10s

    steps:
      - uses: actions/checkout@v4

      - uses: actions/setup-node@v4
        with:
          node-version: '22'
          cache: 'npm'

      - run: npm ci

      - name: Type check
        run: npx tsc --noEmit

      - name: Run tests
        run: npm run test:ci
        env:
          DATABASE_URL: postgresql://postgres:postgres@localhost:5432/myapp_test
          REDIS_URL: redis://localhost:6379
          JWT_ACCESS_SECRET: ci-test-secret-at-least-32-characters
          JWT_REFRESH_SECRET: ci-refresh-secret-at-least-32-characters
          NODE_ENV: test

  build-and-push:
    needs: test
    runs-on: ubuntu-latest
    if: github.ref == 'refs/heads/main'  # only on main branch pushes

    permissions:
      contents: read
      packages: write

    outputs:
      image-tag: ${{ steps.meta.outputs.tags }}

    steps:
      - uses: actions/checkout@v4

      - name: Log in to container registry
        uses: docker/login-action@v3
        with:
          registry: ${{ env.REGISTRY }}
          username: ${{ github.actor }}
          password: ${{ secrets.GITHUB_TOKEN }}

      - name: Extract metadata
        id: meta
        uses: docker/metadata-action@v5
        with:
          images: ${{ env.REGISTRY }}/${{ env.IMAGE_NAME }}
          tags: |
            type=sha,prefix=sha-
            type=raw,value=latest,enable=true

      - name: Build and push Docker image
        uses: docker/build-push-action@v5
        with:
          context: .
          target: production
          push: true
          tags: ${{ steps.meta.outputs.tags }}
          cache-from: type=gha
          cache-to: type=gha,mode=max

  deploy:
    needs: build-and-push
    runs-on: ubuntu-latest
    if: github.ref == 'refs/heads/main'

    steps:
      - name: Deploy to production
        uses: appleboy/ssh-action@v1
        with:
          host: ${{ secrets.DEPLOY_HOST }}
          username: ${{ secrets.DEPLOY_USER }}
          key: ${{ secrets.DEPLOY_SSH_KEY }}
          script: |
            set -e
            docker pull ghcr.io/${{ github.repository }}:latest

            # Start the new version on a staging port — the old container
            # keeps serving live traffic on :3000, untouched, while this boots
            docker run -d \
              --name myapp-next \
              --restart unless-stopped \
              -p 3001:3000 \
              --env-file /etc/myapp/.env \
              ghcr.io/${{ github.repository }}:latest

            # Require the new container to pass its own health check before
            # it's allowed anywhere near the old one. If the new image is
            # broken, this fails here — the old container is never stopped,
            # so a bad deploy produces no outage at all, only a failed job.
            healthy=false
            for i in $(seq 1 15); do
              if curl -sf http://localhost:3001/health > /dev/null 2>&1; then
                healthy=true
                break
              fi
              sleep 2
            done

            if [ "$healthy" != "true" ]; then
              echo "myapp-next failed its health check — aborting deploy, old container untouched"
              docker rm -f myapp-next
              exit 1
            fi

            # The new image is now proven healthy. Retire the old container,
            # free :3000, and rebind the same already-pulled, already-verified
            # image to it. Docker cannot remap a running container's published
            # port, so this last step is still a brief restart — but it is
            # restarting a known-good image instead of gambling on an
            # unverified one, which was the actual danger in the original
            # stop -> rm -> run script (a broken image took the whole app
            # down with no way back).
            docker stop myapp || true
            docker rm myapp || true
            docker rm -f myapp-next
            docker run -d \
              --name myapp \
              --restart unless-stopped \
              -p 3000:3000 \
              --env-file /etc/myapp/.env \
              ghcr.io/${{ github.repository }}:latest

A second caveat, on --env-file /etc/myapp/.env: this is fine for local development, but P-6 (Configuration, Security Hardening) is explicit that production secrets shouldn't live in a flat file on the deploy target — fetch them from a dedicated secrets manager (Vault, AWS Secrets Manager, etc.) at container startup instead, and reserve --env-file for genuinely non-sensitive configuration. The script above is written for clarity about the blue/green mechanics, not as a template for how secrets should actually reach the container.

Honest caveat: this script minimizes risk — the old container is never touched until the new image proves it can pass its own health check, so a broken build fails the deploy job instead of taking production down. It does not achieve true zero-downtime: the final docker run still has to boot a fresh Node process bound to :3000, and the graceful-shutdown code above only shortens that gap, it doesn't close it. Closing it fully requires a reverse proxy (nginx/Caddy) in front of both containers, with its upstream switched from :3000 to :3001 before the old container is stopped — real blue/green, with no shared port that has to be handed off. That's the fix once even a few hundred milliseconds of downtime per deploy is unacceptable; this script is the safe middle ground for a bare-VM setup without one.

Repository secrets to configure

In GitHub → Settings → Secrets and variables → Actions:

DEPLOY_HOST — your server IP or hostname
DEPLOY_USER — SSH username (ubuntu, deploy, etc.)
DEPLOY_SSH_KEY — private SSH key (the public key must be in ~/.ssh/authorized_keys on the server)

.dockerignore

Prevent unnecessary files from being copied into the build context — this speeds up builds and prevents secrets from leaking into images:

text

node_modules
dist
.git
.env
.env.*
*.log
*.test.ts
__tests__
coverage
.github
README.md
docker-compose.yml

Summary

Pino produces JSON logs with near-zero overhead. Never use console.log in production code. redact only does something if you actually log an object shaped like its configured paths.
Child loggers (logger.child({ requestId })) attach context to every log line in a scope without repetition.
Correlation IDs, propagated via AsyncLocalStorage rather than threaded through every function signature, make distributed debugging possible — but ALS context doesn't cross process/queue boundaries on its own; a job payload still needs the ID written in explicitly.
Metrics (prom-client, RED/USE, /metrics) are the third observability pillar alongside logs and traces — aggregate health that logs and traces alone can't show.
Multi-stage Docker builds separate the TypeScript compile step from the production image. Result: ~150MB images instead of ~800MB.
Graceful shutdown — one coordinated SIGTERM handler that closes the server, drains connections, disconnects databases, and flushes OTel spans in sequence, not two competing handlers racing each other.
docker-compose — one command starts Postgres, Redis, and your app for local development with hot reload.
PM2 cluster mode — saturates all CPU cores with independent Node.js processes. Zero-downtime reload with pm2 reload; pair it with pm2-logrotate so logs don't fill the disk.
GitHub Actions — test → build Docker image → push to registry → SSH deploy on every push to main, health-checking the new container before retiring the old one. Note this still isn't true zero-downtime without a reverse proxy in front — see the deploy step's caveat.

Next: WebSockets and real-time communication — the upgrade from HTTP to WebSocket, broadcasting events to connected clients, presence tracking, and scaling WebSockets across multiple servers with Redis Pub/Sub.

OpenTelemetry — Distributed Traces From Minute One

Pino logs with correlation IDs are necessary. They're not sufficient. When a request to your Express API takes 800ms and you don't know if the time was spent in a database query, an external HTTP call, or application logic, you're debugging blind. Distributed traces tell you exactly where the time went.

OpenTelemetry (OTel) is the industry-standard observability framework — vendor-neutral, supported by every major APM tool (Datadog, New Relic, Jaeger, Grafana Tempo, Honeycomb). Set it up once, export to any backend.

Auto-Instrumentation — Zero Code Changes

The @opentelemetry/auto-instrumentations-node package automatically instruments:

Express (request spans, route attributes)
node-postgres / pg (query spans with SQL text)
ioredis (command spans)
http/https (outbound request spans)
dns (resolution spans)
fs (file operation spans — optional, noisy)

bash

npm install @opentelemetry/sdk-node \
  @opentelemetry/auto-instrumentations-node \
  @opentelemetry/exporter-trace-otlp-http

javascript

// instrumentation.js — must be loaded BEFORE anything else
import { NodeSDK } from '@opentelemetry/sdk-node'
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node'
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http'

// Exported (not just created and started) so src/index.ts can await its
// shutdown as one step of the app's own coordinated shutdown sequence.
export const sdk = new NodeSDK({
  serviceName: process.env.SERVICE_NAME ?? 'api-server',
  traceExporter: new OTLPTraceExporter({
    url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT ?? 'http://localhost:4318/v1/traces',
  }),
  instrumentations: [
    getNodeAutoInstrumentations({
      '@opentelemetry/instrumentation-fs': { enabled: false }, // too noisy
      '@opentelemetry/instrumentation-pg': {
        enhancedDatabaseReporting: true, // includes SQL in span attributes
      },
    }),
  ],
})

sdk.start()

// Deliberately no `process.on('SIGTERM', ...)` here. A second, independent
// SIGTERM handler in this file would race the application's own shutdown
// handler in src/index.ts — both firing on the same signal, with no
// guarantee spans are flushed before the other handler calls
// `process.exit()`. Instead, `sdk` is exported so the shutdown sequence
// shown earlier in this module (`src/index.ts`) can call `await sdk.shutdown()`
// itself, after the HTTP server has already stopped accepting new work —
// one handler, one ordered sequence, instead of two racing each other.

Start your application with the instrumentation file loaded:

bash

node --import ./instrumentation.js src/index.js
# or in package.json scripts:
"start": "node --import ./instrumentation.js src/index.js"

After this single change, every Express request gets a trace with child spans for every database query, Redis operation, and outbound HTTP call. No application code changes.

Correlating Trace IDs with Pino Logs

Logs and traces are separate. Connect them by injecting the active trace ID into every log line:

javascript

import { trace, context } from '@opentelemetry/api'
import pino from 'pino'

const baseLogger = pino({ level: 'info' })

// Middleware that creates a request-scoped logger with trace context
app.use((req, res, next) => {
  const span = trace.getActiveSpan()
  const spanContext = span?.spanContext()
  
  req.log = baseLogger.child({
    traceId: spanContext?.traceId,
    spanId: spanContext?.spanId,
    requestId: req.headers['x-request-id'],
  })
  
  next()
})

// Use req.log instead of console.log in route handlers
app.get('/api/orders', async (req, res) => {
  req.log.info('Fetching orders')
  const orders = await getOrders()
  req.log.info({ count: orders.length }, 'Orders fetched')
  res.json(orders)
})

Now when you search for a trace ID in your log aggregator, you see every log line from that exact request alongside the spans.

Custom Spans for Business Logic

Auto-instrumentation covers I/O. For business logic timing (payment processing, report generation, complex calculations), add manual spans:

javascript

import { trace } from '@opentelemetry/api'

const tracer = trace.getTracer('order-service', '1.0.0')

async function processPayment(order) {
  return tracer.startActiveSpan('process-payment', async (span) => {
    span.setAttribute('order.id', order.id)
    span.setAttribute('order.amount_cents', order.amountCents)
    
    try {
      const result = await stripeClient.charges.create({ ... })
      span.setAttribute('stripe.charge_id', result.id)
      span.setStatus({ code: SpanStatusCode.OK })
      return result
    } catch (error) {
      span.recordException(error)
      span.setStatus({ code: SpanStatusCode.ERROR, message: error.message })
      throw error
    } finally {
      span.end()
    }
  })
}

The span appears in your trace waterfall between the database query that loaded the order and the Redis operation that caches the result. You can see exactly how long payment processing takes, independently of everything around it.

Application Metrics: The Third Pillar

Logs answer "what happened" for one event. Traces answer "where did the time go" for one request. Neither answers "how is the system doing right now, in aggregate" — that's what metrics are for: numeric time series, cheap to store and query, the natural fit for dashboards and alerts. "Observability basics" isn't complete without this third pillar alongside logs and traces.

Two frameworks for deciding what to expose:

RED (request-driven services): Rate — requests/sec, Errors — failed requests/sec, Duration — latency distribution. Answers "is the API healthy right now?"
USE (resources): Utilization — percent time busy, Saturation — queue depth or work waiting, Errors — error count. Answers "is the CPU, connection pool, or event loop the bottleneck?"

prom-client is the standard library for exposing Prometheus-format metrics from Node.js:

bash

npm install prom-client

typescript

// src/utils/metrics.ts
import client from 'prom-client';

// Default process metrics — CPU, memory, event loop lag, GC pauses (USE-style)
client.collectDefaultMetrics({ prefix: 'myapp_' });

export const httpRequestDuration = new client.Histogram({
  name: 'http_request_duration_seconds',
  help: 'HTTP request duration in seconds',
  labelNames: ['method', 'route', 'status_code'],
  buckets: [0.01, 0.05, 0.1, 0.3, 0.5, 1, 2, 5],
});

export const httpRequestsTotal = new client.Counter({
  name: 'http_requests_total',
  help: 'Total HTTP requests',
  labelNames: ['method', 'route', 'status_code'],
});

export const httpRequestsInFlight = new client.Gauge({
  name: 'http_requests_in_flight',
  help: 'HTTP requests currently being processed',
});

export const register = client.register;

The same res.on('finish', ...) hook that already drives HTTP request logging can feed metrics too:

typescript

// src/middleware/httpLogger.ts (extended)
import { httpRequestDuration, httpRequestsTotal, httpRequestsInFlight } from '../utils/metrics.js';

export function httpLogger(req: Request, res: Response, next: NextFunction) {
  const start = process.hrtime.bigint();
  httpRequestsInFlight.inc();

  res.on('finish', () => {
    const durationSeconds = Number(process.hrtime.bigint() - start) / 1e9;
    // Use the matched route pattern, not req.originalUrl — otherwise every
    // distinct /users/42, /users/43, ... becomes its own label value and
    // Prometheus's storage grows without bound (see cardinality note below)
    const route = req.route?.path ?? 'unmatched';
    const labels = { method: req.method, route, status_code: String(res.statusCode) };

    httpRequestDuration.observe(labels, durationSeconds);
    httpRequestsTotal.inc(labels);
    httpRequestsInFlight.dec();

    // ... existing logger[level]({ ... }, 'HTTP request') call stays as-is
  });

  next();
}

typescript

// src/app.ts
import { register } from './utils/metrics.js';

app.get('/metrics', async (req, res) => {
  res.setHeader('Content-Type', register.contentType);
  res.send(await register.metrics());
});

Point Prometheus (or a managed equivalent — Grafana Cloud, Datadog's Prometheus scraper) at /metrics and you get RED dashboards and alerting (rate(http_requests_total{status_code=~"5.."}[5m]) > 0.01) with no further code changes. Gate /metrics behind network-level access control (internal-only ingress) — it's an operational endpoint, not a public one.

Log Volume and Cardinality at Scale

Near the low end of this course's advertised range (2K TPS), logging every request at info level is fine — a few thousand JSON lines a second is well within what Pino, a log shipper, and an aggregator absorb without issue. Near the high end (50K TPS), logging every single request becomes expensive in its own right: network egress, ingestion cost, and query latency all scale with line count.

Two separate levers — don't conflate them:

Sampling (for logs) — log every warn/error, but only a fraction of info-level successes (1-in-100, or 100% for the first few minutes after a deploy). Make the decision deterministic per request (hash the request ID) rather than random per line — otherwise a specific request's logs end up half-present, referencing lines that were dropped.
Cardinality (for metrics) — the number of distinct values a label can take. route is a fixed, small set of path patterns and is safe on a metric label. userId or requestId is unbounded — put those in logs and traces, where a value only needs to be searchable, never in a metric label, where every distinct value becomes a permanent new time series.

Knowledge Check

Why is structured logging (e.g., using Pino to output JSON) strongly preferred over standard console.log in production environments?

What is the primary benefit of using a multi-stage Docker build for a Node.js TypeScript application?

What does OpenTelemetry (OTel) auto-instrumentation provide for a Node.js application without requiring any changes to your business logic code?

Test your knowledge with more question sets

Sign in to keep reading

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

PreviousModule P-7: Connecting External Services and Caching Next Module P-9: WebSockets and Real-Time Communication

Discussion

Join the discussion

Loading comments...