Przejdź do treści
·21 min czytania

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

Structured logging z Pino, metryki z Prometheus, distributed tracing z OpenTelemetry. Stos obserwowalności, którego używam dla produkcyjnych aplikacji Node.js, od zera do pełnej widoczności.

node.jsobservabilitydevopsmonitoringbackend
Udostępnij:X / TwitterLinkedIn

Kiedyś myślałem, że obserwowalność oznacza "dodaj trochę console.logów i sprawdź je, kiedy coś się zepsuje". To działało, aż przestało. Punkt przełomowy to był incydent produkcyjny, gdzie nasze API zwracało 200, ale dane były nieaktualne. Żadnych błędów w logach. Żadnych wyjątków. Po prostu cicho złe odpowiedzi, bo downstream cache stał się nieaktualny i nikt nie zauważył przez cztery godziny.

Wtedy nauczyłem się różnicy między monitoringiem a obserwowalnością. Monitoring mówi ci, że coś jest nie tak. Obserwowalność mówi ci, dlaczego jest nie tak. A luka między tymi dwoma to miejsce, gdzie żyją incydenty produkcyjne.

To jest stos obserwowalności, na którym się ustabilizowałem dla serwisów Node.js po wypróbowaniu większości alternatyw. To nie jest najbardziej wyrafinowany setup na świecie, ale łapie problemy zanim użytkownicy je zauważą, a kiedy coś się jednak prześlizgnie, mogę to zdiagnozować w minuty zamiast godzin.

Trzy filary i dlaczego potrzebujesz wszystkich trzech#

Wszyscy mówią o "trzech filarach obserwowalności" — logach, metrykach i trace'ach. Czego nikt ci nie mówi, to że każdy filar odpowiada na fundamentalnie inne pytanie i potrzebujesz wszystkich trzech, bo żaden sam nie odpowie na każde pytanie.

Logi odpowiadają na: Co się stało?

Logi to zapis zdarzeń. "Użytkownik X zalogował się o 14:23." "Zapytanie do bazy danych trwało 450ms." "Żądanie API nie powiodło się z kodem 503." Są szczegółowe, czytelne dla człowieka (albo przynajmniej mogą być) i mówią ci konkretną sekwencję wydarzeń.

Metryki odpowiadają na: Jaki jest trend?

Metryki to wartości liczbowe w czasie. "Opóźnienie P99 to 230ms." "Użycie pamięci wynosi 72%." "Przetwarzamy 1,200 żądań na sekundę." Nie mówią ci co się stało, ale mówią ci czy coś jest nie tak — i czy robi się lepiej czy gorzej.

Trace'y odpowiadają na: Jak przepływa request?

Trace'y śledzą jedno żądanie w miarę jak przechodzi przez wiele serwisów. "Żądanie tego użytkownika trafiło do bramy API, potem do serwisu użytkowników, potem do bazy danych, potem do cache'u Redis, i na tym kroku bazy danych spędziło 400ms." Trace'y pokazują gdzie w łańcuchu serwisów czas jest spędzany.

Dlaczego potrzebujesz wszystkich trzech#

Metryki mówią ci, że opóźnienie P99 wzrosło z 100ms do 800ms. Trace'y pokazują ci, że to krok bazy danych w serwisie płatności jest wolny. Logi z tego serwisu mówią ci, że nowa migracja dodała brakujący indeks, a sequential scan zabija wydajność.

Każdy filar sam zostawiłby cię z częścią historii.

Structured Logging z Pino#

console.log to debugowanie, nie logowanie. W systemie produkcyjnym potrzebujesz logów, które są:

  • Ustrukturyzowane (JSON, nie tekst swobodny)
  • Z poziomami (debug, info, warn, error)
  • Z kontekstem (request ID, user ID, nazwa serwisu)
  • Wydajne (nie blokujące event loop)

Pino jest najszybszym loggerem Node.js, i to z dużym marginesem. Jest 5-10x szybszy niż Winston i 2-3x szybszy niż Bunyan. Może to nie brzmieć, jakby miało znaczenie, aż zaczniesz logować 10,000 żądań na sekundę.

typescript
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 };

Kluczowe decyzje konfiguracyjne:

pino-pretty tylko w development. Na produkcji chcesz surowy JSON — to jest to, co twój agregator logów (Datadog, Loki, CloudWatch) potrafi parsować. Pretty-printing jest dla ludzi, nie dla maszyn.

