Observability in Node.js: Logs, Metriken und Traces ohne die Komplexität

// Was du schreibst
console.log("User login failed", email, error.message);
 
// Was in deiner Log-Datei landet
// User login failed john@example.com ECONNREFUSED
 
// Versuche jetzt:
// 1. Alle Login-Fehler der letzten Stunde zu suchen
// 2. Fehler pro Benutzer zu zählen
// 3. Nur die ECONNREFUSED-Fehler zu filtern
// 4. Dies mit der Anfrage zu korrelieren, die es ausgelöst hat
// Viel Glück. Es ist ein unstrukturierter String. Du grepst durch Text.

// Wie Structured Logging aussieht
{
  "level": 50,
  "time": 1709312587000,
  "msg": "User login failed",
  "email": "john@example.com",
  "error": "ECONNREFUSED",
  "requestId": "req-abc-123",
  "route": "POST /api/auth/login",
  "responseTime": 1247,
  "pid": 12345
}

// src/lib/logger.ts
import pino from "pino";
 
const isProduction = process.env.NODE_ENV === "production";
 
export const logger = pino({
  level: process.env.LOG_LEVEL || (isProduction ? "info" : "debug"),
  // In der Produktion einfach JSON nach stdout. PM2/Container-Runtime erledigt den Rest.
  // In der Entwicklung pino-pretty für menschenlesbare Ausgabe.
  ...(isProduction
    ? {}
    : {
        transport: {
          target: "pino-pretty",
          options: {
            colorize: true,
            translateTime: "HH:MM:ss",
            ignore: "pid,hostname",
          },
        },
      }),
  // Standard-Felder auf jeder Log-Zeile
  base: {
    service: process.env.SERVICE_NAME || "api",
    version: process.env.APP_VERSION || "unknown",
  },
  // Error-Objekte ordentlich serialisieren
  serializers: {
    err: pino.stdSerializers.err,
    error: pino.stdSerializers.err,
    req: pino.stdSerializers.req,
    res: pino.stdSerializers.res,
  },
  // Sensible Felder redigieren
  redact: {
    paths: ["req.headers.authorization", "req.headers.cookie", "password", "creditCard", "ssn"],
    censor: "[REDACTED]",
  },
});

// FATAL (60) - Der Prozess stürzt gleich ab. Weck jemanden auf.
logger.fatal({ err }, "Unrecoverable database connection failure");
 
// ERROR (50) - Etwas ist fehlgeschlagen, das nicht hätte fehlschlagen sollen. Bald untersuchen.
logger.error({ err, userId, orderId }, "Payment processing failed");
 
// WARN (40) - Etwas Unerwartetes, aber behandelt. Im Auge behalten.
logger.warn({ retryCount: 3, service: "email" }, "Retry limit approaching");
 
// INFO (30) - Normale Operationen, die es wert sind, aufgezeichnet zu werden.
logger.info({ userId, action: "login" }, "User authenticated");
 
// DEBUG (20) - Detaillierte Informationen zum Debuggen. Nie in der Produktion.
logger.debug({ query, params }, "Database query executing");
 
// TRACE (10) - Extrem detailliert. Nur wenn du verzweifelt bist.
logger.trace({ headers: req.headers }, "Incoming request headers");

// Jeder Log von diesem Child-Logger enthält userId und sessionId
const userLogger = logger.child({ userId: "usr_4821", sessionId: "ses_xyz" });
 
userLogger.info("User viewed dashboard");
// Ausgabe enthält userId und sessionId automatisch
 
userLogger.info({ page: "/settings" }, "User navigated");
// Ausgabe enthält userId, sessionId UND page

// src/middleware/request-logger.ts
import { randomUUID } from "node:crypto";
import { logger } from "../lib/logger";
import type { Request, Response, NextFunction } from "express";
 
