Repository navigation
AsyncLocalStorage looses context attaching debugger after using await in >= 18.0.0 #43148
Description
Activity
- addedasync_hooksIssues and PRs related to the async hooks subsystem.Issues and PRs related to the async hooks subsystem.
on May 19, 2022 @vdeturckheim, @Qard any thoughts on why connecting the debugger might b e related.
Possibly a bug in PromiseHook. I do recall there was a bunch of debugger escape hatch stuff in the same codegen parts as where PromiseHook connects its own event triggering logic. Could be somewhere an event is not firing. Could be worth using v8.promiseHooks to log which events are being received and compare. 🤔
I have a very similar problem with
async_hooks. I just behaves differently when I attach a debugger. What happens is that thebeforeandaftercallbacks are not called for all hooks when debugger is attached (works fine when it is not). Currently, for me, unclear why.Possibly a bug in PromiseHook. I do recall there was a bunch of debugger escape hatch stuff in the same codegen parts as where PromiseHook connects its own event triggering logic. Could be somewhere an event is not firing. Could be worth using v8.promiseHooks to log which events are being received and compare. thinking
Here is the reproduction updated with the
promiseHooksoutput added:const { AsyncLocalStorage } = require("async_hooks"); const { setTimeout } = require("timers/promises"); const { promiseHooks } = require("v8"); promiseHooks.createHook({ init: (promise, parent) => { console.log("a promise was created", { promise, parent }); }, settled: (promise) => { console.log("a promise resolved or rejected", { promise }); }, before: (promise) => { console.log("a promise is about to call a then handler", { promise }); }, after: (promise) => { console.log("a promise is done calling a then handler", { promise }); }, }); const als = new AsyncLocalStorage(); function runIssue() { als.run("contextualized", () => { syncStep(); asyncStep(); }); console.log(`> Out: ${als.getStore()}`); } function syncStep() { console.log(`> Sync step: ${als.getStore()}`); } async function asyncStep() { console.log(`> Before async ${als.getStore()}`); await setTimeout(1); console.log(`> After async ${als.getStore()}`); } runIssue();
Output without attach any debugger:
> Sync step: contextualized a promise was created { promise: Promise { <pending> }, parent: undefined } > Before async contextualized a promise was created { promise: Promise { <pending> }, parent: undefined } a promise was created { promise: Promise { <pending> }, parent: Promise { <pending>, [Symbol(async_id_symbol)]: 6, [Symbol(trigger_async_id_symbol)]: 1, [Symbol(kResourceStore)]: 'contextualized' } } > Out: undefined a promise resolved or rejected { promise: Promise { <pending>, [Symbol(async_id_symbol)]: 6, [Symbol(trigger_async_id_symbol)]: 1, [Symbol(kResourceStore)]: 'contextualized' } } a promise is about to call a then handler { promise: Promise { <pending>, [Symbol(async_id_symbol)]: 8, [Symbol(trigger_async_id_symbol)]: 6, [Symbol(kResourceStore)]: 'contextualized' } } > After async contextualized a promise resolved or rejected { promise: Promise { <pending>, [Symbol(async_id_symbol)]: 5, [Symbol(trigger_async_id_symbol)]: 1, [Symbol(kResourceStore)]: 'contextualized' } } a promise resolved or rejected { promise: Promise { <pending>, [Symbol(async_id_symbol)]: 8, [Symbol(trigger_async_id_symbol)]: 6, [Symbol(kResourceStore)]: 'contextualized' } } a promise is done calling a then handler { promise: Promise { undefined, [Symbol(async_id_symbol)]: 8, [Symbol(trigger_async_id_symbol)]: 6, [Symbol(kResourceStore)]: 'contextualized' } }Output attaching a debugger:
Debugger attached. > Sync step: contextualized a promise was created { promise: Promise { <pending> }, parent: undefined } > Before async contextualized a promise was created { promise: Promise { <pending> }, parent: undefined } > Out: undefined a promise resolved or rejected { promise: Promise { <pending>, [Symbol(async_id_symbol)]: 9, [Symbol(trigger_async_id_symbol)]: 1, [Symbol(kResourceStore)]: 'contextualized' } } a promise is about to call a then handler { promise: Promise { <pending> } } > After async undefined a promise resolved or rejected { promise: Promise { <pending>, [Symbol(async_id_symbol)]: 8, [Symbol(trigger_async_id_symbol)]: 1, [Symbol(kResourceStore)]: 'contextualized' } } a promise resolved or rejected { promise: Promise { <pending>, [Symbol(async_id_symbol)]: 13, [Symbol(trigger_async_id_symbol)]: 0 } } a promise is done calling a then handler { promise: Promise { undefined, [Symbol(async_id_symbol)]: 13, [Symbol(trigger_async_id_symbol)]: 0 } } Waiting for the debugger to disconnect...I have tested with latest versions (
18.3.0&18.4.0), so the unexpected behavior follow happening.If I can add any other information to fix this bug, let me know @Qard 👍🏻
Appears to be missing the init event for the await linking back to the async function as the parent. Not sure off-hand what the cause would be, but I'll see if I can find some time to look at this soon. 🤔
Bug is still occurring in 18.6.0.
Yep, I haven't had the time to investigate further yet.
I've got a fix for V8 now. https://chromium-review.googlesource.com/c/v8/v8/+/3779922
I'll get that backported whenever it lands. :)
Reacted by Toni Villena, Lxxyx, eriohl, Marcel Link and German SwanReacted by Toni Villena, Lxxyx, eriohl, Marcel Link, German Swan and Bryan NelsonReacted by Toni Villena, Josh Weinstein, eriohl, Marcel Link and German Swan- added a commit that references this issue
on Aug 28, 2022 - added a commit that references this issue
on Sep 1, 2022 - added 3 commits that reference this issue
on Sep 5, 2022 Fix was launched on https://github.com/nodejs/node/releases/tag/v18.9.0
Reacted by Bryan Nelson, eriohl and StanReacted by Carson Full, Stephen Belanger and Stan
Version
>= 18.0.0
Platform
Linux 5.10.9-051009-generic #202101191835 SMP Tue Jan 19 19:17:55 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
Subsystem
Linux Mint
What steps will reproduce the bug?
How often does it reproduce? Is there a required condition?
Doing several tests I could say it's always reproducible attaching a debugger
What is the expected behavior?
Expected output:
What do you see instead?
Output attaching a debugger (using vscode or chrome devtools):
Additional information
The issue has been introduced between
17.9.0(it works as expected) and18.0.0(it doesn't work, neither18.1.0or18.2.0)