Incomplete async stack traces in Node.js 14.15.0

[doberkofler]

• Version: 14.15.0
• Platform: macOS 11.0.1
• Subsystem:

What steps will reproduce the bug?

node --async-stack-traces test.js

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);
    });
}

How often does it reproduce? Is there a required condition?

Fully reproducible

What is the expected behavior?

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

What do you see instead?

~/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)

Additional information

[joyeecheung]

Looks like there might be something wrong with our console.trace implementation, I get this when using the inspector console, which lead to calling the console methods from both Node.js and the V8 inspector, and as can be seen the trace from the inspector is fine while the trace from Node.js isn't.

[joyeecheung]

um, looks like it's a bug in Error.captureStackTrace because I can reproduce this with d8:

main()

function main() {
    sub();
}

async function sub() {
    const err = new Error();
    Error.captureStackTrace(err);
    console.log('before sleep');
    console.log(err.stack);
    await delay(1000);
    const err2 = new Error();
    Error.captureStackTrace(err2);
    console.log(err2.stack);
}

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

$ out.gn/x64.debug/d8 --async-stack-traces ../../node/test.js
before sleep
Error
    at sub (../../node/test.js:9:11)
    at main (../../node/test.js:4:5)
    at ../../node/test.js:1:1
Error
    at sub (../../node/test.js:14:11)

[isgj]

Maybe related to this, in dev environment I get (it doesn't matter the actual error)

From previous event:
    at Query.run (/app/node_modules/sequelize/lib/dialects/mysql/query.js:39:12)
    at runHooks.then.then (/app/node_modules/sequelize/lib/sequelize.js:645:29)
From previous event:
    at Promise.try.then.connection (/app/node_modules/sequelize/lib/sequelize.js:645:12)
From previous event:
    at Promise.resolve.retry (/app/node_modules/sequelize/lib/sequelize.js:641:10)

but when NODE_ENV=production I get only the first part of the stack, what comes after the first From previous event (including this line) is lost.

[pmer]

That output of test.js is reproducible on Node.js v12.20.0, v14.15.1, and v15.3.0.

[pmer]

The stack trace will be complete if you make main an async function and do an await on sub().

[tom10271]

class Client {
    async justASimpleAsyncMethod() {
        return true;
    }

    async connect() {
        throw new Error('Connection failed');
    }
}

class Manager {
    async migrate() {
        client = new Client();

        await client.justASimpleAsyncMethod();
        await client.connect();
    }
}

(async () => {
    const manager = new Manager();

    await manager.migrate();
})();

A similar case, this bug is huge and make error tracking really hard. For the script above I can track to migrate() only but not all the way to await manager.migrate(); as I have await client.justASimpleAsyncMethod();

---

This is my temp solution as this is not a bug I can tolerate

import Promise from 'bluebird';

global.Promise = Promise;
Promise.config({
    longStackTraces: true,
});

[sbrl]

For completeness, @tom10271's workaround does not work if the crash happens in 3rd party library installed via NPM. This bug really needs fixing, because it makes tracking crashes in Tensorflow.js for example very difficult.

[jasnell]

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.

[sbrl]

Ah, so if I'm seeing broken stack traces in a library, then this is instead a bug in said library rather than Node.js. Got it - thanks for the detailed explanation @jasnell!

[derolf]

Let‘s assume one wants to use “background“ promises for some async job. What‘s the correct way to do that in order to get a proper stack of something fails?

[mcqj]

The debate of whether this is or is not a bug is semantics, really. It depends on your POV. I understand that from the POV or a Node core developer, there isn't a bug in Node. From the POV of an application developer, a programming environment that does not fully support your ability to debug is a significant problem.

I don't really care about the semantics of whether it is or isn't a bug, as long as deciding its not a bug is not used as a rationale for closing it and not addressing the issue.

I really feel the issue needs to be addressed in some way, shape or form even if it means having to work around V8 limitations.