ws Server errors on Node.js v10-12 http server don't immediately destroy the Socket like in Node 14+

[davidmurdoch]

In Node 14+ Socket defaults to setting autoDestroy: true. The http library uses these defaults internally. The ws library behaves differently on Node v10-12 than it does on Node 14+ because of this internal change.

In the example program below you'll find that on Node v10-12 the websocket connection will take exactly 30 seconds to close after a maxPayload size error occurs. But on Node v14 and up the closure is nearly instantaneous.

// this program:
//  * starts an http server on port 8545
//  * the http server hands off WebSocket upgrades to a `ws` Server
//  * then sends a WebSocket payload to the server that is over it's `maxPayload` size
//  * it "handles" the server-side `ws` error by listening to the "error" event
//  * it expects the WebSocket connection to close immediately, but on node 10-12 it doesn't

const http = require("http");
const WebSocket = require("ws");
const MAX_PAYLOAD_SIZE = 15 * 1024 * 1024; // an arbitrary size
const PORT = 8545;

const server = http.createServer();
const websocketServer = new WebSocket.Server({
  noServer: true, // we want to use our own `http` server
  maxPayload: MAX_PAYLOAD_SIZE,
});

function handleHttpUpgrade(request, socket, head) {
  websocketServer.handleUpgrade(request, socket, head, (ws, incomingMessage) => {
    // handle websocket errors, like "Max payload size exceeded":
    ws.on("error", (error) => {
      console.log("ws error", error);
      console.log("ws errored at", new Date());
    });

    ws.on("close", () => {
      // log the current time when the server-side websocket is closed
      console.log("ws closed at", new Date());
    });
  });
}

function listening() {
  const clientWebsocket = new WebSocket(`ws://127.0.0.1:${PORT}`);
  clientWebsocket.on("open", () => {
    // send too much data:
    clientWebsocket.send(Buffer.alloc(MAX_PAYLOAD_SIZE + 1));
  });

  clientWebsocket.on("close", () => {
    // log the current time when the client websocket is closed
    console.log("clientWebsocket closed at", new Date());
  });
}

server.on("upgrade", handleHttpUpgrade);
server.listen({ port: PORT }, listening);

I've been able to hack together a potential work around by listening for the socket's "finish" event, and then forceablly calling incomingMessage.destroy():

socket.on("finish", () => {
  incomingMessage.destroy();
});

I doubt this is a good approach, especially across Node versions, as this is certainly calling destroy outside the socket's proper closure lifecycle. I know that in Node 14 this end up destroying the socket many process ticks before it would normally be destroyed. That said, maybe it is fine to call destroy here? It's difficulty to tell as I don't know Node.js Sockets well enough to be sure.

I understand if this will not be considered an issue with the ws library, so please don't hesitate to close if that's the case; but hopefully this issue may shed light on the problem from someone else in the future either way.

[lpinca]

This is probably caused by 8806aa9 but I'm not sure why behavior is different in Node.js <= 12.

[lpinca]

I think there is a race condition:

• The error is emitted
• The close frame is sent and socket.end() is called.
• The client receives the close frame, the 'end' event is emitted on the socket and socket.end() is called.
• At this point the 'end' should be emitted on the server but this does not happen as if the socket is paused and data is not flowing.

This guess is supported by the fact that I cannot reproduce the issue if I use a small buffer (MAX_PAYLOAD_SIZE = 1024). This needs more investigation.

As a temporary workaround you can call ws.terminate() from the listener of the 'error' event. This is more or less what was done before 8806aa9.

[davidmurdoch]

I'm seeing the same behavior for a small buffer of 1024: I get the error, the server close, and the client close events immediately.

Quite the tricky race condition here!

I played around with the MAX_PAYLOAD_SIZE, and at 16374 I get all 3 events immediately, but with 16375 I only get the error and the server close events immediately, and the client close event 30 seconds later. Tested in node v12.22.1 and node v10.23.0.

Observation: 16376 (the size of rejected payload actually sent) is getting suspiciously close to the default highWatermark on these Streams 16384 (2¹⁴).

[lpinca]

Yes, but I don't understand why the data is not flowing again after the error is emitted. Will dig more tomorrow.

[lpinca]

Here is a test case:

const net = require('net');
const stream = require('stream');

const data = Buffer.alloc(15 * 1024 * 1024);

const server = net.createServer(function (socket) {
  function onData(chunk) {
    if (!writable.write(chunk)) {
      socket.pause();
    }
  }

  const writable = new stream.Writable({
    write(chunk, encoding, callback) {
      callback(new Error('Oops'));
    }
  });

  writable.on('error', function (err) {
    console.error(err);

    socket.end();
    socket.removeListener('data', onData);
    socket.resume();
  });

  socket.on('data', onData);
  socket.on('end', function () {
    console.log('server end');
  });
});

server.listen(function () {
  const { port } = server.address();
  const socket = net.createConnection({ port });

  socket.on('connect', function () {
    socket.write(data);
  });

  socket.on('end', function () {
    console.log('client end');
  });

  socket.resume();
});

The problem is that the 'error' event is emitted synchronously in Node.js <= 13, so the socket is first resumed and then paused and it stays paused. Behavior was changed in nodejs/node@75b30c606c released with Node.js 14.0.0.

The following patch should fix the issue.

diff --git a/lib/websocket.js b/lib/websocket.js
index f0b6eb5..142975e 100644
--- a/lib/websocket.js
+++ b/lib/websocket.js
@@ -1,3 +1,5 @@
+/* eslint no-unused-vars: ["error", { "varsIgnorePattern": "^Readable$" }] */
+
 'use strict';
 
 const EventEmitter = require('events');
@@ -6,6 +8,7 @@ const http = require('http');
 const net = require('net');
 const tls = require('tls');
 const { randomBytes, createHash } = require('crypto');
+const { Readable } = require('stream');
 const { URL } = require('url');
 
 const PerMessageDeflate = require('./permessage-deflate');
@@ -983,7 +986,7 @@ function receiverOnError(err) {
   const websocket = this[kWebSocket];
 
   websocket._socket.removeListener('data', socketOnData);
-  websocket._socket.resume();
+  process.nextTick(resume, websocket._socket);
 
   websocket.close(err[kStatusCode]);
   websocket.emit('error', err);
@@ -1032,6 +1035,16 @@ function receiverOnPong(data) {
   this[kWebSocket].emit('pong', data);
 }
 
+/**
+ * Resume a readable stream
+ *
+ * @param {Readable} stream The readable stream
+ * @private
+ */
+function resume(stream) {
+  stream.resume();
+}
+
 /**
  * The listener of the `net.Socket` `'close'` event.
  *

[lpinca]

The same issue also occurred, on all Node.js versions, upon receipt of a large enough chunk of data that included a close frame. Thank you for reporting.