Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ensure that setErrorHandler functions run for errors thrown before the websocket is upgraded #216

Merged
merged 1 commit into from Aug 4, 2022

Conversation

airhorns
Copy link
Member

@airhorns airhorns commented Aug 3, 2022

fastify-websocket has rich support for running requests through the router and hooks before actually upgrading them to full duplex websocket connections outside the normal HTTP lifecycle. Hooks are useful for auth, sessions, tracing, etc etc, and so we take care to make the request look as normal as possible until we reply.hijack() and take over.

Before this change, the onError hook that fastify-websocket was registering was very eagerly handling errors encountered during the hook chain. The onError hook would run before any error handlers added by .setErrorHandler, and it would by-default upgrade the request to dispatch a close code. This changed with the upgrade to fastify v4 -- before, any error in a hook would run the .setErrorHandler errors first, which would probably reply.send, and the request would never get hijacked.

I think the prior behaviour is better for two reasons. First, hook code that is doing auth or sessions or tracing or whatever is going to tend to presume it can reply.send to report an error. I think we should let it instead of having to make every error handler in your app be websocket aware. And second, it is likely to reply.send with a useful response because it is the endorsed way of reporting errors, whereas fastify-websocket's default error handling doesn't really know much about what to do in the face of errors and handles them really generically.

The good news is restoring the fastify v3 behaviour for this module is easy -- we just delete the onError event handler from this library. I think it never really made sense after we switched to dispatching requests through the fastify before upgrading them -- in that phase, the request isn't yet special. The tests pass fine without it on fastify v4. We let fastify's normal error event handling do it's thing before the request gets upgraded. The behavior after upgrade is unchanged, which is to run the websocket specific error handler passed in as an option to this plugin.

Also of note that without making this change, if you reply.send in a setErrorHandler error handler, you end up double sending because the .onError hook hijacks the reply, and then your setErrorHandler code runs and encounters FST_ERR_REP_ALREADY_SENT. Here's the log of me running the new test this PR adds on the old code:

test/hooks.js 1> [1659567917980] INFO (59599 on claw.localdomain): Server listening at http://127.0.0.1:50104
test/hooks.js 1> [1659567917981] INFO (59599 on claw.localdomain): Server listening at http://[::1]:50104
test/hooks.js 1> [1659567917991] INFO (59599 on claw.localdomain): incoming request
test/hooks.js 1>     reqId: "req-1"
test/hooks.js 1>     req: {
test/hooks.js 1>       "method": "GET",
test/hooks.js 1>       "url": "/echo",
test/hooks.js 1>       "hostname": "localhost:50104",
test/hooks.js 1>       "remoteAddress": "127.0.0.1",
test/hooks.js 1>       "remotePort": 50105
test/hooks.js 1>     }
test/hooks.js 1> [1659567917993] ERROR (59599 on claw.localdomain): Fail
test/hooks.js 1>     reqId: "req-1"
test/hooks.js 1>     err: {
test/hooks.js 1>       "type": "Error",
test/hooks.js 1>       "message": "Fail",
test/hooks.js 1>       "stack":
test/hooks.js 1>           Error: Fail
test/hooks.js 1>               at Object.<anonymous> (/Users/airhorns/Code/fastify-websocket/test/hooks.js:94:13)
test/hooks.js 1>               at processTicksAndRejections (node:internal/process/task_queues:96:5)
test/hooks.js 1>     }
test/hooks.js 1> [1659567917996] WARN (59599 on claw.localdomain): Reply already sent
test/hooks.js 1>     reqId: "req-1"
test/hooks.js 1>     err: {
test/hooks.js 1>       "type": "FastifyError",
test/hooks.js 1>       "message": "Reply was already sent.",
test/hooks.js 1>       "stack":
test/hooks.js 1>           FastifyError: Reply was already sent.
test/hooks.js 1>               at Reply.send (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/reply.js:118:26)
test/hooks.js 1>               at Object.<anonymous> (/Users/airhorns/Code/fastify-websocket/test/hooks.js:99:29)
test/hooks.js 1>               at handleError (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/error-handler.js:58:18)
test/hooks.js 1>               at /Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/reply.js:670:13
test/hooks.js 1>               at done (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/hooks.js:213:7)
test/hooks.js 1>               at Object.<anonymous> (/Users/airhorns/Code/fastify-websocket/index.js:93:5)
test/hooks.js 1>               at next (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/hooks.js:219:30)
test/hooks.js 1>               at onSendHookRunner (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/hooks.js:241:3)
test/hooks.js 1>               at onErrorHook (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/reply.js:665:5)
test/hooks.js 1>               at Reply.send (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/reply.js:124:5)
test/hooks.js 1>       "name": "FastifyError",
test/hooks.js 1>       "code": "FST_ERR_REP_ALREADY_SENT",
test/hooks.js 1>       "statusCode": 500
test/hooks.js 1>     }

@airhorns airhorns requested a review from mcollina August 3, 2022 23:14
…e websocket is upgraded

`fastify-websocket` has rich support for running requests through the router and hooks before actually upgrading them to full duplex websocket connections outside the normal HTTP lifecycle. Hooks are useful for auth, sessions, tracing, etc etc, and so we take care to make the request look as normal as possible until we `reply.hijack()` and take over.

