The dreaded "throwing after await"

[fasterthanlime]

This might be completely expected, I'm not completely up-to-date on the state of node.js, but:

Repro steps

git clone https://github.com/fasterthanlime/async-test && cd async-test
npm i
npm start

Versions

$ node --version
v8.0.0

$ npm list
async-test@1.0.0 C:\msys64\home\amwenger\Dev\async-test
`-- trace@3.0.0
  `-- stack-chain@1.3.7

Output

=================================
 Throwing first thing
=================================
Full stack trace:
Error: throwing first thing
    at cherrypie (C:\msys64\home\amwenger\Dev\async-test\index.js:12:13)
    at binomial (C:\msys64\home\amwenger\Dev\async-test\index.js:14:40)
    at abacus (C:\msys64\home\amwenger\Dev\async-test\index.js:15:38)
    at main (C:\msys64\home\amwenger\Dev\async-test\index.js:16:22)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\async-test\index.js:34:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at <anonymous>
    at checkStack (C:\msys64\home\amwenger\Dev\async-test\index.js:38:5)
    at main (C:\msys64\home\amwenger\Dev\async-test\index.js:16:11)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\async-test\index.js:34:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3


=================================
 Throwing after await
=================================
Full stack trace:
Error: after timeout
    at cherrypie (C:\msys64\home\amwenger\Dev\async-test\index.js:26:13)
    at <anonymous>
    at <anonymous>
    at checkStack (C:\msys64\home\amwenger\Dev\async-test\index.js:38:5)
    at main (C:\msys64\home\amwenger\Dev\async-test\index.js:30:11)
    at <anonymous>
    at runMicrotasksCallback (internal/process/next_tick.js:86:5)
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)
    at Function.Module.runMain (module.js:607:11)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3


didn't see abacus, bailing

Expected output

In the second trace, something like:

<snip>
Error: after timeout
    at cherrypie (C:\msys64\home\amwenger\Dev\async-test\index.js:26:13)
    at binomial (path:line)
    at abacus (path:line)
<snip>

[fasterthanlime]

N.B: turning

const binomial = async () => await cherrypie();

into

async function binomial () { await cherrypie(); }

appears to make no difference whatsoever.

[AndreasMadsen]

@fasterthanlime Thanks, that does look suspicious. I will look at it next week after I have handed in my master thesis. In the meantime, I recommend upgrading to node v8.1.x where we landed some changes to how promises show up in async_hooks and thus also trace (nodejs/node#13367).

[fasterthanlime]

Cool, thanks!

Here's the output with node v8.1.2:

=================================
 Throwing first thing
=================================
Full stack trace:
Error: throwing first thing
    at cherrypie (C:\msys64\home\amwenger\Dev\async-test\index.js:12:13)
    at binomial (C:\msys64\home\amwenger\Dev\async-test\index.js:14:40)
    at abacus (C:\msys64\home\amwenger\Dev\async-test\index.js:15:38)
    at main (C:\msys64\home\amwenger\Dev\async-test\index.js:16:22)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\async-test\index.js:34:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at <anonymous>
    at checkStack (C:\msys64\home\amwenger\Dev\async-test\index.js:38:5)
    at main (C:\msys64\home\amwenger\Dev\async-test\index.js:16:11)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\async-test\index.js:34:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at <anonymous>
    at checkStack (C:\msys64\home\amwenger\Dev\async-test\index.js:38:5)
    at main (C:\msys64\home\amwenger\Dev\async-test\index.js:16:11)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\async-test\index.js:34:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3


=================================
 Throwing after await
=================================
Full stack trace:
Error: after timeout
    at cherrypie (C:\msys64\home\amwenger\Dev\async-test\index.js:26:13)
    at <anonymous>
    at <anonymous>
    at checkStack (C:\msys64\home\amwenger\Dev\async-test\index.js:38:5)
    at main (C:\msys64\home\amwenger\Dev\async-test\index.js:30:11)
    at <anonymous>
    at runMicrotasksCallback (internal/process/next_tick.js:86:5)
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)
    at Function.Module.runMain (module.js:607:11)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at <anonymous>
    at checkStack (C:\msys64\home\amwenger\Dev\async-test\index.js:38:5)
    at main (C:\msys64\home\amwenger\Dev\async-test\index.js:30:11)
    at <anonymous>
    at runMicrotasksCallback (internal/process/next_tick.js:86:5)
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)
    at Function.Module.runMain (module.js:607:11)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3

