fix: delay plugin loading until next tick #177

chrskrchr · 2022-03-01T17:51:51Z

Description

This PR is a followup to #173. That original PR attempted to fix the async plugin loading issue described in fastify/3726 by delaying each plugin's after promise resolution until the next tick. However, this resulted in a subtle but significant change where subsequent plugin registration functions were now being enqueued in this.q and executed on the same tick of the event loop as registration, a consequence of the registration function being the only item in this.q. We observed a symptom of this change in the unrelated unit test linked below:

https://github.com/fastify/avvio/pull/173/files#r814200533

We didn't think the above was a major/breaking change in behavior, but that proved to be incorrect per this bug report:

fastify/fastify-cors#189

This PR improves on the initial PR by delaying the entire loading of each plugin to the next tick rather than just the plugin's after promise resolution. This change has been tested in @pvanagtmaal's test repo and produces the expected output for both the working and previously-broken test cases:

➜  fastify-test git:(main) ✗ node working.js
cors registered
└── /
    ├── /
    ├── * (OPTIONS)
    └── v
        ├── 1/user (GET)
        └── 2/user (GET)

➜  fastify-test git:(main) ✗ node broken.js
└── /
    ├── /
    ├── * (OPTIONS)
    └── v
        ├── 1/user (GET)
        └── 2/user (GET)

It also doesn't require any unexpected changes in unrelated test cases like the previous PR.

Checklist

run npm run test and npm run benchmark
tests and/or benchmarks are included
documentation is changed or added
commit message and code follows the Developer's Certification of Origin
and the Code of conduct

plugin.js

test/await-after.test.js

RafaelGSS · 2022-03-01T18:12:27Z

plugin.js

@@ -40,6 +40,13 @@ function promise () {
  return obj
 }

