Observability

Implement production observability with structured logging, metrics, distributed tracing, and alerting. This skill covers the three pillars of observability for production systems.

Purpose

Understand and debug production systems:

• Implement structured, searchable logging
• Collect and visualize application metrics
• Trace requests across distributed services
• Set up meaningful alerts
• Create actionable dashboards
• Debug production issues efficiently

Features

1. Structured Logging

import pino from 'pino';
import { v4 as uuid } from 'uuid';

// Logger configuration
const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  formatters: {
    level: (label) => ({ level: label }),
    bindings: () => ({}),
  },
  timestamp: () => `,"timestamp":"${new Date().toISOString()}"`,
  base: {
    service: process.env.SERVICE_NAME,
    environment: process.env.NODE_ENV,
    version: process.env.APP_VERSION,
  },
  redact: ['password', 'token', 'authorization', 'cookie', '*.password'],
});

// Child logger with context
function createRequestLogger(req: Request) {
  return logger.child({
    requestId: req.headers['x-request-id'] || uuid(),
    userId: req.user?.id,
    path: req.path,
    method: req.method,
  });
}

// Logging middleware
function loggingMiddleware(req: Request, res: Response, next: NextFunction) {
  const log = createRequestLogger(req);
  req.log = log;

  const startTime = Date.now();

  // Log request
  log.info({ type: 'request' }, 'Incoming request');

  // Log response
  res.on('finish', () => {
    const duration = Date.now() - startTime;
    const logData = {
      type: 'response',
      statusCode: res.statusCode,
      duration,
      contentLength: res.get('content-length'),
    };

    if (res.statusCode >= 500) {
      log.error(logData, 'Request failed');
    } else if (res.statusCode >= 400) {
      log.warn(logData, 'Request error');
    } else {
      log.info(logData, 'Request completed');
    }
  });

  next();
}

// Structured error logging
function logError(error: Error, context?: Record<string, any>) {
  logger.error({
    error: {
      message: error.message,
      name: error.name,
      stack: error.stack,
      ...(error as any).details,
    },
    ...context,
  }, 'Error occurred');
}

// Business event logging
interface BusinessEvent {
  event: string;
  userId?: string;
  data: Record<string, any>;
  tags?: string[];
}

function logBusinessEvent(event: BusinessEvent) {
  logger.info({
    type: 'business_event',
    event: event.event,
    userId: event.userId,
    data: event.data,
    tags: event.tags,
  }, `Business event: ${event.event}`);
}

// Usage
logBusinessEvent({
  event: 'order.completed',
  userId: 'user_123',
  data: {
    orderId: 'order_456',
    total: 99.99,
    items: 3,
  },
  tags: ['checkout', 'revenue'],
});

2. Metrics with Prometheus

import { Registry, Counter, Histogram, Gauge, collectDefaultMetrics } from 'prom-client';

// Create registry
const register = new Registry();

// Collect Node.js metrics
collectDefaultMetrics({ register });

// Custom metrics
const httpRequestDuration = new Histogram({
  name: 'http_request_duration_seconds',
  help: 'Duration of HTTP requests in seconds',
  labelNames: ['method', 'route', 'status_code'],
  buckets: [0.01, 0.05, 0.1, 0.5, 1, 2, 5],
  registers: [register],
});

const httpRequestTotal = new Counter({
  name: 'http_requests_total',
  help: 'Total number of HTTP requests',
  labelNames: ['method', 'route', 'status_code'],
  registers: [register],
});

const activeConnections = new Gauge({
  name: 'active_connections',
  help: 'Number of active connections',
  registers: [register],
});

const businessMetrics = {
  ordersTotal: new Counter({
    name: 'orders_total',
    help: 'Total number of orders',
    labelNames: ['status', 'payment_method'],
    registers: [register],
  }),
  orderValue: new Histogram({
    name: 'order_value_dollars',
    help: 'Value of orders in dollars',
    buckets: [10, 50, 100, 250, 500, 1000],
    registers: [register],
  }),
  activeUsers: new Gauge({
    name: 'active_users',
    help: 'Number of active users',
    registers: [register],
  }),
};

// Metrics middleware
function metricsMiddleware(req: Request, res: Response, next: NextFunction) {
  const start = Date.now();

  res.on('finish', () => {
    const duration = (Date.now() - start) / 1000;
    const route = req.route?.path || req.path;

    httpRequestDuration
      .labels(req.method, route, res.statusCode.toString())
      .observe(duration);

    httpRequestTotal
      .labels(req.method, route, res.statusCode.toString())
      .inc();
  });

  next();
}

// Expose metrics endpoint
app.get('/metrics', async (req, res) => {
  res.set('Content-Type', register.contentType);
  res.end(await register.metrics());
});

// Usage in business logic
async function completeOrder(order: Order) {
  await saveOrder(order);

  businessMetrics.ordersTotal
    .labels('completed', order.paymentMethod)
    .inc();

  businessMetrics.orderValue.observe(order.total);
}

