Blog

Kontextbezogene Protokollierung in NodeJS

Sander Koenders

Aktualisiert Oktober 16, 2025

10 Minuten

Einführung

Heutzutage bewegen wir uns weg von Hosting-Umgebungen, für die wir zuständig sind, und hin zu serverlosen Alternativen. Diese serverlosen Alternativen gehen oft Hand in Hand mit NodeJS. Bei der Entwicklung einer großen Anwendung für eine große Gruppe von Benutzern sind wir sicher alle schon einmal auf das Problem gestoßen, dass die Protokollierungsmeldungen überall verstreut sind. Sowohl in Bezug auf das Lesen als auch auf das Schreiben der eigentlichen Protokollierungsimplementierung in Ihrer Anwendung. Geben Sie alle relevanten Informationen für eine Protokollzeile über Ihren gesamten Call-Stack weiter oder gibt es eine bessere Lösung? In diesem Blogbeitrag werden wir darüber sprechen, wie wir versuchen, die Logging-Logik aus unserer Geschäftslogik herauszuhalten und die Logging-Meldungen besser lesbar zu machen!

Das Problem

NodeJS ist eine single threaded Laufzeitumgebung für JavaScript. Das bedeutet, dass NodeJS nicht die Vorteile von Threads nutzen kann, um zu bestimmen, welcher Kontext zu einer bestimmten Anfrage gehört. Ein anfragespezifischer Kontext kann für die Protokollierung sehr nützlich sein, denn er ermöglicht es uns, einer Anfrage eine eindeutige ID zuzuweisen. Damit ist es möglich, alle Protokollierungsmeldungen, die sich auf eine bestimmte Anfrage beziehen, synchron zu betrachten, was die Fehlersuche erheblich erleichtert. Wie also lösen wir dieses Problem in NodeJS? Mit Async Hooks!

Was sind Async-Hooks?

NodeJS ist eine Laufzeitumgebung, die sich stark auf asynchrone Aufrufe stützt. Fast alles in NodeJS ist asynchron. Die Verwendung von Promises und Timeouts zum Beispiel. Der Eventloop ist für die Handhabung dieser asynchronen Ressourcen zuständig. Das Modul async hooks bietet eine API zur Verfolgung dieser asynchronen Ressourcen. Mit dieser API können wir verfolgen, welche asynchrone Ressource mit einer Anfrage verbunden ist.

Wie man es benutzt

In diesem Beispiel werden wir AsyncLocalStorage verwenden (eine kleine Abstraktion über async_hooks). AsyncLocalStorage ermöglicht es uns, mit wenig bis gar keinem Aufwand einen Speicher für jede Anfrage zu erstellen. Das in der NodeJS-Dokumentation verwendete Beispiel erklärt dies recht gut.

import http from 'node:http';
import { AsyncLocalStorage } from 'node:async_hooks';
const asyncLocalStorage = new AsyncLocalStorage();
function logWithId(msg) {
  const id = asyncLocalStorage.getStore();
  console.log(${id !== undefined ? id : '-'}:, msg);
}
let idSeq = 0;
http
  .createServer((req, res) => {
    asyncLocalStorage.run(idSeq++, () => {
      logWithId('start');
      // Imagine any chain of async operations here
      setImmediate(() => {
        logWithId('finish');
        res.end();
      });
    });
  })
  .listen(8080);
http.get('http://localhost:8080');
http.get('http://localhost:8080');
// Prints:
//   0: start
//   1: start
//   0: finish
//   1: finish

Das obige Beispiel erklärt, wie sich zwei Clients mit demselben Node HTTP-Server verbinden. Jede Anfrage wird innerhalb eines asyncLocalStorage.run(...) ausgeführt. Der Kontext wird mit einer id initialisiert (die mit idSeq generiert wird) und diese id wird dann in jedem logWithId-Aufruf ("start" und "finish") verwendet. Wenn Sie sich das Ergebnis ansehen, sehen Sie, dass jede Anfrage "start" und "finish" mit ihrer eigenen zugewiesenen Anfrage-ID ausgibt. Dies zeigt, wie Sie jede Anfrage innerhalb einer Anwendung, die von mehreren Clients gleichzeitig besucht wird, verfolgen können.

Wie können wir dies also in unsere eigene Anwendung einbauen und auf die nächste Stufe bringen? Lassen Sie uns eine kleine, in TypeScript geschriebene ExpressJS-Anwendung erstellen, um zu demonstrieren, wie wir dies in der realen Welt nutzen können. Als erstes müssen wir einen LoggingContext erstellen.

