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.

[hashseed]

Generators are resumed from user code. Async functions are resumed from the micro task queue.

[AndreasMadsen]

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

Because it can be solved in userland, once the building blocks are in place. Node.js has always aimed at keeping the core minimal and instead embrace external modules, only things that are really difficult to implement in userland end up in node core. trace is an 80 lines module (with mostly comments), so arguably it is not that hard. There are also different ways of implementing it, which involves tradeoffs between speed, memory, completeness, and usability. We will likely see different modules, that prioritize differently.

I would say that trace prioritizes memory and completeness, while longjohn prioritizes speed and usability (but I'm likely biased).

Generators are resumed from user code. Async functions are resumed from the micro task queue.

Correct. There is a second concern involving promises. Previously new Promise() was used in combination with generators, this allowed long-stack-trace implementations to monkey-patch global.Promise and essentially implement a PromiseHook C++ API approximation this way. async function consistently returns a promise using a v8 internal reference (not global.Promise), thus monkey-patching global.Promise is not enough.

[Trott]

This issue has been inactive for sufficiently long that it seems like perhaps it should be closed. Feel free to re-open (or leave a comment requesting that it be re-opened) if you disagree. I'm just tidying up and not acting on a super-strong opinion or anything like that.

[TazmanianD]

I would like to argue that this issue be re-opened. If for no other reason than it can be a place to report on any kind of progress that's made on adding better support for stack traces in Node. I think there is a legitimate gap in functionality here and until that gap can be closed, I would argue this issue should stay open.

[jasnell]

I've reopened it. Also, I've changed it from "question" to "feature request"

[TazmanianD]

Thanks! And to put a point on the real problem, imagine my database layer throws an error like the following:

error: syntax error at end of input
    at Connection.parseE (C:\Project\node_modules\pg\lib\connection.js:567:11)
    at Connection.parseMessage (C:\Project\node_modules\pg\lib\connection.js:391:17)
    at Socket.<anonymous> (C:\Project\node_modules\pg\lib\connection.js:129:22)
    at emitOne (events.js:96:13)
    at Socket.emit (events.js:191:7)
    at readableAddChunk (_stream_readable.js:178:18)
    at Socket.Readable.push (_stream_readable.js:136:10)
    at TCP.onread (net.js:560:20)

How is this information useful to me especially if it occurred in production where I don't know what caused it? There is not a single line of code in that stack from my code and the error from the library I'm using doesn't even tell me what's really wrong. I would have absolutely no hope of figuring out what the cause of this was without reviewing every single database statement in my code.

Am I in the minority here that thinks this is major issue in trying to deal with problems?

[TazmanianD]

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

Because it can be solved in userland, once the building blocks are in place. Node.js has always aimed at keeping the core minimal and instead embrace external modules, only things that are really difficult to implement in userland end up in node core.

And I guess I would like to challenge this as well. It seems to me that as something as fundamental as getting a full stack out of errors from my code is exactly what I would expect from my runtime platform. I'm not sure the argument that there are tradeoffs works in this particular case. I would argue that almost any reasonable production environment is going to want a feature like this and implemented in a way that doesn't have major downsides (like a huge performance hit). If such a thing can be done, almost everyone is going to want it and if it can't be done, almost nobody is going to want it. I don't see a lot of room for options here so giving me choices doesn't make me feel any better.

[jbinto]

@TazmanianD +1. I've been keeping myself sane by using transform-async-to-generator, and using Bluebird with long stack traces. I'm sure I'm missing out on performance gains from native async/await, but just like you I couldn't handle dealing with context-free stack traces.

[bjouhier]

You are not a minority. There is a secret solution called coroutines. Other languages like golang have them and they can also be enabled in node.js (npm install fibers or npm install f-promise (better interop with promises)).

Benefits: 1) you can eliminate 99% of your async/await syntax overhead, 2) perfect stack traces (without performance overhead - actually the opposite)

[TazmanianD]

and using Bluebird with long stack traces.

From their own documentation:

