nestjs middleware get request/response body

Question

I am working with nestjs for a project, and want to log as much information as possible, one such thing being the body of the response and request of every http request. I made a nest middleware for that end:

import {token} from 'gen-uid';
import { inspect } from 'util';
import { Injectable, NestMiddleware, MiddlewareFunction } from '@nestjs/common';
import { Stream } from 'stream';
import { createWriteStream, existsSync, mkdirSync } from 'fs';

@Injectable()
export class LoggerMiddleware implements NestMiddleware {
    logfileStream: Stream;

    constructor() {
        if (!existsSync('./logs')) mkdirSync('./logs');
        this.logfileStream = createWriteStream("./logs/serviceName-"+ new Date().toISOString() + ".log", {flags:'a'});
    }

resolve(...args: any[]): MiddlewareFunction {
    return (req, res, next) => {
        let reqToken = token();
        let startTime = new Date();
        let logreq = {
            "@timestamp": startTime.toISOString(),
            "@Id": reqToken,
            query: req.query,
            params: req.params,
            url: req.url,
            fullUrl: req.originalUrl,
            method: req.method,
            headers: req.headers,
            _parsedUrl: req._parsedUrl,
        }

        console.log(
            "timestamp: " + logreq["@timestamp"] + "\t" + 
            "request id: " + logreq["@Id"] + "\t" + 
            "method:  " + req.method + "\t" +
            "URL: " + req.originalUrl);

        this.logfileStream.write(JSON.stringify(logreq));

        const cleanup = () => {
            res.removeListener('finish', logFn)
            res.removeListener('close', abortFn)
            res.removeListener('error', errorFn)
        }

        const logFn = () => {
            let endTime = new Date();
            cleanup()
            let logres = {
                "@timestamp": endTime.toISOString(),
                "@Id": reqToken,
                "queryTime": endTime.valueOf() - startTime.valueOf(),
            }
            console.log(inspect(res));
        }

        const abortFn = () => {
            cleanup()
            console.warn('Request aborted by the client')
        }

        const errorFn = err => {
            cleanup()
            console.error(`Request pipeline error: ${err}`)
        }

        res.on('finish', logFn) // successful pipeline (regardless of its response)
        res.on('close', abortFn) // aborted pipeline
        res.on('error', errorFn) // pipeline internal error

        next();
    };
}
}

Then I set this middleware as a global middleware to log all request, but looking at the res and req object, neither of them have a property.

In the code sample I set the response object to be printed, running a hello world endpoint on my project that returns {"message":"Hello World"} I get the following output:

timestamp: 2019-01-09T00:37:00.912Z request id: 2852f925f987 method: GET URL: /hello-world

