fix(ssrServer): fastify scope resulted in hooks being called more than once #1242

10xLaCroixDrinker · 2024-01-19T18:53:11Z

Description

Scopes the entire application within a top level plugin

Motivation and Context

Currently rejected preflight requests result in an error because preHandler is called twice making it attempt to end timers that have already ended.

ERROR: Fastify application error: method OPTIONS, url "/success", correlationId "1fa8c448-db62-4552-968c-408857451b23", headersSent: false
    reqId: "req-1"
    error: {
      "type": "TypeError",
      "message": "The \"time\" argument must be an instance of Array. Received type number (9.911919)",
      "stack":
          TypeError [ERR_INVALID_ARG_TYPE]: The "time" argument must be an instance of Array. Received type number (9.911919)
              at process.hrtime (node:internal/process/per_thread:84:5)
              at endTimer (~/git/one-app-2/lib/server/utils/logging/fastifyPlugin.js:67:26)
              at Object.<anonymous> (~/git/one-app-2/lib/server/utils/logging/fastifyPlugin.js:189:5)
              at hookIterator (~/git/one-app-2/node_modules/fastify/lib/hooks.js:409:10)
              at next (~/git/one-app-2/node_modules/fastify/lib/hooks.js:243:18)
              at hookRunner (~/git/one-app-2/node_modules/fastify/lib/hooks.js:265:5)
              at notFound (~/git/one-app-2/node_modules/fastify/lib/reply.js:875:5)
              at Reply.callNotFound (~/git/one-app-2/node_modules/fastify/lib/reply.js:451:3)
              at Object.<anonymous> (~/git/one-app-2/node_modules/@fastify/cors/index.js:78:13)
              at preHandlerCallback (~/git/one-app-2/node_modules/fastify/lib/handleRequest.js:137:37)
      "code": "ERR_INVALID_ARG_TYPE"
    }

How Has This Been Tested?

Ran the prod sample locally and sent the following request and validated the error no longer occurred:

$ curl --location --request OPTIONS 'http://localhost:3000/success' \
--header 'Origin: test.fail' \
--header 'Access-Control-Request-Method: GET' \
--header 'Access-Control-Request-Headers: content-type'

I also added logs to each of the handlers and tested the failing preflight before and after

before

Note that preHandler appears twice for req-1

WARN: onRequest 1
    reqId: "req-1"
WARN: onRequest 2
    reqId: "req-1"
WARN: preHandler
    reqId: "req-1"
WARN: preHandler
    reqId: "req-1"
ERROR: Fastify application error: method OPTIONS, url "/success", correlationId "1fa8c448-db62-4552-968c-408857451b23", headersSent: false
    reqId: "req-1"
    error: {
      "type": "TypeError",
      "message": "The \"time\" argument must be an instance of Array. Received type number (9.911919)",
      "stack":
          TypeError [ERR_INVALID_ARG_TYPE]: The "time" argument must be an instance of Array. Received type number (9.911919)
              at process.hrtime (node:internal/process/per_thread:84:5)
              at endTimer (~/git/one-app-2/lib/server/utils/logging/fastifyPlugin.js:67:26)
              at Object.<anonymous> (~/git/one-app-2/lib/server/utils/logging/fastifyPlugin.js:189:5)
              at hookIterator (~/git/one-app-2/node_modules/fastify/lib/hooks.js:409:10)
              at next (~/git/one-app-2/node_modules/fastify/lib/hooks.js:243:18)
              at hookRunner (~/git/one-app-2/node_modules/fastify/lib/hooks.js:265:5)
              at notFound (~/git/one-app-2/node_modules/fastify/lib/reply.js:875:5)
              at Reply.callNotFound (~/git/one-app-2/node_modules/fastify/lib/reply.js:451:3)
              at Object.<anonymous> (~/git/one-app-2/node_modules/@fastify/cors/index.js:78:13)
              at preHandlerCallback (~/git/one-app-2/node_modules/fastify/lib/handleRequest.js:137:37)
      "code": "ERR_INVALID_ARG_TYPE"
    }
WARN: onSend
    reqId: "req-1"
WARN: onResponse
    reqId: "req-1"

after

WARN: onRequest 1
    reqId: "req-1"
WARN: onRequest 2
    reqId: "req-1"
WARN: preHandler
    reqId: "req-1"
WARN: onSend
    reqId: "req-1"

Types of Changes

Bug fix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that would cause existing functionality to not work as expected)
Documentation (adding or updating documentation)
Dependency update
Security update

Checklist:

