lars
webmobiledatenbankendevopsarchitektur
hello (at) larskoelpin.de

Verbessertes NodeJS Logging mit AsyncLocalStorage

November 19, 2022
opstypescript

Beim Monitoring ist das Logging wohl die bekannteste Möglichkeit, Applikationen zu beobachten. Beim Loggen werden Textnachrichten einer Applikation aufgenommen und gespeichert. Strukturiertes Logging ist eine Technik, bei der Log Nachrichten in einem strukturiertem Format, wie JSON, gespeichert werden. Meta-Daten helfen dem Entwickler den Kontext der Log-Nachricht zu verstehen.

Viele Sprachen und Laufzeitumgebungen haben ein Konzept von Threads um Meta-Daten beim Loggen aufzunehmen. Eine ähnliche API suchte man bei NodeJS vergebens — das hat sich mit AsyncLocalStorage geändert.

Thread Modell

In einer normalen Web-Applikation, wie z.B. im Java Umfeld erhält ein Web Request standardmäßig pro Request einen Thread. Das bedeutet, dass alle Operationen im Kontext dieses Threads laufen.

Ein einfaches Beispiel: Ein Nutzer authorisiert eine Anfrage an einen Server, beispielsweise durch einen Token. Es werden nun Rechte-Prüfungen vorgenommen und etwas in eine Datenbank geschrieben, sowie der Prozess durch Loggen unterstützt.

Der gesamte Prozess läuft im Kontext eines Threads ab. Durch die API von ThreadLocal ist es im Java Umfeld möglich, Daten an einen Thread zu speichern und abzurufen. Kommt eine Anfrage an einen Java basierten Webserver an und in jeder Log-Nachricht soll beispielsweise die userId mit auftauchen, die die Anfrage ausgelöst hat, könnte eine Implementierung deshalb wie folgt aussehen.

private static ThreadLocal<String> userId = ThreadLocal.withInitial(() -> null);

public static void main(String[] args) {

    Thread request1 = new Thread(new Runnable() {
        @Override
        public void run() {
            System.out.printf(Thread.currentThread().getName());
            info("Checking access");
            userId.set("USER1");
            info("User logged in");
        }
    });

    Thread request2 = new Thread(new Runnable() {
        @Override
        public void run() {
            System.out.printf(Thread.currentThread().getName());
            info("Checking access");
            userId.set("USER2");
            info("User logged in");
        }
    });
    request2.start();
    request1.start();
}

private static void info(String message) {
    System.out.println(message + " meta data: " + userId.get());
}

In der Main-Methode werden zwei Threads erzeugt, die die Requests simulieren sollen. Innerhalb der Requests wird jeweils der Name des Threads ausgeloggt. Im Thread wird dann die entsprechende userId des Nutzers gesetzt, sowie eine weitere Log-Nachricht abgesetzt.

Mit einer internen Log-API info soll dann eine Log-Nachricht, in diesem Falle System.out, geschrieben werden, sowie die entsprechenden Meta-Daten (userId.get()) der Log-Nachricht erfasst werden.

Wird dieser Code ausgeführt, lässt sich folgender Output beobachten:

Thread-0
Checking access meta data: null
User logged in meta data: USER1
Thread-1
Checking access meta data: null
User logged in meta data: USER2

Obwohl userId als static deklariert ist, erhalten beide Nutzer eine eigene ID.

ThreadLocal ermöglicht also ein Datenspeicherung, um Daten innerhalb eines Threads, oder eben Requests, zu pflegen — Thread Local eben.

Der Vorteil an dem Thread Modell ist, dass alle Operationen Synchron und blockierend sind — sie werden sequentiell abgearbeitet und haben den selben Call-Stack-Kontext. Jegliche Operation innerhalb des Stacks hat deshalb Zugriff auf die aktuelle userid — so auch unser Logger.



JavaScript ist Asynchron

Bei JavaScript, bzw. NodeJS sieht es anders aus. Da IO-Operationen von JavaScript asynchron und Single-Threaded ist, existiert kein einzelner technischer Kontext, wie bei Java beispielsweise Threads, in dem ein Request ausgeführt wird — durch die EventLoop wird ein Request eventuell von verschiedenen Threads abgearbeitet.

