Logging and Observability in Node.js

Why Structured Logging?

// Unstructured (hard to query)
[2024-01-15 10:23:45] ERROR: User 123 failed to login from 192.168.1.1

// Structured JSON (queryable, parseable)
{
  "level": "error",
  "time": "2024-01-15T10:23:45.000Z",
  "msg": "Login failed",
  "userId": "123",
  "ip": "192.168.1.1",
  "reason": "invalid_password",
  "requestId": "req_abc123"
}

Pino Setup

import pino from 'pino';

const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  formatters: {
    level(label) { return { level: label }; },
  },
  base: {
    service: 'user-api',
    env: process.env.NODE_ENV,
    version: process.env.APP_VERSION,
  },
  // Human-readable in development
  transport: process.env.NODE_ENV === 'development'
    ? { target: 'pino-pretty', options: { colorize: true } }
    : undefined,
});

export default logger;

Child Loggers with Context

// Request-scoped logger with correlation ID
app.use((req, res, next) => {
  const requestId = req.headers['x-request-id'] as string || generateId();
  req.logger = logger.child({
    requestId,
    method: req.method,
    url: req.url,
    userAgent: req.headers['user-agent'],
  });
  res.setHeader('x-request-id', requestId);
  next();
});

// Use in controllers
async function createUser(req: Request, res: Response) {
  const log = req.logger;
  log.info('Creating user', { email: req.body.email });

  try {
    const user = await userService.create(req.body);
    log.info('User created', { userId: user.id });
    res.json(user);
  } catch (err) {
    log.error({ err }, 'Failed to create user');
    res.status(500).json({ error: 'Internal error' });
  }
}

Request/Response Logging

import pinoHttp from 'pino-http';

app.use(pinoHttp({
  logger,
  customLogLevel: (req, res) => {
    if (res.statusCode >= 500) return 'error';
    if (res.statusCode >= 400) return 'warn';
    return 'info';
  },
  customSuccessMessage: (req, res) => {
    return `${req.method} ${req.url} ${res.statusCode}`;
  },
  serializers: {
    req: (req) => ({
      id: req.id,
      method: req.method,
      url: req.url,
      // Don't log auth headers
      headers: { ...req.headers, authorization: '[REDACTED]' },
    }),
  },
}));

Error Logging

// Log errors with full context
function logError(logger: Logger, err: unknown, context?: Record<string, unknown>) {
  if (err instanceof Error) {
    logger.error({
      err: {
        message: err.message,
        name: err.name,
        stack: err.stack,
        ...('code' in err ? { code: err.code } : {}),
      },
      ...context,
    }, err.message);
  } else {
    logger.error({ err, ...context }, 'Unknown error');
  }
}

Log Levels

// Guideline for log levels:
logger.trace({ query, params }, 'DB query executing');     // Very verbose
logger.debug({ userId, sessionId }, 'User session checked'); // Debug info
logger.info({ userId }, 'User logged in');                  // Normal operations
logger.warn({ attempts }, 'Rate limit approaching');         // Warning signs
logger.error({ err }, 'Payment processing failed');          // Errors
logger.fatal({ err }, 'Database connection lost');           // System critical

OpenTelemetry Integration

import { trace, context, propagation } from '@opentelemetry/api';

app.use((req, res, next) => {
  const span = trace.getActiveSpan();
  const traceId = span?.spanContext().traceId;

  req.logger = logger.child({ traceId });
  next();
});

Structured logs enable powerful queries in Elasticsearch, Loki, or CloudWatch Insights.