Software Engineering

Node.js und Logging – Teil 1: Der LogService

Mit dem Start dieser Artikelserie richten wir einen LogService ein, in dem wir die Nutzung des Winston-NPM-Pakets kapseln und auf Erweiterungen im Verlauf der Serie vorbereiten. Starten wir die Vorbereitung!

8 Minuten

Vorbereitung

Als Erstes gilt es, die notwendigen NPM-Pakete zu installieren, die wir im Laufe der Artikelserie nutzen:

  • winston als Universal-Logger mit vielen Konfigurationsmöglichkeiten. Die Basis unseres LogServices.
  • cls-rtracer als Request-Tracer, um sämtliche Logs um eine gemeinsame ID zu ergänzen. Diesen werden wir mit Winston verknüpfen, um das volle Potenzial von Correlation-IDs zu entfalten.
  • uuid zur RFC-konformen ID-Erzeugung, die wir als Factory in cls-tracer einbinden, sodass wir kollisionsfreie IDs erhalten, selbst wenn unser System tausende und mehr Anfragen pro Sekunde verarbeitet.
  • morgan als Http-Request-Logger-Middleware für Node.js. Damit erleichtern wir uns im letzten Kapitel die Performanceausgabe pro Request.
  • zod als TypeScript-Schema-Validator, um Input unbekannter Herkunft zu prüfen und anschließend typsicheren Zugriff zu gewährleisten.
  • dotenv um Umgebungsvariablen aus einer Datei in process.env zu laden und in der Node.js-Applikation verfügbar zu machen.

Die Installation der NPM-Pakete

npm i winston cls-rtracer uuid morgan zod dotenv

Die notwendigen Typdefinitionen bei den Paketen, bei denen sie fehlen:

npm i -D @types/morgan @types/uuid

Implementierung des LogServices

Definition der Schnittstelle

Unser LogService umfasst die Funktionalität von Winston unter einer allgemein gültigen Definition. Dabei wollen wir nur einen Teil der Funktionalität offenlegen und den Rest verstecken. Entsprechend formulieren wir die Typen für die Methoden des LogServices sowie deren Signatur.

// Our custom log method type to allow flexible arguments  
type LogMethod = {  
  (message: string, ...meta: unknown[]): void  

  // eslint-disable-next-line @typescript-eslint/no-explicit-any  
  (message: any): void  
}  

// Our LogService interface exposes only the methods we want to allow  
type LogService = {  
  /**  
   * Logs a message with Level 0 - it is a critical issue, which needs immediate attention
   */
  critical: LogMethod  
  /**  
   * Logs a message with Level 1 - it is an error that needs to be addressed, because it might cause malfunctions
   */
  error: LogMethod  
  /**  
   * Logs a message with Level 2 - it is a warning about a potential issue
   */
   warn: LogMethod
  /**  
   * Logs a message with Level 3 - it is general information about application operations
   */
  info: LogMethod  
  /**  
   * Logs a message with Level 4 - it is detailed information useful for debugging, but not needed in normal operations
   */
  verbose: LogMethod  
  /**  
   * Logs a message with Level 5 - it is highly detailed information helpful in diagnosing specific issues
   */  
  debug: LogMethod  
}

Erstellung des Logger als Factory

Wir schreiben eine Methode, die unseren LogService erstellt. Anfangs haben wir noch keine Parameter, anhand deren wir die Erstellung konfigurieren. Wir wissen jedoch, dass später z. B. der LogLevel konfiguriert wird, weshalb wir die Signatur vorbereiten.

Hier ist das Gerüst für die Erstellung des Loggers. Die Formatdefinition erfolgt mit zusätzlicher Erläuterung weiter unten:

type LogServiceArgs = {  
  // We will add arguments later if needed  
}

const ServiceFactory = (_args: LogServiceArgs): LogService => {
  // We define custom levels to have 'critical' as the highest severity  
  // This enables us to set log levels appropriately in different environments  
  const logLevelDefinition = {critical: 0, error: 1, warn: 2, info: 3, verbose: 4, debug: 5}

// To make this definition readable, we move extensive configurations to variables/functions above  
const logger = winston.createLogger({  
  levels: logLevelDefinition,  
  level: 'debug',
  exitOnError: false, // handled exceptions will not cause process.exit  
  transports: [new winston.transports.Console({format: defaultFormat})],  
  format: unhandledFormat, // Format for unhandled exceptions and rejections. Will be used by exceptionHandlers below  
  exceptionHandlers: [new winston.transports.Console()], // Will use the format defined above: unhandledFormat  
  rejectionHandlers: [new winston.transports.Console()], // Will use the format defined above: unhandledFormat  
})  
  // Return only the methods we want to expose and hide the rest of Winston's API  
  // This encapsulation allows us to change the underlying logging library in the future if needed
  return {  
    critical: (...rest) => logger.log('critical', ...rest),  
    error: (...rest) => logger.log('error', ...rest),  
    warn: (...rest) => logger.log('warn', ...rest),  
    info: (...rest) => logger.log('info', ...rest),  
    verbose: (...rest) => logger.log('verbose', ...rest),  
    debug: (...rest) => logger.log('debug', ...rest),  
  }  
}  

const LogService = ServiceFactory({
})  
export default LogService

Formatdefinition der Logausgabe

