Error Logging - kronika niepowodzeń

Trzecia w nocy, a płatności tributów „czasem” nie przechodzą. W konsoli tysiące linijek console.log bez daty i modułu, przemieszanych z dziesięciu żądań, a stack trace zniknął z restartem kontenera. Error Logging to nie tylko zapisywanie błędów, to sztuka dokumentowania każdego incydentu tak, aby przyszłe legiony mogły się z niego uczyć.

W rzymskim kastrum każdy incydent bywa kluczowy: wyłom w murach, konflikt w szeregach, drobny niedobór w skarbcu. Konsul Caesar.js mianuje Cię więc kronikarzem. Dobra kronika to poziom ważności, pola do filtrowania i identyfikator łączący wpisy jednego żądania.

Poziomy - od szeptu do alarmu

NestJS zna sześć poziomów, od najmniej do najbardziej pilnego: verbose, debug, log, warn, error i fatal. Włączenie jednego poziomu włącza też wszystkie poważniejsze od niego.

Pod spodem pracuje biblioteka Winston, która numeruje odwrotnie: error ma 0, warn 1, info 2, aż do silly, a poziomu fatal nie ma wcale.

Winston i transporty

Winston to biblioteka do zaawansowanego logowania: jeden wpis trafia naraz do wielu transportów, czyli konsoli, plików, endpointu HTTP albo zewnętrznego serwisu zbierającego logi. Kronikę budujemy jako serwis implementujący interfejs LoggerService z NestJS. Konstruktor dostaje ConfigService, z którego czyta poziom, i składa logger funkcją winston.createLogger():

