"Reply was already sent" error when connecting to websocket

[fastify]

"Reply was already sent" error when connecting to websocket

[appelgriebsch]

Looks like the issue got solved when I change the log calls in the event handlers to

fastify.get('/ws', { websocket: true }, (connection, request) => {
  fastify.log.info(`Opening websocket connection. No. of clients connected: ${fastify.websocketServer.clients.size}`);

  connection.on('close', () => {
    fastify.log.info(`Closing websocket connection. No. of clients connected: ${fastify.websocketServer.clients.size}`);
  });

So eventually an exception in the handler is the root cause of the problem....

[mcollina]

Good!

[Prinzhorn]

Can we reopen this? Errors inside the handler are currently swallowed, which for me is unexpected behavior and inconsistent with the behavior for regular non-ws routes.

'use strict'

const {SqliteError} = require('better-sqlite3');
const fastify = require('fastify')({
  logger: true
})

fastify.register(require('fastify-websocket'))

fastify.get('/ws', { websocket: true }, () => {
  throw new Error('demonstration')
})

// Declare a route
fastify.get('/', (request, reply) => {
  throw new Error('demonstration')
})

fastify.listen(3000, err => {
  if (err) {
    fastify.log.error(err)
    process.exit(1)
  }
})

Connecting to the ws results in

{
  "level": 40,
  "time": 1615569367599,
  "pid": 28959,
  "hostname": "alex-desktop",
  "reqId": "req-1",
  "err": {
    "type": "FastifyError",
    "message": "Reply was already sent.",
    "stack": "FastifyError: Reply was already sent.\n    at _Reply.Reply.send (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/reply.js:118:26)\n    at preHandlerCallback (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/handleRequest.js:126:11)\n    at preValidationCallback (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/handleRequest.js:107:5)\n    at handler (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/handleRequest.js:70:7)\n    at handleRequest (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/handleRequest.js:18:5)\n    at runPreParsing (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/route.js:421:5)\n    at Object.routeHandler [as handler] (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/route.js:379:7)\n    at Router.lookup (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/find-my-way/index.js:339:14)\n    at Server.<anonymous> (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify-websocket/index.js:50:15)\n    at Server.emit (events.js:315:20)",
    "name": "FastifyError",
    "code": "FST_ERR_REP_ALREADY_SENT",
    "statusCode": 500
  },
  "msg": "Reply already sent"
}

Making an HTTP request

{
  "level": 50,
  "time": 1615569798536,
  "pid": 30071,
  "hostname": "alex-desktop",
  "reqId": "req-1",
  "req": {
    "method": "GET",
    "url": "/",
    "hostname": "localhost:3000",
    "remoteAddress": "127.0.0.1",
    "remotePort": 50970
  },
  "res": { "statusCode": 500 },
  "err": {
    "type": "Error",
    "message": "demonstration",
    "stack": "Error: demonstration\n    at Object.<anonymous> (/home/alex/src/issues/issue-256-websocket-swallows-error/index.js:16:9)\n    at Object.routeOptions.handler (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify-websocket/index.js:125:24)\n    at preHandlerCallback (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/handleRequest.js:124:28)\n    at preValidationCallback (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/handleRequest.js:107:5)\n    at handler (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/handleRequest.js:70:7)\n    at handleRequest (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/handleRequest.js:18:5)\n    at runPreParsing (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/route.js:421:5)\n    at Object.routeHandler [as handler] (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/fastify/lib/route.js:379:7)\n    at Router.lookup (/home/alex/src/issues/issue-256-websocket-swallows-error/node_modules/find-my-way/index.js:339:14)\n    at Server.emit (events.js:315:20)"
  },
  "msg": "demonstration"
}

For the ws handler the information about the original new Error('demonstration') is completely lost. I've basically spent the entire day tracking down a bug and this is one of the reason it took so long.