Node.js und Logging – Teil 9: Performance-Logging der Http-Requests

Ein wichtiger Aspekt des Loggings ist der Einblick in die Performance der Applikation. Für unsere Http-Endpunkte wollen wir genau diesen Aspekt aufgreifen: Jeder Http-Request soll zum Schluss ein Log schreiben, in dem deutlich wird, welcher Endpunkt aufgerufen wurde und wie lange die Bearbeitung gedauert hat.

Durch dieses Feature erhalten wir keine Statistiken und Auswertungen. Dafür nutzen wir in Produktivumgebungen andere Tools wie Prometheus, Loki und Grafana. Bei diesem Ansatz geht es darum, während der lokalen Entwicklung sowie in einer Testumgebung in den Logs Anhaltspunkte zu finden.

Eine meiner Angewohnheiten ist, während der Entwicklung die Logs zu lesen. Die Logs sollten sich wie eine Art Geschichte lesen, die beschreibt, was im Code vorgefallen ist. Das aufmerksame Lesen hat mich schon oft Ungereimtheiten finden lassen, die sich als Bauchgefühl äußerten: "Da stimmt doch was nicht." Dem Gefühl kann ich durch gezielte Tests nachgehen.

Wieder zurück zu unserem Ziel für heute. Um das zu erreichen, liegen folgende Schritte vor uns:

1. Entwicklung der Express-Middleware
2. Einbindung in die Applikation

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

1. Entwicklung der Express-Middleware

Bei der Entwicklung machen wir uns die Funktion des NPM-Pakets Morgan zunutze. Wir können Morgan aufrufen und eine Middleware zurückbekommen. Beim Aufruf definieren wir einige relevante Parameter, die sich als sinnvoll erwiesen haben:

• skipLog ermöglicht es uns, anhand des Requests ein Prädikat zu formulieren, das angibt, ob wir an der Performanceausgabe interessiert sind. Dabei schließen wir einige Fälle aus. Die Details findest du im Code-Snippet.
• immediate ermöglicht es uns, das Log am Anfang des Requests zu verfassen. Sollte unsere Applikation unvermittelt abstürzen, wäre der Eintrag im Log zu finden. In diesem Moment haben wir nur ein reduziertes Set an Informationen, wissen jedoch aus diesem Request, was in kritischen Fällen wertvoll ist. → Deswegen nutzen wir zwei Express-Middleware-Logs. Die Details siehst du im Code-Snippet.

Das Skip-Prädikat

Die Prüfung des Request-Objekts ist umfangreich, daher lagern wir sie in eine eigene Funktion aus. Ziel ist, die Performance-Log-Ausgabe auf die Http-Endpunkte zu beschränken.

/**  
 * Determine if the request should skip logging. This applies to static resources and health checks.
 * Additionally, OPTIONS requests are skipped because with CORS preflight requests, they would flood the logs. 
*/
const skipLog = (req: Request) => {  
  let url = req.url  

  // Skip OPTIONS requests to reduce log noise from CORS preflight requests  
  if (req.method === 'OPTIONS') {  
    return true  
  }  

  // Skip static resource requests  
  if (url.match(/(js|jpg|png|ico|css|woff|woff2|eot)$/gi)) {  
    return true  
  }  

  // Skip our health check endpoint (commonly used in cluster hosting with Kubernetes)  
  if (url.includes('health')) {  
    return true  
  }  

  // Skip metrics endpoint to reduce log noise from monitoring systems  
  if (url.includes('metrics')) {  
    return true  
  }  

  return false  
}

Die zwei Morgan-Middleware-Definitionen

Dank Morgans Flexibilität ist es sinnvoll, zwei Middleware-Definitionen vorzubereiten:

• Eine schlanke Ausgabe über den Eingang eines Requests, bestehend aus dem Http-Verb und dem Endpunkt.
• Eine vollständige Ausgabe mit allen Details, die uns interessieren: Dauer in Millisekunden, Response-Größe und Performance. Hierbei unterscheiden wir zwei Ausgaben
  • response-time
    • Misst die Zeit vom Erreichen des Requests bei Morgan bis zum Schreiben der Response-Header.​
    • Nützlich, um die Dauer der App-Logik (Routing, DB-Abfragen etc.) zu sehen, unabhängig vom Versenden des Bodys.
  • total-time
    • Misst die Zeit vom Erreichen des Requests bei Morgan bis zum vollständigen Abschluss des Response-Versands.​
    • Beinhaltet die Streaming-Zeit des Response-Bodys (z. B. bei großen Downloads), daher immer größer oder gleich response-time.

const immediateRequestLogMiddleware = morgan(`:method :url`, {  
  stream: {write: (text: string) => LogService.debug(text.trim())},  
  immediate: true, // Log at the beginning of the request  
  skip: skipLog, // Skip logging for certain requests  
})  

const responsePerformanceLogMiddleware = morgan(  
  `:method :status :url (:res[content-length] bytes) Response-time :response-time ms Total-time :total-time ms`,  
  {  
    stream: {write: (text: string) => LogService.verbose(text.trim())},  
    immediate: false, // Log after response is sent  
    skip: skipLog, // Skip logging for certain requests  
  },  
)

2. Einbindung in die Applikation

Für die Einbindung bleiben wir unserer Syntax treu, wie wir sie für die Correlation-ID-Middleware verwendet haben. Die Einbindung erfolgt wie folgt:

import PerformanceLogMiddleware from '@/services/PerformanceLogMiddleware'

const app = express()  
CorrelationIdMiddleware(app)
PerformanceLogMiddleware(app) // <- our new middleware
RegisterRoutes(app)

Damit der Aufruf so klappt, definieren wir die Middleware:

export default function PerformanceLogMiddleware (app: Router) {  
  app.use(immediateRequestLogMiddleware)  
  app.use(responsePerformanceLogMiddleware)  
}

Fazit

Mit der heutigen Ergänzung sehen wir in den Logs wichtige Performance-Details. Ein Aufruf des Http-Endpunkts sieht jetzt wie folgt aus:

[2026-01-10T07:43:51.025Z - 67b5824a-5689-4349-92e5-003243bd24c8] debug GET /users/jwt
[2026-01-10T07:43:51.027Z - 67b5824a-5689-4349-92e5-003243bd24c8] info Getting user token
[2026-01-10T07:43:51.028Z - 67b5824a-5689-4349-92e5-003243bd24c8] debug Token sign options: {
  "issuer": "demo-company",
  "subject": "user-uuid",
  "audience": "https://demo-company.de",
  "expiresIn": 86400,
  "algorithm": "RS256"
}
[2026-01-10T07:43:51.065Z - 67b5824a-5689-4349-92e5-003243bd24c8] verbose GET 200 /users/jwt (984 bytes) Response-time 37.273 ms Total-time 39.520 ms

Damit sind wir auch am Ende der Artikelserie angekommen. Ich plane, bald weitere Artikel zum Thema Node.js zu veröffentlichen. Dabei werde ich die Schwerpunkte Applikationsstart und -ende betrachten und meine Erfahrungen hinsichtlich der NPM-Pakete teilen, die bei einem produktiven Einsatz zwingend erforderlich sind (CORS, Rate-Limiting, Parameter Pollution Protection usw.). Zusätzlich gibt es einige Tipps, die ich dir zur Einbindung von Prisma als ORM mitgeben möchte.

Danke fürs Lesen. Bis zur nächsten Artikelserie.