Error Logging - Chronicle of Failures

It is three in the morning and tribute payments "sometimes" fail. The console holds thousands of console.log lines with no date and no module, mixed together from ten requests, and the stack trace vanished when the container restarted. Error Logging is not just writing errors down; it is the art of documenting every incident so that future legions can learn from it.

In a Roman castrum any incident can be crucial: a breach in the walls, a conflict in the ranks, a small shortfall in the treasury. So Consul Caesar.js appoints you chronicler. A good chronicle means a severity level, fields you can filter on and an identifier that ties together the entries of one request.

Levels - from a whisper to an alarm

NestJS knows six levels, from the least to the most urgent: verbose, debug, log, warn, error and fatal. Enabling one level also enables every more severe one.

Underneath works the Winston library, which numbers them the other way round: error is 0, warn 1, info 2, down to silly, and it has no fatal level at all.

Winston and transports

Winston is a library for advanced logging: one entry goes at once to many transports, that is the console, files, an HTTP endpoint or an external service that collects logs. We build the chronicle as a service implementing the LoggerService interface from NestJS. The constructor receives ConfigService, reads the level from it and assembles the logger with 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() builds the format from steps run in order: timestamp() adds the date, errors({ stack: true }) keeps the stack trace, legionFields() adds the legion fields and json() turns the entry into a single JSON line. You change the level through LOG_LEVEL, without rebuilding the application.

Legion fields and the console

A custom format step is created with winston.format(): it receives the entry object info (type TransformableInfo), may change it and must return it. That is how the legion fields and the console format come about:

1  // Every entry gets the legion fields and the request ID
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 for development - colours and one line per entry
19    return new winston.transports.Console({
20      format: winston.format.combine(
21        winston.format.colorize(),
22        winston.format.printf(this.consoleFormat),
23      ),
24    });
25  }

The trace field that NestJS passes with errors becomes stack. The console gets a coloured one-line version, while JSON stays in the files that machines read.

Files that change by themselves

The DailyRotateFile transport from the winston-daily-rotate-file package starts a new file every day according to datePattern and deletes old ones by itself once they exceed maxFiles. The third file also gets a filter, that is a format step returning false for ordinary entries:

1  private fileTransports() {
2    // Only entries flagged as urgent reach the critical file
3    const onlyCritical = winston.format((info) =>
4      info.requiresAttention ? info : false,
5    );
6
7    return [
8      // Rotating files for 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      // A separate file for errors
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 requiring immediate attention
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 splits a file that grows too big on the same day, and level: 'error' lets only errors into the second file. The first version of this chronicle had level: 'fatal' here, and since Winston knows no such level, not a single entry reached the file.

Entries with context

The logWithContext() method passes one object to this.winston.log(): level, message, context and metadata. The domain methods rely on it:

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  }

The domain methods only assemble metadata. You find every security incident with one filter on category, and the requiresAttention flag sends the serious ones to the critical file.

The contract with NestJS

The LoggerService interface requires the log, error and warn methods; debug, verbose and fatal are optional:

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 has no fatal level - this is the most serious error, flagged as urgent
23    this.winston.error(message, { context, requiresAttention: true });
24  }
25}

NestJS calls error(message, trace, context): the second argument is the stack trace, the third the class name. fatal() becomes an error flagged as urgent, so it also lands in the critical file.

One identifier per request

The first version of the chronicle drew a random requestId for every line, so the entries of one request never matched. We assign the identifier once, as a UUID from randomUUID(), and keep it in AsyncLocalStorage from Node.js - a store visible to the whole chain of calls. The whole thing is an ordinary Express middleware:

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 ?? 'no-request';
16}

requestStore.run() opens the store and only inside it calls next(), so the controller, the services and every await see the same identifier. The client receives it in the X-Request-Id header, so when reporting a bug they can give you the page number in the chronicle.

Plugging in the chronicle

You register the service in a module as a provider and replace the default logger with it:

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 holds back the startup entries until you plug in your own logger, and app.get() takes it from the container. That is why useLogger comes right after create: every following configuration step, such as registering filters, already logs to the chronicle.

Tracking errors

Logs tell you what happened, and ErrorTrackingService counts what repeats. It receives the chronicle and the TypeORM DataSource for SQL queries:

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  }

An error becomes a record with a severity and a fingerprint, goes to the chronicle and the database, and a CRITICAL one raises the alarm.

Severity and fingerprint come from two helper methods:

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  }

Losing the database is CRITICAL, a server or security error is HIGH, a client error is MEDIUM. The fingerprint is an MD5 digest computed with createHash from node:crypto; it only serves grouping, not data protection, so fast MD5 is enough.

The record goes into the error_logs table through a parameterised query:

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  }

The $1-$10 placeholders instead of string concatenation protect against SQL injection, and an error message is often a copy of user input.

Finally, statistics for a chosen period:

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    // Plug in Slack, e-mail or PagerDuty here
39  }
40}

COUNT(*) tells you how many times errors occurred, and COUNT(DISTINCT fingerprint) how many different ones there were. A good chronicle does not only document events, it lets you foresee problems: an error that shows up more often every week becomes visible before the alarm.

The chronicler's advice

I recommend one rule: in services log through the NestJS Logger, and let Winston stay a configuration detail you can replace without touching the code. Never write passwords or tokens to the chronicle. In the next lesson the chronicle will serve health checks, and in the deployment module we will gather the chronicles of many instances in one place.

Remember: a wise centurion learns from the mistakes of others, but the best one learns from his own well-kept chronicle.

1// Error Logging - Chronicle of the Imperium's Failures
2// Structured logging with levels and context
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  // Log levels: 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    // Color formatting
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  // Get recent logs
67  getRecentLogs(count: number = 10) {
68    return this.logs.slice(-count);
69  }
70
71  // Filter by level
72  getLogsByLevel(level: string) {
73    return this.logs.filter(l => l.level === level);
74  }
75}
76
77// ===========================================
78// 2. Usage in a 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('Collecting tribute from ' + province + ': ' + amount);
87
88    try {
89      if (amount <= 0) {
90        this.logger.warn('Attempt to collect a zero tribute!');
91        throw new Error('The amount must be positive');
92      }
93
94      this.logger.log('Tribute collected successfully');
95      return { province, amount, collected: true };
96    } catch (error) {
97      this.logger.error('Error while collecting tribute: ' + error.message);
98      throw error;
99    }
100  }
101}
102
103console.log('=== Error Logging ===');
104console.log('Levels: log < debug < warn < error < fatal');
105console.log('Logger("Context") - logger with context');
106console.log('Custom LoggerService - custom implementation');
107console.log('Each entry: level, message, context, timestamp');
108