Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Suppress "raw" stack? #204

Closed
aseemk opened this issue Feb 13, 2014 · 12 comments
Closed

Suppress "raw" stack? #204

aseemk opened this issue Feb 13, 2014 · 12 comments

Comments

@aseemk
Copy link
Contributor

aseemk commented Feb 13, 2014

I love the async stack feature of Streamline.js — one of its most useful, underrated features, I think. It seems to always be a superset of the "raw" stack. Is there any reason the "raw" stack is still shown, then?

If there is a reason, perhaps it doesn't apply to most common uses. Could showing or suppressing this raw stack be made into an option? I'd think the default should be to not show it.

It's not a huge deal, but it makes every error stack trace twice as long, which is particularly annoying and noisy with tests where you're comparing JSON etc.

@bjouhier
Copy link
Member

I see two reasons to have it:

  • it helps me debug streamline itself. When the bug is in the runtime itself I don't want to be fooled by the async stack and I need the raw stack.
  • it has some pedagogic value. It shows what's really going on.

But I agree that 99% of the time you just don't care about the raw stack. I'd rather keep it by default (because of the pedagogic value) but have an option to turn it off.

@aseemk
Copy link
Contributor Author

aseemk commented Jul 31, 2014

I'd still love to see this (and personally, as long as the async stack trace behavior is documented, I don't think raw stack traces needs to be the default just for educational purposes), but quick thought: this is only a really significant issue, I realized, when the error message is multi-line.

Streamline thinks every line of the stack after the first is part of the stack, when in reality, the stack may not begin until e.g. line 100. And that's when having this duplicate "raw" stack is extremely noisy: because it duplicates 99 lines before showing the actual stack.

(An example of multi-line messages are Mocha's "diff" assertions, when using assertion libraries like expect.js and comparing objects for loose equality. That's what I meant by "comparing JSON" above.)

Is there a way for Streamline to properly handle multi-line messages in the stack trace? E.g. could it look at error.message and search for that substring in error.stack?

Thanks Bruno!

@bjouhier
Copy link
Member

I'll think more about it. Detecting error.message at the beginning of error.stack is a good idea.

@bjouhier
Copy link
Member

@aseemk I did a first pass on it. I've eliminated the duplicate error.message lines. Can you try it? I get the feel that it should be sufficient because the raw stack is usually shallow (and thus not very bothersome).

@bjouhier
Copy link
Member

I'm not closing yet because I may need to propagate the fix the generators runtime (galaxy).

@aseemk
Copy link
Contributor Author

aseemk commented Aug 4, 2014

Yes, mutli-line error.message is now handled well! Thanks!

I'll still request some improvement here, because this is the kind of heavy duplication I commonly see:

Error: This
is
a
multi-
line
error
message
    <<< async stack >>>
  at ___closure (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:99:298)
  at ___ (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:99:395)
  at ___ (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:105:13)
  at /Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:93:14
  at Object.__g.trampoline.flush (/Users/aseemk/Projects/Node/example/models/node_modules/neo4j/lib/Node.js:2:3350)
  at Request.___ [as _callback] (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:116:61)
  at Request.self.callback (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:129:22)
  at Request.EventEmitter.emit (events.js:98:17)
  at Request.<anonymous> (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:873:14)
  at Request.EventEmitter.emit (events.js:117:20)
  at IncomingMessage.<anonymous> (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:824:12)
  at IncomingMessage.EventEmitter.emit (events.js:117:20)
  at _stream_readable.js:920:16
  at process._tickCallback (node.js:415:13)
    at exports_index__1 (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:131:5)
    at module_exports__1 (/Users/aseemk/Projects/Node/example/www/middleware/csrf._coffee:7:9)
    at module_exports__1 (/Users/aseemk/Projects/Node/example/www/middleware/logger._coffee:55:26)
    <<< raw stack >>>
  at ___closure (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:99:298)
  at ___ (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:99:395)
  at ___ (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:105:13)
  at /Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:93:14
  at Object.__g.trampoline.flush (/Users/aseemk/Projects/Node/example/models/node_modules/neo4j/lib/Node.js:2:3350)
  at Request.___ [as _callback] (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:116:61)
  at Request.self.callback (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:129:22)
  at Request.EventEmitter.emit (events.js:98:17)
  at Request.<anonymous> (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:873:14)
  at Request.EventEmitter.emit (events.js:117:20)
  at IncomingMessage.<anonymous> (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:824:12)
  at IncomingMessage.EventEmitter.emit (events.js:117:20)
  at _stream_readable.js:920:16
  at process._tickCallback (node.js:415:13)

At least with the code I work with, it looks like the async stack is always the raw stack plus the extra/smart async stuff. Is that always the case? If so, can I suggest this instead?

Error: This
is
a
multi-
line
error
message
  at ___closure (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:99:298)
  at ___ (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:99:395)
  at ___ (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:105:13)
  at /Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:93:14
  at Object.__g.trampoline.flush (/Users/aseemk/Projects/Node/example/models/node_modules/neo4j/lib/Node.js:2:3350)
  at Request.___ [as _callback] (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:116:61)
  at Request.self.callback (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:129:22)
  at Request.EventEmitter.emit (events.js:98:17)
  at Request.<anonymous> (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:873:14)
  at Request.EventEmitter.emit (events.js:117:20)
  at IncomingMessage.<anonymous> (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:824:12)
  at IncomingMessage.EventEmitter.emit (events.js:117:20)
  at _stream_readable.js:920:16
  at process._tickCallback (node.js:415:13)
    <<< async stack >>>
    at exports_index__1 (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:131:5)
    at module_exports__1 (/Users/aseemk/Projects/Node/example/www/middleware/csrf._coffee:7:9)
    at module_exports__1 (/Users/aseemk/Projects/Node/example/www/middleware/logger._coffee:55:26)

Or alternately, have the async stack simply scrap the raw part (since that's rarely useful in my experience — yours too?):

Error: This
is
a
multi-
line
error
message
    <<< async stack >>>
    at exports_index__1 (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:131:5)
    at module_exports__1 (/Users/aseemk/Projects/Node/example/www/middleware/csrf._coffee:7:9)
    at module_exports__1 (/Users/aseemk/Projects/Node/example/www/middleware/logger._coffee:55:26)
    <<< raw stack >>>
  at ___closure (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:99:298)
  at ___ (/Users/aseemk/Projects/Node/example/www/routes/site._coffee:99:395)
  at ___ (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:105:13)
  at /Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:93:14
  at Object.__g.trampoline.flush (/Users/aseemk/Projects/Node/example/models/node_modules/neo4j/lib/Node.js:2:3350)
  at Request.___ [as _callback] (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:116:61)
  at Request.self.callback (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:129:22)
  at Request.EventEmitter.emit (events.js:98:17)
  at Request.<anonymous> (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:873:14)
  at Request.EventEmitter.emit (events.js:117:20)
  at IncomingMessage.<anonymous> (/Users/aseemk/Projects/Node/example/node_modules/request/request.js:824:12)
  at IncomingMessage.EventEmitter.emit (events.js:117:20)
  at _stream_readable.js:920:16
  at process._tickCallback (node.js:415:13)

WDYT?

@bjouhier
Copy link
Member

@aseemk I looks more like a bug in the way the async stack is generated. Can you send me a repro.

I'd like to fix it before publishing to npm.

@aseemk
Copy link
Contributor Author

aseemk commented Aug 10, 2014

Here you go Bruno:

$ npm install
$ touch stack._js
var Request = require('request');

function foo(_) {
    var resp = Request.get({
        url: 'http://www.google.com/foo/bar'
    }, _);

    if (resp.statusCode !== 200) {
        throw new Error([
            'This', 'is', 'a', 'multi-', 'line', 'error', 'message'
        ].join('\n'));
    }

    return true;
}

setTimeout(_, 1);
console.log(foo(_));
$ _node stack._js 

/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:136
                throw err;
                      ^
Error: This
is
a
multi-
line
error
message
    <<< async stack >>>
    at ___ (/Users/aseemk/Projects/Node/streamline-test/stack._js:9:20)
    at Request.___ [as _callback] (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:105:13)
    at Request.self.callback (/Users/aseemk/Projects/Node/streamline-test/node_modules/request/request.js:123:22)
    at Request.EventEmitter.emit (events.js:98:17)
    at Request.<anonymous> (/Users/aseemk/Projects/Node/streamline-test/node_modules/request/request.js:1047:14)
    at Request.EventEmitter.emit (events.js:117:20)
    at IncomingMessage.<anonymous> (/Users/aseemk/Projects/Node/streamline-test/node_modules/request/request.js:998:12)
    at IncomingMessage.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16
    at process._tickCallback (node.js:415:13)
    at main (/Users/aseemk/Projects/Node/streamline-test/stack._js:18:13)
    <<< raw stack >>>
    at ___ (/Users/aseemk/Projects/Node/streamline-test/stack._js:9:20)
    at Request.___ [as _callback] (/Users/aseemk/Projects/Node/streamline/lib/callbacks/runtime.js:105:13)
    at Request.self.callback (/Users/aseemk/Projects/Node/streamline-test/node_modules/request/request.js:123:22)
    at Request.EventEmitter.emit (events.js:98:17)
    at Request.<anonymous> (/Users/aseemk/Projects/Node/streamline-test/node_modules/request/request.js:1047:14)
    at Request.EventEmitter.emit (events.js:117:20)
    at IncomingMessage.<anonymous> (/Users/aseemk/Projects/Node/streamline-test/node_modules/request/request.js:998:12)
    at IncomingMessage.EventEmitter.emit (events.js:117:20)
    at _stream_readable.js:920:16
    at process._tickCallback (node.js:415:13)

This is with the current master Streamline.

@bjouhier
Copy link
Member

Thanks. I can reproduce. It's really a bug. With this variant:

"use strict";
var Request = require('request');

function bar(_, resp) {
    if (resp.statusCode !== 200) {
        throw new Error([
            'This', 'is', 'a', 'multi-', 'line', 'error', 'message'
        ].join('\n'));
    }   
}

function foo(_) {
    var resp = Request.get({
        url: 'http://www.google.com/foo/bar'
    }, _);

    bar(_, resp);
    return true;
}

setTimeout(_, 1);
console.log(foo(_));

I get:

Error: This
is
a
multi-
line
error
message
    <<< async stack >>>
    at bar (/Users/bruno/dev/syracuse/foo._js:6:18)
    at foo (/Users/bruno/dev/syracuse/foo._js:17:5)
    at main (/Users/bruno/dev/syracuse/foo._js:28:13)
    <<< raw stack >>>
    at __$bar (/Users/bruno/dev/syracuse/foo._js:6:18)
    at __func (/Users/bruno/dev/syracuse/node_modules/streamline/lib/callbacks/runtime.js:45:5)
    at bar (/Users/bruno/dev/syracuse/foo._js:4:74)
    at ___ (/Users/bruno/dev/syracuse/foo._js:17:16)
    at Request.___ [as _callback] (/Users/bruno/dev/syracuse/node_modules/streamline/lib/callbacks/runtime.js:108:13)
    at Request.self.callback (/Users/bruno/dev/syracuse/node_modules/request/request.js:123:22)
    at Request.EventEmitter.emit (events.js:98:17)
    at Request.<anonymous> (/Users/bruno/dev/syracuse/node_modules/request/request.js:1047:14)
    at Request.EventEmitter.emit (events.js:117:20)
    at IncomingMessage.<anonymous> (/Users/bruno/dev/syracuse/node_modules/request/request.js:998:12)

@bjouhier
Copy link
Member

@aseemk I just committed a fix. Can you test and let me know if it's ok. I'll publish afterwards.

@aseemk
Copy link
Contributor Author

aseemk commented Aug 11, 2014

Awesome! Did a quick test and it works fantastically. Thank you!

@aseemk
Copy link
Contributor Author

aseemk commented Aug 11, 2014

I'm happy to close this issue then. Now that the two stacks are no longer redundant in our use cases, I definitely see the value of keeping both.

@aseemk aseemk closed this as completed Aug 11, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

No branches or pull requests

2 participants