express logging response body

Question

The title should be pretty self explanetory.

For debugging purposes, I would like express to print the response code and body for every request serviced. Printing the response code is easy enough, but printing the response body is trickier, since it seems the response body is not readily available as a property.

The following does NOT work:

var express = require('express');
var app = express();

// define custom logging format
express.logger.format('detailed', function (token, req, res) {                                    
    return req.method + ': ' + req.path + ' -> ' + res.statusCode + ': ' + res.body + '\n';
});  

// register logging middleware and use custom logging format
app.use(express.logger('detailed'));

// setup routes
app.get(..... omitted ...);

// start server
app.listen(8080);

Of course, I could easily print the responses at the client who emitted the request, but I would prefer doing at the server side too.

PS: If it helps, all my responses are json, but hopefully there is a solution that works with general responses.

Answer 1

Not sure if it's the simplest solution, but you can write a middleware to intercept data written to the response. Make sure you disable app.compress().

function logResponseBody(req, res, next) {
  var oldWrite = res.write,
      oldEnd = res.end;

  var chunks = [];

  res.write = function (chunk) {
    chunks.push(chunk);

    return oldWrite.apply(res, arguments);
  };

  res.end = function (chunk) {
    if (chunk)
      chunks.push(chunk);

    var body = Buffer.concat(chunks).toString('utf8');
    console.log(req.path, body);

    oldEnd.apply(res, arguments);
  };

  next();
}

app.use(logResponseBody);

Answer 2

I ran into an issue using the approach suggested by Laurent. Sometimes chunk is a string, and therefore causes problems in the call to Buffer.concat(). Anyways, I found a slight modification fixed things:

function logResponseBody(req, res, next) {
  var oldWrite = res.write,
      oldEnd = res.end;

  var chunks = [];

  res.write = function (chunk) {
    chunks.push(new Buffer(chunk));

    oldWrite.apply(res, arguments);
  };

  res.end = function (chunk) {
    if (chunk)
      chunks.push(new Buffer(chunk));

    var body = Buffer.concat(chunks).toString('utf8');
    console.log(req.path, body);

    oldEnd.apply(res, arguments);
  };

  next();
}

app.use(logResponseBody);

Answer 3

The above accepted code has issues with ES6. Use the below code

function logReqRes(req, res, next) {
  const oldWrite = res.write;
  const oldEnd = res.end;

  const chunks = [];

  res.write = (...restArgs) => {
    chunks.push(Buffer.from(restArgs[0]));
    oldWrite.apply(res, restArgs);
  };

  res.end = (...restArgs) => {
    if (restArgs[0]) {
      chunks.push(Buffer.from(restArgs[0]));
    }
    const body = Buffer.concat(chunks).toString('utf8');

    console.log({
      time: new Date().toUTCString(),
      fromIP: req.headers['x-forwarded-for'] || 
      req.connection.remoteAddress,
      method: req.method,
      originalUri: req.originalUrl,
      uri: req.url,
      requestData: req.body,
      responseData: body,
      referer: req.headers.referer || '',
      ua: req.headers['user-agent']
    });

    // console.log(body);
    oldEnd.apply(res, restArgs);
  };

  next();
}

module.exports = logReqRes;

Answer 4

This solution might not be heavyweight enough for some use cases, but I think it's the simplest. It's also typescript compatible. If you only want logging for JSON responses, all you have to do is substitute the send method with the json method in the code below. Note, I took inspiration from Jonathan Turnock's answer, but made it simpler.

app.use((req, res, next) => {
    let send = res.send;
    res.send = c => {
        console.log(`Code: ${res.statusCode}`);
        console.log("Body: ", c);
        res.send = send;
        return res.send(c);
    }
    next();
});

Answer 5

You can use express-winston and configure using:

expressWinston.requestWhitelist.push('body');
expressWinston.responseWhitelist.push('body');

Example in coffeescript:

expressWinston.requestWhitelist.push('body')
expressWinston.responseWhitelist.push('body')
app.use(expressWinston.logger({
      transports: [
        new winston.transports.Console({
          json: true,
          colorize: true
        })
      ],
      meta: true, // optional: control whether you want to log the meta data about the request (default to true)
      msg: "HTTP {{req.method}} {{req.url}}", // optional: customize the default logging message. E.g. "{{res.statusCode}} {{req.method}} {{res.responseTime}}ms {{req.url}}"
      expressFormat: true, // Use the default Express/morgan request formatting, with the same colors. Enabling this will override any msg and colorStatus if true. Will only output colors on transports with colorize set to true
      colorStatus: true, // Color the status code, using the Express/morgan color palette (default green, 3XX cyan, 4XX yellow, 5XX red). Will not be recognized if expressFormat is true
      ignoreRoute: function (req, res) { return false; } // optional: allows to skip some log messages based on request and/or response
    }));

