AsyncLocalStorage `getStore` unexpected behaviour

[NoelAbrahams]

• Node.js Version: 13.11.0
• OS: Windows 10
• Scope: Code
• Module: async_hooks

Sample Code

import { AsyncLocalStorage } from 'async_hooks';
const asynLocalStorage = new AsyncLocalStorage();

httpServer.on('request', (request, response) => {

    // Storage map
    const key = 'KEY-1';
    const store = new Map();
    store.set(key, { foo: 'foo' });

    // Run in context
    asyncLocalStorage.run(store, () => {

        request.on('end', () => {

            // asyncLocalStorage.enterWith(store);
            const local = asyncLocalStorage.getStore(); 
            console.log((local?.get('KEY-1'))); // Line-B: This is undefined 
        });

        const local = asyncLocalStorage.getStore();
        console.log(local?.get('KEY-1')); // Line-A: This is fine

        // Other work (omitted)
    });
});

Expected outcome
The call togetStore should return and log the stored map (Line-B)

Actual
The value is undefined

Does anyone have an idea why the call to getStore is not preserving the context?

Related
#2537

[gireeshpunathil]

/cc @vdeturckheim

[Doc999tor]

I forced it to work only after wrapping httpServer.on('request'... in asyncLocalStorage.run context

[NoelAbrahams]

@Doc999tor also uncommenting the line // asyncLocalStorage.enterWith(store) above makes it work, but I'm not sure why that is necessary. Also enterWith seems to create a global store, ie one that is shared across requests. I may be wrong there....

Just want to understand what's going on, and the recommended approach.

[vdeturckheim]

@NoelAbrahams I just ran the following code (there were a couple nits in your snippet):

const { AsyncLocalStorage } = require('async_hooks');
const asyncLocalStorage = new AsyncLocalStorage();

const httpServer = new require('http').Server();
httpServer.on('request', (request, response) => {

    // Storage map
    const key = 'KEY-1';
    const store = new Map();
    store.set(key, { foo: 'foo' });

    // Run in context
    asyncLocalStorage.run(store, () => {

        request.on('end', () => {
            
            const local = asyncLocalStorage.getStore();
            console.log('E', (local.get('KEY-1'))); // Line-B: This is undefined
        });

        const local = asyncLocalStorage.getStore();
        console.log(local.get('KEY-1')); // Line-A: This is fine
        response.end('ok\n');
        // Other work (omitted)
    });
});

httpServer.listen(8080)

Then

% curl http://localhost:8080/

And it printed:

{ foo: 'foo' }
E { foo: 'foo' }

Which is the expected outcome. Can you try to run this example and tell me if this fails on your side?

[NoelAbrahams]

@vdeturckheim thanks for getting back. The snippet I posted was from a larger code-base, but you're right: there is no bug in that code per se.

Here is the minimal repro that I've managed to isolate:

const { AsyncLocalStorage } = require("async_hooks");
const http = require("http");
const asyncLocalStorage = new AsyncLocalStorage();

class Wrapper {

    run(store, callback) {

        asyncLocalStorage.runSyncAndReturn(store, callback);
    }

    get bar() {
        return asyncLocalStorage.getStore();
    }
}

const wrapper = new Wrapper();
const httpServer = http.createServer();

httpServer.on('request', (request, response) => {

    const bar = { bar: 'bar' };

    wrapper.run(bar, () => {

        request.on('end', () => {

            // asyncLocalStorage.enterWith(bar);
            const local = wrapper.bar;
            console.log('E', local); // This is undefined
        });

        const local = wrapper.bar;
        console.log(local);

        response.end('ok\n');
        // Other work (omitted)
    });
});

httpServer.listen(8080);

Basically, sticking AsyncLocalStorage in a wrapper causes this behaviour.

Is this expected? What's the solution?

Thanks

[addaleax]

Fwiw, one big difference between ALS and domains (as I understand it) is that ALS exclusively uses async_hooks for context tracking, and has no special handling for event listeners. I don’t see how ALS would know that the request.on('end') callback was registered from the outer context?

[Doc999tor]

@addaleax

request.on('end') callback was registered from the outer context

It's not, it's registered inside callback function - so it's the scope of async locale store, all happened inside it should have the same context

[vdeturckheim]

If I get it right, for ASL, what's important if where the emit call is made in term of context. The listeners will be on the same context.

There is probably a scoping issue in the context. Replacing runSyncAndReturn by run to get strong context isolation, fixes the issue. I am strinng trying to check why this.

[vdeturckheim]

So, the event is indeed emitted outside of the scope:

const { AsyncLocalStorage, executionAsyncResource, executionAsyncId, createHook } = require("async_hooks");
const http = require("http");
const asyncLocalStorage = new AsyncLocalStorage();


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

function debug(...args) {
    // Use a function like this one when debugging inside an AsyncHooks callback
    fs.writeFileSync('/dev/stdout', `${util.format(...args)}\n`, { flag: 'a' });
}

console.log(asyncLocalStorage.kResourceStore);

createHook({
    init(asyncId, type, triggerAsyncId, resource) {
        debug(triggerAsyncId, '=>', asyncId, executionAsyncResource()[asyncLocalStorage.kResourceStore]);
        resource.__id = asyncId;
    }
}).enable();

class Wrapper {

    run(store, callback) {

        asyncLocalStorage.runSyncAndReturn(store, callback);
        debug('EXIT')
    }

    get bar() {
        return asyncLocalStorage.getStore();
    }
}

const wrapper = new Wrapper();
const httpServer = http.createServer();

httpServer.on('request', (request, response) => {

    const bar = { bar: 'bar' };

    wrapper.run(bar, () => {

        request.on('end', () => {
            debug('B', executionAsyncId());
            // asyncLocalStorage.enterWith(bar);
            const local = wrapper.bar;
            debug('E', local); // This is undefined
        });

        const local = wrapper.bar;
        debug(local);

        debug('A', executionAsyncId());
        response.end('ok\n');
        // Other work (omitted)
    });
});

httpServer.listen(8080);

produces

Symbol(kResourceStore)
1 => 3 undefined
3 => 4 undefined
3 => 5 undefined
5 => 6 undefined
5 => 7 undefined
5 => 8 undefined
{ bar: 'bar' }
A 6
6 => 9 { bar: 'bar' }
EXIT
6 => 10 undefined
9 => 11 { bar: 'bar' }
9 => 12 { bar: 'bar' }
9 => 13 { bar: 'bar' }
10 => 14 undefined
11 => 15 { bar: 'bar' }
11 => 16 { bar: 'bar' }
11 => 17 { bar: 'bar' }
B 14
E undefined

What we want to see here is that 14 is a child of 10. 10 is a child of 6 but created after the callback call in run. This is possible because runSyncAndReturn is synchronous. I am not not clear yet on wether nodejs/node#31950 would fix it (I don't think so).

[puzpuzpuz]

This issue is potentially related with nodejs/node#33723. AsyncResource.bind utility introduced in nodejs/node#34574 could be used to mitigate it.

[vdeturckheim]

Over the time I have seen multiple use for such bind. @puzpuzpuz I think we have a case for it :)

[puzpuzpuz]

@vdeturckheim yeah, I also had a use case, so that why I created nodejs/node#33723. There were some prior attempts to integrate EEs with async_hooks, but maybe we need to plan another one carefully and make it happen? See the issue for more context.

[mcollina]

For anyone stumbling on this, you can take a look at the following issues in order to fix this in your code:

nestjs/nest#8837
fastify/fastify#3570
fastify/fastify#3571

[BobDu]

Note some fix about expressjs to help people who see this issue after

expressjs/body-parser#414
stream-utils/raw-body#71

So, if you findings bug in expressjs loss asyncLocalStorage when have request body payload, you need use expressjs 4.18 or later to reslove it.