Debugging Techniques - rozwiązywanie problemów

Serwis zwraca zły wynik i nie wiadomo dlaczego. Wstawiasz console.log przed podejrzaną linią, restartujesz, patrzysz. Za mało - dokładasz drugi. I trzeci. Po kwadransie masz kilkanaście wydruków, konsolę pełną śmieci i wciąż nie wiesz, w którym miejscu wartość się psuje. Potem połowa tych wydruków zostaje w kodzie na zawsze.

Zwiadowca legionu nie działa po omacku. Ma drabinę narzędzi: najpierw patrzy z obozu, potem wysyła patrol, a gdy trzeba - zatrzymuje marsz i bada teren krok po kroku. Ta lekcja ustawia taką drabinę dla Twojego kodu.

Drabina narzędzi

Cztery szczeble, od wbudowanych po zewnętrzne:

1. NestJS Logger - wbudowany, zawsze pod ręką. Pokazuje, co się stało, ale nie zatrzymuje programu.
2. Node.js Inspector - uruchamiany flagą --inspect, pozwala zatrzymać program i obejrzeć jego wnętrze.
3. VS Code Debugger - ten sam mechanizm, tylko z breakpointami klikanymi w edytorze zamiast w przeglądarce.
4. Zewnętrzne APM - New Relic, Datadog i podobne. Obserwują aplikację na produkcji, gdzie żadnego breakpointa nie postawisz.

Kolejność nie jest przypadkowa: każdy kolejny szczebel kosztuje więcej przygotowania, więc wchodzisz na niego dopiero, gdy poprzedni nie wystarczył.

Szczebel pierwszy: poziomy logowania

NestJS ma wbudowany logger z pięcioma poziomami: error, warn, log, verbose, debug. W trybie deweloperskim dostępne są wszystkie - właśnie po to, żeby móc zejść głębiej bez dokładania kodu.

Poziomy wybierasz przy tworzeniu aplikacji:

1// main.ts
2async function bootstrap() {
3  const app = await NestFactory.create(AppModule, {
4    logger: ['error', 'warn', 'log', 'verbose', 'debug'],
5  });
6
7  await app.listen(3000);
8}

Tablica w opcji logger mówi, które poziomy mają być widoczne. Podanie samego ['error', 'warn'] wycisza resztę - i to jest zwykle ustawienie produkcyjne, bo debug na produkcji zalałby dyski. W development podajesz pełen zestaw.

Zwróć uwagę, że konfiguracja idzie jako drugi argument NestFactory.create, przy tworzeniu aplikacji. Nie ma metody w rodzaju app.setLogLevel() ani Logger.setLevel() - poziomy ustala się raz, na starcie.

Logger zamiast console.log

Mając poziomy, zastępujemy wydruki prawdziwym loggerem:

1@Injectable()
2export class LegionsService {
3  private readonly logger = new Logger(LegionsService.name);
4
5  async findOne(id: number) {
6    this.logger.debug(`Szukam legionu ${id}`);
7
8    const legion = await this.repo.findOne({ where: { id } });
9
10    if (!legion) {
11      this.logger.warn(`Legion ${id} nie istnieje`);
12      throw new NotFoundException();
13    }
14
15    return legion;
16  }
17}

new Logger(LegionsService.name) nadaje loggerowi kontekst - nazwę klasy, która pojawi się w każdym wpisie. Dzięki temu w konsoli widzisz, skąd pochodzi komunikat, bez dopisywania tego ręcznie do treści.

Przewaga nad console.log jest praktyczna: wpisy debug znikają same, gdy zmienisz konfigurację na produkcyjną. Nie musisz ich usuwać przed wdrożeniem ani pamiętać, gdzie je zostawiłeś - dlatego to polecam jako nawyk: nie wydruki, tylko logger z właściwym poziomem.

Szczebel drugi: Node.js Inspector

Logger pokazuje, co program zrobił. Czasem potrzebujesz zobaczyć, co robi w tej chwili - wtedy zatrzymujesz go w wybranym miejscu.

Służy do tego flaga --inspect, która włącza protokół debugowania V8 i pozwala podłączyć się do działającego procesu:

1node --inspect dist/main.js

Droga jest czterostopniowa. Uruchom aplikację z flagą --inspect. Otwórz Chrome DevTools pod adresem chrome://inspect i podłącz się do procesu. Ustaw breakpoint w kodzie - miejsce, w którym program ma się zatrzymać. Analizuj zmienne i call stack, czyli stos wywołań mówiący, którędy program tu dotarł.

Ten czwarty krok jest tym, czego console.log nie da: widzisz wszystkie zmienne w zasięgu, a nie tylko te, które wcześniej zgadłeś i wydrukowałeś. Możesz też przejść program krok po kroku i zobaczyć, w którym miejscu wartość zmienia się na złą.

Sama flaga niczego nie sprawdza ani nie uruchamia - jedynie otwiera drzwi, przez które debugger może zajrzeć do środka.

Szczeble wyżej

VS Code Debugger korzysta z tego samego protokołu, tylko breakpointy stawiasz klikając obok numeru linii, a zmienne oglądasz w panelu edytora. Nic nowego pod spodem - wygodniejsza obsługa tego samego mechanizmu.

