end() stacktrace formatting messing with our stacktraces

[Mooky]

We have an issue with the Q formatting of the stack trace - its not
playing well with our stack-trace manipulation.
When we have an unhandled error - and end() throws it, the resultant
stacktrace is unreadable.

To improve our error reporting we have a NestedError.
Which looks like this:

function NestedError(message, cause) {
this.constructor.prototype.__proto__ = Error.prototype;
this.name = this.constructor.name;
this.message = message;
this.cause = cause;
Error.captureStackTrace(this, this.constructor);
if (cause) {
var causeDetail = _.isString(cause) ? cause :
util.inspect(cause);
this.stack += "\n Caused by : " + (cause.stack ? cause.stack :
causeDetail) + "\n";
}
}

And when we get an error like : new NestedError("BANG!", new
Error("CRASH!"));
The stack trace looks like this :

NestedError: BANG!
at Object.module.exports.doSomething (E:\dev\projects\moo\server
\test\errors-test.js:60:30)
at Object.wrapTest (E:\dev\projects\moo\test\dep\node_modules
\nodeunit\lib\core.js:235:16)
at wrapTest (E:\dev\projects\moo\test\dep\node_modules\nodeunit\lib
\core.js:235:16)
at Object.exports.runTest (E:\dev\projects\moo\test\dep
\node_modules\nodeunit\lib\core.js:69:9)
at exports.runSuite (E:\dev\projects\moo\test\dep\node_modules
\nodeunit\lib\core.js:117:25)
at _concat (E:\dev\projects\moo\test\dep\node_modules\nodeunit\deps
\async.js:508:13)
at async.forEachSeries.iterate (E:\dev\projects\moo\test\dep
\node_modules\nodeunit\deps\async.js:118:13)
at async.forEachSeries.iterate (E:\dev\projects\moo\test\dep
\node_modules\nodeunit\deps\async.js:129:25)
at _concat (E:\dev\projects\moo\test\dep\node_modules\nodeunit\deps
\async.js:510:17)
at exports.test.test.done (E:\dev\projects\moo\test\dep
\node_modules\nodeunit\lib\types.js:146:17)
Caused by : Error: CRASH!
at Object.module.exports.doSomethingElse (E:\dev\projects\moo
\server\test\errors-test.js:60:55)
at Object.wrapTest (E:\dev\projects\moo\test\dep\node_modules
\nodeunit\lib\core.js:235:16)
at wrapTest (E:\dev\projects\moo\test\dep\node_modules\nodeunit\lib
\core.js:235:16)
at Object.exports.runTest (E:\dev\projects\moo\test\dep
\node_modules\nodeunit\lib\core.js:69:9)
at exports.runSuite (E:\dev\projects\moo\test\dep\node_modules
\nodeunit\lib\core.js:117:25)
at _concat (E:\dev\projects\moo\test\dep\node_modules\nodeunit\deps
\async.js:508:13)
at async.forEachSeries.iterate (E:\dev\projects\moo\test\dep
\node_modules\nodeunit\deps\async.js:118:13)
at async.forEachSeries.iterate (E:\dev\projects\moo\test\dep
\node_modules\nodeunit\deps\async.js:129:25)
at _concat (E:\dev\projects\moo\test\dep\node_modules\nodeunit\deps
\async.js:510:17)
at exports.test.test.done (E:\dev\projects\moo\test\dep
\node_modules\nodeunit\lib\types.js:146:17)

(In this case there is a lot of repetition - but in reality its rarely
the case because the error and nested error are on completely
different call stacks)

When Q tries to format the error stacktrace, we get

NestedError: BANG!
N
e
s
t
e
d
E
r
r
o
r
:

B
A
N
G
!






a
t

m
o
o

(
E
:
\
d
e
v
\
p
r
o
j
e
c
t
s
\
m
o
o
\
<snip - its too long :) >

Wondering if we should change our NestedError impl so Q doesnt make
the stack trace unreadable.
Or whether we should consider changing Q.

Cheers,
M

[Mooky]

And for a non-nested error, we are also seeing some oddness

From previous event:
at <error: TypeError: Cannot call method 'isNative' of undefined>

Don't know why/where that error is coming from...

[Domenic Denicola]

That's a very strange custom error class pattern. Does it get better if you do the following?

function NestedError(message, cause) {

this.message = message;
this.cause = cause;

Error.captureStackTrace(this, NestedError);

if (cause) {
var causeDetail = _.isString(cause) ? cause :
util.inspect(cause);
this.stack += "\n Caused by : " + (cause.stack ? cause.stack :
causeDetail) + "\n";
}
}

NestedError.prototype = Object.create(Error.prototype);
NestedError.prototype.constructor = NestedError;
NestedError.prototype.name = "NestedError";

---

If that doesn't fix the problem, I assume the issue is that the V8 stack trace formatting functions (found in the Q source code) barf on your custom "stack" line, since it doesn't follow the same formatting as every other stack line. Not sure that should be a supported scenario.

