1200832 - Async stacks aren't working in the console or debugger with javascript.options.asyncstack=true

Status: RESOLVED FIXED

(DevTools :: General, defect)

Description

[Brian Grinstead [:bgrins]]

STR:

* Make sure javascript.options.asyncstack is set to true (Nightly and Dev Edition for now have this as the default)
* Open: data:text/html,<script>setTimeout(function foo() {setTimeout(function bar() {console.trace();debugger;}, 100);}, 100);</script>

Expected - the trace shows:

  bar();
  foo();

Actual - the trace shows:

  bar();

I've noticed the same behavior with Promise resolutions too.

Comment 1

[Florian Bender]

Is this still an issue?

Comment 2

[Jeff Griffiths (:canuckistani) (:⚡︎)]

(In reply to Florian Bender from comment #1)
> Is this still an issue?

Yes.

Comment 3

[Tom Tromey :tromey]

The debugger part is already filed as bug 1142571.

Comment 4

[Tom Tromey :tromey]

There are two problems here.  First, Console.cpp ignores async parents:

https://dxr.mozilla.org/mozilla-central/source/dom/base/Console.cpp#981

Second, Exceptions.cpp has a couple of spots where it makes an empty stack
frame rather than return null:

https://dxr.mozilla.org/mozilla-central/source/dom/bindings/Exceptions.cpp#681
https://dxr.mozilla.org/mozilla-central/source/dom/bindings/Exceptions.cpp#816

Fixing these gives me an async stack for the original example, but I don't
know what other fallout there might be.  In particular I get:

console.trace():
bar() debugger eval code:1
foo() debugger eval code:1
<anonymous> debugger eval code:1

There may be other spots needing a similar change, but I am not sure.
For example, this walks the stack but does not consider async parents:

https://dxr.mozilla.org/mozilla-central/source/devtools/shared/Console.jsm#370

Comment 5

[Tom Tromey :tromey]

Attachment: WIP patch

Comment 6

[Tom Tromey :tromey]

Attachment: make Console.trace follow async parents

Now with a test case.

One thing I am wondering is whether we should add an async cause field
to ConsoleStackEntry.

Comment 7

[Tom Tromey :tromey]

I think exposing the async cause is best, and with that plus a small
client change I now get:

console.trace():
bar() debugger eval code:1
(Async: setTimeout handler) foo() debugger eval code:1
(Async: setTimeout handler) <anonymous> debugger eval code:1

Comment 8

[Tom Tromey :tromey]

Attachment: make Console.trace follow async parents

Comment 9

[Tom Tromey :tromey]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=007bde2694d0

Comment 10

[Tom Tromey :tromey]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1454eebb1003

Comment 11

[Tom Tromey :tromey]

Attachment: make Console.trace follow async parents

Comment 12

[Tom Tromey :tromey]

Comment on attachment 8672029 [details] [diff] [review]
make Console.trace follow async parents

This changes console.trace to display async stack parents.

This exposes the async cause on ConsoleStackEntry so the console can display async parents more clearly.  It changes ReifyStack to follow the async parent when it exists.  It also removes a "dummy frame" case from Exceptions.cpp in order to make this work properly -- but note that the corresponding dummy frame case in CreateStack does not need to change (changing this runs into crashes elsewhere; and in any case the CreateStack case corresponds to an empty stack, not a frame without a direct parent).

I think the devtools bits are relatively straightforward.  The change to Widgets.Stacktrace.render came about because I happened to notice a message about stacktrace being null when playing with the console before the change; that is, it is a fix for a minor latent bug.

Comment 13

[Andrea Marchesini [:baku]]

Comment on attachment 8672029 [details] [diff] [review]
make Console.trace follow async parents

Review of attachment 8672029 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/webidl/Console.webidl
@@ +80,5 @@
>    unsigned long lineNumber = 0;
>    unsigned long columnNumber = 0;
>    DOMString functionName = "";
>    unsigned long language = 0;
> +  DOMString? asyncCause;

what about: DOMString asyncCause = ""; ?

Comment 14

[Brian Grinstead [:bgrins]]

Comment on attachment 8672029 [details] [diff] [review]
make Console.trace follow async parents

Review of attachment 8672029 [details] [diff] [review]:
-----------------------------------------------------------------

Looks great! Should we file a new bug for these async causes to bubble up in the UI when an error is thrown in an async callback?

::: devtools/client/webconsole/test/browser_webconsole_console_trace_async.js
@@ +1,1 @@
> +/* vim:set ts=2 sw=2 sts=2 et: */

This test will fail in release builds and other places where the feature is off by default.  You can test this locally via:

./mach mochitest devtools/client/webconsole/test/browser_webconsole_console_trace_async.js --setpref javascript.options.asyncstack=false

This test could also take advantage of add_task and BrowserTestUtils to be easier to work with and e10s friendly.  I made some updates locally to test this so I'll just paste in the work:

add_task(function* runTest() {

  // Async stacks aren't on by default in all builds
  yield new Promise(resolve => {
    SpecialPowers.pushPrefEnv({"set": [
      ["javascript.options.asyncstack", true]
    ]}, resolve);
  });

  let {tab} = yield loadTab("data:text/html;charset=utf8,<p>hello");
  let hud = yield openConsole(tab);
  BrowserTestUtils.loadURI(gBrowser.selectedBrowser, TEST_URI);

  let [result] = yield waitForMessages({
    webconsole: hud,
    messages: [{
      name: "console.trace output",
      consoleTrace: {
        file: "test-console-trace-async.html",
        fn: "inner",
      },
    }],
  });

  let node = [...result.matched][0];
  ok(node, "found trace log node");
  ok(node.textContent.includes("console.trace()"),
     "trace log node includes console.trace()");
  ok(node.textContent.includes("promise callback"),
     "trace log node includes promise callback");
  ok(node.textContent.includes("setTimeout handler"),
     "trace log node includes setTimeout handler");

  // The expected stack trace object.
  let stacktrace = [
    {
      columnNumber: 3,
      filename: TEST_URI,
      functionName: "inner",
      language: 2,
      lineNumber: 9
    },
    {
      asyncCause: "promise callback",
      columnNumber: 1,
      filename: TEST_URI,
      functionName: "time1",
      language: 2,
      lineNumber: 13,
    },
    {
      asyncCause: "setTimeout handler",
      columnNumber: 1,
      filename: TEST_URI,
      functionName: "",
      language: 2,
      lineNumber: 18,
    }
  ];

  let obj = node._messageObject;
  ok(obj, "console.trace message object");
  ok(obj._stacktrace, "found stacktrace object");
  is(obj._stacktrace.toSource(), stacktrace.toSource(),
    "stacktrace is correct");
});

Comment 15

[Tom Tromey :tromey]

(In reply to Andrea Marchesini (:baku) from comment #13)
> Comment on attachment 8672029 [details] [diff] [review]
> make Console.trace follow async parents
> 
> Review of attachment 8672029 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: dom/webidl/Console.webidl
> @@ +80,5 @@
> >    unsigned long lineNumber = 0;
> >    unsigned long columnNumber = 0;
> >    DOMString functionName = "";
> >    unsigned long language = 0;
> > +  DOMString? asyncCause;
> 
> what about: DOMString asyncCause = ""; ?

I wanted asyncCause not to be present unless it was explicitly set.
This approach makes it appear as the empty string.

Comment 16

[Tom Tromey :tromey]

Attachment: make Console.trace follow async parents

Use Brian's test case.

Comment 17

[Tom Tromey :tromey]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=8a6a915ebdb6

Comment 18

[Tom Tromey :tromey]

(In reply to Brian Grinstead [:bgrins] from comment #14)
> Comment on attachment 8672029 [details] [diff] [review]
> make Console.trace follow async parents
> 
> Review of attachment 8672029 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks great! Should we file a new bug for these async causes to bubble up in
> the UI when an error is thrown in an async callback?

Maybe bug 1141222 is related?  I am not sure.
I think it doesn't hurt to file another bug.

Comment 19

[Tom Tromey :tromey]

Attachment: make Console.trace follow async parents

This makes a trivial change to a test case that was affected by the
patch.  I'm planning to carry over the r+.

Comment 20

[Tom Tromey :tromey]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=03add21638de

Comment 21

[Tom Tromey :tromey]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=533fe95f97b7

Comment 22

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/eb5224bab72b

Comment 23

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/eb5224bab72b