Skip to content

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

Description

@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)

Activity

  1. mhdawson commented on May 27, 2022

    @mhdawson
    Member

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

  2. Qard commented on May 27, 2022

    @Qard
    Member

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

  3. eriohl commented on Jun 6, 2022

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

  4. tonivj5 commented on Jun 21, 2022

    @tonivj5
    Author

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

  5. Qard commented on Jun 21, 2022

    @Qard
    Member

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

  6. ml1nk commented on Jul 14, 2022

    @ml1nk

    Bug is still occurring in 18.6.0.

  7. Qard commented on Jul 14, 2022

    @Qard
    Member

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

  8. Qard commented on Jul 22, 2022

    @Qard
    Member

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

  9. added a commit that references this issue on Aug 28, 2022
  10. tonivj5 commented on Sep 11, 2022

    @tonivj5
    Author
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    async_hooksIssues and PRs related to the async hooks subsystem.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions