Structured Logging with Correlation IDs

Ever stared at a wall of logs trying to figure out which error belongs to which request? When you've got multiple requests hitting your server simultaneously, traditional logging becomes useless fast:

[ERROR] User not found
[ERROR] Database connection failed
[INFO] Request completed

Which error belongs to which request? Impossible to tell. This is where correlation IDs come in.

The Solution: Correlation IDs

A correlation ID is a unique identifier assigned to each request that travels through your entire application:

[b1e3c7f2] → POST /login    → UserService.find()    → Response
[9f2d4a81] → GET /projects  → ProjectService.list() → Response

Every log entry includes this ID, making it trivial to trace a request's journey through your system – even across multiple services in a microservices architecture.

AsyncLocalStorage: The Secret Ingredient

The challenge with correlation IDs is propagation. You don't want to pass the ID as a parameter through every single function call. Node.js solves this elegantly with AsyncLocalStorage:

typescript

// common/logger/logger.service.ts
import { AsyncLocalStorage } from 'async_hooks';

// Global storage for request context
export const correlationStorage = new AsyncLocalStorage<{
  correlationId: string;
  userId?: string;
  requestPath?: string;
}>();

// Helper for easy access anywhere in the codebase
export function getCorrelationId(): string {
  const store = correlationStorage.getStore();
  return store?.correlationId || 'no-correlation-id';
}

export function getRequestContext(): Record<string, unknown> {
  const store = correlationStorage.getStore();
  if (!store) return {};
  return {
    correlationId: store.correlationId,
    userId: store.userId,
    requestPath: store.requestPath,
  };
}

Why AsyncLocalStorage? It works seamlessly across async/await boundaries, requires no manual context passing, and is thread-safe – each request gets its own isolated store.

The Correlation Middleware

The middleware is where the magic begins. It creates the correlation ID, sets up the context, and wraps the entire request lifecycle:

typescript

// common/middleware/correlation.middleware.ts
import { Injectable, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { v4 as uuidv4 } from 'uuid';
import { correlationStorage, CustomLoggerService } from '../logger/logger.service';

@Injectable()
export class CorrelationMiddleware implements NestMiddleware {
  private readonly logger = new CustomLoggerService();

  use(req: Request, res: Response, next: NextFunction) {
    // 1. Get existing correlation ID or create new one
    const correlationId =
      (req.headers['x-correlation-id'] as string) ||  // From client/gateway
      (req.headers['x-request-id'] as string) ||      // Alternative header
      uuidv4();                                        // Generate new

    // 2. Store on request object
    req.correlationId = correlationId;

    // 3. Include in response header (for debugging)
    res.setHeader('x-correlation-id', correlationId);

    // 4. Extract user ID from JWT if present
    let userId: string | undefined;
    const authHeader = req.headers.authorization;
    if (authHeader?.startsWith('Bearer ')) {
      try {
        const token = authHeader.slice(7);
        const payload = JSON.parse(
          Buffer.from(token.split('.')[1], 'base64').toString(),
        );
        userId = payload.sub;
      } catch {
        // Token parsing failed - ignore
      }
    }

    // 5. Run request within correlation context
    correlationStorage.run(
      { correlationId, userId, requestPath: req.path },
      () => {
        const startTime = Date.now();

        // Log when response finishes
        res.on('finish', () => {
          const duration = Date.now() - startTime;
          this.logger.logRequest(
            req.method,
            req.originalUrl,
            res.statusCode,
            duration,
          );
        });

        next();
      },
    );
  }
}

The key insight here is correlationStorage.run(). Everything that executes within this callback – including all async operations – has access to the correlation context. No manual passing required.

Registering the Middleware

Apply the middleware globally so every request gets a correlation ID:

typescript

// app.module.ts
import { Module, MiddlewareConsumer, NestModule } from '@nestjs/common';
import { CorrelationMiddleware } from './common/middleware/correlation.middleware';

@Module({ ... })
export class AppModule implements NestModule {
  configure(consumer: MiddlewareConsumer) {
    consumer.apply(CorrelationMiddleware).forRoutes('*');
  }
}

Custom Logger with Winston

Now for the logger that automatically includes the correlation ID in every log entry:

typescript

// common/logger/logger.service.ts
import { Injectable, LoggerService, Scope } from '@nestjs/common';
import * as winston from 'winston';

@Injectable({ scope: Scope.TRANSIENT })
export class CustomLoggerService implements LoggerService {
  private logger: winston.Logger;
  private context?: string;

  constructor() {
    // JSON format for production (parseable by log aggregators)
    const jsonFormat = winston.format.combine(
      winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }),
      winston.format.errors({ stack: true }),
      winston.format((info) => {
        // Automatically inject correlation ID
        const requestContext = getRequestContext();
        return { ...info, ...requestContext };
      })(),
      winston.format.json(),
    );

    // Pretty format for development
    const devFormat = winston.format.combine(
      winston.format.colorize({ all: true }),
      winston.format.timestamp({ format: 'HH:mm:ss.SSS' }),
      winston.format.printf((info) => {
        const { timestamp, level, message, correlationId, userId } = info;
        const corrId = correlationId ? `[${correlationId.slice(0, 8)}]` : '';
        const userStr = userId ? `[user:${userId}]` : '';
        return `${timestamp} ${corrId}${userStr} ${level} ${message}`;
      }),
    );

    this.logger = winston.createLogger({
      level: process.env.LOG_LEVEL || 'info',
      format: jsonFormat,
      transports: [
        new winston.transports.Console({
          format: process.env.NODE_ENV === 'production' ? jsonFormat : devFormat,
        }),
        new winston.transports.File({
          filename: 'logs/error.log',
          level: 'error',
          maxsize: 5242880,  // 5MB
          maxFiles: 5,
        }),
        new winston.transports.File({
          filename: 'logs/combined.log',
          maxsize: 5242880,
          maxFiles: 5,
        }),
      ],
    });
  }

  log(message: string, context?: string) {
    this.logger.info(message, { context: context || this.context });
  }

  error(message: string, trace?: string, context?: string) {
    this.logger.error(message, { trace, context: context || this.context });
  }

  warn(message: string, context?: string) {
    this.logger.warn(message, { context: context || this.context });
  }

  logRequest(method: string, url: string, statusCode: number, duration: number) {
    const level = statusCode >= 500 ? 'error' : statusCode >= 400 ? 'warn' : 'info';
    this.logger.log(level, `${method} ${url} ${statusCode} ${duration}ms`, {
      type: 'http_request',
      method,
      url,
      statusCode,
      duration,
    });
  }
}

