2.4.0 eats Error objects when logging

[ninja-]

After upgrading from 2.3.0 to 2.4.0, winston stops logging errors when using:

logger.error("Message", new Error("hello"));

I am using this piece of code for formatter

function configuredFormatter(colors) {
    /**
     * @param {Object} options
     * @return {string}
     */
    return function formatter(options) {
        let {
            meta,
            level,
            label,
            message,
            timestamp
        } = options;

        let {
            from,
            stack, trace,
            message: objectMessage
        } = meta;

        delete meta.from;
        delete meta.message;
        delete meta.stack;
        delete meta.trace;

        let formattedMessage = new Message()
            .setColorizer(new Colorizer(colors))
            .setTime(timestamp)
            .setLabel(label)
            .setLevel(level)
            .setFrom(from)
            .setMessage(message || objectMessage)
            .toString();

        formattedMessage += utils.getStackTrace(stack || trace);
        formattedMessage += utils.metaToYAML(meta);

        return formattedMessage;
    };
}

on 2.4.0 there is no stack/trace etc. there is no sign of the error object in the arguments.
the result is that the error is not printed to logs correctly.

downgrading to 2.3.0 fixes the problem.

upgrading to 3.0.0-rc1 + using winston.createLogger
makes the app loop forever displaying the first log message which is really weird :|

[ninja-]

This is the original formatter code IIRC https://github.com/eugeny-dementev/winston-console-formatter, modified a bit

[ninja-]

since 2.3.1 is also fine the regression might be caused by this ? bac951c

[ninja-]

There are discussions on the exact same problem here....nothing was fixed since, sadly.
#977
#1042
#1007

[evanbattaglia]

I was bitten by this too and can confirm that, in my case, it was caused by #977, which is between 2.3.1 and 2.4.0. (Errors passed in in options.meta stopped working between 2.3.0 and 2.3.1, apparently, when cycle.decycle(options.meta) was added, but not yet added for the general case in the clone function. See #1007).

It appears that running cycle.decycle() removes much information, such as the stack trace, from an error.

$ node
> e = new Error('foobar')
Error: foobar
    at repl:1:5
    at Script.runInThisContext (vm.js:65:33)
    at REPLServer.defaultEval (repl.js:246:29)
    at bound (domain.js:370:14)
    at REPLServer.runBound [as eval] (domain.js:383:12)
    at REPLServer.onLine (repl.js:497:10)
    at REPLServer.emit (events.js:165:20)
    at REPLServer.Interface._onLine (readline.js:287:10)
    at REPLServer.Interface._line (readline.js:640:8)
    at REPLServer.Interface._ttyWrite (readline.js:920:14)
> e.stack
'Error: foobar\n    at repl:1:5\n    at Script.runInThisContext (vm.js:65:33)\n    at REPLServer.defaultEval (repl.js:246:29)\n    at bound (domain.js:370:14)\n    at REPLServer.runBound [as eval] (domain.js:383:12)\n    at REPLServer.onLine (repl.js:497:10)\n    at REPLServer.emit (events.js:165:20)\n    at REPLServer.Interface._onLine (readline.js:287:10)\n    at REPLServer.Interface._line (readline.js:640:8)\n    at REPLServer.Interface._ttyWrite (readline.js:920:14)'
> require('cycle').decycle(e)
{}
> require('cycle').decycle(e).stack
undefined

edit: upon closer inspection, I'm not sure what is going in the case of #1007, but what is going in my problem case is that I am using a formatter. Thus, when winston runs return String(options.formatter(exports.clone(options)));. exports.clone checks to see if what is passed in is an error, but in this case, since the error is in options.meta and not options, that case does not fire. Instead it passes all of options into cycle.decycle(), which strips the error (in options.meta) of its message and stack trace.

[amitguptagwl]

I'm using 3.0.0-rc4, and observed that when log error with error object;

process.on('unhandledRejection', (reason, p) => {
    logger.log.error(reason, 'Unhandled Rejection at Promise', p);
});

It logs

{"0":"U","1":"n","2":"h","3":"a","4":"n","5":"d","6":"l","7":"e","8":"d","9":" ","10":"R","11":"e","12":"j","13":"e","14":"c","15":"t","16":"i","17":"o","18":"n","19":" ","20":"a","21":"t","22":" ","23":"P","24":"r","25":"o","26":"m","27":"i","28":"s","29":"e","level":"error","message":{}}

But if I use pino, it prints properly

{"level":50,"time":1523851621182,"msg":"Unhandled Rejection at Promise {}","pid":14497,"hostname":"some host name","type":"Error","stack":"complete stack trace","v":1}

[indexzero]

Duplicate of #1007.

@amitguptagwl the unhandledRejection problem is interesting, please open a new issue for it.

[Bec-k]

It seems there is the same problem in v3.3.3. It eats/swallows error.message if error is provided with a introduction string, like this: logger.error('ops', new Error('this will not be visible'));
While this will work:
logger.error(new Error('this will be visible'));