AsyncLocalStorage looses context attaching debugger after using await in >= 18.0.0

[tonivj5]

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?

const { AsyncLocalStorage } = require("async_hooks");
const { setTimeout } = require("timers/promises");

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);
  //  using not-promised setTimeout works as expected
  //  setTimeout(() => {
  //    console.log(`After async ${als.getStore()}`);
  //  }, 1);

  console.log(`After async ${als.getStore()}`);
}

runIssue();

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:

Sync step: contextualized
Before async contextualized
Out: undefined
After async contextualized

What do you see instead?

Output attaching a debugger (using vscode or chrome devtools):

Debugger attached.
Sync step: contextualized
Before async contextualized
Out: undefined
After async undefined
Waiting for the debugger to disconnect...

Additional information

The issue has been introduced between 17.9.0 (it works as expected) and 18.0.0 (it doesn't work, neither 18.1.0 or 18.2.0)

[mhdawson]

@vdeturckheim, @Qard any thoughts on why connecting the debugger might b e related.

[Qard]

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. 🤔

[eriohl]

I have a very similar problem with async_hooks. I just behaves differently when I attach a debugger. What happens is that the before and after callbacks are not called for all hooks when debugger is attached (works fine when it is not). Currently, for me, unclear why.

[tonivj5]

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 promiseHooks output 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 👍🏻

[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. 🤔

[ml1nk]

Bug is still occurring in 18.6.0.

[Qard]

Yep, I haven't had the time to investigate further yet.

[Qard]

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. :)

[tonivj5]

Fix was launched on https://github.com/nodejs/node/releases/tag/v18.9.0