Winston: Error.message being appended to info.message

[spfellers]

Please tell us about your environment:

• _winston version?_
  
  
  
  • [ ] winston@2
  
  
  • [x] winston@3
  
  
• _node -v outputs:_ v8.11.4
• _Operating System?_ macOS
• _Language?_ all

What's the problem?

Errors should not be appended to the message property.

const {createLogger, format, transports} = require('winston');
const logger = createLogger({
    level: 'info',
    format: format.printf(info => `${info.level}: ${info.message}`),
    transports: [new transports.Console()],
    exitOnError: false
});
logger.error('Error Message:', new Error('This is an Error Log'));
logger.info('Object Message:', {a: 'lamb', b: 'cow'});

// results in
// error: Error Message:This is an Error Log
// info: Object Message:

What do you expect to happen instead?

Errors should not be forced onto the message property, thats what format.errors() is for.
If I want to get a stack trace for errors formatted properly I would do:

const {createLogger, format, transports} = require('winston');
const logger = createLogger({
    level: 'info',
    format: format.printf(info => `${info.level}: ${info.message} ${info.stack || ''}`),
    transports: [new transports.Console()],
    exitOnError: false
});
logger.error('Error Message:', new Error('This is an Error Log'));
logger.info('Object Message:', {a: 'lamb', b: 'cow'});

// results in
// error: Error Message:This is an Error Log Error: This is an Error Log
//           <stack trace>
//           <stack trace>
//           <stack trace>
//           <stack trace>
//           <stack trace>
//           <stack trace>
//           <stack trace>
// info: Object Message:

Problem: error.message gets printed twice because its on the stack and the message

I would expect the error message to only get appended to the message if you use format.errors().

[codyzu]

Looks like #1664 is trying to fix this. In the meantime, my solution is to use a custom formatter that "undos" that concatenation:

const {format} = require('winston');

const fixErrors = format(info => {
  // Only modify the info it there was an error
  if (info.stack === undefined) {
    return info;
  }

  const {message} = info;

  // Get the original error message
  const errorMessage =
    info[Symbol.for('splat')] &&
    info[Symbol.for('splat')][0] &&
    info[Symbol.for('splat')][0].message;

  // Check that the original error message was concatenated to the message
  if (
    errorMessage === undefined ||
    message.length <= errorMessage.length ||
    !message.endsWith(errorMessage)
  ) {
    return info;
  }

  // Slice off the original error message from the log message
  info.message = message.slice(0, errorMessage.length * -1);
  return info;
});

module.exports = fixErrors;

And finally, use it like so:

const winston = require('winston');
const fixErrors = require('./fix-errors');

const logger = winston.loggers.add('myLogger', {
  format: winston.format.combine(winston.format.splat(), fixErrors(), winston.format.printf(info => `${info.level.toUpperCase()} ${info.message} ${info.stack === undefined ? '' : info.stack}`)),
  transports: coreTransports,
});

const error = new Error('something bad happened');
logger.error('was doing this and', error);

Resulting in:

ERROR was doing this and Error: something bad happened <rest of the stack>

[tom-milner]

I ran into this problem today, and created the following formatter to un-concatenate the messages:

const messageFormat = format(info => {
    if (info.level == "error") {
        const errorMessage = info[Symbol.for("splat")][0].message;
        info.message = info.message.replace(errorMessage, "");
    }
    return info
})