+function loadPluginNextTick (toLoad, cb) {


Can you add a comment explaining why this is necessary?

…ment

mcollina · 2022-03-01T20:37:04Z

plugin.js

+  const parent = this
+  process.nextTick(() => {
+    loadPlugin.call(parent, toLoad, cb)
+  })


please avoid creating this function.

hey @mcollina - apologies if I'm being dense here, but is the issue here that this work is being delayed until the next tick? or that it's being done within an anonymous function

Just with the anonymous function. Instead of allocating a new closure you can use a top-level function and pass arguments to it:

process.nextTick(console.log, 42)

oh wow - I had no idea that process.nextTick() could accept a list of args 🤦

I just push a commit with this refactor. The function still needs to use .bind(parent) to set the right context for the loadPlugin call (which still creates a new function internally), but the refactor is a bit more readable IMO.

RafaelGSS · 2022-03-02T12:29:56Z

test/await-after.test.js

+  t.notOk(thirdLoaded, 'third is not loaded')
+  t.notOk(fourthLoaded, 'fourth is not loaded')
+
+  const contents = await fs.readFile(path.join(__dirname, 'fixtures', 'dummy.txt'), 'utf-8')


what is your intention reading it twice?

Just wanting to mix in a bit of async FS I/O in various contexts (e.g., both at the top-level and within a plugin) per @Eomm's request on the original PR:

#173 (comment)

OK - so it looks like this top-level async FS read (a late addition to the original PR) was what caused the test to pass without my changes. It prevented the bug from occurring. I've removed the top-level FS read from the test and verified that test fails as expected without my changes.

@Eomm - can you verify that the remaining FS read that occurs within the plugin registration function on L363 still satisfies your original request to mix in some async FS I/O in the test?

…onymous closure

RafaelGSS

The tests added are passing even without your change. Could you take a look?

chrskrchr · 2022-03-02T13:47:45Z

The tests added are passing even without your change. Could you take a look?

ooof - that's obviously unexpected. Will take a look ASAP.

…rom occurring

xtx1130

I think this case can be added in test cases:

const t = require('tap')
const avvio = require('avvio')
let record = ''
const app = {}
avvio(app, { autostart: false })
function sleep(timeMs){
  return new Promise((resolve) => setTimeout(resolve, timeMs));
}

(async () => {
  await app.use(async function plugin0() {
    t.pass("plugin0 init");
    record += 'plugin0|'
  })
  await app.use(async function plugin1() {
    t.pass("plugin1 init");
    await sleep(500);
    record += 'plugin1|'
  })
  await sleep(1);
  await app.use(async function plugin2() {
    t.pass("plugin2 init");
    await sleep(500);
    record += 'plugin2|'
  })
  record += 'ready'
  t.equal(record, 'plugin0|plugin1|plugin2|ready')
})()

before:

after:

chrskrchr · 2022-03-03T12:59:33Z

I think this case can be added in test cases:

...

Nice! Would you like to see that test in place of the existing test added in this PR? Or alongside it? It's more or less testing the same behavior AFAICT, but with a different style of assertions.

chrskrchr · 2022-03-03T13:35:27Z

It's more or less testing the same behavior AFAICT, but with a different style of assertions.

Actually, I see that your test case is testing the await app.use() behavior rather than app.after(). I've added it to the await-use.test.js suite.

chrskrchr · 2022-03-03T13:37:54Z

The tests added are passing even without your change. Could you take a look?

ooof - that's obviously unexpected. Will take a look ASAP.

Also, the false negative mentioned above was addressed by removing the top-level async FS read that was preventing the underlying bug from occurring when my code wasn't present:

#177 (comment)

mcollina

lgtm

RafaelGSS

LGTM.

* fix: delay plugin loading until next tick * move `loadPluginNextTick` function alongside `loadPlugin` and add comment * refactor loadPluginNextTick to use a bound function rather than an anonymous closure * remove top-level FS read from unit test that was preventing the bug from occurring * add additional test case

chrskrchr · 2022-03-03T17:53:35Z

Merged #177 into master.

😬 I mean, what are the odds I screw this up twice?

xtx1130

Great work!

fix: delay plugin loading until next tick

28f88b4

chrskrchr commented Mar 1, 2022

View reviewed changes

plugin.js Show resolved Hide resolved

test/await-after.test.js Show resolved Hide resolved

chrskrchr marked this pull request as ready for review March 1, 2022 17:57

chrskrchr mentioned this pull request Mar 1, 2022

Promise returned by FastifyInstance.register() is resolved before plugin's async registration promise has resolved fastify/fastify#3726

Closed

2 tasks

RafaelGSS reviewed Mar 1, 2022

View reviewed changes

move loadPluginNextTick function alongside loadPlugin and add com…

01d84b7

…ment

mcollina reviewed Mar 1, 2022

View reviewed changes

RafaelGSS reviewed Mar 2, 2022

View reviewed changes

refactor loadPluginNextTick to use a bound function rather than an an…

2b4a86f

…onymous closure

RafaelGSS requested changes Mar 2, 2022

View reviewed changes

remove top-level FS read from unit test that was preventing the bug f…

42fd8d9

…rom occurring

xtx1130 suggested changes Mar 3, 2022

View reviewed changes

add additional test case

692aede

mcollina approved these changes Mar 3, 2022

View reviewed changes

RafaelGSS approved these changes Mar 3, 2022

View reviewed changes

mcollina merged commit a8dcf0e into fastify:master Mar 3, 2022

chrskrchr deleted the ck.asyncPluginFix2 branch March 3, 2022 18:55

xtx1130 reviewed Mar 4, 2022

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: delay plugin loading until next tick #177

fix: delay plugin loading until next tick #177

chrskrchr commented Mar 1, 2022 •

edited

Loading

RafaelGSS Mar 1, 2022

chrskrchr Mar 1, 2022 •

edited

Loading

mcollina Mar 1, 2022

chrskrchr Mar 1, 2022

mcollina Mar 2, 2022

chrskrchr Mar 2, 2022

RafaelGSS Mar 2, 2022

chrskrchr Mar 2, 2022

chrskrchr Mar 2, 2022 •

edited

Loading

RafaelGSS left a comment

chrskrchr commented Mar 2, 2022

xtx1130 left a comment

chrskrchr commented Mar 3, 2022

chrskrchr commented Mar 3, 2022 •

edited

Loading

chrskrchr commented Mar 3, 2022

mcollina left a comment

RafaelGSS left a comment

chrskrchr commented Mar 3, 2022

xtx1130 left a comment

fix: delay plugin loading until next tick #177

fix: delay plugin loading until next tick #177

Conversation

chrskrchr commented Mar 1, 2022 • edited Loading

Description

Checklist

RafaelGSS Mar 1, 2022

Choose a reason for hiding this comment

chrskrchr Mar 1, 2022 • edited Loading

Choose a reason for hiding this comment

mcollina Mar 1, 2022

Choose a reason for hiding this comment

chrskrchr Mar 1, 2022

Choose a reason for hiding this comment

mcollina Mar 2, 2022

Choose a reason for hiding this comment

chrskrchr Mar 2, 2022

Choose a reason for hiding this comment

RafaelGSS Mar 2, 2022

Choose a reason for hiding this comment

chrskrchr Mar 2, 2022

Choose a reason for hiding this comment

chrskrchr Mar 2, 2022 • edited Loading

Choose a reason for hiding this comment

RafaelGSS left a comment

Choose a reason for hiding this comment

chrskrchr commented Mar 2, 2022

xtx1130 left a comment

Choose a reason for hiding this comment

chrskrchr commented Mar 3, 2022

chrskrchr commented Mar 3, 2022 • edited Loading

chrskrchr commented Mar 3, 2022

mcollina left a comment

Choose a reason for hiding this comment

RafaelGSS left a comment

Choose a reason for hiding this comment

chrskrchr commented Mar 3, 2022

xtx1130 left a comment

Choose a reason for hiding this comment

chrskrchr commented Mar 1, 2022 •

edited

Loading

chrskrchr Mar 1, 2022 •

edited

Loading

chrskrchr Mar 2, 2022 •

edited

Loading

chrskrchr commented Mar 3, 2022 •

edited

Loading