redact — Automatycznie cenzuruje wrażliwe pola. Nie chcesz, żeby tokeny auth czy hasła pojawiały się w twoich logach. Zdefiniuj to raz w konfiguracji loggera, a nie w każdym miejscu logowania.

base — Metadane dołączane do każdego wpisu logu. Nazwa serwisu, wersja, środowisko. Kiedy agregatujesz logi z wielu serwisów, te pola pozwalają filtrować.

Logowanie na poziomie żądania#

Każde żądanie HTTP powinno mieć unikalny identyfikator, który przechodzi przez wszystkie logi wygenerowane podczas obsługi tego żądania:

typescript
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();
}

logger.child() tworzy nowy logger, który dziedziczy wszystko z rodzica i dodaje dodatkowe pola. Każdy log wygenerowany z req.log automatycznie zawiera request ID, metodę, ścieżkę — bez przekazywania ich jawnie za każdym razem.

AsyncLocalStorage do automatycznej propagacji kontekstu#

Podejście z child loggerem działa, ale wymaga przekazywania req.log przez każde wywołanie funkcji. To się robi nużące. AsyncLocalStorage to rozwiązuje — dostarcza store kontekstowy, który podąża za asynchronicznym przepływem wykonania bez jawnego przekazywania.

typescript
// 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;
}

Teraz twój middleware wraps obsługę żądania w kontekst:

typescript
// 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();
  });
}

A dowolna funkcja gdziekolwiek na stosie wywołań może pobrać logger:

typescript
// 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
}

Metryki z Prometheus#

Logi mówią ci co się stało. Metryki mówią ci, jak system sobie radzi. Różnica jest jak różnica między czytaniem każdej transakcji na wyciągu bankowym a patrzeniem na saldo konta.

Cztery typy metryk#

Prometheus ma cztery typy metryk. Zrozumienie, którego używać kiedy, oszczędzi ci najczęstszych błędów.

Counter — Wartość, która tylko rośnie. Liczba żądań, liczba błędów, przetworzone bajty. Resetuje się do zera przy restarcie.

typescript
// "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"],
});

Gauge — Wartość, która może rosnąć i maleć. Aktualne połączenia, rozmiar kolejki, temperatura, użycie heap.

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

Histogram — Obserwuje wartości i zlicza je w konfigurowalnych kubełkach. Czas trwania żądań, rozmiar odpowiedzi. Tak dostajesz percentyle (P50, P95, P99).

typescript
// "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],
});

Summary — Podobny do Histogramu, ale oblicza kwantyle po stronie klienta. Używaj Histogramu, chyba że masz konkretny powód. Summary nie mogą być agregowane między instancjami.

Pełna konfiguracja prom-client#

typescript
// 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],
});

Middleware metryk#

typescript
// 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();
}

Endpoint /metrics#

typescript
// 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;

Niestandardowe metryki biznesowe to prawdziwa potęga#

Domyślne metryki Node.js (heap size, event loop lag, GC duration) to minimum. Mówią ci o zdrowiu runtime'u. Ale metryki biznesowe mówią ci o zdrowiu aplikacji.

typescript
// 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;
  }
}

Skok w ordersProcessed{status="failed"} mówi ci coś, czego żadna ilość metryk CPU nigdy nie powie.

Kardynalność etykiet: cichy zabójca#

Słowo ostrzeżenia. Każda unikalna kombinacja wartości etykiet tworzy nową serię czasową. Jeśli dodasz etykietę userId do swojego countera żądań HTTP, a masz 100,000 użytkowników, właśnie stworzyłeś 100,000+ serii czasowych. Prometheus się zatrzyma.

Zasady dla etykiet:

  • Tylko niska kardynalność: metoda HTTP (7 wartości), kod statusu (5 kategorii), ścieżka (dziesiątki, nie tysiące)
  • Nigdy nie używaj user ID, request ID, adresów IP ani timestampów jako wartości etykiet
  • Jeśli nie jesteś pewien, nie dodawaj etykiety. Zawsze możesz dodać ją później, ale usunięcie wymaga zmiany dashboardów i alertów

Dashboardy Grafana#

Prometheus przechowuje dane. Grafana je wizualizuje. Oto panele, które wstawiam na każdy dashboard serwisu Node.js.

Podstawowy dashboard#

1. Request Rate (requests/second)

promql
rate(nodeapp_http_requests_total[5m])

Pokazuje wzorzec ruchu. Przydatne do wykrywania nagłych skoków lub spadków.

2. Error Rate (%)

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

Najważniejsza pojedyncza liczba. Jeśli przekroczy 1%, coś jest nie tak.

3. p50 / p95 / p99 Latency

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

P50 mówi ci o typowym doświadczeniu. P99 mówi ci o najgorszym doświadczeniu. Jeśli P99 to 10x P50, masz problem z tail latency.

4. Event Loop Lag

promql
nodeapp_nodejs_eventloop_lag_seconds{quantile="0.99"}

Jeśli przekroczy 100ms, twój event loop jest zablokowany. Prawdopodobnie synchroniczna operacja w asynchronicznej ścieżce.

5. Heap Usage

promql
nodeapp_nodejs_heap_size_used_bytes / nodeapp_nodejs_heap_size_total_bytes * 100

Obserwuj stały trend wzrostowy — to wyciek pamięci. Skoki podczas GC są normalne.

6. Active Handles

promql
nodeapp_nodejs_active_handles_total

Otwarte file descriptory, sockety, timery. Ciągle rosnąca liczba oznacza, że tracisz handle — prawdopodobnie nie zamykasz połączeń do bazy danych albo odpowiedzi HTTP.

Dashboard jako kod#

Możesz wersjonować swoje dashboardy używając provisioning feature Grafany. Eksportuj JSON dashboardu z Grafany, commitnij go do repo, a twój dashboard przeżyje reinstalacje Grafany. To nie jest opcjonalne dla produkcji — to ta sama zasada co infrastructure as code.

Distributed Tracing z OpenTelemetry#

Tracing to filar, który większość zespołów adoptuje jako ostatni, a który chcieliby adoptować jako pierwszy. Kiedy masz wiele serwisów rozmawiających ze sobą (nawet jeśli to tylko "serwer API + baza danych + Redis + zewnętrzne API"), tracing pokazuje ci pełny obraz podróży żądania.

Czym jest trace?#

Trace to drzewo spanów. Każdy span reprezentuje jednostkę pracy — żądanie HTTP, zapytanie do bazy, wywołanie funkcji. Spany mają czas rozpoczęcia, zakończenia, status i atrybuty. Są połączone trace ID, które jest propagowane między granicami serwisów.

Trace: abc-123
├── [API Gateway] POST /api/orders (250ms)
│   ├── [Auth Service] validate-token (12ms)
│   ├── [Order Service] create-order (230ms)
│   │   ├── [PostgreSQL] INSERT INTO orders (15ms)
│   │   ├── [Redis] SET order:cache (2ms)
│   │   └── [Payment Service] charge (200ms)
│   │       ├── [Stripe API] POST /v1/charges (180ms)
│   │       └── [PostgreSQL] UPDATE orders SET status (8ms)
│   └── [Email Service] send-confirmation (async, 45ms)

Jedno spojrzenie mówi ci: 250ms żądanie spędziło 180ms czekając na Stripe. To jest miejsce, które optymalizujesz.

Setup OpenTelemetry#

OpenTelemetry (OTel) to standard. Zastąpił fragmentaryczny krajobraz klientów Jaegera, klientów Zipkina i vendorowych SDK jednym, vendor-neutralnym API.

typescript
// 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)
  );
});

Uruchom swoją aplikację z:

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

To wszystko. Bez żadnych zmian w kodzie aplikacji dostajesz trace'y dla każdego żądania HTTP, każdego zapytania do bazy, każdego polecenia Redis.

Ręczne tworzenie spanów#

Auto-instrumentacja pokrywa wywołania infrastrukturalne, ale czasem chcesz tracować logikę biznesową:

typescript
// 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();
    }
  });
}

Propagacja kontekstu trace'u#

Magia distributed tracingu polega na tym, że trace ID podąża za żądaniem między serwisami. Kiedy Serwis A wywołuje Serwis B, kontekst trace'u jest automatycznie wstrzykiwany do nagłówków HTTP (nagłówek traceparent zgodnie ze standardem W3C Trace Context).

Auto-instrumentacja obsługuje to dla wychodzących wywołań HTTP. Ale jeśli używasz kolejki wiadomości, musisz propagować ręcznie:

typescript
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();
    });
  });
}

