Socket recovery works only once

[vojjin-gmail]

Describe the bug
I have multiplayer game/chat site where users are sometimes disconnected due to bad internet connection. With new socket.io now I use opton for socket recovery. I have created a button on page to deliberately close client's connection to socket. When I did it first time, socket was recovered and everything was fine. After second attempt to disconnect, socket is not recovered

To Reproduce

Please fill the following code example:

Socket.IO server version: 4.7.2

Server

MyAppHttp.js (simplified)

let express = require('express');
let app = express();
let bodyParser = require('body-parser');
const fs = require('fs');

const privateKey = fs.readFileSync(__dirname + "/../pkey.pem", "utf8");
const certificate = fs.readFileSync(__dirname + "/../pcert.pem", "utf8");
const credentials = {
	key: privateKey,
	cert: certificate
};
let http = require('https').createServer(credentials, app);
let options = {
	cors: {
		origin: "*"
	},
	connectionStateRecovery: {
		maxDisconnectionDuration: 2 * 60 * 1000,
		skipMiddlewares: true,
	}
};
let io = require('socket.io')(http, options);
app.use(bodyParser.json());
app.use(bodyParser.urlencoded({
	extended: true
}));

exports.app = app;
exports.io = io;
exports.http = http;

main.js (simplified)

const myAppConn = require('./system/MyAppHttp');
const Constants = require("./system/Constants");
let notifierUser = require("./classes/notifier/NotifierUser");
let appErrorLogger = require("./system/AppErrorLogger")
new appErrorLogger("notifier");

let somethingChanged = false;
let users = {};
let disconnects = {};

myAppConn.io.on('connection', (socket) => {
	if (socket.recovered) {
		console.log('recovery was successful: ' + socket.id);
		if (disconnects.hasOwnProperty(socket.id)) {
			clearTimeout(disconnects[socket.id]);
			delete disconnects[socket.id];
		}
		somethingChanged = true;
	} else {
		console.log('recovery NOT successful');
		users[socket.id]=....
		...
	}
	socket.on('disconnect', () => {
		console.log("Disconnecting " + socket.id);
		disconnectUser(socket);
	});
});
myAppConn.http.listen(Constants.PORT_NOTIFIER, () => {
	console.log('listening on *:' + Constants.PORT_NOTIFIER);
});
function disconnectUser(socket) {
	if (!disconnects.hasOwnProperty(socket.id)) {
		disconnects[socket.id] = setTimeout(() => {
			...
			if (users.hasOwnProperty(socket.id)) {
				delete (users[socket.id]);
				console.log("deleted user " + socket.id);
			}
			somethingChanged = true;
		}, 30000);
	}

}

Socket.IO client version: 4.7.2

Client
(simplified)

class Notifier {
	constructor() {
		this.socket = null;
		this.tm = null;
		this.connectionObject = {
			reconnectionAttempts: Infinity,
			reconnectionDelay: 10000,
			reconnectionDelayMax: 10000,
			randomizationFactor: 0.5,
			timeout: 20000,
			upgrade: false,
			query: ""
		};
	}

	connect() {

		this.socket = io(vojjin.nodeserver + ":" + Constants.PORT_NOTIFIER, this.connectionObject);

		this.socket.on('connect', () => {
			console.log("recovered?", this.socket.recovered);
			if (this.socket.recovered) {
				// any event missed during the disconnection period will be received now
			} else {
				// new or unrecoverable session
			}
			$("#info").text("CONNECTED");
		});
		this.socket.on('disconnect', () => {
			$("#info").text("NOT CONNECTED");

		});
	}
}

let notifier = new Notifier();
$(document).ready(function () {
	notifier.connect();
	$("#info").on("click", function () {
		//click on info text will disconnect
		if (notifier.socket.io.engine) {
			notifier.socket.io.engine.close();
		}

	});
});

Expected behavior
I expected to recover again. But no, it is not recovering, rather it is giving new socket id after second disconnection.

Platform:

• Device: Mac Studio M1 ultra
• OS: MacOS SOnoma 14.1.1

[darrachequesne]

Hi! I was not able to reproduce, could you please check this example?

Is there anything in the debug logs (DEBUG=socket* node index.js)?

[vojjin-gmail]

After further investigation, I realize that it is recovering, but not always. Just can't figure it out in which circumstances is not able to recover.

[vojjin-gmail]

DEBUG=socket*

socket.io:server initializing namespace / +0ms
  socket.io:server creating engine.io instance with opts {"cors":{"origin":"*"},"connectionStateRecovery":{"maxDisconnectionDuration":120000,"skipMiddlewares":true},"cleanupEmptyChildNamespaces":false,"path":"/socket.io"} +1ms
  socket.io:server attaching client serving req handler +0ms
listening on *:3001
  socket.io:server incoming connection with id XGExCQcN4HRDwSIkAAAA +10s
  socket.io-parser decoded 0{"pid":"ADjddwNNuyFeRUkbAAAC","offset":"OmFsFTC"} as {"type":0,"nsp":"/","data":{"pid":"ADjddwNNuyFeRUkbAAAC","offset":"OmFsFTC"}} +0ms
  socket.io:client connecting to namespace / +0ms
  socket.io:namespace adding socket to nsp / +0ms
  socket.io:socket socket connected - writing packet +0ms
  socket.io:socket join room Hq27hONfiooCOXoCAAAB +0ms
  socket.io:socket join room cohort8 portal +1ms