[AndreasMadsen]

Thanks, I didn't really expect the upgrade to fix it.

It looks like there is another bug, at bootstrap_node.js:575:3 should never occur more than once per trace. I did suspect this bug existed but I could never create it. This is awesome, thanks.

[fasterthanlime]

Happy to help!

I have a whole suite of tests like that, because I was tired of getting useless stack traces in my error reports: https://github.com/itchio/itch/blob/cead3ba6bcbe5c46f57dc6b95b01763e73a87420/src/confidence/stacktrace.spec.ts

My current solution is using babel to transpile all Promise code to bluebird, and enable bluebird's longStackTraces collection. Which works well enough, but I feel like native v8 promises + async_hooks should be faster, since bluebird Promises are coroutine-based.

There's literally 0 time pressure on this though - before I can switch to native promises + async_hooks, electron has to release with node v8.0.0, and that'll probably take a few weeks!

[AndreasMadsen]

Your "Throwing first thing" creates 13 Promise instances, I'm having some trouble identifying them all. Could you demonstrate the issue where async/await is ported to the new Promise(), .then(), and .catch() API.

edit: I have pushed a new master that removes some of the at bootstrap_node.js:575:3 duplicates. Not all of them can be removed (or should be removed) as some of them are due to how node.js executes the microtask queue in combination with nextTick.

[fasterthanlime]

Your "Throwing first thing" creates 13 Promise instances, I'm having some trouble identifying them all. Could you demonstrate the issue where async/await is ported to the new Promise(), .then(), and .catch() API.

Interesting, the issue doesn't seem to appear with pure promises

• Repo is at https://github.com/fasterthanlime/promise-test

$ npm start

> async-test@1.0.0 start C:\msys64\home\amwenger\Dev\promise-test
> node --stack_trace_limit=100 index.js

=================================
 Throwing first thing
=================================
Full stack trace:
Error: throwing first thing
    at Promise (C:\msys64\home\amwenger\Dev\promise-test\index.js:11:12)
    at Promise (<anonymous>)
    at cherrypie (C:\msys64\home\amwenger\Dev\promise-test\index.js:10:27)
    at binomial (C:\msys64\home\amwenger\Dev\promise-test\index.js:13:26)
    at abacus (C:\msys64\home\amwenger\Dev\promise-test\index.js:14:24)
    at firstThing (C:\msys64\home\amwenger\Dev\promise-test\index.js:15:21)
    at main (C:\msys64\home\amwenger\Dev\promise-test\index.js:34:3)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\promise-test\index.js:37:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at Promise.catch (<anonymous>)
    at checkStack (C:\msys64\home\amwenger\Dev\promise-test\index.js:43:11)
    at firstThing (C:\msys64\home\amwenger\Dev\promise-test\index.js:15:10)
    at main (C:\msys64\home\amwenger\Dev\promise-test\index.js:34:3)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\promise-test\index.js:37:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at Promise.then (<anonymous>)
    at checkStack (C:\msys64\home\amwenger\Dev\promise-test\index.js:40:18)
    at firstThing (C:\msys64\home\amwenger\Dev\promise-test\index.js:15:10)
    at main (C:\msys64\home\amwenger\Dev\promise-test\index.js:34:3)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\promise-test\index.js:37:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at Promise (<anonymous>)
    at cherrypie (C:\msys64\home\amwenger\Dev\promise-test\index.js:10:27)
    at binomial (C:\msys64\home\amwenger\Dev\promise-test\index.js:13:26)
    at abacus (C:\msys64\home\amwenger\Dev\promise-test\index.js:14:24)
    at firstThing (C:\msys64\home\amwenger\Dev\promise-test\index.js:15:21)
    at main (C:\msys64\home\amwenger\Dev\promise-test\index.js:34:3)
    at Object.<anonymous> (C:\msys64\home\amwenger\Dev\promise-test\index.js:37:1)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)
    at Function.Module._load (module.js:458:3)
    at Function.Module.runMain (module.js:605:10)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3

