Node.js und Logging – Teil 7: Einführung der Correlation-ID

Nachdem wir im letzten Artikel sensible Informationen entfernt haben, fügen wir jetzt ein wichtiges Datum hinzu: die Correlation-ID. Ich möchte nicht voraussetzen, dass du diesen Begriff einordnen kannst. Deswegen beginnen wir vor der Umsetzung mit einem theoretischen Block. Denn eins ist sicher: Die Correlation-ID hilft dir beim Debuggen. Bei verteilten Systemen mit Microservices ist sie die einzige Chance, überhaupt zu verstehen, was vor sich geht.

Welches Problem löst die Correlation-ID?
Wie hilft uns cls-rtracer dabei?
Ergänzung im EnvVarService: Correlation-ID-Header-Namen
Erstellung einer Express-Middleware
Einbindung in unsere Express-Applikation

Bevor wir loslegen, schau dir die bisherigen Artikel dieser Serie an. Du findest die Links im Überblick zur Artikelserie.

1. Welches Problem löst die Correlation-ID?

Das Problem

In moderner Backendentwicklung arbeiten wir meist mit verteilten Systemen (Microservices), asynchroner Kommunikation (Queues, Events), paralleler Verarbeitung (Threads, Worker) sowie Load-Balancern und Retries.

Eine einzelne Benutzeranfrage erzeugt dabei viele technische Requests über mehrere Services hinweg. Ohne zusätzliche Kennung sind Logs dann zeitlich vermischt, serviceübergreifend nicht zuordenbar und kaum zu debuggen.

Fragen wie diese werden schwer zu beantworten:

Warum ist diese Anfrage fehlgeschlagen?
Wo ging Zeit verloren?
Welcher Service hat den Fehler ausgelöst?

Die Lösung

Eine Correlation-ID ist eine eindeutige, zufällige ID (z. B. ein UUID), die pro fachlicher Anfrage erzeugt oder übernommen wird und bei jedem weiteren Aufruf mitgeführt wird.

Ihre typischen Eigenschaften sind:

gleich für alle Logs derselben Anfrage
transportiert über HTTP-Header, Message-Header, Context
unabhängig von Sessions, User-IDs oder Datenbank-IDs.

Damit bildet die Correlation-ID die Grundlage für Tracing- und Observability-Lösungen wie OpenTelemetry, Jaeger oder Zipkin. Du begegnest ihr manchmal mit anderem Namen, wie Trace-ID oder Request-ID.

2. Wie hilft uns cls-rtracer dabei?

Nachdem wir wissen, was die Correlation-ID ist und wozu wir sie brauchen, wird schnell klar, warum wir eine Express-Middleware benötigen: Wenn uns keine Correlation-ID geliefert wird, wollen wir an unserem Systemrand – in unserem Fall am HTTP-Endpunkt – eine neue Correlation-ID erzeugen.

Für die Umsetzung verwenden wir das NPM-Paket cls-rtracer. Das Paket stellt uns zwei Funktionalitäten zur Verfügung:

Einer Express-Middleware, die wir mittels Optionen konfigurieren wollen. Dies allein rechtfertigt die Nutzung des NPM-Pakets nicht, da das Selbstbauen geringeren Aufwand erfordern würde.
Das NPM-Paket umfasst zusätzlich die Speicherung und Verwaltung der Correlation-ID im AsyncLocalStorage, sodass wir darauf zum einen jederzeit Zugriff haben und zum anderen jede asynchrone Ausführung eine eigene Correlation-ID erhält. Letzteres ist relevant, weil wir für jeden potenziell gleichzeitig ausgeführten HTTP-Aufruf eine andere Correlation-ID verwenden.

Achtung: Mit dieser Nutzung haben wir einen Performance-Impact, der bei Systemen mit hoher Last besonders relevant ist. Die maximalen Requests pro Sekunde, die unsere Express-Applikation verarbeiten kann, sinken.

Ich bin der festen Überzeugung, dass gerade in solchen Situationen (hohe Last) das eindeutige Tracing anhand einer Correlation-ID unerlässlich ist, um Fehler in den Logs nachzuvollziehen. Denn wenn ein Fehler passiert, dann unter Last, während Hunderte parallele Prozesse Ausgaben in den Logs erzeugen.

