How-to : Logging request/response in Nest.js properly (in one place)

[julien-sarazin]

Issue posted on stackoverflow - https://stackoverflow.com/questions/55093055/logging-request-response-in-nest-js

[mxthevs]

You can use a middleware for that.

import { Injectable, NestMiddleware, Logger } from '@nestjs/common';

import { Request, Response, NextFunction } from 'express';

@Injectable()
export class AppLoggerMiddleware implements NestMiddleware {
  private logger = new Logger('HTTP');

  use(request: Request, response: Response, next: NextFunction): void {
    const { ip, method, path: url } = request;
    const userAgent = request.get('user-agent') || '';

    response.on('close', () => {
      const { statusCode } = response;
      const contentLength = response.get('content-length');

      this.logger.log(
        `${method} ${url} ${statusCode} ${contentLength} - ${userAgent} ${ip}`
      );
    });

    next();
  }
}

and in the AppModule

export class AppModule implements NestModule {
  configure(consumer: MiddlewareConsumer): void {
    consumer.apply(AppLoggerMiddleware).forRoutes('*');
  }
}

[MFrat]

@mxthevs 'close' callback is never called =/

[melihbirim]

Hello @mxthevs instead of path: url it is better to use originalUrl to log the enpoints called

[Jeontaeyun]

How about use finish event instead of close event.

import { Request, Response, NextFunction } from "express";
import { Injectable, NestMiddleware, Logger } from "@nestjs/common";

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  private logger = new Logger("HTTP");

  use(request: Request, response: Response, next: NextFunction): void {
    const { ip, method, originalUrl } = request;
    const userAgent = request.get("user-agent") || "";

    response.on("finish", () => {
      const { statusCode } = response;
      const contentLength = response.get("content-length");

      this.logger.log(
        `${method} ${originalUrl} ${statusCode} ${contentLength} - ${userAgent} ${ip}`,
      );
    });

    next();
  }
}

Because as far as know express connection is maintained after send response.
So close event can't be fired

Reference

01. Node document about response event

[DiegoECQ]

is possible add the response body?

[syahiaoui]

if you need to have the response time you can use this example

'use strict';
import { Request, Response, NextFunction } from 'express';
import { Injectable, NestMiddleware, Logger } from '@nestjs/common';

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  private logger = new Logger('HTTP');

  use(request: Request, response: Response, next: NextFunction): void {
    const startAt = process.hrtime();
    const { ip, method, originalUrl } = request;
    const userAgent = request.get('user-agent') || '';

    response.on('finish', () => {
      const { statusCode } = response;
      const contentLength = response.get('content-length');
      const diff = process.hrtime(startAt);
      const responseTime = diff[0] * 1e3 + diff[1] * 1e-6;
      this.logger.log(
        `${method} ${originalUrl} ${statusCode} ${responseTime}ms ${contentLength} - ${userAgent} ${ip}`,
      );
    });

    next();
  }
}

[raarts]

contentLength is undefined for me. How do I get the actual content length even when chunked?

[theycantrevealus]

How to get response text content?

[carloseduardodb]

I wanted to get the response of all requests made on my server with a middleware, but I'm not able to implement.

[carloseduardodb]

How to get response text content?

I got it doing like the code below hope it helps:

let send = res.send;
res.send = (exitData) => {
   if (
     res?.getHeader('content-type')?.toString().includes('application/json')
   ) {
     fullLog.push({
       code: res.statusCode,
       exit: exitData.toString().substring(0, 1000),
       endDate: new Date(),
       type: 'response',
     });
   }
   res.send = send;
   return res.send(exitData);
};

Here I only get the answers in JSON, but I have to do some tests to see if everything will work out, hope it helps.

Integrating with the code above it would look like this:

'use strict';
import { Request, Response, NextFunction } from 'express';
import { Injectable, NestMiddleware, Logger } from '@nestjs/common';

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  private logger = new Logger('HTTP');

  use(request: Request, response: Response, next: NextFunction): void {
    const startAt = process.hrtime();
    const { ip, method, originalUrl } = request;
    const userAgent = request.get('user-agent') || '';

    response.on('finish', () => {
      const { statusCode } = response;
      const contentLength = response.get('content-length');
      const diff = process.hrtime(startAt);
      const responseTime = diff[0] * 1e3 + diff[1] * 1e-6;
      this.logger.log(
        `${method} ${originalUrl} ${statusCode} ${responseTime}ms ${contentLength} - ${userAgent} ${ip}`,
      );
    });

let send = res.send;
response.send = (exitData) => {
   if (
     response?.getHeader('content-type')?.toString().includes('application/json')
   ) {
     console.log({
       code: response.statusCode,
       exit: exitData.toString().substring(0, 1000),
       endDate: new Date(),
     });
   }
   response.send = send;
   return res.send(exitData);
};

    next();
  }
}

[aurelien-brabant]

How to get response text content?

I got it doing like the code below hope it helps:

