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

Make stack trace format more user friendly #592

Merged
merged 4 commits into from Feb 24, 2016

Conversation

Projects
None yet
4 participants
@svaarala
Owner

svaarala commented Feb 16, 2016

Make stack trace format a little bit more user friendly. Fixes #588.

Tasks:

  • Figure out improvements
  • Testcase fixes
  • Test test-dev-lightfunc.js manually (it depends on lightfunc built-ins)
  • Update website examples
  • Releases

@svaarala svaarala added this to the v1.5.0 milestone Feb 16, 2016

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

Current format, from Duktape 1.4.0:

duk> function foo() { [1.].forEach(function () { aiee; }) }
= undefined
duk> foo()
ReferenceError: identifier 'aiee' undefined
    duk_js_var.c:1259
    anon input:1 preventsyield
    forEach  native strict preventsyield
    foo input:1
    global input:1 preventsyield
@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

The current draft produces something along the lines of what @HouQiming proposed:

duk> function foo() { [1.].forEach(function () { aiee; }) }
= undefined
duk> foo()
ReferenceError: identifier 'aiee' undefined
    duk_js_var.c:1259
    at anon (input:1) preventsyield
    at forEach () native strict preventsyield
    at foo (input:1)
    at global (input:1) preventsyield
@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

That synthetic call stack entry (duk_js_var.c:1259) could maybe be:

(duk_js_var.c:1259)

Adding "at" might give an impression it's a call stack entry (when it's not):

at (duk_js_var.c:1259)

This pull could also deal with anonymous function names which now print out as:

at anon (foo.js:123) ...

so they're not distinguishable from a function actually named "anon". The function name could just be omitted in that case:

at (foo.js:123) ...

Or a single space could be used:

at  (foo.js:123) ...

Or the placeholder could contain something which would make it unlikely to be an actual function name:

at [anon] (foo.js:123) ...
@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

Yet another option for the synthetic native throw site would be a flag-like indicator:

at (foo.c:123) throwsite

A fake (anon) function name could be added:

at [anon] (foo.c:123) throwsite
@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

Added brackets to anon and "at" to the synthetic call site, so things look like this now:

duk> function foo() { [1.].forEach(function () { aiee; }) }
= undefined
duk> foo()
ReferenceError: identifier 'aiee' undefined
    at (duk_js_var.c:1259)
    at [anon] (input:1) preventsyield
    at forEach () native strict preventsyield
    at foo (input:1)
    at global (input:1) preventsyield

The synthetic entry is different now in that it's missing a function name entirely so it doesn't match anonymous functions (it's not a function so maybe that's logical).

@HouQiming

This comment has been minimized.

HouQiming commented Feb 16, 2016

I think a flag would work better. When one is debugging some code, the
native entry would likely be treated in a similar manner as normal call
stack entries. One may really need to inspect the relevant native, possibly
duktape-internal, code to see what went wrong.

On Tue, Feb 16, 2016 at 4:49 PM, Sami Vaarala notifications@github.com
wrote:

Yet another option for the synthetic native throw site would be a
flag-like indicator:

at (foo.c:123) throwsite


Reply to this email directly or view it on GitHub
#592 (comment).

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

@HouQiming do you have a suggestion for a flag name? :)

I'll let this pull sit for a while in case there are more suggestions. Also while the stack trace format is not under any versioning guarantees, it'd be nice to make enough changes here so that it wouldn't be then touched in a while.

@svaarala svaarala force-pushed the more-friendly-stack-trace branch from eca6fd3 to ec20227 Feb 16, 2016

@HouQiming

This comment has been minimized.

HouQiming commented Feb 16, 2016

How about "internal" or "api"?

I totally agree with letting it sit for a while. I just hope to eventually
get my editor to parse those duktape stack traces I produce :)

On Tue, Feb 16, 2016 at 4:56 PM, Sami Vaarala notifications@github.com
wrote:

@HouQiming https://github.com/HouQiming do you have a suggestion for a
flag name? :)

