Error Logging - La chronique des défaillances

Il est trois heures du matin et les paiements des tributs échouent « parfois ». La console contient des milliers de lignes console.log sans date ni module, mélangées entre dix requêtes, et la pile d'appels a disparu au redémarrage du conteneur. L'Error Logging, ce n'est pas seulement noter les erreurs : c'est l'art de documenter chaque incident pour que les futures légions puissent en tirer des leçons.

Dans un castrum romain, chaque incident peut être décisif : une brèche dans les murs, un conflit dans les rangs, un petit manque dans le trésor. Le consul Caesar.js te nomme donc chroniqueur. Une bonne chronique, c'est un niveau de gravité, des champs filtrables et un identifiant qui relie les entrées d'une même requête.

Les niveaux - du murmure à l'alarme

NestJS connaît six niveaux, du moins urgent au plus urgent : verbose, debug, log, warn, error et fatal. Activer un niveau active aussi tous les niveaux plus graves.

En dessous travaille la bibliothèque Winston, qui numérote dans l'autre sens : error vaut 0, warn 1, info 2, jusqu'à silly, et elle n'a aucun niveau fatal.

Winston et les transports

Winston est une bibliothèque de logging avancé : une entrée part en même temps vers plusieurs transports, c'est-à-dire la console, des fichiers, un endpoint HTTP ou un service externe qui collecte les logs. On construit la chronique comme un service qui implémente l'interface LoggerService de NestJS. Le constructeur reçoit ConfigService, y lit le niveau et assemble le logger avec 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() compose le format à partir d'étapes exécutées dans l'ordre : timestamp() ajoute la date, errors({ stack: true }) conserve la pile d'appels, legionFields() ajoute les champs de la légion et json() transforme l'entrée en une seule ligne JSON. Tu changes le niveau avec LOG_LEVEL, sans reconstruire l'application.

Les champs de la légion et la console

Une étape de format personnalisée se crée avec winston.format() : elle reçoit l'objet d'entrée info (type TransformableInfo), peut le modifier et doit le renvoyer. C'est ainsi que naissent les champs de la légion et le format de la console :

1  // Chaque entrée reçoit les champs de la légion et l'identifiant de la requête
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    // Console pour le développement - couleurs et une ligne par entrée
19    return new winston.transports.Console({
20      format: winston.format.combine(
21        winston.format.colorize(),
22        winston.format.printf(this.consoleFormat),
23      ),
24    });
25  }

Le champ trace que NestJS transmet avec les erreurs devient stack. La console reçoit une version colorée sur une ligne, tandis que le JSON reste dans les fichiers lus par les machines.

Des fichiers qui changent tout seuls

Le transport DailyRotateFile du paquet winston-daily-rotate-file commence chaque jour un nouveau fichier selon datePattern et supprime lui-même les anciens quand ils dépassent maxFiles. Le troisième fichier reçoit en plus un filtre, c'est-à-dire une étape de format qui renvoie false pour les entrées ordinaires :

1  private fileTransports() {
2    // Seules les entrées marquées comme urgentes vont dans le fichier critique
3    const onlyCritical = winston.format((info) =>
4      info.requiresAttention ? info : false,
5    );
6
7    return [
8      // Fichiers rotatifs pour la production
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      // Un fichier séparé pour les erreurs
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      // Incidents exigeant une attention immédiate
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 découpe un fichier devenu trop gros le jour même, et level: 'error' ne laisse entrer que les erreurs dans le deuxième fichier. La première version de cette chronique mettait ici level: 'fatal', et comme Winston ne connaît pas ce niveau, aucune entrée n'arrivait dans le fichier.

Des entrées avec contexte

La méthode logWithContext() passe un seul objet à this.winston.log() : niveau, message, contexte et métadonnées. Les méthodes métier s'appuient sur elle :

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  }

Les méthodes métier se contentent d'assembler les métadonnées. Tu retrouves tous les incidents de sécurité avec un seul filtre sur category, et le drapeau requiresAttention envoie les plus graves dans le fichier critique.

Le contrat avec NestJS

L'interface LoggerService exige les méthodes log, error et warn ; debug, verbose et fatal sont facultatives :

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 n'a pas de niveau fatal - c'est l'error la plus grave, marquée comme urgente
23    this.winston.error(message, { context, requiresAttention: true });
24  }
25}

