Enable a better unhandled exception experience #84

kenperkins · 2012-01-13T22:00:16Z

tldr: Preserve formatting for handled exceptions in a transport when json=false.

Currently, at Clipboard.com we wrap all node applications in an upstart script that essentially ends up as:

/usr/local/bin/node $APP 1>>$LOGFILE 2>>$ERRORFILE

Combined with console.log and console.error, we're in a position to monitor for unhanded exceptions which are still human readable in the error log.

I've been evaluating winston, but I have one gripe re: error handling with unhanded exceptions.

Here's the output of a unhanded exception to the console:

node.js:201
    throw e; // process.nextTick error, or 'error' event on first tick
          ^
ReferenceError: x is not defined
    at Object.<anonymous> (/clipboard/src/node/winston-log.js:56:1)
    at Module._compile (module.js:432:26)
    at Object..js (module.js:450:10)
    at Module.load (module.js:351:31)
    at Function._load (module.js:310:12)
    at Array.0 (module.js:470:10)
    at EventEmitter._tickCallback (node.js:192:40)

When we catch this with stderr, it's nice and human readable. However, when we use Winston combined with a File transport and handled exceptions (with json=false) you get the following:

13 Jan 13:37:46 - error: uncaughtException pid=4874, uid=0, gid=0, cwd=/var/log/clipboard, execPath=/usr/local/bin/node, version=v0.6.5, argv=[node, /clipboard/src/node/winston-log.js], rss=12767232, heapTotal=7829952, heapUsed=3200976, loadavg=[0.6064453125, 0.48388671875, 0.4375], uptime=10935.226142303, trace=[column=1, file=/clipboard/src/node/winston-log.js, function=, line=56, method=null, native=false, column=26, file=module.js, function=Module._compile, line=432, method=_compile, native=false, column=10, file=module.js, function=Object..js, line=450, method=.js, native=false, column=31, file=module.js, function=Module.load, line=351, method=load, native=false, column=12, file=module.js, function=Function._load, line=310, method=_load, native=false, column=10, file=module.js, function=Array.0, line=470, method=0, native=false, column=40, file=node.js, function=EventEmitter._tickCallback, line=192, method=_tickCallback, native=false], stack=[ReferenceError: x is not defined,     at Object.<anonymous> (/clipboard/src/node/winston-log.js:56:1),     at Module._compile (module.js:432:26),     at Object..js (module.js:450:10),     at Module.load (module.js:351:31),     at Function._load (module.js:310:12),     at Array.0 (module.js:470:10),     at EventEmitter._tickCallback (node.js:192:40)]

Of course, this wraps on most consoles, and you end up with something to this effect:

13 Jan 13:37:46 - error: uncaughtException pid=4874, uid=0, gid=0, cwd=/var/log/clipboard, execPath=/usr/local/bin/node,
version=v0.6.5, argv=[node, /clipboard/src/node/winston-log.js], rss=12767232, heapTotal=7829952, heapUsed=3200976,
loadavg=[0.6064453125, 0.48388671875, 0.4375], uptime=10935.226142303, trace=[column=1,
file=/clipboard/src/node/winston-log.js, function=, line=56, method=null, native=false, column=26, file=module.js, 
function=Module._compile, line=432, method=_compile, native=false, column=10, file=module.js, function=Object..js,
line=450, method=.js, native=false, column=31, file=module.js, function=Module.load, line=351, method=load, native=false,
column=12, file=module.js, function=Function._load, line=310, method=_load, native=false, column=10, file=module.js,
function=Array.0, line=470, method=0, native=false, column=40, file=node.js, function=EventEmitter._tickCallback, line=192,
method=_tickCallback, native=false], stack=[ReferenceError: x is not defined,     at Object.<anonymous>
(/clipboard/src/node/winston-log.js:56:1),     at Module._compile (module.js:432:26),     at Object..js (module.js:450:10),     at
Module.load (module.js:351:31),     at Function._load (module.js:310:12),     at Array.0 (module.js:470:10),     at
EventEmitter._tickCallback (node.js:192:40)]

When we look at this output, it's exceptionally difficult to digest what's going on.

Link from IRC with some commentary: https://gist.github.com/1608837

The text was updated successfully, but these errors were encountered:

indexzero · 2012-01-13T23:27:46Z

You can set the json option on the console to get a JSON literal with stack trace

kenperkins · 2012-01-14T00:07:55Z

But the json formatted exception is still not human consumable; in the log the json is a single line that is entirely un-consumable.

