Corréler les journaux entre des appels asynchrones à l’aide d’AsyncLocalStorage

Tout développeur backend finit par se retrouver dans ce scénario précis : un requestId est créé lorsqu’une requête arrive, et à un endroit situé à six niveaux de profondeur, au sein d’une fonction d’aide à la base de données ou d’une fonction de journalisation partagée, on a besoin de ce même identifiant pour relier une entrée de journal au requête qui l’a déclenchée. La solution évidente consiste à transmettre cet ID en argument à travers chaque fonction de la chaîne. Cela fonctionne, mais c’est difficile à maintenir, car chaque fonction intermédiaire doit maintenant gérer un paramètre dont elle n’a pas besoin autrement que pour le transmettre à l’appel suivant.

Les solutions naïves, et pourquoi elles échouent toutes les deux

Il est tentant de recourir à une variable au niveau du module, mais cet instinct est erroné, et les conséquences ne se manifesteront que lors du fonctionnement en production :

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
}

Cette approche semble raisonnable si l’on imagine qu’une seule requête est traitée à la fois, mais elle échoue dès lors que l’on prend en compte la manière dont Node gère réellement la concurrence. Node traite de nombreuses requêtes « simultanément » en alternant leur exécution autour des points await plutôt qu’en les exécutant strictement l’une après l’autre. La requête A écrit dans currentRequestId, puis rencontre un await et cède le contrôle au cycle d’événements, qui peut immédiatement commencer à traiter la requête B et écraser cette même variable avec l’ID de B. Lorsque le code de la requête A reprend, currentRequestId pointe vers B, et à partir de ce moment-là, chaque instruction d’affichage dans la requête A attribue silencieusement et sans erreur l’ID incorrect.

AsyncLocalStorage : un contexte qui suit l’exécution, et non la pile d’appels

AsyncLocalStorage, inclus dans le module intégré async_hooks de Node, a été conçu pour résoudre précisément ce problème. Il conserve une valeur distincte pour chaque chaîne logique d’exécution asynchrone, et il le fait correctement même lorsque les requêtes s’entremêlent à travers des appels await, des chaînes de promesses et des fonctions de rappel.

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
}

L’appel de requestContext.run(store, next) va au-delà d’une simple affectation de valeur : il crée un contexte qui s’applique automatiquement à tout ce qui est exécuté à partir de cet appel, que l’exécution soit synchrone ou asynchrone. Cela inclut le code qui continue après un await, celui qui s’exécute à l’intérieur d’un gestionnaire .then(), ou encore celui qui est déclenché plus tard en tant que callback suite à une opération I/O. Même au cœur d’un outil de requête de base de données défini dans un fichier complètement distinct, l’appel de requestContext.getStore() renvoie le contexte correspondant à la requête en cours, et non celui emprunté à la dernière requête ayant été exécutée. Cela est dû au fait que le contexte est lié à la chaîne d’exécution asynchrone spécifique qui effectue l’appel, et non à une variable partagée dans laquelle chaque requête écrit ses données.

Pourquoi cela fonctionne réellement au-delà des limites de await

C’est cette propriété qui distingue AsyncLocalStorage d’une variable ordinaire, et elle est directement liée au fonctionnement interne de async/await. Chaque fois qu’une fonction async est suspendue à un await puis reprend son exécution, Node enregistre le contexte asynchrone auquel cette reprise est associée et le restaure automatiquement avant que la continuation ne s’exécute :

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);
  });
});

Entre les deux appels à logSomething, le cycle d’événements était entièrement libre d’exécuter le code d’autres requêtes, mais aucune de ces exécutions simultanées n’a altéré le contexte que cette continuation particulière perçoit une fois qu’elle reprend. C’est précisément la garantie que la variable partagée classique ne pouvait pas offrir : une correction qui reste valide même face au type d’exécution simultanée que le modèle de concurrence de Node favorise activement.

Le véritable avantage : un enregistrement structuré sans paramètres de thread partout

C’est ici que la complexité supplémentaire de AsyncLocalStorage s’avère utile dans une application réelle : on peut créer un outil d’enregistrement qui associe automatiquement le contexte de la requête à chaque appel, sans que le code appelant ait besoin de transmettre un paramètre pour cela :

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

Rien dans la signature de fonction processPayment n’a dû changer pour que cela fonctionne. Elle ne reçoit jamais d’argument requestId et n’en transmet jamais à aucune fonction appelée, pourtant chaque ligne d’audit qu’elle génère est correctement étiquetée avec la requête qui en est responsable. C’est là le véritable avantage : les données liées à une requête deviennent accessibles partout dans la chaîne d’appels, sans encombrer chaque signature de fonction entre le début de la requête et l’endroit où ces données sont réellement utilisées.

La limite qui embrouille les gens

Le contexte que vous créez à l’intérieur de .run() ne s’applique qu’au code qui fait réellement partie de cette même chaîne d’exécution : tout ce qui est invoqué depuis l’intérieur du callback, que ce soit directement ou indirectement, y compris à travers des chaînes de promesses en attente. Il ne s’étend pas en arrière vers le code qui a été exécuté avant l’appel de .run(), et il ne s’étend pas non plus vers l’avant vers des tâches qui se détachent véritablement de cette chaîne :

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();
  });
});

L’appel à setTimeout depuis l’intérieur du contexte fonctionne toujours comme prévu, car le mécanisme de propagation async_hooks de Node couvre les timers, les promesses et presque toutes les primitives asynchrones standard que l’on peut rencontrer. C’est plutôt avec les tâches exécutées de manière déconnectée, conçues intentionnellement pour survivre au-delà de la requête qui les a déclenchées, que les problèmes surviennent. Une tâche envoyée vers un processus travailleur indépendant en est un bon exemple : il n’existe aucune chaîne d’exécution la reliant au contexte d’origine, car il ne s’agit pas du tout de la continuation de la même séquence asynchrone d’appels. Il s’agit plutôt d’une séquence distincte et sans rapport.

Remarque honnête sur les performances

AsyncLocalStorage n’est pas gratuit. Capturer et restaurer le contexte à chaque transition asynchrone exige beaucoup d’efforts, et les versions anciennes de Node géraient cela de manière bien moins efficace que le moteur actuel. Dans les versions récentes de Node, la charge supplémentaire pour une application web typique est suffisamment faible pour ne pas poser de problème à la grande majorité des projets, et les avantages en termes de correction et de code plus propre valent presque toujours ce petit coût. Si vous fonctionnez à une échelle extrême où chaque microseconde par requête compte, il est utile de faire des benchmarks pour votre cas spécifique. Mais pour presque tous les services backend, il est raisonnable de le considérer comme une option par défaut fiable. Ce n’est pas un truc d’optimisation spécialisé à utiliser occasionnellement ; c’est un outil dont le coût, bien que faible et connu à l’avance, se paie presque toujours dans des circonstances normales.

L’idée réelle derrière tout cela

AsyncLocalStorage ne doit pas être considéré comme une variable globale qui se comporte simplement de manière polie. Il est structurellement lié à un seul et même flux d’exécution asynchrone : il survit à chaque await, à chaque fonction de rappel et à chaque résolution de promesse au sein de ce flux, tout en restant complètement invisible pour tout autre flux exécuté en même temps. Une fois que ce modèle est bien compris, son comportement cesse de sembler être un tour de passe-passe pour apparaître comme l’outil idéal pour une tâche précise : rendre les données liées à une requête accessibles depuis n’importe où au sein d’une chaîne d’appels, sans obliger chaque fonction de cette chaîne à savoir, ou se soucier, du fait que ces données lui sont transmises.

Lectures complémentaires