Logging Patterns

Logging Patterns

Why Structured JSON Logs

console.log strings become unsearchable noise at scale. Structured logs are queryable, alertable, and machine-parseable.

// ❌ WRONG — unstructured, unsearchable, no context
console.log('User logged in: ' + userId);
console.error('DB error: ' + err.message);

// ✅ CORRECT — structured, every field indexable
logger.info({ userId, action: 'login' }, 'User authenticated');
logger.error({ err, query, durationMs }, 'Database query failed');

A structured log entry looks like this on the wire:

{
  "level": "info",
  "time": 1714000000000,
  "traceId": "01HX4ZK9R3BVNMJ2QPFW5T8CDE",
  "service": "api",
  "userId": "usr_abc123",
  "action": "login",
  "msg": "User authenticated"
}

Every field is independently filterable in any log aggregator (Loki, Datadog, CloudWatch, Splunk).

Log Levels

Use the right level. Miscalibrated levels create alert fatigue (too much noise) or blind spots (too quiet).

Rule: Production log level should be info by default. Never ship with debug or trace enabled in production — they produce excessive volume and may log sensitive data.

Setup: Pino (Recommended)

Pino is the fastest production logger for Node.js with minimal overhead.

// logger.ts
import pino from 'pino';

export const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  // Redact PII fields wherever they appear in the log object
  redact: {
    paths: [
      'req.headers.authorization',
      'req.headers.cookie',
      'body.password',
      'body.token',
      'body.creditCard',
      '*.email',       // redact email in any nested object
      '*.ssn',
      '*.phone',
    ],
    censor: '[REDACTED]',
  },
  // In development: pretty-print. In production: JSON.
  transport: process.env.NODE_ENV === 'development'
    ? { target: 'pino-pretty', options: { colorize: true } }
    : undefined,
});

Setup: Winston (Alternative)

// logger.ts
import winston from 'winston';

export const logger = winston.createLogger({
  level: process.env.LOG_LEVEL ?? 'info',
  format: winston.format.combine(
    winston.format.timestamp(),
    winston.format.errors({ stack: true }),
    winston.format.json(),
  ),
  transports: [
    new winston.transports.Console(),
    // Add file/remote transports as needed
  ],
});

Trace ID Propagation

Every log entry for a single request must share the same trace ID. This lets you reconstruct a full request trace from fragmented log lines.

// trace-context.ts — using AsyncLocalStorage (Node 16+)
import { AsyncLocalStorage } from 'node:async_hooks';

interface TraceContext {
  traceId: string;
  spanId?: string;
}

const storage = new AsyncLocalStorage<TraceContext>();

export const getTraceContext = (): TraceContext | undefined => storage.getStore();

export const runWithTrace = <T>(ctx: TraceContext, fn: () => T): T =>
  storage.run(ctx, fn);

// middleware/trace.ts — attach at request entry point
import { randomUUID } from 'node:crypto';
import { runWithTrace } from '../trace-context.js';

export function traceMiddleware(
  req: Request,
  res: Response,
  next: NextFunction,
): void {
  // Accept incoming trace ID from upstream (e.g. load balancer) or generate new
  const traceId =
    (req.headers['x-trace-id'] as string) ?? randomUUID();

  // Propagate to downstream services
  res.setHeader('x-trace-id', traceId);

  runWithTrace({ traceId }, next);
}

// logger.ts — inject trace ID into every log entry automatically
import pino from 'pino';
import { getTraceContext } from './trace-context.js';

const baseLogger = pino({ level: process.env.LOG_LEVEL ?? 'info' });

export const logger = {
  trace: (obj: object, msg: string) =>
    baseLogger.trace({ ...getTraceContext(), ...obj }, msg),
  debug: (obj: object, msg: string) =>
    baseLogger.debug({ ...getTraceContext(), ...obj }, msg),
  info: (obj: object, msg: string) =>
    baseLogger.info({ ...getTraceContext(), ...obj }, msg),
  warn: (obj: object, msg: string) =>
    baseLogger.warn({ ...getTraceContext(), ...obj }, msg),
  error: (obj: object, msg: string) =>
    baseLogger.error({ ...getTraceContext(), ...obj }, msg),
  fatal: (obj: object, msg: string) =>
    baseLogger.fatal({ ...getTraceContext(), ...obj }, msg),
} as const;

Now every logger.info(...) call in any downstream function automatically includes traceId without threading it manually through every argument.

Log at Boundaries

