1343158 - Unable to get meaningful stack traces from async functions

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Mark Hammond [:markh] [:mhammond]]

Attachment: scratchpad sample showing missing stack entries

When running xpcshell tests using async functions, often the stack traces are missing all intermediate async functions, making diagnosis of failures almost impossible. This same issue is preventing us moving to async functions in other parts of the product (as we can't get useful stack traces, which we consider critical)

Attached is a sample which can be run from a "browser scratchpad" - note that the |wait3| and |wait4| entries are omitted from the stack trace.

I asked on IRC and :jimb tells me that while the current behaviour is correct in a particular technical sense (ie, that Error.stack only capture currently active stack frames), he agrees it's not useful and that I should file a bug - so here I am :)

(Note the same basic problem exists using Task.jsm tasks, but I thought I should reproduce using only native JS features.)

Comment 1

[Jim Blandy :jimb]

I *think* the problem that arises with promises, of having "stacks" that grow without bound as the program runs, cannot arise here. A stack that just shows the series of 'await' calls that led to the current location represents a real continuation, a chain of calls each of which will at some point be resumed, just like an ordinary stack. So having stack traces as captured by Error follow 'await' calls instead of just dying at the event loop seems practical and useful.

Comment 2

[Mark Hammond [:markh] [:mhammond]]

(oops - FTR, my attachment has at line 22 |wait3().catch(err => { // line 22| - it *should* read |wait4().catch(err => { // line 22| - but note that the exact same stack is printed when it does.)

Comment 3

[Tooru Fujisawa [:arai]]

so, the stack information gets lost at await
(because we currently use generator internally)

  async function f() {
      print(new Error().stack); // [e-mail]:2:11
                                // [e-mail]:11:5
                                // @test.js:13:1

      await 10;

      print(new Error().stack); // [e-mail]:8:11
  }
  function main() {
      f();
  }
  main();

maybe, we could capture the stack at the point of function invocation,
and use it through the async function.

Comment 4

[Tooru Fujisawa [:arai]]

this will also apply to async generator (bug 1331092)
we'll need to capture the stack for each resume, and reuse the stack information after each await.

Comment 5

[Tooru Fujisawa [:arai]]

(In reply to Tooru Fujisawa [:arai] from comment #3)
> maybe, we could capture the stack at the point of function invocation,
> and use it through the async function.

or, simply, capture before await and restore after await,
in that way async generator can use the same code.

Comment 6

[Tooru Fujisawa [:arai]]

fwiw, here's the point that the operation can be done

[initial invocation]

https://dxr.mozilla.org/mozilla-central/rev/106a96755d3bcebe64bbbc3b521d65d262ba9c02/js/src/vm/AsyncFunction.cpp#79
>     if (Call(cx, unwrappedVal, thisValue, args2, &generatorVal)) {


[resume (including the first chunk before await)]

https://dxr.mozilla.org/mozilla-central/rev/106a96755d3bcebe64bbbc3b521d65d262ba9c02/js/src/vm/AsyncFunction.cpp#178-179
>     if (!CallSelfHostedFunction(cx, funName, generatorVal, args, &result))
>         return AsyncFunctionThrown(cx, resultPromise);


[before await]

https://dxr.mozilla.org/mozilla-central/rev/106a96755d3bcebe64bbbc3b521d65d262ba9c02/js/src/vm/AsyncFunction.cpp#192
>     return AsyncFunctionAwait(cx, resultPromise, value);

Comment 7

[Tooru Fujisawa [:arai]]

Attachment: (WIP) Restore stack trace for async function after await.

Here's WIP patch that at least shows stack information, like following:

  async function f() {
      print(new Error().stack); // [e-mail]:2:11
                                // [e-mail]:11:5
                                // @test.js:13:1

      await 10;

      print(new Error().stack); // [e-mail]:8:11
                                // async function*[e-mail]:11:5
                                // @test.js:13:1
  }
  function main() {
      f();
  }
  main();

currently this captures the stack at async function invocation, and restores for each resume, by AutoSetAsyncStackForNewCalls.
I'm not sure if this is right approach tho.
also, showing "async function*" before the resotred stack won't make sense for this case.

can I have some feedback on how to go from here?
is there better way to save/restore/display stack?

Comment 8

[Jim Blandy :jimb]

I don't think that's quite right. I got Jason Orendorff to explain the big picture to me and he said something entirely different, so I may be wrong here. I'm going to needinfo him, as well as the original poster.

It seems to me that code like the below should actually print a stack like this:

Threw an exception: Error: tantrum
Exception's stack:
flaky@/home/jimb/moz/async-stack2.js:3:25
inner@/home/jimb/moz/async-stack2.js:8:16
middle@/home/jimb/moz/async-stack2.js:13:16
outer@/home/jimb/moz/async-stack2.js:18:16

In the general case, a promise can have many `then` and `catch` callbacks, each of which are attached separately, so it's not clear which of the many potential continuations make sense to report as a stack when a promise is rejected.

But in the specific case of pure async functions awaiting values of other async functions, the promises are not exposed, and there is always a single chain of continuations awaiting both results and errors. This is the stack that programmers are going to want to see.

// not trustworthy
async function flaky() {
  throw new Error("tantrum");
}

async function inner() {
  let addend = await Promise.resolve(100);
  return await flaky() + addend; // line 8
}

async function middle() {
  let addend = await Promise.resolve(1000);
  return await inner() + addend; // line 13
}

async function outer() {
  let addend = await Promise.resolve(10000);
  return await middle() + addend; // line 18
}

outer().then(v => {
  print("Final result, should be 11142: " + uneval(v));
}).catch(e => {
  print("Threw an exception: " + e);
  print("Exception's stack:\n" + e.stack);
});

Comment 9

[Jason Orendorff [:jorendorff]]

I agree with Jim about the case where an async function calls another async function (and immediately awaits the result).

In arai's example, when `main` calls `f`, that's different. To me that case (calling an async function and *not* using `await` or `.then` on the result) is more like spawning a thread. When I spawn a thread, and it hits an error, I don't expect to see the stack where I spawned it seamlessly sewn into that thread's stack; it should be reported differently.

Comment 10

[Jim Blandy :jimb]

Comment on attachment 8841935 [details] [diff] [review]
(WIP) Restore stack trace for async function after await.

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

So I think this not quite the right approach, as explained.

Comment 11

[Tooru Fujisawa [:arai]]

I believe whether awaiting or not on the caller have nothing to do with callee's stack.

this is the output of the WIP patch.

Threw an exception: Error: tantrum
Exception's stack:
[e-mail]:3:9
[e-mail]:8:16
async function*[e-mail]:13:16
async function*[e-mail]:18:16
async function*@test.js:21:1

do you mean we should strip the last part?

Comment 12

[Tooru Fujisawa [:arai]]

Attachment: 01-Bug_1343158____WIP__Restore_stack_trace_.patch

anyway, I found that result Promise already has the stack for allocation site, that is the callsite of the async function, and it can be used for each resume.

Comment 13

[Mark Hammond [:markh] [:mhammond]]

(In reply to Jim Blandy :jimb from comment #8)
> I don't think that's quite right. I got Jason Orendorff to explain the big
> picture to me and he said something entirely different, so I may be wrong
> here. I'm going to needinfo him, as well as the original poster.
> 
> It seems to me that code like the below should actually print a stack like
> this:
> 
> Threw an exception: Error: tantrum
> Exception's stack:
> flaky@/home/jimb/moz/async-stack2.js:3:25
> inner@/home/jimb/moz/async-stack2.js:8:16
> middle@/home/jimb/moz/async-stack2.js:13:16
> outer@/home/jimb/moz/async-stack2.js:18:16

Agreed. However:

(In reply to Tooru Fujisawa [:arai] from comment #11)
> I believe whether awaiting or not on the caller have nothing to do with
> callee's stack.
> 
> this is the output of the WIP patch.
> 
> Threw an exception: Error: tantrum
> Exception's stack:
> [e-mail]:3:9
> [e-mail]:8:16
> async function*[e-mail]:13:16
> async function*[e-mail]:18:16
> async function*@test.js:21:1
> 
> do you mean we should strip the last part?

Looks fairly close - the column number in the first is wrong, and the additional entry at the end seems fine to me - but I suspect I'm not understanding the finer points of this discussion and it's already moved on, so I'm clearing needinfo.

Comment 14

[Tooru Fujisawa [:arai]]

(In reply to Mark Hammond [:markh] from comment #13)
> the column number in the first is wrong

9 is the beginning of |new Error("tantrum");|, that is the callsite of Error constructor that captures the stack.
so 9 is the correct column for the example.

Comment 15

[Tooru Fujisawa [:arai]]

any opinion on comment #11 ?

Comment 16

[Jim Blandy :jimb]

(In reply to Tooru Fujisawa [:arai] from comment #11)
> I believe whether awaiting or not on the caller have nothing to do with
> callee's stack.
> 
> this is the output of the WIP patch.
> 
> Threw an exception: Error: tantrum
> Exception's stack:
> [e-mail]:3:9
> [e-mail]:8:16
> async function*[e-mail]:13:16
> async function*[e-mail]:18:16
> async function*@test.js:21:1
> 
> do you mean we should strip the last part?

Okay, having looked at this a bit more carefully, I'm not sure that the last part is a problem at all. This is certainly the stack that I would want to see for the example I posted in comment 8, or at least a lot closer than what we get now. I think Jason agrees.

> anyway, I found that result Promise already has the stack for allocation
> site, that is the callsite of the async function, and it can be used for
> each resume.

Does using those stacks give the same results as shown in comment 11?

Comment 17

[Tooru Fujisawa [:arai]]

I read the discussion on IRC, and I think now I understand the whole issue here (especially past/future things) :)
I'll think a bit more about it.

(In reply to Jim Blandy :jimb from comment #16)
> (In reply to Tooru Fujisawa [:arai] from comment #11)
> > I believe whether awaiting or not on the caller have nothing to do with
> > callee's stack.
> > 
> > this is the output of the WIP patch.
> > 
> > Threw an exception: Error: tantrum
> > Exception's stack:
> > [e-mail]:3:9
> > [e-mail]:8:16
> > async function*[e-mail]:13:16
> > async function*[e-mail]:18:16
> > async function*@test.js:21:1
> > 
> > do you mean we should strip the last part?
> 
> Okay, having looked at this a bit more carefully, I'm not sure that the last
> part is a problem at all. This is certainly the stack that I would want to
> see for the example I posted in comment 8, or at least a lot closer than
> what we get now. I think Jason agrees.

thanks :)
for simple case that the past/future are same, the current patch should almost work.
I'll research how it works on more complicated cases (that call and await are separated).


> > anyway, I found that result Promise already has the stack for allocation
> > site, that is the callsite of the async function, and it can be used for
> > each resume.
> 
> Does using those stacks give the same results as shown in comment 11?

Yes, the Promise is created when the async function is called, at the same stack,
so the allocation site represents the same stack information as the async function gets called.

Comment 18

[:Paolo Amadini]

This blocks bug 1353542 which is high priority Photon work, and per bug 1353542 comment 1 it's also Quantum Flow.

I was indeed looking into converting some Task.jsm calls into async functions in xpcshell test, and couldn't do it because the test failures in helper functions are impossible to correlate to their caller if this bug is not fixed.

Comment 19

[Jim Blandy :jimb]

Comment on attachment 8842244 [details] [diff] [review]
01-Bug_1343158____WIP__Restore_stack_trace_.patch

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

Thank you very much for the patch.

This looks good to me, but it needs some tests in js/src/jit-test. If you have difficulty finding suitable examples of similar tests, let me know; I think I know where to find some.

Comment 20

[Jim Blandy :jimb]

Needinfo'ing Arai just to make sure we don't skip a cycle.

Comment 21

[Tooru Fujisawa [:arai]]

Attachment: Restore stack trace for async function after await.

thanks :)

Added a test to jstests, since there's already getPromiseResult testing function available.
the test checks if the stack contains expected lines, or doesn't contain unexpected lines,
before and after "await".

Comment 22

[Jim Blandy :jimb]

Comment on attachment 8857289 [details] [diff] [review]
Restore stack trace for async function after await.

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

Perfect, thanks very much!

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8417a09fdec3
Restore stack trace for async function after await. r=jimb

Comment 24

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Backed out for failing own test in Windows plain shell:

https://hg.mozilla.org/integration/mozilla-inbound/rev/a169c685cb1ce727610de9c8a3cf709c63e58c31

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=8417a09fdec380d7afe7751643c750b32e15b0c6&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=90949695&repo=mozilla-inbound

TEST-PASS | ecma_2017\AsyncFunctions\EarlyErrors.js | (args: "--ion-eager --ion-offthread-compile=off")
## ecma_2017\AsyncFunctions\ErrorStack.js: rc = 3, run time = 0.153
1343158: Error.stack should provide meaningful stack trace in async function
ecma_2017\AsyncFunctions\ErrorStack.js:66:5 Error: Assertion failed: got false, expected true: [stack: outer@ecma_2017\AsyncFunctions\ErrorStack.js:62:17\nasync*@ecma_2017\AsyncFunctions\ErrorStack.js:82:22\n]
Stack:
  outer@ecma_2017\AsyncFunctions\ErrorStack.js:66:5
  async*@ecma_2017\AsyncFunctions\ErrorStack.js:82:22
TEST-UNEXPECTED-FAIL | ecma_2017\AsyncFunctions\ErrorStack.js | (args: "")

Comment 25

[Tooru Fujisawa [:arai]]

totally forgot that separator is different on windows :P
https://treeherder.mozilla.org/#/jobs?repo=try&revision=8791dd985c5ea1971eb5490e4cfac020244789c5

Comment 26

[Tooru Fujisawa [:arai]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/aa5bbe2a55aa33e57240f233d40cc5d6655b6820
Bug 1343158 - Restore stack trace for async function after await. r=jimb

Comment 27

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

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