Make it work with Async Hooks

[kjarmicki]

Hi,

I'm using Async Hooks to store the current request context data throughout its lifetime. Unfortunately, there's a known issue with Async Hooks resulting in the context being lost when using callbacks instead of promises.

This PR fixes that by wrapping raw-body call. I've used native Promise constructor instead of util.promisify because it has been available since 0.12. Unfortunately, this also means dropped support for 0.8 and 0.10. If maintaining 0.8 and 0.10 support is important to you, I can add async_hooks availability check and decide whether to wrap raw-body based on that.

[dougwilson]

If maintaining 0.8 and 0.10 support is important to you

I haven't actually looked at the changes yet, but just wanted to note on this in that the question is really around how important to you for this change to be released any time soon. If you're OK waiting some indeterminate release timeframe, it's perfectly find to drop that support. But if you want to see something released soon, it's best to continue to support it so we can release it.

[kjarmicki]

But if you want to see something released soon, it's best to continue to support it so we can release it.

I'd certainly prefer faster release, so I'll make sure that this change is backwards-compatible

[dougwilson]

Nice. I also noticed while looking through the changes there is a behavior change in the order in which validations are occurring. I'm not sure if that was intentional or not, but it certainly revealed a gap in our test suite :D I'm going to add a test for that behavior to make it very obvious where this PR changed it to help out 👍

[kjarmicki]

there is a behavior change in the order in which validations are occurring

I can add the test for it myself, but I don't really understand how this PR could have changed the order of validations 🤔

As far as I understand it, the logic used to be:

readBody((error, body) => {
  if (error) {
    // handle error
    return;
  }
  // handle success, which includes verify
});

Now it is:

readBody()
  .then(() => {}) // handle success, which includes verify
  .catch(() => {}) // handle error

which is equivalent in terms of execution order, assuming that handlers are not using shared state... or am I missing something? I haven't changed anything in the success/error handling logic, just moved it around as a whole.

[dougwilson]

Hi @kjarmicki sorry about that! As I was going to add the test, I observed that if I just took the test you added here and placed on on master without your changes to lib/read.js, it passes! So either (a) there isn't an issue here or (b) the test you added is not actually testing the change you made.

[dougwilson]

Apologies on the above, I was using an older Node.js version than the test supported. So the test does fail on master. I added a comment above to have it so that the test still shows up on all versions, but is clear on the test's state (skipped on older versions).

[dougwilson]

In addition to the above, it seems like this doesn't handle the async hook context (or whatever it is called, sorry!) when the getBody has an error. Here is an example mocha test that fails on your branch I would expect to pass (but let me know if it is actually expected to fail, if that is the case):

    it('should work with async hooks', function (done) {
      var _bodyParser = bodyParser.text()
      var asyncHooks = require('async_hooks')
      var asyncLocalStorage = new asyncHooks.AsyncLocalStorage()

      var server = http.createServer(function (req, res) {
        const store = {
          contextMaintained: true
        }
        asyncLocalStorage.run(store, function () {
          _bodyParser(req, res, function (err) {
            res.end(JSON.stringify(asyncLocalStorage.getStore()))
          })
        })
      })

      request(server)
        .post('/')
        .set('Content-Type', 'text/plain; charset=x-fake')
        .send('user is tobi')
        .expect(200, '{"contextMaintained":true}', done)
    })

[dougwilson]

It a lot of ways, this is kind of giving me deja vu w.r.t. domains API, where they didn't work "out of the box" with various things, even if they were de-facto Node.js design patterns (like in this case using Node.js-style callbacks) and required modules to be heavily modified to not "loose" the domain. Of course after all that work the domains API was just obsoleted and then the module had to undo all that work again, least they stop working once the API was pulled from Node.js core 😅 . The whole time being that the user could use one of the domain APIs to just make it work without any of those module modifications -- makes me wonder if that is not the case here with async hooks... so I dug through the Node.js documentation and I think your test is just using the wrong Node.js API. From https://nodejs.org/api/async_hooks.html#async_hooks_asynclocalstorage_run_store_callback_args

The store is not accessible outside of the callback function or the asynchronous operations created within the callback.

Since middleware will call next asynchronously, it looks like by definition that asyncLocalStorage.run will not make the store available within the callback passed to the body parser created in the callback to run. This sounds from Node.js's own documentation to be working as it should...

