Strukturalne logowanie w Node.js: Przekształcanie chaosu podczas debugowania w produkcji w klarowność

Klient skarży się, że proces płatności u niego zawiodł. Twoja tablica kontrolna wskazuje na nierozwiązany błąd: TypeError: Cannot read properties of undefined (reading 'id').

Otwierasz plik wskazany w śladzie wywołań i problematyczny wiersz wydaje się zupełnie zwyczajny:

const customerId = session.user.id;

Dlaczego więc session.user był w tym momencie niezdefiniowany?

Próbujesz odtworzyć ten błąd lokalnie. Logujesz się, przechodzisz przez proces płatności i nic się nie psuje. Sprawdzasz bazę danych i stwierdzasz, że każdy rekord testowy ma dołączony kompletny obiekt użytkownika. Bez możliwości zobaczenia, jakie dane faktycznie dotarły do tego wiersza kodu w środowisku produkcyjnym, musisz zgadywać.

Tego typu dochodzenie może pochłonąć całe dni pracy inżynierów. Ale jeśli zainstalowałeś logowanie w sposób celowy i uporządkowany, ten sam błąd często zostaje rozwiązany w ciągu kilku minut.

Dlaczego debugowanie Node.js w środowisku produkcyjnym jest trudne

Podczas rozwoju lokalnego masz dostęp do interaktywnych narzędzi debugowania, natychmiastową informację z terminala oraz zazwyczaj tylko jednego użytkownika korzystającego z aplikacji – ciebie samego. Jeśli jakaś ścieżka wywoła błąd, po prostu uruchamiasz ją ponownie z innymi danymi, aż przyczyna zostanie ustalona.

Środowisko produkcyjne nie oferuje żadnych z tych udogodnień:

• Asynchroniczna eksploatacja: Node.js obsługuje wiele operacji jednocześnie za pomocą pętli zdarzeń. Podczas gdy jedna prośba czeka na wywołanie bazy danych, inna już wykonuje swoją własną logikę. Wyniki z konsoli pochodzące od równoczesnych żądań mieszają się ze sobą, co utrudnia ich odczyt.
• Dane tymczasowe: Dokładna treść danych przesłanych przez użytkownika istnieje w pamięci tylko przez krótki czas. Gdy nieobsłużony błąd powoduje awarię procesu lub serwer odpowiada kodem 500, te konkretne dane stają się nieodzyskane.

Cienkie ślady stosu wywołań: Ślad stosu wywołań w JavaScript informuje o gdzie doszło do błędu w wykonywaniu kodu, ale prawie nigdy nie wskazuje dlaczego. Nie ujawnia również, który użytkownik dokonał wywołania, które opcje zostały wybrane ani co faktycznie zwróciła usługa nadrzędna.

Bez celowego rejestrowania działań aplikacja zachowuje się jak zamknięta czarna skrzynka. Skuteczne praktyki logowania pełnią rolę panelu kontrolnego, który pokazuje, co dzieje się w jej wnętrzu.

Pułapka logów konsoli

Większość programistów najpierw sięga po funkcję console.log() podczas debugowania aplikacji Node.js. Jest ona dostępna wraz z środowiskiem wykonawczym, nie wymaga konfiguracji i zapisuje dane bezpośrednio do stdout.

Jednak poleganie na niej w środowisku produkcyjnym powoduje trzy istotne problemy.

1. Tworzy tekst niestrukturyzowany

Weźmy na przykład tę linię:

console.log("Payment processed for user: " + userId + " amount: " + amount);

Gdy platforma agregacji logów, taka jak Datadog, CloudWatch czy Grafana Loki, przyjmuje tę linię tekstową, przechowuje ją jako zwykły ciąg znaków bez żadnego indeksowania. Nie ma efektywnego sposobu na zapytanie typu „wszystkie płatności powyżej 1000”, ponieważ platforma musiałaby użyć kosztownego analizatora regex tylko po to, by wyekstrahować te wartości.

2. Brak kontekstu wykonywania

Załóżmy, że log błędów zawiera jedynie następujący tekst:

Database timeout on query

Nie ma tu żadnych informacji wskazujących, która ścieżka wywołała zapytanie, który użytkownik był zaangażowany lub kiedy nadeszła prośba.