Mon Nov 27 2023 09:16:16 GMT+0100 (GMT+01:00) Not recovoered, No data copy
Mon Nov 27 2023 09:16:25 GMT+0100 (GMT+01:00) ["7832 / portal / Hq27hONfiooCOXoCAAAB"]
  socket.io:client client close with reason transport close +1m
  socket.io:socket closing socket - reason transport close +1m
  socket.io:socket connection state recovery is enabled for sid Hq27hONfiooCOXoCAAAB +0ms
Mon Nov 27 2023 09:17:29 GMT+0100 (GMT+01:00) Disconnecting Hq27hONfiooCOXoCAAAB
  socket.io:server incoming connection with id bmGa03IxjcJ6DS4LAAAD +1m
  socket.io-parser decoded 0{"pid":"kD3oAcM1LO1MHOm9AAAC","offset":"OmFsRgc"} as {"type":0,"nsp":"/","data":{"pid":"kD3oAcM1LO1MHOm9AAAC","offset":"OmFsRgc"}} +1m
  socket.io:client connecting to namespace / +7s
  socket.io:namespace adding socket to nsp / +1m
  socket.io:namespace connection state recovered for sid Hq27hONfiooCOXoCAAAB +2ms
  socket.io:socket join room Hq27hONfiooCOXoCAAAB +7s
  socket.io:socket join room cohort8 portal +0ms
  socket.io:socket socket connected - writing packet +0ms
  socket.io:socket join room Hq27hONfiooCOXoCAAAB +0ms
Mon Nov 27 2023 09:17:35 GMT+0100 (GMT+01:00) recovery was successful: Hq27hONfiooCOXoCAAAB
Mon Nov 27 2023 09:17:45 GMT+0100 (GMT+01:00) ["7832 / portal / Hq27hONfiooCOXoCAAAB"]
  socket.io:client client close with reason transport close +2m
  socket.io:socket closing socket - reason transport close +2m
  socket.io:socket connection state recovery is enabled for sid Hq27hONfiooCOXoCAAAB +0ms
Mon Nov 27 2023 09:19:40 GMT+0100 (GMT+01:00) Disconnecting Hq27hONfiooCOXoCAAAB
  socket.io:server incoming connection with id sYQXYLazRoGhlbqbAAAE +2m
  socket.io-parser decoded 0{"pid":"kD3oAcM1LO1MHOm9AAAC","offset":"OmFsl3n"} as {"type":0,"nsp":"/","data":{"pid":"kD3oAcM1LO1MHOm9AAAC","offset":"OmFsl3n"}} +2m
  socket.io:client connecting to namespace / +11s
  socket.io:namespace adding socket to nsp / +2m
  socket.io:namespace connection state recovered for sid Hq27hONfiooCOXoCAAAB +1ms
  socket.io:socket join room Hq27hONfiooCOXoCAAAB +11s
  socket.io:socket join room cohort8 portal +0ms
  socket.io:socket socket connected - writing packet +2ms
  socket.io:socket join room Hq27hONfiooCOXoCAAAB +0ms
Mon Nov 27 2023 09:19:51 GMT+0100 (GMT+01:00) recovery was successful: Hq27hONfiooCOXoCAAAB
Mon Nov 27 2023 09:19:55 GMT+0100 (GMT+01:00) ["7832 / portal / Hq27hONfiooCOXoCAAAB"]
  socket.io:client client close with reason transport close +7m
  socket.io:socket closing socket - reason transport close +7m
  socket.io:socket connection state recovery is enabled for sid Hq27hONfiooCOXoCAAAB +0ms
Mon Nov 27 2023 09:27:14 GMT+0100 (GMT+01:00) Disconnecting Hq27hONfiooCOXoCAAAB
  socket.io:server incoming connection with id b0mtms4e75h1jA8eAAAF +8m
  socket.io-parser decoded 0{"pid":"kD3oAcM1LO1MHOm9AAAC","offset":"OmFtGDo"} as {"type":0,"nsp":"/","data":{"pid":"kD3oAcM1LO1MHOm9AAAC","offset":"OmFtGDo"}} +8m
  socket.io:client connecting to namespace / +10s
  socket.io:namespace adding socket to nsp / +8m
  socket.io:socket socket connected - writing packet +10s
  socket.io:socket join room 2TjTo85IoFOqq_HdAAAG +0ms
  socket.io:socket join room cohort8 portal +0ms
Mon Nov 27 2023 09:27:24 GMT+0100 (GMT+01:00) Not recovoered, but copied data and joined from Hq27hONfiooCOXoCAAAB to 2TjTo85IoFOqq_HdAAAG
Mon Nov 27 2023 09:27:26 GMT+0100 (GMT+01:00) ["7832 / portal / Hq27hONfiooCOXoCAAAB","7832 / portal / 2TjTo85IoFOqq_HdAAAG"]
  socket.io:socket leave room cohort8 portal +20s
Mon Nov 27 2023 09:27:44 GMT+0100 (GMT+01:00) socket Hq27hONfiooCOXoCAAAB leaves cohort8 portal
Mon Nov 27 2023 09:27:44 GMT+0100 (GMT+01:00) deleted user Hq27hONfiooCOXoCAAAB
Mon Nov 27 2023 09:27:46 GMT+0100 (GMT+01:00) ["7832 / portal / 2TjTo85IoFOqq_HdAAAG"]