Namespace connect event failed to trigger randomly. REDIS SENTINEL + SOCKETIO

[bhavesh-webosmotic]

I have faced a strange issue with REDIS, Socket io. Sometimes connection events never trigger on the server.
I am using transports as WebSocket only.

The code works like 60 out of 40 times. But, that is too random.
The code is working fine most of the time. It only failed when the socket.io client failed to trigger the namespace connect event.
I did try to lower the socket version to V3 on both client and server but issues were the same.

FYI.
I do have handle code in the try-catch statement and also tried to add logs. But the strange thing is I never found any connection log on the server when this thing happen. for the successful connection I am getting all the logs.
I did try many ways to find the issue and added many logs. It was difficult for me to look into 24 instances for logs.
So, I tried to generate the engine id on my own to find the exact instance which has this issue.

The finding

• Server health is normal.
• It randomly failed to trigger a connection event of the namespace. So it means I have another working socket connection on the same server.
• Client recevies ping pong. But when we emit anything from the client it never received on the server due to the failure of the connection event trigger.
• Socket remain in the connected state on both the side, client and server
• Socket Middleware logs were fine.
• I have used regex to connect namespace. it's also working. I have added [PASS] log for the same namespace I got an issue with.

NOTE: As I can not share actual ids and other information. I have replaced actual ids with random ids.

Server Code

Package on server-side

  "ioredis": "^4.27.4",
  "socket.io": "^4.1.2",
  "socket.io-redis": "^6.1.1",

---

socket.js file

---

const sio = io(server, {
      transports: ['websocket'],
      path: '/app',
      pingInterval: 15000,
      pingTimeout: 5000,
      cors: {
        origin: '*',
      },
    });
sio.engine.generateId = function (req) {
      return (
        ((process && process.env && process.env.pm_id) || 'none') +
        '_' +
        app.get('nodeInstanceId') +
        '_' +
        new Date().getTime() +
        '_' +
        parseInt(Math.random() * 10000000)
      );
    };
sio
      .of(/.*/)
      .use(socketVerifyToken)
      .on('connection', (socket) => {
        const namespace = socket.nsp.name.split('/')[1];
        const ip = (socket.request && socket.request.connection && socket.request.connection.remoteAddress) || '-';
        socket.emit('connected', {			<=================== This need to be triggerd on namespace connection
          namespace,
          socket: socket.id,
          ip,
          nodeInstanceId: this.app.get('nodeInstanceId'),
        });
      });

---

Middleware.js

---

const socketVerifyToken = async (socket, next) => {
    return next();
};

---

Client Code
Package on client side
"socket.io-client": "^4.1.2",

---

this.socket = io(`${getURL(this.options.host).origin}/${this.key}`, { path: '/app',transports: ["websocket"]});
this.socket.on('connect', function () {
	console.log('connected', true)
})

---

LOGS

[PASS]Successfully connected client events logs look like on the server

---

2021-06-04T11:31:52.226Z engine handshaking client "2_node-dbd493d4-192.168.1.1_1622806312226_9869353"
2021-06-04T11:31:52.226Z socket.io:server incoming connection with id 2_node-dbd493d4-192.168.8.5_1622806312226_9869353
2021-06-04T11:31:52.582Z socket.io-parser decoded 0/namespaceABC, as {"type":0,"nsp":"/namespaceABC"}
2021-06-04T11:31:52.582Z socket.io:client connecting to namespace /namespaceABC
2021-06-04T11:31:52.582Z socket.io:namespace adding socket to nsp /namespaceABC
2021-06-04T11:31:52.583Z socket.io:socket socket connected - writing packet
2021-06-04T11:31:52.583Z socket.io:socket join room BuheuAXQSJkF8u4kAAAB
2021-06-04T11:31:52.583Z socket.io:client writing packet {"type":0,"data":{"sid":"BuheuAXQSJkF8u4kAAAB"},"nsp":"/namespaceABC"}
2021-06-04T11:31:52.583Z socket.io-parser encoding packet {"type":0,"data":{"sid":"BuheuAXQSJkF8u4kAAAB"},"nsp":"/namespaceABC"}
2021-06-04T11:31:52.583Z socket.io-parser encoded {"type":0,"data":{"sid":"BuheuAXQSJkF8u4kAAAB"},"nsp":"/namespaceABC"} as 0/namespaceABC,{"sid":"BuheuAXQSJkF8u4kAAAB"}

===**=**=**======== Triggered namespace connect event. So the next event is emitted from namespace connect method. Emit event name is "connected"
                                                                                                     