Gdzie wysyłać trace'y#

Jaeger — Klasyczna opcja open-source. Dobre UI, łatwy do uruchomienia lokalnie z Dockerem. Ograniczone długoterminowe przechowywanie.

Grafana Tempo — Jeśli już używasz Grafany i Loki, Tempo to naturalny wybór dla trace'ów. Używa object storage (S3/GCS) dla opłacalnego długoterminowego przechowywania.

Grafana Cloud / Datadog / Honeycomb — Jeśli nie chcesz uruchamiać infrastruktury. Droższe, mniej obciążenia operacyjnego.

Do lokalnego developmentu Jaeger w Dockerze jest idealny:

yaml
# 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

Endpointy Health Check#

Health checki to najprostsza forma obserwowalności i pierwsza rzecz, którą powinieneś zaimplementować. Odpowiadają na jedno pytanie: "Czy ten serwis jest w stanie obsługiwać żądania teraz?"

Trzy typy health checków#

/health — Ogólny stan zdrowia. Czy proces działa i odpowiada?

/ready — Gotowość. Czy ten serwis może obsługiwać ruch? (Czy połączył się z bazą danych? Czy załadował konfigurację? Czy rozgrzał cache?)

/live — Żywotność. Czy proces żyje i nie jest w deadlocku? (Czy może odpowiedzieć na proste żądanie w ramach timeoutu?)

To rozróżnienie ma znaczenie dla Kubernetes, gdzie liveness probes restartują zablokowane kontenery, a readiness probes usuwają kontenery z load balancera podczas startupu lub awarii zależności.

typescript
// 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;
}

Częsty błąd: zbyt agresywne liveness probes. Jeśli twój liveness probe sprawdza bazę danych, a baza tymczasowo leży, Kubernetes zrestartuje twój kontener. Ale restart nie naprawi bazy. Teraz masz crash loop na szczycie awarii bazy. Trzymaj liveness probes proste — powinny wykrywać tylko deadlockowane lub zablokowane procesy.

Error Tracking z Sentry#

Logi łapią błędy, których się spodziewałeś. Sentry łapie te, których się nie spodziewałeś.

Różnica jest istotna. Dodajesz bloki try/catch wokół kodu, o którym wiesz, że może failować. Ale bugi, które najbardziej się liczą, to te w kodzie, o którym myślałeś, że jest bezpieczny. Nieobsłużone promise rejection, błędy typów z nieoczekiwanych odpowiedzi API, null pointer access na optional chainach, które nie były wystarczająco opcjonalne.

typescript
// 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;
    },
  });
}

Koszt nieobsłużonych promise rejections#

Od Node.js 15, nieobsłużone promise rejections domyślnie crashują proces. To jest dobre — wymusza obsługę błędów. Ale potrzebujesz siatki bezpieczeństwa:

typescript
// 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);
  });
});

Ważna część: Sentry.flush() przed process.exit(). Bez tego event błędu może nie dotrzeć do Sentry zanim proces umrze.

Alerting: Alerty, które naprawdę mają znaczenie#

Posiadanie 200 metryk Prometheus i zero alertów to vanity monitoring. Posiadanie 50 alertów, które odpalają się codziennie, to alert fatigue — zaczniesz je ignorować, a potem przegapisz ten, który się liczy.

Cel to mała liczba alertów o wysokim sygnale, które znaczą "coś jest naprawdę nie tak i człowiek musi na to spojrzeć."

Alerty, które naprawdę mnie budzą#

yaml
# 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"

Zwróć uwagę na klauzulę for przy każdym alercie. Bez niej pojedynczy skok triggeruje alert. 5-minutowy for oznacza, że warunek musi być prawdziwy przez 5 ciągłych minut. To eliminuje szum z chwilowych blipów.

Higiena alertów#

Każdy alert musi przejść ten test:

  1. Czy jest actionable? Jeśli nikt nie może nic z tym zrobić, nie alertuj. Loguj, dashboarduj, ale nie budź nikogo.
  2. Czy wymaga interwencji człowieka? Jeśli się samo naprawia (jak chwilowy blip sieci), klauzula for powinna to odfiltrować.
  3. Czy odpalił się w ciągu ostatnich 30 dni? Jeśli nie, może być źle skonfigurowany albo próg jest zły. Przejrzyj go.
  4. Kiedy się odpala, czy ludzie się tym przejmują? Jeśli zespół regularnie go odrzuca, usuń go albo popraw próg.