=================================
 Throwing after await
=================================
Full stack trace:
Error: after timeout
    at Promise.then (C:\msys64\home\amwenger\Dev\promise-test\index.js:26:13)
    at <anonymous>
    at Promise.catch (<anonymous>)
    at checkStack (C:\msys64\home\amwenger\Dev\promise-test\index.js:43:11)
    at secondThing (C:\msys64\home\amwenger\Dev\promise-test\index.js:30:10)
    at firstThing.then (C:\msys64\home\amwenger\Dev\promise-test\index.js:34:27)
    at <anonymous>
    at runMicrotasksCallback (internal/process/next_tick.js:86:5)
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)
    at Function.Module.runMain (module.js:607:11)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at Promise.then (<anonymous>)
    at checkStack (C:\msys64\home\amwenger\Dev\promise-test\index.js:40:18)
    at secondThing (C:\msys64\home\amwenger\Dev\promise-test\index.js:30:10)
    at firstThing.then (C:\msys64\home\amwenger\Dev\promise-test\index.js:34:27)
    at <anonymous>
    at runMicrotasksCallback (internal/process/next_tick.js:86:5)
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)
    at Function.Module.runMain (module.js:607:11)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at Promise.then (<anonymous>)
    at cherrypie (C:\msys64\home\amwenger\Dev\promise-test\index.js:25:6)
    at binomial (C:\msys64\home\amwenger\Dev\promise-test\index.js:28:26)
    at abacus (C:\msys64\home\amwenger\Dev\promise-test\index.js:29:24)
    at secondThing (C:\msys64\home\amwenger\Dev\promise-test\index.js:30:21)
    at firstThing.then (C:\msys64\home\amwenger\Dev\promise-test\index.js:34:27)
    at <anonymous>
    at runMicrotasksCallback (internal/process/next_tick.js:86:5)
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)
    at Function.Module.runMain (module.js:607:11)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3
    at Promise (<anonymous>)
    at cherrypie (C:\msys64\home\amwenger\Dev\promise-test\index.js:24:5)
    at binomial (C:\msys64\home\amwenger\Dev\promise-test\index.js:28:26)
    at abacus (C:\msys64\home\amwenger\Dev\promise-test\index.js:29:24)
    at secondThing (C:\msys64\home\amwenger\Dev\promise-test\index.js:30:21)
    at firstThing.then (C:\msys64\home\amwenger\Dev\promise-test\index.js:34:27)
    at <anonymous>
    at runMicrotasksCallback (internal/process/next_tick.js:86:5)
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)
    at Function.Module.runMain (module.js:607:11)
    at startup (bootstrap_node.js:158:16)
    at bootstrap_node.js:575:3

[AndreasMadsen]

@fasterthanlime Well I'm no expert in async/await, but I'm pretty sure you can't just remove the async and await statements.

(async () => {})() corresponds to new Promise( () => {}) and await promise; corresponds to .then(() => promise), or something like that.

[fasterthanlime]

@fasterthanlime Well I'm no expert in async/await, but I'm pretty sure you can't just remove the async and await statements.

(async () => {})() corresponds to new Promise( () => {}) and await promise; corresponds to .then(() => promise), or something like that.

That's what I did though :)

 const cherrypie = () =>
    new Promise((resolve, reject) => setTimeout(resolve, 200))
    .then(() => {
      throw new Error(`after timeout`);
    })

These all behave the same:

// relay the original promise
const v1 = () => functionReturningPromise();

// wrap the original promise - if it resolves the wrapper
// will resolve, if it rejects the wrapper will reject
const v2 = () => Promise.resolve(functionReturningPromise());

// async functions "rethrow" rejections and can "return"
// resolved values asynchronously
const v3 = async () => await functionReturningPromise();

