Debugging Techniques - solving problems

A service returns the wrong result and nobody knows why. You put a console.log before the suspect line, restart, look. Not enough - you add a second. And a third. A quarter of an hour later you have a dozen printouts, a console full of noise, and still no idea where the value goes bad. Then half those printouts stay in the code forever.

A legion's scout does not work blind. He has a ladder of tools: first he looks from the camp, then he sends a patrol, and when he must - he halts the march and examines the ground step by step. This lesson sets up such a ladder for your code.

The ladder of tools

Four rungs, from built-in to external:

1. The NestJS Logger - built in, always at hand. It shows what happened, but does not stop the program.
2. The Node.js Inspector - started with the --inspect flag, it lets you halt the program and look inside it.
3. The VS Code Debugger - the same mechanism, only with breakpoints clicked in the editor rather than the browser.
4. External APM - New Relic, Datadog and their kind. They observe the application in production, where you cannot set any breakpoint.

The order is not arbitrary: each rung costs more preparation, so you climb it only once the previous one has not sufficed.

Rung one: log levels

NestJS has a built-in logger with five levels: error, warn, log, verbose, debug. In development mode all of them are available - precisely so you can go deeper without adding code.

You choose the levels when creating the application:

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}

The array in the logger option says which levels should be visible. Passing only ['error', 'warn'] silences the rest - and that is usually the production setting, because debug in production would flood the disks. In development you pass the full set.

Note that the configuration goes in as the second argument to NestFactory.create, when the application is created. There is no method like app.setLogLevel() or Logger.setLevel() - the levels are fixed once, at startup.

A logger instead of console.log

With the levels set, we replace printouts with a real logger:

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

new Logger(LegionsService.name) gives the logger a context - the class name that will appear in every entry. Thanks to it you see in the console where a message comes from, without writing that into the text by hand.

The advantage over console.log is practical: debug entries disappear on their own once you switch to the production configuration. You do not have to remove them before deploying or remember where you left them - which is why I recommend it as a habit: not printouts, but a logger at the right level.

Rung two: the Node.js Inspector

A logger shows what the program did. Sometimes you need to see what it is doing right now - and then you halt it at a chosen place.

The --inspect flag serves that purpose. It enables the V8 debugging protocol and lets you attach to a running process:

1node --inspect dist/main.js

The path has four steps. Run the application with the --inspect flag. Open Chrome DevTools at chrome://inspect and attach to the process. Set a breakpoint in the code - the place where the program should halt. Analyse the variables and the call stack, the stack of calls telling you how the program got here.

That fourth step is what console.log cannot give: you see all the variables in scope, not just the ones you guessed and printed earlier. You can also step through the program and watch exactly where a value turns bad.

The flag itself checks nothing and runs nothing - it only opens the door through which a debugger can look inside.

The higher rungs

The VS Code Debugger uses the same protocol, only you place breakpoints by clicking beside a line number and inspect variables in the editor's panel. Nothing new underneath - a more comfortable handle on the same mechanism.

External APM solves a different problem: in production you cannot halt the application with a breakpoint, because it is serving real traffic. Tools like New Relic or Datadog collect data in the background - response times, exceptions, slow queries - and let you reach the cause after the fact, from what they gathered.

Summary

The scouting is done in order, not blind:

• the ladder of tools from built-in to external: NestJS Logger → Node.js Inspector → VS Code Debugger → external APM,
• the logger has five levels: error, warn, log, verbose, debug - in development all of them are available,
• you set the levels as the second argument to NestFactory.create(AppModule, { logger: [...] }) - there is no setLogLevel or Logger.setLevel,
• production usually gets ['error', 'warn'], development the full set,
• new Logger(ClassName.name) gives entries a context, and debug entries vanish by themselves once the configuration changes,
• the --inspect flag enables the V8 debugging protocol and lets a debugger attach; it checks nothing and runs nothing,
• four steps: run with --inspect, open chrome://inspect, set a breakpoint, analyse variables and the call stack,
• the advantage over printouts: you see every variable in scope, not only the ones guessed in advance,
• the VS Code Debugger is the same protocol with a friendlier handle,
• in production no breakpoint is possible - there APM tools work, collecting data in the background.

In the next lesson we will look at what happens when an application shuts down - graceful shutdown, or striking camp without abandoning the wounded. For now remember: a logger tells you what happened; the inspector lets you halt the march and see what is happening now.

1// Debugging Techniques - Solving Problems in the Imperium
2// NestJS debugging tools and techniques
3import { Injectable, Logger } from '@nestjs/common';
4
5// ===========================================
6// 1. Logger as a debugging tool
7// ===========================================
8
9@Injectable()
10export class DebugService {
11  private logger = new Logger('Debug');
12
13  // Debugging with context
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  // Measuring execution time
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 for debugging
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 + ' - ERROR after ' + 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('=== Memory usage ===');
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() - detailed information');
106console.log('measureExecution() - measuring time');
107console.log('DebugInterceptor - automatic request logging');
108console.log('process.memoryUsage() - checking memory');
109