Structured Logging for Node.js

In Monitoring a SaaS in Production we wired up metrics and alerts so the team knows something is wrong within minutes of it happening. Metrics tell you a spike exists. They rarely tell you why. That's a logging problem, and it's the one we're solving here.

This is part of the Full Stack SaaS Masterclass, a build-it-for-real series taking a multi-tenant SaaS from an empty folder to production. Module 4 covers the operational concerns that separate a demo from a product a team can actually run. Logging sits at the base of that stack: incident response, support tickets, and audit trails all eventually route back to "what does the log say."

Most Node.js apps start with console.log and stay there far longer than they should, because it works fine on a laptop with one request at a time. It stops working the moment two requests are in flight concurrently and their log lines interleave in a shared terminal, or a customer support ticket needs an answer and the only tool available is grep against a wall of unstructured text. Structured logging fixes that, and it's cheap enough to set up early that there's little reason to defer it.

Why plain text logs stop working

A console.log call produces a string. Strings are fine for a human staring at a terminal, and actively hostile to any system trying to query logs at scale. Once logs move to CloudWatch, Datadog, or any aggregator, every downstream tool ends up parsing that string back apart with regex to extract the fields it actually needs: request ID, user ID, status code, duration. Regex-based parsing is brittle. A one-word change to a log message breaks every saved search and alert built against it.

Structured logging inverts the approach: instead of writing a sentence and hoping someone can parse it later, you write a JSON object with named fields from the start.

{
  "level": "error",
  "time": "2023-09-14T10:22:31.482Z",
  "requestId": "8f14e45f-ceea-467e-add1-a889b9f6bfaa",
  "organizationId": "org_9f2c1a",
  "userId": "usr_71b30d",
  "route": "POST /invoices",
  "statusCode": 500,
  "durationMs": 812,
  "msg": "Failed to create invoice: unique constraint violation"
}

Every field here is queryable without parsing. "Show me every 500 for organization org_9f2c1a in the last hour" is a filter, not a regex. That difference is the entire value proposition, and it compounds as the system grows: the tenth engineer debugging an incident benefits from the same structured fields the first one set up.

Picking a logging library and wiring it into NestJS

Node.js has a few solid structured logging libraries. pino is a reasonable default for a NestJS backend. It's built around minimizing per-call overhead (JSON serialization with a fast path, rather than the general-purpose JSON.stringify most loggers rely on), and it integrates cleanly with NestJS through nestjs-pino.

// main.ts
import { NestFactory } from '@nestjs/core';
import { Logger } from 'nestjs-pino';
import { AppModule } from './app.module';

async function bootstrap() {
  const app = await NestFactory.create(AppModule, { bufferLogs: true });
  app.useLogger(app.get(Logger));
  await app.listen(3000);
}
bootstrap();

// logger.module.ts
import { Module } from '@nestjs/common';
import { LoggerModule } from 'nestjs-pino';

@Module({
  imports: [
    LoggerModule.forRoot({
      pinoHttp: {
        level: process.env.LOG_LEVEL ?? 'info',
        redact: ['req.headers.authorization', 'req.headers.cookie', '*.password', '*.token'],
        serializers: {
          req: (req) => ({ method: req.method, url: req.url }),
          res: (res) => ({ statusCode: res.statusCode }),
        },
        transport:
          process.env.NODE_ENV === 'development'
            ? { target: 'pino-pretty', options: { singleLine: true } }
            : undefined,
      },
    }),
  ],
})
export class AppLoggerModule {}

Two things matter in that config beyond the obvious. First, redact is not an afterthought; it's the difference between a log line and a leaked credential, and it belongs in the initial setup rather than a follow-up ticket after a security review flags it. Second, the pino-pretty transport is scoped to development only. In production you want raw JSON going to stdout, because that's what your log aggregator expects, and pretty-printing it first just adds CPU work nobody reads.

With that in place, injecting the logger into a service is direct:

import { Injectable } from '@nestjs/common';
import { InjectPinoLogger, PinoLogger } from 'nestjs-pino';

@Injectable()
export class InvoiceService {
  constructor(@InjectPinoLogger(InvoiceService.name) private readonly logger: PinoLogger) {}

