Winston logger custom format overwriting timestamp

user_1334007 0
Viewed 1514

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.

winston node.js logging
2 Answers

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.

user_85228320

Hey) I tried to reproduce your case but I could not reproduce. Try this code

const winston = require('winston');

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

  let strArgs = '';

  if (args) {
    console.log('args', args);
    strArgs = args.map((argument) => JSON.stringify(argument)).join(' ');
  }

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

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

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

I checked, in first case timestamp is undefined. In second case I got timestamp: 'this is bad'. Winston does not pass his own timestamp to my log info.

user_146285060
Related