let send = res.send;
res.send = (exitData) => {
   if (
     res?.getHeader('content-type')?.toString().includes('application/json')
   ) {
     fullLog.push({
       code: res.statusCode,
       exit: exitData.toString().substring(0, 1000),
       endDate: new Date(),
       type: 'response',
     });
   }
   res.send = send;
   return res.send(exitData);
};

Here I only get the answers in JSON, but I have to do some tests to see if everything will work out, hope it helps.

Integrating with the code above it would look like this:

'use strict';
import { Request, Response, NextFunction } from 'express';
import { Injectable, NestMiddleware, Logger } from '@nestjs/common';

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  private logger = new Logger('HTTP');

  use(request: Request, response: Response, next: NextFunction): void {
    const startAt = process.hrtime();
    const { ip, method, originalUrl } = request;
    const userAgent = request.get('user-agent') || '';

    response.on('finish', () => {
      const { statusCode } = response;
      const contentLength = response.get('content-length');
      const diff = process.hrtime(startAt);
      const responseTime = diff[0] * 1e3 + diff[1] * 1e-6;
      this.logger.log(
        `${method} ${originalUrl} ${statusCode} ${responseTime}ms ${contentLength} - ${userAgent} ${ip}`,
      );
    });

let send = res.send;
response.send = (exitData) => {
   if (
     response?.getHeader('content-type')?.toString().includes('application/json')
   ) {
     console.log({
       code: response.statusCode,
       exit: exitData.toString().substring(0, 1000),
       endDate: new Date(),
     });
   }
   response.send = send;
   return res.send(exitData);
};

    next();
  }
}

This a working solution to intercept response data but it's still hacky and it would feel great to have something more integrated.

[abdulkalam1233]

contentLength is undefined for me. How do I get the actual content length even when chunked?

response.getHeaders()['content-length'] , use this

[rpCal]

How to add database timing? I use typeorm. Is there a way to get database instance from request or response object?

[aurelien-brabant]

Depending on how you have things set up you should be able to inject a TypeORM data source (or connection if using an older version of TypeORM) using standard dependency injection. That goes only if you are using a class-based middleware and registering it from a module that itself makes these injections possible.

[rpCal]

@aurelien-brabant I can rewrite some parts of entities, if logs are posible :D can you help me and show me some example code? I understand I can write middleware and get instance of typeorm but how to get time or each query or just summary of all queries ?

[drewish]

Anyone have an idea how to log the route that was called? Meaning rather than the path of /users/1/documents you'd use the version with the placeholder: /users/:userId/documents. I'd like to group logs by request to an endpoint.

[nicobao]

is possible add the response body?

I solved it like that:

import { Injectable, NestMiddleware, Logger } from '@nestjs/common';

import { Request, Response, NextFunction } from 'express';

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  private logger = new Logger('HTTP');

  use(request: Request, response: Response, next: NextFunction): void {
    const { method, originalUrl, body } = request;
    this.logger.log(`[REQ] ${method} ${originalUrl} ${JSON.stringify(body)}`);

    var oldWrite = response.write;
    var oldEnd = response.end;
    var chunks = [];
    response.write = function (chunk: any) {
      chunks.push(chunk);
      return oldWrite.apply(response, arguments);
    };
    response.end = function (chunk: any) {
      if (chunk) {
        chunks.push(chunk);
      }
      return oldEnd.apply(response, arguments);
    };

    response.on('finish', () => {
      const { statusCode } = response;
      const responseBody = Buffer.concat(chunks).toString('utf8');
      this.logger.log(
        `[RESP] ${method} ${originalUrl} ${statusCode} ${responseBody}`,
      );
    });

    next();
  }
}

I used this stackoverflow response as inspiration.

[Marlrus]

I needed this to enrich some OpenTelemetry data on responses, especially errors as NestJS is not allowing me to access the response body in the @opentelemetry/instrumentation-http responseHook through the regular response.on('data') and response.on('end') events.

Had a really hard time with this as well but managed a similar solution in middleware:

import { ConfigService } from '@nestjs/config';
import { Injectable, NestMiddleware } from '@nestjs/common';
import { Response, NextFunction } from 'express';
import { CustomRequest } from '../commons/types';

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
  constructor(private readonly configService: ConfigService) {}

  use(req: CustomRequest, res: Response, next: NextFunction) {
    /* Your Pre existing Middleware code Here */

    interceptAllResponses(res);

    next();
  }
}

const interceptAllResponses = (res: Response) => {
  const originalResponseEndRef = res.end;
  const chunkBuffers = [];

  res.end = (...chunks: any[]) => {
    /* This is effectively middleware for res.end */
    for (const chunk of chunks) {
      if (chunk) chunkBuffers.push(Buffer.from(chunk));
    }
    const body = Buffer.concat(chunkBuffers).toString('utf8');

    const parsedBody = JSON.parse(body);

    /* Do what you want with your response body */
    console.log(parsedBody);

    originalResponseEndRef.apply(res, chunks);

    return res;
  };
};

Inspired by this thread and this article: NestJS: Request and response logging with middleware

I never got anything on the res.write method so I removed it. I tried with MB size responses and still nothing but I'll monitor and update if I come to need to override res.write.