Client reconnects but fails to register with a namespace

[a-gertner]

First of all big thanks to developer(s) behind python-socketio and flask-socketio. I have been using both very successfully for a few years now.

I have encountered a situation where server-client pair does not behave as I would expect it to. I am not sure if this is a bug or intended behaviour. Would appreciate some guidance.

Here are minimal steps to recreate.

server:

import flask_socketio
import flask
import threading

app = flask.Flask('test')

sio = flask_socketio.SocketIO(app,
    ping_timeout=10,
    ping_interval=10,
    logger=True,
    engineio_logger=True,
) 

@app.route("/simulate_timeout")
def timeout():
    '''This route will simulate a network outage
    it will make sure main server thread is blocked long enough for clients
    to disconnect
    '''
    print('simulating timeout')
    threading.Event().wait(timeout=30)
    return 'simulating timeout'

@sio.on('connect', namespace='/clients')
def client_connected(message):
    print(f'Client connected. {message=}')

@sio.on('disconnect', namespace='/clients')
def client_discconnected():
    print('Client disconnected')

@sio.on('msg', namespace='/clients')
def msg(message):
    print(f'/clients received {message=}')

sio.run(app, port=8081, host='0.0.0.0') 

Client setup (I run this from an interactive shell to make it simpler to explore objects) after the setup is complete:

import socketio

sio = socketio.Client(
    engineio_logger = True,
    logger = True,
)


sio.connect(
    url='http://127.0.0.1:8081/socketio',
    transports=['websocket'],
    namespaces=['/clients'],
    retry=True,
)

Sequence of steps to reproduce.

• Start the server (using the code above)
• Start the client
  At this stage I observe (as expected):

client:

