exceptionHandlers - transport formatters do not work?

[mir3z]

Please tell us about your environment:

• winston version?
  • [ ] winston@2
  • [X] winston@3
• node -v outputs: v8.11.2
• Operating System? (Windows, macOS, or Linux) macOS Sierra 10.12.6
• Language? (all | TypeScript X.X | ES6/7 | ES5 | Dart) ES6

What is the problem?

I'm trying to understand how does exception handler work and -- belive me -- it's not easy.

Consider the code:

createLogger({
    exceptionHandlers: [
        new transports.Console(),
    ]
});

throw new Error("WTF");

and it prints me JSON:

{"error":{},"level":"error","message":"uncaughtException: WTF\nError: WTF\n    at eval (webpack:///./src/main/javascript/logger/test.js?:46:7)\n    at Object../src/main/javascript/logger/test.js (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:121:1)\n    at __webpack_require__ (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:20:30)\n    at /Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:84:18\n    at Object.<anonymous> (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:87:10)\n    at Module._compile (module.js:652:30)\n    at Object.Module._extensions..js (module.js:663:10)\n    at Module.load (module.js:565:32)\n    at tryModuleLoad (module.js:505:12)\n    at Function.Module._load (module.js:497:3)","stack":"Error: WTF\n    at eval (webpack:///./src/main/javascript/logger/test.js?:46:7)\n    at Object../src/main/javascript/logger/test.js (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:121:1)\n    at __webpack_require__ (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:20:30)\n    at /Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:84:18\n    at Object.<anonymous> (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:87:10)\n    at Module._compile (module.js:652:30)\n    at Object.Module._extensions..js (module.js:663:10)\n    at Module.load (module.js:565:32)\n    at tryModuleLoad (module.js:505:12)\n    at Function.Module._load (module.js:497:3)","exception":true,"date":"Sat Sep 22 2018 21:38:20 GMT+0200 (CEST)","process":{"pid":70430,"uid":501,"gid":20,"cwd":"/Users/mzemski/workspace/delphi-platform/mail-render","execPath":"/Users/mzemski/.nvm/versions/node/v8.11.2/bin/node","version":"v8.11.2","argv":["/Users/mzemski/.nvm/versions/node/v8.11.2/bin/node","/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js"],"memoryUsage":{"rss":27590656,"heapTotal":11354112,"heapUsed":8035432,"external":147553}},"os":{"loadavg":[2.23291015625,2.06884765625,2.056640625],"uptime":707149},"trace":[{"column":7,"file":"webpack:///./src/main/javascript/logger/test.js?","function":"eval","line":46,"method":null,"native":false},{"column":1,"file":"/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js","function":"Object../src/main/javascript/logger/test.js","line":121,"method":"js","native":false},{"column":30,"file":"/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js","function":"__webpack_require__","line":20,"method":null,"native":false},{"column":18,"file":"/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js","function":null,"line":84,"method":null,"native":false},{"column":10,"file":"/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js","function":null,"line":87,"method":null,"native":false},{"column":30,"file":"module.js","function":"Module._compile","line":652,"method":"_compile","native":false},{"column":10,"file":"module.js","function":"Module._extensions..js","line":663,"method":".js","native":false},{"column":32,"file":"module.js","function":"Module.load","line":565,"method":"load","native":false},{"column":12,"file":"module.js","function":"tryModuleLoad","line":505,"method":null,"native":false},{"column":3,"file":"module.js","function":"Module._load","line":497,"method":"_load","native":false}]}

Next step - let's add a formatter:

createLogger({
    format: format.simple(),
    exceptionHandlers: [
        new transports.Console(),
    ]
});

now it prints a nicely formatted message:

