node icon indicating copy to clipboard operation
node copied to clipboard

inconsistent stacktrace on errors after awaiting non-asynchronous value in an indirectly called async function

Open MisterD123 opened this issue 2 years ago • 0 comments

Version

v18.13.0 v20.3.0

Platform

Microsoft Windows NT 10.0.22621.0 x64, Linux trnstr 6.3.8 #1-NixOS SMP PREEMPT_DYNAMIC Wed Jun 14 09:17:06 UTC 2023 x86_64 GNU/Linux

Subsystem

No response

What steps will reproduce the bug?

async function indirectCall(callback) { // function indirectCall(callback) {
    return callback() // return await callback()
}

async function foo() {
    console.log(new Error("1").stack)
    await undefined // await new Promise(setImmediate)
    console.log(new Error("2").stack)
    await undefined
    console.log(new Error("3").stack)
}

async function main() {
    await indirectCall(foo) // await foo()
}
main()

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

The bug is deterministic, occuring reliably on every execution of the snippet.

The bug does not occur when any single line in the snippet is replaced with the commented-out alternative behind it. So it seems to me, for this bug to occur, this particular combination of circumstances is required:

  • foo must be called indirectly through indirectCall
  • indirectCall must be declared async
  • indirectCall must return the result of calling its parameter without awaiting it
  • this only ocurrs for stack traces gathered after the first await inside foo. after a second, third or more await statements, the stack trace is correct again.
  • inside foo, the first value of the first await statement must be synchronously available: It seems, await undefined can be replaced by any value that is synchronously avilable and the bug still occurs. This includes simple values such as await 123, but can also include Promise values such as await Promise.resolve(). Most notably, even when assigning new Promise(setImmediate) to a variable and then awaiting this variable before executing the code, the bug will still occur if the promise has completed by the time that foo is called, c.f. the following variant of the snippet:
const actualPromise = new Promise(setImmediate)

async function indirectCall(callback) {
    return callback()
}

async function foo() {
    console.log(new Error("1").stack)
    await actualPromise
    console.log(new Error("2").stack)
    await undefined
    console.log(new Error("3").stack)
}

async function main() {
    await indirectCall(foo)
}
actualPromise.then(main) // main()

actualPromise.then(main) in the last line ensures that the program is executed only after actualPromise is complete, and then the bug occurs. When instead calling main() immediately without awaiting actualPromise first, the execution of foo is started when actualPromise is still incomplete, and then the bug does not occur.

What is the expected behavior? Why is that the expected behavior?

Either:

Error: 1
    at foo (scratch.js:6:17)
    at indirectCall (scratch.js:2:12)
    at main (scratch.js:14:11)
Error: 2
    at foo (scratch.js:8:17)
    at indirectCall (scratch.js:2:12)
    at async main (scratch.js:14:5)
Error: 3
    at foo (scratch.js:10:17)
    at indirectCall (scratch.js:2:12)
    at async main (scratch.js:14:5)

or:

Error: 1
    at foo (scratch.js:6:17)
    at indirectCall (scratch.js:2:12)
    at main (scratch.js:14:11)
Error: 2
    at foo (scratch.js:8:17)
    at async main (scratch.js:14:5)
Error: 3
    at foo (scratch.js:10:17)
    at async main (scratch.js:14:5)

I suppose it is fine, or possibly even correct, if stack traces 2 and 3 do not include the indirectCall frame, because stack trace 1 is gathered synchronously, but stack traces 2 and 3 are gathered asynchronously, after indirectCall has already returned the promise returned by callback() without awaiting it, and thus indirectCall is not part of the call stack any more at that point.

In either case though, all three stack traces should include both foo and main, and particularly I would expect stack traces 2 and 3 to be identical, as they are both executed asynchronously under the same call stack.

What do you see instead?

Error: 1
    at foo (scratch.js:6:17)
    at indirectCall (scratch.js:2:12)
    at main (scratch.js:14:11)
    at Object.<anonymous> (scratch.js:16:1)
    at Module._compile (node:internal/modules/cjs/loader:1255:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1309:10)
    at Module.load (node:internal/modules/cjs/loader:1113:32)
    at Module._load (node:internal/modules/cjs/loader:960:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:83:12)
    at node:internal/main/run_main_module:23:47
Error: 2
    at foo (scratch.js:8:17)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
Error: 3
    at foo (scratch.js:10:17)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async main (scratch.js:14:5)

Stack trace 1 is much larger, but again, this is fine due to its synchronous execution.

Stack traces 2 and 3 differ though. Notably, the at async main frame is missing in stack trace 2. I believe this is incorrect, and also highly problematic because it makes it impossible to see, along which path the call to foo originated that resulted in the error, if the call stack ever passes through such a pattern of call sites.

Additional information

No response

MisterD123 avatar Jun 21 '23 16:06 MisterD123