{"process":{"pid":4879,"uid":0,"gid":0,"cwd":"/var/log/clipboard","execPath":"/usr/local/bin/node","version":"v0.6.5","argv":["node","/clipboard/src/node/winston-log.js"],"memoryUsage":{"rss":12902400,"heapTotal":7829952,"heapUsed":3230752}},"os":{"loadavg":[0.33642578125,0.4287109375,0.42041015625],"uptime":10967.267525449},"trace":[{"column":1,"file":"/clipboard/src/node/winston-log.js","function":"","line":56,"method":null,"native":false},{"column":26,"file":"module.js","function":"Module._compile","line":432,"method":"_compile","native":false},{"column":10,"file":"module.js","function":"Object..js","line":450,"method":".js","native":false},{"column":31,"file":"module.js","function":"Module.load","line":351,"method":"load","native":false},{"column":12,"file":"module.js","function":"Function._load","line":310,"method":"_load","native":false},{"column":10,"file":"module.js","function":"Array.0","line":470,"method":"0","native":false},{"column":40,"file":"node.js","function":"EventEmitter._tickCallback","line":192,"method":"_tickCallback","native":false}],"stack":["ReferenceError: x is not defined","    at Object.<anonymous> (/clipboard/src/node/winston-log.js:56:1)","    at Module._compile (module.js:432:26)","    at Object..js (module.js:450:10)","    at Module.load (module.js:351:31)","    at Function._load (module.js:310:12)","    at Array.0 (module.js:470:10)","    at EventEmitter._tickCallback (node.js:192:40)"],"level":"error","message":"uncaughtException","timestamp":"13 Jan 13:38:18"}

Even beautified, the stacktrace is significantly harder to digest than the original exception.

{
    "process": {
        "pid": 4879,
        "uid": 0,
        "gid": 0,
        "cwd": "/var/log/clipboard",
        "execPath": "/usr/local/bin/node",
        "version": "v0.6.5",
        "argv": ["node", "/clipboard/src/node/winston-log.js"],
        "memoryUsage": {
            "rss": 12902400,
            "heapTotal": 7829952,
            "heapUsed": 3230752
        }
    },
    "os": {
        "loadavg": [0.33642578125, 0.4287109375, 0.42041015625],
        "uptime": 10967.267525449
    },
    "trace": [{
        "column": 1,
        "file": "/clipboard/src/node/winston-log.js",
        "function": "",
        "line": 56,
        "method": null,
        "native": false
    }, {
        "column": 26,
        "file": "module.js",
        "function": "Module._compile",
        "line": 432,
        "method": "_compile",
        "native": false
    }, {
        "column": 10,
        "file": "module.js",
        "function": "Object..js",
        "line": 450,
        "method": ".js",
        "native": false
    }, {
        "column": 31,
        "file": "module.js",
        "function": "Module.load",
        "line": 351,
        "method": "load",
        "native": false
    }, {
        "column": 12,
        "file": "module.js",
        "function": "Function._load",
        "line": 310,
        "method": "_load",
        "native": false
    }, {
        "column": 10,
        "file": "module.js",
        "function": "Array.0",
        "line": 470,
        "method": "0",
        "native": false
    }, {
        "column": 40,
        "file": "node.js",
        "function": "EventEmitter._tickCallback",
        "line": 192,
        "method": "_tickCallback",
        "native": false
    }],
    "stack": ["ReferenceError: x is not defined", "    at Object.<anonymous> (/clipboard/src/node/winston-log.js:56:1)", "    at Module._compile (module.js:432:26)", "    at Object..js (module.js:450:10)", "    at Module.load (module.js:351:31)", "    at Function._load (module.js:310:12)", "    at Array.0 (module.js:470:10)", "    at EventEmitter._tickCallback (node.js:192:40)"],
    "level": "error",
    "message": "uncaughtException",
    "timestamp": "13 Jan 13:38:18"
}

indexzero · 2012-01-18T10:05:54Z

@kenperkins I'm open to suggestions here. Pull request?

SeanBannister · 2012-02-21T13:42:51Z

One other slight disadvantage to setting json to true is you loose colorize on the console

faridnsh · 2012-03-17T12:52:58Z

This might help, can have both colors and human readable. #109

simonexmachina · 2012-09-11T03:00:44Z

+1

jimthedev · 2013-03-05T21:29:22Z

+1

fizerkhan · 2013-03-13T11:53:24Z

+1
Desperately needed.

srlowe · 2013-05-02T06:33:48Z

+1 This is currently my biggest gripe with winston. It makes diagnosing problems much slower and more painful than it should be.

