Structured Application Logging

Why Structured Logging Matters

Unstructured log lines like console.log('User logged in') are nearly useless at scale. Structured logging emits machine-readable JSON objects, making logs searchable, filterable, and analyzable by tools like ELK, Datadog, or CloudWatch Insights.

Problems with Unstructured Logs

• Hard to query: Grepping for specific fields is error-prone and slow
• No consistent schema: Different developers log different formats
• Missing context: No request ID, user ID, or timestamp precision

What Structured Logging Looks Like

// Bad - unstructured
console.log(`Order ${orderId} created for user ${userId}`);

// Good - structured
logger.info('Order created', {
  orderId: 'ord_abc123',
  userId: 'usr_xyz789',
  amount: 29.99,
  currency: 'USD',
  requestId: 'req_001'
});

Benefits

• Searchability: Query logs by any field (e.g., userId:usr_xyz789)
• Aggregation: Count errors by endpoint, user, or error type
• Alerting: Trigger alerts on specific structured fields
• Correlation: Trace a request across microservices via correlation IDs

Winston: Configuration and Transports

Winston is the most widely used Node.js logging library. It supports multiple transports (console, file, HTTP, MongoDB), custom formats, and level-based filtering.

Basic Setup

import winston from 'winston';

const logger = winston.createLogger({
  level: process.env.LOG_LEVEL || 'info',
  format: winston.format.combine(
    winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss.SSS' }),
    winston.format.errors({ stack: true }),
    winston.format.json()
  ),
  defaultMeta: {
    service: 'order-service',
    environment: process.env.NODE_ENV
  },
  transports: [
    new winston.transports.Console(),
    new winston.transports.File({
      filename: 'logs/error.log',
      level: 'error',
      maxsize: 10 * 1024 * 1024, // 10MB
      maxFiles: 5
    }),
    new winston.transports.File({
      filename: 'logs/combined.log',
      maxsize: 50 * 1024 * 1024,
      maxFiles: 10
    })
  ]
});

Custom Transports

import { Transport, TransportStreamOptions } from 'winston';

class ElasticsearchTransport extends Transport {
  constructor(opts: TransportStreamOptions) {
    super(opts);
  }

  async log(info: any, callback: () => void) {
    await fetch('http://elasticsearch:9200/logs/_doc', {
      method: 'POST',
      headers: { 'Content-Type': 'application/json' },
      body: JSON.stringify(info)
    });
    callback();
  }
}

Environment-Specific Configuration

function createLogger(env: string) {
  const baseConfig = {
    level: env === 'production' ? 'warn' : 'debug',
    format: env === 'production'
      ? winston.format.combine(
          winston.format.timestamp(),
          winston.format.json()
        )
      : winston.format.combine(
          winston.format.colorize(),
          winston.format.simple()
        )
  };
  return winston.createLogger(baseConfig);
}

Pino: High-Performance Logging

Pino is significantly faster than Winston (up to 5x) because it serializes JSON synchronously without buffering. It outputs newline-delimited JSON, which is ideal for container environments where stdout is aggregated by the platform.

Basic Setup

import pino from 'pino';

const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  formatters: {
    level(label) {
      return { level: label };
    }
  },
  timestamp: pino.stdTimeFunctions.isoTime,
  redact: ['req.headers.authorization', 'req.body.password'],
  base: {
    service: 'payment-service',
    version: '1.2.0'
  }
});

logger.info({ userId: 'usr_123', amount: 99.99 }, 'Payment processed');
// Output: {"level":"info","time":"2024-01-15T10:30:00.000Z","service":"payment-service","version":"1.2.0","userId":"usr_123","amount":99.99,"msg":"Payment processed"}

Child Loggers for Context

// Create a child logger with request context
const reqLogger = logger.child({
  requestId: 'req_abc123',
  userId: 'usr_xyz789',
  endpoint: 'POST /api/orders'
});

reqLogger.info('Processing order');
// All subsequent logs from this child include requestId, userId, and endpoint
reqLogger.warn({ inventory: 3 }, 'Low inventory');
reqLogger.error({ error: err }, 'Order failed');

Pino Transports (pino-transport)

import pino from 'pino';

const transport = pino.transport({
  targets: [
    {
      target: 'pino/file',
      options: { destination: '/var/log/app.log', mkdir: true }
    },
    {
      target: 'pino-elasticsearch',
      options: {
        node: 'http://elasticsearch:9200',
        index: 'app-logs'
      }
    }
  ]
});

const logger = pino({ level: 'info' }, transport);

Winston vs Pino

Request Context and Correlation IDs

In microservices and even monoliths, a single user request may touch multiple services, databases, and queues. Correlation IDs let you trace the entire journey of a request across all components.

Middleware for Request IDs

import { v4 as uuidv4 } from 'uuid';
import { Request, Response, NextFunction } from 'express';
import pino from 'pino';

const logger = pino({ level: 'info' });

function requestLogger(req: Request, res: Response, next: NextFunction) {
  const requestId = req.headers['x-request-id'] as string || uuidv4();
  const startTime = Date.now();

  req.log = logger.child({
    requestId,
    method: req.method,
    path: req.path,
    userAgent: req.headers['user-agent']
  });

  res.setHeader('X-Request-Id', requestId);

  req.log.info('Request received');

  res.on('finish', () => {
    req.log.info({
      statusCode: res.statusCode,
      duration: Date.now() - startTime
    }, 'Request completed');
  });

  next();
}

Propagating Context Across Services

// When calling another service, forward the correlation ID
async function callPaymentService(order: Order, requestId: string) {
  const response = await fetch('http://payment-service/charge', {
    method: 'POST',
    headers: {
      'Content-Type': 'application/json',
      'X-Request-Id': requestId  // Propagate correlation
    },
    body: JSON.stringify(order)
  });
  return response.json();
}

AsyncLocalStorage for Automatic Context

import { AsyncLocalStorage } from 'async_hooks';

const asyncLocalStorage = new AsyncLocalStorage<Map<string, any>>();

// Every async call within this context automatically has access to the store
asyncLocalStorage.run(new Map([['requestId', 'req_abc']]), async () => {
  await processOrder(); // requestId available without passing explicitly
  await updateInventory();
  await sendConfirmation();
});

// Inside any function in the chain
function log(message: string) {
  const store = asyncLocalStorage.getStore();
  const requestId = store?.get('requestId');
  console.log(JSON.stringify({ requestId, message }));
}

Best Practices

• Generate a unique request ID at the edge (API gateway or first service)
• Propagate the ID in X-Request-Id header across all service calls
• Store the ID in AsyncLocalStorage for automatic context propagation
• Include the ID in every log line for easy correlation

Log Levels and Severity Strategy

Choosing the right log level is critical. Misuse creates noise (everything logged as info) or hides critical issues (errors logged as warn).

Standard Levels

Configuration by Environment

const logLevels: Record<string, string> = {
  development: 'debug',
  staging: 'info',
  production: 'warn',
  test: 'silent'
};

const logger = pino({
  level: logLevels[process.env.NODE_ENV] || 'info'
});

Structured Error Logging

// Never log errors as strings - preserve the stack trace
try {
  await processPayment(order);
} catch (err) {
  // Bad: loses stack trace
  logger.error(`Payment failed: ${err.message}`);

  // Good: preserves full context
  logger.error({
    err: err instanceof Error ? err : new Error(String(err)),
    orderId: order.id,
    amount: order.total,
    paymentMethod: order.paymentMethod
  }, 'Payment processing failed');
}

Dynamic Level Adjustment

// Runtime level adjustment for debugging production issues
app.post('/admin/log-level', (req, res) => {
  const { level } = req.body;
  if (['fatal', 'error', 'warn', 'info', 'debug', 'trace'].includes(level)) {
    logger.level = level;
    logger.info({ newLevel: level }, 'Log level changed');
    res.json({ success: true });
  } else {
    res.status(400).json({ error: 'Invalid log level' });
  }
});

Security and Privacy in Logging

Logs often contain sensitive data. A single misconfigured log line can leak PII, credentials, or tokens, leading to compliance violations (GDPR, HIPAA) or security breaches.

Data You Should Never Log

• Passwords, API keys, secrets, or tokens
• Credit card numbers or SSNs
• Full request/response bodies without sanitization
• Personal health information (PHI)

Redaction with Pino

import pino from 'pino';

const logger = pino({
  redact: [
    'req.headers.authorization',
    'req.headers.cookie',
    'req.body.password',
    'req.body.creditCard',
    'user.ssn',
    '*.token',       // Redact any nested 'token' field
    '*.secret'       // Redact any nested 'secret' field
  ],
  redact: {
    censor: '[REDACTED]',
    remove: true  // Completely removes the field instead of censoring
  }
});

Winston Sanitization

const sanitizeFormat = winston.format((info) => {
  const sensitiveFields = ['password', 'token', 'ssn', 'creditCard'];
  for (const field of sensitiveFields) {
    if (info[field]) {
      info[field] = '[REDACTED]';
    }
  }
  return info;
});

const logger = winston.createLogger({
  format: winston.format.combine(
    sanitizeFormat(),
    winston.format.json()
  )
});

Audit Logging

// Separate audit log for compliance (append-only, immutable)
const auditLogger = pino({
  level: 'info'
}, pino.destination({
  dest: '/var/log/audit.log',
  sync: true  // Synchronous for audit trail integrity
}));

function auditLog(action: string, userId: string, details: Record<string, any>) {
  auditLogger.info({
    audit: true,
    action,
    userId,
    timestamp: new Date().toISOString(),
    ip: details.ip,
    resource: details.resource
  });
}

// Usage
auditLog('user.login', 'usr_123', { ip: '192.168.1.1', resource: '/api/auth' });
auditLog('data.export', 'usr_123', { ip: '192.168.1.1', resource: '/api/users' });