format info object appears to be polluted if the first parameter to logger is an object

[GeekyDeaks]

Please tell us about your environment:

• winston version?
  • winston@2
  • winston@3.1.0
• _node -v outputs: 8.11.1
• Operating System? macOS
• Language? ES5

What is the problem?

If the first parameter to one of the logger functions (e.g. logger.info()) is an object, it appears to pollute the info object during formatting. The following code replicates the issue for me:

const winston = require('winston')
const { format, transports } = winston
const logger = winston.createLogger()
const util = require('util')

logger.add(new transports.Console({
    format: winston.format.combine(
        winston.format( (info) => {
            console.log(util.inspect(info, 4))
            return info
        })(),
        winston.format.splat(),
        winston.format.simple()
    )
}))

logger.info('with string %s %j', 'first string', { with: 'object' })
logger.info('without string %j', { with: 'object' })

I get the following output

{ level: 'info',
  message: 'with string %s %j',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ 'first string', { with: 'object' } ],
  [Symbol(message)]: '{"level":"info","message":"with string %s %j"}' }
info: with string first string {"with":"object"}
{ with: 'object',
  level: 'info',
  message: 'without string %j',
  [Symbol(level)]: 'info',
  [Symbol(splat)]: [ { with: 'object' } ],
  [Symbol(message)]: '{"with":"object","level":"info","message":"without string %j"}' }
info: without string {"with":"object"} {"with":"object"}

What do you expect to happen instead?

I would not expect the with element to be present in the info object during the second call to logger.info()

[GeekyDeaks]

I have a workaround, which seems a little brutal but does the job for me. I simply added this formatter to top of the list:

format( (info) => {
    const keep = [ 'level', 'message', MESSAGE, LEVEL, SPLAT ]
    Object.keys(info).forEach( k => {
        if(!keep.includes(k)) delete info[k]
    })
    return info
})()

[GeekyDeaks]

Did a little digging and think I found where this is happening:

winston/lib/winston/logger.js

Lines 172 to 180 in 919ce41

	const [meta] = splat;
	if (typeof meta === 'object' && meta !== null) {
	this.write(Object.assign({}, meta, {
	[LEVEL]: level,
	[SPLAT]: splat.slice(1),
	level,
	message: msg
	}));
	} else {

So meta is getting set to the first argument and if it's an object, it gets Object.assign()d. I'm guessing this is for some kind of backward compatibility?

[radarsu]

The part of code above is also responsible for other issue:

When there is an object that should be stringified using toJSON() method, i.e.

        // sequelize object
        const user = await UserEntity.create({
            login: data.login,
            passwordHash,
        });
        log.error(`FINAL USER`, user);

It's context is replaced by this.write(Object.assign({}, meta, (...) and further it causes error:

[TypeError: exception] Cannot read property 'include' of undefined {
    at Model.get (C:\Users\rkroh\Desktop 3\shard\server\node_modules\sequelize\lib\model.js:3251:66)
    at Model.toJSON (C:\Users\rkroh\Desktop 3\shard\server\node_modules\sequelize\lib\model.js:4106:12)
    at JSON.stringify (<anonymous>)
    at stringify (C:\Users\rkroh\Desktop 3\shard\server\node_modules\logform\node_modules\fast-safe-stringify\index.js:11:18)
    at Format.module.exports.format [as transform] (C:\Users\rkroh\Desktop 3\shard\server\node_modules\logform\json.js:24:19)
    at DerivedLogger._transform (C:\Users\rkroh\Desktop 3\shard\server\node_modules\winston\lib\winston\logger.js:250:29)
    at DerivedLogger.Transform._read (C:\Users\rkroh\Desktop 3\shard\server\node_modules\winston\node_modules\readable-stream\lib\_stream_transform.js:184:10)
    at DerivedLogger.Transform._write (C:\Users\rkroh\Desktop 3\shard\server\node_modules\winston\node_modules\readable-stream\lib\_stream_transform.js:172:83)
    at doWrite (C:\Users\rkroh\Desktop 3\shard\server\node_modules\winston\node_modules\readable-stream\lib\_stream_writable.js:428:64)
    at writeOrBuffer (C:\Users\rkroh\Desktop 3\shard\server\node_modules\winston\node_modules\readable-stream\lib\_stream_writable.js:417:5)
    at DerivedLogger.Writable.write (C:\Users\rkroh\Desktop 3\shard\server\node_modules\winston\node_modules\readable-stream\lib\_stream_writable.js:334:11)
    at DerivedLogger.log (C:\Users\rkroh\Desktop 3\shard\server\node_modules\winston\lib\winston\logger.js:189:12)
    at DerivedLogger.(anonymous function).args [as error] (C:\Users\rkroh\Desktop 3\shard\server\node_modules\winston\lib\winston\create-logger.js:62:21)
    at UserService.<anonymous> (C:\Users\rkroh\Desktop 3\shard\server\src\services\user.service.ts:36:13)
    at Generator.next (<anonymous>)
    at fulfilled (C:\Users\rkroh\Desktop 3\shard\server\src\services\user.service.ts:10:58)

[GeekyDeaks]

That might actually be a slight bug in sequelize too. During the get() it references this._options.include, but never checks first if this._options exists:

https://github.com/sequelize/sequelize/blob/122bd1743f273e1f0e577759bc5ce86e0d874b65/lib/model.js#L3320-L3324

Are you able to call user.toJSON() without an error?

EDIT: ignore me - user.toJSON() is never called. It's going to be data.login.toJSON() or passwordHash.toJSON()

[radarsu]

Yes, calling user.toJSON() directly wasn't causing error.

If you check the this object inside sequelize (model.js) toJSON() call you will see that the context changes, so I think it's ok that sequelize expects include option to be guaranteed.

[indexzero]

Fixed in #1552 and logform@2.0.0