Disconnecting client from server-side too quickly leaves client alive

[joshrickert]

Note: for support questions, please use one of these channels: stackoverflow or slack

You want to:

• [x] report a bug
• [ ] request a feature

Current behaviour

Using socket.io, but this looks to be an underlying bug in engine.io. The server successfully closes the connection, but the client endlessly polls for a connection if done too quickly after the connection has been established.

Steps to reproduce (if the current behaviour is a bug)

I am doing the following in my test:

1. Standing up a socket.io server and connecting to it with the socketio-client.
2. On connect, the client emits an authentication event. The server responds with success or failure.
3. After the response is received, the test is done, so the server tells all clients to disconnect (socket.disconnect(true)). Then the server closes itself.
4. All connections are successfully severed.
5. At this point, the client endlessly tries to poll for a reconnection.

Setting the transport to websocket-only solves the issue for me.

Expected behaviour

The client should shut itself down when the server tells it to disconnect.

Setup

• OS: Linux
• browser: Node.js
• engine.io version: 3.2.1

Other information (e.g. stacktraces, related issues, suggestions how to fix)

My best guess is that some kind of race condition is occurring between the server-initiated shutdown and the client's transport upgrade from polling to websockets, leaving the client in an inconsistent state.

The debug logs are illuminating:

  engine.io-client:socket creating transport "polling" +0ms
  engine.io-client:polling polling +0ms
  engine.io-client:polling-xhr xhr poll +0ms
  engine.io-client:polling-xhr xhr open GET: http://localhost:45375/socket.io/?EIO=3&transport=polling&t=MB_EmzB&b64=1 +0ms
  engine.io-client:polling-xhr xhr data null +1ms
  engine.io-client:socket setting transport polling +6ms
  engine intercepting request for path "/socket.io/" +0ms
  engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=MB_EmzB&b64=1" +1ms
  engine handshaking client "U8pHV0lMe_Izjp-BAAAA" +1ms
  engine:socket sending packet "open" ({"sid":"U8pHV0lMe_Izjp-BAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}) +0ms
  engine:socket sending packet "message" (0) +0ms
  engine:polling setting request +0ms
  engine:socket flushing buffer to transport +1ms
  engine:polling writing "96:0{"sid":"U8pHV0lMe_Izjp-BAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}2:40" +1ms
  engine:socket executing batch send callback +3ms
a user connected (logged by server)
  engine.io-client:polling polling got data 96:0{"sid":"U8pHV0lMe_Izjp-BAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}2:40 +21ms
  engine.io-client:socket socket receive: type "open", data "{"sid":"U8pHV0lMe_Izjp-BAAAA","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}" +15ms
  engine.io-client:socket socket open +0ms
  engine.io-client:socket starting upgrade probes +1ms
  engine.io-client:socket probing transport "websocket" +1ms
  engine.io-client:socket creating transport "websocket" +0ms
  engine.io-client:socket socket receive: type "message", data "0" +3ms
  engine.io-client:socket flushing 1 packets in socket +1ms
  engine.io-client:polling-xhr xhr open POST: http://localhost:45375/socket.io/?EIO=3&transport=polling&t=MB_Emzc&b64=1&sid=U8pHV0lMe_Izjp-BAAAA +26ms
  engine.io-client:polling-xhr xhr data 142:42["authentication",{"userId":"0684f400-48e4-11e8-9e27-cd307478e8ce","id":"Pws5t5CbvVmKVTrtmkIszrEHFrqyn9BGGbsAnjmqfTUKrAQg2AzuYl3i3jFaNE1b"}] +0ms
  engine.io-client:polling polling +8ms
  engine.io-client:polling-xhr xhr poll +1ms
  engine.io-client:polling-xhr xhr open GET: http://localhost:45375/socket.io/?EIO=3&transport=polling&t=MB_Emzd&b64=1&sid=U8pHV0lMe_Izjp-BAAAA +0ms
  engine.io-client:polling-xhr xhr data null +0ms
  engine upgrading existing transport +21ms
  engine:socket might upgrade socket transport from "polling" to "websocket" +16ms
  engine intercepting request for path "/socket.io/" +1ms
  engine handling "POST" http request "/socket.io/?EIO=3&transport=polling&t=MB_Emzc&b64=1&sid=U8pHV0lMe_Izjp-BAAAA" +0ms
  engine setting new request for existing client +0ms
  engine:polling received "142:42["authentication",{"userId":"0684f400-48e4-11e8-9e27-cd307478e8ce","id":"Pws5t5CbvVmKVTrtmkIszrEHFrqyn9BGGbsAnjmqfTUKrAQg2AzuYl3i3jFaNE1b"}]" +20ms
  engine:socket packet +2ms
  engine intercepting request for path "/socket.io/" +6ms
  engine handling "GET" http request "/socket.io/?EIO=3&transport=polling&t=MB_Emzd&b64=1&sid=U8pHV0lMe_Izjp-BAAAA" +0ms
  engine setting new request for existing client +0ms
  engine:polling setting request +5ms
  engine:socket sending packet "message" (2["authenticated",true]) +6ms
  engine:socket flushing buffer to transport +0ms
  engine:polling writing "24:42["authenticated",true]" +1ms
  engine.io-client:socket probe transport "websocket" opened +15ms
  engine.io-client:polling polling got data 24:42["authenticated",true] +14ms
  engine.io-client:socket socket receive: type "message", data "2["authenticated",true]" +1ms
  engine.io-client:polling polling +1ms
  engine.io-client:polling-xhr xhr poll +15ms
  engine.io-client:polling-xhr xhr open GET: http://localhost:45375/socket.io/?EIO=3&transport=polling&t=MB_Emzs&b64=1&sid=U8pHV0lMe_Izjp-BAAAA +0ms
  engine.io-client:polling-xhr xhr data null +0ms
    ✓ should authenticate with a valid token (138ms)
Disconnecting U8pHV0lMe_Izjp-BAAAA (logged by server)
  engine:socket sending packet "message" (1) +4ms
user disconnected (logged by server)
  engine closing all open clients +7ms
  engine closing webSocketServer +0ms
  engine:ws received "2probe" +0ms
  engine:ws writing "3probe" +1ms
  engine.io-client:socket probe transport "websocket" pong +8ms
  engine.io-client:socket pausing current transport "polling" +0ms
  engine.io-client:polling we are currently polling - waiting to pause +7ms
  engine.io-client:socket socket error {"type":"TransportError","description":503} +3ms
  engine.io-client:socket socket close with reason: "transport error" +0ms
  engine.io-client:socket probe transport "websocket" failed because of error: socket closed +1ms
  engine:socket client did not complete upgrade - transport closed +13ms
  engine closing all open clients +11ms
  engine closing webSocketServer +0ms

  1 passing (274ms)

  engine.io-client:socket creating transport "polling" +1s
  engine.io-client:polling polling +1s
  engine.io-client:polling-xhr xhr poll +1s
  engine.io-client:polling-xhr xhr open GET: http://localhost:45375/socket.io/?EIO=3&transport=polling&t=MB_EnGC&b64=1 +0ms
  engine.io-client:polling-xhr xhr data null +0ms
  engine.io-client:socket setting transport polling +1ms
  engine.io-client:socket socket error {"type":"TransportError","description":503} +2ms
  engine.io-client:socket socket close with reason: "transport error" +0ms
  engine.io-client:polling transport not open - deferring close +3ms
  engine.io-client:socket creating transport "polling" +1s
  engine.io-client:polling polling +1s
  engine.io-client:polling-xhr xhr poll +1s
  engine.io-client:polling-xhr xhr open GET: http://localhost:45375/socket.io/?EIO=3&transport=polling&t=MB_EnXg&b64=1 +0ms
  engine.io-client:polling-xhr xhr data null +0ms
  engine.io-client:socket setting transport polling +1ms
  engine.io-client:socket socket error {"type":"TransportError","description":503} +2ms
  engine.io-client:socket socket close with reason: "transport error" +0ms
  engine.io-client:polling transport not open - deferring close +3ms
  engine.io-client:socket creating transport "polling" +4s
  engine.io-client:polling polling +4s
  engine.io-client:polling-xhr xhr poll +4s
  engine.io-client:polling-xhr xhr open GET: http://localhost:45375/socket.io/?EIO=3&transport=polling&t=MB_EoTe&b64=1 +0ms
  engine.io-client:polling-xhr xhr data null +0ms
  engine.io-client:socket setting transport polling +1ms
  engine.io-client:socket socket error {"type":"TransportError","description":503} +2ms
  engine.io-client:socket socket close with reason: "transport error" +0ms
  engine.io-client:polling transport not open - deferring close +3ms
(repeat forever)

[lpinca]

Not sure if it's the same issue but I found something similar while updating tests in Primus. Here is a test case:

const eio = require('engine.io');
const eioc = require('engine.io-client');
const http = require('http');

const httpServer = http.createServer();
const eioServer = new eio.Server();

httpServer.on('request', (req, res) => {
  eioServer.handleRequest(req, res);
});

let socket;
eioServer.on('connection', () => {
  socket.close();
  httpServer.close();
});

httpServer.listen(3000, () => {
  socket = new eioc('http://localhost:3000/');
});

The process does not exit. Here is what happens:

1. Transport#close() is called.
2. The transport is not open yet so the close is deferred.
3. The opening packet is eventually received but Transport#onOpen() is never called and so the 'open' event is never emitted. This is because Transport#onClose() is called synchronously right after Transport#doClose() changing the readyState to 'closed' before the opening packet is received.

[amok]

Any updates on this issue?

[joseph-montanez]

I've run into the same issue with Cordova and its implementation of listeners errors at:

https://github.com/socketio/engine.io-client/blob/main/lib/socket.ts#L915

  if (typeof removeEventListener === "function") {
    removeEventListener("offline", this.offlineEventListener, false);
  }

I assume this is because the offlineEventListener has not yet been initialized after the socket.io server rapidly restarting. For the time being I just put an additional condition to ensure its initialized.

  if (typeof removeEventListener === "function" && typeof this.offlineEventListener !== "undefined") {
    removeEventListener("offline", this.offlineEventListener, false);
  }

If not the code beneath to mark the connection as closed doesn't run and an error is thrown while removing the this.offlineEventListener. The traceback goes all the way down to Cannot read properties of undefined (reading 'handleEvent') - https://github.com/apache/cordova-js/blob/master/src/common/channel.js#L138

FYI - If you're building this on an M1 Mac (darwinarm64), I needed to override the version of ngrok used by zuul-ngrok in the package.json i.e:

"overrides": { "ngrok": "4.3.1", },

Ngrok 4 supports M1 Mac, but the zuul-ngrok hasn't been updated for 6 years.