AsyncLocalStorage doesn't propagate across Promise chains?

Question

Consider the following code run under NodeJS 14.4 on Windows:

const async_hooks = require('async_hooks');
const fs = require('fs');
const util = require('util');

let asyncLocalStorage = new async_hooks.AsyncLocalStorage();
asyncLocalStorage.enterWith({blah: 7});

function log(...args) {
  fs.writeSync(1, `${util.format(...args)}\n`);
}

function getCurrentId() {
  return async_hooks.executionAsyncId();
}

new Promise((res, rej) => {
    log(`first promise: ${getCurrentId()}`);
    res();
    log(`first promise done`);
}).then(() => {
    log(`second promise: ${getCurrentId()}`);
    asyncLocalStorage.enterWith({id: 7});
    log(`id in second promise=${asyncLocalStorage.getStore().id}`);
    log(`second promise done`);
}).then(() => {
    log(`third promise: ${getCurrentId()}`);
    log(`id in third promise=${asyncLocalStorage.getStore().id}`);
});

I expected the local storage from the second promise to propagate to the third one. However, the output of this code is the following:

first promise: 1
first promise done
second promise: 3
id in second promise=7
second promise done
third promise: 4
id in third promise=undefined

If I turn on debugging via async-local-storage, the following output is revealed:

2(PROMISE) init by 1
first promise: 1
first promise done
3(PROMISE) init by 2    <-- when first promise is done, context for the second promise is init'd
4(PROMISE) init by 3    <-- but context for third promise is also initiated, before the second promise even ran!
second promise: 3
id in second promise=7  <-- so the async store is set only after the context for the third promise is init'd
second promise done
third promise: 4
id in third promise=undefined  <-- which means AsyncLocalStorage did not copy the store to the third promise

Am I missing something in expecting the store to propagate to the third promise as well?

Answer 1

First of all, note that, even in Node 17, enterWith is marked as experimental, with a recommendation to use AsyncLocalStorage#run, since it eliminates these types of issues. It's not broken, per se, just has surprising implications like the one described here. Protracted discussion here.

The docs for enterWith describe it as:

Transitions into the context for the remainder of the current synchronous execution and then persists the store through any following asynchronous calls.

In other words, enterWith will use that context for everything called within a specific function, and then discards it when that function completes. It's important to note that promise chains are a sequence of independent functions. This solved callback hell by allowing them to be independent, but it's an important distinction here, as each in the chain "enters and exits" sequentially, returning scope back to the calling context at each step. To make this more clear, this is an equivalent representation, with the promise handlers declared externally in reverse order of their later use (rewritten slightly to log the whole store):

const third = () => {
  // my context is the enclosing scope
  log(`third promise: ${getCurrentId()}`);
  log(`store in third promise`, asyncLocalStorage.getStore());
};

const second = () => {
  log(`second promise: ${getCurrentId()}`);
  asyncLocalStorage.enterWith({ id: 7 });
  log(`store in second promise`, asyncLocalStorage.getStore());
  log(`second promise done`);
  // now we'll leave the `{ id: 7 }` store behind to be garbage collected
};

const first = (res) => {
  log(`first promise: ${getCurrentId()}`);
  res();
  log(`first promise done`);
};

new Promise(first).then(second).then(third);

We can further demonstrate by adding a call to third within second, and can see the scope retained:

const second = () => {
  log(`second promise: ${getCurrentId()}`);
  asyncLocalStorage.enterWith({ id: 7 });
  log(`store in second promise`, asyncLocalStorage.getStore());
  log('***** running nested third');
  third();
  log('***** done running nested third');
  log(`second promise done`);
};

Now the final output is:

first promise: 1
first promise done
second promise: 3
store in second promise { id: 7 }
***** running nested third
third promise: 3
store in third promise { id: 7 }
***** done running nested third
second promise done
third promise: 4
store in third promise { blah: 7 }

Final note: The async/await syntax's similarity to standard sequential code can be clearer for this purpose, as you're changing the store for the remainder of the outer function, and each step is therefore "chained" within a constant context:

async function run() {
  log(`first promise: ${getCurrentId()}`);
  await Promise.resolve();
  log(`first promise done`);

  log(`second promise: ${getCurrentId()}`);
  asyncLocalStorage.enterWith({id: 7});
  log(`id in second promise=${asyncLocalStorage.getStore().id}`);
  await Promise.resolve();
  log(`second promise done`);

  log(`third promise: ${getCurrentId()}`);
  log(`id in third promise=${asyncLocalStorage.getStore().id}`);
}

Now the output is:

first promise: 1
first promise done
second promise: 4
id in second promise=7
second promise done
third promise: 6
id in third promise=7