export interface IContext {
  requestId: string;
  traceId: string;
  ipAddress: string;
}
const LoggingContext = () => {
  const asyncLocalStorage = new AsyncLocalStorage<IContext>();
  return {
    init: (context: IContext, callback: () => void) => {
      asyncLocalStorage.run(context, () => {
        callback();
      });
    }
  };
};
export loggingContext = LoggingContext();

Wir erstellen eine Methode namens LoggingContext. Dies ist im Wesentlichen ein Wrapper für die Erstellung unseres AsyncLocalStorage und gibt ein Objekt mit Methoden zurück, die wir dem Client-Code zur Verfügung stellen möchten. Die Methode init initialisiert den Kontext für jede Anfrage und ruft eine Funktion callback auf, wenn die Initialisierung abgeschlossen ist. Der Kontext wird mit einem Objekt initialisiert, das mit IContext konform ist und eine requestId, traceId und die ipAddress enthält, von der aus die Anfrage gesendet wurde. Wir können nun eine einfache Express-Anwendung erstellen, die diesen LoggingContext verwendet

const app = express();
app.use((req, res, next) => {
  const requestId = uuidv4();
  const traceId = (req.headers['x-trace-id'] ?? requestId) as string;
  const ipAddress = (req.headers['x-forwarded-for'] ?? req.socket.remoteAddress ?? '') as string;
  const context = {
    requestId,
    traceId,
    ipAddress,
  };
  loggingContext.init(context, next);
});
app.get('/', (req, res) => {
  res.send('ok');
});

Ich musste die Anweisung typescript as verwenden, um den Compiler anzuweisen, dass traceId und ipAddress vom Typ string sind. In einer produktiven Anwendung würden Sie eine robustere Prüfung dieser Variablen durchführen, aber um dieses Beispiel einfach zu halten, habe ich mich dafür entschieden, es so zu machen. In dem obigen Beispiel sehen wir die Erstellung einer Express-Anwendung. Diese Anwendung verwendet app.use(...), um eine Middleware zu definieren, die bei jeder Anfrage ausgeführt wird. Die nächste Anweisung ermöglicht es uns, mit der nächsten Middleware oder dem nächsten Request Handler fortzufahren. Wir konstruieren einen Kontext mit requestId, traceId und ipAddress, den wir dann zum Aufruf von loggingContext.init verwenden. Die Funktion next wird ebenfalls an loggingContext.init übergeben und wird ausgeführt, wenn der Kontext initialisiert ist. Wenn eine Anfrage an den / Endpunkt gestellt wird, wird ok zurückgegeben. Als nächstes erstellen wir eine log Methode innerhalb unseres loggingContext, um Nachrichten auf der Konsole zu protokollieren.

export interface IContext {
  requestId: string;
  traceId: string;
  ipAddress: string;
}
export interface ILogObj {
  operation: string;
  data: Record<string, any>;
}
const LoggingContext = (transport: Pick<Console, 'log'>) => {
  const asyncLocalStorage = new AsyncLocalStorage<IContext>();
  return {
    init: (context: IContext, callback: () => void) => {
      asyncLocalStorage.run(context, () => {
        callback();
      });
    },
    log: (obj: ILogObj) => {
      const timeStamp = new Date().toISOString();
      transport.log({
        timestamp, // Add a timestamp to our log message
        ...asyncLocalStorage.getStore(), // Spread our context with requestId, traceId and ipAddress
        ...logObj // Spread the values of logObj
      })
    }
  };
};
export loggingContext = LoggingContext(console);

Es wurden drei Änderungen am LoggingContext vorgenommen. Die erste Änderung ist die Hinzufügung von ILogObj. Diese Schnittstelle beschreibt das Layout unserer Protokollnachricht. Ich habe mich dafür entschieden, operation hinzuzufügen, um zu beschreiben, welche Aktion ausgeführt wird, und data, um einen Datensatz mit nützlichen Eigenschaften hinzuzufügen, die in der Protokollnachricht enthalten sein sollten. Die zweite Änderung ist die Hinzufügung von transport in der Methode LoggingContext. Dies ist im Wesentlichen der Transport, der für die Protokollnachrichten verwendet wird. In diesem Fall verwende ich console, um die Nachrichten zur Konsole zu transportieren. Die dritte und letzte Änderung ist die Hinzufügung der log-Methode, die es uns ermöglicht, ILogObj mit dem Anfragekontext und dem Zeitstempel auf der Konsole zu protokollieren.

Jetzt müssen wir nur noch die Vorteile der neuen Protokollmethode in der Express-Anwendung nutzen.

const app = express();
app.use((req, res, next) => {
  const requestId = uuidv4();
  const traceId = (req.headers['x-trace-id'] ?? requestId) as string;
  const ipAddress = (req.headers['x-forwarded-for'] ?? req.socket.remoteAddress ?? '') as string;
  const context = {
    requestId,
    traceId,
    ipAddress,
  };
  loggingContext.init(context, next);
});
app.get('/', (req, res) => {
  loggingContext.log({
    operation: 'Received request on endpoint',
    data: {
      endpoint: '/',
    },
  });
  const responseMsg = 'ok';
  loggingContext.log(JSON.stringify({
    operation: 'About to send response',
    data: {
      responseMsg,
    }, null, 1),
  });
  res.send(responseMsg);
});
app.listen(port);
http.get('http://localhost:3000');
http.get('http://localhost:3000');
// Output:
// {
//   "timeStamp": "2022-10-10T15:30:47.887Z",
//   "level": "LOG",
//   "requestId": "3ce652e0-b771-43fd-9eda-2ed0f581ba46",
//   "traceId": "3ce652e0-b771-43fd-9eda-2ed0f581ba46",
//   "ipAddress": "127.0.0.1",
//   "operation": "Received request on endpoint",
//   "data": {
//     "endpoint": "/"
//   }
// }
// {
//   "timeStamp": "2022-10-10T15:30:47.891Z",
//   "level": "LOG",
//   "requestId": "8ae509ee-e806-4b09-b5c7-ab2c018fc95f",
//   "traceId": "8ae509ee-e806-4b09-b5c7-ab2c018fc95f",
//   "ipAddress": "127.0.0.1",
//   "operation": "Received request on endpoint",
//   "data": {
//     "endpoint": "/"
//   }
// }
// {
//   "timeStamp": "2022-10-10T15:30:47.887Z",
//   "level": "LOG",
//   "requestId": "3ce652e0-b771-43fd-9eda-2ed0f581ba46",
//   "traceId": "3ce652e0-b771-43fd-9eda-2ed0f581ba46",
//   "ipAddress": "127.0.0.1",
//   "operation": "About to send response",
//   "data": {
//     "responseMsg": "ok"
//   }
// }
// {
//   "timeStamp": "2022-10-10T15:30:47.891Z",
//   "level": "LOG",
//   "requestId": "8ae509ee-e806-4b09-b5c7-ab2c018fc95f",
//   "traceId": "8ae509ee-e806-4b09-b5c7-ab2c018fc95f",
//   "ipAddress": "127.0.0.1",
//   "operation": "About to send response",
//   "data": {
//     "responseMsg": "ok"
//   }
// }

Beachten Sie, dass jeder Anfrage eine eigene requestId und traceId zugewiesen wurde, obwohl die Anfragen zur gleichen Zeit bearbeitet wurden. Wir haben nun eine großartige Möglichkeit geschaffen, die Protokollmeldungen zu einer Anfrage zu verfolgen.

Verfolgung von Anfragen über mehrere Dienste hinweg

Nachdem wir nun also eine Möglichkeit geschaffen haben, unsere Anfragen innerhalb unserer Anwendung zu verfolgen, wie gehen wir vor, um unsere Anfragen über mehrere Dienste hinweg zu verfolgen? Erinnern Sie sich an die traceId, die wir zu unserem Kontext hinzugefügt haben? Wir können traceId auch verwenden, um unsere Anfragen über mehrere Dienste hinweg zu verfolgen. Und wie? Indem wir sie einfach mit unseren ausgehenden Anfragen weitergeben! Lassen Sie uns axios verwenden und einen axios Interceptor zu unserer Anwendung hinzufügen.