Simple hack I use to solve the problem described in 84. I remove 'trace' completely from the meta info (seems to be it's duplicated in err.stack. I also remove the split('\n') from err.stack, which causes the one line problem.

srlowe · 2013-05-02T07:04:19Z

I've added a pull request containing the simple hack I use to solve this problem myself (#245) I don't expect you to merge this as is, but perhaps people could try it and comment as to whether this is a suitable fix, and whether there are any side effects.

mondalaci · 2013-07-25T10:38:23Z

+1

davidleureka · 2013-08-22T19:59:34Z

It would really be nice to have stack traces that are easy to read.

chrisspiegl · 2013-09-09T12:23:39Z

+1

moxystudios · 2013-09-15T06:26:16Z

+1

eugeneiiim · 2013-12-30T03:52:12Z

+1

givan · 2014-02-21T22:01:28Z

+1. I want to be able to set the logging level for the unhandled exceptions. Currently my transport is defined as:

new winston.transports.DailyRotateFile(
            { name: 'mainlog', level: "info", handleExceptions: true, filename: activeConfig.logger.main, maxsize: 107374182400, maxFiles: 10, datePattern: '.yyyy-MM-dd'}
        )

And the unhandled exceptions are logged at level info. I want them to be logged as level error.

danielealbano · 2014-08-08T09:30:20Z

+1

eallegretta · 2014-10-15T01:33:48Z

+1

callicles · 2014-11-05T13:46:53Z

+1

oojacoboo · 2014-11-10T03:58:58Z

Anything on this, been 2 years :(

JohannesRudolph · 2014-11-19T14:37:42Z

+1

ykka · 2014-12-23T09:20:23Z

I've spent like 3 hours trying to figure it out... This pull request is going to be part of 0.9.0, whereas we got 0.8.x at the moment?

So... there is a solution where you use .cli() and colorize: true on your logger and it prints the stack (stacktrace) as last thing so it's easier to debug.

but yeah, +1 so badly.

samejack · 2015-02-27T01:32:50Z

use humanReadableUnhandledException:true config to fix it. as follows

{
      level: 'debug',
      humanReadableUnhandledException: true,
      handleExceptions: true,
      json: false,
      colorize: true
    }

indexzero · 2015-02-27T01:50:55Z

Oh yeah, this is totally fixed. Thanks for the comment @samejack!

Plenty of nice changes since 0.7 Highlights: - Correctly log Error objects: winstonjs/winston@ad2d5e1 - Logging objects to file causes slowdown (we don't log to file in this project) winstonjs/winston@5c4bd41 - Better logging of unhandled exceptions winstonjs/winston#84

indexzero mentioned this issue Apr 21, 2013

Add some other info to uncaughtExceptions meta #117

Closed

indexzero removed the low-priority label Sep 30, 2014

indexzero mentioned this issue Dec 16, 2014

Error StackTrace is not logged in a user friendly format #360

Closed

samzilverberg mentioned this issue Dec 17, 2014

human readable printing of uncaught exceptions #516

Closed

indexzero closed this as completed Feb 27, 2015

alandotcom mentioned this issue Apr 9, 2015

Update Winston to 1.0.0 ripple/ripple-rest#342

Merged

charukiewicz mentioned this issue Sep 15, 2015

added humanReadableUnhandledException to README #710

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Enable a better unhandled exception experience #84

Enable a better unhandled exception experience #84

kenperkins commented Jan 13, 2012

indexzero commented Jan 13, 2012

kenperkins commented Jan 14, 2012

indexzero commented Jan 18, 2012

SeanBannister commented Feb 21, 2012

faridnsh commented Mar 17, 2012

simonexmachina commented Sep 11, 2012

jimthedev commented Mar 5, 2013

fizerkhan commented Mar 13, 2013

srlowe commented May 2, 2013

srlowe commented May 2, 2013

mondalaci commented Jul 25, 2013

davidleureka commented Aug 22, 2013

chrisspiegl commented Sep 9, 2013

moxystudios commented Sep 15, 2013

eugeneiiim commented Dec 30, 2013

givan commented Feb 21, 2014

danielealbano commented Aug 8, 2014

eallegretta commented Oct 15, 2014

callicles commented Nov 5, 2014

oojacoboo commented Nov 10, 2014

JohannesRudolph commented Nov 19, 2014

ykka commented Dec 23, 2014

samejack commented Feb 27, 2015

indexzero commented Feb 27, 2015

Enable a better unhandled exception experience #84

Enable a better unhandled exception experience #84

Comments

kenperkins commented Jan 13, 2012

indexzero commented Jan 13, 2012

kenperkins commented Jan 14, 2012

indexzero commented Jan 18, 2012

SeanBannister commented Feb 21, 2012

faridnsh commented Mar 17, 2012

simonexmachina commented Sep 11, 2012

jimthedev commented Mar 5, 2013

fizerkhan commented Mar 13, 2013

srlowe commented May 2, 2013

srlowe commented May 2, 2013

mondalaci commented Jul 25, 2013

davidleureka commented Aug 22, 2013

chrisspiegl commented Sep 9, 2013

moxystudios commented Sep 15, 2013

eugeneiiim commented Dec 30, 2013

givan commented Feb 21, 2014

danielealbano commented Aug 8, 2014

eallegretta commented Oct 15, 2014

callicles commented Nov 5, 2014

oojacoboo commented Nov 10, 2014

JohannesRudolph commented Nov 19, 2014

ykka commented Dec 23, 2014

samejack commented Feb 27, 2015

indexzero commented Feb 27, 2015