Zewnętrzne APM rozwiązują inny problem: na produkcji nie zatrzymasz aplikacji breakpointem, bo obsługuje prawdziwy ruch. Narzędzia w rodzaju New Relic czy Datadog zbierają dane w tle - czasy odpowiedzi, wyjątki, wolne zapytania - i pozwalają dojść do przyczyny po fakcie, na podstawie tego, co zebrały.

Podsumowanie

Zwiad prowadzony po kolei, nie po omacku:

• drabina narzędzi od wbudowanych do zewnętrznych: NestJS Logger → Node.js Inspector → VS Code Debugger → zewnętrzne APM,
• logger ma pięć poziomów: error, warn, log, verbose, debug - w trybie development dostępne są wszystkie,
• poziomy ustawiasz jako drugi argument NestFactory.create(AppModule, { logger: [...] }) - nie ma setLogLevel ani Logger.setLevel,
• na produkcji zwykle ['error', 'warn'], w development pełen zestaw,
• new Logger(NazwaKlasy.name) nadaje wpisom kontekst, a wpisy debug same znikają po zmianie konfiguracji,
• flaga --inspect włącza protokół debugowania V8 i pozwala podłączyć debugger; niczego nie sprawdza ani nie uruchamia,
• cztery kroki: uruchom z --inspect, otwórz chrome://inspect, ustaw breakpoint, analizuj zmienne i call stack,
• przewaga nad wydrukami: widzisz wszystkie zmienne w zasięgu, nie tylko te zgadnięte wcześniej,
• VS Code Debugger to ten sam protokół z wygodniejszą obsługą,
• na produkcji breakpointa nie postawisz - tam pracują APM zbierające dane w tle.

W następnej lekcji zajmiemy się tym, co dzieje się przy zatrzymywaniu aplikacji - graceful shutdown, czyli zwijanie obozu bez porzucania rannych. A na razie zapamiętaj: logger mówi, co się stało; inspector pozwala zatrzymać marsz i zobaczyć, co dzieje się teraz.

1// Debugging Techniques - Rozwiazywanie Problemow w Imperium
2// Narzedzia i techniki debugowania NestJS
3import { Injectable, Logger } from '@nestjs/common';
4
5// ===========================================
6// 1. Logger jako narzedzie debugowania
7// ===========================================
8
9@Injectable()
10export class DebugService {
11  private logger = new Logger('Debug');
12
13  // Debugowanie z kontekstem
14  debugRequest(method: string, url: string, body: any) {
15    this.logger.debug('=== REQUEST DEBUG ===');
16    this.logger.debug('Method: ' + method);
17    this.logger.debug('URL: ' + url);
18    this.logger.debug('Body: ' + JSON.stringify(body, null, 2));
19    this.logger.debug('Timestamp: ' + new Date().toISOString());
20  }
21
22  // Mierzenie czasu wykonania
23  async measureExecution<T>(
24    label: string,
25    fn: () => Promise<T>,
26  ): Promise<T> {
27    const start = Date.now();
28    this.logger.debug('START: ' + label);
29
30    try {
31      const result = await fn();
32      const duration = Date.now() - start;
33      this.logger.debug('END: ' + label + ' (' + duration + 'ms)');
34      return result;
35    } catch (error) {
36      const duration = Date.now() - start;
37      this.logger.error(
38        'FAIL: ' + label + ' (' + duration + 'ms) - ' + error.message
39      );
40      throw error;
41    }
42  }
43}
44
45// ===========================================
46// 2. Interceptor do debugowania
47// ===========================================
48
49import {
50  CallHandler,
51  ExecutionContext,
52  NestInterceptor,
53} from '@nestjs/common';
54import { Observable, tap } from 'rxjs';
55
56@Injectable()
57export class DebugInterceptor implements NestInterceptor {
58  private logger = new Logger('DebugInterceptor');
59
60  intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
61    const request = context.switchToHttp().getRequest();
62    const method = request.method;
63    const url = request.url;
64    const start = Date.now();
65
66    this.logger.debug(method + ' ' + url + ' - START');
67
68    return next.handle().pipe(
69      tap({
70        next: (data) => {
71          const duration = Date.now() - start;
72          this.logger.debug(
73            method + ' ' + url + ' - ' + duration + 'ms'
74          );
75        },
76        error: (error) => {
77          const duration = Date.now() - start;
78          this.logger.error(
79            method + ' ' + url + ' - BLAD po ' + duration + 'ms: '
80            + error.message
81          );
82        },
83      }),
84    );
85  }
86}
87
88// ===========================================
89// 3. Memory leak detection
90// ===========================================
91
92function checkMemoryUsage() {
93  const usage = process.memoryUsage();
94  console.log('=== Uzycie pamieci ===');
95  console.log('RSS:       ' + Math.round(usage.rss / 1024 / 1024) + ' MB');
96  console.log('Heap Used: ' + Math.round(usage.heapUsed / 1024 / 1024) + ' MB');
97  console.log('Heap Total:' + Math.round(usage.heapTotal / 1024 / 1024) + ' MB');
98  console.log('External:  ' + Math.round(usage.external / 1024 / 1024) + ' MB');
99}
100
101checkMemoryUsage();
102
103console.log('');
104console.log('=== Debugging Techniques ===');
105console.log('Logger.debug() - szczegolowe informacje');
106console.log('measureExecution() - mierzenie czasu');
107console.log('DebugInterceptor - automatyczne logowanie requestow');
108console.log('process.memoryUsage() - sprawdzanie pamieci');
109