const port = 3000;
const app = express();
axios.interceptors.request.use((config: AxiosRequestConfig) => {
  config.headers = config.headers ?? {};
  config.headers['x-trace-id'] = loggingContext.getTraceId();
  return config;
});
app.use((req, res, next) => {
  const requestId = uuidv4();
  const traceId = (req.headers['x-trace-id'] ?? requestId) as string;
  const ipAddress = (req.headers['x-forwarded-for'] ?? req.socket.remoteAddress ?? '') as string;
  const context = {
    requestId,
    traceId,
    ipAddress,
  };
  loggingContext.init(context, next);
});
app.get('/', async (req, res) => {
  const config: AxiosRequestConfig = {
    method: 'GET',
    url: http://127.0.0.1:${port}/hello,
  };
  loggingContext.log({
    operation: 'Performing Axios request',
    data: {
      config,
    },
  });
  axios
    .request(config)
    .then((res) => res.data)
    .then(res.send);
});
app.get('/hello', (req, res) => {
  const responseObj = {
    hello: 'World',
  };
  loggingContext.log({
    operation: 'About to send response',
    data: {
      endpoint: '/hello',
      responseObj,
    },
  });
  res.send(responseObj);
});
app.listen(port);
http.get('http://localhost:3000');
http.get('http://localhost:3000');
// Output:
// {
//   "timeStamp": "2022-10-10T16:01:02.843Z",
//   "requestId": "82c12c4c-57b2-413a-a94e-a1be6c1de693",
//   "traceId": "82c12c4c-57b2-413a-a94e-a1be6c1de693",
//   "ipAddress": "127.0.0.1",
//   "operation": "Performing Axios request",
//   "data": {
//     "config": {
//     "method": "GET",
//     "url": "http://127.0.0.1:3000/hello"
//     }
//  }
// }
// {
//   "timeStamp": "2022-10-10T16:01:02.851Z",
//   "requestId": "294d8a9d-02a4-40f8-83dc-89a1769adeeb",
//   "traceId": "294d8a9d-02a4-40f8-83dc-89a1769adeeb",
//   "ipAddress": "127.0.0.1",
//   "operation": "Performing Axios request",
//   "data": {
//     "config": {
//     "method": "GET",
//     "url": "http://127.0.0.1:3000/hello"
//     }
//   }
// }
// {
//   "timeStamp": "2022-10-10T16:01:02.853Z",
//   "requestId": "6a058dc8-fe15-4270-93e8-5f3e0622f3bd",
//   "traceId": "82c12c4c-57b2-413a-a94e-a1be6c1de693",
//   "ipAddress": "127.0.0.1",
//   "operation": "About to send response",
//   "data": {
//     "endpoint": "/hello",
//     "responseObj": {
//     "hello": "World"
//     }
//   }
// }
// {
//   "timeStamp": "2022-10-10T16:01:02.857Z",
//   "requestId": "e59ec69a-c617-4350-85b5-7e8329e7ac0b",
//   "traceId": "294d8a9d-02a4-40f8-83dc-89a1769adeeb",
//   "ipAddress": "127.0.0.1",
//   "operation": "About to send response",
//   "data": {
//     "endpoint": "/hello",
//     "responseObj": {
//     "hello": "World"
//     }
//   }
// }

Im obigen Beispiel haben wir einen Axios-Interceptor hinzugefügt. Dieser Interceptor verwendet die getTraceId-Methode von loggingContext, um die traceId zu erhalten, mit der der Kontext initialisiert wurde. Immer wenn eine Anfrage mit Axios gesendet wird, wird der Interceptor ausgeführt und die x-trace-id zu unserer Anfrage hinzugefügt. Die Middleware, die wir bereits hatten, sorgt dann dafür, dass die x-trace-id im loggingContext verwendet wird. Das obige Beispiel verwendet Axios, um eine Anfrage an /hello zu senden. Im Ergebnis können Sie sehen, dass sich bei jeder Anfrage die requestId ändert, die verschiedenen Clients aber immer noch über traceId verfolgt werden können.

Fazit

Die Einführung des async_hooks-Moduls in NodeJS bietet uns eine großartige Möglichkeit, Aufrufe durch den Callstack in NodeJS zu verfolgen. Dies hilft uns zu erkennen, welche Protokollmeldungen mit welcher Anfrage verbunden sind. Es hilft uns auch, unsere Geschäftslogik von der Protokollierungslogik innerhalb der Anwendung zu trennen. Das bedeutet, dass der Callstack der Anwendung sauberer ist, weil wir keine unnötigen Parameter an Methoden übergeben müssen, wenn sie für die Protokollierung von Nachrichten benötigt werden.

GitHub: Node kontextuelle Protokollierung von Sander Koenders

Tags: