Socket.io: Websocket broken with 2.1.0 and cluster / socket.io-redis

[bendenoz]

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

Just wanted to mention upgrading to 2.1.0 silently broke websocket on my setup.
It took some time to realize because it was properly falling back to polling only.

Reverting to 2.0.4 server (not client) resolves the problem for now

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

upgrade to socke.io to 2.1.0

Note: the best way to get a quick answer is to provide a failing test case, by forking the following fiddle for example.

update, the issue is apparently connected to the use of cluster, and ioredis adapter

repro:

const express = require('express');
const app = express();
const server = require('http').createServer(app);
const io = require('socket.io')(server);
const port = process.env.PORT || 3000;
const cluster = require('cluster');
const adapter = require('socket.io-redis');

if (cluster.isMaster) {
  for (var i =0; i < 4; i++) {
    cluster.fork();
  }
} else {
  app.use(express.static(__dirname + '/public'));

  io.on('connect', onConnect);
  server.listen(port, () => console.log('server listening on port ' + port));
  io.adapter(adapter(redisServer));

  function onConnect(socket){
    console.log('connect ' + socket.id);

    socket.on('disconnect', () => console.log('disconnect ' + socket.id));
  }
}

Expected behaviour

working websockets

Setup

• OS:
• browser:
• socket.io version: 2.1.0

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

Server errors

DEBUG=socket.io* DEBUG=engine*

  engine handshaking client "1jSK1mUZdTy7N0jXAAAA" +0ms
  engine:socket sending packet "open" ({"sid":"1jSK1mUZdTy7N0jXAAAA","upgrades":[],"pingInterval":25000,"pingTimeout":5000}) +0ms
  engine:socket flushing buffer to transport +13ms
  engine:ws writing "0{"sid":"1jSK1mUZdTy7N0jXAAAA","upgrades":[],"pingInterval":25000,"pingTimeout":5000}" +0ms
  engine:socket sending packet "message" (0) +16ms
  engine:transport setting request +0ms
The server is running at http://localhost:8000/ (#43756)
  engine:socket flushing buffer to transport +65ms
  engine:ws writing "40" +80ms
  engine:socket transport error +1ms
  engine:ws closing +3ms
  engine:socket error triggered by discarded transport +52ms
  engine handshaking client "Nphvg46q6cw4bh_7AAAA" +0ms
  engine:socket sending packet "open" ({"sid":"Nphvg46q6cw4bh_7AAAA","upgrades":[],"pingInterval":25000,"pingTimeout":5000}) +0ms
  engine:socket flushing buffer to transport +1ms
  engine:ws writing "0{"sid":"Nphvg46q6cw4bh_7AAAA","upgrades":[],"pingInterval":25000,"pingTimeout":5000}" +0ms
  engine:socket sending packet "message" (0) +2ms
  engine:transport setting request +0ms
  engine:socket flushing buffer to transport +7ms
  engine:ws writing "40" +8ms
  engine:socket transport error +1ms
  engine:ws closing +2ms
  engine:socket error triggered by discarded transport +8ms
  engine handshaking client "qYiMn4woVqVKvFmqAAAA" +0ms
  engine:socket sending packet "open" ({"sid":"qYiMn4woVqVKvFmqAAAA","upgrades":[],"pingInterval":25000,"pingTimeout":5000}) +0ms
  engine:socket flushing buffer to transport +1ms
  engine:ws writing "0{"sid":"qYiMn4woVqVKvFmqAAAA","upgrades":[],"pingInterval":25000,"pingTimeout":5000}" +0ms
  engine:socket sending packet "message" (0) +4ms
  engine:transport setting request +0ms
  engine:socket flushing buffer to transport +7ms
  engine:ws writing "40" +10ms
  engine:socket transport error +3ms
  engine:ws closing +3ms
  engine:socket error triggered by discarded transport +18ms
  engine handshaking client "FcW9mtO-3dnEvaA-AAAA" +0ms
  engine:socket sending packet "open" ({"sid":"FcW9mtO-3dnEvaA-AAAA","upgrades":[],"pingInterval":25000,"pingTimeout":5000}) +0ms
  engine:socket flushing buffer to transport +3ms
  engine:ws writing "0{"sid":"FcW9mtO-3dnEvaA-AAAA","upgrades":[],"pingInterval":25000,"pingTimeout":5000}" +0ms
  engine:socket sending packet "message" (0) +27ms
  engine:transport setting request +0ms
  engine:socket flushing buffer to transport +14ms
  engine:ws writing "40" +35ms
  engine:socket transport error +3ms
  engine:ws closing +5ms
  engine:socket error triggered by discarded transport +19ms
  engine handshaking client "16SrwNNmWl1o1sdyAAAB" +5s
  engine:socket sending packet "open" ({"sid":"16SrwNNmWl1o1sdyAAAB","upgrades":[],"pingInterval":25000,"pingTimeout":5000}) +5s
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "0{"sid":"16SrwNNmWl1o1sdyAAAB","upgrades":[],"pingInterval":25000,"pingTimeout":5000}" +5s
  engine:socket sending packet "message" (0) +1ms
  engine:transport setting request +5s
  engine:socket flushing buffer to transport +3ms
  engine:ws writing "40" +4ms
  engine:socket transport error +1ms
  engine:ws closing +1ms
  engine:socket error triggered by discarded transport +6ms
  engine handshaking client "eW6tDpTdGHrWPEXuAAAB" +3s
  engine:socket sending packet "open" ({"sid":"eW6tDpTdGHrWPEXuAAAB","upgrades":[],"pingInterval":25000,"pingTimeout":5000}) +3s
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "0{"sid":"eW6tDpTdGHrWPEXuAAAB","upgrades":[],"pingInterval":25000,"pingTimeout":5000}" +3s
  engine:socket sending packet "message" (0) +0ms
  engine:transport setting request +3s
  engine:socket flushing buffer to transport +3ms
  engine:ws writing "40" +3ms
  engine:socket transport error +2ms
  engine:ws closing +2ms
  engine:socket error triggered by discarded transport +7ms
  engine handshaking client "ruhv9xolYbNnqtEkAAAB" +2s
  engine:socket sending packet "open" ({"sid":"ruhv9xolYbNnqtEkAAAB","upgrades":[],"pingInterval":25000,"pingTimeout":5000}) +2s
  engine:socket flushing buffer to transport +1ms
  engine:ws writing "0{"sid":"ruhv9xolYbNnqtEkAAAB","upgrades":[],"pingInterval":25000,"pingTimeout":5000}" +2s
  engine:socket sending packet "message" (0) +0ms
  engine:transport setting request +2s
  engine:socket flushing buffer to transport +4ms
  engine:ws writing "40" +4ms
  engine:socket transport error +0ms
  engine:ws closing +1ms
  engine:socket error triggered by discarded transport +3ms
  engine handshaking client "gawz_pvsNYywT8i0AAAB" +3s
  engine:socket sending packet "open" ({"sid":"gawz_pvsNYywT8i0AAAB","upgrades":[],"pingInterval":25000,"pingTimeout":5000}) +3s
  engine:socket flushing buffer to transport +0ms
  engine:ws writing "0{"sid":"gawz_pvsNYywT8i0AAAB","upgrades":[],"pingInterval":25000,"pingTimeout":5000}" +3s
  engine:socket sending packet "message" (0) +1ms
  engine:transport setting request +3s
  engine:socket flushing buffer to transport +5ms
  engine:ws writing "40" +6ms
  engine:socket transport error +3ms
  engine:ws closing +3ms
  engine:socket error triggered by discarded transport +2ms