Audytuję swoje alerty kwartalnie. Każdy alert dostaje jeden z trzech wyników: zachowaj, dostosuj próg, albo usuń.

Minimalny żywotny stos#

Wszystko powyżej to "pełny" stos. Nie potrzebujesz tego wszystkiego od pierwszego dnia. Oto jak skalować swoją obserwowalność w miarę jak projekt rośnie.

Etap 1: Side project / solo deweloper#

Potrzebujesz trzech rzeczy:

  1. Ustrukturyzowane logi konsolowe — Użyj Pino, wypisuj JSON na stdout. Nawet jeśli czytasz je tylko z pm2 logs, JSON logi są przeszukiwalne i parsowalne.

  2. Endpoint /health — Zajmuje 5 minut do implementacji, ratuje cię, kiedy debugujesz "czy to w ogóle działa?"

  3. Darmowy tier Sentry — Łapie błędy, których nie przewidziałeś. Darmowy tier daje ci 5,000 eventów/miesiąc, co jest wystarczające dla side projectu.

Etap 2: Rosnący projekt / mały zespół#

Dodaj:

  1. Metryki Prometheus + Grafana — Kiedy "wydaje się wolne" nie wystarcza i potrzebujesz danych. Zacznij od request rate, error rate i p99 latency.

  2. Agregacja logów — Kiedy ssh na serwer i grep po plikach przestaje się skalować. Loki + Promtail, jeśli już używasz Grafany.

  3. Podstawowe alerty — Error rate > 1%, p99 > 1s, serwis down. Trzy alerty. To tyle.

Etap 3: Serwis produkcyjny / wiele serwisów#

Dodaj:

  1. Distributed tracing z OpenTelemetry — Kiedy "API jest wolne" staje się "który z 5 serwisów, które wywołuje, jest wolny?" Auto-instrumentacja OTel daje ci 80% wartości bez żadnych zmian w kodzie.

  2. Dashboard jako kod — Wersjonuj swoje dashboardy Grafany. Podziękujesz sobie, kiedy będziesz musiał je odtworzyć.

  3. Ustrukturyzowany alerting — AlertManager z właściwym routingiem, eskalacją i regułami wyciszania.

  4. Metryki biznesowe — Zamówienia/sekundę, conversion rate, głębokość kolejki. Metryki, o które dba twój zespół produktowy.

Czego unikać#

  • Vendorzy APM z pricing per-host — Na skali koszt jest absurdalny. Open source (Prometheus + Grafana + Tempo + Loki) daje ci 95% funkcjonalności.
  • Poziomy logów poniżej INFO na produkcji — Wygenerujesz terabajty DEBUG logów i zapłacisz za storage. Używaj DEBUG tylko podczas aktywnego badania problemów, potem wyłącz.
  • Niestandardowe metryki do wszystkiego — Zacznij od metody RED (Rate, Errors, Duration) dla każdego serwisu. Dodawaj niestandardowe metryki tylko kiedy masz konkretne pytanie do odpowiedzenia.
  • Złożone próbkowanie trace'ów — Zacznij od prostego sample rate (10% na produkcji). Adaptywne próbkowanie to przedwczesna optymalizacja dla większości zespołów.

Końcowe przemyślenia#

Obserwowalność to nie produkt, który kupujesz, ani narzędzie, które instalujesz. To praktyka. To różnica między operowaniem swoim serwisem a nadzieją, że serwis operuje się sam.

Stos, który opisałem — Pino do logów, Prometheus do metryk, OpenTelemetry do trace'ów, Sentry do błędów, Grafana do wizualizacji, AlertManager do alertów — to nie jest najprostszy możliwy setup. Ale każdy element zarabia na swoje miejsce, odpowiadając na pytanie, na które inne elementy nie potrafią odpowiedzieć.

Zacznij od ustrukturyzowanych logów i endpointu health. Dodaj metryki, kiedy musisz wiedzieć "jak bardzo jest źle". Dodaj trace'y, kiedy musisz wiedzieć "gdzie idzie czas". Każda warstwa buduje na poprzedniej i żadna z nich nie wymaga przepisania aplikacji.

Najlepszy czas na dodanie obserwowalności to przed twoim ostatnim incydentem produkcyjnym. Drugi najlepszy czas to teraz.

Powiązane wpisy