3. Może pogorszyć wydajność pętli zdarzeń

W określonych warunkach — szczególnie przy zapisywaniu do plików lub przekazywaniu wyjścia przez pipeline na niektórych systemach — console.log() jest wykonywany synchronicznie. Gdy obciążenie jest wysokie, częste wywołania console.log() blokują pętlę zdarzeń Node.js, co zwiększa opóźnienia w całym aplikacji.

Trzy filary rejestracji zdarzeń na poziomie produkcyjnym

Aby logi były rzeczywiście przydatne do debugowania, konieczne jest wdrożenie trzech podstawowych praktyk: ustrukturyzowanego wyjścia, spójnych poziomów powagi oraz identyfikatorów korelacji.

1. Ustrukturyzowana rejestracja zdarzeń (JSON)

Zamiast zapisywać zwykłe łańcuchy tekstowe, aplikacja powinna emitować każdą pozycję logu jako ustrukturyzowany obiekt JSON. Klucze JSON mogą być automatycznie indeksowane przez platformy do logowania.

{
  "timestamp": "2026-03-24T14:32:01.412Z",
  "level": "error",
  "message": "Payment processing failed",
  "userId": "usr_9912",
  "orderId": "ord_5521",
  "attempt": 3,
  "error": "Gateway timeout"
}

W tym formacie nie ma potrzeby domyślania się, co poszło nie tak — wystarczy wyszukać orderId: „ord_5521”, aby natychmiast uzyskać dostęp do wszystkich zapisów związanych z tą zamówieniem.

2. Znaczące poziomy logów

Nie każda pozycja wymaga takiego samego poziomu uwagi. Stosowanie spójnych poziomów logowania pomaga utrzymać produkcyjne dane w zrozumiałej formie:

• DEBUG: Szczegółowe informacje diagnostyczne przeznaczone do rozwoju, takie jak pełne wydruki danych lub wewnętrzne decyzje rozgałęziające. Zazwyczaj są one ukrywane w środowisku produkcyjnym.
• INFO: Standardowe komunikaty operacyjne potwierdzające prawidłową pracę aplikacji, np. Server started on port 3000 lub User account created.

OSTRZEŻENIE: Sytuacje, z których system samodzielnie się odbudował, ale które mogą wskazywać na rosnący problem — na przykład brak danych w pamięci podręcznej zmuszający do użycia bazy danych jako alternatywy lub próba połączenia z przestarzałym punktem końcowym przez klienta.

BŁĘD: Awarie, które uniemożliwiły zakończenie operacji i wymagają interwencji człowieka, takie jak nieudana transakcja płatnicza lub nierozwiązane odrzucenie obietnicy.

3. ID korelacji (Śledzenie zapytań)

Ponieważ Node.js wykonuje operacje asynchronicznie, potrzebny jest sposób na śledzenie pojedynczego zapytania w trakcie jego przepływu przez kontrolery, usługi, wywołania bazy danych oraz zewnętrzne żądania API.

ID korelacji – powszechnie nazywane requestId lub traceId – to unikalny identyfikator tworzony w momencie pierwszego przybycia żądania HTTP. Ten identyfikator jest dołączany do każdej linii dziennika generowanej podczas przetwarzania danego żądania.

Praktyczna implementacja: Ustrukturyzowane logowanie w Express

Załóżmy teraz, że wprowadzimy to w praktykę, budując gotową do użycia konfigurację logowania przy użyciu Pino, bardzo szybkiego loggera JSON dla Node.js, w połączeniu z wbudowaną API AsyncLocalStorage do obsługi ID korelacji.

Krok 1: Konfiguracja sklepu kontekstowego i loggera

Node.js zawiera wbudowany moduł AsyncLocalStorage, dostępny poprzez podstawowy moduł node:async_hooks. Można go porównać do pamięci lokalnej wątku stosowanej w językach wielowątkowych: utrzymuje on kontekst aktywny podczas wywołań asynchronicznych, bez konieczności ręcznego przekazywania parametrów wątkowych do każdej funkcji.

// logger.js
import pino from 'pino';
import { AsyncLocalStorage } from 'node:async_hooks';

