Request Logging and Correlation IDs

One access-log line per request, and an id generated in middleware that follows the work through every log and call.

Syntaxintercept(context: ExecutionContext, next: CallHandler): Observable<unknown>

An interceptor is a class with an intercept(context, next) method that Nest wraps around a route handler. Code before next.handle() runs on the way in; RxJS operators piped onto the Observable it returns run on the way out. That makes it the one place to time a request and log its outcome exactly once.

Where it runs

The order is middleware, then guards, then interceptors, then pipes, then the handler, then interceptors again, then exception filters. Two consequences follow. A guard — a class whose canActivate returns true, false or throws — decides before any interceptor exists, so an interceptor never sees a 401 or a 403. Pipes, which transform and validate arguments, run inside the interceptor, so a validation failure does reach it, as an error on the Observable.

Correlation ids

A correlation id is one value attached to everything a single request causes: its log lines, its outgoing HTTP calls, its queue jobs. Generate it in middleware, because middleware runs first and guards log too. Keep it in a Node AsyncLocalStorage, which makes a value readable from every async call made inside a callback, so no service needs an extra parameter.

What trips people up

Accept an inbound x-request-id only from a gateway you control. A public endpoint that trusts the header lets one client collapse your whole log index onto a single id.

Example

Example · typescript
// src/observability/logging.interceptor.ts
import {
  CallHandler,
  ExecutionContext,
  HttpException,
  Injectable,
  Logger,
  NestInterceptor,
} from '@nestjs/common';
import { AsyncLocalStorage } from 'node:async_hooks';
import type { Request, Response } from 'express';
import { Observable, tap } from 'rxjs';
import type { RequestStore } from './request-context.js';

@Injectable()
export class LoggingInterceptor implements NestInterceptor {
  private readonly logger = new Logger('http');

  constructor(private readonly als: AsyncLocalStorage<RequestStore>) {}

  intercept(context: ExecutionContext, next: CallHandler): Observable<unknown> {
    // A global interceptor also runs for WebSocket and microservice handlers,
    // where switchToHttp() would give you nothing useful.
    if (context.getType() !== 'http') {
      return next.handle();
    }

    const http = context.switchToHttp();
    const request = http.getRequest<Request>();
    const response = http.getResponse<Response>();
    const startedAt = process.hrtime.bigint();
    const requestId = this.als.getStore()?.requestId;

    const write = (status: number, error?: unknown): void => {
      const durationMs = Number(process.hrtime.bigint() - startedAt) / 1e6;
      this.logger.log('request', {
        requestId,
        method: request.method,
        // The route template, never the concrete path: /orders/:id, not
        // /orders/42, so the field stays groupable.
        route: request.route?.path ?? request.url,
        status,
        durationMs: Math.round(durationMs),
        handler: `${context.getClass().name}.${context.getHandler().name}`,
        error: error instanceof Error ? error.message : undefined,
      });
    };

    return next.handle().pipe(
      tap({
        // The handler returned: the response status is already set.
        next: () => write(response.statusCode),
        // The handler (or a pipe) threw: the filter has not run yet.
        error: (error: unknown) =>
          write(error instanceof HttpException ? error.getStatus() : 500, error),
      }),
    );
  }
}

When to use it

  • Produce one access-log line per request with status and duration, instead of a logger call in every handler.
  • Join the logs of three services for one user action using a single id.
  • Find the slowest handler in production by sorting the duration field.
  • Read the current request's id in a repository without threading it through every signature.

More examples

The id: store, middleware, registration

This is the half of the job the interceptor cannot do. The id has to be created before guards so an authorisation failure can be logged with it, and it has to live in AsyncLocalStorage so a repository five calls deep can read it without the signature change rippling through the codebase.

Example · typescript
// src/observability/request-context.ts
import { AsyncLocalStorage } from 'node:async_hooks';
import { Module } from '@nestjs/common';

export interface RequestStore {
  requestId: string;
}

// The AsyncLocalStorage class is used as the injection token: the key the
// injector files this one shared instance under.
@Module({
  providers: [
    { provide: AsyncLocalStorage, useValue: new AsyncLocalStorage<RequestStore>() },
  ],
  exports: [AsyncLocalStorage],
})
export class RequestContextModule {}

// src/observability/request-id.middleware.ts
import { Injectable, NestMiddleware } from '@nestjs/common';
import { AsyncLocalStorage } from 'node:async_hooks';
import { randomUUID } from 'node:crypto';
import type { NextFunction, Request, Response } from 'express';
import type { RequestStore } from './request-context.js';

@Injectable()
export class RequestIdMiddleware implements NestMiddleware {
  constructor(private readonly als: AsyncLocalStorage<RequestStore>) {}