3. Distributed Tracing with OpenTelemetry

import { NodeSDK } from '@opentelemetry/sdk-node';
import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentations-node';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import { Resource } from '@opentelemetry/resources';
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions';
import { trace, SpanStatusCode, context } from '@opentelemetry/api';

// Initialize OpenTelemetry
const sdk = new NodeSDK({
  resource: new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: process.env.SERVICE_NAME,
    [SemanticResourceAttributes.SERVICE_VERSION]: process.env.APP_VERSION,
    [SemanticResourceAttributes.DEPLOYMENT_ENVIRONMENT]: process.env.NODE_ENV,
  }),
  traceExporter: new OTLPTraceExporter({
    url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT,
  }),
  instrumentations: [
    getNodeAutoInstrumentations({
      '@opentelemetry/instrumentation-http': {
        ignoreIncomingRequestHook: (req) => req.url === '/health',
      },
      '@opentelemetry/instrumentation-express': {},
      '@opentelemetry/instrumentation-pg': {},
      '@opentelemetry/instrumentation-redis': {},
    }),
  ],
});

sdk.start();

// Custom spans
const tracer = trace.getTracer('my-service');

async function processOrder(orderId: string): Promise<void> {
  return tracer.startActiveSpan('processOrder', async (span) => {
    try {
      span.setAttributes({
        'order.id': orderId,
      });

      // Child span for validation
      await tracer.startActiveSpan('validateOrder', async (validationSpan) => {
        const isValid = await validateOrder(orderId);
        validationSpan.setAttributes({ 'order.valid': isValid });
        validationSpan.end();
      });

      // Child span for payment
      await tracer.startActiveSpan('processPayment', async (paymentSpan) => {
        const payment = await chargeCard(orderId);
        paymentSpan.setAttributes({
          'payment.id': payment.id,
          'payment.amount': payment.amount,
        });
        paymentSpan.end();
      });

      span.setStatus({ code: SpanStatusCode.OK });
    } catch (error) {
      span.setStatus({
        code: SpanStatusCode.ERROR,
        message: error.message,
      });
      span.recordException(error);
      throw error;
    } finally {
      span.end();
    }
  });
}

// Propagate context across services
async function callExternalService(endpoint: string, data: any) {
  return tracer.startActiveSpan('externalServiceCall', async (span) => {
    span.setAttributes({
      'http.url': endpoint,
      'http.method': 'POST',
    });

    // Inject trace context into headers
    const headers: Record<string, string> = {};
    const propagator = trace.getTracerProvider();

    const response = await fetch(endpoint, {
      method: 'POST',
      headers: {
        'Content-Type': 'application/json',
        ...headers,
      },
      body: JSON.stringify(data),
    });

    span.setAttributes({
      'http.status_code': response.status,
    });

    span.end();
    return response;
  });
}

4. Error Tracking

import * as Sentry from '@sentry/node';
import { ProfilingIntegration } from '@sentry/profiling-node';

// Initialize Sentry
Sentry.init({
  dsn: process.env.SENTRY_DSN,
  environment: process.env.NODE_ENV,
  release: process.env.APP_VERSION,
  integrations: [
    new ProfilingIntegration(),
  ],
  tracesSampleRate: process.env.NODE_ENV === 'production' ? 0.1 : 1.0,
  profilesSampleRate: 0.1,
  beforeSend(event, hint) {
    // Filter out known errors
    const error = hint.originalException as Error;
    if (error?.message?.includes('ECONNRESET')) {
      return null;
    }
    return event;
  },
});

// Error handler middleware
app.use(Sentry.Handlers.errorHandler({
  shouldHandleError(error) {
    // Only report 5xx errors
    return error.status >= 500;
  },
}));

// Custom error reporting
function reportError(error: Error, context?: Record<string, any>) {
  Sentry.withScope((scope) => {
    if (context) {
      scope.setExtras(context);
    }
    scope.setTags({
      component: context?.component || 'unknown',
    });
    Sentry.captureException(error);
  });

  // Also log
  logError(error, context);
}

// Capture user context
app.use((req, res, next) => {
  if (req.user) {
    Sentry.setUser({
      id: req.user.id,
      email: req.user.email,
    });
  }
  next();
});

5. Alerting Configuration

