Logging interceptor in NestJS - Step-by-Step Execution

Concept Flow - Logging interceptor

Request received

↓

Interceptor intercepts request

↓

Log request details

↓

Pass control to handler

↓

Handler processes request

↓

Interceptor intercepts response

↓

Log response details

↓

Send response back

The interceptor catches the request, logs info, lets the handler run, then logs the response before sending it back.

Execution Sample

NestJS

import { Injectable, NestInterceptor, ExecutionContext, CallHandler } from '@nestjs/common';
import { Observable, tap } from 'rxjs';

@Injectable()
export class LoggingInterceptor implements NestInterceptor {
  intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
    console.log('Before handler');
    return next.handle().pipe(tap(() => console.log('After handler')));
  }
}

This interceptor logs a message before and after the request handler runs.

Execution Table

Step	Action	Log Output	Handler Called	Response Sent
1	Request received by interceptor	'Before handler'	No	No
2	Pass control to handler	Nothing	Yes	No
3	Handler processes request	Nothing	Yes	No
4	Response intercepted	Nothing	Yes	No
5	Log after handler	'After handler'	Yes	No
6	Send response back	Nothing	Yes	Yes

💡 Response sent back after logging post-handler message

Variable Tracker

Variable	Start	After Step 1	After Step 5	Final
Log Output	''	'Before handler'	'After handler'	'After handler'
Handler Called	false	false	true	true
Response Sent	false	false	false	true

Key Moments - 2 Insights

Why do we see 'Before handler' logged before the handler runs?

Because the interceptor logs 'Before handler' immediately when intercept() is called, before passing control to the handler (see execution_table step 1).

Why is 'After handler' logged only after the handler finishes?

The interceptor uses RxJS tap operator on the handler's observable to log after the handler completes (see execution_table step 5).

Visual Quiz - 3 Questions

Look at the execution table, what is logged at step 3?

A 'Before handler'

B Nothing

C 'After handler'

D 'Handler running'

💡 Hint

Check the 'Log Output' column at step 3 in the execution_table.

At which step is the handler actually called?

A Step 2

B Step 1

C Step 5

D Step 6

💡 Hint

Look at the 'Handler Called' column in execution_table to find when it changes to 'Yes'.

If we remove the tap operator, what changes in the logs?

A 'Before handler' will not log

B Both logs will still appear

C 'After handler' will not log

D No logs will appear

💡 Hint

The tap operator triggers 'After handler' log after handler finishes, see code in execution_sample.

Concept Snapshot

Logging Interceptor in NestJS:
- Implements NestInterceptor interface
- intercept() logs before passing control
- Uses next.handle() to call handler
- Uses RxJS tap() to log after handler completes
- Helps track request and response flow

Full Transcript

A logging interceptor in NestJS catches incoming requests before they reach the handler. It logs a message 'Before handler' immediately. Then it passes control to the handler using next.handle(). After the handler finishes processing, the interceptor logs 'After handler' using the RxJS tap operator on the observable returned by the handler. Finally, the response is sent back to the client. This flow helps developers see when requests start and finish processing.

Practice

1. What is the main purpose of a LoggingInterceptor in a NestJS application?

easy

A. To manage user authentication and authorization

B. To handle database connections automatically

C. To log details about incoming requests and outgoing responses

D. To serve static files like images and CSS

Solution

1. Step 1: Understand the role of interceptors

   Interceptors in NestJS run code before and after request handlers, often used for logging or modifying requests/responses.

2. Step 2: Identify the purpose of LoggingInterceptor

   A LoggingInterceptor specifically tracks and logs request and response details for debugging and monitoring.

3. Final Answer:

   To log details about incoming requests and outgoing responses -> Option C

4. Quick Check:

   LoggingInterceptor = logs requests/responses [OK]

Hint: LoggingInterceptor logs request and response info [OK]

Common Mistakes:

• Confusing interceptors with middleware
• Thinking interceptors handle authentication
• Assuming interceptors serve static files

2. Which of the following is the correct way to implement the intercept method in a NestJS LoggingInterceptor?

easy

A. intercept(context, next) { return next.handle(); }

B. intercept(context, next) { next.handle(); }

C. intercept(context) { return next.handle(); }

D. intercept(next) { return context.handle(); }

Solution

1. Step 1: Recall the intercept method signature

   The intercept method receives two parameters: context and next. It must return next.handle() to continue the request lifecycle.