export function requestLogger(req: Request, res: Response, next: NextFunction) {
  const requestId = req.headers["x-request-id"]?.toString() || randomUUID();
  const startTime = performance.now();
 
  // Einen Child-Logger an den Request anhängen
  req.log = logger.child({
    requestId,
    method: req.method,
    url: req.originalUrl,
    userAgent: req.headers["user-agent"],
    ip: req.headers["x-forwarded-for"]?.toString().split(",").pop()?.trim() || req.socket.remoteAddress,
  });
 
  res.setHeader("x-request-id", requestId);
  req.log.info("Request received");
 
  res.on("finish", () => {
    const duration = Math.round(performance.now() - startTime);
    const logMethod = res.statusCode >= 500 ? "error" : res.statusCode >= 400 ? "warn" : "info";
 
    req.log[logMethod](
      {
        statusCode: res.statusCode,
        duration,
        contentLength: res.getHeader("content-length"),
      },
      "Request completed",
    );
  });
 
  next();
}

// src/lib/async-context.ts
import { AsyncLocalStorage } from "node:async_hooks";
import { logger } from "./logger";
import type { Logger } from "pino";
 
interface RequestContext {
  requestId: string;
  logger: Logger;
  userId?: string;
  startTime: number;
}
 
export const asyncContext = new AsyncLocalStorage<RequestContext>();
 
// Den kontextuellen Logger von überall im Call Stack holen
export function getLogger(): Logger {
  const store = asyncContext.getStore();
  return store?.logger || logger;
}
 
export function getRequestId(): string | undefined {
  return asyncContext.getStore()?.requestId;
}

// src/middleware/async-context-middleware.ts
import { randomUUID } from "node:crypto";
import { asyncContext } from "../lib/async-context";
import { logger } from "../lib/logger";
import type { Request, Response, NextFunction } from "express";
 
export function asyncContextMiddleware(req: Request, res: Response, next: NextFunction) {
  const requestId = req.headers["x-request-id"]?.toString() || randomUUID();
  const requestLogger = logger.child({ requestId });
 
  const context = {
    requestId,
    logger: requestLogger,
    startTime: performance.now(),
  };
 
  asyncContext.run(context, () => {
    res.setHeader("x-request-id", requestId);
    next();
  });
}

// src/services/order-service.ts
import { getLogger } from "../lib/async-context";
 
export async function processOrder(orderId: string) {
  const log = getLogger(); // Hat automatisch requestId angehängt!
 
  log.info({ orderId }, "Processing order");
 
  const items = await fetchOrderItems(orderId);
  log.debug({ itemCount: items.length }, "Order items fetched");
 
  const total = calculateTotal(items);
  log.info({ orderId, total }, "Order processed successfully");
 
  return { orderId, total, items };
}
 
// Kein Logger als Parameter nötig. Es funktioniert einfach.

# Logs in Echtzeit ansehen
pm2 logs api --lines 100
 
# Logs werden gespeichert unter ~/.pm2/logs/
# api-out.log  — stdout (deine JSON-Logs)
# api-error.log — stderr (unbehandelte Exceptions, Stack-Traces)

pm2 install pm2-logrotate
pm2 set pm2-logrotate:max_size 50M
pm2 set pm2-logrotate:retain 14
pm2 set pm2-logrotate:compress true

# /etc/promtail/config.yml
server:
  http_listen_port: 9080
 
positions:
  filename: /tmp/positions.yaml
 
clients:
  - url: http://loki:3100/loki/api/v1/push
 
scrape_configs:
  - job_name: node-api
    static_configs:
      - targets:
          - localhost
        labels:
          job: node-api
          environment: production
          __path__: /home/deploy/.pm2/logs/api-out.log
    pipeline_stages:
      - json:
          expressions:
            level: level
            msg: msg
            service: service
      - labels:
          level:
          service:
      - timestamp:
          source: time
          format: UnixMs

// "Wie viele Anfragen haben wir bedient?"
const httpRequestsTotal = new Counter({
  name: "http_requests_total",
  help: "Total number of HTTP requests",
  labelNames: ["method", "route", "status_code"],
});

// "Wie viele Verbindungen sind gerade aktiv?"
const activeConnections = new Gauge({
  name: "active_connections",
  help: "Number of currently active connections",
});

