All connections stop processing events at the same time

[morland96]

Hi guys!
I'm recently facing an issue that all my connections turn into a strange state almost at the same time

So basically, I have a customised "telemetry" packet a little bit under 1k size sending every 5 seconds. After running them for couple hours, all of such "telemetry" events starting timeout. I double checked the server side and I can confirm that none of those events been received (I logged at the first line of my event handler".

The strangest part is: while these kind events keeping timeout, the socketio pingpong packets are still sending as normal. The log looks like this:

2023-12-31 03:15:51,394 - INFO - Sending packet MESSAGE data 2/node,1659["report_telemetry","{\"system\": {\"current_config_tag\": \"2afa24ceba44e4ac\", \"cpu_
2023-12-31 03:15:51,469 - INFO - Received packet MESSAGE data 3/node,1659[{"return_code":0,"ts":"2023-12-30T19:15:51.380215","message":"Telemetry resolved"}]  
2023-12-31 03:15:56,494 - INFO - Sending packet MESSAGE data 2/node,1660["report_telemetry","{\"system\": {\"current_config_tag\": \"2afa24ceba44e4ac\", \"cpu_
2023-12-31 03:15:56,570 - INFO - Received packet MESSAGE data 3/node,1660[{"return_code":0,"ts":"2023-12-30T19:15:56.480691","message":"Telemetry resolved"}]  
2023-12-31 03:15:58,958 - INFO - Received packet PING data                                                                                                     
2023-12-31 03:15:58,958 - INFO - Sending packet PONG data                                                                                                      
2023-12-31 03:16:01,598 - INFO - Sending packet MESSAGE data 2/node,1661["report_telemetry","{\"system\": {\"current_config_tag\": \"2afa24ceba44e4ac\", \"cpu_
2023-12-31 03:16:01,674 - INFO - Received packet MESSAGE data 3/node,1661[{"return_code":0,"ts":"2023-12-30T19:16:01.584726","message":"Telemetry resolved"}]  
2023-12-31 03:16:06,690 - INFO - Sending packet MESSAGE data 2/node,1662["report_telemetry","{\"system\": {\"current_config_tag\": \"2afa24ceba44e4ac\", \"cpu_
2023-12-31 03:16:26,725 - INFO - Sending packet MESSAGE data 2/node,1663["report_telemetry","{\"system\": {\"current_config_tag\": \"2afa24ceba44e4ac\", \"cpu_
2023-12-31 03:16:46,767 - INFO - Sending packet MESSAGE data 2/node,1664["report_telemetry","{\"system\": {\"current_config_tag\": \"2afa24ceba44e4ac\", \"cpu_
2023-12-31 03:16:59,013 - INFO - Received packet PING data                                                                                                     
2023-12-31 03:16:59,022 - INFO - Sending packet PONG data                                                                                                      
2023-12-31 03:17:06,802 - INFO - Sending packet MESSAGE data 2/node,1665["report_telemetry","{\"system\": {\"current_config_tag\": \"2afa24ceba44e4ac\", \"cpu_
2023-12-31 03:17:26,821 - INFO - Sending packet MESSAGE data 2/node,1666["report_telemetry","{\"system\": {\"current_config_tag\": \"2afa24ceba44e4ac\", \"cpu_

As you can see, servers stop sending ACKs from 2023-12-31 03:16:06,690 and I can confirm that the event handler is not been triggered. Why this happens?

More information about this issue:

• I have an nginx proxy, but I tried to let the client talk to the server directly. Same result.
• All clients (roughly 10) suppose to be long live. It was working while for a really long time (about a month) but start failing recently.
• It happens everyday and for all clients almost the same time (within few seconds)
• All clients are forced to use the websocket mode, not polling then upgrading
• I have changed the ping interval to 60s
• I'm actually using flask-socketio, but I think this is not related to flask-socketio itself.
• The backend is been served via uwsgi with gevent, the config looks like this:

[uwsgi]
strict = true
master = true
enable-threads = true
vacuum = true                          ; Delete sockets during shutdown
single-interpreter = true
die-on-term = true                     ; Shutdown when receiving SIGTERM (default is respawn)
need-app = true

wsgi-file = wsgi.py
callable = app
http-websockets = true
gevent = 1024

disable-logging = true
log-4xx = true
log-5xx = true

Versions:
flask-socketio==5.2.0
python-socketio[client]==5.9.1
python-engineio==4.7.1

[miguelgrinberg]

First of all, I'd like to ask that you follow the instructions on the issue template. If you have a question, or if you are not sure if this is an issue on this project then you have to use the discussions board. The issues board is for well understood issues that I need to work on.

As far as your problem, you should look in your server logs for anything of significance happening at the time this problem starts.

[miguelgrinberg]

You don't need to review all possible logs. The log with the server-side version of the Socket.IO events you show above from the client will suffice.

[morland96]

Yep. But I still failed to find out the reason.

[miguelgrinberg]

So basically you are saying that you are 100% sure that you can see the server sending ping packets and receiving pong responses at around 3:16 on December 31 (the timestamp in the log above), yet at around that time it silently stopped receiving events from the client? Have you really checked this, because I doubt this can happen without any clues in the log.

[morland96]

Basically, yes. I know it sounds weird. Things I can confirm:

• ping pong working as normal
• the connection keeps considered alive, not disconnected event triggered
• but the events stopped been processing
• it's keep happening once per day at a random time

[miguelgrinberg]

@morland96 you already described the problem. What I'm asking is for logs that support your statements.