Response body is logging only the last char: "body":"}"

[habmic]

Hi, I am trying to log my response body (with the latest version 2.0.0). I think I followed the documentation (which is awesome by the way!), and got the following code:

const winston = require('winston');
const expressWinston = require('express-winston');

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

module.exports = expressWinston.logger({
  transports: [
    new winston.transports.File({
      name: 'req-res',
      filename: '/var/log/nodejs/req-res.log',
      level: 'info',
    }),
  ],
  bodyBlacklist: ['password', 'pass', 'hash'],
});

The result is: "res":{"statusCode":401,"body":"}"}

After review the source code I think I found a bug, the chunk res.end = function(chunk, encoding) { parameter will get only the last char.

The following code:

function logResponseBody(req, res, next) {

    var oldWrite = res.write,
        oldEnd = res.end;

    var chunks = [];

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

        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();
}

manage to log the entire response, maybe the code should also aggregate the entire chunks? Do you want me to try fix the code and pull request it?

Thanks a lot, Michael.

[rosston]

You're absolutely write about the code causing the problem. This behavior is somewhat expected. Or rather, I'm not sure how best to address the problem. I wrestled with it here too: https://github.com/bithavoc/express-winston/issues/112#issuecomment-223194115

I realize that logging the entire streamed body is probably desirable, but I'm a little worried about how to do that well. This is the main problem: if the developer expects that streaming a JSON response will require less memory than sending it all at once, we've violated that expectation by (re-)building up the entire response body as it gets streamed out.

The only way I can think of to solve this is to monkey-patch res.write (just like we do res.end) and then build up the response with each subsequent res.write call until finally logging after res.end is called. That means the streamed response resides entirely in memory at some point due only to the logger.

So I guess here are my questions:

1. What is the typical goal of streaming the body? Is it to get data to the client earlier? To reduce the memory footprint of the response? Or is it just that there's one particular library that happens to stream JSON in this way?
2. Probably somewhat dependent on (1), but how common is this scenario? I don't think I've run into it in the large, real-world application of my day job, but I realize that doesn't necessarily mean anything.

[habmic]

I do agree that a production node application shouldn't log each and every response, but there few cases that I can think of that could benefit from this feature:

1. non-production environment, I think that it makes your debugging much easier and provides a more complete view of of your backend behavior
2. At this point using this feature doesn't actually provide much benefit, I think when a developer chooses to log the response body he/she would expect the log the entire body. As for you concern about the memory usage, I do agree. I think that you should provide the ability to log the entire response but explain the implication in the documents, We would like to use this feature only in non-production environment so I don't actually care about memory at this point.

Another solution could be to try and pipe the response somehow, It is just an idea, I could try and create a branch with that if you think it worth a try.

[rosston]

If you've got an approach in mind for piping the response somehow, then feel free to try it out. I can't think of a way that would work, given that the interface to writing to winston is simply a synchronous function call. But it's possible I'm missing something.

I can also see your point in (1) about a non-production environment. In that case, we could add an option to enable streamed-response logging (it would be disabled by default), and consumers of the module can enable/disable it based on environment. I'd welcome a PR for that approach.

If someone else doesn't come up with a PR, I would kind of like to hear from more people how common this problem is. Like I said in my previous comment, I don't think I've run into this scenario in my day job, but perhaps streaming JSON is more common than I think?

[tgemes]

Just ran into this today. We often send error responses this way:

return res.status(400).send({
  message: err
});

In fact I believe this is the default way how MEAN.js applications are built with the boilerplate.

I would very much like to log these error message bodies with express-winston, but all I get today is

"res":{"body":"}"

Since these are short error messages, memory footprint is not a concern.

I don't know how to restrict response body logs to just these kinds of error messages though. Not sure whether bodyWhiteList and bodyBlackList apply to both requests and responses.

[rosston]

There's a PR to handle streaming: https://github.com/bithavoc/express-winston/pull/120. It's waiting on some changes before merge.

@tgemes Your example shouldn't be affected by the inability to log streamed responses. res.send is synchronous, not streaming. Are your errors Error or Error-like? It's very common for errors to not be JSON.stringify-able (try JSON.stringify(new Error('foo')) in node), either because:

1. they don't have any enumerable own properties (i.e., those returned by Object.keys()), or
2. they have circular references (which cause JSON.stringify to throw an error).

To answer your other question: bodyWhitelist and bodyBlacklist only apply to requests. I imagine that's probably not desired behavior, although there is another way to filter a response body: add body to the responseWhitelist and then add a responseFilter function that trims out the res.body itself.

[NikhilPunwaney]

Has there been any update on this?