NestJS: Request and response logging with middleware

Much of what can go wrong happens when request reaches an API. When it does, the response include the thrown error. Hence, logs of requests and responses are handy for debugging. The same logs are also useful for determining the volume and origin of traffic reaching an API.

Middleware in NestJS have access to the entire request and response body. This is due to their position between the client and route handler. Let’s apply that to logging. To demonstrate, here’s a repo made using nest new.

Logging requests to NestJS

Here’s the steps:

1. Define the following logger.middleware to intercept calls to the pre-defined app.controller:

import { Injectable, NestMiddleware, RequestMethod } from '@nestjs/common';
import { Request, Response, NextFunction } from 'express';
import { RouteInfo } from '@nestjs/common/interfaces';
import { request } from 'http';
@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  use(req: Request, res: Response, next: NextFunction) {
    // Gets the request log
    console.log(`req:`, {
      headers: req.headers,
      body: req.body,
      originalUrl: req.originalUrl,
    });
    // Ends middleware function execution, hence allowing to move on 
    if (next) {
      next();
    }
  }
}

2. In app.module, apply LoggerMiddleware:

export class AppModule implements NestModule {
  configure(consumer: MiddlewareConsumer) {
    consumer
      .apply(LoggerMiddleware)
      .forRoutes({ path: '*', method: RequestMethod.ALL });
  }
}

To show what a request with a JSON body would look like, I modified app.controller to accept a POST request.

Now to test it. Set up Postman or Curl to pass in the following . I included a header and request body for the sake of demonstration:

curl -X "POST" http://localhost:3000/ -H "access-token:abcd1234" -H "Content-Type: application/json" --data '{"id": 1234, "name":"user1"}'

Here’s the resulting request log:

req: {
  headers: {
    host: 'localhost:3000',
    'user-agent': 'curl/7.81.0',
    accept: '*/*',
    'access-token': 'abcd1234',
    'content-type': 'application/json',
    'content-length': '28'
  },
  body: { id: 1234, name: 'user1' },
  originalUrl: '/'
}

Logging responses from NestJS

Now what if I also want the response logged? Some processing is needed because it is emitted as a writable stream:

1. When the stream starts (res.write): Write the stream to capture the response body Buffer chunks.
2. When the stream ends (res.end): Concat all the chunks together as JSON and parse

logger.middleware does this within getResponseLog().

const getResponseLog = (res: Response) => {
  const rawResponse = res.write;
  const rawResponseEnd = res.end;
  const chunkBuffers = [];
  res.write = (...chunks) => {
    const resArgs = [];
    for (let i = 0; i < chunks.length; i++) {
      resArgs[i] = chunks[i];
      if (!resArgs[i]) {
        res.once('drain', res.write);
        i--;
      }
    }
    if (resArgs[0]) {
      chunkBuffers.push(Buffer.from(resArgs[0]));
    }
    return rawResponse.apply(res, resArgs);
  };
  console.log(`Done writing, beginning res.end`);
  res.end = (...chunk) => {
    const resArgs = [];
    for (let i = 0; i < chunk.length; i++) {
      resArgs[i] = chunk[i];
    }
    if (resArgs[0]) {
      chunkBuffers.push(Buffer.from(resArgs[0]));
    }
    const body = Buffer.concat(chunkBuffers).toString('utf8');
    res.setHeader('origin', 'restjs-req-res-logging-repo');
     const responseLog = {
      response: {
        statusCode: res.statusCode,
        body: JSON.parse(body) || body || {},
        // Returns a shallow copy of the current outgoing headers
        headers: res.getHeaders(),
      },
    };
    console.log('res: ', responseLog);
    rawResponseEnd.apply(res, resArgs);
    return responseLog as unknown as Response;
  };
};

The overall steps are:

1. Perform res.write in object mode. This takes in the Buffer chunks as a rest parameter. Using object mode avoids needing to specify the res.write encoding arg.
2. res.write goes over all chunks and store them in resArgs[]. If any chunk throws an error due to a full buffer as determined by !resArgs[i], drain and resume stream from error chunk.
   The first chunk (chunks[0]) is important: It contains a Buffer of res.body. Store this in an array (chunkBuffers[]) outside of res.write.
3. At the very end, pass in resArgs[] as arguments of rawResponse via apply(). This determines the output boolean returned by res.write.
4. With res.write done, end the stream with res.end. Run this too in object mode to skip specifying the encoding.
   Same as res.write, go over all chunks and store them in its own resArgs[]. The exception is the first chunk (chunks[0]) which is stored in the same external array (chunkBuffers[])
5. With all chunks[0] processed, concat them and encode as utf8. Parsing with JSON.parse reveals the response object. Include it with responseLog.
6. Lastly, emit the end event by passing resArgs[] as arguments of rawResponse via apply(). This terminates the stream to prevent the service response from being stuck on waiting for the stream to end.

Using the same curl above for the request log, here’s the resulting log:

req: {
  headers: {
    host: 'localhost:3000',
    'user-agent': 'curl/7.81.0',
    accept: '*/*',
    'access-token': 'abcd1234',
    'content-type': 'application/json',
    'content-length': '28'
  },
  body: { id: 1234, name: 'user1' },
  originalUrl: '/'
}
...
res:  {
  response: {
    statusCode: 201,
    body: { message: 'Hello World!' },
    headers: [Object: null prototype] {
      'x-powered-by': 'Express',
      'content-type': 'application/json; charset=utf-8',
      'content-length': '26',
      etag: 'W/"1a-iEQ9RXvkycqsT4vWvcdHrxZT8OE"',
      // Declared as a custom header using res.setHeader()   
      origin: 'restjs-req-res-logging-repo'
    }
  }

Now go forth and try it out!

GitHub - YFLooi/nestjs-req-res-logging: Setup to log all requests and response via middleware in…

References

Stream | Node.js v18.8.0 Documentation

Buffer | Node.js v18.8.0 Documentation

JavaScript apply() Method By Practical Examples