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

bhavesh-webosmotic · 2021-06-05T10:51:13Z

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

The text was updated successfully, but these errors were encountered:

bhavesh-webosmotic · 2021-06-09T12:51:34Z

I have removed namespace and using namespace+channel to separate each room. It's working fine.

Still unable to find why the namespace connection event is not triggered.

darrachequesne · 2021-06-09T16:11:54Z

Hi! I can't reproduce the issue you are experiencing.

Does it happen randomly or are you able to reproduce consistently?

bhavesh-webosmotic · 2021-06-09T16:35:03Z

its too random.. also it happen with ubuntu only. In windows I never had that issue.
Tomorrow I will share ubuntu version and node version too.
FYI, I am using 3 ubuntu server. Each has 8 pm2-cluster.

bhavesh-webosmotic · 2021-06-10T06:43:49Z

@darrachequesne Finally. I found where it's failing the actual use case you can test with.

I did add some log where library trigger connection event and added log at the server code side where it receives connection event.

Socket.io triggers the following line.
this.emitReserved("connection", socket);
But on the server I never received it.

It happened with Ubuntu with PM2 only.
Running a single instance of server works fine in ubuntu.

Maybe you can set up the following environment to troubleshoot the issue.
OS: Ubuntu
process manager: PM2 with 2 instance
Write code to connect socket with namespace
On the client-side you can refresh few times it might get stuck as in the below image

bhavesh-webosmotic · 2021-06-10T07:50:07Z

Found something. When emit passes it returns true and the socket triggers a connection event. When it gets failed it return false,
I added logs to see what's going on.
in the below image the return value is false when emit failed.

logs
Passed to connect

Failed to connect

bhavesh-webosmotic · 2021-06-10T10:50:42Z

Did more tests and found when this condition is true in the console. Socket library fails trigger use function of the namespace.
Failed blue mark is function has some issue.

Added console to get length of fns.

See the response true in image and length of

++++++++++++++++++++++++
When the condition is false. All connection works fine.

bhavesh-webosmotic · 2021-06-10T11:49:33Z

Finally found the issue.
The issue is with regex in namespace+PM2+ubuntu. I changed the logic to pass static namespace names and it works fine. with PM2 + ubuntu.

Not working

      sio
      .of(/.*/)

Working

      sio
      .of("namespaceABN")

ChrisKatsaras · 2021-06-15T22:14:03Z

I'm also experiencing this intermittent issue when using a regex expression?
@bhavesh-webosmotic but doesn't your solution above limit your ability to have dynamic namespaces?
@darrachequesne any ideas given that we have both had this issue?

darrachequesne · 2021-06-16T05:58:27Z

@ChrisKatsaras the only possible explanation that I see is that there is another namespace (not dynamic) that gets the "connection" event first:

io.of("/test").on("connection", (socket) => {
  // triggered
});

io.of(/.*/).on("connection", (socket) => {
  // not triggered 
});

Could it be your case?

bhavesh-webosmotic · 2021-06-16T09:08:10Z

@ChrisKatsaras Yes. You are right about the limited namespace. in my case, I have very little namespace like 4-5 so I just looped over them and make it work. It's not a great solution. but for me, it's working.
It's really good if we have that dynamic namespace with regex.

@darrachequesne Yes, you are right about.. It's calling another namespace connection method that is not registered and emits is returning false because of no event listener registered.

As I saw while debugging the namespace list was like ["/", "/namespaceABC"] but the connection method fns value was [].

Maybe because it creating the default main namespace and I have not registered any event for it as the namespace list has "/" in it.

ChrisKatsaras · 2021-06-16T13:05:27Z

@darrachequesne that seems like a good explanation of what would happen but I don't think so in my case 😓
Basically, I only have the second code snippet and not the first and it still seems to be an intermittent issue.
However, given what @darrachequesne has said, I may be able to go the route he's decided on since I'm theoretically not having that many namespaces either.
I'll do some more testing today and see if anything changes @darrachequesne !
Thank you both for getting back to me so quickly! I really appreciate it 🎉

ChrisKatsaras · 2021-06-16T20:33:49Z

So I did some testing again but sadly still didn't work as intended @darrachequesne . However, given my requirements, I've decided to go with the solution @bhavesh-webosmotic suggested 😄
Thanks again!

darrachequesne · 2021-06-17T13:06:40Z

OK, I guess we can close the issue now.

Please reopen if needed.

tuntag · 2021-07-13T03:25:28Z

This shouldn't close before we could use back the dynamic workspaces with multi-nodes.

Related: socketio/socket.io#3960

darrachequesne · 2021-07-13T06:18:35Z

@tuntafag the issue was closed as I was not able to reproduce the problem: https://github.com/socketio/socket.io-fiddle/tree/issues/socket.io/3960

Could you please check?

FA-QuangLT · 2021-07-13T07:27:39Z

I'm also experiencing this intermittent issue when using a regex expression for dynamic namespace.

But, In case:

Running a single socket.io node.
Or only one namespace
Or without namespace
=> it works normally.

Note: I have only one the code snippet for namespace instance in my app. This issue occurs when running on multiple node deployed in Kubernetes with many pods.

Is there any solution for this issue ? My application has many namespaces so I needs using dynamic namespace instead of hard code.

darrachequesne · 2021-07-13T08:59:46Z

Is there any solution for this issue ?

@FA-QuangLT as usual, if we cannot reproduce the issue, I'm afraid we won't be able to help you...

FA-QuangLT · 2021-07-13T10:26:59Z

@darrachequesne I think this issue only occurs when running on multiple node that deployed in Kubernetes with many pods using dynamic namespace.
I'm trying hard to come up with a workaround, but there just might not be one...
Thank you for your quick response.

Namespaces that match the regex of a parent namespace will now be added as a child of this namespace: ```js const parentNamespace = io.of(/^\/dynamic-\d+$/); const childNamespace = io.of("/dynamic-101"); ``` Related: - #4615 - #4164 - #4015 - #3960

Namespaces that match the regex of a parent namespace will now be added as a child of this namespace: ```js const parentNamespace = io.of(/^\/dynamic-\d+$/); const childNamespace = io.of("/dynamic-101"); ``` Related: - socketio#4615 - socketio#4164 - socketio#4015 - socketio#3960

bhavesh-webosmotic added the bug Something isn't working label Jun 5, 2021

darrachequesne closed this as completed Jun 17, 2021

darrachequesne added a commit to socketio/socket.io-fiddle that referenced this issue Jul 13, 2021

add test case

a984670

Related: socketio/socket.io#3960

darrachequesne mentioned this issue Oct 18, 2021

Dynamic namespace connect sometime not triggers namespace scope with Socket io, Kubernetes #4015

Closed

thombohlk mentioned this issue Nov 12, 2021

Event listeners on dynamic namespaces break when server emits on matching custom namespace before client connects #4164

Closed

SStoliarchuk mentioned this issue Jan 4, 2022

use() middleware is not triggered #4237

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

bhavesh-webosmotic commented Jun 5, 2021

bhavesh-webosmotic commented Jun 9, 2021

darrachequesne commented Jun 9, 2021

bhavesh-webosmotic commented Jun 9, 2021

bhavesh-webosmotic commented Jun 10, 2021 •

edited

Loading

bhavesh-webosmotic commented Jun 10, 2021 •

edited

Loading

bhavesh-webosmotic commented Jun 10, 2021 •

edited

Loading

bhavesh-webosmotic commented Jun 10, 2021 •

edited

Loading

ChrisKatsaras commented Jun 15, 2021 •

edited

Loading

darrachequesne commented Jun 16, 2021

bhavesh-webosmotic commented Jun 16, 2021 •

edited

Loading

ChrisKatsaras commented Jun 16, 2021 •

edited

Loading

ChrisKatsaras commented Jun 16, 2021

darrachequesne commented Jun 17, 2021

tuntag commented Jul 13, 2021

darrachequesne commented Jul 13, 2021

FA-QuangLT commented Jul 13, 2021 •

edited

Loading

darrachequesne commented Jul 13, 2021

FA-QuangLT commented Jul 13, 2021

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

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

Comments

bhavesh-webosmotic commented Jun 5, 2021

The finding

Server Code

bhavesh-webosmotic commented Jun 9, 2021

darrachequesne commented Jun 9, 2021

bhavesh-webosmotic commented Jun 9, 2021

bhavesh-webosmotic commented Jun 10, 2021 • edited Loading

bhavesh-webosmotic commented Jun 10, 2021 • edited Loading

bhavesh-webosmotic commented Jun 10, 2021 • edited Loading

bhavesh-webosmotic commented Jun 10, 2021 • edited Loading

ChrisKatsaras commented Jun 15, 2021 • edited Loading

darrachequesne commented Jun 16, 2021

bhavesh-webosmotic commented Jun 16, 2021 • edited Loading

ChrisKatsaras commented Jun 16, 2021 • edited Loading

ChrisKatsaras commented Jun 16, 2021

darrachequesne commented Jun 17, 2021

tuntag commented Jul 13, 2021

darrachequesne commented Jul 13, 2021

FA-QuangLT commented Jul 13, 2021 • edited Loading

darrachequesne commented Jul 13, 2021

FA-QuangLT commented Jul 13, 2021

bhavesh-webosmotic commented Jun 10, 2021 •

edited

Loading

bhavesh-webosmotic commented Jun 10, 2021 •

edited

Loading

bhavesh-webosmotic commented Jun 10, 2021 •

edited

Loading

bhavesh-webosmotic commented Jun 10, 2021 •

edited

Loading

ChrisKatsaras commented Jun 15, 2021 •

edited

Loading

bhavesh-webosmotic commented Jun 16, 2021 •

edited

Loading

ChrisKatsaras commented Jun 16, 2021 •

edited

Loading

FA-QuangLT commented Jul 13, 2021 •

edited

Loading