Client errors

on chrome

websocket.js:112 WebSocket connection to 'ws://localhost:8000/socket.io/?EIO=3&transport=websocket' failed: Invalid frame header
WS.doOpen @ websocket.js:112
Transport.open @ transport.js:80
Socket.open @ socket.js:245
Socket @ socket.js:119
Socket @ socket.js:28
Manager.open.Manager.connect @ manager.js:226
(anonymous) @ manager.js:540

[interglobalmedia]

2.1.0 does not work for me either. only if i use example as is here. versions and everything. Following steps on site does not work. FYI.

[mayorbobster]

I achieved breakage using this. I have an application that gets temperatures from a software defined radio that sends time/humidity/temperature to a file. Nodejs reads the file (using filewatch), and on update, updates time/temperature/humidity on an html file. I recently have been adding the nodejs html file to an apache web server. My html file has 8 svg images, all but 2 of them broke (just an icon, not the image). (The image mime type must be applied to the html file prior to nodejs/html display, it does so using: [a predefined mimetype array, a scan of the html file and a network pipe]: nodejs is asynchronous and image mime types cannot be determined after the fact). The change I did to get it working (not with Apache, just nodejs unto itself), was to change:
.listen(port, "0.0.0.0"); to .listen(port);
I also got an error message for each failing image:
96:0{"sid":"pEvbvm7_DlNgmRddAAAE","upgrades":["websocket"],"pingInterval":25000,"pingTimeout":5000}2:40

Hopefully this information helps someone.

[darrachequesne]

@bendenoz that's weird, the code you provided should not work in any case, since the requests reach the workers node randomly (but sticky-session is required, please see https://socket.io/docs/using-multiple-nodes/).

Unless you use transports: ['websocket'] on the client-side. I guess that's your case.

What's weird then is that we reverted to ws as our default WebSocket server implementation in 2.1.0 (instead of uws in 2.0.4) because there were reports of errors when used within a Node.js cluster.

update, the issue is apparently connected to the use of cluster, and ioredis adapter

Is there something we could fix?

[mayorbobster]

On 2018-08-18 04:12 PM, Damien Arrachequesne wrote:
>

update, the issue is apparently connected to the use of cluster,
and ioredis adapter

Is there something we could fix?

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/socketio/socket.io/issues/3226#issuecomment-414089309,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ATK_FYU1Qs4Quk49g33EKx9I_o4AiNlRks5uSJFlgaJpZM4TaJto.

No, but thank you for your prompt reply.
Bob

[bendenoz]

@darrachequesne yes the example is an attempt to make a simplified version of our app, in the real life setup sticky sessions are handled, although this should not be a problem if the websocket connects.

Currently still using 2.0.4 for the moment, I'll try to repro when I have more time

[bendenoz]

So after more testing it turned out to be a conflict with another server component using ws too (subscriptions-transport-ws), on a different path but trying to do a double upgrade.

All is good after working around the upgrade issue.