Winston: Don't modify arguments passed to logging methods

[paulerickson]

Please tell us about your environment:

• _winston version?_
  
  
  
  • [ ] winston@2
  
  
  • [X] winston@3
  
  
• _node -v outputs:_ v11.4.0
• _Operating System?_ (Linux)
• _Language?_ (ES6/7)

What is the problem?

Winston modifies objects passed to it!

I have a webservice with error handler:

   handleError(err, req, res, next) {
     winston.warn(err)
     res.status(err.status || err.statusCode || 500).json(err)
   }

I expect, say, a 404 response with body {"message":"Not Found"}, but with the winston.warn call included, it becomes {"message":"Not Found","level":"warn"}. Of course, it's worse after going through formatters—I get tabs, ANSI color codes, etc.—but out of the box I still get the level property.

What do you expect to happen instead?

No mutation

Other information

[sparkida]

Please fix so that data is not unexpectedly mutated.

It looks like there was some confusion between the Triple-beam and non-enumerable properties, wherein the defineProperty configuration is overridden once we assign directly in the logger here

[DABH]

Avoiding an extra copy for a logged object can be a significant performance gain, so I believe that's the reason winston works with the original object rather than a copy. We're aware of what you mentioned with non-enumerability and triple-beam properties, but other users would also be unhappy even if all the properties we set were non-enumerable :)

Perhaps a good solution is to add an option (default false) to Logger that specifies copying objects rather than using them directly (which in turn mutates them). @indexzero open to your thoughts on this.

Another relevant issue that's open https://github.com/winstonjs/winston/issues/1486 is what to do with an object you log that contains a field like message -- we're aware of and thinking about that case too (personally I think that's where the Symbol stuff with triple-beam should ideally help... unsure of performance implications though).

[sparkida]

but other users would also be unhappy even if all the properties we set were non-enumerable :)

Yes @DABH, the only thing I have mentioned is mutating the object at all would be bad practice. And I don't think copying the object is any less evil.

The ideal way to manage objects, in Javascript, is through context and inheritance and the evolution used by a lot of other modules is that they drop their signature patterns altogether and end up with a single object parameter, so compared to:

log(<MyDataObject>)
log(<Level>, <MyDataObject>)
log(<Level>, <MyDataObject>, <SPLAT>)

We'd instead have all options as:

log(<Object>{
  level: <String>,
  data: <MyDataObject>,
  ...
})

Or if we want to keep the signature pattern, then we can simply do this on the receiving end:

log(<level>, <MyDataObject>)

// Winston.logger ...
log(level, data, splat) {
  ...parse arguments to determine signature format
  const logInstance = {
    level,
    // this is the custom data
    data,
    ...
  };
}

[paulerickson]

Yeah, I would definitely not start deep copying arguments. It seems to me like toString, JSON.stringify, enumeration, and getters are all that are really needed for serialization, no?

Now, I could override something like that to have mutative side effects, but my point here is not that the library should bend over backwards to control for that, just that it shouldn't _do_ it itself.

[indexzero]

This is by design. The README for info clearly states that the objects are mutable. In this particular case, you could avoid the mutability if you wished, but opting not to use the convenience method .warn. Instead:

winston.log({ level: 'warn', ...err });

@sparkida unfortunately there is no easy way to handle all permutations of possible inputs that folks which to provide. In particular the desire of most developers includes:

1. Variable-arity (e.g. logger.log('info', 'Interpolate %s [%j]', 'please', { myData: 'stuff' }))
2. Using errors as "data" objects (as in this case) – despite Error instances having non-enumerable properties.

... and many others. In general from a historical perspective, winston@1, and winston@2 did clone each object that was passed to it. This led to an significantly lower performance – which as a project we sought to fix in winston@3.

There are trade-offs for performance vs. features. We opt for performance whenever possible.

[sparkida]

Thanks @indexzero, I didn't know that would avoid mutation.

[dpurrington]

The log utility we use can't have side effects. This is a deal-breaker for us, unfortunately.

[kibertoad]

@dpurrington pino is a great logger, I highly recommend it.