Versucht man also den Anwendungsfall von oben mit ähnlichem Code mit JavaScript abzubilden, könnte das so aussehen.

let userId;

const setUserId = (u) => {
    userId = u;
}

const info = (m) => {
    console.log(m + " meta: " + userId);
}

const loadAsync = async (withDelay) => {
    return new Promise((res, rej) => {
        if (!withDelay) {
            setTimeout(() => {
                info("user logged in")
                res();
            }, 100)
        } else {
            info("user logged in")
            res()
        }
    })
}

const onRequest = async (userId, special) => {
    setUserId(userId)
    info("Checking access");
    await loadAsync(special)
}


onRequest("user1", false);
onRequest("user2", true);

Der Code macht prinzipiell dasselbe, wie das entsprechende Java-Pondon. Wenn eine Anfrage beim Server an onRequest soll die zunächst userid für den Nutzer gesetzt werden innerhalb der Anfrage gesetzt werden. Wurde die UserId gesetzt wird eine Anfrage an ein externes System, abgebildet durch loadAsync abgesetzt. loadAsync hat die Besonderheit echte Gegebenheiten zu simulieren — durch den Parameter withDelay kann also ein verzögern der Antwort erreicht werden.

Wäre der Code logisch derselbe, wie das Java-Pondon müsste

user logged in meta: datauser1
user logged in meta: datauser2

ausgeloggt werden — Wird es aber nicht. Stattdessen ist in der Konsole

user logged in meta: datauser2
user logged in meta: datauser2

zu erkennen. Doch warum ist das so?

Durch das Delay-Flag wird der Rückgabe-Wert von loadAsync von Nutzer 1 verzögert. Der Callstack sieht deshalb so aus:

onRequest - User1
userId = user1
loadAsync -> Asynchrone EventLoop (Callback in 100ms)
-- Callstack ist leer -- 
onRequest - User2
userId = user2
loadAsync -> Asynchrone EventLoop (Callback in 0ms)
-- Callstack ist leer --
-- EventLoop wird abgearbeitet --
loadAsync -- user2
info // userId ist user2
-- user logged in meta: datauser2 --
loadAsync -- user1
info // userId ist user2
-- user logged in meta: datauser2 --

Das Problem ist also, dass das synchrone Merken des Zustandes durch verschiedene Unebenheiten in der realen Welt beeinflusst werden kann. Die Asynchronität von JavaScript macht das einfache Modell damit zunichte.

Glückerlicherweise gibt es eine Lösung: AsyncLocalStorage. AsyncLocalStorage ist eine API, die allen Callbacks innerhalb eines asynchronen Call-Stacks eine API zur Speicherung und Abrufen von Daten ermöglicht, ganz egal in welcher Reihenfolge diese abgearbeitet werden. Das sieht in der Praxis dann etwa so aus:

const { AsyncLocalStorage } = require('node:async_hooks')
const asyncLocalStorage = new AsyncLocalStorage();

const info = (m) => {
    console.log(m + "meta data" + asyncLocalStorage.getStore());
}

// ...

const onRequest = async (userId, special) => {
    asyncLocalStorage.run(userId, async () => {
       await loadAsync(special)
    })
}

Anstatt, dass wie zuvor ein globaler Zustand mit den Daten existiert, wird ein Objekt vom Typ AsyncLocalStorage erzeugt. Dieser hat in dem Code dieselbe Funktion wie zuvor die userId Variable, oder eben ThreadLocal bei Java.

Mittels asyncLocalStorage.run wird ein asynchroner Kontext aufgespannt. Alle Funktionen die innerhalb dieses Kontextes aufgerufen werden, können mittels

asyncLocalStorage.getStore() auf die Daten Zugreifen, die für den Kontext aktiv abgelegt wurden. In dem Beispiel wird jeder Request mit einer userId versehen. Genau mit dieser API ist es also denkbar das Logging von NodeJS Applikationen erheblich zu verbessern.

https://nodejs.org/api/async_hooks.html

Implementierung mit expressJS