1// logging/legionary-logger.service.ts
2import { Injectable, LoggerService } from '@nestjs/common';
3import { ConfigService } from '@nestjs/config';
4import * as winston from 'winston';
5import DailyRotateFile from 'winston-daily-rotate-file';
6import { getRequestId } from './request-context';
7
8@Injectable()
9export class LegionaryLoggerService implements LoggerService {
10  private readonly winston: winston.Logger;
11  private readonly context: string = 'Legionary';
12
13  constructor(private configService: ConfigService) {
14    this.winston = winston.createLogger({
15      level: this.configService.get('LOG_LEVEL', 'info'),
16      format: winston.format.combine(
17        winston.format.timestamp(),
18        winston.format.errors({ stack: true }),
19        this.legionFields(),
20        winston.format.json(),
21      ),
22      transports: [this.consoleTransport(), ...this.fileTransports()],
23    });
24  }

winston.format.combine() składa format z kroków wykonywanych po kolei: timestamp() dopisuje datę, errors({ stack: true }) zachowuje stack trace, legionFields() dokłada pola legionu, a json() zamienia wpis w jedną linię JSON. Poziom zmienisz przez LOG_LEVEL, bez przebudowy aplikacji.

Pola legionu i konsola

Własny krok formatu tworzy winston.format(): dostaje obiekt wpisu info (typ TransformableInfo), może go zmienić i musi go zwrócić. Tak powstają pola legionu i format konsoli:

1  // Każdy wpis dostaje pola legionu i identyfikator żądania
2  private legionFields = winston.format((info) => {
3    info.cohort = 'Equus Niger';
4    info.centurion = 'Caesar.js';
5    info.context = info.context || this.context;
6    info.requestId = getRequestId();
7    if (info.trace) {
8      info.stack = info.trace;
9      delete info.trace;
10    }
11    return info;
12  });
13
14  private consoleFormat = (info: winston.Logform.TransformableInfo) =>
15    `${info.timestamp} [${info.context}] ${info.level}: ${info.message}`;
16
17  private consoleTransport() {
18    // Konsola dla developmentu - kolory i jedna linijka na wpis
19    return new winston.transports.Console({
20      format: winston.format.combine(
21        winston.format.colorize(),
22        winston.format.printf(this.consoleFormat),
23      ),
24    });
25  }

Pole trace, które NestJS przekazuje przy błędach, staje się stack. Konsola dostaje kolorową, jednolinijkową wersję, a JSON zostaje dla plików czytanych przez maszyny.

Pliki, które zmieniają się same

Transport DailyRotateFile z pakietu winston-daily-rotate-file każdego dnia zaczyna nowy plik według datePattern i sam usuwa stare, gdy przekroczą maxFiles. Trzeci plik dostaje dodatkowo filtr, czyli krok formatu zwracający false dla zwykłych wpisów:

1  private fileTransports() {
2    // Do pliku krytycznego trafiają tylko wpisy oznaczone jako pilne
3    const onlyCritical = winston.format((info) =>
4      info.requiresAttention ? info : false,
5    );
6
7    return [
8      // Pliki rotacyjne dla produkcji
9      new DailyRotateFile({
10        filename: 'logs/legionariusze-cohort-%DATE%.log',
11        datePattern: 'YYYY-MM-DD',
12        maxFiles: '30d',
13        maxSize: '100m',
14        level: 'info',
15      }),
16      // Oddzielny plik dla błędów
17      new DailyRotateFile({
18        filename: 'logs/legionariusze-errors-%DATE%.log',
19        datePattern: 'YYYY-MM-DD',
20        maxFiles: '90d',
21        maxSize: '100m',
22        level: 'error',
23      }),
24      // Incydenty wymagające natychmiastowej uwagi
25      new DailyRotateFile({
26        filename: 'logs/legionariusze-critical-%DATE%.log',
27        datePattern: 'YYYY-MM-DD',
28        maxFiles: '365d',
29        level: 'warn',
30        format: onlyCritical(),
31      }),
32    ];
33  }

maxSize dzieli zbyt duży plik tego samego dnia, a level: 'error' wpuszcza do drugiego pliku tylko błędy. Pierwsza wersja tej kroniki miała tu level: 'fatal', a skoro Winston nie zna takiego poziomu, do pliku nie trafiał żaden wpis.

Wpisy z kontekstem

Metoda logWithContext() przekazuje do this.winston.log() jeden obiekt: poziom, treść, kontekst i metadane. Opierają się na niej metody dziedzinowe:

1  logWithContext(level: string, message: string, context: string, metadata: Record<string, unknown> = {}) {
2    this.winston.log({ level, message, context, ...metadata });
3  }
4
5  logLegionActivity(activity: string, legionariusze: any, details?: any) {
6    this.logWithContext('info', 'Legion Activity', 'LegionManagement', {
7      activity,
8      legionariusze: {
9        name: legionariusze.name,
10        rank: legionariusze.rank,
11        id: legionariusze.id,
12      },
13      details,
14      category: 'legion_activity',
15    });
16  }
17
18  logTributeOperation(operation: string, tribute: any, legionariusze: any, result?: any) {
19    this.logWithContext('info', 'Tribute Operation', 'TributeManagement', {
20      operation,
21      tribute: { id: tribute.id, name: tribute.name, value: tribute.value },
22      legionariusze: { name: legionariusze.name, rank: legionariusze.rank },
23      result,
24      category: 'tribute_operation',
25    });
26  }
27
28  logSecurityIncident(incident: string, severity: 'LOW' | 'MEDIUM' | 'HIGH' | 'CRITICAL', details: any) {
29    const logLevel = severity === 'CRITICAL' ? 'error' :
30      severity === 'HIGH' ? 'warn' : 'info';
31
32    this.logWithContext(logLevel, 'Security Incident', 'Security', {
33      incident,
34      severity,
35      details,
36      category: 'security_incident',
37      requiresAttention: severity === 'CRITICAL' || severity === 'HIGH',
38    });
39  }

Metody dziedzinowe tylko składają metadane. Wszystkie incydenty bezpieczeństwa znajdziesz jednym filtrem po category, a flaga requiresAttention kieruje poważne do pliku krytycznego.

Kontrakt z NestJS

Interfejs LoggerService wymaga metod log, error i warn; metody debug, verbose i fatal są opcjonalne:

1  log(message: string, context?: string) {
2    this.winston.info(message, { context });
3  }
4
5  error(message: string, trace?: string, context?: string) {
6    this.winston.error(message, { trace, context });
7  }
8
9  warn(message: string, context?: string) {
10    this.winston.warn(message, { context });
11  }
12
13  debug(message: string, context?: string) {
14    this.winston.debug(message, { context });
15  }
16
17  verbose(message: string, context?: string) {
18    this.winston.verbose(message, { context });
19  }
20
21  fatal(message: string, context?: string) {
22    // winston nie ma poziomu fatal - to najpoważniejszy error z flagą pilności
23    this.winston.error(message, { context, requiresAttention: true });
24  }
25}