ServerResponse { domain: null, _events: { finish: [Function: bound resOnFinish] }, _eventsCount: 1, _maxListeners: undefined, output: [], outputEncodings: [], outputCallbacks: [], outputSize: 0, writable: true, _last: false, upgrading: false, chunkedEncoding: false, shouldKeepAlive: true, useChunkedEncodingByDefault: true, sendDate: true, _removedConnection: false, _removedContLen: true, _removedTE: true, _contentLength: 0, _hasBody: false, _trailer: '', finished: true, _headerSent: true, socket: null, connection: null, _header: 'HTTP/1.1 304 Not Modified\r\nX-Powered-By: Express\r\nETag: W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"\r\nDate: Wed, 09 Jan 2019 00:37:00 GMT\r\nConnection: keep-alive\r\n\r\n', _onPendingData: [Function: bound updateOutgoingData], _sent100: false, _expect_continue: false, req: IncomingMessage { _readableState: ReadableState { objectMode: false, highWaterMark: 16384, buffer: [Object], length: 0, pipes: null, pipesCount: 0, flowing: true, ended: true, endEmitted: false, reading: false, sync: true, needReadable: false, emittedReadable: true, readableListening: false, resumeScheduled: true, destroyed: false, defaultEncoding: 'utf8', awaitDrain: 0, readingMore: true, decoder: null, encoding: null }, readable: true, domain: null, _events: {}, _eventsCount: 0, _maxListeners: undefined, socket: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, connection: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, httpVersionMajor: 1, httpVersionMinor: 1, httpVersion: '1.1', complete: true, headers: { host: 'localhost:5500', 'user-agent': 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:64.0) Gecko/20100101 Firefox/64.0', accept: 'text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8', 'accept-language': 'en-US,en;q=0.5', 'accept-encoding': 'gzip, deflate', connection: 'keep-alive', 'upgrade-insecure-requests': '1', 'if-none-match': 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' }, rawHeaders: [ 'Host', 'localhost:5500', 'User-Agent', 'Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:64.0) Gecko/20100101 Firefox/64.0', 'Accept', 'text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8', 'Accept-Language', 'en-US,en;q=0.5', 'Accept-Encoding', 'gzip, deflate', 'Connection', 'keep-alive', 'Upgrade-Insecure-Requests', '1', 'If-None-Match', 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' ], trailers: {}, rawTrailers: [], upgrade: false, url: '/hello-world', method: 'GET', statusCode: null, statusMessage: null, client: Socket { connecting: false, _hadError: false, _handle: [Object], _parent: null, _host: null, _readableState: [Object], readable: true, domain: null, _events: [Object], _eventsCount: 10, _maxListeners: undefined, _writableState: [Object], writable: true, allowHalfOpen: true, _bytesDispatched: 155, _sockname: null, _pendingData: null, _pendingEncoding: '', server: [Object], _server: [Object], _idleTimeout: 5000, _idleNext: [Object], _idlePrev: [Object], _idleStart: 12562, _destroyed: false, parser: [Object], on: [Function: socketOnWrap], _paused: false, read: [Function], _consuming: true, _httpMessage: null, [Symbol(asyncId)]: 151, [Symbol(bytesRead)]: 0, [Symbol(asyncId)]: 153, [Symbol(triggerAsyncId)]: 151 }, _consuming: false, _dumped: true, next: [Function: next], baseUrl: '', originalUrl: '/hello-world', _parsedUrl: Url { protocol: null, slashes: null, auth: null, host: null, port: null, hostname: null, hash: null, search: null, query: null, pathname: '/hello-world', path: '/hello-world', href: '/hello-world', _raw: '/hello-world' }, params: {}, query: {}, res: [Circular], body: {}, route: Route { path: '/hello-world', stack: [Array], methods: [Object] } }, locals: {}, statusCode: 304, statusMessage: 'Not Modified', [Symbol(outHeadersKey)]: { 'x-powered-by': [ 'X-Powered-By', 'Express' ], etag: [ 'ETag', 'W/"19-c6Hfa5VVP+Ghysj+6y9cPi5QQbk"' ] } }

In no place in the response object does the {"message":"Hello World"} message appears, I would like to know how to obtain the body from the res and req objects if it is possible please.

Note: I know that nestjs has Interceptors, but following what the documentation says, middleware should be the solution for this problem.

Solution 1

I've run against this question accidentally, it was listed in "related" to my question.

I can extend Kim Kern's answer a bit more, about responses.

Problem with response is that response body ain't a property of response object, but stream. To be able to get it, you need to override methods, which writes to that stream.

Like Kim Kern already said, you can look onto this thread, there is accepted answer how to do this.

Or you can take express-mung middleware, which will do it for you, for example:

var mung = require('express-mung');
app.use(mung.json(
  function transform(body, req, res) {
    console.log(body); // or whatever logger you use
    return body;
  }
));

And there are two other different ways, which NestJS can offer you:

• Interceptors, like you said. There is example of LoggingInterceptor in documentation.
• You can write decorator for controller's methods, which will intercept their responses.

import { isObservable, from, of } from 'rxjs';
import { mergeMap } from 'rxjs/operators';

/**
 * Logging decorator for controller's methods
 */
export const LogReponse = (): MethodDecorator =>
  (target: object, propertyKey: string | symbol, descriptor: TypedPropertyDescriptor<any>) => {

    // save original method
    const original = descriptor.value;

    // replace original method
    descriptor.value = function() { // must be ordinary function, not arrow function, to have `this` and `arguments`

      // get original result from original method
      const ret = original.apply(this, arguments);

      // if it is null or undefined -> just pass it further
      if (ret == null) {
        return ret;
      }

      // transform result to Observable
      const ret$ = convert(ret);

      // do what you need with response data
      return ret$.pipe(
        map(data => {
          console.log(data); // or whatever logger you use
          return data;
        })
      );
    };

    // return modified method descriptor
    return descriptor;
  };

function convert(value: any) {
  // is this already Observable? -> just get it
  if (isObservable(value)) {
    return value;
  }

  // is this array? -> convert from array
  if (Array.isArray(value)) {
    return from(value);
  }

  // is this Promise-like? -> convert from promise, also convert promise result
  if (typeof value.then === 'function') {
    return from(value).pipe(mergeMap(convert));
  }

  // other? -> create stream from given value
  return of(value);
}

Note though, that this will executes before interceptors, because this decorator change methods behaviour.

And I don't think this is nice way to do logging, just mentioned it for variety :)

Solution 2

The response body will not be accessible as a property. See this thread for a solution.

You should however be able to access the request body with req.body since nest uses bodyParser by default.

Solution 3

It's incredible how something so trivial is so hard to do.

The easier way to log response body is to create an Interceptor (https://docs.nestjs.com/interceptors):

AppModule:

providers: [
    {
      provide: APP_INTERCEPTOR,
      useClass: HttpInterceptor,
    }
]

HttpInterceptor:

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

@Injectable()
export class HttpInterceptor implements NestInterceptor {
  private readonly logger = new Logger(HttpInterceptor.name);

  intercept(
    context: ExecutionContext,
    next: CallHandler<any>,
  ): Observable<any> | Promise<Observable<any>> {
    return next.handle().pipe(
      map(data => {
        this.logger.debug(data);
        return data;
      }),
    );
  }
}

Comments

[Alex Fortuna]

By using this I can see successful responses only, as data structures (I'm using GraphQL). If, say, an auth guard blocks the query (message: "Unauthorized" being the response), the interceptor is not invoked. Is there a known way how to access the raw response body after all in-app processing has taken place? I want to log actual details on what could have went wrong.