Log at the edges of your system, not in the middle of business logic.

HTTP Request / Response

// middleware/request-logger.ts
export function requestLoggerMiddleware(
  req: Request,
  res: Response,
  next: NextFunction,
): void {
  const start = Date.now();

  logger.info({
    method: req.method,
    url: req.url,
    userAgent: req.headers['user-agent'],
  }, 'HTTP request received');

  res.on('finish', () => {
    const durationMs = Date.now() - start;
    const level = res.statusCode >= 500 ? 'error'
      : res.statusCode >= 400 ? 'warn'
      : 'info';

    logger[level]({
      method: req.method,
      url: req.url,
      statusCode: res.statusCode,
      durationMs,
    }, 'HTTP request completed');
  });

  next();
}

Database Calls

// db/query.ts
export async function query<T>(sql: string, params: unknown[]): Promise<T[]> {
  const start = Date.now();
  try {
    const rows = await pool.query<T>(sql, params);
    const durationMs = Date.now() - start;

    if (durationMs > 200) {
      logger.warn({ durationMs, sql: sanitizeSql(sql) }, 'Slow query detected');
    } else {
      logger.debug({ durationMs, rowCount: rows.length }, 'DB query OK');
    }

    return rows;
  } catch (err) {
    logger.error({ err, durationMs: Date.now() - start }, 'DB query failed');
    throw err;
  }
}

// Never log raw SQL with parameter values — they may contain PII or secrets.
// Log a sanitized version (query shape only) or a query name/identifier.
function sanitizeSql(sql: string): string {
  return sql.replace(/\s+/g, ' ').substring(0, 200);
}

External API Calls

// lib/http-client.ts
export async function callExternalApi(
  url: string,
  options: RequestInit,
): Promise<Response> {
  const start = Date.now();
  logger.info({ url: redactUrl(url), method: options.method }, 'External API call started');

  try {
    const response = await fetch(url, options);
    const durationMs = Date.now() - start;

    if (!response.ok) {
      logger.warn({
        url: redactUrl(url),
        statusCode: response.status,
        durationMs,
      }, 'External API returned non-2xx');
    } else {
      logger.info({ url: redactUrl(url), statusCode: response.status, durationMs }, 'External API call OK');
    }

    return response;
  } catch (err) {
    logger.error({ err, url: redactUrl(url), durationMs: Date.now() - start }, 'External API call failed');
    throw err;
  }
}

// Strip tokens and API keys from URLs before logging
function redactUrl(url: string): string {
  return url.replace(/([?&])(key|token|secret|api_key)=[^&]*/gi, '$1$2=[REDACTED]');
}

Avoid Logging PII

PII includes: email addresses, phone numbers, names, IP addresses (in some jurisdictions), passwords, payment card numbers, health data, location data.

// ❌ WRONG — PII in log
logger.info({ email: user.email, name: user.name }, 'User registered');

// ✅ CORRECT — use internal identifiers only
logger.info({ userId: user.id, plan: user.plan }, 'User registered');

Use Pino's redact (shown in Setup above) as a safety net, but don't rely on it as the primary defense — don't pass PII into logs in the first place.

Minimum redact paths for any service handling users:

redact: [
  'req.headers.authorization',
  'req.headers.cookie',
  '*.password',
  '*.token',
  '*.secret',
  '*.creditCard',
  '*.cardNumber',
  '*.ssn',
  '*.email',
  '*.phone',
]

Child Loggers for Scoped Context

Pino child loggers bind context fields once, so you don't repeat them on every call.

// Add a request-scoped child logger to the request object
app.use((req: Request, _res: Response, next: NextFunction) => {
  req.log = logger.child({
    requestId: req.headers['x-request-id'],
    method: req.method,
    path: req.path,
  });
  next();
});

// In a route handler — no need to repeat method/path/requestId
router.get('/users/:id', async (req, res) => {
  req.log.info({ userId: req.params.id }, 'Fetching user');
  // ...
});

Checklist

• No bare console.log / console.error — replaced with structured logger
• Trace ID attached to every request and propagated downstream
• redact config covers at minimum: authorization header, cookie, password, token, email
• Log at request boundary (in + out), DB call, and external API call
• Slow query threshold defined and logs a warn
• Production log level is info (not debug or trace)
• 5xx responses produce an error log; 4xx produce a warn
• No PII fields passed as log data — use IDs, not names/emails/phones
• Log format is JSON in production, pretty-print allowed in development only