NestJS woła error(message, trace, context): drugi argument to stack trace, trzeci - nazwa klasy. fatal() staje się błędem z flagą pilności, więc trafia także do pliku krytycznego.

Jeden identyfikator na żądanie

Pierwsza wersja kroniki losowała requestId przy każdej linijce, więc wpisy jednego żądania do siebie nie pasowały. Identyfikator nadajemy raz, jako UUID z randomUUID(), i trzymamy w AsyncLocalStorage z Node.js - schowku widocznym dla całego łańcucha wywołań. Całość to zwykły middleware Express:

1// logging/request-context.ts
2import { AsyncLocalStorage } from 'node:async_hooks';
3import { randomUUID } from 'node:crypto';
4import { NextFunction, Request, Response } from 'express';
5
6const requestStore = new AsyncLocalStorage<{ requestId: string }>();
7
8export function requestContextMiddleware(req: Request, res: Response, next: NextFunction) {
9  const requestId = randomUUID();
10  res.setHeader('X-Request-Id', requestId);
11  requestStore.run({ requestId }, () => next());
12}
13
14export function getRequestId(): string {
15  return requestStore.getStore()?.requestId ?? 'poza-żądaniem';
16}

requestStore.run() otwiera schowek i dopiero w nim woła next(), więc kontroler, serwisy i każdy await widzą ten sam identyfikator. Klient dostaje go w nagłówku X-Request-Id, więc zgłaszając błąd, poda Ci numer strony w kronice.

Podłączenie kroniki

Serwis rejestrujesz w module jako provider i zastępujesz nim domyślny logger:

1// main.ts
2import { NestFactory } from '@nestjs/core';
3import { AppModule } from './app.module';
4import { LegionaryLoggerService } from './logging/legionary-logger.service';
5import { requestContextMiddleware } from './logging/request-context';
6
7async function bootstrap() {
8  const app = await NestFactory.create(AppModule, { bufferLogs: true });
9
10  app.useLogger(app.get(LegionaryLoggerService));
11  app.use(requestContextMiddleware);
12
13  await app.listen(3000);
14}
15bootstrap();

bufferLogs: true wstrzymuje wpisy z uruchamiania, aż podłączysz własny logger, a app.get() pobiera go z kontenera. Dlatego useLogger stoi zaraz po create: każdy kolejny krok konfiguracji, choćby rejestracja filtrów, loguje już do kroniki.

Śledzenie błędów

Logi opowiadają, co się działo, a ErrorTrackingService liczy, co się powtarza. Dostaje kronikę i DataSource z TypeORM do zapytań SQL:

1// services/error-tracking.service.ts
2import { Injectable } from '@nestjs/common';
3import { createHash } from 'node:crypto';
4import { DataSource } from 'typeorm';
5import { LegionaryLoggerService } from '../logging/legionary-logger.service';
6
7@Injectable()
8export class ErrorTrackingService {
9  constructor(
10    private logger: LegionaryLoggerService,
11    private dataSource: DataSource
12  ) {}
13
14  async trackError(error: any, context: any = {}) {
15    const errorRecord = {
16      timestamp: new Date(),
17      message: error.message,
18      stack: error.stack,
19      name: error.name,
20      code: error.code,
21      context,
22      severity: this.determineSeverity(error),
23      fingerprint: this.generateFingerprint(error),
24      environment: process.env.NODE_ENV,
25      version: process.env.APP_VERSION || '1.0.0'
26    };
27
28    this.logger.logWithContext('error', 'Error Tracked', 'ErrorTracking', {
29      errorRecord,
30      requiresAttention: errorRecord.severity === 'CRITICAL'
31    });
32
33    await this.saveErrorToDatabase(errorRecord);
34
35    if (errorRecord.severity === 'CRITICAL') {
36      await this.sendCriticalErrorAlert(errorRecord);
37    }
38
39    return errorRecord;
40  }

Błąd staje się rekordem z powagą i odciskiem, trafia do kroniki i bazy, a przy CRITICAL uruchamia alarm.

Powagę i odcisk wyznaczają dwie metody pomocnicze:

1  private determineSeverity(error: any): 'LOW' | 'MEDIUM' | 'HIGH' | 'CRITICAL' {
2    if (error.name === 'DatabaseConnectionError' ||
3        error.message?.includes('ECONNREFUSED') ||
4        error.code === 'COHORT_BREAKING') {
5      return 'CRITICAL';
6    }
7
8    if (error.status >= 500 ||
9        error.name === 'UnauthorizedError' ||
10        error.code?.startsWith('SECURITY_')) {
11      return 'HIGH';
12    }
13
14    if (error.status >= 400 ||
15        error.name === 'ValidationError') {
16      return 'MEDIUM';
17    }
18
19    return 'LOW';
20  }
21
22  private generateFingerprint(error: any): string {
23    const signature = `${error.name}:${error.message}:${error.code || 'no-code'}`;
24    return createHash('md5').update(signature).digest('hex');
25  }

Utrata bazy to CRITICAL, błąd serwera lub bezpieczeństwa - HIGH, błąd klienta - MEDIUM. Odcisk to skrót MD5 liczony przez createHash z node:crypto; służy tylko do grupowania, nie do ochrony danych, więc szybki MD5 wystarcza.

Rekord trafia do tabeli error_logs zapytaniem z parametrami:

1  private async saveErrorToDatabase(errorRecord: any) {
2    await this.dataSource.query(`
3      INSERT INTO error_logs (
4        timestamp, message, stack, error_type, error_code,
5        context, severity, fingerprint, environment, version
6      ) VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10)
7    `, [
8      errorRecord.timestamp,
9      errorRecord.message,
10      errorRecord.stack,
11      errorRecord.name,
12      errorRecord.code,
13      JSON.stringify(errorRecord.context),
14      errorRecord.severity,
15      errorRecord.fingerprint,
16      errorRecord.environment,
17      errorRecord.version
18    ]);
19  }

Znaczniki $1-$10 zamiast sklejania tekstu chronią przed SQL injection, a treść błędu bywa kopią danych od użytkownika.

Na koniec statystyki z wybranego okresu:

1  async getErrorStatistics(timeframe: 'hour' | 'day' | 'week' | 'month' = 'day') {
2    const since = this.getTimeframeCutoff(timeframe);
3
4    const stats = await this.dataSource.query(`
5      SELECT
6        error_type,
7        severity,
8        COUNT(*) as occurrence_count,
9        COUNT(DISTINCT fingerprint) as unique_errors,
10        MIN(timestamp) as first_occurrence,
11        MAX(timestamp) as last_occurrence
12      FROM error_logs
13      WHERE timestamp >= $1
14      GROUP BY error_type, severity
15      ORDER BY occurrence_count DESC
16    `, [since]);
17
18    return stats;
19  }
20
21  private getTimeframeCutoff(timeframe: string): Date {
22    const now = new Date();
23    switch (timeframe) {
24      case 'hour':
25        return new Date(now.getTime() - 60 * 60 * 1000);
26      case 'day':
27        return new Date(now.getTime() - 24 * 60 * 60 * 1000);
28      case 'week':
29        return new Date(now.getTime() - 7 * 24 * 60 * 60 * 1000);
30      case 'month':
31        return new Date(now.getTime() - 30 * 24 * 60 * 60 * 1000);
32      default:
33        return new Date(now.getTime() - 24 * 60 * 60 * 1000);
34    }
35  }
36
37  private async sendCriticalErrorAlert(errorRecord: any) {
38    // Tu podłączysz Slacka, e-mail albo PagerDuty
39  }
40}