I'll let this pull sit for a while in case there are more suggestions.
Also while the stack trace format is not under any versioning guarantees,
it'd be nice to make enough changes here so that it wouldn't be then
touched in a while.


Reply to this email directly or view it on GitHub
#592 (comment).

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

@HouQiming I'm sure others share your goal :)

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

So here's the current state, with the internal call site flagged 'internal' and [anon] because it lacks a function name (this is actually good for future proofing because adding the C99 __func__ to the internal call site would be possible):

duk> function foo() { [1.].forEach(function () { aiee; }) }
= undefined
duk> foo()
ReferenceError: identifier 'aiee' undefined
    at [anon] (duk_js_var.c:1259) internal
    at [anon] (input:1) preventsyield
    at forEach () native strict preventsyield
    at foo (input:1)
    at global (input:1) preventsyield

@svaarala svaarala force-pushed the more-friendly-stack-trace branch from ec20227 to 4d0f0d8 Feb 16, 2016

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

Using a tab for indent seems to also divide opinions a little bit. With tab = 8 it's actually a rather deep indent, so it could be changed to 4 spaces here.

@HouQiming

This comment has been minimized.

HouQiming commented Feb 16, 2016

I think 4 spaces is better in practice. Editors don't really care, so
console applications should be prioritized.

On Tue, Feb 16, 2016 at 5:26 PM, Sami Vaarala notifications@github.com
wrote:

Using a tab for indent seems to also divide opinions a little bit. With
tab = 8 it's actually a rather deep indent, so it could be changed to 4
spaces here.


Reply to this email directly or view it on GitHub
#592 (comment).

@fatcerberus

This comment has been minimized.

Contributor

fatcerberus commented Feb 16, 2016

I have a hard time wrapping my head around that native entry - you say it's not a real callstack entry, so is it logically related to the actual top call?

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 16, 2016

For the example stack trace above, the ReferenceError is thrown from Ecmascript code and the line related to the topmost activation is input:1 which is correct and useful for the function on top of the callstack.

The synthetic entry in this case indicates the exact internal throw site which is in variable lookup code, at duk_js_var.c:1259. There is no separate callstack entry for this because the variable lookup is triggered from the bytecode executor.

@svaarala svaarala force-pushed the more-friendly-stack-trace branch from 4d0f0d8 to d41c005 Feb 21, 2016

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

Rebased and made the indent use 4 spaces instead of a tab. Current state:

((o) Duktape 1.4.99 (v1.4.0-160-gd41c005-dirty)
duk> function foo() { [1.].forEach(function () { aiee; }) }
= undefined
duk> foo()
ReferenceError: identifier 'aiee' undefined
    at [anon] (duk_js_var.c:1259) internal
    at [anon] (input:1) preventsyield
    at forEach () native strict preventsyield
    at foo (input:1)
    at global (input:1) preventsyield

Another example:

function bar() {
    aiee;
}
function foo() {
    bar();
}
foo();

Results in:

$ ./duk test.js
ReferenceError: identifier 'aiee' undefined
    at [anon] (duk_js_var.c:1259) internal
    at bar (test.js:2)
    at foo (test.js:5)
    at global (test.js:7) preventsyield
error in executing file test.js
@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

Unless there are any more suggestions for improvement, I'll fix the testcases, update the website documentation etc and we have a new, improved traceback format in master :)

@fatcerberus

This comment has been minimized.

Contributor

fatcerberus commented Feb 21, 2016

I like that with [anon] bracketed - it distinguishes anonymous functions from ones that just happened to be named "anon". :)

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

@fatcerberus It was the best compromise I could figure: brackets can't appear in legitimate function names so it should very rarely be ambiguous (it can though if you forcible edit the function name and set it to a specific value). Using the empty string would mean there'd be two spaces there (or if one was omitted, one field would just be missing).

@harold-b

This comment has been minimized.

Contributor

harold-b commented Feb 21, 2016

That looks really nice. Does is happen to show calls when the 'this' binding is not the global env? As in, fake methods like "Foo.doSomething()" ? Or would that make no sense?

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

The current traceback format doesn't show the "this" binding in any way right now, unfortunately. Can you provide an example what/how would be shown?

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

One thing I don't like too much is "preventsyield" internal flag which is relevant but too long. Maybe "noyield"?

@fatcerberus

This comment has been minimized.

Contributor

fatcerberus commented Feb 21, 2016

What does that flag mean anyway?

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

It means that a thread yield cannot happen because that call is in the call stack.

@fatcerberus

This comment has been minimized.

Contributor

fatcerberus commented Feb 21, 2016

Ah, "noyield" would be okay with me then.

@harold-b

This comment has been minimized.

Contributor

harold-b commented Feb 21, 2016

Well, what I did on the debug client was check the if the current function on the callstack is not anonymous, if not, then I check if 'this' evaluated to an object and if that object was not the global object, I got the constructor name and prefixed it to the function name as such:

    at Game.foo(test.js:2)
    at [anon] (test.js:4) internal
    at App.initialize(test.js:5)
    at main(test.js:7) preventsyield

Don't know how you feel about that though.

@harold-b

This comment has been minimized.

Contributor

harold-b commented Feb 21, 2016

Though I think it would be visually appealing and helpful if it weren't an issue as you guys have described.

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

@fatcerberus Because _Tracedata refers to it that won't be the case. The same thing happens now for functions: all functions in the throw site are referenced by the _Tracedata as long as the error object itself is reachable.

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

@harold-b Opened #602 to track this. I agree it would be nice especially for code dealing with a lot of objects, but it seems too risky to implement in this pull.

@harold-b

This comment has been minimized.

Contributor

harold-b commented Feb 21, 2016

@svaarala Awesome, thanks! 👍

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

The current native flag names are here: #592 (comment)

const char *str_tailcalled = " tailcalled";
const char *str_strict = " strict";
const char *str_construct = " construct";
const char *str_prevyield = " preventsyield";
const char *str_directeval = " directeval";

Suggestions for making these a bit shorter?

  • preventsyield -> noyield
  • tailcalled -> tailcall (the '-ed' maybe isn't necessary?)
@fatcerberus

This comment has been minimized.

Contributor

fatcerberus commented Feb 21, 2016

I agree on tailcalled -> tailcall. "noyield" I'm not sure yet if it would be misleading.

@HouQiming

This comment has been minimized.

HouQiming commented Feb 21, 2016

After re-reading it carefully, I think we should also bracket "input" since
it's plausible to have a module named "input". Maybe ""?

About miscellaneous data like "this" binding, I think the ultimate solution
is to provide a call back that adds some extra text to a call stack entry.
It can be used to dump something out of the "this" binding, and I want to
insert my native call stack in the middle of my log when something fails in
a native-duktape-native-duktape call chain. Just adding some text when
unwinding things at the throw site should be less invasive and more general
than tracking "this" or something.

I think it should be a DUK_OPT since most people probably won't need it.
And it's not exactly a high priority thing comparing to the amount of work
required. Please take your time and don't feel pressured :)

On Sun, Feb 21, 2016 at 9:52 AM, Bruce Pascoe notifications@github.com
wrote:

I agree on tailcalled -> tailcall. "noyield" I'm not sure yet if it would
be misleading.


Reply to this email directly or view it on GitHub
#592 (comment).

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

@HouQiming The "input" in this example is actually the .name of the function and is given explicitly by the Duktape command line: https://github.com/svaarala/duktape/blob/master/examples/cmdline/duk_cmdline.c#L523. So it cannot be changed as such, but it's up to the caller to decide what name to use.

Re: adding a formatting callback, it wouldn't help because the "this" binding is no longer available when the stack trace is being formatted. So we wouldn't be able to give it to the callback.

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 21, 2016

Re: adding options and/or callbacks, that would technically be possible but I'd prefer we didn't: there are always special needs which are difficult to account for. One can add callbacks to format entries etc, but it's easy to add a lot of stuff (and worry about versioning all of them) and still fail to add that one special thing that is needed in some specific environment.

However, the good news is that it's actually quite easy to just replace the whole .stack getter if necessary which gives you a lot of flexibility. There are two basic options for that (in addition to just editing Duktape directly):

  • Just redefine it in Error.prototype.stack using duk_def_prop(). You can write a normal Duktape/C function which can read _Tracedata and go from there.
  • Replace Error.prototype.stack during the dist process using a custom builtin. There's now a process for that in genbuiltins.py: you can remove and edit built-ins as part of the dist. You don't need to edit Duktape sources to do this anymore.

Both will rely on _Tracedata and are versioning fragile, i.e.they may need changes on minor releases. The same would be true for any callbacks. You could also replace the .stack getter with a function which called the original and edited whatever it returned.

There's currently no support to access Duktape internal headers from outside, but that's actually a separate issue and would be nice to fix, so that one could write functions that peeked into the internals, knowing that you have no versioning guarantees.

Anyway, this pull request is about what to do with the default format :)

@svaarala svaarala force-pushed the more-friendly-stack-trace branch 2 times, most recently from 345432e to 336b6f9 Feb 22, 2016

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 22, 2016

Current state:

duk> function foo() { [1.].forEach(function () { aiee; }) }
= undefined
duk> foo()
ReferenceError: identifier 'aiee' undefined
    at [anon] (duk_js_var.c:1259) internal
    at [anon] (input:1) noyield
    at forEach () native strict noyield
    at foo (input:1)
    at global (input:1) noyield

@fatcerberus Opinions on "noyield" vs. "preventsyield" or some alternative? I'd prefer "noyield" because it's shorter and less prominent. It's cryptic anyway if you don't know what it means beforehand.

@fatcerberus

This comment has been minimized.

Contributor

fatcerberus commented Feb 22, 2016

I was under the impression that noyield functions prevent a yield if they are anywhere on the callstack, at least that was the impression I got from your description above. If that's the case then "noyield" is misleading because it implies it's only that function that can't yield.

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 22, 2016

@fatcerberus That impression is correct, and I agree with your reasoning, preventsyield is clearer (but long). I'd like to find a shorter alternative if possible :)

"prevyield" would be ambiguous too (could be mistaken for "previous yield" or something).

Well, if there are no better suggestions I'll grudgingly change it back to "preventsyield" ;)

@fatcerberus

This comment has been minimized.

Contributor

fatcerberus commented Feb 22, 2016

Maybe "preventyield" (without the 's')?

@svaarala svaarala force-pushed the more-friendly-stack-trace branch 2 times, most recently from f57782f to 8f4e050 Feb 23, 2016

Make .stack format more user friendly
* Add 'at foo' to indicate function name

* Put file/line into parentheses for better readability

* Use [anon] for anymous functions, which is better than an empty string but
  distinguishable from a function actually named 'anon'

* Rename tailcalled flag to tailcall

* Switch from tab indent to 4 space indent

@svaarala svaarala force-pushed the more-friendly-stack-trace branch 2 times, most recently from acd2dfc to a3c755a Feb 24, 2016

svaarala added some commits Feb 16, 2016

Test case fixes for new traceback format
Also fix DUK_OPT_LIGHTFUNC_BUILTINS testcase (test-dev-lightfunc.js) which had
a few regressions.

@svaarala svaarala force-pushed the more-friendly-stack-trace branch from a3c755a to 0beaaa6 Feb 24, 2016

@svaarala

This comment has been minimized.

Owner

svaarala commented Feb 24, 2016

Restored "preventsyield", merging once the tests pass.

svaarala added a commit that referenced this pull request Feb 24, 2016

Merge pull request #592 from svaarala/more-friendly-stack-trace
Make stack trace format more user friendly

@svaarala svaarala merged commit 65ce215 into master Feb 24, 2016

2 checks passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
continuous-integration/travis-ci/push The Travis CI build passed
Details

@svaarala svaarala deleted the more-friendly-stack-trace branch Feb 24, 2016

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment