Obserwowalność w Node.js: Logi, metryki i trace'y bez zbędnej złożoności

import pino from "pino";
 
const logger = pino({
  level: process.env.LOG_LEVEL ?? "info",
  transport:
    process.env.NODE_ENV === "development" ? { target: "pino-pretty", options: { colorize: true } } : undefined,
  base: {
    service: "api",
    version: process.env.APP_VERSION ?? "unknown",
    environment: process.env.NODE_ENV ?? "development",
  },
  redact: {
    paths: ["req.headers.authorization", "req.headers.cookie", "body.password", "body.token", "body.creditCard"],
    censor: "[REDACTED]",
  },
  serializers: {
    req: pino.stdSerializers.req,
    res: pino.stdSerializers.res,
    err: pino.stdSerializers.err,
  },
});
 
export { logger };

import { randomUUID } from "crypto";
import { logger } from "./logger";
 
function requestLogger(req, res, next) {
  const requestId = req.headers["x-request-id"] ?? randomUUID();
  const startTime = performance.now();
 
  // Create a child logger with request context
  req.log = logger.child({
    requestId,
    method: req.method,
    path: req.originalUrl,
    userAgent: req.headers["user-agent"],
    ip: req.headers["x-forwarded-for"]?.toString().split(",").pop()?.trim() || req.socket.remoteAddress,
  });
 
  // Set the request ID header on the response for correlation
  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>();
 
// Get the contextual logger from anywhere in the call stack
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 "crypto";
import { asyncContext } from "../lib/async-context";
import { logger } from "../lib/logger";
 
export function asyncContextMiddleware(req, res, next) {
  const requestId = req.headers["x-request-id"] ?? randomUUID();
  const requestLogger = logger.child({ requestId });
 
  const context = {
    requestId,
    logger: requestLogger,
    startTime: performance.now(),
  };
 
  asyncContext.run(context, () => {
    next();
  });
}

// src/services/user-service.ts
import { getLogger } from "../lib/async-context";
 
export async function getUserById(id: string) {
  const log = getLogger();
  log.info({ userId: id }, "Fetching user");
  // The log automatically includes requestId, no manual passing needed
}

// "How many requests have we served?"
const httpRequestsTotal = new Counter({
  name: "http_requests_total",
  help: "Total number of HTTP requests",
  labelNames: ["method", "route", "status_code"],
});

// "How many connections are active right now?"
const activeConnections = new Gauge({
  name: "active_connections",
  help: "Number of currently active connections",
});

// "How long do requests take?" with buckets at 10ms, 50ms, 100ms, etc.
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";
 
// Create a custom registry to avoid polluting the global one
export const metricsRegistry = new Registry();
 
// Collect default Node.js metrics:
// - process_cpu_seconds_total
// - process_resident_memory_bytes
// - nodejs_heap_size_total_bytes
// - nodejs_active_handles_total
// - nodejs_eventloop_lag_seconds
// - nodejs_gc_duration_seconds
collectDefaultMetrics({
  register: metricsRegistry,
  prefix: "nodeapp_",
  gcDurationBuckets: [0.001, 0.01, 0.1, 1, 2, 5],
});
 
// --- HTTP Metrics ---
 
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],
});
 
export const httpRequestSizeBytes = new Histogram({
  name: "nodeapp_http_request_size_bytes",
  help: "Size of HTTP request bodies in bytes",
  labelNames: ["method", "route"] as const,
  buckets: [100, 1000, 10000, 100000, 1000000],
  registers: [metricsRegistry],
});
 
// --- Business Metrics ---
 
export const ordersProcessed = new Counter({
  name: "nodeapp_orders_processed_total",
  help: "Total number of orders processed",
  labelNames: ["status"] as const, // "success", "failed", "refunded"
  registers: [metricsRegistry],
});
 
export const activeWebSocketConnections = new Gauge({
  name: "nodeapp_active_websocket_connections",
  help: "Number of active WebSocket connections",
  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";
 
// Normalize routes to avoid cardinality explosion
// /api/users/123 → /api/users/:id
// Without this, Prometheus will create a new time series for every user ID
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) {
  // Don't track metrics for the metrics endpoint itself
  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();
}

// src/routes/metrics.ts
import { Router } from "express";
import { metricsRegistry } from "../lib/metrics";
 
const router = Router();
 
router.get("/metrics", async (req, res) => {
  // Basic auth protection — don't expose metrics publicly
  const authHeader = req.headers.authorization;
  const expected = `Basic ${Buffer.from(`${process.env.METRICS_USER}:${process.env.METRICS_PASSWORD}`).toString(
    "base64",
  )}`;
 
  if (!authHeader || authHeader !== expected) {
    res.status(401).set("WWW-Authenticate", "Basic").send("Unauthorized");
    return;
  }
 
  try {
    const metrics = await metricsRegistry.metrics();
    res.set("Content-Type", metricsRegistry.contentType);
    res.send(metrics);
  } catch (err) {
    res.status(500).send("Error collecting metrics");
  }
});
 
export default router;

// In your order service
import { ordersProcessed, externalApiDuration } from "../lib/metrics";
 
export async function processOrder(order: Order) {
  try {
    // Time the payment provider call
    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" });
 
    externalApiDuration.startTimer({
      service: "stripe",
      endpoint: "charges.create",
    })({ status: "error" });
 
    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

nodeapp_nodejs_active_handles_total

// src/instrumentation.ts
// This file MUST be loaded before any other imports.
// In Node.js, use --require or --import flag.
 
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();
 
// Graceful shutdown
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";
 
// When publishing a message
function publishEvent(queue: string, payload: object) {
  const carrier: Record<string, string> = {};
 
  // Inject current trace context into the carrier
  propagation.inject(context.active(), carrier);
 
  // Send both the payload and the trace context
  messageQueue.publish(queue, {
    payload,
    traceContext: carrier,
  });
}
 
// When consuming a message
function consumeEvent(message: QueueMessage) {
  // Extract the trace context from the message
  const parentContext = propagation.extract(context.active(), message.traceContext);
 
  // Run the handler within the extracted context
  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;
}

// src/lib/sentry.ts
import * as Sentry from "@sentry/node";
import { nodeProfilingIntegration } from "@sentry/profiling-node";
 
export function initSentry() {
  Sentry.init({
    dsn: process.env.SENTRY_DSN,
    environment: process.env.NODE_ENV || "development",
    release: process.env.APP_VERSION || "unknown",
 
    tracesSampleRate: process.env.NODE_ENV === "production" ? 0.1 : 1.0,
    profilesSampleRate: 1.0,
 
    integrations: [
      nodeProfilingIntegration(),
      Sentry.rewriteFramesIntegration({
        root: process.cwd(),
      }),
    ],
 
    enabled: process.env.NODE_ENV === "production",
 
    ignoreErrors: ["ECONNRESET", "ECONNABORTED", "EPIPE", "SyntaxError: Unexpected token"],
 
    beforeSend(event) {
      if (event.request) {
        delete event.request.headers?.["x-forwarded-for"];
        delete event.request.headers?.["x-real-ip"];
        delete event.request.cookies;
      }
 
      if (event.request?.query_string) {
        const params = new URLSearchParams(event.request.query_string);
        params.delete("token");
        params.delete("api_key");
        event.request.query_string = params.toString();
      }
 
      return event;
    },
  });
}

// src/server.ts — near the top of your entry point
 
process.on("unhandledRejection", (reason, promise) => {
  logger.fatal({ reason, promise }, "Unhandled promise rejection — crashing");
  Sentry.captureException(reason);
 
  Sentry.flush(2000).finally(() => {
    process.exit(1);
  });
});
 
process.on("uncaughtException", (error) => {
  logger.fatal({ err: error }, "Uncaught exception — crashing");
  Sentry.captureException(error);
 
  Sentry.flush(2000).finally(() => {
    process.exit(1);
  });
});

# prometheus/rules/node-api.yml
groups:
  - name: node-api-critical
    rules:
      - alert: HighErrorRate
        expr: |
          (
            sum(rate(nodeapp_http_requests_total{status_code=~"5.."}[5m]))
            /
            sum(rate(nodeapp_http_requests_total[5m]))
          ) > 0.01
        for: 5m
        labels:
          severity: critical
        annotations:
          summary: "Error rate above 1% for 5 minutes"
          description: "{{ $value | humanizePercentage }} of requests are returning 5xx"
 
      - alert: HighP99Latency
        expr: |
          histogram_quantile(0.99,
            sum(rate(nodeapp_http_request_duration_seconds_bucket[5m])) by (le)
          ) > 1
        for: 5m
        labels:
          severity: critical
        annotations:
          summary: "p99 latency above 1 second for 5 minutes"
 
      - alert: HighHeapUsage
        expr: |
          (
            nodeapp_nodejs_heap_size_used_bytes
            /
            nodeapp_nodejs_heap_size_total_bytes
          ) > 0.80
        for: 10m
        labels:
          severity: critical
        annotations:
          summary: "Heap usage above 80% for 10 minutes"
 
      - alert: ServiceDown
        expr: up{job="node-api"} == 0
        for: 1m
        labels:
          severity: critical
        annotations:
          summary: "Node.js API is down"
 
  - name: node-api-warnings
    rules:
      - alert: HighEventLoopLag
        expr: |
          nodeapp_nodejs_eventloop_lag_seconds{quantile="0.99"} > 0.1
        for: 5m
        labels:
          severity: warning
        annotations:
          summary: "Event loop lag above 100ms"
 
      - alert: TrafficDrop
        expr: |
          sum(rate(nodeapp_http_requests_total[5m]))
          < (sum(rate(nodeapp_http_requests_total[5m] offset 1h)) * 0.5)
        for: 10m
        labels:
          severity: warning
        annotations:
          summary: "Traffic dropped by more than 50% compared to 1 hour ago"
 
      - alert: SlowDatabaseQueries
        expr: |
          histogram_quantile(0.99,
            sum(rate(nodeapp_db_query_duration_seconds_bucket[5m])) by (le, operation)
          ) > 0.5
        for: 5m
        labels:
          severity: warning
        annotations:
          summary: "p99 database query time above 500ms"