The beauty of this setup is that the logger automatically picks up the correlation ID from AsyncLocalStorage. You just call logger.log() anywhere in your code, and the ID is included.

The Result

In development, you get clean, readable output:

14:32:15.123 [b1e3c7f2] info  POST /auth/login 200 45ms
14:32:15.456 [9f2d4a81] info  GET /projects 200 12ms
14:32:15.789 [b1e3c7f2][user:abc123] info  GET /settings 200 8ms

In production, you get structured JSON ready for Datadog, ELK, or any log aggregator:

json

{
  "timestamp": "2024-01-15T14:32:15.123Z",
  "level": "info",
  "message": "POST /auth/login 200 45ms",
  "correlationId": "b1e3c7f2-1234-5678-9abc-def012345678",
  "type": "http_request",
  "method": "POST",
  "url": "/auth/login",
  "statusCode": 200,
  "duration": 45
}

Exception Filter Integration

The correlation ID becomes especially valuable in error responses. Include it so users can reference it in support requests:

typescript

// common/filters/http-exception.filter.ts
import { getCorrelationId } from '../logger/logger.service';

@Catch()
export class AllExceptionsFilter implements ExceptionFilter {
  catch(exception: unknown, host: ArgumentsHost) {
    const correlationId = getCorrelationId();  // Automatically available!

    response.status(status).json({
      statusCode: status,
      message,
      correlationId,  // User can reference this in support tickets
      timestamp: new Date().toISOString(),
    });
  }
}

The Complete Flow

Here's how it all fits together:

┌─────────────────────────────────────────────────────────────┐
│  Request comes in                                           │
│         ▼                                                   │
│  Middleware creates correlationId                           │
│         ▼                                                   │
│  AsyncLocalStorage.run() establishes context                │
│         ▼                                                   │
│  ┌─────────────────────────────────────────────────────┐   │
│  │  Controller → Service → Repository                   │   │
│  │     ↓            ↓           ↓                       │   │
│  │  logger.log() fetches correlationId automatically    │   │
│  └─────────────────────────────────────────────────────┘   │
│         ▼                                                   │
│  Response with x-correlation-id header                      │
└─────────────────────────────────────────────────────────────┘

Conclusion

Structured logging with correlation IDs transforms debugging from guesswork into precision. When something goes wrong in production, you can filter your logs by a single ID and see the complete story of what happened – from the initial request through every service call to the final response.

The setup takes maybe an hour, but the time it saves during incident response is immeasurable. If you're building anything beyond a toy project, this is table stakes for observability.