Search code examples
node.jsloggingnestjsx-correlation-id

Is there an easy way to assign correlationId to requests and also persist it in logs with NestJS?


I've inherited a NestJS project that has a middleware created by the previous developer. It generates a correlationId that is attached to requests which works fine. However, in order to actually use this efficiently inside the code and test cases you would need to use or have a extended version of express.Request that has the correlationId inside.

I am looking for a way to make this more convenient to use from a developer perspective and hide the boilerplate code. Is there a way to achieve this?

For example, if you have a controller:

async createUser(@Req() request: AppRequest,
                 @Body() payload: any,
                 @Res() response: Response)
{
   return this.users.create(request, payload);
}

You would need to pass the request to the service so that any printed logs in CloudWatch would have a correlationId. Otherwise if you just console.log you would get out-of-sync logs that are hard to track, because each log would appear at slightly different time and you really have no way to know which log is related to what request.

What I'd like instead would be to be able to call logger.info() from this.users.create() and it would already include the correlationId.

Coming from Spring Boot I'd imagine there is a way to achieve this with Nodejs and NestJS as well?

Here's the middleware:

const onHeaders = require('on-headers');

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  use(request: Request, response: Response, next: NextFunction) {
    httpContext.middleware(request, response, () => {
      const startTime = process.hrtime();

      const correlationId = (
        request.headers['request-id'] ||
        request.headers['x-request-id'] ||
        request.headers['x-correlation-id'] ||
        request.headers.correlationId ||
        uuidv4()
      ).toString();

      const { method, baseUrl, body } = request;
      const url = (baseUrl || '') + (request.url || '-');
      const route = `${method} ${request.route ? request.route.path : url}`;

      const logger = rootLogger.child({ correlationId, route, url, method });
      onHeaders(response, function onHeaders() {
        const diff = process.hrtime(startTime);
        const responseTime = diff[0] * 1e3 + diff[1] * 1e-6;
        response.setHeader('X-Response-Time', responseTime);
        logger.info(
          {
            responseTime,
            statusCode: response.statusCode,
          },
          'Responsed',
        );
      });

      request.logger = logger;
      request.correlationId = correlationId;
      response.setHeader('x-correlation-id', correlationId);
      next();
    });
  }
}

Solution

  • NestJS has three dependency injection scopes - default, request and transient. If you define a request-scoped dependency, you can inject the request object into it.

    @Injectable({
        scope: Scope.REQUEST
    })
    export class MyLogger {
        constructor(@Inject(REQUEST) private readonly request: AppRequest) {}
    
        info(...args: any[]) {
            console.info(this.request.correlationId, ...args);
        }
    }
    

    It does not matter how deep in the tree this logger is instantiated - it will still have access to the request object. So you don't have to pass the request object down the stack.

    The problem with this approach is that a new instance of MyLogger is created for every single request. And in turn, a new instance for each class that has MyLogger as a dependency is created. And then classes that have these classes as dependencies. And so on. Basically, there is a high likelihood that you will recreate the whole tree every time there is a new request. This might not have a huge impact on performance, but personally I find it a bit annoying. If any of your services use in-memory caching, that could be a problem.

    My preferred solution is using the cls-hooked library. It's old and hasn't been updated in forever, but it works like a charm. CLS stands for continuation-local storage, and hooked means that it is able to maintain context across asynchronous calls by tapping into the NodeJS's async hooks system.

    CLS is like an encapsulated context, which can store values and provides access to them in any point of the code. Thus you can create a dedicated CLS context for each request, set the correlation ID there and then access it anywhere in the stack without having to pass it down every single function call. You could also store the whole request / response objects. I prefer it because it does not have the downside that request-scoped providers do.

    I explain it in more detail in this answer: Replicate React Context in Nodejs.