// "Wie lange dauern Anfragen?" mit Buckets bei 10ms, 50ms, 100ms, usw.
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.25, 0.5, 1, 2.5, 5, 10],
});

// src/lib/metrics.ts
import { Registry, Counter, Histogram, Gauge, collectDefaultMetrics } from "prom-client";
 
// Eigene Registry erstellen
export const metricsRegistry = new Registry();
 
// Standard-Node.js-Metriken sammeln
collectDefaultMetrics({
  register: metricsRegistry,
  prefix: "nodeapp_",
  gcDurationBuckets: [0.001, 0.01, 0.1, 1, 2, 5],
});
 
// --- HTTP-Metriken ---
 
export const httpRequestsTotal = new Counter({
  name: "nodeapp_http_requests_total",
  help: "Total number of HTTP requests received",
  labelNames: ["method", "route", "status_code"] as const,
  registers: [metricsRegistry],
});
 
export const httpRequestDuration = new Histogram({
  name: "nodeapp_http_request_duration_seconds",
  help: "Duration of HTTP requests in seconds",
  labelNames: ["method", "route", "status_code"] as const,
  buckets: [0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10],
  registers: [metricsRegistry],
});
 
// --- Business-Metriken ---
 
export const ordersProcessed = new Counter({
  name: "nodeapp_orders_processed_total",
  help: "Total number of orders processed",
  labelNames: ["status"] as const,
  registers: [metricsRegistry],
});
 
export const externalApiDuration = new Histogram({
  name: "nodeapp_external_api_duration_seconds",
  help: "Duration of external API calls",
  labelNames: ["service", "endpoint", "status"] as const,
  buckets: [0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30],
  registers: [metricsRegistry],
});
 
export const dbQueryDuration = new Histogram({
  name: "nodeapp_db_query_duration_seconds",
  help: "Duration of database queries",
  labelNames: ["operation", "table"] as const,
  buckets: [0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1, 5],
  registers: [metricsRegistry],
});

// src/middleware/metrics-middleware.ts
import { httpRequestsTotal, httpRequestDuration } from "../lib/metrics";
import type { Request, Response, NextFunction } from "express";
 
// Routen normalisieren, um Kardinalitätsexplosion zu vermeiden
function normalizeRoute(req: Request): string {
  const route = req.route?.path || req.path;
  return route
    .replace(/\/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/g, "/:uuid")
    .replace(/\/\d+/g, "/:id")
    .replace(/\/[a-f0-9]{24}/g, "/:objectId");
}
 
export function metricsMiddleware(req: Request, res: Response, next: NextFunction) {
  if (req.path === "/metrics") {
    return next();
  }
 
  const end = httpRequestDuration.startTimer();
 
  res.on("finish", () => {
    const route = normalizeRoute(req);
    const labels = {
      method: req.method,
      route,
      status_code: res.statusCode.toString(),
    };
 
    httpRequestsTotal.inc(labels);
    end(labels);
  });
 
  next();
}

// In deinem Order-Service
import { ordersProcessed, externalApiDuration } from "../lib/metrics";
 
export async function processOrder(order: Order) {
  try {
    const paymentTimer = externalApiDuration.startTimer({
      service: "stripe",
      endpoint: "charges.create",
    });
 
    const charge = await stripe.charges.create({
      amount: order.total,
      currency: "usd",
      source: order.paymentToken,
    });
 
    paymentTimer({ status: "success" });
    ordersProcessed.inc({ status: "success" });
    return charge;
  } catch (err) {
    ordersProcessed.inc({ status: "failed" });
    throw err;
  }
}

rate(nodeapp_http_requests_total[5m])

100 * (
  sum(rate(nodeapp_http_requests_total{status_code=~"5.."}[5m]))
  /
  sum(rate(nodeapp_http_requests_total[5m]))
)

histogram_quantile(0.99,
  sum(rate(nodeapp_http_request_duration_seconds_bucket[5m])) by (le)
)

