Client sends multiple ping to server

[HanfordWu]

Hi,

python-socketio: 4.6.0
python-engineio: 3.13.2

I got this log:

workers_1  | 21/06/2021 07:54:17 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:17 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:17 [INFO] engineio.client._receive_packet(): Received packet PONG data None
workers_1  | 21/06/2021 07:54:18 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:18 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:18 [INFO] engineio.client._receive_packet(): Received packet PONG data None
workers_1  | 21/06/2021 07:54:19 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:19 [INFO] engineio.client._receive_packet(): Received packet PONG data None
workers_1  | 21/06/2021 07:54:19 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:19 [INFO] engineio.client._receive_packet(): Received packet PONG data None
workers_1  | 21/06/2021 07:54:20 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:20 [INFO] engineio.client._receive_packet(): Received packet PONG data None
workers_1  | 21/06/2021 07:54:20 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:20 [INFO] engineio.client._receive_packet(): Received packet PONG data None
workers_1  | 21/06/2021 07:54:28 [INFO] apps.tasks.image_push_results(): starting image_push_results
workers_1  | 21/06/2021 07:54:28 [INFO] apps.tasks.work_push_results(): starting work_push_results
workers_1  | 21/06/2021 07:54:30 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:30 [INFO] engineio.client._receive_packet(): Received packet PONG data None
workers_1  | 21/06/2021 07:54:31 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:31 [INFO] engineio.client._receive_packet(): Received packet PONG data None
workers_1  | 21/06/2021 07:54:42 [INFO] engineio.client._ping_loop(): PONG response has not been received, aborting
workers_1  | 21/06/2021 07:54:42 [INFO] engineio.client._send_packet(): Sending packet PING data None
workers_1  | 21/06/2021 07:54:42 [INFO] engineio.client._read_loop_websocket(): Unexpected error receiving packet: "WebSocket read returned None", aborting
workers_1  | 21/06/2021 07:54:42 [INFO] engineio.client._read_loop_websocket(): Waiting for write loop task to end
workers_1  | 21/06/2021 07:54:42 [INFO] engineio.client._ping_loop(): Exiting ping task
workers_1  | 21/06/2021 07:54:42 [INFO] engineio.client._write_loop(): Exiting write loop task
workers_1  | 21/06/2021 07:54:42 [INFO] engineio.client._read_loop_websocket(): Waiting for ping loop task to end
workers_1  | 21/06/2021 07:54:42 [INFO] socketio.client._handle_eio_disconnect(): Engine.IO connection dropped

Looks like at 07:54:17, client sent two ping, after that client keep sending ping and getting pong. However, at 07:54:42, looks like ping_loop found it didn't receive a pong after 25 seconds. And aborting the connection.

Other than that, normally, ping/pong would be very regular, every 25 seconds, in my client however, there are often a bunch of ping/pong come out.

If this client connects server at startup, I don't see above happen. But once server disconnected, and then restart, client connected again, above case could happen.

Does anyone have idea?

Thank you very much for help!

[miguelgrinberg]

Do you have the earlier part of the log? It would be useful to see if there is anything interesting that happened before this problem started. I can't really tell you what's wrong, but my guess is that you have more than one client instance, as that would explain why there are some many PING requests going out to the server.

[HanfordWu]

Ohh, before this log, those are more duplicated ping/pong log, nothing special. But for more information, the socketio server is an aiohttp server started using 3 gunicorn workers. This means server has 3 instances. I am not sure if this could result in multiple ping/pong sending from client. But I suppose the client should have only one websocket connection and ping_loop.

[miguelgrinberg]

Having multiple server instances should not cause this. The only explanation I have is that you have multiple client connections. In that case each client will send its own ping packets. I'm not sure why restarting the server causes this.

If you want to share a complete log I'm happy to take a look. I get that you found nothing interesting, but maybe you don't know what to look for.

[HanfordWu]

Hi Miguel,
Here is more log: taas_worker log

Before this experiment, client send 1 ping and get 1 pong every 25 sec.

At 04:03:58, I bring down the socket server.

Our client has its own infinite reconnection mechanism. Since engine.io v3.13.2 reconnecting had issue. So, from 04:03:58 to 04:05:15, client tried to reconnect three times. And the last time, it succeeds.

However, after reconnected, the ping/pong start send twice every time. eg. 04:05:43 and 04:05:44 two pings/pongs, so on and so forth.

Thank you for looking at the log!

[miguelgrinberg]

Did you notice that there are two instances of "Engine.IO connection established" in the log? That confirms what I'm saying, you have two connections active at the same time.

[HanfordWu]

Yes, from server side, there are two sid generated as well. I thought it was because client's multiple reconnect requests on the fly, and the first sid will be replaced finally. But now looks like the client is having those two connections at the same time. However, I don't know why two connections. I assume a client can only have one connection.

This only happen when server disconnected and back.

[miguelgrinberg]

@HanfordWu this is a bug in your reconnection logic. You said you are not using the reconnection support in this package, correct? So I don't see how this can be caused by the package itself.

[HanfordWu]

Ohh, yes, we are using our own reconnection logic. I will upgrade to 3.14.2, and cancel our reconnection. Then check the reconnection again.
Thanks!

[frankgreco]

I am running into a similar issue where everything is "double-logged". However, the SID is the same 👇🏼

Attempting polling connection to http://localhost:5001/socket.io/?transport=polling&EIO=4
Attempting polling connection to http://localhost:5001/socket.io/?transport=polling&EIO=4
Polling connection accepted with {'sid': 'ZZXN7B6BNp4xPHAEAAAM', 'upgrades': ['websocket'], 'pingInterval': 25000, 'pingTimeout': 20000, 'maxPayload': '5e8'}
Polling connection accepted with {'sid': 'ZZXN7B6BNp4xPHAEAAAM', 'upgrades': ['websocket'], 'pingInterval': 25000, 'pingTimeout': 20000, 'maxPayload': '5e8'}
Engine.IO connection established
Engine.IO connection established

[miguelgrinberg]

@frankgreco your case is different. You have your logger badly configured, it has a duplicated stream. If you are setting up your logging configuration, then instead of logger=True you should pass logger=my_logger, where my_logger if the logger that you want the library to use.