IyTjTrAV5Onb1MlEAAAA: Sending packet OPEN data {'sid': 'IyTjTrAV5Onb1MlEAAAA', 'upgrades': [], 'pin                                                                                                              gTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}                                                                                                                                                  
IyTjTrAV5Onb1MlEAAAA: Received request to upgrade to websocket                                                                                                                                                   
IyTjTrAV5Onb1MlEAAAA: Upgrade to websocket successful                                                                                                                                                            
IyTjTrAV5Onb1MlEAAAA: Received packet MESSAGE data 0/clients,{}                                                                                                                                                  
Client connected. message=None                                                                                                                                                                                   
IyTjTrAV5Onb1MlEAAAA: Sending packet MESSAGE data 0/clients,{"sid":"HAIOHsJH_kNkhy11AAAB"}  

server:

IyTjTrAV5Onb1MlEAAAA: Sending packet OPEN data {'sid': 'IyTjTrAV5Onb1MlEAAAA', 'upgrades': [], 'pin                                                                                                              gTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}                                                                                                                                                  
IyTjTrAV5Onb1MlEAAAA: Received request to upgrade to websocket                                                                                                                                                   
IyTjTrAV5Onb1MlEAAAA: Upgrade to websocket successful                                                                                                                                                            
IyTjTrAV5Onb1MlEAAAA: Received packet MESSAGE data 0/clients,{} 

• Check client's .namespaces, .connection_namespaces and .connected attributes
• Send one message from client (just to check it all works)

client:

sio.connected
True
>>> sio.namespaces
{'/clients': 'HAIOHsJH_kNkhy11AAAB'}
>>> sio.connection_namespaces
['/clients']
>>> sio.emit('msg', 'messagedata', namespace='/clients')
Emitting event "msg" [/clients]
Sending packet MESSAGE data 2/clients,["msg","messagedata"]

server:

IyTjTrAV5Onb1MlEAAAA: Received packet MESSAGE data 2/clients,["msg","messagedata"]
received event "msg" from HAIOHsJH_kNkhy11AAAB [/clients]
/clients received message='messagedata'

... so far so good.

Now I open http://127.0.0.1:8081/simulate_timeout from browser. I expect this to block server's main thread. I expect client to time out when it does not receive response to its PING and then client to reconnect because it was initialised with retry=True.

Here is what happens:

client:

packet queue is empty, aborting
Exiting write loop task
Server has stopped communicating, aborting
Waiting for write loop task to end
Engine.IO connection dropped
Connection failed, new attempt in 1.47 seconds
Exiting read loop task
Attempting WebSocket connection to ws://127.0.0.1:8081/socket.io/?transport=websocket&EIO=4
Connection failed, new attempt in 2.40 seconds
Attempting WebSocket connection to ws://127.0.0.1:8081/socket.io/?transport=websocket&EIO=4
Connection failed, new attempt in 3.82 seconds
Attempting WebSocket connection to ws://127.0.0.1:8081/socket.io/?transport=websocket&EIO=4
WebSocket connection accepted with {'sid': 'grXbsL2grJh7t_T-AAAE', 'upgrades': [], 'pingTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}
Engine.IO connection established
Sending packet MESSAGE data 0/clients,{}
Exiting write loop task
Sending packet CLOSE data None
Engine.IO connection dropped
Connection failed, new attempt in 5.33 seconds
WebSocket connection was closed, aborting
Waiting for write loop task to end
Exiting read loop task
Attempting WebSocket connection to ws://127.0.0.1:8081/socket.io/?transport=websocket&EIO=4
WebSocket connection accepted with {'sid': 'iOFYd1uf3qJMRCifAAAF', 'upgrades': [], 'pingTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}
Engine.IO connection established
Sending packet MESSAGE data 0/clients,{}
Exiting write loop task
Received packet MESSAGE data 0/clients,{"sid":"lxLfRROYOatM_m8eAAAG"}
Namespace /clients is connected
Reconnection successful
WebSocket connection was closed, aborting
Waiting for write loop task to end
Engine.IO connection dropped
Connection failed, new attempt in 0.82 seconds
Exiting read loop task
Attempting WebSocket connection to ws://127.0.0.1:8081/socket.io/?transport=websocket&EIO=4
WebSocket connection accepted with {'sid': 'Vvhfa3lOnPN0XJImAAAH', 'upgrades': [], 'pingTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}
Engine.IO connection established
Sending packet MESSAGE data 0/clients,{}
Received packet MESSAGE data 0/clients,{"sid":"9WXvM21jDSJcv4InAAAI"}
Namespace /clients is connected
Received packet MESSAGE data 4/clients,"Unable to connect"
Reconnection successful
Connection to namespace /clients was rejected. data=Unable to connect
Received packet PING data 
Sending packet PONG data
...

server:

simulating timeout
IyTjTrAV5Onb1MlEAAAA: Sending packet PING data None
IyTjTrAV5Onb1MlEAAAA: Unexpected error "timed out", closing connection
rt43e1B6Zj36dWoYAAAC: Sending packet OPEN data {'sid': 'rt43e1B6Zj36dWoYAAAC', 'upgrades': [], 'pingTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}
rt43e1B6Zj36dWoYAAAC: Received request to upgrade to websocket
rt43e1B6Zj36dWoYAAAC: Upgrade to websocket successful
rt43e1B6Zj36dWoYAAAC: Unexpected error "[WinError 10053] An established connection was aborted by the software in your host machine", closing connection
mtqY0-q1f0Lbw_lFAAAD: Sending packet OPEN data {'sid': 'mtqY0-q1f0Lbw_lFAAAD', 'upgrades': [], 'pingTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}
mtqY0-q1f0Lbw_lFAAAD: Received request to upgrade to websocket
mtqY0-q1f0Lbw_lFAAAD: Upgrade to websocket successful
mtqY0-q1f0Lbw_lFAAAD: Unexpected error "[WinError 10053] An established connection was aborted by the software in your host machine", closing connection
Client disconnected
server=127.0.0.1:8081//socket.io/ client=127.0.0.1:59701 socket shutdown error: [WinError 10038] An operation was attempted on something that is not a socketserver=127.0.0.1:8081//socket.io/ client=127.0.0.1:59709 socket shutdown error: [WinError 10038] An operation was attempted on something that is not a socketgrXbsL2grJh7t_T-AAAE: Sending packet OPEN data {'sid': 'grXbsL2grJh7t_T-AAAE', 'upgrades': [], 'pingTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}
grXbsL2grJh7t_T-AAAE: Received request to upgrade to websocket
grXbsL2grJh7t_T-AAAE: Upgrade to websocket successful
iOFYd1uf3qJMRCifAAAF: Sending packet OPEN data {'sid': 'iOFYd1uf3qJMRCifAAAF', 'upgrades': [], 'pingTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}
iOFYd1uf3qJMRCifAAAF: Received request to upgrade to websocket
iOFYd1uf3qJMRCifAAAF: Upgrade to websocket successful
iOFYd1uf3qJMRCifAAAF: Received packet MESSAGE data 0/clients,{}
Client connected. message=None
iOFYd1uf3qJMRCifAAAF: Sending packet MESSAGE data 0/clients,{"sid":"lxLfRROYOatM_m8eAAAG"}
iOFYd1uf3qJMRCifAAAF: Received packet CLOSE data
Client disconnected
Vvhfa3lOnPN0XJImAAAH: Sending packet OPEN data {'sid': 'Vvhfa3lOnPN0XJImAAAH', 'upgrades': [], 'pingTimeout': 10000, 'pingInterval': 10000, 'maxPayload': 1000000}
Vvhfa3lOnPN0XJImAAAH: Received request to upgrade to websocket
Vvhfa3lOnPN0XJImAAAH: Upgrade to websocket successful
Vvhfa3lOnPN0XJImAAAH: Received packet MESSAGE data 0/clients,{}
Client connected. message=None
Vvhfa3lOnPN0XJImAAAH: Sending packet MESSAGE data 0/clients,{"sid":"9WXvM21jDSJcv4InAAAI"}
Vvhfa3lOnPN0XJImAAAH: Received packet MESSAGE data 0/clients,{}
Vvhfa3lOnPN0XJImAAAH: Sending packet MESSAGE data 4/clients,"Unable to connect"
Vvhfa3lOnPN0XJImAAAH: Sending packet PING data None
Vvhfa3lOnPN0XJImAAAH: Received packet PONG data
...

If I then try try to examine the client it appears to be in a weird state. It is connected. And it continues to do PING/PONG with the server, but it is not registered with any namespace. Attempt to emit to the namespace /clients will fail:

client:

>>> sio.connected
True
>>> sio.namespaces
{}
>>> sio.connection_namespaces
['/clients']
>>> sio.emit('msg', 'messagedata', namespace='/clients')
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "C:\git\visualizer\venv\Lib\site-packages\socketio\client.py", line 214, in emit
    raise exceptions.BadNamespaceError(
socketio.exceptions.BadNamespaceError: /clients is not a connected namespace.

Is this intended behavior? Am I not using the client correctly? I am expecting client to reconnect to original namespace or fail to reconnect entirely.

Any help appreciated

python-socketio==5.11.3
flask-socketio==5.3.6

[miguelgrinberg]

I'm not sure I understand this:

Now I open http://127.0.0.1:8081/simulate_timeout from browser. I expect this to block server's main thread. I expect client to time out when it does not receive response to its PING and then client to reconnect because it was initialised with retry=True.

Why would waiting on an event block the server? If this is what happens for you then you have a problem. Like maybe you are using gevent or eventlet for the server, but your Event object is from the Python standard library and not from gevent or eventlet as it should. If you used a set of compatible concurrency tools, then waiting on an event should not block anything other than the endpoint that is waiting.

[a-gertner]

Hi, @miguelgrinberg

Code inside http://127.0.0.1:8081/simulate_timeout is not what I am using in production. In fact I agree with you code like that does not belong in a threaded server.

I only use it to simulate a very rare condition that occurs in production on k8s. How it occurs I still did not figure out, but it may have to do not with my code or your library but with the infrastructure.

From logs that I gathered I can see that when the situation occurs main thread gets hard-blocked long-enough for clients to begin disconnecting. Which is fine, it happens very rarely. What worries me is that when clients attempt reconnecting they end up in that weird state when it is considers itself connected but is not registered with a namespace. This leaves the whole client-server pair in an unusable state.

I am open to any ideas.

[miguelgrinberg]

Let's start from the beginning. Which web server are you using? Which async mode? If you are using gevent or eventlet, have you monkey patched the standard library so that it becomes non-blocking?

Really if you have a server that can block completely, I feel there is no point in looking at downstream problems. First let's make sure your server does not block, and maybe that removes the reconnection issue.

I also noticed that you have modified the default Socket.IO timeouts. Why did you do that? The defaults are chosen to be compatible with most deployment platforms, and also to minimize the heart beat churn, which slows every thing down. Unless you have a good reason to change these timeouts, I recommend that you always use the defaults.

[a-gertner]

I am using:
gevent==24.11.1
eventlet==0.36.0

I run flask-socketio.SocketIO with async_mode='eventlet', monkeypatched.

In production my intervals are set to:
SOCKETIO_PING_INTERVAL = 60
SOCKETIO_PING_TIMEOUT = 30

I modified them in the example above to make it it easier to reproduce the situation locally.

I am almost certain that blocking in production occurs due to infrastructure. So perhaps you statement "Really if you have a server that can block completely, I feel there is no point in looking at downstream problems." is the answer.

Wouldn't the same situation occur due to a loss of comms between server and client?

[miguelgrinberg]

You can't be using both gevent and eventlet. If you are using eventlet, then gevent should not even be installed, or viceversa. These aren't packages that cooperate together, they are incompatible with each other.

Also, eventlet is not well maintained and hasn't been for a long time. See their readme for details.

Wouldn't the same situation occur due to a loss of comms between server and client?

What same situation? A blocked server? If the server's networking goes down then all clients will get disconnected. I don't believe the server will block, but even if it does, it wouldn't matter since the network is down and no connections will happen anyway. The clients will all attempt to reconnect, and should succeed once the network is restored on the server. If the networking on one of clients goes down, then the server will disconnect that client after it fails to respond to the ping packet. This should not affect the connections with other clients, nor cause any blocking.

I'm still confused about the problem you are seeing, because the code that you provided does not block unless you are mixing incompatible concurrency primitives. You claim that you are using eventlet and that you are monkey patching, but none of this is evident in the example code you provided.

[a-gertner]

You are right I don't use both gevent and eventlet simultaniously. Async mode is eventlet in my case. I will take your feedback seriously and consider moving to gevent. I was under impression that eventlet is preferred mode as it is the first in the list of default options selected by flask-socketio as outlined here

A situation I am trying to recreate is:

• Server gets blocked (perhaps due to the lack of CPU resource on the k8s cluster) for a period of time long enough for clients to start disconnecting but not long enough for them to give up retrying

What I expect to see:

• When server becomes available again clients reconnect successfully

What I actually see:

• Clients reconnect but fail to rejoin the namespace

I admit that the method I used to simulate that is rather crude. Hard blocking the server was the first thing that came to my mind. But it appears to cause the same symptoms that I have observed in the logs of remote production server. Symptoms are:

• "packet queue is empty, aborting" message from enginio
• followed by client disconnect
• followed by client reconnect attempts which eventually succeed but without rejoining the namespace.

Can you recommend a better method to simulate the same?

Also it is worth mentioning that the code I shared is an absolutely minimal example that demonstrates the problem that I see and it is not my production code.

[miguelgrinberg]

Right, and what I'm saying is that if the server gets blocked long enough that clients start to drop then all bets are off pretty much. This isn't a condition that is expected to happen during normal use.

I can't say for sure that there is no bug in the reconnection logic, maybe there is. But if the only way for this bug to appear is to block the server for more than 25 seconds (using default timeouts) then really the problem is the blocking of the server, which should never be allowed to happen. The whole point of using an asynchronous server is that everything is non-blocking.

I would recommend that you address the blocking problem in your server first. Then if the reconnection issues persist we can figure out a way to reproduce assuming a well behaved server.