[Mooky]

BTW: 0.8.5 ... because I forgot to mention earlier.

Its very possible our NestedError imp is suboptimal - it was from very
early in our project.

But I dont think thats the problem.
I think the problem is that getStackFrames(error) ends up returning a
string (our formatted stack).
I'm reading the earlier thread on stack traces too ::
https://groups.google.com/group/q-continuum/browse_thread/thread/c3f1464359dfb3ef
I'll comment further when I've finished... (but perhaps stacktrace
formatting should perhaps be made optional?)

-M

On Sep 26, 2:34 pm, Domenic Denicola <dome...@domenicdenicola.com>
wrote:

[Domenic Denicola]

Well first try upgrading to the latest since several bug fixes have been made specifically to stack trace formatting since 0.8.5.

I agree on your diagnosis, so we should probably make getStackFrames more robust---our bug. But, you're putting stuff in error.stack that isn't formatted according to the pseudo-standard, so in all fairness we weren't anticipating that.

[Mooky]

I tried with the latest version - no change.
It is specifically because getFrames is returning a string (formatted
stacktrace) instead of an array of frames.
To some extent getFrames is assuming the Error.stack property hasn't
already been accessed - and therefore already lazy-formatted by V8
already.

I'm interested to see where Q is planning on going with stack traces -
maybe we can ditch our NestedError altogether...
Definitely, we found error information in node a bit of a challenge
after java - the lowest-level stack is often next-to-useless.

I also suspect that whatever Q does, it might also be something that
some users may want to opt out of....

Cheers,
-N




On Sep 26, 3:02 pm, Domenic Denicola <dome...@domenicdenicola.com>
wrote:

> Well first try upgrading to the latest since several bug fixes have been made specifically to stack trace formatting since 0.8.5.
>
> I agree on your diagnosis, so we should probably make getStackFrames more robust---our bug. But, you're putting stuff in error.stack that isn't formatted according to the pseudo-standard, so in all fairness we weren't anticipating that.
>

> On Sep 26, 2012, at 9:50, "Mooky" <nick.minute...@gmail.com> wrote:
>
>
>
>
>
>
>
> > BTW: 0.8.5 ... because I forgot to mention earlier.
>
> > Its very possible our NestedError imp is suboptimal - it was from very
> > early in our project.
>
> > But I dont think thats the problem.
> > I think the problem is that getStackFrames(error) ends up returning a
> > string (our formatted stack).
> > I'm reading the earlier thread on stack traces too ::

> >https://groups.google.com/group/q-continuum/browse_thread/thread/c3f1...

[Domenic Denicola]

I see, yes, indeed we can’t deal with `error.stack` already being accessed. Perhaps we should bail out and not attempt to rewrite the stack trace if we detect this (i.e. `if (!Array.isArray(stack))`).

 

Could you test this change? After line 394 of the current version (i.e. after `var stack = objectWithStack.stack;` in `getStackFrames`), add

 

if (!Array.isArray(stack)) {

    return null;

}

 

I believe this should correctly make Q abort its rewriting attempts. If that indeed works, I’ll try to get it into Q proper soon, with tests etc. In the meantime, I filed a bug:

 

https://github.com/kriskowal/q/issues/116

 

Thanks for tracking this down, and for sticking with us instead of giving up in frustration! :)

[Mooky]

> To some extent getFrames is assuming the Error.stack property hasn't
> already been accessed - and therefore already lazy-formatted by V8
> already.

In fact, if you have code that just happens to log an error, but still
ends up passing it up (not always good practice), then the same
problem will occur.
e.g.
function doSomething() {
return trySomething()
.fail(function(error){
log.warn("Failed to do something", error);
return Q.reject(error);
});
}

-M

[Domenic Denicola]

Ouch, that sucks :-/. Wonder if we can fix it, somehow.

 

I guess we could parse the stack string manually instead of capturing and manipulating the stack frames using `Error.prepareStackTrace`. The format is pretty standardized so this should usually work... Probably a good idea. https://github.com/kriskowal/q/issues/117

 

I think the next release of Q is going to focus on progress and cancellation; after that we’ll do another focused on the stack trace and error-reporting story. I’m adding some milestones to reflect this:

 

https://github.com/kriskowal/q/issues/milestones

[Mooky]

The other thing to consider is that errors may be reported (logged)
before any call to end().
So, to some extent, doing it in end() is too late.

-M

On Sep 26, 4:30 pm, Domenic Denicola <dome...@domenicdenicola.com>
wrote:

> Ouch, that sucks :-/. Wonder if we can fix it, somehow.
>

> I guess we could parse the stack string manually instead of capturing and manipulating the stack frames using `Error.prepareStackTrace`. The format is pretty standardized so this should usually work... Probably a good idea.https://github.com/kriskowal/q/issues/117