Verknüpfung von Protokollen bei asynchronen Aufrufen mithilfe von AsyncLocalStorage

Jeder Backend-Entwickler stößt irgendwann auf genau dieses Szenario: Ein requestId wird erstellt, wenn eine Anfrage eintrifft, und irgendwo sechs Ebenen tief, innerhalb eines Datenbank-Helpers oder einer gemeinsamen Protokollierungsfunktion, benötigt man genau diesen Identifikator, um einen Protokolleintrag mit der auslösenden Anfrage in Verbindung bringen zu können. Die offensichtliche Lösung besteht darin, die ID als Argument durch jede Funktion in der Kette weiterzugeben. Das funktioniert zwar, ist aber schwer zu warten, denn nun trägt jede Zwischenfunktion einen Parameter mit sich, den sie außer zur Weitergabe an die nächste Aufrufstufe nicht benötigt.

Die naiven Lösungen – und warum sie beide versagen

Es ist verlockend, auf eine einfache Variable auf Modulebene zurückzugreifen, doch dieser Instinkt ist in einer Weise falsch, die erst im Produktivbetrieb offensichtlich wird:

let currentRequestId = null;

app.use((req, res, next) => {
  currentRequestId = req.headers["x-request-id"];
  next();
});

function logSomething(message) {
  console.log(`[${currentRequestId}] ${message}`); // works... until it doesn't
}

Der Ansatz erscheint vernünftig, wenn man sich vorstellt, dass nur eine Anfrage zurzeit verarbeitet wird, bricht er jedoch zusammen, sobald man berücksichtigt, wie Node tatsächlich Konkurrenzverarbeitung handhabt. Node bedient viele Anfragen „gleichzeitig“, indem es deren Ausführung an Stellen mit await abwechselt, anstatt sie strikt nacheinander auszuführen. Anfrage A schreibt in currentRequestId, stößt dann auf ein await und gibt die Kontrolle an den Event-Loop zurück, der sofort mit der Verarbeitung von Anfrage B beginnen und diese gleiche Variable mit B’s ID überschreiben kann. Wenn der Code von Anfrage A wieder fortgesetzt wird, zeigt currentRequestId bereits auf B, und ab diesem Moment weist jede Log-Aussage in Anfrage A stillschweigend, aber zuverlässig die falsche ID aus.

AsyncLocalStorage: Der Kontext folgt der Ausführung, nicht dem Aufrufstapel

AsyncLocalStorage, das als Teil des eingebauten async_hooks-Moduls von Node mitgeliefert wird, ist speziell dafür konzipiert, genau dieses Problem zu lösen. Es speichert einen eigenen Wert für jede logische Kette der asynchronen Ausführung und tut dies auch dann korrekt, wenn Anfragen sich über await-Aufrufe, Promise-Ketten und Callbacks mischen.

const { AsyncLocalStorage } = require("async_hooks");
const requestContext = new AsyncLocalStorage();

app.use((req, res, next) => {
  const store = { requestId: req.headers["x-request-id"] || crypto.randomUUID() };
  requestContext.run(store, next); // everything inside next() runs "inside" this context
});

function logSomething(message) {
  const store = requestContext.getStore();
  console.log(`[${store?.requestId}] ${message}`); // correct, regardless of interleaving
}

Die Aufrufung von requestContext.run(store, next) bewirkt mehr als nur die Zuweisung eines Wertes – sie eröffnet einen Kontext, der automatisch alle innerhalb dieses Aufrufs aufgerufenen Operationen durchläuft, unabhängig davon, ob die Ausführung synchron oder asynchron ist. Dazu gehören auch Codeabschnitte, die nach einem await weiterlaufen, innerhalb eines .then()-Handlers ausgeführt werden oder später als Callback aus einer I/O-Operation abgerufen werden. Selbst tief im Inneren eines in einer völlig separaten Datei definierten Hilfsprogramms für Datenbankabfragen gibt requestContext.getStore() stets den Kontext zurück, der zur jeweiligen Anfrage gehört – niemals einen Kontext, der von einer zuvor ausgeführten Anfrage entlehnt wurde. Der Grund dafür ist, dass der Kontext an die spezifische asynchrone Ausführungskette gebunden ist, die den Aufruf auslöst, und nicht an eine gemeinsam genutzte Variable, in die jede Anfrage schreibt.

Warum das tatsächlich über await-Grenzen hinweg funktioniert

Dies ist die Eigenschaft, die AsyncLocalStorage von einer gewöhnlichen Variablen unterscheidet, und sie hängt direkt damit zusammen, wie async/await im Hintergrund funktioniert. Jedes Mal, wenn eine async-Funktion an einem await pausiert und später wieder fortgesetzt wird, behält Node fest, mit welchem asynchronen Kontext diese Wiederaufnahme verbunden ist, und stellt ihn automatisch vor dem Ausführen der Fortsetzung wieder her:

app.get("/orders/:id", async (req, res) => {
  requestContext.run({ requestId: req.headers["x-request-id"] }, async () => {
    logSomething("fetching order"); // context is present
    const order = await db.getOrder(req.params.id); // pauses, other requests may run here
    logSomething("order fetched"); // context is STILL correctly present after resuming
    res.json(order);
  });
});