Long stack traces imply a substantial performance penalty, around 4-5x for throughput`

Which I would consider unacceptable for production use. The irony here is that the major argument in favor of the asynchronous model of Node is precisely for performance reasons and if the first thing you do is something to kill performance precisely as a consequence of that model, you gotta ask what the point in using Node is :-).

npm install fibers or npm install f-promise

Oh man, you're my hero! It sounds like fibers is exactly what I've been wanting and I can see how they solve a bunch of different problems. I just played with it a bit but this may be a "user space" solution to my original problem that I'm actually happy with.

I did give your f-promise library a try and one thing I noticed in a simple benchmark is that it does appear to be just a tad slower than using generators or async/await (about 2%). Is that a surprise? Of course such a small cost is totally worth the benefit.

There does seem to be a bunch of libraries built on top of fibers. Care to make an argument for yours over the others? You might want to consider having your library added to their list: https://github.com/laverdet/node-fibers/wiki.

[bjouhier]

Fibers' overhead depends on your code patterns. If you are writing low level code which is completely dominated by callbacks (each callback doing little work, with shallow stacks) I would not recommend fibers because of the overhead of switching into a fiber in every callback.

On the other hand, as soon as you start to have a somewhat thick layer of logic on top of async calls, then coroutines are a winner. An async function calling another async function will not involve any intermediate promise creation / promise resolution overhead; it will just be a direct, normal function call (this is why you get perfect stack traces for free). So the deeper your stacks, the more you gain.

And this is no toy. Some frameworks (Meteor) have been built with fibers. The project I am involved with has been using it for 5+ years. We used it hidden under a preprocessor (streamline.js) initially, which gave us the option to swap fibers for pure callbacks or generators (in case something went wrong with fibers). But the newer parts of the project are now written with f-promise.

One important gotcha: fibers does not run in browsers, as it requires a binary add-on. I hope that coroutines will make it into JavaScript some day but there has been very strong resistance so far (the single-frame continuation rule).

The main selling point of my little library: the simplicity of its API (2 calls) and the ease of interop with promises (and callbacks too - just noticed this was not documented so I added it to the README). I also designed it to be a natural upgrade for the streamline.js community (CLS feature is compatible). But just google around and you'll find other libraries.

[rektide]

V8 now offers an --async-stack-traces flag! See: https://github.com/v8/v8.dev/pull/49/files#diff-af1399a75d6310211a72be0dc2571ea5R44

I'm not sure what if any Node's support this new V8 capability.

[moberemk]

Current release (Node 11) just updated to v8 7.0; looks like the async stack traces are coming in 7.1 if I'm reading this right, so hopefully it'll be coming soon.

[hashseed]

This V8 feature is still experimental and depends on a spec change to a particular detail of async/await. It also isn't able to reconstruct the full stack trace in some cases. But it's better than nothing. I hope you can use it by Node 12, but you probably can already check it out with Node Canary.

[ustun]

Just confirmed that the node version at https://nodejs.org/download/v8-canary/v12.0.0-v8-canary20181217e2f11a7b92/ supports the --async-stack-traces flag mentioned in the article at v8 blog.

[advance512]

@eliranamar
Async stack traces @ 12.0

[bjarketrux]

Detailed information about the implementation: https://docs.google.com/document/d/13Sy_kBIJGP0XT34V1CV3nkWya4TwYx9L3Yv45LdGB6Q/edit

[gajus]

Is --async-stack-traces required in v12?

[BridgeAR]

@gajus no. Those are tracked by default.

[jedwards1211]

Are async stack traces supposed to work inside catch blocks? Or does it depend on the intervening code to have an async chain? They're missing for me with code like this in Node 12.16.2 at least... (connection.query involves event emitters under the hood)

I had hoped that the new Promise created within the method would guarantee that the async stack trace gets added to whatever rejection error.

async query(sql, parameters) {
  try {
    await new Promise((resolve, reject) => connection.query(sql, (error, result) => error ? reject(error) : resolve(result)));
  } catch (err) {
    // None of these include the async stack traces...
    console.error(err.stack)
    console.error(new Error('Test').stack)
    throw new Error('Test')
  }
  // but if we get here than this error does get the async stack trace
  throw new Error('Test')
}

[jeremysmith1]

@TazmanianDI Edward j

[klesun]

And here comes node v15.11.0 with unhandled promises forcefully quitting the app by default, but stack traces still don't include lines beyond /node_modules/:

klesun@klesuns-MacBook-Pro boost-portal % node --async-stack-traces server.js

/Users/klesun/gits/archived/boost-portal/node_modules/web3-core-helpers/lib/errors.js:43
        return new Error(message);
               ^
Error: Invalid JSON RPC response: "user project is inactive\n"
    at Object.InvalidResponse (/Users/klesun/gits/archived/boost-portal/node_modules/web3-core-helpers/lib/errors.js:43:16)
    at XMLHttpRequest.request.onreadystatechange (/Users/klesun/gits/archived/boost-portal/node_modules/web3-providers-http/lib/index.js:95:32)
    at XMLHttpRequestEventTarget.dispatchEvent (/Users/klesun/gits/archived/boost-portal/node_modules/xhr2-cookies/xml-http-request-event-target.ts:44:13)
    at XMLHttpRequest._setReadyState (/Users/klesun/gits/archived/boost-portal/node_modules/xhr2-cookies/xml-http-request.ts:219:8)
    at XMLHttpRequest._onHttpResponseEnd (/Users/klesun/gits/archived/boost-portal/node_modules/xhr2-cookies/xml-http-request.ts:345:8)
    at IncomingMessage.<anonymous> (/Users/klesun/gits/archived/boost-portal/node_modules/xhr2-cookies/xml-http-request.ts:311:39)
    at IncomingMessage.emit (node:events:390:22)
    at endReadableNT (node:internal/streams/readable:1307:12)
    at processTicksAndRejections (node:internal/process/task_queues:81:21)

back to console.log binary searching the codebase ;c