Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Stacktrace incomplete when throwing from async catch

Why is there no async stacktrace when rethrowing an asynchronous exception? With node 12+, the exception when running the following code:

async function crash() {
    try {
        await (async () => {throw new Error('dead');})();
    } catch (e) {
        throw new Error('rethrow');
    }
}

async function foo() {
    await new Promise(resolve => setTimeout(() => resolve(), 1));
    await crash();
}

async function entrypoint() {
    try {
        await foo();
    } catch(e) {
        console.log(e.stack);
    }
}
entrypoint();

is woefully incomplete:

Error: rethrow
    at crash (/async-stackt/crash.js:6:15)

I found a workaround by defining the exception in the beginning of crash(), which yields a much nicer:

Error: rethrow
    at crash (/workaround.js:2:17)
    at foo (/workaround.js:12:11)
    at async entrypoint (/workaround.js:17:9)

This is not optimal, since the error has to be constructed in advance whether it is needed or not, and the stacktrace is somewhat imprecise.

Why is the stack trace incomplete when throwing an error from an async catch block? Is there any workaround or change to the code to get a complete stack trace in the first place?

like image 401
phihag Avatar asked Jan 14 '20 00:01

phihag


2 Answers

That stack trace is showing you what's ON the stack at that time. When you make an asynchronous call such as setTimeout(), it runs the setTimeout() which registers a timer that will fire some time in the future and then it continues execution. Since you're using await here, it pauses the execution of foo(), but it continues execution of the code after where foo() was called. Since that's also an await, it continues executing the code that called entrypoint(). After that finishes, the stack is entirely empty.

Then, sometime later, your timer fires and its callback gets called with a completely clean stack. In your case, the setTimeout() callback just calls resolve() which then triggers a promise to schedule its resolve handlers to run on the next event loop tick. That returns back to the system and the stack frame is again empty. On that next tick of the event loop, the promise resolve handlers are called and that satisfies the await on that promise which is inside a function context. When that await is satisfied, the rest of that function starts to execute.

When that function gets to the end of its execution, the interpreter knows that this was a suspended function context. There is no return from the function to happen because that already happened earlier. Instead, since this is an async function, the end of the function execution resolves the promise that this async function returns. Resolving that promise then schedules its resolve handlers to be called on the next tick of the event loop and then it returns control back to the system. The stack frame is again empty. On that next tick of the event loop, it calls the resolve handlers which satisifies the await in the await foo() statement and the entrypoint() function can continue to run, picking up where it was last suspended.

So, the key here is that when the timer goes off, execution goes from foo back to entrypoint, not via a stack and a return statement (that function already returned awhile ago), but via promises getting resolved. So, at the time the timer goes off and you then call crash(), the stack is indeed empty except for the function call to crash() itself.

This concept of an empty stack when promises are resolved goes to the heart of how an async function actually works so it's important to understand that. You have to remember that it pauses the internal execution of the function containing the await, but as soon as it hits the first await, it immediately causes the function to return a promise and the the callers continue further execution. The caller is not paused unless they also so an await in which case the callers of the caller continuing executing. At some point, somebody gets to continue executing and eventually, it returns control back to the system with a now-empty stack.

The timer event (or some other promise triggering event) then gets called with a completely empty stack frame with no remnants from the original call sequence.

Unfortunately, the only work-around I'm aware of now is to do what you found - create the Error object earlier when the original stack is still alive. If I remember correctly, there is a discussion about adding some features to the Javascript language to make asynchronous tracing easier. I don't remember the details of the proposal, but perhaps by remembering what the stack frame was when the function was originally called since what it is after the promise is resolved/rejected and when the Error object is created is no longer very useful.


In case anyone was unfamiliar with how async functions work and how they suspend their own execution upon the first await, but then return early, here's a little demo:

function delay(t) {
    return new Promise(resolve => {
        setTimeout(resolve, t);
    });
}

async function stepA() {
    console.log("5");
    await stepB();
    console.log("6");
}

async function stepB() {
    console.log("3");
    await delay(50);
    console.log("4");
}

console.log("1");
stepA();
console.log("2");

This generates the following output. If you follow this execution path step-by-step, you will see how each await causes an early return from that function and can then see how the stack frame will be empty once the promise that is being awaited gets resolved. This is the output generated:

1
5
3
2
4
6

It's clear why 1 is first as it's the first thing to execute.

Then, it should be clear why 5 comes next when stepA() is first called.

Then, stepA calls stepB() so as it begins to execute, that's why we see 3 next.

Then, stepB calls await delay(50). That executes delay(50) which starts a timer and then immediately returns a promise that is hooked to that timer. It then hits the await and it stops execution of stepB.

When stepB hit that await, it causes stepB at that point to return a promise that comes from the function being async. That promise will be hooked to stepB execution eventually (in the future) getting a chance to finish all of its execution. For now the execution of stepB is suspended.

When stepB returns its promise, that goes back to where stepA executed await stepB();. Now that stepB() has returned (an unfulfilled promise), then stepA hits its await on that unfulfilled promise. That suspends the execution of stepA and it returns a promise at that point.

So, now that the original function call to stepA() has returned (an unfulfilled promise) and there is no await on that function call, that top level code after that function call continues to execute and we see the console output the 2.

That console.log("2") is that last statement to execute here so control is returned back to the interpreter. At this point, the stack frame is completely empty.

Then, sometime later, the timer fires. That inserts an event in the JS event queue. When the JS interpreter is free, it picks up that event and calls the timer callback associated with that event. This does only one thing (call resolve() on a promise) and then returns. Calling resolve on that promise schedules that promise to trigger it's .then() handlers on the next tick of the event loop. When that happens, the await on the line of code await delay(50); gets satisfied and execution of that function resumes. We then see the 4 in the console as the last line of stepB executes.

After the console.log("4"); executes, stepB has now finished executing and it can resolve it's async promise (the one returned by it earlier). Resolving that promise tells it to schedule its .then() handlers for the next tick of the event loop. Control goes back to the JS interpreter.

On the next tick of the event loop, the .then() handlers notify the await in the await stepB(); that the promise has now been resolved and execution of stepA continues and now we see 6 in the console. That is the last line of stepA to execute to it can resolve its async promise and return control back to the system.

As it turns out, there is nobody listening to the async promise that the call to stepA() returned so there is no further execution.

like image 185
jfriend00 Avatar answered Nov 14 '22 00:11

jfriend00


I ran into the same issue in Node 12 and found out that it was fixed in a later version of V8: commit.

Gotta wait for Node 14, I guess...

The bug had to do with the stack trace not being tracked in catch blocks. So one workaround is to use the Promise's .catch function instead:

async function crash() {
    await (async () => {throw new Error('dead');})()
        .catch(e => { throw new Error('rethrow'); });
}
like image 38
Kannan Goundan Avatar answered Nov 14 '22 00:11

Kannan Goundan