On the other hand https://nodejs.org/api/async_hooks.html#async_hooks_asynclocalstorage_enterwith_store says

Calling asyncLocalStorage.enterWith(store) will transition into the context for the remainder of the current synchronous execution and will persist through any following asynchronous calls.

So that sounds like what you should be using as it says there that it will "[...] persist through any following asynchronous calls".

I'm not saying I understand async hooks, from from it. But the documentation from Node.js itself seems to indicate you're using the wrong thing to work with async operations. If I'm misreading it, I'm very sorry! Perhaps you can point to where it says that what your test is doing is actually supposed to work within an async operation (the middleware callback).

[kjarmicki]

In addition to the above, it seems like this doesn't handle the async hook context (or whatever it is called, sorry!) when the getBody has an error. Here is an example mocha test that fails on your branch I would expect to pass (but let me know if it is actually expected to fail, if that is the case)

This test should certainly pass and you've found a bug in my implementation 🙂 I've fixed it with 779a0a3

It a lot of ways, this is kind of giving me deja vu w.r.t. domains API, where they didn't work "out of the box" with various things, even if they were de-facto Node.js design patterns (like in this case using Node.js-style callbacks) and required modules to be heavily modified to not "loose" the domain.

Yes, this does sound familiar. I haven't really used domains API, but judging by the documentation it looks like it's solving similar problem. I hope they got it right this time and the whole thing won't be scraped in the next few years 😉

The store is not accessible outside of the callback function or the asynchronous operations created within the callback.

I'm baffled now 😄 because as far as I understand the callback function and the asynchronous operations here, this is demonstrably not true.

Using the following minimal example, Node.js v12.18.2:

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

storage.run('anything', () => {
  setTimeout(() => {
    console.log(storage.getStore()); // prints "anything"
  }, 10);
});

I consider setTimeout callback to be asynchronous operation created within the callback and the store is accessible there.

According to Node.js documentation, this is precisely the sort of thing AsyncLocalStorage was created for: "It allows storing data throughout the lifetime of a web request or any other asynchronous duration". That's exactly what I'm trying to achieve. https://nodejs.org/api/async_hooks.html#async_hooks_class_asynclocalstorage

Also, if I were wrong, then wrapping getBody call in a promise wouldn't do anything because it's still an async operation created within the callback, but it did. There's also this part of the documentation, stating that context can sometimes be lost in the callback-based code. That's what brought me here in the first place 🙂

I'll give enterWith(store) a try but, I'm a bit concerned it could do a bit too much and leak store between requests, but I'll investigate that, thanks 👍

[dougwilson]

I'm baffled now 😄 because as far as I understand the callback function and the asynchronous operations here, this is demonstrably not true.

That is very strange. The docs (and this module) seem to show the opposite. Perhaps we should open an issue with the Node.js core project to get some clarity on this behavior before we continue to move forward? I know the Async Hook are an Experimental API so likely has wrong/bad docs, rough edges to the APIs, etc. But this was the same issue with domains as well, as it didn't end well adopting within the Experimental timeline of that API. It would probably be beneficial to this module and code if perhaps we could get some core member involvement here; perhaps this whole PR is a work around to a bug in the API that they can just fix, for example? It would be a shame if that were true and all this work was done.

[dougwilson]

I just also tried setImmediate, process.nextTick and they kept the store as well. So what makes the callbacks in this case different from those? Could we distill it down to an example as simple as you provided that looses the store? I would like to at least file a bug report to Node.js core about it as it does seem from simple experiments that this module should just be working, and it not working is feeling more like an async hooks bug vs something that this module needs to actually fix.

[kjarmicki]

Here's one:

const {AsyncLocalStorage} = require('async_hooks');
const {createReadStream} = require('fs');

const storage = new AsyncLocalStorage();

const stream1 = createReadStream(__filename);
storage.run('something', () => {
  // context lost, prints undefined
  stream1.on('data', () => console.log(storage.getStore()));
});

const stream2 = createReadStream(__filename);
storage.run('something else', () => {
  // context maintained, prints "something else"
  new Promise((resolve) => stream2.on('data', resolve)).then(() => console.log(storage.getStore()));
});

It's certainly weird, but it's kind of consistent with that part of the documentation:

