Async Stack Traces in Node.js 14.15.0

Question

Based on the documentation I would assume that Node.js 14 does now support stack traces in async code but unfortunately using node --async-stack-traces test.js still generates only a partial stack trace and I would be most interested to understand why.

Running the following code:

main()

function main() {
    sub();
}

async function sub() {
    console.trace('before sleep');
    await delay(1000);
    console.trace('after sleep');
}

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

shows the complete stack before but only a partial stack after using await:

~/MyDev/doberkofler/test $ node test.js
Trace: before sleep
    at sub (/Users/doberkofler/MyDev/doberkofler/test/test.js:10:10)
    at main (/Users/doberkofler/MyDev/doberkofler/test/test.js:6:2)
    at Object.<anonymous> (/Users/doberkofler/MyDev/doberkofler/test/test.js:3:1)
    at Module._compile (internal/modules/cjs/loader.js:1063:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1092:10)
    at Module.load (internal/modules/cjs/loader.js:928:32)
    at Function.Module._load (internal/modules/cjs/loader.js:769:14)
    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:72:12)
    at internal/main/run_main_module.js:17:47
Trace: after sleep
    at sub (/Users/doberkofler/MyDev/doberkofler/test/test.js:12:10)
~/MyDev/doberkofler/test $

Answer 1

Async stack traces will work, but only for an unbroken chain of async methods. So to fix your example, make your main method async, and then await the call to sub.

If you use promises, or miss an await before return then it will break.

This is explained here: https://github.com/nodejs/node/issues/36126#issuecomment-827023528

This is not as much a bug as it is just a limitation of the zero-cost async stack traces mechanism implemented by v8.

Specifically, let's look at the original example:

main()

function main() {
    sub();
}

async function sub() {
    console.trace('before sleep');
    await delay(1000);
    console.trace('after sleep');
}

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

The main is a regular synchronous function. It calls sub() which triggers console.trace('before sleep') synchronously within the scope of main()'s callstack. That is why before sleep contains the full stack trace information. What happens next is that main()'s callstack unwinds before the microtask queue later triggers the console.trace('after sleep'). By the time the second console.trace() is called, main() callstack is long gone and information about it no longer exists for v8 to do anything about it. While sub() looks like it's a single callstack, it's actually several spread out over time.

In order for after sleep to get the full stack trace, the caller of sub() has to be an async function and the call to sub() has to use await. For instance:

main()

async function main() {
    await sub();
}

async function sub() {
    console.trace('before sleep');
    await delay(1000);
    console.trace('after sleep');
}

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

How does this change things? Well, making main() async and having it await sub() means that v8 must retain the callstack information for main() until sub() completes -- that is, the full callstack information for main() will still be resident in memory and easily available to v8. When the second call to console.trace() occurs (and it creates the internal Error object used to generate the printed stack, all of the callstack details will be readily at hand and a proper error stack that goes only back to the top-most async function using await is generated:

Trace: before sleep
    at sub (/root/node/tmp/f.js:8:13)
    at main (/root/node/tmp/f.js:4:10)
    at Object.<anonymous> (/root/node/tmp/f.js:1:1)
    at Module._compile (node:internal/modules/cjs/loader:1108:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1137:10)
    at Module.load (node:internal/modules/cjs/loader:988:32)
    at Function.Module._load (node:internal/modules/cjs/loader:828:14)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:76:12)
    at node:internal/main/run_main_module:17:47
Trace: after sleep
    at sub (/root/node/tmp/f.js:10:13)
    at async main (/root/node/tmp/f.js:4:4)

The bottom line is that it absolutely is not a bug. The async stack traces mechanism is working exactly as it is designed to work -- it's just limited in what information it can capture. Now, whether that can be improved upon or not is a secondary discussion, but there is no bug in Node.js here as we are relying entirely on what v8 is providing to us here.

Answer 2

This problem might be a bug in v8: https://github.com/nodejs/node/issues/36126