2021-06-04T11:31:52.583Z socket.io:client writing packet {"type":2,"data":["connected",{"namespace":"namespaceABC","socket":"BuheuAXQSJkF8u4kAAAB","ip":"::ffff:192.168.1.7","nodeInstanceId":"node-dbd493d4-192.168.8.5"}],"nsp":"/namespaceABC"}
2021-06-04T11:31:52.583Z socket.io-parser encoding packet {"type":2,"data":["connected",{"namespace":"namespaceABC","socket":"BuheuAXQSJkF8u4kAAAB","ip":"::ffff:192.168.1.7","nodeInstanceId":"node-dbd493d4-192.168.8.5"}],"nsp":"/namespaceABC"}
2021-06-04T11:31:52.583Z socket.io-parser encoded {"type":2,"data":["connected",{"namespace":"namespaceABC","socket":"BuheuAXQSJkF8u4kAAAB","ip":"::ffff:192.168.1.7","nodeInstanceId":"node-dbd493d4-192.168.8.5"}],"nsp":"/namespaceABC"} as 2/namespaceABC,["connected",{"namespace":"namespaceABC","socket":"BuheuAXQSJkF8u4kAAAB","ip":"::ffff:192.168.1.7","nodeInstanceId":"node-dbd493d4-192.168.8.5"}]
2021-06-04T11:31:52.871Z socket.io-parser decoded 2/namespaceABC,0["pubble:subscribe",{"channel":"community_account_2904_32227"}] as {"type":2,"nsp":"/namespaceABC","id":0,"data":["pubble:subscribe",{"channel":"community_account_2904_32227"}]}
2021-06-04T11:31:52.871Z socket.io:socket got packet {"type":2,"nsp":"/namespaceABC","id":0,"data":["pubble:subscribe",{"channel":"community_account_2904_32227"}]}
2021-06-04T11:31:52.872Z socket.io:socket emitting event ["pubble:subscribe",{"channel":"community_account_2904_32227"}]
2021-06-04T11:31:52.872Z socket.io:socket attaching ack callback to event
2021-06-04T11:31:52.872Z socket.io:socket dispatching an event ["pubble:subscribe",{"channel":"community_account_2904_32227"},null]
2021-06-04T11:31:52.872Z socket.io:socket sending ack [true]

---

[FAILED] When socket io failed to trigger connection event of the namespace.

---

2021-06-04T12:21:06.682Z engine handshaking client "2_node-ac5ec95f-192.168.8.5_1622809266682_448501"
2021-06-04T12:21:06.684Z socket.io:server incoming connection with id 2_node-ac5ec95f-192.168.8.5_1622809266682_448501
2021-06-04T12:21:06.958Z socket.io-parser decoded 0/namespaceABC, as {"type":0,"nsp":"/namespaceABC"}
2021-06:21:06.958Z socket.io:namespace adding socket to nsp /namespaceABC
2021-06-04T12:21:06.959Z socket.io:socket socket connected - writing packet
2021-06-04T12:21:06.959Z socket.io:socket join room 3i2TNVRmUKTUfOYSAAAA
2021-06-04T12:21:06.959Z socket.io:client writing packet {"type":0,"data":{"sid":"3i2TNVRmUKTUfOYSAAAA"},"nsp":"/namespaceABC"}
2021-06-04T12:21:06.960Z socket.io-parser encoding packet {"type":0,"data":{"sid":"3i2TNVRmUKTUfOYSAAAA"},"nsp":"/namespaceABC"}
2021-06-04T12:21:06.960Z socket.io-parser encoded {"type":0,"data":{"sid":"3i2TNVRmUKTUfOYSAAAA"},"nsp":"/namespaceABC"} as 0/namespaceABC,{"sid":"3i2TNVRmUKTUfOYSAAAA"}

===**=**=**======== Failed to trigger namespace connect event. Emit event name is "connected".No connected event in below.

2021-06-04T12:21:07.237Z socket.io-parser decoded 2/namespaceABC,2["pubble:subscribe",{"channel":"community_event_888"}] as {"type":2,"nsp":"/namespaceABC","id":2,"data":["pubble:subscribe",{"channel":"community_event_888"}]}
2021-06-04T12:21:07.237Z socket.io:socket got packet {"type":2,"nsp":"/namespaceABC","id":2,"data":["pubble:subscribe",{"channel":"community_event_888"}]}
2021-06-04T12:21:07.237Z socket.io:socket emitting event ["pubble:subscribe",{"channel":"community_event_888"}]
2021-06-04T12:21:07.237Z socket.io:socket attaching ack callback to event
2021-06-04T12:21:07.238Z socket.io:socket dispatching an event ["pubble:subscribe",{"channel":"community_event_888"},null]
2021-06-04T12:21:07.241Z socket.io-parser decoded 2/namespaceABC,3["pubble:subscribe",{"channel":"app_5445_5445"}] as {"type":2,"nsp":"/namespaceABC","id":3,"data":["pubble:subscribe",{"channel":"app_5445_5445"}]}
2021-06-04T12:21:07.241Z socket.io:socket got packet {"type":2,"nsp":"/namespaceABC","id":3,"data":["pubble:subscribe",{"channel":"app_5445_5445"}]}
2021-06-04T12:21:07.241Z socket.io:socket emitting event ["pubble:subscribe",{"channel":"app_5445_5445"}]
2021-06-04T12:21:07.241Z socket.io:socket attaching ack callback to event
2021-06-04T12:21:07.241Z socket.io:socket dispatching an event ["pubble:subscribe",{"channel":"app_5445_5445"},null]
2021-06-04T12:21:17.237Z socket.io-parser decoded 1/namespaceABC, as {"type":1,"nsp":"/namespaceABC"}-04T12:21:06.958Z socket.io:client connecting to namespace /namespaceABC
2021-06-04T12