Eine Perplexity-Anfrage mit dem nachfolgenden Prompt ergibt die Aussage, dass mit einem Performanceverlust von 5–15 % zu rechnen ist. In Szenarien mit horizontal skalierendem Hosting zu verschmerzen. Falls du selbst recherchieren möchtest, hier ist mein Prompt als Startpunkt.

I use cls-rtracer with AsyncLocalStorage in my Node.js Express application. What is the performance impact for requests per second due to the usage of this?

3. Ergänzung im EnvVarService: Correlation-ID-Header-Namen

Für die Express-Middleware benötigen wir einen Header-Namen, in dem die Correlation-ID übertragen wird. Aus historischen Protokollen wie dem E-Mail-RFC 822 wurde die Praxis übernommen, eigene Header-Namen mit x- zu beginnen. Dies verhindert Namenskollisionen mit standardisierten Headern. Für die Correlation-ID verwende ich stets den Namen x-correlation-id. Entsprechend sieht die Anpassung im EnvVarService aus:

// Change in the zod schema
const schema = z.object({  
  LOG_LEVEL: withDevDefault(z.enum(LogLevels), LogLevels.DEBUG),  
  LOG_FORMAT: withDevDefault(z.enum(LogFormats), LogFormats.PLAIN),  
  LOG_CORRELATION_ID_HEADER: withDevDefault(z.string().min(1), 'x-correlation-id'),  
})

// Update in the return statement for all logging values
return {  
  logLevel: parsed.data.LOG_LEVEL,  
  logFormat: parsed.data.LOG_FORMAT,  
  logCorrelationIdHeader: parsed.data.LOG_CORRELATION_ID_HEADER,  
}

Bitte vergiss nicht, eine passende Aktualisierung für die Tests in setupTestEnvVars.ts vorzunehmen. Genauso in .env.dist und .env.

4. Erstellung einer Express-Middleware

Die Express-Middleware erstellen wir in der Datei /src/services/correlationId/CorrelationIdMiddleware.ts. Wir greifen auf den neuen Wert des EnvVarServices zu und setzen ihn in der Hilfsfunktion ein, die uns cls-rtracer bereitstellt.

import { expressMiddleware } from 'cls-rtracer'  
import { v4 as uuidv4 } from 'uuid'  
import type { Router } from 'express'  
import EnvVarService from '@/services/EnvVarService'  

export default function CorrelationIdMiddleware (app: Router) {  
  const middleware = expressMiddleware({  
    // Respect request header flag (default: false).  
    // If set to true, the middleware/plugin will always use a value from
    // the specified header (if the value is present).
    useHeader: true,  
    // Add request id to response header (default: false).  
    // If set to true, the middleware/plugin will add the request id to the specified
    // header. Use the headerName option to specify the header name.
    echoHeader: true,  
    // Request/response header name, case-insensitive (default: 'X-Request-Id'). 
    // Used if useHeader/echoHeader is set to true.
    headerName: EnvVarService.logging.logCorrelationIdHeader,  
    // A custom function to generate your request IDs (default: UUID v1).  
    requestIdFactory: uuidv4,  
  })  
  app.use(middleware)  
}

5. Einbindung in unsere Express-Applikation

Als letzter Schritt bleibt die Einbindung in die Express-Applikation. Den Aufruf habe ich analog zur Einbindung der dynamisch generierten TSOA-Routen definiert.

const app = express()
CorrelationIdMiddleware(app)
RegisterRoutes(app)
// other app configuration

Im Rahmen eines Tests können wir die Umsetzung prüfen:

it('should validate correlation-id is present in response headers', async () => {  
  // act  
  const {headers} = await agent.get('/entities')  

  // assert  
  expect(headers['x-correlation-id']).toBeDefined()  
})

Fazit

Mit diesem Schritt haben wir einen wesentlichen Baustein für professionelles Logging geschaffen. Jedoch hilft uns die bisherige Arbeit nur so weit, dass die Correlation-ID pro HTTP-Aufruf existiert. Sie findet sich noch nicht in den Logs und müsste von uns mühsam in jedes Log-Statement eingebunden werden. Das ist kein akzeptabler Ansatz. Deshalb werden wir im nächsten Artikel sicherstellen, dass unser LogService diese Arbeit erledigt: Jedes Log-Statement wird automatisch um die Property ergänzt.