nodeapp_nodejs_eventloop_lag_seconds{quantile="0.99"}

nodeapp_nodejs_heap_size_used_bytes / nodeapp_nodejs_heap_size_total_bytes * 100

// src/instrumentation.ts
// Diese Datei MUSS vor allen anderen Imports geladen werden.
 
import { NodeSDK } from "@opentelemetry/sdk-node";
import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http";
import { OTLPMetricExporter } from "@opentelemetry/exporter-metrics-otlp-http";
import { PeriodicExportingMetricReader } from "@opentelemetry/sdk-metrics";
import { getNodeAutoInstrumentations } from "@opentelemetry/auto-instrumentations-node";
import { Resource } from "@opentelemetry/resources";
import { ATTR_SERVICE_NAME, ATTR_SERVICE_VERSION } from "@opentelemetry/semantic-conventions";
 
const sdk = new NodeSDK({
  resource: new Resource({
    [ATTR_SERVICE_NAME]: process.env.SERVICE_NAME || "node-api",
    [ATTR_SERVICE_VERSION]: process.env.APP_VERSION || "0.0.0",
    "deployment.environment": process.env.NODE_ENV || "development",
  }),
 
  traceExporter: new OTLPTraceExporter({
    url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT || "http://localhost:4318/v1/traces",
  }),
 
  metricReader: new PeriodicExportingMetricReader({
    exporter: new OTLPMetricExporter({
      url: process.env.OTEL_EXPORTER_OTLP_ENDPOINT || "http://localhost:4318/v1/metrics",
    }),
    exportIntervalMillis: 15000,
  }),
 
  instrumentations: [
    getNodeAutoInstrumentations({
      "@opentelemetry/instrumentation-fs": { enabled: false },
      "@opentelemetry/instrumentation-dns": { enabled: false },
      "@opentelemetry/instrumentation-http": {
        ignoreIncomingPaths: ["/health", "/ready", "/metrics"],
      },
      "@opentelemetry/instrumentation-express": {
        ignoreLayersType: ["middleware"],
      },
    }),
  ],
});
 
sdk.start();
 
process.on("SIGTERM", () => {
  sdk.shutdown().then(
    () => console.log("OTel SDK shut down successfully"),
    (err) => console.error("Error shutting down OTel SDK", err),
  );
});

node --import ./src/instrumentation.ts ./src/server.ts

// src/services/order-service.ts
import { trace, SpanStatusCode } from "@opentelemetry/api";
 
const tracer = trace.getTracer("order-service");
 
export async function processOrder(orderId: string): Promise<Order> {
  return tracer.startActiveSpan("processOrder", async (span) => {
    try {
      span.setAttribute("order.id", orderId);
 
      const order = await fetchOrder(orderId);
      span.setAttribute("order.total", order.total);
      span.setAttribute("order.item_count", order.items.length);
 
      const validationResult = await tracer.startActiveSpan("validateOrder", async (validationSpan) => {
        const result = await validateInventory(order);
        validationSpan.setAttribute("validation.passed", result.valid);
        if (!result.valid) {
          validationSpan.setStatus({
            code: SpanStatusCode.ERROR,
            message: `Validation failed: ${result.reason}`,
          });
        }
        validationSpan.end();
        return result;
      });
 
      if (!validationResult.valid) {
        span.setStatus({
          code: SpanStatusCode.ERROR,
          message: "Order validation failed",
        });
        throw new Error(validationResult.reason);
      }
 
      const payment = await processPayment(order);
      span.setAttribute("payment.id", payment.id);
      span.setStatus({ code: SpanStatusCode.OK });
      return order;
    } catch (err) {
      span.recordException(err as Error);
      span.setStatus({
        code: SpanStatusCode.ERROR,
        message: (err as Error).message,
      });
      throw err;
    } finally {
      span.end();
    }
  });
}

import { context, propagation } from "@opentelemetry/api";
 
// Beim Veröffentlichen einer Nachricht
function publishEvent(queue: string, payload: object) {
  const carrier: Record<string, string> = {};
  propagation.inject(context.active(), carrier);
  messageQueue.publish(queue, {
    payload,
    traceContext: carrier,
  });
}
 