In most cases your application or library code should have no issues with AsyncLocalStorage. But in rare cases you may face situations when the current store is lost in one of asynchronous operations. Then you should consider the following options.

If your code is callback-based, it is enough to promisify it with util.promisify(), so it starts working with native promises.

The problem with this part is that it's really vague. "This should work. If it doesn't, wrap it with a promise" 🤷 but they seem to be aware of that.

[dougwilson]

Sure, but as far as we know, it's a bug they are no aware of. Have you tried to report it and see what they say? I mean, if they say "sorry, no fix, wrap in a promise" then fine, but maybe they are like "oh no! we'll get that fixed" and then everyone is for the better, including this module. It doesn't hurt to attempt to report the issue. The docs do not call out it should not work, and still, what bugs me is the docs explicitly say what is working for us should not work:

https://nodejs.org/api/async_hooks.html#async_hooks_asynclocalstorage_run_store_callback_args

The store is not accessible outside of the callback function or the asynchronous operations created within the callback.

[kjarmicki]

I agree 👍

Here's the issue: nodejs/node#34365

[kjarmicki]

I just realized something. We might've been reading this sentence wrong:

The store is not accessible outside of the callback function or the asynchronous operations created within the callback.

I'll break it into two sentences:

1. The store is not accessible outside of the callback function.
2. The store is not accessible outside of the asynchronous operations created within the callback.

Can this interpretation be correct? English is not my first language so I need a little help here 🙂

[kjarmicki]

@dougwilson assuming that the sentence interpretation from my previous comment is correct, is there anything else you'd like me to do in this PR?

[dougwilson]

Well, it means that this whole PR would be for not, as your test added here does not adhere to that. I still think we need to open an issue on Node.js to enguage the async hooks authors to make sure what we are doing here is what is intended and also that the test you wrote is actually valid vs the one I showed.

[kjarmicki]

Ok, so after asking Node folks and poking this API on my own here's my summary:

storage.run(store, () => ...) works intuitively most of the time, except for events, since in Node they're not considered async resources. There's a discussion about supporting it, but no commitment has been made so far: nodejs/node#33723
This makes sense in the context of this PR because body parsing is done with streams and streams have an event-based API.

Weirdly, enterWith(store) seems helpful in certain cases, but according to Node developers, only by accident and the preferred way is to wrap the code that's losing context in a Promise: nodejs/node#34430 (comment)

Well, it means that this whole PR would be for not, as your test added here does not adhere to that.

Could you elaborate? If you revert my changes from read.js but leave the tests in place, they will fail.

Btw, if you're reluctant to pull in this change because it's based on an experimental module's behaviour I fully understand and I have no problem with fixing it on my side using patch-package 🙂

[dougwilson]

So I know it has been a while, but it seemed like I had to engage the original async_hooks author to determine the answers here. It boils down to your original issue is mainly that your usage of the API was not correct; for things like HTTP request, the API is designed such that you should be using https://nodejs.org/dist/latest-v14.x/docs/api/async_hooks.html#async_hooks_asynclocalstorage_enterwith_store to begin your capture in your request handler. Using this API does indeed make it such that your context correctly transits through the data events emitted from the request.

You can also find a long (and ongoing) discussion about these points here: nodejs/node#35286

[Qard]

The event emitter thing is a fairly nuanced issue so I'll try to explain some things. First of all, event emitters on their own are not inherently async, so it doesn't quite make sense to universally treat them as such. It's only through something else which is async that the behaviour of an event emitter can become async.

What AsyncLocalStorage tracks is things that actually are async, and will draw its relationship graph based on what actually triggered the current async scope. However, an event emitter, similar to promises, introduces indirection into a block of code by placing it in a callback that will be called later. This indirection technically exists in regular callback-based APIs too, but they usually are single-use and the callback is supplied in the same place that kicks off the execution that the callback is expecting a response from. An event emitter, on the other hand, and again like promises, can attach a handler in a completely different place from where the execution is kicked off, making the logical "origin" of the execution rather unclear.

For this reason, there are cases where purpose specific handling needs to exist for the given case you are working with. This is why AsyncResource exists, and actually achieves exactly what your patch here is trying to do, but with much better performance. I'd recommend giving that a try.

I should also clarify: the use of enterWith(...) does not eliminate the need for AsyncResource here. As explained above, the execution of the handlers will still be linked to wherever the emit happens, and not where the handler was bound.