Observability Traces und Logs in Node.js verweben

Einleitung

In modernen verteilten Systemen ist das Verständnis des Anwendungsverhaltens und die schnelle Diagnose von Problemen von größter Bedeutung. Während Anwendungen skalieren und komplexer werden, reichen traditionelle Logging- oder eigenständige Tracing-Tools allein nicht aus. Wir benötigen eine ganzheitliche Sicht, bei der Anwendungsprotokolle untrennbar mit dem zugrunde liegenden operativen Kontext verbunden sind – dem Ausführungspfad, den Komponenteninteraktionen und den von Traces bereitgestellten Zeitinformationen. Hier wird die Verbindung Ihres Logging-Frameworks mit Ihrem Tracing-System unglaublich wertvoll.

Im Node.js-Ökosystem sticht Pino als Hochleistungslogger hervor, während sich OpenTelemetry als Industriestandard für das Sammeln von Telemetriedaten, einschließlich Spuren, etabliert hat. Die Überbrückung der Lücke zwischen Pino und OpenTelemetry ermöglicht es uns, unsere Protokolle mit Trace-Kontext anzureichern, wodurch sie für das Debugging, die Leistungsanalyse und das allgemeine Systemverständnis erheblich leistungsfähiger werden. Dieser Artikel führt Sie durch den Prozess der Herstellung dieser entscheidenden Verbindung und verbessert letztendlich die Observability Ihrer Anwendung.

Die Säulen der Observability

Bevor wir uns mit den Implementierungsdetails befassen, definieren wir kurz die Kernkonzepte, mit denen wir arbeiten werden:

Observability: Die Fähigkeit, den internen Zustand eines Systems abzuleiten, indem dessen externe Ausgaben untersucht werden. Es geht darum, beliebige Fragen zu Ihrem System zu stellen und Antworten aus den von ihm bereitgestellten Daten (Logs, Metriken, Traces) zu erhalten.
Logs: Diskrete, mit Zeitstempeln versehene Aufzeichnungen von Ereignissen, die innerhalb einer Anwendung auftreten. Sie liefern detaillierte textuelle Informationen darüber, was wann und manchmal auch warum passiert ist. Pino ist eine ausgezeichnete Wahl für strukturiertes, leistungsstarkes Logging in Node.js.
Traces: Repräsentieren die End-to-End-Reise einer Anfrage oder Transaktion durch ein verteiltes System. Eine Trace besteht aus einem oder mehreren Spans, wobei jeder Span eine logische Arbeitseinheit darstellt (z. B. ein Funktionsaufruf, eine Datenbankabfrage, eine API-Anfrage). Traces liefern Kontext-, Kausalitäts- und Latenzinformationen über Servicgrenzen hinweg. OpenTelemetry bietet einen herstellerunabhängigen Standard für die Generierung und Sammlung von Traces.
Trace Context: Informationen, die eine Trace und ihren aktuellen Span identifizieren. Dieser Kontext wird über Prozess- und Servicgrenzen hinweg propagiert, sodass einzelne Spans zu einer vollständigen Trace verknüpft werden können. Schlüsselkomponenten sind traceId und spanId.

Ziel ist es, unsere Pino-Protokolle mit diesem Trace-Kontext zu versehen, sodass Sie mühelos von einem problematischen Protokolleintrag direkt zur relevanten Trace gelangen, die seinen gesamten Ausführungspfad zeigt.

Pino-Logs mit OpenTelemetry-Traces verbinden

Das Prinzip der Integration von Pino mit OpenTelemetry ist unkompliziert: Überall dort, wo ein Protokoll ausgegeben wird, möchten wir die aktuelle OpenTelemetry traceId und spanId in den Protokolleintrag aufnehmen. Dies schafft eine direkte Korrelation.

Schritt 1: OpenTelemetry einrichten

Stellen Sie zunächst sicher, dass Ihre Anwendung mit OpenTelemetry instrumentiert ist. Dies beinhaltet die Installation der notwendigen SDKs und Auto-Instrumentierungs-Pakete.

npm install @opentelemetry/sdk-node @opentelemetry/api @opentelemetry/auto-instrumentations-node
npm install @opentelemetry/exporter-collector --save-dev # Oder ein anderer Exporter wie OTLP gRPC

Initialisieren Sie dann OpenTelemetry am Einstiegspunkt Ihrer Anwendung (z. B. src/instrumentation.js oder src/tracing.js).