# prometheus/alerts.yml
groups:
  - name: application
    rules:
      # High error rate
      - alert: HighErrorRate
        expr: |
          sum(rate(http_requests_total{status_code=~"5.."}[5m]))
          /
          sum(rate(http_requests_total[5m]))
          > 0.05
        for: 5m
        labels:
          severity: critical
        annotations:
          summary: High error rate detected
          description: Error rate is {{ $value | humanizePercentage }}

      # Slow response time
      - alert: SlowResponseTime
        expr: |
          histogram_quantile(0.95,
            sum(rate(http_request_duration_seconds_bucket[5m])) by (le)
          ) > 2
        for: 5m
        labels:
          severity: warning
        annotations:
          summary: Slow response times detected
          description: 95th percentile latency is {{ $value }}s

      # High memory usage
      - alert: HighMemoryUsage
        expr: |
          process_resident_memory_bytes / 1024 / 1024 / 1024 > 2
        for: 10m
        labels:
          severity: warning
        annotations:
          summary: High memory usage
          description: Memory usage is {{ $value | humanize }}GB

      # Service down
      - alert: ServiceDown
        expr: up == 0
        for: 1m
        labels:
          severity: critical
        annotations:
          summary: Service is down
          description: "{{ $labels.instance }} has been down for more than 1 minute"

  - name: business
    rules:
      # Low order volume
      - alert: LowOrderVolume
        expr: |
          sum(rate(orders_total{status="completed"}[1h])) < 10
        for: 30m
        labels:
          severity: warning
        annotations:
          summary: Low order volume
          description: Order rate is {{ $value }} orders/hour

      # Payment failures
      - alert: HighPaymentFailureRate
        expr: |
          sum(rate(orders_total{status="payment_failed"}[15m]))
          /
          sum(rate(orders_total[15m]))
          > 0.1
        for: 5m
        labels:
          severity: critical
        annotations:
          summary: High payment failure rate
          description: Payment failure rate is {{ $value | humanizePercentage }}

6. Health Checks

import { HealthCheck, HealthCheckResult, HttpHealthIndicator, DiskHealthIndicator, MemoryHealthIndicator } from '@nestjs/terminus';

interface HealthStatus {
  status: 'healthy' | 'degraded' | 'unhealthy';
  checks: Record<string, CheckResult>;
  timestamp: string;
  version: string;
}

interface CheckResult {
  status: 'pass' | 'fail' | 'warn';
  duration: number;
  message?: string;
}

async function healthCheck(): Promise<HealthStatus> {
  const checks: Record<string, CheckResult> = {};
  let overallStatus: HealthStatus['status'] = 'healthy';

  // Database check
  checks.database = await checkDatabase();
  if (checks.database.status === 'fail') overallStatus = 'unhealthy';

  // Redis check
  checks.redis = await checkRedis();
  if (checks.redis.status === 'fail') overallStatus = 'unhealthy';

  // External API check
  checks.externalApi = await checkExternalApi();
  if (checks.externalApi.status === 'warn') {
    overallStatus = overallStatus === 'healthy' ? 'degraded' : overallStatus;
  }

  // Memory check
  checks.memory = checkMemory();
  if (checks.memory.status === 'warn') {
    overallStatus = overallStatus === 'healthy' ? 'degraded' : overallStatus;
  }

  return {
    status: overallStatus,
    checks,
    timestamp: new Date().toISOString(),
    version: process.env.APP_VERSION || 'unknown',
  };
}

async function checkDatabase(): Promise<CheckResult> {
  const start = Date.now();
  try {
    await db.$queryRaw`SELECT 1`;
    return {
      status: 'pass',
      duration: Date.now() - start,
    };
  } catch (error) {
    return {
      status: 'fail',
      duration: Date.now() - start,
      message: error.message,
    };
  }
}

// Endpoints
app.get('/health', async (req, res) => {
  const health = await healthCheck();
  const statusCode = health.status === 'healthy' ? 200 :
                     health.status === 'degraded' ? 200 : 503;
  res.status(statusCode).json(health);
});

app.get('/health/live', (req, res) => {
  res.status(200).json({ status: 'alive' });
});

app.get('/health/ready', async (req, res) => {
  const health = await healthCheck();
  res.status(health.status === 'unhealthy' ? 503 : 200).json(health);
});

Use Cases

1. Debugging Production Issues

// Correlation ID for request tracing
const correlationId = req.headers['x-correlation-id'] || uuid();
req.log = logger.child({ correlationId });

// Log at decision points
req.log.info({ userId, action: 'checkout.started' });
// ... process ...
req.log.info({ orderId, action: 'order.created' });

2. Performance Monitoring

// Track key business metrics
businessMetrics.apiLatency.observe(duration);
businessMetrics.cacheHitRate.set(hits / total);

Best Practices

Do's

• Use correlation IDs - Trace requests across services
• Log at appropriate levels - Don't log everything as error
• Set meaningful alerts - Alert on symptoms, not causes
• Create actionable dashboards - Show what matters
• Implement log rotation - Prevent disk exhaustion
• Sample high-volume traces - Balance detail vs cost

Don'ts

• Don't log sensitive data
• Don't ignore alert fatigue
• Don't skip structured logging
• Don't forget log levels
• Don't alert on every error
• Don't neglect log retention policies

Related Skills

• kubernetes - Container orchestration
• backend-development - Application code
• performance-profiling - Performance analysis

Reference Resources

• OpenTelemetry Documentation
• Prometheus Documentation
• Grafana Documentation
• Pino Logger