Fix context loss when async storage is instantiated early in the request lifecycle #12

kibertoad · 2020-08-13T13:52:22Z

…tion

kibertoad · 2020-08-13T14:00:30Z

@Eomm Does the light-my-request go through the whole usual HTTP request flow with http body parser et all? I wonder if behaviour is different from what was reported in fastify/help#236 due to missing some of the steps that happen in real usage scenarios.

mcollina · 2020-08-13T15:22:23Z

lib/requestContextPlugin.js

@@ -10,7 +10,7 @@ function plugin(fastify, opts, next) {
  fastify.decorate('requestContext', requestContext)
  fastify.decorateRequest('requestContext', requestContext)

-  fastify.addHook('onRequest', (req, res, done) => {
+  fastify.addHook(opts.hook || 'onRequest', (req, res, done) => {


I think we might want to run this on multiple hooks as well, maybe it should be an array?

Added, but what is the use-case for that? Why would you want to reinitialize storage on multiple steps, if just the earliest one should suffice? Also I'm thinking of switching default to preValidation, as it seems to be logical to init it as early as possible. Thoughts?

onRequest happens before preValidation.

I don't think it should be reinitialized, but probably something must be done to retain the context.

I digged deeper, and yes, we are definitely losing the context after payload parsing is triggered (as in we retain storage betwen onRequest and preParsing, but lose between preParsing and preValidation), which actually seems to be a problem that was around a while and was breaking CLS in the past as well. Still investigating what the options are.

This looks like a variation of nodejs/node#34401
What are we using for body parsing in fastify? some kind of custom in-house solution? is there some sort of pooling involved there?

I think this can be done by manually doing something inside the 'preValidation' hook.
@puzpuzpuz do you think it would be possible to create a custom AsyncResource there and restore it in that way?

If the request object is available in all hooks, then yes, it should be possible to initialize an AsyncResource early enough, store it in req and then restore it where necessary and, may be, wrap next calls with asyncResource.runInAsyncScope. This approach also requires proper integration between ALS and the AsyncResource, but that part is trivial.

That's possible, the core request is available.

@puzpuzpuz @mcollina What am I doing wrong?

function plugin(fastify, opts, next) { fastify.decorate('requestContext', requestContext) fastify.decorateRequest('requestContext', requestContext) const hook = opts.hook || 'onRequest' if (hook === 'onRequest' || hook === 'preParsing') { fastify.addHook('preValidation', (req, res, done) => { const asyncResource = req.asyncResource asyncResource.runInAsyncScope(done, req) }) } fastify.addHook(hook, (req, res, done) => { const asyncResource = new AsyncResource('fastify-request-context') als.runWith(() => { req.asyncResource = asyncResource asyncResource.runInAsyncScope(done, req) }, opts.defaultStoreValues) }) next() }

@kibertoad you should move AsyncResource ctor call inside of the als.runWith call. This way it'll be associated with the same store object (I mean the Map object created by the als wrapper library).

@puzpuzpuz Thanks!
@mcollina I believe PR is ready for the final rereview.

mcollina · 2020-08-13T15:23:06Z

test/requestContextPlugin.e2e.spec.js

+      handler: endpoint,
+    })
+
+    app.listen(8085, '0.0.0.0', (err, address) => {


please set 0 as the port and use app.server.address() to get the actual port.
There is no need to use 0.0.0.0 either.

mcollina · 2020-08-13T15:23:54Z

test/requestContextPlugin.e2e.spec.js

+const { TestService } = require('./internal/testService')
+
+function initAppPostWithPrevalidation(endpoint) {
+  return new Promise((resolve) => {


Do not wrap with a promise, use an async function. .listen() returns a promise if a callback is not passed in.

mcollina · 2020-08-13T15:24:14Z

test/requestContextPlugin.e2e.spec.js

+    let responseCounter = 0
+    return new Promise((resolveResponsePromise) => {
+      const promiseRequest2 = new Promise((resolveRequest2Promise) => {
+        const promiseRequest1 = new Promise((resolveRequest1Promise) => {


please use async functions instead.

Are you sure that would work as expected? In this case we want to able to have flexibility to control when each promise resolves specifically, and I don't think that is possible with async functions.

…test that covers multi-phase asyncstorage usage

Eomm · 2020-08-13T18:24:22Z

test/requestContextPlugin.e2e.spec.js

+const { fastifyRequestContextPlugin } = require('../lib/requestContextPlugin')
+const { TestService } = require('./internal/testService')
+
+async function initAppPostWithPrevalidation(endpoint) {


this function is duplicated in test/requestContextPlugin.spec.js (except ready vs listen)

Could you use once?

Yeah, need to do a couple of deduplication passes. Will do.

@Eomm Extracted this part, probably can extract some more.

Eomm · 2020-08-13T18:28:32Z

lib/requestContextPlugin.js

@@ -10,7 +10,7 @@ function plugin(fastify, opts, next) {
  fastify.decorate('requestContext', requestContext)
  fastify.decorateRequest('requestContext', requestContext)

-  fastify.addHook('onRequest', (req, res, done) => {
+  fastify.addHook(opts.hook || 'preValidation', (req, res, done) => {


Would it be a semver major this change?

***continue
if the opts.hook is an array, it won't works, so we need to iterate over the array.
Why we should add the same hook on multiple lifecycle events?

Yes, will have to do major version bump.

Hopefully there is a way to fix losing context from onRequest stage, though, but worst case scenario, initting ASL only on preValidation upwards can be made canonic.

Eomm · 2020-08-13T18:33:30Z

index.d.ts

 export type RequestContextOptions = {
  defaultStoreValues?: Record<string, any>
+  hook?: Hook | Hook[]


I think it is wrong since this doesn't work:

fastify.addHook(['onResponse', 'preHandler'], ()=>{}) // throw new FST_ERR_HOOK_INVALID_TYPE()

***continue

Don't see much point in having multiple hooks, so kept just one.

kibertoad · 2020-08-14T10:20:46Z

lib/requestContextPlugin.js

    als.runWith(() => {
+      wrapHttpEmitters(req.raw, res.raw)


@puzpuzpuz In your example I see that you are using reply.res instead of res.raw. Any reason for that?

IIRC that property is not available in Fastify v2.x which my plugin requires.

lib/requestContextPlugin.js

mcollina · 2020-08-14T14:29:31Z

lib/requestContextPlugin.js

    als.runWith(() => {
-      done()
+      const asyncResource = new AsyncResource('fastify-request-context')
+      req.asyncResource = asyncResource


I would probably store this in a symbol instead

mcollina

lgtm

(test will fail as there is a botched find-my-way release out, don-'t worry about them as it will be fixed in a few minutes)

kibertoad · 2020-08-14T15:46:11Z

@mcollina Jobs still fail for me when I rerun them, even though they pass locally with fully rebuilt package-lock.json.
Are GitHub actions caching dependencies by default?

Eomm · 2020-08-15T10:59:38Z

Are GitHub actions caching dependencies by default?

No, you should be able to re-run the pipeline going in the details of the run in order to let the badge in README green again

Add test for POST request with body, using async storage in prevalida…

2a9df9c

…tion

kibertoad requested a review from Eomm August 13, 2020 13:52

Fix linting

4e8b091

kibertoad mentioned this pull request Aug 13, 2020

fastify-request-context is not working for POST API calls fastify/help#236

Closed

kibertoad added 3 commits August 13, 2020 17:21

Add end-to-end test

3da0d3b

Fix linting

7bce481

Implement hook configuration support

075a526

kibertoad changed the title ~~Add test for POST request with body, using async storage in prevalida…~~ Support specifying alternate hook for the plugin Aug 13, 2020

Fix typo

d405af2

kibertoad requested a review from mcollina August 13, 2020 14:56

Remove unneeded timeout config

d97cb01

mcollina reviewed Aug 13, 2020

View reviewed changes

kibertoad added 2 commits August 13, 2020 18:48

Address code review comments

48c23e7

Set default to preValidation which actually works, update types, add …

c37fe5c

…test that covers multi-phase asyncstorage usage

Eomm reviewed Aug 13, 2020

View reviewed changes

Remove support for multiple hooks, clarify documentation

965f256

rahul2123 approved these changes Aug 14, 2020

View reviewed changes

kibertoad added 4 commits August 14, 2020 11:18

Reduce duplication

5e19b08

Add test case for not losing context after body parsing

0be0b99

Monkey-patch event emitter to support all lifecycle phases

b7384f0

Fix Node 10 support

d859cfa

kibertoad commented Aug 14, 2020

View reviewed changes

kibertoad requested review from Eomm and mcollina August 14, 2020 10:24

kibertoad changed the title ~~Support specifying alternate hook for the plugin~~ Fix context loss when async storage is instantiated early in the request lifecycle Aug 14, 2020

kibertoad added 2 commits August 14, 2020 16:36

Implement alternate solution without monkey-patching

4cedd50

Extend test to also cover preSerialization hook

ecaea79

mcollina reviewed Aug 14, 2020

View reviewed changes

Use symbol for asyncResource

457f7ac

mcollina approved these changes Aug 14, 2020

View reviewed changes

kibertoad merged commit a5cbaf2 into master Aug 14, 2020

kibertoad deleted the test/prevalidation branch August 14, 2020 15:34

vdeturckheim mentioned this pull request Sep 4, 2020

express.json() breaks AsyncLocalStorage in node 14 expressjs/express#4396

Closed

kibertoad mentioned this pull request Mar 8, 2021

Upgrading from 1.0.1 to 1.0.2 results in requestContext.get('key') returning undefined kibertoad/asynchronous-local-storage#8

Closed

kibertoad mentioned this pull request Dec 22, 2021

AsyncLocalStorage fastify/fastify#3569

Closed

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix context loss when async storage is instantiated early in the request lifecycle #12

Fix context loss when async storage is instantiated early in the request lifecycle #12

kibertoad commented Aug 13, 2020 •

edited

Loading

kibertoad commented Aug 13, 2020 •

edited

Loading

mcollina Aug 13, 2020

kibertoad Aug 13, 2020

mcollina Aug 13, 2020

kibertoad Aug 13, 2020 •

edited

Loading

kibertoad Aug 13, 2020

puzpuzpuz Aug 14, 2020

mcollina Aug 14, 2020

kibertoad Aug 14, 2020 •

edited

Loading

puzpuzpuz Aug 14, 2020

kibertoad Aug 14, 2020

mcollina Aug 13, 2020

kibertoad Aug 13, 2020

mcollina Aug 13, 2020

kibertoad Aug 13, 2020

mcollina Aug 13, 2020

kibertoad Aug 13, 2020

mcollina Aug 13, 2020

Eomm Aug 13, 2020

kibertoad Aug 13, 2020

kibertoad Aug 14, 2020

Eomm Aug 13, 2020

kibertoad Aug 13, 2020

kibertoad Aug 13, 2020

Eomm Aug 13, 2020

kibertoad Aug 13, 2020

kibertoad Aug 14, 2020

puzpuzpuz Aug 14, 2020

mcollina Aug 14, 2020

kibertoad Aug 14, 2020

mcollina left a comment

kibertoad commented Aug 14, 2020

Eomm commented Aug 15, 2020

Fix context loss when async storage is instantiated early in the request lifecycle #12

Fix context loss when async storage is instantiated early in the request lifecycle #12

Conversation

kibertoad commented Aug 13, 2020 • edited Loading

kibertoad commented Aug 13, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kibertoad Aug 13, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kibertoad Aug 14, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mcollina left a comment

Choose a reason for hiding this comment

kibertoad commented Aug 14, 2020

Eomm commented Aug 15, 2020

kibertoad commented Aug 13, 2020 •

edited

Loading

kibertoad commented Aug 13, 2020 •

edited

Loading

kibertoad Aug 13, 2020 •

edited

Loading

kibertoad Aug 14, 2020 •

edited

Loading