2. Step 2: Check each option for correct syntax

   intercept(context, next) { return next.handle(); } correctly uses both parameters and returns next.handle(). Options A, C, and D either miss parameters or do not return the observable.

3. Final Answer:

   intercept(context, next) { return next.handle(); } -> Option A

4. Quick Check:

   intercept(context, next) returns next.handle() [OK]

Hint: intercept always returns next.handle() with both parameters [OK]

Common Mistakes:

• Omitting return statement
• Missing one of the parameters
• Calling handle on wrong object

3. Given this LoggingInterceptor code snippet, what will be logged when a request is handled?

intercept(context, next) {
  const now = Date.now();
  return next.handle().pipe(
    tap(() => console.log(`Request took ${Date.now() - now}ms`))
  );
}

medium

A. Logs the time taken to process the request in milliseconds

B. Logs the request URL only

C. Logs the response body content

D. Logs an error message if the request fails

Solution

1. Step 1: Analyze the timing logic

   The code records the current time before the request is handled, then logs the difference after the response is sent.

2. Step 2: Understand the logged message

   The console.log outputs "Request took Xms" where X is the elapsed time in milliseconds.

3. Final Answer:

   Logs the time taken to process the request in milliseconds -> Option A

4. Quick Check:

   LoggingInterceptor measures request duration [OK]

Hint: Look for Date.now() difference to find elapsed time [OK]

Common Mistakes:

• Assuming it logs request URL or body
• Thinking it logs errors only
• Ignoring the timing calculation

4. Identify the error in this LoggingInterceptor code:

intercept(context, next) {
  const now = Date.now();
  next.handle().pipe(
    tap(() => console.log(`Request took ${Date.now() - now}ms`))
  );
}

medium

A. tap operator is not imported

B. Incorrect use of Date.now()

C. Missing context parameter

D. Missing return statement before next.handle()

Solution

1. Step 1: Check the intercept method return

   The intercept method must return the observable from next.handle() to continue the request lifecycle.

2. Step 2: Identify missing return

   The code calls next.handle().pipe(...) but does not return it, so the request will not proceed properly.

3. Final Answer:

   Missing return statement before next.handle() -> Option D

4. Quick Check:

   intercept must return next.handle() observable [OK]

Hint: Always return next.handle() in intercept method [OK]

Common Mistakes:

• Forgetting to return the observable
• Misusing Date.now() for timing
• Ignoring required parameters

5. You want to create a LoggingInterceptor that logs the request method, URL, and the time taken for each request. Which code snippet correctly implements this behavior?

hard

A. intercept(context, next) {
const req = context.getRequest();
const now = Date.now();
next.handle().pipe(
tap(() => console.log(`${req.method} ${req.url} - ${Date.now() - now}ms`))
);
}

B. intercept(context, next) {
const req = context.switchToHttp().getRequest();
const now = Date.now();
return next.handle().pipe(
tap(() => console.log(`${req.method} ${req.url} - ${Date.now() - now}ms`))
);
}

C. intercept(context, next) {
const req = context.switchToHttp().getRequest();
const now = Date.now();
return next.handle().pipe(
map(() => console.log(`${req.method} ${req.url} - ${Date.now() - now}ms`))
);
}

D. intercept(context, next) {
const req = context.switchToHttp().getRequest();
const now = Date.now();
return next.handle().pipe(
tap(() => console.error(`${req.method} ${req.url} - ${Date.now() - now}ms`))
);
}

Solution

1. Step 1: Access request object correctly

   Use context.switchToHttp().getRequest() to get the HTTP request object in NestJS interceptors.

2. Step 2: Use tap operator for side effects

   The tap operator is used to perform logging without altering the response stream. Using map or console.error is incorrect here.

3. Final Answer:

   intercept(context, next) { const req = context.switchToHttp().getRequest(); const now = Date.now(); return next.handle().pipe( tap(() => console.log(`${req.method} ${req.url} - ${Date.now() - now}ms`)) ); } -> Option B

4. Quick Check:

   Use switchToHttp(), tap, and return next.handle() [OK]

Hint: Use switchToHttp().getRequest() and tap for logging [OK]

Common Mistakes:

• Not returning next.handle()
• Using map instead of tap
• Using console.error instead of console.log
• Incorrect request object access