Node.js und Logging – Teil 8: Jede Log-Ausgaben mit Correlation-ID

Unser großes Ziel heute ist einfach und ein Game-Changer: Jedes Log-Statement wird automatisch um die Ausgabe der Correlation-ID ergänzt. Bei meinen ersten Versuchen habe ich die Correlation-ID vom Controller in meine Applikation übertragen. Das hieß, jeder Aufruf hatte stets als ersten Parameter die Correlation-ID.

Dies reduzierte nicht nur die Lesbarkeit. Wann immer ich in den Untiefen meiner Applikation eine Log-Ausgabe hinzufügen wollte, musste ich viele Refaktorierungen vornehmen. Schlimmer noch: Da ich die Correlation-ID nicht ins Log geschrieben habe (z. B. schlichtweg, weil ich vergessen habe, dies zu tun), habe ich beim Debuggen das passende Log nicht gefunden. Die daraus resultierenden Fehlannahmen bei meiner Fehleranalyse haben mich stundenlange Irrwege beschreiten lassen. Das alles soll dir erspart bleiben.

Für das neue Feature liegen folgende Schritte vor uns:

1. Hilfsfunktion zum Auslesen der aktuellen Correlation-ID
2. EnvVarService mit Fallback Correlation-ID
3. Einbindung in den LogService

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

1. Hilfsfunktion zum Auslesen der aktuellen Correlation-ID

Das NPM-Paket cls-rtracer bietet die Funktion id, um die Correlation-ID aus dem AsyncLocalStorage zu extrahieren. Die Signatur liefert unknown | undefined. Das ist für unsere Zwecke suboptimal, weswegen wir in unserer eigenen Hilfsfunktion den Typ auf string | null reduzieren.

Ich nutze hier bewusst nicht den Fallbackwert, den wir gleich im EnvVarService definieren. Das erlaubt mir, in der aufrufenden Funktion zu entscheiden, ob und wie ich mit einer fehlenden Correlation-ID umgehen möchte.

import { id as getCorrelationId } from 'cls-rtracer'  

export default (): string | null => {  
  const correlationId = getCorrelationId()  

  if (!correlationId) {  
    return null  
  }  

  if (typeof correlationId !== 'string') {  
    return null  
  }  

  return correlationId  
}

2. EnvVarService mit Fallback Correlation-ID

Einige unserer Logs haben keine Correlation-ID. Dazu gehören z.B. die Log-Ausgaben beim Applikationsstart und -ende. Damit die Log-Ausgaben grundsätzlich gleich aussehen, nutze ich bei der Ausgabe einer fehlenden Correlation-ID einen Fallback. Damit die je nach Bedarf konfiguriert werden kann, bietet sich der EnvVarService an:

// 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'),
  LOG_CORRELATION_ID_FALLBACK: withDevDefault(z.string().min(1), 'xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx'),  
})

// 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,
  logCorrelationIdFallback: parsed.data.LOG_CORRELATION_ID_FALLBACK,
}

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

3. Einbindung in den LogService

Für unseren LogService greifen wir abermals auf die Winston-Format-Wrapper zurück. Dabei ergänzen wir das Info-Objekt um die Correlation-ID. Sollte diese nicht gesetzt sein, nutzen wir den Fallback aus dem EnvVarService:

// To add correlation ID to each log entry  
const addCorrelationId = winston.format((info) => {  
  info.correlationId = getCorrelationId() || EnvVarService.logging.logCorrelationIdFallback  
  return info  
})

Damit die Correlation-ID in den Logs erscheint, müssen wir für das Plain-Format die Ausgabe anpassen. Ich empfehle die Ausgabe direkt am Anfang zusätzlich zur Zeit, jedoch vor dem LogLevel. Somit ergibt sich eine harmonische leserliche Ausgabe.

const logFormat = winston.format.printf((info) => {  
  let output = `[${info.timestamp} - ${info.correlationId}] ${info.level} ${info.message}`

Fazit

Mit diesen kleinen Anpassungen haben wir unser Logging auf ein monumentales Level gehoben. Hier ein Auszug eines HTTP-Aufrufs mit den Logs, um es zu veranschaulichen:

[2026-01-09T15:19:48.862Z - xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx] debug Server is started {
  "port": 4000,
  "nodeEnv": "development"
}
[2026-01-09T15:19:50.781Z - 62870b63-50ae-4416-8025-79e7faec31ec] info Getting user token
[2026-01-09T15:19:50.782Z - 62870b63-50ae-4416-8025-79e7faec31ec] debug Token sign options: {
  "issuer": "demo-company",
  "subject": "user-uuid",
  "audience": "https://demo-company.de",
  "expiresIn": 86400,
  "algorithm": "RS256"
}

Statt lange zu feiern, nehmen wir uns weitere Verfeinerungen vor. Morgen geht es mit dem Performance-Logging weiter. Wir schreiben eine Express-Middleware, die bei jedem Aufruf die Dauer ins Log schreibt – natürlich mit der Correlation-ID.