Zwischen den beiden Aufrufen von logSomething hatte der Event-Loop völlig freie Bahn, den Code anderer Anfragen auszuführen, doch diese Interferenzen beeinträchtigten nicht den Kontext, den die jeweilige Fortsetzung nach der Wiederaufnahme wahrnimmt. Genau das ist die Garantie, die eine naive gemeinsame Variable nicht bieten konnte: Eine Korrektheit, die auch bei genau dieser Art von verschachteltem Ausführungsablauf Bestand hat, den Modell für Konkurrenz in Node aktiv fördert.

Der eigentliche Vorteil: Strukturiertes Logging ohne überall vorhandene Thread-Parameter

Genau hier zeigt sich der Nutzen der zusätzlichen Komplexität von AsyncLocalStorage in einer echten Anwendung: Man kann einen Logger erstellen, der den Kontext der Anfrage automatisch jeder Aufrufung hinzufügt, ohne dass im aufrufenden Code irgendwo ein Parameter übergeben werden muss:

function createLogger() {
  return {
    info(message, extra = {}) {
      const store = requestContext.getStore();
      logger.info({ requestId: store?.requestId, ...extra }, message);
    },
  };
}

// deep inside some completely unrelated file, five layers into the call stack
const log = createLogger();
log.info("Payment processed", { amount: 4999 }); // requestId is present, automatically

In der Funktionssignatur von processPayment musste sich nichts ändern, damit das funktioniert. Sie nimmt niemals ein requestId-Argument entgegen und gibt es auch nicht an andere Funktionen weiter, dennoch ist jede von ihr ausgegebene Logzeile korrekt mit der dafür verantwortlichen Anfrage versehen. Das ist der eigentliche Vorteil: Daten im Kontext einer Anfrage sind überall in der Aufrufkette verfügbar, ohne dass jede Funktionssignatur zwischen Beginn der Anfrage und dem Ort ihrer tatsächlichen Verwendung überladen wird.

Die Grenze, die Menschen in Verwirrung bringt

Der Kontext, den Sie innerhalb von .run() einrichten, erstreckt sich nur auf Code, der tatsächlich Teil derselben Ausführungskette ist: Alles, was von innerhalb des Callbacks aufgerufen wird – sei es direkt oder indirekt, einschließlich über Ketten von wartenden Promises. Er erstreckt sich nicht rückwärts auf Code, der vor dem Aufruf von .run() ausgeführt wurde, und er erstreckt sich auch nicht nach vorne auf Aufgaben, die sich wirklich von dieser Kette lösen:

app.use((req, res, next) => {
  requestContext.run({ requestId: req.headers["x-request-id"] }, () => {
    setTimeout(() => {
      logSomething("delayed log"); // still correct — setTimeout inside the context stays tracked
    }, 1000);
    next();
  });
});

Der Aufruf von setTimeout innerhalb des Kontexts funktioniert weiterhin wie erwartet, da Node’s async_hooks-Mechanismus Timern, Promises sowie nahezu alle gängigen asynchronen Primitiven abdeckt. Probleme treten erst bei Aufgaben auf, die absichtlich so gestaltet sind, länger zu existieren als der Anfrage, die sie ausgelöst hat. Eine Aufgabe, die in einen separaten, unabhängigen Worker-Prozess geschoben wird, ist ein gutes Beispiel: Es gibt keine Ausführungskette, die sie mit dem ursprünglichen Kontext verbindet, da es sich überhaupt nicht um eine Fortsetzung derselben asynchronen Aufrufsequenz handelt – es handelt sich dabei um eine eigenständige, unverwandte Sequenz.

Ehrliche Hinweise zur Leistung

AsyncLocalStorage ist nicht kostenlos. Der Erhalt und die Wiederherstellung des Kontexts bei jeder asynchronen Übertragung erfordert erhebliche Aufwand, und ältere Versionen von Node hanterten dies deutlich weniger effizient als die heutige Laufzeitumgebung. In aktuellen Node-Versionen ist der Aufwand für eine typische Webanwendungsarbeitlast so gering, dass er für die überwiegende Mehrheit der Projekte keine Rolle spielt, und die Vorteile in Bezug auf Korrektheit sowie saubereren Code sind fast immer diesen geringen Aufwand wert. Wenn Sie in einem extremen Umfeld arbeiten, bei dem jede Mikrosekunde pro Anfrage zählt, lohnt es sich, Ihren konkreten Fall zu benchmarken. Für nahezu jeden Backend-Service ist es jedoch sinnvoll, dies als sicheren Standard zu betrachten. Es handelt sich dabei nicht um irgendeinen spezialisierten Optimierungstrick, den man gelegentlich anwendet; es ist ein Werkzeug mit einem kleinen, bekannten Aufwand, der sich in fast allen normalen Fällen auszahlt.

Die eigentliche Idee dahinter

AsyncLocalStorage sollte nicht als globale Variable betrachtet werden, die zufällig höflich funktioniert. Strukturell ist es an eine bestimmte Kette der asynchronen Ausführung gebunden: Es überdauert jeden await, jedes Callback und jede Lösung einer Promise innerhalb dieser Kette, bleibt aber völlig unsichtbar für jede andere gleichzeitig laufende Kette. Sobald man dieses Konzept verinnerlicht hat, wirkt das Verhalten nicht mehr wie ein Trick, sondern erscheint als genau das richtige Werkzeug für eine bestimmte Aufgabe – nämlich Daten im Rahmen einer Anfrage von überall innerhalb einer Aufrufkette zugänglich zu machen, ohne dass jede Funktion in dieser Kette wissen oder sich darum kümmern muss, dass die Daten überhaupt an ihr vorbeigeleitet werden.