// don't write that ;)
const v4 = () => {
  return new Promise((resolve, reject) => {
    functionReturningPromise().then(resolve).catch(reject);
  });
}

edit: I should clarify - according to my understanding of async/await and promises, those should all: resolve or reject according to whatever the Promise returned by functionReturningPromise does, and should make both vx and functionReturningPromise appear in the ideal stack trace. I have no doubt that they all have subtle implementation differences though.

The noise bothers me a lot less than missing frames :)

[AndreasMadsen]

I have no doubt that they all have subtle implementation differences though.

They have subtle differences in the standard too. It is about how many rounds the microtask queue take. Promise.resolve(1).then((val) => Promise.resolve(val)).then(...) results in the same as Promise.resolve(1).then(...) but they behave slightly differently.

The noise bothers me a lot less than missing frames :)

I know, but that was an issue I understood :)

[AndreasMadsen]

Okay, I have reduced it to promises. It is not exactly the same but the issue is the same:

throwing first thing:

'use strict';

function binomial() {
  return new Promise(function binomialPromise() {
    throw new Error('throwing first thing');
  });
}

function abacus() {
  return Promise.resolve().then(function abacusThen() {
    return binomial();
  });
}

abacus().catch(function (e) {
  process._rawDebug(e);
});

Error: throwing first thing
    at binomialPromise (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:5:11)
    at binomial (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:4:10)
 ** at abacusThen (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:11:12)
    at Object.<anonymous> (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:15:15)
    at abacus (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:10:28)
    at abacus (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:10:18)
    at Object.<anonymous> (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:15:1)

after timeout:

'use strict';

function binomial() {
  return Promise.resolve(/* timeout */).then(function binomialThen() {
    throw new Error('after timeout');
  });
}

function abacus() {
  return Promise.resolve().then(function abacusThen() {
    return binomial();
  });
}

abacus().catch(function (e) {
  process._rawDebug(e);
});

Error: after timeout
    at binomialThen (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:5:11)
    at Object.<anonymous> (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:15:15)
    at abacus (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:10:28)
    at abacus (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:10:18)
    at Object.<anonymous> (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:15:1)

[AndreasMadsen]

I have debugged it some more. The stack trace is actually correct, the problem is that v8 calls Error.prepareStackTrace when .stack is called and not when new Error() is called.

I will think about possible solutions to this, but I'm not sure it can be fixed.

throwing first thing

async function binomial() {
  const a = new Error('throwing first thing'); a.stack; throw a;
}

async function abacus() {
  await binomial();
}

async function main() {
  try {
    await abacus();
  } catch (e) {
    process._rawDebug(e.stack);
  }
}

main();

Error: throwing first thing
    at binomial (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:3:13)
    at abacus (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:7:9)
    at main (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:12:11)
    at Object.<anonymous> (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-first.js:18:1)

after timeout

async function binomial() {
  await Promise.resolve(/* timeout */);
  const a = new Error('after timeout'); a.stack; throw a;
}

async function abacus() {
  await binomial();
}

async function main() {
  try {
    await abacus();
  } catch (e) {
    process._rawDebug(e.stack);
  }
}

main();

Error: throwing first thing
    at binomial (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:4:13)
    at binomial (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:3:3)
    at binomial (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:3:3)
    at abacus (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:8:9)
    at main (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:13:11)
    at Object.<anonymous> (/Users/Andreas/Sites/node_modules/trace/test/scripts/await-throwing-second.js:19:1)

[fasterthanlime]

Ah, so the only way out would be to have a new hook in node when it creates the Exception (rather than when .stack is accessed for the first time)?

[AndreasMadsen]

Ah, so the only way out would be to have a new hook in node when it creates the Exception (rather than when .stack is accessed for the first time)?

Yep. I tried overwriting global.Error and Error.captureStackTrace non of those allowed me to get notified, so an extra hook is needed. Allowing Error.captureStackTrace to be overwritten or extended, seems like the most straight-forward approach.

---

The primary reason for lazy creation of .stack is the string generation takes time. I think a good solution is to continue to delay the .stack formatting, but allow the callSite array to be modified upon new Error creation.