Before this change, the `onError` hook that `fastify-websocket` was registering was very eagerly handling errors encountered during the hook chain. The `onError` hook would run *before* any error handlers added by `.setErrorHandler`, and it would by-default upgrade the request to dispatch a close code. This changed with the upgrade to fastify v4 -- before, any error in a hook would run the `.setErrorHandler` errors first, which would probably reply.send, and the request would never get hijacked.

I think the prior behaviour is better for two reasons. First, hook code that is doing auth or sessions or tracing or whatever is going to tend to presume it can `reply.send` to report an error. I think we should let it instead of having to make every error handler in your app be websocket aware. And second, it is likely to reply.send with a useful response because it is the endorsed way of reporting errors, whereas fastify-websocket's default error handling doesn't really know much about what to do in the face of errors and handles them really generically.

The good news is restoring the fastify v3 behaviour for this module is easy -- we just delete the `onError` event handler from this library. I think it never really made sense after we switched to dispatching requests through the fastify before upgrading them -- in that phase, the request isn't yet special. We let fastify's normal error event handling do it's thing before the request gets upgraded. The behavior after upgrade is unchanged, which is to run the websocket specific error handler passed in as an option to this plugin.

Also of note that without making this change, if you `reply.send` in a `setErrorHandler` error handler, you end up double sending because the `.onError` hook hijacks the reply, and then your `setErrorHandler` code runs and encounters `FST_ERR_REP_ALREADY_SENT`. Here's the log of me running the new test this PR adds on the old code:

```
test/hooks.js 1> [1659567917980] INFO (59599 on claw.localdomain): Server listening at http://127.0.0.1:50104
test/hooks.js 1> [1659567917981] INFO (59599 on claw.localdomain): Server listening at http://[::1]:50104
test/hooks.js 1> [1659567917991] INFO (59599 on claw.localdomain): incoming request
test/hooks.js 1>     reqId: "req-1"
test/hooks.js 1>     req: {
test/hooks.js 1>       "method": "GET",
test/hooks.js 1>       "url": "/echo",
test/hooks.js 1>       "hostname": "localhost:50104",
test/hooks.js 1>       "remoteAddress": "127.0.0.1",
test/hooks.js 1>       "remotePort": 50105
test/hooks.js 1>     }
test/hooks.js 1> [1659567917993] ERROR (59599 on claw.localdomain): Fail
test/hooks.js 1>     reqId: "req-1"
test/hooks.js 1>     err: {
test/hooks.js 1>       "type": "Error",
test/hooks.js 1>       "message": "Fail",
test/hooks.js 1>       "stack":
test/hooks.js 1>           Error: Fail
test/hooks.js 1>               at Object.<anonymous> (/Users/airhorns/Code/fastify-websocket/test/hooks.js:94:13)
test/hooks.js 1>               at processTicksAndRejections (node:internal/process/task_queues:96:5)
test/hooks.js 1>     }
test/hooks.js 1> [1659567917996] WARN (59599 on claw.localdomain): Reply already sent
test/hooks.js 1>     reqId: "req-1"
test/hooks.js 1>     err: {
test/hooks.js 1>       "type": "FastifyError",
test/hooks.js 1>       "message": "Reply was already sent.",
test/hooks.js 1>       "stack":
test/hooks.js 1>           FastifyError: Reply was already sent.
test/hooks.js 1>               at Reply.send (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/reply.js:118:26)
test/hooks.js 1>               at Object.<anonymous> (/Users/airhorns/Code/fastify-websocket/test/hooks.js:99:29)
test/hooks.js 1>               at handleError (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/error-handler.js:58:18)
test/hooks.js 1>               at /Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/reply.js:670:13
test/hooks.js 1>               at done (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/hooks.js:213:7)
test/hooks.js 1>               at Object.<anonymous> (/Users/airhorns/Code/fastify-websocket/index.js:93:5)
test/hooks.js 1>               at next (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/hooks.js:219:30)
test/hooks.js 1>               at onSendHookRunner (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/hooks.js:241:3)
test/hooks.js 1>               at onErrorHook (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/reply.js:665:5)
test/hooks.js 1>               at Reply.send (/Users/airhorns/Code/fastify-websocket/node_modules/fastify/lib/reply.js:124:5)
test/hooks.js 1>       "name": "FastifyError",
test/hooks.js 1>       "code": "FST_ERR_REP_ALREADY_SENT",
test/hooks.js 1>       "statusCode": 500
test/hooks.js 1>     }
```
Copy link
Member

@mcollina mcollina left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm

@mcollina mcollina merged commit 1848dfe into master Aug 4, 2022
@airhorns
Copy link
Member Author

airhorns commented Aug 5, 2022

@mcollina I think technically speaking this is semver major in that errors will be handled a little bit differently, but pragmatically speaking I am not sure anyone will really notice as it is very subtle. Do you have a preference asto what the next version should be?

@Uzlopak Uzlopak deleted the pre-upgrade-error-dispatch branch August 5, 2022 12:45
@mcollina
Copy link
Member

mcollina commented Aug 5, 2022

Let's bump the major, it's not as problematic as bumping Fastify.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants