ws client-side disconnect is not detected

[qiulang]

I searched socket.io issues found this one about client-side disconnect is not detected. It was closed in 2017 but others commented they still hit the problem and this is what I have been experiencing (socket.io 2.3).

Our work flow are like these:

1. Each user in our system will have a unique user id. In io.on('connection', socket => { /* ... */ }); I will record the userid with socket.id in redis (using a hash with socket.id as the field and user.id as the value) and in socket.on('disconnect', /* ... */); I will delete that pair of user.id and socket.io.
2. Every two or three days when I check that redis hash I always find some user.id has more than one socket.id, which means I didn't get disconnect event for some socket connection. I attached a screenshot to show what I mean

Here redis recorded user 134_243_1000962235 has 2 socket connections TfJmlyJngwG5c6aVAABT & gAACwSLokQnzAVb0AADV. We implement our system that if we detect a user does login with another ws connection while we still have the old ws connection record we will call close() on socket.io.client

So I think that the reason I have several socket.ids point to one user is that I didn't get the disconnect event for those socket.id so they still exist in our redis record. I assume that if the network connection is bad, it is possbile that I won't get the disconnect event at the server side. But the problem is that it happens regularly and I can't figure out a way to clear those obsolete records.

Has anyone also experienced this problem ? Thanks.

[darrachequesne]

Hi! A possible explanation is that your server was killed and restarted, so the cleanup method wasn't executed. Could it be possible?

Else, I don't know how that can happen. Would you be able to get the state of the Socket, and the underlying connection (socket.conn) for those IDs?

I was not able to reproduce the issue with the load testing script here: https://socket.io/docs/v4/load-testing/#manual-client-creation

const { Server } = require("socket.io");

const io = new Server(3000);

let connectionCount = 0, disconnectionCount = 0;

io.on("connection", socket => {
  connectionCount++;

  socket.on("disconnect", (reason) => {
    disconnectionCount++;
  });
});

setInterval(() => {
  console.log(`current connected: ${io.sockets.sockets.size} ; total connections: ${connectionCount} ; total disconnections: ${disconnectionCount}`);
}, 5000);

[qiulang]

Hi when the server restarts we will log it and I think it is possible that the disconnect event happens when the server is restarting. But it still can't account for all the obsoleted data I see in redis. I am pasting some logs here to show why I think so.

1. I have 3 restarts since I asked the question. I believe those restarts can be one of reasons I missed some disconnect events.

/* when the server restarts it will connect to redis and we log that info */

2021-11-16 10:27:56: app:info Connect to redis using ...
2021-11-15 16:17:34: app:info Connect to redis using ...
2021-11-15 15:50:33: app:info Connect to redis using

2. Before I asked the question yesterday (around 1 pm 11/15) I run a clean up script to remove all the obsoleted data, so when I asked the question the redis records were clean. Now I check the redis records (around 13:30 11/16) I see user 134_243_1001056441 has 2 obsoleted socket.ids pointing to him
   

3. I run a query against user 134_243_1001056441, using the keyword meaning redis records a pair of user.id and socket.id. I found it has 70 ws connections since I asked the question yesterday. It means that I got 68 disconnect event and missed 2, so they still exist in redis.
   

4. I further checked the last time I saw those socket.id in our log. One of them happened around the time our server restarted but the other did not.

/* this one did not happened around the time the server restarted */
2021-11-15 14:33:29: app:info 134_243_1001056441 exists with socket id zs0G4acwYya0xi4BAABB, tell it to logoff.
/* this one did happened around the time the server restarted at 11-15 16:17:34*/
2021-11-15 16:18:03: app:info 134_243_1001056441 exists with socket id RwtFqW7SuC8Ann0vAAAE, tell it to logoff.

5. The log "tell it to logoff" means that the sever see a new connection but it stores the old one, so it will emit a logoff message to the client to let the client call close() and then record the new socket.id. A normal work flow are these

2021-11-15 16:18:01: app:info store in hash table user_socket 134_243_1001056292 => sFzuA0s8lutZ96hGAAAB AND SUB subscribe

/*  a new connection */

2021-11-15 16:50:12: app:websocket:debug user 134_243_1001056292, seid:134, ccgeid:243 login using socket P6h-2b0MlqinkpXNAAAJ
2021-11-15 16:50:12: app:info 134_243_1001056292 exists with socket id sFzuA0s8lutZ96hGAAAB, tell it to logoff.
2021-11-15 16:50:12: app:info store in hash table user_socket 134_243_1001056292 => P6h-2b0MlqinkpXNAAAJ

/* the client side call close() so we get a disconnect event */ 
2021-11-15 16:50:12: app:websocket:debug socket id sFzuA0s8lutZ96hGAAAB has disconnected with reason client namespace disconnect

6. Of course I don't have enough log yet to make a conclusive argument. So I have run my clear script to clean redis record again and I will check the redis record tomorrow.

[darrachequesne]

Thanks for the details, please keep us updated if you find anything 👍