My change requires a change to the documentation and I have updated the documentation accordingly.
These changes should be applied to a maintenance branch.
This change requires cross browser checks.
Performance tests should be ran against the server prior to merging.
This change impacts caching for client browsers.
This change impacts HTTP headers.
This change adds additional environment variable requirements for One App users.
I have added the Apache 2.0 license header to any new files created.

What is the Impact to Developers Using One App?

No errors on preflight rejection

…n once

github-actions · 2024-01-19T18:55:43Z

Size Change: 0 B

Total Size: 712 kB

ℹ️ View Unchanged

Filename	Size
`./build/app/app.js`	164 kB
`./build/app/app~vendors.js`	411 kB
`./build/app/runtime.js`	7.07 kB
`./build/app/service-worker-client.js`	7.25 kB
`./build/app/vendors.js`	123 kB

_{compressed-size-action}

JAdshead · 2024-01-19T19:50:23Z

__tests__/server/ssrServer.spec.js

+    expect(register).toHaveBeenCalledTimes(22);
+    expect(register.mock.calls[1][0]).toEqual(fastifySensible);
+    expect(register.mock.calls[2][0]).toEqual(ensureCorrelationId);
+    expect(register.mock.calls[3][0]).toEqual(fastifyCookie);
+    expect(register.mock.calls[4][0]).toEqual(logging);
+    expect(register.mock.calls[5][0]).toEqual(fastifyMetrics);
+    expect(register.mock.calls[6]).toEqual([


we should revisit these tests. just bumping the calls number does not make it obvious what should or should not be happening.

10xLaCroixDrinker · 2024-01-19T23:36:59Z

__tests__/integration/one-app.spec.js

@@ -178,7 +178,7 @@ describe('Tests that require Docker setup', () => {
        },
      });

-      expect(response.status).toBe(200);
+      expect(response.status).toBe(404);


This was only 200 because the application error caused by this bug was not setting the HTTP status and it defaulted to 200. Fixed in #1243

For some more background this test did not change when we migrated from express to fastify. However, it was correct in express. The cors express middleware does not change the HTTP status on preflight rejection and it defaults to 200. The @fastify/cors package calls reply.callNotFound on preflight rejection.

fix(ssrServer): fastify scope resulted in hooks being called more tha…

aede225

…n once

10xLaCroixDrinker requested review from a team as code owners January 19, 2024 18:53

JAdshead reviewed Jan 19, 2024

View reviewed changes

Matthew-Mallimo previously approved these changes Jan 19, 2024

View reviewed changes

10xLaCroixDrinker mentioned this pull request Jan 19, 2024

fix(errorHandler): application errors would result in a 200 response #1243

Merged

14 tasks

test(integration): expect 404 for preflight rejection

408e9a4

10xLaCroixDrinker dismissed Matthew-Mallimo’s stale review via 408e9a4 January 19, 2024 23:33

10xLaCroixDrinker commented Jan 19, 2024

View reviewed changes

Matthew-Mallimo approved these changes Jan 22, 2024

View reviewed changes

Merge branch 'main' into bugfix/scope-application

1515c4a

dogpatch626 approved these changes Jan 22, 2024

View reviewed changes

10xLaCroixDrinker merged commit 2d84d6a into main Jan 22, 2024
9 checks passed

10xLaCroixDrinker deleted the bugfix/scope-application branch January 22, 2024 21:10

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix(ssrServer): fastify scope resulted in hooks being called more than once #1242

fix(ssrServer): fastify scope resulted in hooks being called more than once #1242

10xLaCroixDrinker commented Jan 19, 2024 •

edited

Loading

github-actions bot commented Jan 19, 2024 •

edited

Loading

JAdshead Jan 19, 2024

10xLaCroixDrinker Jan 19, 2024

10xLaCroixDrinker Jan 19, 2024

fix(ssrServer): fastify scope resulted in hooks being called more than once #1242

fix(ssrServer): fastify scope resulted in hooks being called more than once #1242

Conversation

10xLaCroixDrinker commented Jan 19, 2024 • edited Loading

Description

Motivation and Context

How Has This Been Tested?

Types of Changes

Checklist:

What is the Impact to Developers Using One App?

github-actions bot commented Jan 19, 2024 • edited Loading

JAdshead Jan 19, 2024

Choose a reason for hiding this comment

10xLaCroixDrinker Jan 19, 2024

Choose a reason for hiding this comment

10xLaCroixDrinker Jan 19, 2024

Choose a reason for hiding this comment

10xLaCroixDrinker commented Jan 19, 2024 •

edited

Loading

github-actions bot commented Jan 19, 2024 •

edited

Loading