Winston logger custom format overwriting timestamp

Question

I am using winston logger version 3.3.3 in a node app. I have a custom formatter for the output that looks like this:

const winston = require('winston');
const jsonStr = require('fast-safe-stringify');

const customFormat = winston.format.printf(data => {
    const { level, message, timestamp } = data;
    const args = data[Symbol.for('splat')];

    let strArgs = '';

    if (args) {
        strArgs = args.map(jsonStr).join(' ');
    } 

    return `${timestamp} ${level}: ${message} ${strArgs}\n`;
});

logger = winston.createLogger({
    level: 'debug',
    format: winston.format.combine(winston.format.timestamp(), customFormat),
    transports: [new winston.transports.Console()]
});

logger.log('debug', 'hi', 123, { a: 1, b: 'two' });
logger.log('debug', 'hi', { timestamp: 'this is bad' });

This lets me log things with multiple arguments of different types:

logger.log('debug', 'hi', 123, { a: 1, b: 'two' });
> 2020-11-11T19:01:46.942Z debug: hi 123 {"a":1,"b":"two"}

which is what I want. The problem is that if I log an object that contains a field called timestamp it overrides the timestamp field in the formatter.

logger.log('debug', 'hi', { timestamp: 'this is bad' } );
> this is bad debug: hi {"timestamp":"this is bad"}

So now the logger's timestamp is the string "this is bad", which is bad. If I output the data parameter to the printf() method I see this:

{
    timestamp: 'this is bad',
    level: 'debug',
    message: 'hi',
    [Symbol(level)]: 'debug',
    [Symbol(splat)]: [ { timestamp: 'this is bad' } ] }
}

So you can see that the timestamp field is apparently being overwritten by the argument I'm passing in. It only happens if the third argument to the log() method is an object with a property called timestamp. So this is fine:

logger.log('debug', 'hi', 123, { timestamp: 'this is fine' } );

data: {
    level: 'debug',
    message: 'hi',
    timestamp: '2020-11-11T19:08:27.326Z',
    [Symbol(level)]: 'debug',
    [Symbol(splat)]: [ 123, { timestamp: 'this is fine' } ]
}
> 2020-11-11T19:08:27.326Z debug: hi 123 {"timestamp":"this is fine"}

Is this a bug in winston or is my printf() method not right?

Note I have a git repo that reproduces this issue here.

Answer 1

well a simple solution is to add a format or alias for the timestamp in timeStamp.format() as follows

logger = winston.createLogger({
    level: 'debug',
    format: winston.format.combine(
        winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }), // can also alias
        customFormat
    ),
    transports: [new winston.transports.Console()]
});

logger.log('debug', 'hi', { timestamp: 'this is bad' } );

// outputs
2020-11-19 20:08:36 debug: hi {"timestamp":"this is bad"}
{
  timestamp: '2020-11-19 20:08:36',
  level: 'debug',
  message: 'hi',
  [Symbol(level)]: 'debug',
  [Symbol(splat)]: [ { timestamp: 'this is bad' } ]
}

coming to the explanation part I'm actually not sure why timeStamp gets overwritten it's quite strange.