The store when using enterWith/exitWith in asyncLocalStorage is not "stacked"

[giltayar]

• Version: 15.5.0
• Platform: MacOS
• Subsystem: async_hooks

What steps will reproduce the bug?

I expected the following program to work:

import {AsyncLocalStorage} from 'async_hooks'
import assert from 'assert'

const asyncLocalStorage = new AsyncLocalStorage()

// This section works nicely: the store is "stacked"
asyncLocalStorage.run({depth: 1}, () => {
  assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 1})

  asyncLocalStorage.run({depth: 2}, () => {
    assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 2})
  })

  assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 1})
})

// This section how when using enterWith/exit the store is not stacked
asyncLocalStorage.enterWith({depth: 1})
assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 1})

asyncLocalStorage.enterWith({depth: 2})
assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 2})

asyncLocalStorage.exit(() => {
  // **** this fails because the store returns undefined
  assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 1})

  asyncLocalStorage.exit(() => {
    assert.deepStrictEqual(asyncLocalStorage.getStore(), undefined)
  })
})

assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 2})

But it fails in the line after the marked ****. The reason I expected it to work is because I assumed that enter/exit has the same "stacked" semantics as run, in that entering twice and exiting once will give me the store of the first enter. Unfortunately, the store I get after the first exit is undefined.

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

Consistent. Always.

What is the expected behavior?

The program should pass without error. See above for why.

What do you see instead?

A failure of the code:

node:internal/process/esm_loader:74
    internalBinding('errors').triggerUncaughtException(
                              ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly deep-equal:
+ actual - expected

+ undefined
- {
-   depth: 1
- }
    at file:///Users/giltayar/code/mono/packages/request-id-logger-fastify-plugin/src/foo.js:26:10
    at AsyncLocalStorage.exit (node:async_hooks:323:14)
    at file:///Users/giltayar/code/mono/packages/request-id-logger-fastify-plugin/src/foo.js:24:19
    at ModuleJob.run (node:internal/modules/esm/module_job:152:23)
    at async Loader.import (node:internal/modules/esm/loader:166:24)
    at async Object.loadESM (node:internal/process/esm_loader:68:5) {
  generatedMessage: true,
  code: 'ERR_ASSERTION',
  actual: undefined,
  expected: { depth: 1 },
  operator: 'deepStrictEqual'
}

Additional information

This also fails in v14.15.1

[targos]

@nodejs/async_hooks

[puzpuzpuz]

@giltayar asyncLocalStorage.exit() is not supposed to work in a "stacked" way. As its doc says:

This methods runs a function synchronously outside of a context and return its return value.
The store is not accessible within the callback function or the asynchronous operations
created within the callback.

What you faced in your snippet is a consequence of the described behavior, i.e. the context will always be undefined within als.exit()'s callback. If you need to return to the previous context (i.e. store), you need to do the als.getStore() call within the previous async call in the chain, just like you did it here:

asyncLocalStorage.run({depth: 1}, () => {
  assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 1})

  asyncLocalStorage.run({depth: 2}, () => {
    // new scope (`als.run()` acts as if it would be a new async call in the chain)
    assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 2})
  })

  // here we're in the scope of the previous async call
  assert.deepStrictEqual(asyncLocalStorage.getStore(), {depth: 1})
})

Also, als.enterWith() simply replaces the context with the provided object/primitive, so it doesn't have the behavior you expect. In general, this method should be used with precaution as it doesn't limit store's lifetime/scope.

[giltayar]

@puzpuzpuz I thought this is maybe the defined behavior, but it wasn't clear from the documentation. If this is the defined behavior, then, yes, this issue can be closed. I'll wait a bit to see if anybody else has any input, and close it in a day or two if not. Thanks for the clarification!

[puzpuzpuz]

I thought this is maybe the defined behavior, but it wasn't clear from the documentation. If this is the defined behavior, then, yes, this issue can be closed.

Looks like the doc are a bit misleading. I've created #36705 as an attempt to make things more clear.

[Qard]

Yeah, ALS is not in any way stacked. The current storage value is stored directly on the current resource, so it's a one-to-one relationship--any history would be lost.

[iamFIREcracker]

Yeah, ALS is not in any way stacked. The current storage value is stored directly on the current resource, so it's a one-to-one relationship--any history would be lost.

This comment threw me off a little when I first read it, so expanded the OP's nested enterWith() example to include branching and asynchronous operations as well, hoping that that will help me and others to understand better what's going on behind the scenes:

var { AsyncLocalStorage } = require("async_hooks");
var assert = require("assert");

const asyncLocalStorage = new AsyncLocalStorage();

asyncLocalStorage.run({ depth: 1 }, () => {
  assert.deepStrictEqual(asyncLocalStorage.getStore(), { depth: 1 });

  asyncLocalStorage.run({ depth: 2 }, () => {
    setTimeout(() => {
      assert.deepStrictEqual(asyncLocalStorage.getStore(), { depth: 2 });
    }, 2000);
  });

  asyncLocalStorage.run({ depth: 3 }, () => {
    setTimeout(() => {
      assert.deepStrictEqual(asyncLocalStorage.getStore(), { depth: 3 });
    }, 1000);
  });

  assert.deepStrictEqual(asyncLocalStorage.getStore(), { depth: 1 });
});

What does this tell us? Even though you cannot directly access the values that were previously bound to the specific AsyncLocalStorage instance, all the values are stored somewhere, in memory, and they indeed form a stack (one or multiple stacks -- in the example both { depth: 3 } and {depth: 2} have { depth: 1 } as parent.

[Qard]

They only form a stack in the sense that the code itself forms a stack. When you do asyncLocalStorage.run({ depth: 2 }, ...) it is internally creating a new AsyncResource which it enters for the lifetime of the callback and all async activity within that callback will be connected to that AsyncResource. When you reach the check at the end for depth: 1, that passes because the AsyncResource stack internal to the other asyncLocalStorage.run(...) calls has exited by that point, returning to the original AsyncResource of the outer run.

While it may not be especially clear, what this means is that multiple sets of context data are not stored and therefore accessible in descending async code. Only the data of the nearest run will be reachable. The store.getStore(...) method is a very simply mechanism that only gets the current resource and grabs a symbol property off of it which stores the context data. What AsyncLocalStorage does internally is copy that symbol property onto every AsyncResource instance created while in the lifetime of another, which is to say those setTimeout(...) calls create an internal AsyncResource which copies its context data from the AsyncResource internal to the store.run(...) method. No stacking of context data, just stacking of the underlying resource tree. In a sense, this means sync code will essentially have stacked contexts like this, but async code will never return to the outer resource and therefore never restore the conceptually outer context.