export const asyncLocalStorage = new AsyncLocalStorage();const baseLogger = pino({
  level: process.env.LOG_LEVEL || 'info',
  timestamp: pino.stdTimeFunctions.isoTime,
});// A proxy that injects the requestId into every log entry automatically
export const logger = new Proxy(baseLogger, {
  get(target, property) {
    const store = asyncLocalStorage.getStore();
    const childLogger = store?.requestId
      ? target.child({ requestId: store.requestId })
      : target;    return childLogger[property];
  }
});

Krok 2: Implementacja middleware Express

Następnie napisz middleware, który przypisuje identyfikator do każdego przychodzącego żądania i wykonuje resztę cyklu życia żądania w kontekście AsyncLocalStorage.

// middleware.js
import { randomUUID } from 'node:crypto';
import { asyncLocalStorage, logger } from './logger.js';

export function requestContextMiddleware(req, res, next) {
  // Use existing header if forwarded by a load balancer, or create a new UUID
  const requestId = req.headers['x-request-id'] || randomUUID();

  res.setHeader('x-request-id', requestId);  asyncLocalStorage.run({ requestId }, () => {
    const startTime = Date.now();    logger.info({
      method: req.method,
      url: req.url,
      ip: req.ip
    }, 'Incoming request');    res.on('finish', () => {
      const durationMs = Date.now() - startTime;

      const logData = {
        statusCode: res.statusCode,
        durationMs
      };      if (res.statusCode >= 500) {
        logger.error(logData, 'Request completed with server error');
      } else {
        logger.info(logData, 'Request completed');
      }
    });    next();
  });
}

Krok 3: Użycie loggera w logice biznesowej

W funkcjach kontrolerów lub usług po prostu imporтуj wspólny logger. Nie ma potrzeby ręcznego przekazywania req lub requestId jako parametrów funkcji.

// orderService.js
import { logger } from './logger.js';

export async function processOrder(user, cart) {
  logger.info({ cartItemsCount: cart.items.length }, 'Validating cart inventory');  if (!user || !user.id) {
    logger.warn({ userState: user }, 'Attempted checkout without a valid user ID');
    throw new Error('User identification is missing');
  }  // Continue checkout logic...
}

Jeśli coś pójdzie nie tak wewnątrz processOrder, wpis do dziennika będzie wyglądał w ten sposób:

{
  "time": "2026-03-24T14:40:12.102Z",
  "level": 40,
  "requestId": "9b1deb4d-3b7d-4bad-9bdd-2b0d7b3dcb6d",
  "userState": null,
  "msg": "Attempted checkout without a valid user ID"
}

Zauważ, jak requestId pojawia się automatycznie w tym wpisie. Posiadając tę wartość, możesz przeszukać swoje dzienniki i odtworzyć pełną sekwencję zdarzeń związanych z daną prośbą, od początku do końca.

Anatomia 5-minutowego rozwiązania

Wróćmy do pierwotnego problemu: session.user okazuje się być undefined w trakcie procesu płatności.

Bez ustrukturyzowanego kontekstu (scenariusz koszmaru)

• Ślad stosu wskazuje na const customerId = session.user.id.
• Sprawdzasz bazę danych i stwierdzasz, że wszystkie konta testowe mają w pełni ważne sesje.

Spędzasz 45 minut na testowaniu różnych teorii: płatności gościnne, wygasłe sesje, zachowanie specyficzne dla urządzeń mobilnych.

Wprowadzasz tymczasowe wywołania console.log() do środowiska produkcyjnego, mając nadzieję, że błąd ponownie się pojawi, abyś mógł go zaobserwować w czasie rzeczywistym.

Problem pozostaje nierozwiązany przez kilka dni.

Z użyciem strukturyzowanego kontekstu (scenariusz 5 minut)

• Bierzesz requestId z raportu o błędzie klienta lub powiadomienia o błędzie 500.
• Szukasz w swoim agregatorze logów wpisu requestId: "9b1deb4d-3b7d-4bad-9bdd-2b0d7b3dcb6d".
• Przeglądasz trzy linie z dziennika powiązane z tym ID i czytasz je po kolei. Pierwsza pokazuje, że żądanie trafia do ścieżki checkout. Druga ujawnia, że sesja należy do anonimowego, nieautoryzowanego gościa, a nie do zalogowanego klienta. Trzecia potwierdza, że logika checkout odrzuciła próbę właśnie dlatego, że nie było dostępne ważne ID użytkownika.
• Czytanie tych trzech wpisów razem od razu ujawnia podstawową przyczynę: użytkownicy gościnni dostają się bezpośrednio do autoryzowanej ścieżki checkout, omijając zamierzony przekierowanie dla użytkowników gościnnych.
• Naprawa sprawdzenia autoryzacji zajmuje około pięciu minut.

Rozwiązanie pojawiło się szybko nie dlatego, że kod stał się prostszy, ale dlatego, że działająca aplikacja już udokumentowała swój własny ścieżkę wykonywania.

Częste błędy w logowaniu, których należy unikać

Nawet doświadczone zespoły w kilka przewidywalnych sposobów pogarszają jakość swoich dzienników:

• Zapisywanie wrażliwych danych (PII): Nigdy nie zapisuj do dzienników haseł, tokenów autoryzacji, pełnych numerów kart ani innych danych osobowych. Korzystaj z wbudowanych funkcji maskowania — na przykład opcji redact w Pino — aby automatycznie usuwać pola takie jak password lub authorization przed zserializowaniem danych.
• Zapisywanie wszystkiego w środowisku produkcyjnym: Zalewanie żywego systemu danymi o poziomie DEBUG przy rzeczywistym ruchu zużywa zasoby CPU i powoduje wzrost kosztów przechowywania dzienników. Domyślnie ustaw środowiska produkcyjne na poziom INFO lub WARN, a tylko tymczasowo zwiększ poziom szczegółowości, gdy jest to faktycznie konieczne.

Odrzucanie szczegółów błędu: Unikaj sytuacji, w których łapiesz błąd i rejestrujesz tylko zwykły ciąg znaków, ponieważ w ten sposób tracisz sam obiekt błędu oraz jego ślad stosu. Zamiast tego zawsze przekazuj pełny obiekt błędu do funkcji logowania, na przykład logger.error({ err }, "Nie udało się zapisać danych"), aby nic nie zostało utracone.

Wprowadzanie możliwości obserwacji do kodu

Zastosowanie solidnych nawyków logowania zmienia sposób, w jaki postrzegasz systemy produkcyjne. Zamiast traktować aplikację jako coś, od czego po prostu oczekujesz prawidłowego działania, zaczynasz traktować ją jako żywy proces, który jest zobowiązany udzielić wyjaśnienia, gdy coś pójdzie nie tak.

Aby to osiągnąć, nie wymaga to dużego wysiłku na początku: sformatuj logi w formacie JSON, oznacz każdą przychodzącą prośbę identyfikatorem korelacji oraz zapisz istotne zmienne w momencie wykrycia błędu. Następnym razem, gdy w środowisku produkcyjnym pojawi się nieoczekiwany błąd, dzięki temu przygotowaniu będziesz mógł poświęcić czas na jego naprawę, zamiast zgadywać, co się stało.

Powiązane materiały

• Tworzenie systemu obsługi błędów na poziomie produkcyjnym w aplikacjach Node.js — Dowiedz się, jak klasyfikować błędy w Node.js, zaprojektować spersonalizowaną hierarchię błędów, zcentralizować obsługę błędów asynchronicznych oraz chronić ślady wywołań dla odporności aplikacji w produkcji.

Znajdowanie rzeczywistego wąskiego gardła w spowolnionym endpointie Node.js — Poznaj systematyczną metodę śledzenia opóźnień w backendzie wzdłuż ścieżki żądania — od kodu Node.js po zapytania do bazy danych — przy użyciu pomiarów czasu i EXPLAIN ANALYZE.

Wzory strukturyzowanego logowania do skutecznego debuggowania API Node.js — Dowiedz się, jak zastąpić rozproszone wywołania console.log strukturyzowanym logowaniem, identyfikatorami żądań, poziomami logów oraz metrykami czasowymi, aby szybciej debugować API Node.js.

Budowanie API w Node.js z obsługą Observable: logowanie, metryki i tracing — Dowiedz się, jak strukturyzowane logowanie, śledzenie zapytań, metryki oraz zdyscyplinowane systemy powiadamiania łączą się, aby znacznie uprościć debugowanie API w Node.js w środowisku produkcyjnym.