// src/tracing.js
import { NodeSDK } from '@opentelemetry/sdk-node';
import { ConsoleSpanExporter } from '@opentelemetry/sdk-trace-base';
import { Resource } from '@opentelemetry/resources';
import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions';
import { PeriodicExportingSpanProcessor } from '@opentelemetry/sdk-trace-base';
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http';
import { ExpressInstrumentation } from '@opentelemetry/instrumentation-express';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-grpc'; // Beispiel OTLP Exporter

const sdk = new NodeSDK({
  resource: new Resource({
    [SemanticResourceAttributes.SERVICE_NAME]: 'my-nodejs-app',
    [SemanticResourceAttributes.SERVICE_VERSION]: '1.0.0',
  }),
  spanProcessor: new PeriodicExportingSpanProcessor(new OTLPTraceExporter()), // Oder new ConsoleSpanExporter() für die Entwicklung
  instrumentations: [
    new HttpInstrumentation(),
    new ExpressInstrumentation(),
    // Fügen Sie andere relevante Instrumentierungen hinzu, wie z. B. @opentelemetry/instrumentation-pg für PostgreSQL
  ],
});

sdk.start();

console.log('OpenTelemetry Tracing initialisiert.');

// Um sicherzustellen, dass Traces beim Herunterfahren geleert werden
process.on('SIGTERM', () => {
  sdk.shutdown()
    .then(() => console.log('Tracing beendet'))
    .catch((error) => console.log('Fehler beim Beenden des Tracings', error))
    .finally(() => process.exit(0));
});

Stellen Sie sicher, dass Sie Ihre Anwendung mit aktivierter Instrumentierung ausführen:

node -r ./src/tracing.js src/index.js

Schritt 2: Trace-Kontext in Pino integrieren

Pino bietet eine leistungsstarke Funktion namens "bindings" oder "child loggers", mit der Sie kontextbezogene Eigenschaften zu Protokolleinträgen hinzufügen können. Wir können die Methode trace.getSpanContext() aus @opentelemetry/api verwenden, um die aktuellen Trace- und Span-IDs abzurufen.

Installieren Sie zunächst Pino:

npm install pino

Erstellen Sie nun Ihre Pino-Logger-Instanz. Der Schlüssel ist die Verwendung von pino-caller oder einer benutzerdefinierten Funktion zum Einfügen des Trace-Kontexts. Eine praktische Möglichkeit ist die Erstellung eines Child-Loggers für jede Anfrage oder Operation, bei der Kontext verfügbar ist.

Werfen wir einen Blick auf ein Beispiel mit Express.js:

// src/index.js (nach OpenTelemetry-Instrumentierung)
import express from 'express';
import pino from 'pino';
import { trace } from '@opentelemetry/api';

const app = express();
const port = 3000;

// Erstellen eines Basis-Pino-Loggers
const logger = pino({
  level: process.env.LOG_LEVEL || 'info',
  formatters: {
    // Dieser Formatter stellt sicher, dass Korrelations-IDs auf der obersten Ebene liegen
    log: (obj) => {
      if (obj.traceId && obj.spanId) {
        return { traceId: obj.traceId, spanId: obj.spanId, ...obj };
      }
      return obj;
    },
  },
});

// Middleware zum Einfügen des OpenTelemetry-Trace-Kontexts in den Logger
app.use((req, res, next) => {
  const currentSpan = trace.getSpan(trace.activeContext());
  if (currentSpan) {
    const spanContext = currentSpan.spanContext();
    if (spanContext.traceId && spanContext.spanId) {
      // Erstellen eines Child-Loggers mit Trace- und Span-IDs
      req.log = logger.child({
        traceId: spanContext.traceId,
        spanId: spanContext.spanId,
      });
      req.log.debug('Request started'); // Beispiel-Log
    } else {
      req.log = logger; // Kein Trace-Kontext, Basis-Logger verwenden
    }
  } else {
    req.log = logger; // Kein aktiver Span, Basis-Logger verwenden
  }
  next();
});

app.get('/', (req, res) => {
  req.log.info('Bearbeite Root-Anfrage');
  // Simuliere einige Arbeiten, die einen weiteren Span erzeugen könnten
  const myService = {
    doSomething: (log) => {
      log.debug('Tue etwas Wichtiges im Service');
      // Hier könnten Sie potenziell einen neuen Span erstellen, wenn dies ein separates Modul/eine Funktion wäre
      // const newSpan = tracer.startSpan('myService.doSomething');
      // newSpan.end();
    }
  };
  myService.doSomething(req.log);
  res.send('Hallo von Node.js mit korrelierten Logs!');
});

app.get('/error', (req, res) => {
    req.log.error('Ein Fehler ist bei der Request-Verarbeitung aufgetreten!');
    res.status(500).send('Etwas ist schief gelaufen!');
});

