Пов’язування журналів між асинхронними викликами за допомогою 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. До моменту, коли код запиту 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, кожної функції-відповіді та кожного вирішення обіцянки в межах цієї послідовності, залишаючись при цьому абсолютно невидимим для будь-якої іншої послідовності, яка виконується одночасно. Як тільки ви зрозумієте цю модель, його поведінка перестає здаватися трюком та починає виглядати як саме той інструмент, що потрібен для конкретної задачі: забезпечувати доступ до даних, пов’язаних із запитом, з будь-якої точки всередині ланцюга викликів, не змушуючи кожну функцію в цьому ланцюзі знати чи перейматися тим, що дані проходять через неї.