  async createInvoice(organizationId: string, amount: number): Promise<void> {
    this.logger.info({ organizationId, amount }, 'Creating invoice');

    try {
      // ... invoice creation logic
    } catch (error) {
      this.logger.error({ organizationId, err: error }, 'Invoice creation failed');
      throw error;
    }
  }
}

The err field matters here: pino's default error serializer expands an Error object into its message and stack trace as separate JSON fields, rather than the string interpolation you'd get from console.log(error). That's what lets you search for a specific exception type across every service without opening individual log lines.

Threading a correlation ID through every log line

A single log line is rarely useful on its own during an incident. What you actually want is every log line that belongs to one request, across every service it touched, and structured fields alone don't get you there unless every one of those lines shares a common ID. That's what a correlation ID (often called a request ID or trace ID) is for.

The cleanest way to propagate it through a NestJS app without threading it as a parameter through every function call is Node's AsyncLocalStorage, which gives each request its own isolated context that survives across await boundaries.

// request-context.ts
import { AsyncLocalStorage } from 'async_hooks';
import { randomUUID } from 'crypto';

interface RequestContext {
  requestId: string;
  organizationId?: string;
}

export const requestContext = new AsyncLocalStorage<RequestContext>();

export function getRequestId(): string {
  return requestContext.getStore()?.requestId ?? 'no-context';
}

// request-context.middleware.ts
import { Injectable, NestMiddleware } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { randomUUID } from 'crypto';
import { requestContext } from './request-context';

@Injectable()
export class RequestContextMiddleware implements NestMiddleware {
  use(req: Request, res: Response, next: NextFunction): void {
    const requestId = (req.headers['x-request-id'] as string) ?? randomUUID();
    res.setHeader('x-request-id', requestId);

    requestContext.run({ requestId }, () => next());
  }
}

Any logger call anywhere in that request's call stack, including inside a queue job triggered by it if the ID is forwarded onto the job payload, can now pull getRequestId() and attach it automatically. Wire it into the pino config's mixin option so it's never something an engineer has to remember to pass explicitly:

LoggerModule.forRoot({
  pinoHttp: {
    mixin() {
      return { requestId: getRequestId() };
    },
  },
});

This is the single highest-leverage addition to a logging setup after structure itself. Without it, reconstructing "everything that happened during this one failed checkout" means guessing at timestamps and hoping nothing else was happening concurrently. With it, it's one query.

Tradeoffs: what structured logging costs you

None of this is free, and the costs deserve an honest look before you treat it as an obvious win.

Structured logs are less pleasant to read directly in a terminal during local development, which is why the pino-pretty transport above exists specifically to soften that for local work while keeping production output as raw JSON. Serialization has a real, if small, CPU cost per log call, which matters if a hot path logs on every iteration of a loop rather than once per request. And redaction configuration needs upkeep. Every new field that might carry a credential, a password, an API key, a session token, needs to be added to the redact list, and that list is easy to forget about once the initial setup is done.

The upside outweighs those costs for almost any SaaS backend past the earliest prototype stage, but it's worth naming them rather than pretending structured logging is a pure upgrade with no maintenance surface.

Production pitfalls worth planning for

Logging PII into unstructured fields. Structure doesn't prevent someone from putting a customer's email address into a free-form msg string or a properties object nobody's reviewing. Redaction rules only catch fields they know about by name; treat any new field added to a log call with the same scrutiny you'd apply to an API response.

Log volume outpacing what you're willing to pay for. Structured JSON logs are larger per line than a terse text message, and verbose debug-level logging left on in production multiplies that. Set LOG_LEVEL per environment, default to info in production, and reserve debug for a deliberate, time-boxed investigation rather than a permanent setting.

Losing logs during a graceful shutdown. If the process exits before the transport finishes flushing buffered log lines, whatever explains a crash is exactly what's missing from the aggregator. Make sure your shutdown hook waits for the logger to flush before the process exits, particularly if logs are batched before being sent off-box.

Correlation IDs that stop at the HTTP boundary. A request ID that only exists inside the API process is far less useful than one forwarded onto every downstream call: the BullMQ job it enqueues, the outbound HTTP call to a third-party API, the message published to another service. Forward it deliberately at every boundary, or the trail goes cold exactly where an incident usually gets interesting.