flatiron/winston — Issue #84: Enable a better unhandled exception experience
Author: kenperkins
Created: 2012-01-13 22:00:16+00:00
State: open

**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:

```bash
/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. (/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. (/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.
(/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.