Korelacja logów z różnych asynchronicznych wywołań za pomocą AsyncLocalStorage
Dowiedz się, jak Node.js AsyncLocalStorage śledzi kontekst na poziomie każdej prośby, takiego jak requestId, pomiędzy wywołaniami await, bez konieczności ręcznego przenoszenia go przez każdą funkcję.
Źródła: The Node.js Feature That Replaces Passing `requestId` Through Every Single Function
Każdy programista zajmujący się backendem prędzej czy później napotyka dokładnie tę sytuację: gdy przychodzi żądanie, tworzy się requestId, a gdzieś sześć poziomów niżej, w narzędziu do pracy z bazą danych lub wspólnej funkcji logowania, potrzebny jest ten sam identyfikator, aby móc powiązać wpis w dzienniku z żądaniem, które go wywołało. Oczywistym rozwiązaniem jest przekazywanie tego ID jako argumentu przez każdą funkcję w łańcuchu. Działa to, ale utrzymanie takiego rozwiązania jest trudne, ponieważ teraz każda funkcja pośrednia przenosi parametr, którego nie używa poza przekazaniem go dalej do następnej funkcji.
Naiwne rozwiązania i dlaczego oba zawodzą
Kuszące jest użycie prostej zmiennej na poziomie modułu, ale ten instynkt jest błędny – problem ujawni się dopiero w środowisku produkcyjnym:
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
}
Taki podejście wydaje się rozsądne, jeśli założyć, że jednocześnie przetwarzana jest tylko jedna prośba, ale zawodzi, gdy weźmiemy pod uwagę sposób, w jaki Node faktycznie radzi sobie z równoczesnością. Node obsługuje wiele żądań „jednocześnie”, mieszając ich wykonywanie wokół punktów await, zamiast uruchamiać je ściśle po kolei. Prośba A zapisuje wartość do currentRequestId, następnie napotyka instrukcję await i przekazuje kontrolę z powrotem do pętli zdarzeń, która może natychmiast rozpocząć przetwarzanie prośby B i nadpisać tę samą zmienną jej identyfikatorem. Gdy kod prośby A wraca do wykonywania, currentRequestId wskazuje już na B, i od tego momentu każde zdanie logujące w prośbie A błędnie przypisuje niewłaściwy identyfikator.
AsyncLocalStorage: Kontekst, który podąża za wykonywaniem, a nie za stosem wywołań
AsyncLocalStorage, dostępny jako część wbudowanego modułu async_hooks w Node, został stworzony właśnie po to, by rozwiązać ten problem. Przechowuje odrębną wartość dla każdego logicznego łańcucha asynchronicznego wykonywania i robi to poprawnie, nawet gdy żądania są mieszane pomiędzy wywołaniami await, łańcuchami obietnic i funkcjami zwrotnymi.
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
}
Wywołanie requestContext.run(store, next) służy nie tylko do przypisania wartości – otwiera ono kontekst, który automatycznie obejmuje wszystko, co zostanie wywołane w ramach tego zapytania, niezależnie od tego, czy wykonywanie jest synchroniczne, czy asynchroniczne. Obejmuje to kod kontynuujący się po instrukcji await, kod uruchamiany wewnątrz obsługi .then(), a także kod wywoływany później jako funkcja zwrotna po jakiejś operacji wejścia/wyjścia. Nawet w głębi pomocnika do zapytań bazodanowych zdefiniowanego w zupełnie oddzielnym pliku, wywołanie requestContext.getStore() zwraca kontekst należący do właściwego żądania, a nie taki pożyczony od żądania, które akurat zostało wykonywane wcześniej. Dzieje się tak dlatego, że kontekst jest powiązany z konkretnym łańcuchem wykonywania asynchronicznego, który dokonał tego wywołania, a nie z jedną wspólną zmienną, do której zapisuje dane każde żądanie.
Dlaczego to faktycznie działa pomimo granic await
To właśnie ta cecha odróżnia AsyncLocalStorage od zwykłej zmiennej i bezpośrednio wpływa na sposób działania async/await w głębi systemu. Za każdym razem, gdy funkcja async zostaje wstrzymana na poziomie await i później kontynuowana, Node śledzi, z jakim asynchronicznym kontekstem jest to kontynuowanie powiązane, i automatycznie przywraca go przed uruchomieniem dalszej części kodu:
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);
});
});
Pomiędzy dwoma wywołaniami logSomething pętla zdarzeń mogła swobodnie wykonywać kod innych żądań, a mimo to żadne z tych równoległych operacji nie zakłóciło tego, w jakim kontekście będzie działać dalsza część kodu po jego kontynuacji. To właśnie jest gwarancją, której nie mogła zapewnić prosta zmienna współdzielona: poprawność działania nawet w warunkach takiego równoległego wykonywania, które jest aktywnie promowane przez model koniugacji w Node.
Prawdziwa korzyść: ustrukturyzowane logowanie bez parametrów wątkowych wszędzie
To właśnie tutaj dodana złożoność AsyncLocalStorage przynosi korzyści w rzeczywistej aplikacji: można stworzyć narzędzie do logowania, które automatycznie przypisuje kontekst żądania do każdej wywołania, bez konieczności przekazywania żadnych parametrów w kodzie wywołującym:
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
W sygnaturze funkcji processPayment nie trzeba było nic zmieniać, aby to zadziałało. Funkcja ta nigdy nie przyjmuje argumentu requestId ani go nie przekazuje żadnej innej funkcji, a mimo to każda linia logu jest prawidłowo oznaczona żądaniem, które ją wygenerowało. To jest prawdziwa korzyść: dane związane z konkretnym żądaniem stają się dostępne wszędzie w łańcuchu wywołań, bez konieczności mnożenia sygnatur funkcji pomiędzy początkiem żądania a miejscem, gdzie te dane są faktycznie wykorzystywane.
Granica, która sprawia problemy
Kontekst ustanowiony wewnątrz .run() obejmuje jedynie kod, który faktycznie należy do tej samej łańcuchu wykonywania: wszystko, co zostanie wywołane z wnętrza funkcji callback, bez względu na to, czy bezpośrednio, czy pośrednio, w tym poprzez łańcuchy oczekiwanych obietnic. Nie rozciąga się on wstecz na kod, który został wykonyany przed wezwaniem .run(), ani nie obejmuje prac, które rzeczywiście oddzielają się od tego łańcucha:
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();
});
});
Wywoływanie setTimeout wewnątrz danego kontekstu nadal działa zgodnie z oczekiwaniami, ponieważ mechanizm propagacji async_hooks w Node obejmuje timery, obietnice oraz niemal wszystkie standardowe prymitywy asynchroniczne, z którymi możemy się spotkać. Problemy pojawiają się natomiast w przypadku zadań realizowanych „fire-and-forget”, które są celowo zaprojektowane tak, by przetrwać dłużej niż żądanie, które je uruchomiło. Dobrym przykładem jest zadanie przesłane do oddzielnego, niezależnego procesu roboczego – nie istnieje łańcuch wykonywania, który łączyłby je z kontekstem, z którego pochodzi, ponieważ w ogóle nie jest to kontynuacja tej samej sekwencji asynchronicznych wywołań. Jest to odrębna, niepowiązana sekwencja.
Szczerza ocena wydajności
AsyncLocalStorage nie jest darmowy. Przechwytywanie i przywracanie kontekstu podczas każdej asynchronicznej zmiany wymaga sporego wysiłku, a starsze wersje Node radziły sobie z tym znacznie mniej efektywnie niż dzisiejszy silnik wykonawczy. W aktualnych wersjach Node nakład pracy związany z typowym obciążeniem aplikacji internetowych jest na tyle mały, że nie będzie miało znaczenia dla zdecydowanej większości projektów, a korzyści w postaci poprawności i lepszego kodu prawie zawsze wynagradzają ten niewielki koszt. Jeśli działasz na ekstremalnej skali, gdzie każda mikrosekunda na zapytanie ma znaczenie, warto przeprowadzić testy porównawcze dla swojego konkretnego przypadku. Ale dla niemal każdej usługi backendowej uznanie tego za bezpieczny standard jest rozsądne. To nie jakiś specjalistyczny trik optymalizacyjny, do którego uciekasz od czasu do czasu; to narzędzie o niewielkim, znanych kosztach, które w niemal wszystkich normalnych sytuacjach się zwraca.
Prawdziwa idea stojąca za tym
AsyncLocalStorage nie powinien być postrzegany jako zmienna globalna, która przypadkowo zachowuje się uprzejmie. Strukturalnie jest powiązany z konkretnym łańcuchem asynchronicznego wykonywania: przetrwa każde await, każdy callback oraz każdą realizację obietnicy w tym łańcuchu, pozostając przy tym całkowicie niewidoczny dla jakiegokolwiek innego łańcucha działającego jednocześnie. Gdy już zrozumiesz ten model, jego zachowanie przestanie wydawać się podstępem i zacznie jawić się jako dokładnie odpowiedni narzędzie do jednego konkretnego zadania: umożliwienia dostępu do danych zdefiniowanych w kontekście żądania z dowolnego miejsca w łańcuchu wywołań, bez konieczności zmuszania każdej funkcji w tym łańcuchu do wiedzy lub troski o to, że dane są przez nią przekazywane.
Literatura pokrewna
- Wybór między Promise.all, Promise.race a sekwencyjnymi oczekiwaniami — Dowiedz się, kiedy Promise.all() przyspiesza API Node.js, dlaczego szybko zawodzi przy każdym odrzuceniu oraz jak wybrać odpowiedni wzorzec asynchroniczny.
- Poprawianie błędów w obróbce błędów async-await w kodzie produkcyjnym Node.js — Poznaj pięć powszechnych błędów w obróbce błędów async/await w JavaScript i Node.js, które powodują ciche awarie i sytuacje konkurencyjne, oraz konkretnych rozwiązań.