Сопоставление логов между асинхронными вызовами с использованием AsyncLocalStorage

Каждый разработчик бэкенда рано или поздно сталкивается с именно такой ситуацией: при поступлении запроса создается requestId, и где-то на шестом уровне вложенности, внутри помощника для работы с базой данных или общей функции логирования, требуется тот же идентификатор, чтобы связать запись в логах с запросом, который её вызвал. Очевидным решением является передача этого ID в качестве аргумента через каждую функцию в цепочке. Это работает, но такой подход затрудняет обслуживание, поскольку теперь каждая промежуточная функция несёт параметр, который ей совершенно не нужен, кроме как передать его следующей функции.

Примитивные решения и причины их неудачи

Хочется воспользоваться простой переменной на уровне модуля, но это решение ошибочно, и его последствия проявятся только при работе в продакшене:

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
}

Такой подход кажется разумным, если предположить, что одновременно обрабатывается только один запрос, но он теряет смысл при учете того, как на самом деле Node обрабатывает конкурентность. Node обслуживает множество запросов «одновременно», переключаясь между их выполнением в точках await, а не выполняя их строго по очереди. Запрос A записывает значение в currentRequestId, затем достигает точки await и возвращает управление циклу событий, который может немедленно начать обработку запроса B и перезаписать эту же переменную ID запроса B. К тому моменту, когда код запроса A возобновляет работу, currentRequestId уже указывает на B, и с этого момента каждое сообщение о логе в запросе A ошибочно указывает неверный ID.

AsyncLocalStorage: контекст, следующий за выполнением, а не стеком вызовов

AsyncLocalStorage, входящий в состав встроенного модуля Node async_hooks, предназначен именно для решения этой проблемы. Он хранит отдельное значение для каждой логической цепочки асинхронной обработки и делает это корректно даже тогда, когда запросы переплетаются между вызовами await, цепочками обещаний и функциями-возвратами.

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
}

Вызов requestContext.run(store, next) предусматривает не просто присвоение значения, а создание контекста, который автоматически обрабатывает всё, что запускается внутри этого вызова, независимо от того, является ли выполнение синхронным или асинхронным, включая код, который продолжает работу после оператора await, выполняется внутри обработчика .then() или запускается позже в качестве обратного вызова от какой-либо операции ввода-вывода. Даже в глубине помощника для выполнения запросов к базе данных, определённого в совершенно отдельном файле, вызов requestContext.getStore() возвращает контекст, принадлежащий конкретному запросу, а не контекст, заимствованный у какого-либо ранее выполненного запроса. Это происходит потому, что контекст привязан к конкретной цепочке асинхронного выполнения, совершающей вызов, а не к какой-либо общей переменной, в которую записывается каждый запрос.

Почему это действительно работает между границами await

Именно это свойство отличает AsyncLocalStorage от обычной переменной и напрямую связано с тем, как на самом деле работают конструкции async/await. Каждый раз, когда функция async приостанавливается на операторе await и затем возобновляет работу, Node отслеживает, с каким асинхронным контекстом связано это возобновление, и автоматически восстанавливает его перед выполнением следующего кода:

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

В промежутке между двумя вызовами logSomething цикл событий имел полную свободу для выполнения кода других запросов, однако ни один из этих параллельных операций не нарушал того контекста, в котором выполнялся код после возобновления. Именно это и является гарантией, которую не могла обеспечить простая общедоступная переменная: корректность, сохраняющаяся даже при таком виде параллельного выполнения, который активно поддерживается моделью конкурентности Node.

Настоящая польза: структурированное логирование без необходимости указания параметров потоков повсюду

Именно здесь добавленная сложность AsyncLocalStorage оправдывает себя в реальном приложении: вы можете создать механизм логирования, который автоматически привязывает контекст запроса к каждому вызову, при этом в коде-запросчике не требуется передавать никаких параметров:

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

Для работы этого механизма ничего не пришлось менять в сигнатуре функции processPayment. Она никогда не принимает аргумент requestId и никогда не передаёт его другим функциям, тем не менее каждая запись в логе правильно маркируется запросом, ответственным за неё. В этом и заключается настоящая польза: данные, связанные с конкретным запросом, становятся доступными в любой точке цепочки вызовов, не засоряя сигнатуры всех функций между началом запроса и моментом его фактического использования.

Граница, которая создает проблемы

Контекст, задаваемый внутри .run(), охватывает только тот код, который действительно является частью этой же цепочки выполнения: всё, что вызывается изнутри обратного вызова, будь то напрямую или косвенно, включая цепочки ожидающихся обещаний. Он не распространяется назад на код, который был выполнен до вызова .run(), и не распространяется вперед на операции, которые фактически отделяются от этой цепочки:

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

Вызов setTimeout изнутри данного контекста по-прежнему работает как ожидается, поскольку механизм распространения событий async_hooks в Node покрывает таймеры, обещания и практически все стандартные асинхронные примитивы, с которыми можно столкнуться. Проблемы возникают лишь при работе, выполнение которой запланировано автоматически и предназначено для продолжения существования даже после завершения запроса, который её запустил. Хорошим примером является задача, отправленная в отдельный, независимый рабочий процесс: между ней и контекстом, откуда она начала свою работу, нет никакой цепочки выполнения, поскольку это совсем не продолжение одной и той же асинхронной последовательности вызовов — это совершенно отдельная, не связанная между собой последовательность.

Честное замечание о производительности

AsyncLocalStorage — не бесплатный инструмент. Захват и восстановление контекста при каждой асинхронной смене состояния требует значительных усилий, причем более старые версии Node обрабатывали это гораздо менее эффективно, чем современная версия. В текущих релизах Node нагрузка, связанная с использованием этого инструмента для типичных веб-приложений, настолько незначительна, что она не будет иметь значения для подавляющего большинства проектов, а улучшения в корректности кода и его чистоте почти всегда оправдывают эту небольшую стоимость. Если вы работаете в условиях крайней масштабированности, где каждая доля секунды на обработку запроса имеет значение, стоит провести тестирование в вашем конкретном случае. Однако для практически любого бэкенд-сервиса разумно считать его безопасным стандартным решением. Это не какой-то специализированный трюк оптимизации, к которому обращаются время от времени; это инструмент с небольшой, известной затратой, которая окупается в почти всех обычных ситуациях.

Истинная идея, стоящая за этим

AsyncLocalStorage не следует рассматривать как глобальную переменную, которая просто ведет себя корректно. Структурно он привязан к конкретной цепочке асинхронной обработки: он сохраняется после каждого вызова await, каждой обратной связи и реализации обещания внутри этой цепочки, при этом остаётся совершенно невидимым для любой другой цепочки, работающей одновременно. Как только вы осознаёте эту модель, его поведение перестаёт казаться уловкой и начинает выглядеть как именно тот инструмент, который необходим для выполнения определённой задачи: обеспечивать доступ к данным, связанным с запросом, из любой точки внутри цепочки вызовов, не заставляя каждую функцию в этой цепочке знать или беспокоиться о том, что данные передаются через неё.