Answer 6

I found the simplest solution to this problem was to add a body property to the res object when sending the response, which can later be accessed by the logger. I add this to my own namespace that I maintain on the req and res objects to avoid naming collisions. e.g.

res[MY_NAMESPACE].body = ...

I have a utility method that formats all responses to my standardized API/JSON response, so adding this one liner there exposed the response body when the logging gets triggered by onFinished event of res.

Answer 7

I actually made this nifty little npm to solve this exact problem, hope you like it!

https://www.npmjs.com/package/morgan-body

Answer 8

Most of the suggestions seemed a little sledgehammer, Spent some time with this issue tonight and wrote up my findings after digging into a few libs to help make something bespoke.

//app.js
...
app.use(requestLoggerMiddleware({ logger: console.log }));

app.get(["/", "/api/health"], (req, res) => {
    res.send({ message: "OK", uptime: process.uptime() });
...
});

// middleware.js
/**
 * Interceptor function used to monkey patch the res.send until it is invoked
 * at which point it intercepts the invokation, executes is logic such as res.contentBody = content
 * then restores the original send function and invokes that to finalize the req/res chain.
 *
 * @param res Original Response Object
 * @param send Original UNMODIFIED res.send function
 * @return A patched res.send which takes the send content, binds it to contentBody on
 * the res and then calls the original res.send after restoring it
 */
const resDotSendInterceptor = (res, send) => (content) => {
    res.contentBody = content;
    res.send = send;
    res.send(content);
};

/**
 * Middleware which takes an initial configuration and returns a middleware which will call the
 * given logger with the request and response content.
 *
 * @param logger Logger function to pass the message to
 * @return Middleware to perform the logging
 */
const requestLoggerMiddleware = ({ logger }) => (req, res, next) => {
    logger("RECV <<<", req.method, req.url, req.hostname);
    res.send = resDotSendInterceptor(res, res.send);
    res.on("finish", () => {
        logger("SEND >>>", res.contentBody);
    });
    next();
};

module.exports = { requestLoggerMiddleware };

Full working example and article in the git repo https://github.com/JonathanTurnock/ReqResLoggingExample

Answer 9

Typescript solution based on Laurent's answer:

import { NextFunction, Request, Response } from 'express-serve-static-core';
//...

app.use(logResponseBody);

function logResponseBody(req: Request, res: Response, next: NextFunction | undefined) {
    const [oldWrite, oldEnd] = [res.write, res.end];
    const chunks: Buffer[] = [];

    (res.write as unknown) = function(chunk) {
        chunks.push(Buffer.from(chunk));
        (oldWrite as Function).apply(res, arguments);
    };

    res.end = function(chunk) {
        if (chunk) {
            chunks.push(Buffer.from(chunk));
        }
        const body = Buffer.concat(chunks).toString('utf8');
        console.log(new Date(), `  ↪ [${res.statusCode}]: ${body}`);
        (oldEnd as Function).apply(res, arguments);
    };
    if (next) {
      next();
    }
}

Answer 10

May be this would help someone who is looking to get the response logged So, we use the middleware to intercept the request just before being served to the client. Then if we are using res.send method to send the data, override the method in the middleware and make sure to console log the body. If you are planning to use res.send alone then this should work fine, but incase if you use res.end or res.sendFile, then overwrite those methods and log only the required things (obviously logging the entire octet stream of file should never be logged for perfomance purposes.

Here I use pino as the logger. Created it as singleton service.

// LoggingResponseRouter.js

var loggingResponseRouter = require('express').Router();
var loggingService = require('./../service/loggingService');
var appMethodInstance = require('./../constants/appMethod');
var path = require('path');
var fs = require('fs');
var timeZone = require('moment-timezone');
var pino = require('pino')();


loggingResponseRouter.use((req, res, next) => {

    // set the fileName it needs to log
    appMethodInstance.setFileName(__filename.substring(__filename.lastIndexOf(path.sep) + 1, __filename.length - 3));
    //loggingService.debugAndInfolog().info('logging response body', appMethodInstance.getFileName()); 
    let send = res.send;
    res.send = function(body){
        loggingService.debugAndInfolog().info('Response body before sending: ', body);
        send.call(this, body);
    }
    next();
});
module.exports = loggingResponseRouter;

Main file - Main.js

const corsRouter = require('./app/modules/shared/router/corsRouter');
const logRequestRouter = require('./app/modules/shared/router/loggingRequestRouter');
const loggingResponseRouter = require('./app/modules/shared/router/loggingResponseRouter');
const express = require('express');
var path = require('path');
const app = express();


// define bodyparser middleware
const bodyParser = require('body-parser');

const port = process.env.PORT || 3000;

// Now use the middleware prior to any others
app.use(bodyParser.json());
// use this to read url form encoded values as wwell
app.use(bodyParser.urlencoded({extended:true}));
console.log('before calling cors router in main js');
app.use(corsRouter);
app.use(logRequestRouter);
app.use(loggingResponseRouter);


app.get('/api', (req, res) => {
    console.log('inside api call');
    res.send('aapi');
});


app.listen(port, () => {
    console.log('starting the server');
});

And this is the loggingService - loggingService.js

var pino = require('pino');
var os = require('os');
var appMethodInstance = require('./../constants/appMethod'); 
var pinoPretty = require('pino-pretty');
var moment = require('moment');
var timeZone = require('moment-timezone');


class Logger{
    constructor(){
        this.appName = 'Feedback-backend';
        this.filenameval = '';

    }

    getFileName(){
        console.log('inside get filename');
        console.log(appMethodInstance.getFileName());
        if(appMethodInstance.getFileName() === null || appMethodInstance.getFileName() === undefined){
            this.filenameval = 'bootstrapping...'
        }else {
            this.filenameval = appMethodInstance.getFileName();
        }
        console.log('end');
        return this.filenameval;
    }

    debugAndInfolog(){
        return pino({
                    name: 'feedback-backend',
                    base: {
                        pid: process.pid,
                        fileName: this.getFileName(),
                        moduleName: 'modulename',
                        timestamp: timeZone().tz('America/New_York').format('YYYY-MM-DD HH:mm:ss.ms'),

                        hostName: os.hostname()
                    },
                    level: 'info',
                    timestamp: timeZone().tz('America/New_York').format('YYYY-MM-DD HH:mm:ss.ms'),
                    messageKey: 'logMessage',
                    prettyPrint: {
                        messageKey: 'logMessage'
                    }
    });
}

errorAndFatalLog(){

    return pino({
        name: 'feedback-backend',
        base: {
            pid: process.pid,
            fileName: this.getFileName(),
            moduleName: 'modulename',
            timestamp: timeZone().tz('America/New_York').format('YYYY-MM-DD HH:mm:ss.ms'),
            hostName: os.hostname()
        },
        level: 'error',
        timestamp: timeZone().tz('America/New_York').format('YYYY-MM-DD HH:mm:ss.ms'),
        prettyPrint: {
            messageKey: 'FeedbackApp'
        }
    });
}
}




module.exports = new Logger(); 

Answer 11

I have similar need to this question.

Based on accepted answer, I modify it with proxy and trace response body only when it's json.

const traceMiddleware = (req, res, next) => {
  const buffers = []
  const proxyHandler = {
    apply(target, thisArg, argumentsList) {
      const contentType = res.getHeader('content-type')
      if (
        typeof contentType === 'string' && contentType.includes('json') && argumentsList[0]
      ) {
        buffers.push(argumentsList[0])
      }
      return target.call(thisArg, ...argumentsList)
    }
  }
  res.write = new Proxy(res.write, proxyHandler)
  res.end = new Proxy(res.end, proxyHandler)
  res.on('finish', () => {
    // tracing logic inside
    trace(req, res, Buffer.concat(buffers).toString('utf8'))
  })
  next()
}

Answer 12

I tried to create the simplest typescript solution for Request and Response JSON Body log and that works fine with tsoa framework.

Note: Its also works in no body request/response cases.

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

function logRequestResponseMiddleware(req: Request, res: Response, next: NextFunction): void {
    settingLogRequest(req);
    settingLogResponse(req, res);
    next();
}

function settingLogRequest(req: Request): void {
    // use a proper logging library here
    console.debug({
        'url': req.url,
        'method': req.method,
        'bodyRequest': req.body,
        'headers': req.headers,
    });
}

function settingLogResponse(req: Request, res: Response): void {
    const copyJSON = res.json;
    let responseBody: any = undefined;
    res.json = (jsonBody: any) => {
        res.json = copyJSON;
        responseBody = jsonBody;
        return res.json(jsonBody);
    };
    const copyEnd = res.end;
    res.end = (args: any) => {
        res.end = copyEnd;
        // use a proper logging library here
        console.debug({
            'url': req.url,
            'method': req.method,
            'bodyRequest': req.body,
            'statusCode': res.statusCode,
            'bodyResponse': responseBody,
        });
        return res.end(args);
    };
}

const app: Application = express();
app.use(logRequestResponseMiddleware);

I use it with tsoa framework.

Bellow the tsoa response handler (routes.ts):

} else if (data !== null && data !== undefined) {
    response.status(statusCode || 200).json(data);
} else {
    response.status(statusCode || 204).end();
}