Doch wie sieht das in der Praxis — in echten Applikationen — aus. Viele Applikationen nutzen expressJS und für das Logging einen Logger wie Bunyan.

Der Usecase ist ganz simple. Ein Nutzer macht einen Request mit der ID des Nutzers im user-id-Query-Parameter.

const app = express();
const MDC = new AsyncLocalStorage();
const mdcMiddleware = (req: any, res: any, next: any) => {
   const requestData = new Map();
   requestData.set("userId", req.query.userid)
   MDC.run(requestData, () => {
	 next();
   });
}
app.use(mdcMiddleware)
app.get((req: any, res: any) => {
	MDC.getStore().put("userId",  req.query.userid)
});
app.get("/", (req: any, res: any) => {
   info("getting all files")
    setTimeout(() => {
        info("sending response");
        res.send([])
    }, Math.random() * 6000);
})

app.listen(3000);

Zuerst wird express mittels require imporiert und eine express Instanz erzeugt. Danach wird ein AsyncLocalStorage erzeugt, der die Daten für den Logging-Kontext vorhalten soll. Der Logging Kontext ist eine Map, in der beliebige Key-Value Paare gespeichert werden können. Eine Integration mit express lässt sich durch das Nutzen vom Middleware Konzept erreichen. Es existiert demnach eine Funktion mdcMiddleware, die vor jedem Bearbeiten einer Anfrage aufgerufen wird. Innerhalb der Middleware wird der Kontext aufgespannt und danach die nachstehenden Funktionen mittels next aufgerufen. Jede Funktion die nach dieser Middleware aufgerufen wird ist demnach im Kontext und erhält Zugriff auf die Daten mittels MDC.getStore(). Es folgt deshalb eine Middleware, die den Kontext mit der ID des Nutzers, extrahiert aus dem userId-Parameter, befüllt.

In der wirklichen Logik werden Nachrichten ausgeloggt und während der Verarbeitung eine zufällige Anzahl an Sekunden gewartet, um ein sequentielles Verarbeiten der Anfragen zu verhindern.

Die letzte Implementierung, die dann noch fehlt, ist die des Loggers.

const info = (msg: string) => {
  const kv = MDC.getStore()
  const mdcVals = Object.fromEntries(kv);
  console.log(JSON.stringify({...mdcVals,  message: msg }));
}

Dieser kann ohne Probleme auf den Key-Value store zugreifen und die Daten entsprechend serialisieren. Wird jetzt ein HTTP GET Request gegen localhost:3000/?userId= mit einer zufälligen userId ausgeführt, wird folgendes geloggt.

{"userId":"lars1","message":"getting all files"}
{"userId":"lars2","message":"getting all files"}
{"userId":"lars1","message":"sending response"}
{"userId":"lars3","message":"getting all files"}
{"userId":"lars4","message":"getting all files"}
{"userId":"lars3","message":"sending response"}
{"userId":"lars5","message":"getting all files"}
{"userId":"lars2","message":"sending response"}
{"userId":"lars6","message":"getting all files"}
{"userId":"lars6","message":"sending response"}
{"userId":"lars5","message":"sending response"}
{"userId":"lars4","message":"sending response"}

Es hat also funktioniert. Die Log-Nachrichten werden asynchron abgearbeitet, der entsprechende Kontext wird dennoch beibehalten. Mit dieser API wäre jetzt natürlich denkbar noch weitere Parameter in den Kontext zu setzen:

  • RequestId
  • LobbyId
  • TraceId
  • …

Zusammenfassung

In dem Beitrag hab ich mir angeschaut, wie Programmiersprachen wie Java Meta-Daten an Log-Nachrichten abbilden. Da NodeJS aufgrund der EventLoop Asnychron ist, gibt es kein wirkliches Konzept von ThreadLocal wie bei anderen Sprachen. Es muss deshalb ein Mechanismus gefunden werden, einen Speichermechanismus zu geben, der über den Callstack hinweg Daten speichern kann. Mit AsyncLocalStorage haben wir genau diesen bekommen. Das AsyncLocalStorage-API bietet uns die Möglichkeit das Verhalten von ThreadLocal auch für Asynchrone Operationen zu erreichen.