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 https://github.com/nodejs/node/pull/11752
2. Integrate PromiseHook C++ API to async_hooks and land async_hooks – PR: https://github.com/nodejs/node/pull/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.

[AndreasMadsen]

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.

There is no magic solution. I'm not saying it is impossible, but it is very difficult. The day we have high-performance long stack traces that works across all asynchronous boundaries (not just promises), then I will take a long vacation and stop working on node-core.

Until then, imperfect solutions with different trade-offs will have to compete.

[BridgeAR]

I honestly think there is very little we can do here because looking at the stack will always have a high performance penalty. I am certain that as soon as there is something that could be done, it will also be done. Having a feature request for this does not really help a lot. Therefore I tend to closing this again and to remove the feature request label (besides the fact that it is a question and a feature request at the moment). @AndreasMadsen what do you think?

[AndreasMadsen]

@BridgeAR as I understand it, looking at the stack isn't really the expensive part, it is translateing the addresses to JavaScript callsites. So in theory, if there is an immutable data structure for that, then it only get expensive when actually printing the stack. But such a data structure is unlikely with a JIT runtime.

This feature request is definitely on V8 to implement, node already have the hooks for DevTools so our side isn't the problem.

I'm fine with closing this if there is a v8 issue.

[BridgeAR]

CC @nodejs/v8

[TimothyGu]

@AndreasMadsen Async stack trace is already available through Dev Tools / V8 Inspector after https://github.com/nodejs/node/pull/13870 (which integrates async_hooks with Inspector integration).

[AndreasMadsen]

Async stack trace is already available through Dev Tools / V8 Inspector after #13870 (which integrates async_hooks with Inspector integration).

Yes, that is what I said.

node already have the hooks for DevTools so our side isn't the problem.

There is nothing more we can do right now.

[TazmanianD]

Well it appears to me that fibers is a genuine solution to the problem which tells me that it obviously can be solved. Now that's not entirely fair because fibers is a much larger solution that does things you guys have obviously chosen to not include in node core.

What's still unclear to me is that if there is something on the V8 side that they can implement that would improve things for Node, either in node core or in user space. If there are things in V8 that have some reasonable plan for, I would argue keeping this open until then (as long as there is some reasonable timeframe). But given what I see in fibers so far, I won't complain if you want to just close this :-).

In any event, I think there's some possible room for some documentation or introduction from the Node team. I've been a Java developer for many years and a year ago I switched to a team using Node and decided to give it a try. I hated it and the top two reasons were callback hell and useless stack traces (which should tell you just how strongly I felt about this issue). Those two along with my displeasure in the weakly type nature of Javascript nearly turned me into an active opponent of Node. Fortunately, I eventually discovered solutions to all of my complaints. Promises help a little and generators/async/await/fibers are all total solutions to callback hell. Typescript is a 90% solution to my typing issue and up till now, I found generators to be a 75% solution to the stack trace problem (but not async/await which is why I started this issue).

So I've gone from almost being an active opponent to maybe not quite a fan but trending in that direction. But it took me an entire year to go through that process. I was working with people who had been using Node for years and they barely knew promises and nothing about generators and certainly not fibers. If you look at the getting started guide on Node's main home page, there is no mention of any of these additional technologies and every one of the examples shows off the usage of callbacks.

Perhaps you should consider some sort of "Node for Java developers" article that explains the pitfalls and potential solutions that someone like me can have. I gather you guys are taking a fairly agnostic approach to telling users what to do with Node and don't want to pick sides or recommend external modules or libraries but I think by not doing so, you leave a lot of people to the random luck of the internet to stumble across solutions to really common problems.

[alexkozy]

Looking at the stack is not expensive, as well as resolving could be not expensive if we correctly cache symbolized frames (as was measured in the wild there are not a lot of unique call frames). Currently we can speedup cache lookup I think 2 times if we remove support of Function.prototype.displayName from V8. I'm not sure how useful is this feature - displayName allows to change function name in stacks from JS runtime. [1] Or at least we can limited this feature that displayName can be changed only once before first call of this function.

AFAIR, penalty for promise.prototype.then was around 3-4 times slower, mostly because promise.prototype.then is super fast by itself. For Chromium setTImeout, setInterval and requestAnimationFrame async stack enabled/disabled almost non-observable from performance point of view. I can double check numbers.

Another point that in the world where we use async functions instead of promises, async stacks potentially can be very fast. Since it's enough to store only one pointer from one generator to another to reconstruct async stack trace.

[1] https://cs.chromium.org/chromium/src/v8/src/isolate.cc?rcl=5ec87e41b4b216167e449f2bf477459e93d72907&l=686

[AndreasMadsen]

@ak239 A problem we are having with async_hooks and async stack traces is that Error.prepareStackTrace is called lazily, thus when Error.prepareStackTrace is called the async context is the context of error.stack and not new Error(). Would it be possible to get notified when an error is created and similarly when Error.captureStackTrace is called?

We don't actually need to build the error string when a new error is created, we just need to get notified to set the context.

This won't be a fast solution but it a very good solution when performance isn't a concern.

see https://github.com/AndreasMadsen/trace/issues/34 for the original discussion. /cc @fasterthanlime

[TazmanianD]

One note I would make on performance is that ideally the system under normal operation wouldn't have any noticeable performance impact. If building the stack traces is slow, but only when an error actually occurs, I would say that's quite acceptable. We're taught in the Java world that exceptions are expensive and you should only use them in exceptional circumstances and not as a means of normal control flow.

[ejoebstl]

I came here looking for a way to show proper stacktraces when using async-await in node.js.

Until this feature is finished, using Bluebird promises with BLUEBIRD_LONG_STACK_TRACES=1 can serve as a workaround.

[capaj]

@ejoebstl that does not help for this particular issue. Long stack traces help if you're using raw promises. With await the stack is blown away every time-see my issue https://github.com/tgriesser/knex/issues/2500 for example

[jbunton-atlassian]

Hi there. I think I've solved this in trace PR #40. I'd love any feedback or testing anybody could give this code :)

You can try it out by installing it from my repo:

npm install 'git://github.com/jbunton-atlassian/trace#a4e78d89e09ab4830f302bf85a30a528a5746e0b'

[ejoebstl]

@capaj Depends. If you use i.e. babel or babel-node with transform-async-to-promises it works. A lot of people seem to use this setup.

In my specific case, I was using it for unit tests and it was just what I needed. I agree that this is a hack, and the underlying issue should be fixed as soon as possible.

[gregberge]

I experienced the same issue, how can I help?

[shkkmo]

I don't really need a whole stack, I really just need the freaking line number for the error. This should be a basic functionality for any coding tool. How does this not work in node?

[bnoordhuis]

@shkkmo Your description is lacking but it sounds like a different issue. File a new bug if you have a no third-party deps test case.

Regarding this issue, I think we should close it out. It's been discussed by knowledgeable people and if the consensus is that there are good reasons for why things are the way they are, then there's no point in keeping it open.

[BridgeAR]

Closed due to the mentioned reasons.

[ak1394]

Hm. I'm very happy that this issue has been been discussed by knowledgeable people, but I would appreciate a bit more of a background info. What is the proposed way to get the stack trace in this case?

[moberemk]

Yeah, this is a massive headache for end users. For those of us who want to use async/await as intended, with native Promises, this requires us to make use of workarounds or hacks to get any useful debug information.

Who's intended to take care of this now? Is it supposed to be a v8 problem? If so, a link to a relevant place to follow up and track this would be incredible. If the solution is "there is no solution, use Bluebird/userland trace libraries/go back to callback hell" well...that'd be really good to know before building any more projects in Node.

[johan13]

I know that the Node.js guys want keep everything that can be done in userland out of the core. But to me, generating stack traces seems like an important enough feature to make an exception.

[bnoordhuis]

@aleksey-bykov You already got a warning and deletion further up this thread. Don't let it happen again.

[TazmanianD]

I do want to add a last shout-out for the solution mentioned above that has been working for me. I've been using Node fibers and the f-promise library for a short while now and it's been great. It is effectively a solution to this problem and I highly recommend it.

[ak1394]

@TazmanianDI well, it might be a good solution for a new project, but for existing codebases 'rewrite using new library' doesn't sound too appealing.

[johan13]

I'm using trace for debugging. For production the performance penalty is too big, but it does give you resonable stack traces. It works with native Promises.

(But as I wrote above, this is the kind of functionality you'd expect from the platform, whether it is V8 or Node.js.)

[Janpot]

https://mathiasbynens.be/notes/async-stack-traces I might misinterpret this but it looks like a v8 core dev explaining that performant async stack traces are possible?

[johan13]

@Janpot, it'd ge great if they get around to implementing that! 👍