  use(req: Request, res: Response, next: NextFunction): void {
    const inbound = req.header('x-request-id');
    const requestId =
      process.env.TRUST_REQUEST_ID === 'true' && inbound ? inbound : randomUUID();

    res.setHeader('x-request-id', requestId);
    // Everything awaited inside this callback can read the store, including
    // guards, pipes, the handler and the exception filter.
    this.als.run({ requestId }, () => next());
  }
}

// src/app.module.ts
import { MiddlewareConsumer, Module, NestModule } from '@nestjs/common';
import { APP_INTERCEPTOR } from '@nestjs/core';
import { LoggingInterceptor } from './observability/logging.interceptor.js';
import { RequestContextModule } from './observability/request-context.js';
import { RequestIdMiddleware } from './observability/request-id.middleware.js';
import { OrdersModule } from './orders/orders.module.js';

@Module({
  imports: [RequestContextModule, OrdersModule],
  providers: [
    // APP_INTERCEPTOR registers a global interceptor through the injector, so
    // it can take constructor dependencies. The shorthand
    // app.useGlobalInterceptors(new LoggingInterceptor(...)) cannot, because
    // you build the instance yourself.
    { provide: APP_INTERCEPTOR, useClass: LoggingInterceptor },
  ],
})
export class AppModule implements NestModule {
  configure(consumer: MiddlewareConsumer): void {
    // Named wildcard: Express 5 path syntax, used since Nest 11.
    consumer.apply(RequestIdMiddleware).forRoutes('*path');
  }
}

Logging the requests the interceptor never sees

Add this when your access log shows 10 requests but the load balancer counted 60: the missing ones were rejected by a guard or a throttler, upstream of every interceptor. The filter is the last stage in the lifecycle, so it sees all of them.

Example · typescript
// src/observability/logging-exception.filter.ts
import { ArgumentsHost, Catch, HttpException, Logger } from '@nestjs/common';
import { BaseExceptionFilter } from '@nestjs/core';
import { AsyncLocalStorage } from 'node:async_hooks';
import type { Request } from 'express';
import type { RequestStore } from './request-context.js';

// An exception filter turns a thrown value into a response. @Catch() with no
// argument means every exception, including the ones a guard throws before
// any interceptor has been created.
@Catch()
export class LoggingExceptionFilter extends BaseExceptionFilter {
  private readonly logger = new Logger('http');

  constructor(private readonly als: AsyncLocalStorage<RequestStore>) {
    super();
  }

  catch(exception: unknown, host: ArgumentsHost): void {
    const request = host.switchToHttp().getRequest<Request>();

    this.logger.warn('request rejected', {
      requestId: this.als.getStore()?.requestId,
      method: request.method,
      path: request.url,
      status: exception instanceof HttpException ? exception.getStatus() : 500,
    });

    // Hand back to the built-in filter so the response body is unchanged.
    super.catch(exception, host);
  }
}

// src/app.module.ts (excerpt)
import { APP_FILTER } from '@nestjs/core';

// Registering through APP_FILTER injects both the store and the HTTP adapter
// that BaseExceptionFilter needs. Registered with useGlobalFilters() instead,
// you must pass the adapter from HttpAdapterHost yourself.
const providers = [{ provide: APP_FILTER, useClass: LoggingExceptionFilter }];

Carrying the id to the next service

Use this the first time you debug across a service boundary. It is also the pattern to copy for queue jobs: put the id in the job payload, and have the processor open its own store with it so the worker's logs belong to the request that queued the work.

Example · typescript
// src/inventory/inventory.client.ts
import { HttpService } from '@nestjs/axios';
import { Injectable } from '@nestjs/common';
import { AsyncLocalStorage } from 'node:async_hooks';
import { firstValueFrom } from 'rxjs';
import type { RequestStore } from '../observability/request-context.js';

@Injectable()
export class InventoryClient {
  constructor(
    private readonly http: HttpService,
    private readonly als: AsyncLocalStorage<RequestStore>,
  ) {}

  async reserve(sku: string, quantity: number): Promise<void> {
    const requestId = this.als.getStore()?.requestId;

    // HttpService methods return Observables; firstValueFrom awaits the
    // single response value.
    await firstValueFrom(
      this.http.post(
        '/reservations',
        { sku, quantity },
        // The same id the access log printed, so the inventory service's
        // lines join this request in one query.
        { headers: requestId ? { 'x-request-id': requestId } : {} },
      ),
    );
  }
}

Related

nest loggingnest interceptorsnest middlewarenest exception filtersnest tracing

Discussion

  • Be the first to comment on this lesson.