COUNT(*) mówi, ile razy błędy wystąpiły, a COUNT(DISTINCT fingerprint) - ile było różnych. Dobra kronika nie tylko dokumentuje wydarzenia, ale pozwala przewidywać problemy: błąd, który co tydzień pojawia się częściej, zobaczysz przed alarmem.

Rada kronikarza

Polecam jedną zasadę: w serwisach loguj przez Logger z NestJS, a Winston niech zostanie szczegółem konfiguracji, który wymienisz bez dotykania kodu. Nie zapisuj w kronice haseł ani tokenów. W następnej lekcji kronika posłuży health checkom, a w module o wdrożeniach zbierzemy kroniki wielu instancji w jednym miejscu.

Pamiętaj: mądry centurion uczy się na błędach innych, ale najlepszy uczy się na własnej, dobrze prowadzonej kronice.

1// Error Logging - Kronika Niepowodzen Imperium
2// Strukturalne logowanie z poziomami i kontekstem
3import { Injectable, Logger, LoggerService, LogLevel } from '@nestjs/common';
4
5// ===========================================
6// 1. Custom Logger Service
7// ===========================================
8
9@Injectable()
10export class LegionaryLoggerService implements LoggerService {
11  private context: string = 'Imperium';
12  private logs: Array<{
13    level: string;
14    message: string;
15    context: string;
16    timestamp: string;
17  }> = [];
18
19  // Poziomy logow: log < debug < warn < error < fatal
20  log(message: string, context?: string) {
21    this.writeLog('LOG', message, context);
22  }
23
24  error(message: string, trace?: string, context?: string) {
25    this.writeLog('ERROR', message, context);
26    if (trace) {
27      console.error('Stack trace:', trace);
28    }
29  }
30
31  warn(message: string, context?: string) {
32    this.writeLog('WARN', message, context);
33  }
34
35  debug(message: string, context?: string) {
36    this.writeLog('DEBUG', message, context);
37  }
38
39  verbose(message: string, context?: string) {
40    this.writeLog('VERBOSE', message, context);
41  }
42
43  private writeLog(level: string, message: string, context?: string) {
44    const timestamp = new Date().toISOString();
45    const ctx = context || this.context;
46
47    const logEntry = { level, message, context: ctx, timestamp };
48    this.logs.push(logEntry);
49
50    // Formatowanie kolorowe
51    const prefix = '[' + ctx + ']';
52    const time = timestamp.split('T')[1].split('.')[0];
53
54    switch (level) {
55      case 'ERROR':
56        console.error(time + ' ' + prefix + ' ERROR: ' + message);
57        break;
58      case 'WARN':
59        console.warn(time + ' ' + prefix + ' WARN: ' + message);
60        break;
61      default:
62        console.log(time + ' ' + prefix + ' ' + level + ': ' + message);
63    }
64  }
65
66  // Pobierz ostatnie logi
67  getRecentLogs(count: number = 10) {
68    return this.logs.slice(-count);
69  }
70
71  // Filtruj po poziomie
72  getLogsByLevel(level: string) {
73    return this.logs.filter(l => l.level === level);
74  }
75}
76
77// ===========================================
78// 2. Uzycie w serwisie
79// ===========================================
80
81@Injectable()
82export class TributeService {
83  private logger = new Logger('TributeService');
84
85  collectTribute(province: string, amount: number) {
86    this.logger.log('Zbieranie tributu z ' + province + ': ' + amount);
87
88    try {
89      if (amount <= 0) {
90        this.logger.warn('Proba zebrania zerowego tributu!');
91        throw new Error('Kwota musi byc dodatnia');
92      }
93
94      this.logger.log('Tribute zebrany pomyslnie');
95      return { province, amount, collected: true };
96    } catch (error) {
97      this.logger.error('Blad przy zbieraniu tributu: ' + error.message);
98      throw error;
99    }
100  }
101}
102
103console.log('=== Error Logging ===');
104console.log('Poziomy: log < debug < warn < error < fatal');
105console.log('Logger("Context") - logger z kontekstem');
106console.log('Custom LoggerService - wlasna implementacja');
107console.log('Kazdy wpis: level, message, context, timestamp');
108