app.listen(port, () => {
  logger.info(`App lauscht auf http://localhost:${port}`);
});

In diesem Beispiel:

Wir erstellen einen Basis-pino-Logger.
Eine Middleware fängt eingehende Anfragen ab.
Innerhalb der Middleware wird trace.getSpan(trace.activeContext()) verwendet, um den aktuell aktiven OpenTelemetry-Span abzurufen.
Wenn ein Span vorhanden ist, werden seine traceId und spanId extrahiert.
Ein child-Logger wird mit logger.child({ traceId, spanId }) erstellt. Dieser Child-Logger fügt automatisch diese Eigenschaften zu jedem von ihm produzierten Protokoll hinzu.
req.log wird dann dieser Child-Logger zugewiesen, wodurch er in der gesamten Request-Verarbeitungskette verfügbar ist.

Wenn Sie nun eine Anfrage an / stellen, sehen Ihre Konsole (oder Ihr Protokollziel) Protokolle ähnlich wie diese (für bessere Lesbarkeit formatiert):

{
  "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6",
  "spanId": "f7e8d9c0b1a2e3f4",
  "level": 30,
  "time": 1678886400000,
  "pid": 12345,
  "hostname": "my-host",
  "msg": "Request started"
}
{
  "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6",
  "spanId": "f7e8d9c0b1a2e3f4",
  "level": 30,
  "time": 1678886400000,
  "pid": 12345,
  "hostname": "my-host",
  "msg": "Handling root request"
}
{
  "traceId": "a1b2c3d4e5f6a7b8c9d0e1f2a3b4c5d6",
  "spanId": "f7e8d9c0b1a2e3f4",
  "level": 20,
  "time": 1678886400000,
  "pid": 12345,
  "hostname": "my-host",
  "msg": "Doing something important in service"
}

Beachten Sie, wie traceId und spanId in allen Protokollen, die zur selben Anfrage gehören, konsistent vorhanden sind. Diese starke Korrelation ist das, was eine leistungsstarke Observability ermöglicht.

Anwendung und Vorteile

Mit dieser Einrichtung erhalten Sie mehrere Vorteile:

Schnellere Ursachenanalyse: Wenn ein Fehlerprotokoll erscheint, können Sie sofort dessen traceId verwenden, um die vollständige Trace abzurufen und alle Operationen, Dienste und Zeitmessungen zu sehen, die an dieser Anfrage beteiligt waren. Dies reduziert die Zeit, die mit der Durchsicht unrelated Protokolle verbracht wird, erheblich.
Kontextreiche Protokolle: Jeder Protokolleintrag hat den Kontext der Operation, zu der er gehört, auch wenn diese Operation mehrere Dienste umfasst.
Verbessertes Debugging: Sie können Protokolle nach traceId in Ihrem Protokollmanagementsystem filtern, um nur die Protokolle zu sehen, die für eine bestimmte Benutzerinteraktion oder einen bestimmten Prozess relevant sind, und so eine sequenzielle Erzählung von Ereignissen zu liefern.
Identifizierung von Leistungsengpässen: Durch die Korrelation von Protokollen mit Trace-Zeiten können Sie genau bestimmen, welcher Teil Ihres Codes oder welcher externe Aufruf zu lange dauert, und ihn dann bei Bedarf zu seinen detaillierten Protokollen vergrößern.
Vereinheitlichte Observability-Erfahrung: Protokollmanagementsysteme (wie Elastic Stack, Splunk, Sumo Logic, Datadog) und APM-Tools (wie Jaeger, Zipkin, Datadog APM, New Relic) können diese Korrelations-IDs nutzen, um Protokolle neben Traces anzuzeigen und so eine wirklich einheitliche Sicht auf die Gesundheit und Leistung Ihrer Anwendung zu bieten.

Fazit

Die Integration von Pino-Protokollen mit OpenTelemetry-Traces ist ein grundlegender Schritt zur Erzielung umfassender Observability in Ihren Node.js-Anwendungen. Durch das Einbetten von Trace- und Span-IDs direkt in Ihre Protokolleinträge wandeln Sie disparate Telemetriesignale in eine leistungsstarke, vernetzte Erzählung des Verhaltens Ihres Systems um. Diese Korrelation vereinfacht das Debugging, beschleunigt die Ursachenanalyse und liefert ein viel klares Bild des operativen Zustands Ihrer Anwendung. Die Übernahme dieser Praxis verschiebt Ihre Observability-Strategie von fragmentierten Erkenntnissen zu einem wirklich kohärenten Verständnis Ihrer verteilten Systeme.