error: uncaughtException: WTF
Error: WTF
    at eval (webpack:///./src/main/javascript/logger/test.js?:46:7)
    at Object../src/main/javascript/logger/test.js (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:121:1)
    at __webpack_require__ (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:20:30)
    at /Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:84:18
    at Object.<anonymous> (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:87:10)
    at Module._compile (module.js:652:30)
    at Object.Module._extensions..js (module.js:663:10)
    at Module.load (module.js:565:32)
    at tryModuleLoad (module.js:505:12)
    at Function.Module._load (module.js:497:3) {"error":{},"stack":"Error: WTF\n    at eval (webpack:///./src/main/javascript/logger/test.js?:46:7)\n    at Object../src/main/javascript/logger/test.js (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:121:1)\n    at __webpack_require__ (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:20:30)\n    at /Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:84:18\n    at Object.<anonymous> (/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js:87:10)\n    at Module._compile (module.js:652:30)\n    at Object.Module._extensions..js (module.js:663:10)\n    at Module.load (module.js:565:32)\n    at tryModuleLoad (module.js:505:12)\n    at Function.Module._load (module.js:497:3)","exception":true,"date":"Sat Sep 22 2018 21:39:36 GMT+0200 (CEST)","process":{"pid":70437,"uid":501,"gid":20,"cwd":"/Users/mzemski/workspace/delphi-platform/mail-render","execPath":"/Users/mzemski/.nvm/versions/node/v8.11.2/bin/node","version":"v8.11.2","argv":["/Users/mzemski/.nvm/versions/node/v8.11.2/bin/node","/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js"],"memoryUsage":{"rss":27660288,"heapTotal":11354112,"heapUsed":8028008,"external":152880}},"os":{"loadavg":[2.5576171875,2.1982421875,2.10400390625],"uptime":707225},"trace":[{"column":7,"file":"webpack:///./src/main/javascript/logger/test.js?","function":"eval","line":46,"method":null,"native":false},{"column":1,"file":"/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js","function":"Object../src/main/javascript/logger/test.js","line":121,"method":"js","native":false},{"column":30,"file":"/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js","function":"__webpack_require__","line":20,"method":null,"native":false},{"column":18,"file":"/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js","function":null,"line":84,"method":null,"native":false},{"column":10,"file":"/Users/mzemski/workspace/delphi-platform/mail-render/src/main/javascript/lib/app.js","function":null,"line":87,"method":null,"native":false},{"column":30,"file":"module.js","function":"Module._compile","line":652,"method":"_compile","native":false},{"column":10,"file":"module.js","function":"Module._extensions..js","line":663,"method":".js","native":false},{"column":32,"file":"module.js","function":"Module.load","line":565,"method":"load","native":false},{"column":12,"file":"module.js","function":"tryModuleLoad","line":505,"method":null,"native":false},{"column":3,"file":"module.js","function":"Module._load","line":497,"method":"_load","native":false}]}

Now let's move formatter to the transport level:

createLogger({
    exceptionHandlers: [
        new transports.Console({
             format: format.simple(),
        }),
    ]
});

And what now? I still got JSON without formatted message.

But this is not the end. Let's now remove exceptionHandlers and add handleExceptions: true to console transport:

createLogger({
    transports: [
        new transports.Console({
             format: format.simple(),
             handleExceptions: true,
        }),
    ]
});

And guess what - formatting suddenly started working! Isn't it magic?

What do you expect to happen instead?

I expect to have working formatters at any level

[kbirger]

Is handleExceptions: true on a transport supposed to be equivalent to setting an exceptionHandler? I don't get why there are two completely parallel ways to achieve the same thing, except perhaps to enable you to have a general logger which also handles exceptions (as opposed to defining a separate one)

[samypr100]

This used to work on winston@2 (formatting of exception handlers), I don't understand why formatters don't work on winston@3.

[trickpeeraze]

You are facing the same problem with me. I think the root cause was about winston-transport that when we set its format it will recreate an info object which mean an Error instance will be lost the identity.

transformed = this.format.transform(Object.assign({}, info), this.format.options);

https://github.com/winstonjs/winston-transport/blob/46db8f3c8cd8b106ade8d7e04a191ee388683d60/index.js#L88-L94

Should we handle more about error case on this?

[lykkin]

ran into this issue as well. naively, it looks like an issue with the way things are being proxied through ExceptionStream. since this calls log on the underlying transport it skips the transform call in TransportStream#_write.

not totally sure the cleanest way to address this, but it seems like this could be fixed by turning ExceptionStream into a duplex and piping it into the underlying stream, or maybe placing a transform call in TransportStream#log.

[coderovich]

I faced with the same issue. Winston v3.8.1 still with this behaviour :(