Missing stack traces from async functions after the first await

[TazmanianDI]

Version: v7.7.3
Platform: Windows 7x64

The purpose of this issue is really a more broad request for better stack traces with async/await but I figured I would start with a very specific case. If we need to broaden the description, I'm good with that. I've seen a number of lengthy discussion on this subject in various places but I don't see any actual issues for it so I thought I'd start one and hopefully it's not just a duplicate of something I missed.

I'm filing the specific issue here because it seems the async/await functionality just added provides less useful error handling than we could get with generators.

async function functionOne() {
  await new Promise((resolve) => {
    setTimeout(() => { resolve(); }, 1);
  });
  throw new Error('Something Bad');
}

async function functionTwo() {
  await functionOne();
}

functionTwo()
  .catch((error) => {
    console.error(error);
  });

Outputs:

Error: Something Bad
    at functionOne (C:\Work\sandbox.js:5:9)

That stack is missing everything that called functionOne (functionTwo specifically).

The generator equivalent of this:

const co = require('co');

function* functionOne() {
  yield new Promise((resolve) => {
    setTimeout(() => { resolve(); }, 1);
  });
  throw new Error('Something Bad');
}

function* functionTwo() {
  yield* functionOne();
}

co(functionTwo())
  .catch((error) => {
    console.log(error);
  });

Outputs:

Error: Something Bad
    at functionOne (C:\Work\sandbox.js:7:9)
    at functionOne.next (<anonymous>)
    at functionTwo (C:\Work\sandbox.js:11:10)
    at functionTwo.next (<anonymous>)
    at onFulfilled (C:\Work\NPS\nps-dev\node_modules\co\index.js:65:19)

Here you can see both functionOne and functionTwo in the stack.

If the error is thrown before any await in the code, then you actually get a complete stack trace even if the function was called in a whole chain of awaits and regardless if those awaits were first or not:

async function throwFunction() {
  throw new Error('Something bad');
}

async function functionOne() {
  return await throwFunction();
}

async function functionTwo() {
  return await Promise.resolve();
}

async function functionThree() {
  await functionTwo();
  return await functionOne();
}

functionThree()
  .catch((error) => {
    console.log(error);
  });

Outputs:

Error: Something bad
    at throwFunction (C:\Work\sandbox.js:2:9)
    at functionOne (C:\Work\sandbox.js:6:16)
    at functionThree (C:\Work\sandbox.js:15:16)
    at process._tickCallback (internal/process/next_tick.js:109:7)
    at Module.runMain (module.js:607:11)
    at run (bootstrap_node.js:425:7)
    at startup (bootstrap_node.js:146:9)
    at bootstrap_node.js:540:3

The real driving force behind this was that I finally found the recipe to get complete stack traces, even when dealing with existing code using promises. With a try...catch in the generator, we can use VError to weld together the errors thrown by promises with the stack of the code calling the generator. This does not seem to work with async functions.

Here's a more complete example using generators that I really wish would continue to work with async functions:

const co = require('co');
const VError = require('verror');

function calledFromAPromise() {
  throw new Error('Something bad');
}

function doAPromise() {
  return new Promise((resolve) => {
    setTimeout(() => { resolve(); }, 1);
  })
    .then(() => { calledFromAPromise(); });
}

function* queryFunction() {
  return yield* yieldRethrow(doAPromise());
}

function* functionOne() {
  return yield* queryFunction();
}

function* functionTwo() {
  return yield* functionOne();
}

function* yieldRethrow(iterable) {
  try {
    return yield iterable;
  } catch (error) {
    throw new VError(error);
  }
}

co(functionTwo())
  .catch((error) => {
    console.log(error);
  });

Outputs (with some non-relevant stuff removed):

{ VError: : Something bad
    at yieldRethrow (C:\Work\sandbox.js:31:11)
    at yieldRethrow.throw (<anonymous>)
    at queryFunction (C:\Work\sandbox.js:16:17)
    at functionOne (C:\Work\sandbox.js:20:17)
    at functionTwo (C:\Work\sandbox.js:24:17)
    at onRejected (C:\Work\NPS\nps-dev\node_modules\co\index.js:81:24)
  jse_cause: 
   Error: Something bad
       at calledFromAPromise (C:\Work\sandbox.js:5:9)
       at Promise.then (C:\Work\sandbox.js:12:19),

The async equivalent outputs this:

{ VError: : Something bad
    at yieldRethrow (C:\Work\sandbox.js:30:11)
  jse_cause: 
   Error: Something bad
       at calledFromAPromise (C:\Work\sandbox.js:4:9)
       at Promise.then (C:\Work\sandbox.js:11:19),

As you can see, this has the same problem as at the top in that the rethrown error doesn't have a complete stack.

[richardlau]

Cc @nodejs/diagnostics

[hashseed]

That's because Error.stack only reflects the actual stack. The inspector provides async stack traces, but Error.stack will never include the async parts due to the overhead of collecting it.

[scottmas]

Wouldn't it be nice if there was a way to enable async stack traces via a flag or something? Or when NODE_ENV === 'development' and the like?

The overhead is huge, but there are cases when developers will want Error.stack to generate async errors for them.

[hashseed]

You could run node with --inspect and enable async stack trace in DevTools.

[scottmas]

I'm thinking something more command-liney would be better. Personally, I only use Chrome DevTools when I really want to figure out precisely what's happening. But most of the time, developers just want informative stack traces in their terminal.

[cjihrig]

something more command-liney would be better

Would node -r longjohn work for you?

[scottmas]

Arrr, meehaps

[jkrems]

Would it be possible to add a V8 option that enables async error stacks for "normal" error.stack properties? Or would that be too risky?

[gsathya]

We have promisehooks in V8 that will help you build these async stack traces. Node can use this API to expose an async stack trace.

[AndreasMadsen]

The @nodejs/diagnostics plan for solving this is:

1. upgrade to V8 5.7, this contains the PromiseHook C++ API – PR deps: update V8 to 5.7 #11752
2. Integrate PromiseHook C++ API to async_hooks and land async_hooks – PR: async_hooks initial implementation #11883
3. This will allow module authors to create a long-stack-trace model that always works.

This problem is unlikely to be solved by node core directly, we will just give the tools to module authors such that they can solve it. For example I have written https://github.com/AndreasMadsen/trace, which uses an undocumented version of async_hooks. This won't solve this issue as is, because we still don't have the PromiseHook C++ API, but it will eventually be updated.

[scottmas]

Just so I understand, what's the reasoning behind solving this in userland instead of node core?

[TazmanianDI]

And I guess the question I have is what changed? This problem didn't seem to exist with the equivalent generator code. I understand there are technical differences between generators and async/await but the fundamental idea that the VM pauses execution and then resumes seems the same and yet when we did that with generators, the full stack trace was available.