NestJS appelle error(message, trace, context) : le deuxième argument est la pile d'appels, le troisième le nom de la classe. fatal() devient une erreur marquée comme urgente, elle arrive donc aussi dans le fichier critique.

Un identifiant par requête

La première version de la chronique tirait un requestId au hasard pour chaque ligne, si bien que les entrées d'une même requête ne correspondaient jamais. On attribue l'identifiant une seule fois, sous forme d'UUID avec randomUUID(), et on le garde dans AsyncLocalStorage de Node.js - un espace de stockage visible par toute la chaîne d'appels. Le tout est un middleware Express ordinaire :

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 ?? 'hors-requete';
16}

requestStore.run() ouvre l'espace de stockage et n'appelle next() qu'à l'intérieur, donc le contrôleur, les services et chaque await voient le même identifiant. Le client le reçoit dans l'en-tête X-Request-Id : en signalant un bug, il te donnera le numéro de page de la chronique.

Brancher la chronique

Tu enregistres le service comme provider dans un module et tu remplaces le logger par défaut avec lui :

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 retient les entrées du démarrage jusqu'à ce que tu branches ton propre logger, et app.get() le récupère dans le conteneur. C'est pourquoi useLogger vient juste après create : chaque étape de configuration suivante, comme l'enregistrement des filtres, écrit déjà dans la chronique.

Suivre les erreurs

Les logs racontent ce qui s'est passé, et ErrorTrackingService compte ce qui se répète. Il reçoit la chronique et le DataSource de TypeORM pour les requêtes 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  }

Une erreur devient un enregistrement avec une gravité et une empreinte, part dans la chronique et dans la base, et une erreur CRITICAL déclenche l'alarme.

La gravité et l'empreinte viennent de deux méthodes utilitaires :

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  }

Perdre la base, c'est CRITICAL, une erreur serveur ou de sécurité, HIGH, une erreur client, MEDIUM. L'empreinte est un condensé MD5 calculé par createHash de node:crypto ; elle ne sert qu'à regrouper, pas à protéger des données, donc un MD5 rapide suffit.

L'enregistrement arrive dans la table error_logs par une requête paramétrée :

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  }

Les marqueurs $1-$10 au lieu de la concaténation de texte protègent contre l'injection SQL, et le message d'une erreur est souvent une copie des données de l'utilisateur.

Enfin, les statistiques pour une période choisie :

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    // Branche ici Slack, un e-mail ou PagerDuty
39  }
40}

COUNT(*) indique combien de fois des erreurs sont survenues, et COUNT(DISTINCT fingerprint) combien d'erreurs différentes il y a eu. Une bonne chronique ne se contente pas de documenter les événements, elle permet d'anticiper les problèmes : une erreur qui revient plus souvent chaque semaine devient visible avant l'alarme.

Le conseil du chroniqueur

Je te recommande une règle : dans les services, écris les logs avec le Logger de NestJS et laisse Winston rester un détail de configuration que tu pourras remplacer sans toucher au code. N'écris jamais de mots de passe ni de jetons dans la chronique. Dans la prochaine leçon, la chronique servira aux health checks, et dans le module sur les déploiements nous rassemblerons les chroniques de plusieurs instances en un seul endroit.

Retiens : un centurion avisé apprend des erreurs des autres, mais le meilleur apprend de sa propre chronique, bien tenue.

1// Error Logging - Kronika Niepowodzen Imperium
2// Logging structuré avec niveaux et contexte
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  // Niveaux de logs : 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    // Formatage coloré
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  // Récupérer les logs récents
67  getRecentLogs(count: number = 10) {
68    return this.logs.slice(-count);
69  }
70
71  // Filtrer par niveau
72  getLogsByLevel(level: string) {
73    return this.logs.filter(l => l.level === level);
74  }
75}
76
77// ===========================================
78// 2. Utilisation dans un service
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 must be dodatnia');
92      }
93
94      this.logger.log('Tribute zebrany pomyslnie');
95      return { province, amount, collected: true };
96    } catch (error) {
97      this.logger.error('Error przy zbieraniu tributu: ' + error.message);
98      throw error;
99    }
100  }
101}
102
103console.log('=== Error Logging ===');
104console.log('Niveaux : log < debug < warn < error < fatal');
105console.log('Logger("Context") - logger avec contexte');
106console.log('Custom LoggerService - implémentation personnalisée');
107console.log('Chaque entrée : level, message, context, timestamp');
108