requestFilter regression in 2.2.0

[tgemes]

Thanks for the cool package. We've been using v2.0.0 for a long while with a requestFilter like this:

requestWhitelist: ['method', 'url', 'body'],
requestFilter: function(req, propName) {
  if (req.url && req.url.toString().indexOf('/myapi') > -1 && propName === 'body') {
    var jsonbody = JSON.parse(JSON.stringify(req[propName]));
    delete jsonbody.field2;
    return jsonbody;
  }
}

The desired outcome: field2 was excluded from the body when the request log got written to a transport file. This worked fine in 2.0.0.

We recently upgraded to 2.2.0 and this feature stopped working and kept including field2 in the logs, so we had to revert to 2.0.0.

Thought you might want to look into why this regression happened. Please let me know if you need any additional info.

[rosston]

Sorry, just getting to this. Are those all of your options / the entirety of your request filter? I've set up a test (see below) to reproduce your scenario against the different versions. It does indeed pass in 2.0.0 and fail in 2.2.0. BUT it fails in 2.2.0 by not having req.body in the logs at all, which is different from field2 being included in the logs (as you described).

describe('requestFilter option', function () {
  it('should trim property with cloned request body', function () {
    var testHelperOptions = {
      req: {
        body: {
          field1: 'foo',
          field2: 'bar'
        }
      },
      loggerOptions: {
        requestWhitelist: ['method', 'url', 'body'],
        requestFilter: function(req, propName) {
          if (propName === 'body') {
            var jsonbody = JSON.parse(JSON.stringify(req[propName]));
            delete jsonbody.field2;
            return jsonbody;
          }
        }
      }
    };

    return loggerTestHelper(testHelperOptions).then(function (result) {
      result.log.meta.req.should.be.ok();
      result.log.meta.req.body.field1.should.equal('foo'); // TypeError: Cannot read property 'field1' of undefined
      should.not.exist(result.log.meta.req.body.field2);
    });
  });
});

[deedw]

I am also experiencing this issue which is a security risk.

I have code similar to the following that masks password and other sensitive fields before logging. This worked fine up until version 2.1.0. Versions 2.1.1 and 2.1.2 did not log any values for body, but from version 2.1.3, the body object is logged unmodified by the requestFilter, so all passwords have been logged in clear text.

app.use(expressWinston.logger({
    transports: [
        new winston.transports.Console({
          json: true,
          colorize: true
        })
    ],
    requestWhitelist: ["body"],
    requestFilter: (req, propName) => {
        if (propName == "body") {
            if (!_.isObject(req.body)) return req.body;
            return _.mapValues(req.body, (v, k) => {
                if (k == "password") return "******";
                return v;
            });
        } else {
            return req[propName];
        }
    }
}));

Logged in version 2.1.0:

{
  "res": {
    "statusCode": 200
  },
  "req": {
    "body": {
      "username": "myusername",
      "password": "******"
    }
  },
  "responseTime": 4,
  "level": "info",
  "message": "HTTP POST /"
}

Logged in version 2.1.3 (and 2.4.0):

{
  "res": {
    "statusCode": 200
  },
  "req": {
    "body": {
      "username": "myusername",
      "password": "password"
    }
  },
  "responseTime": 13,
  "level": "info",
  "message": "HTTP POST /"
}

[rosston]

@deedw I haven't tried to reproduce yet, but looking at your example and the module code, I can definitely see how this is happening. This definitely seems like a regression, and I think I have a fix for it, but it might be a day or two before I get to it.

If you need a hack fix until then, you might try the following requestFilter (note, untested code):

requestFilter: (req, propName) => {
  if (propName == "password") {
    return "******";
  } else {
    return req[propName];
  }
}

This takes advantage of the (extremely confusing) fact that requestFilter gets called with req.body as req (after the initial requestFilter-ing of req happens).

[deedw]

Thanks for looking at this @rosston

I've locked at version 2.1.0 for now, but look forward to updating to fixed version when you have the time.

[deedw]

@rosston Did you manage to find time to look at your fix for this regression?

[rosston]

@deedw Just opened a PR, #153. All tests pass, and I'm pretty sure it fixes your issue. I'd love if you could run it for a little bit and let me know what you think. I'm only so confident in the test suite at this point. 😏

[deedw]

Somewhat belatedly I have tested your fix and it works for me. Looking forward to being able to update from 2.1.0!