Im Aufruf von CreateLogger nutzen wir zwei Formatdefinitionen: unhandledFormat und defaultFormat. Deren Verwendung wirkt auf den ersten Blick verkehrt. Deshalb eine Erklärung:

  • Die Definition eines Formats direkt im Transport der beiden Handler wird von Winston ignoriert. Deswegen müssen wir das Format für unbehandelte Exceptions und Promises als Standard festlegen.
  • Für die normalen Logausgaben müssen wir entsprechend diesem Ansatz unser Wunschformat in dessen Transport festlegen.

Hier die beiden Formatdefinitionen:

// Format for unhandled exceptions and rejections  
const unhandledFormat = winston.format.combine(  
  winston.format.timestamp(), // To add timestamp to log entries as ISO string  
  winston.format.errors({stack: false}), // We receive all data by default, no stack trace needed here  
  winston.format.prettyPrint({colorize: true}), // To make unhandled Error output readable in console with indention  
)  

// Default format for regular log entries  
const defaultFormat = winston.format.combine(  
  winston.format.colorize({all: true}), // To colorize the output based on log level  
  winston.format.timestamp(), // To add timestamp to log entries as ISO string  
  winston.format.errors({stack: true}), // To log JavaScript Error with stack trace  
  attachMetadata(), // To attach metadata from splat to the message  
  logFormat, // Our custom log format defined above as [timestamp] level message  
)

Beim unhandledFormat-Format nutzen wir PrettyPrint, um Zeilenumbrüche und Einrückungen zu erhalten, sodass die Ausgabe leserlich bleibt. Für das defaultFormat-Format stellen wir sicher, dass potenzielle Metadaten – selbst bei fehlerhafter Nutzung des LogServices – ausgegeben werden.

Warum fragst du dich? Ich habe häufig in meinem Code Zeilen wie die folgende:

const foo = 'bar'  
LogService.info('Show variable', foo)

Ohne den Workaround würde der Wert von foo nicht ausgegeben werden. Winston unterstützt nur Objekte als zusätzlichen Parameter. Entsprechend habe ich mir den Helfer attachMetadata geschrieben.

// Winston expects metadata to be objects, so a list of values instead of a single object will be lost.  
// So, we attach metadata from splat. We can do sth. like this without harm:  
// LogService.warn('Some text', 'string', {foo: 'bar'}, 4000)  
const attachMetadata = winston.format((info) => {  
  const splat = info[Symbol.for('splat')]  
  const additionalMetadata: string[] = []  

  // We check all splat entries, so misused logging calls are handled as well.  
  // For each entry in splat:
  //  - if it is a single primitive value, append it to the message
  //  - if it is anything else but an error, stringify it and append to the message
  // -> Errors are attached in logFormat above with stack trace
  if (splat && Array.isArray(splat) && splat.length >= 1) {  
    splat.forEach((entry) => {  
      if (typeof entry === 'string' || typeof entry === 'number' || typeof entry === 'boolean' || typeof entry === 'bigint') {  
        additionalMetadata.push(String(entry))  
      } else if (!(entry instanceof Error)) {  
        additionalMetadata.push(JSON.stringify(entry, null, 2))  
      }  
    })  
  }  

  // If we have additional metadata, append it to the message  
  if (additionalMetadata.length > 0) {  
    info.message = `${info.message} ${additionalMetadata.join(', ')}`  
  }  

  return info  
})

Im defaultFormat steckt ein kleines Gimmick, um auf einen Sonderfall vorbereitet zu sein. Wenn ein Fehler geloggt werden soll, möchte ich eine leserlich formatierte Ausgabe inklusive des StackTraces. Dieser wird im attachMetadata bewusst nicht behandelt, sondern erst im Helfer logFormat eingebunden, damit Zeilenumbrüche und Einrückungen erhalten bleiben. Ein enormer Vorteil beim Lesen der Ausgaben.

// Custom log format to include timestamp, level and message  
// If there is any error to be logged in Splat, include its message and stack trace as well  
// All additional metadata will be handled in the attachMetadata helper below  
const logFormat = winston.format.printf((info) => {  
  let output = `[${info.timestamp}] ${info.level} ${info.message}`  

  // In case there are several items in splat and one is an error, it would be swallowed.  
  //We iterate over them and append their stringified versions to the output.  const splat = info[Symbol.for('splat')]  
  if (splat && Array.isArray(splat) && splat.length > 0) {  
    splat.forEach((item) => {  
      if (item instanceof Error && (item.stack || item.message)) {  
        const {stack, ...rest} = item  
        output += `\nError details: ${toString(rest)}${stack ? `\nStack trace: ${stack}` : ''}`  
      }  
    });  
  }  

  return output  
})

Fazit

Mit der neuen Erweiterung können wir in der index.ts den Code umschreiben und statt console.log() eine Debug-Ausgabe nutzen: 

app.listen(PORT, () => {  
  LogService.debug(`Server is listening on port`, PORT)  
})

Womit die Ausgabe beim Start der Applikation wie folgt ausgegeben wird (bei dir im Terminal wird die Ausgabe mit Farbe erfolgen):

[2026-01-02T12:39:12.919Z] debug Server is listening on port 4000

Damit ist die Grundlage des LogServices geschaffen. Als Nächstes kümmern wir uns um den Service für Umgebungsvariablen, damit wir den LogService je Umgebung individuell konfigurieren können.

call to action background image

Abonniere meinen Newsletter

Erhalte einmal im Monat Nachrichten aus den Bereichen Softwareentwicklung und Kommunikation gespikt mit Buch- und Linkempfehlungen.