// Beim Konsumieren einer Nachricht
function consumeEvent(message: QueueMessage) {
  const parentContext = propagation.extract(context.active(), message.traceContext);
  context.with(parentContext, () => {
    tracer.startActiveSpan("processEvent", (span) => {
      span.setAttribute("queue.message_id", message.id);
      handleEvent(message.payload);
      span.end();
    });
  });
}

# docker-compose.otel.yml
services:
  jaeger:
    image: jaegertracing/all-in-one:latest
    ports:
      - "16686:16686" # Jaeger UI
      - "4318:4318" # OTLP HTTP receiver
    environment:
      - COLLECTOR_OTLP_ENABLED=true

// src/routes/health.ts
import { Router } from "express";
import { Pool } from "pg";
import Redis from "ioredis";
 
const router = Router();
 
interface HealthCheckResult {
  status: "ok" | "degraded" | "error";
  checks: Record<string, { status: "ok" | "error"; latency?: number; message?: string }>;
  uptime: number;
  timestamp: string;
  version: string;
}
 
async function checkDatabase(pool: Pool): Promise<{ ok: boolean; latency: number }> {
  const start = performance.now();
  try {
    await pool.query("SELECT 1");
    return { ok: true, latency: Math.round(performance.now() - start) };
  } catch {
    return { ok: false, latency: Math.round(performance.now() - start) };
  }
}
 
async function checkRedis(redis: Redis): Promise<{ ok: boolean; latency: number }> {
  const start = performance.now();
  try {
    await redis.ping();
    return { ok: true, latency: Math.round(performance.now() - start) };
  } catch {
    return { ok: false, latency: Math.round(performance.now() - start) };
  }
}
 
export function createHealthRoutes(pool: Pool, redis: Redis) {
  router.get("/live", (_req, res) => {
    res.status(200).json({ status: "ok" });
  });
 
  router.get("/ready", async (_req, res) => {
    const [db, cache] = await Promise.all([checkDatabase(pool), checkRedis(redis)]);
 
    const allOk = db.ok && cache.ok;
    res.status(allOk ? 200 : 503).json({
      status: allOk ? "ok" : "not_ready",
      checks: { database: db, redis: cache },
    });
  });
 
  router.get("/health", async (_req, res) => {
    const [db, cache] = await Promise.all([checkDatabase(pool), checkRedis(redis)]);
 
    const anyError = !db.ok || !cache.ok;
    const allError = !db.ok && !cache.ok;
 
    const result: HealthCheckResult = {
      status: allError ? "error" : anyError ? "degraded" : "ok",
      checks: {
        database: {
          status: db.ok ? "ok" : "error",
          latency: db.latency,
          ...(!db.ok && { message: "Connection failed" }),
        },
        redis: {
          status: cache.ok ? "ok" : "error",
          latency: cache.latency,
          ...(!cache.ok && { message: "Connection failed" }),
        },
      },
      uptime: process.uptime(),
      timestamp: new Date().toISOString(),
      version: process.env.APP_VERSION || "unknown",
    };
 
    res.status(result.status === "error" ? 503 : 200).json(result);
  });
 
  return router;
}

# prometheus/alerts.yml
groups:
  - name: node-api
    rules:
      - alert: HighErrorRate
        expr: |
          100 * sum(rate(nodeapp_http_requests_total{status_code=~"5.."}[5m]))
          / sum(rate(nodeapp_http_requests_total[5m])) > 5
        for: 2m
        labels:
          severity: critical
 
      - alert: HighLatency
        expr: |
          histogram_quantile(0.99,
            sum(rate(nodeapp_http_request_duration_seconds_bucket[5m])) by (le)
          ) > 5
        for: 5m
        labels:
          severity: warning
 
      - alert: EventLoopBlocked
        expr: nodeapp_nodejs_eventloop_lag_seconds{quantile="0.99"} > 0.1
        for: 2m
        labels:
          severity: warning