Waiting for client events leads to timeouts

[jorgschulze73]

Hi miguel, been using Flask-SocketIO for a while but stumbled upon some issues recently; hopefully you'll be able to provide some insights on how to resolve them.

This is my current setup:

• Flask-SocketIO running both SocketIO and REST endpoints
• Requests to the REST api are "forwarded" to SocketIO clients
• Deployed using uWSGI+gevent behind nginx on 1 worker

The problem:
I have noticed that requests are consistently timing out when using call or emit + waiting for callback; in particular way, I'm not seeing the concurrency behaviour that I would expect from using gevent.

Here is a simple snippet:

from flask_socketio import Namespace, call

class MyApiNamespace(Namespace):
    name = '/my_api'

    # connect / disconnect handlers
    
    @staticmethod
    def handle(request):
        name = '<request_name>'
        body = '<request_body>'
        to = '<random_client_sid>'

        return call(name, body, namespace=MyApiNamespace.name, to=to, timeout=10)


@rest_api.route('/my_api', methods=['POST'])
def my_api():
    return MyApiNamespace.handle(request.data)

What I would expect to happen:
The call invocation should take care of yielding the current greenlet, potentially letting another one run.
Whenever the socketio will invoke its callback, the request will complete and client would be returned data immediately.

What I'm seeing:
The request never returns before the timeout is hit; moreover, the handling time for each one of these requests seem to creep up over time:

Apr 23 10:09:48 myapi uwsgi[31227]: [pid: 31230|app: 0|req: 795/813] <redacted> () {56 vars in 1197 bytes} [Tue Apr 23 10:09:38 2024] POST /my_api => generated 148 bytes in 10017 msecs (HTTP/1.1 200) 2 headers in 81 bytes (3 switches on core 93)
...
Apr 23 10:09:55 myapi uwsgi[31227]: [pid: 31230|app: 0|req: 825/942] <redacted> () {56 vars in 1197 bytes} [Tue Apr 23 10:09:31 2024] POST /my_api => generated 372 bytes in 24237 msecs (HTTP/1.1 200) 2 headers in 81 bytes (3 switches on core 32)

As a side note, I also have monkey patching applied at the very beginning of the entry point invoked by uWSGI.

I would appreciate your guidance in troubleshooting this issue, or attempting to work around possible limitations.

Thank you!

[miguelgrinberg]

What does the client do when it receives one of these events? The client must send an acknowledgement, that is what triggers the callback.

[jorgschulze73]

The client performs a task that can take up to few seconds, then invoke the callback with the data that should be returned to the REST api call.
The problem here is that for some reason the socketio client doesn't even seem to receive the event sent from the call.

[miguelgrinberg]

Enable Socket.IO logging in the server to see if the events are going out to your client.

[jorgschulze73]

So I've tried enabling logging as you suggested, found that when I have a single client things work pretty smoothly:

...
Apr 23 18:46:28 myapi uwsgi[4853]: rSKMHyoHVAaCyfYOAAVl: Sending packet MESSAGE data 2/my_api,6["handle",{"arg1": "arg1", "arg2": "arg2"}]
Apr 23 18:46:29 myapi uwsgi[4853]: rSKMHyoHVAaCyfYOAAVl: Received packet MESSAGE data 3/my_api,6[{"res": {"success"}}]
Apr 23 18:46:29 myapi uwsgi[4853]: [pid: 4861|app: 0|req: 843/1212] <redacted> () {56 vars in 1203 bytes} [Tue Apr 23 18:46:28 2024] POST /my_api => generated 1364 bytes in 1309 msecs (HTTP/1.1 200) 2 headers in 82 bytes (3 switches on core 904)
Apr 23 18:46:32 myapi uwsgi[4853]: rSKMHyoHVAaCyfYOAAVl: Sending packet PING data None
Apr 23 18:46:32 myapi uwsgi[4853]: rSKMHyoHVAaCyfYOAAVl: Received packet PONG data
Apr 23 18:46:35 myapi uwsgi[4853]: rSKMHyoHVAaCyfYOAAVl: Sending packet MESSAGE data 2/my_api,8["handle",{"arg1": "arg1", "arg2": "arg2"}]
Apr 23 18:46:37 myapi uwsgi[4853]: rSKMHyoHVAaCyfYOAAVl: Received packet MESSAGE data 3/my_api,8[{"res": {"success"}}]
Apr 23 18:46:37 myapi uwsgi[4853]: [pid: 4861|app: 0|req: 856/1420] <redacted> () {56 vars in 1203 bytes} [Tue Apr 23 18:46:35 2024] POST /my_api => generated 1364 bytes in 2565 msecs (HTTP/1.1 200) 2 headers in 82 bytes (3 switches on core 453)
Apr 23 18:46:44 myapi uwsgi[4853]: rSKMHyoHVAaCyfYOAAVl: Sending packet MESSAGE data 2/my_api,10["handle",{"arg1": "arg1", "arg2": "arg2"}]
Apr 23 18:46:45 myapi uwsgi[4853]: rSKMHyoHVAaCyfYOAAVl: Received packet MESSAGE data 3/my_api,10[{"res": {"success"}}]
Apr 23 18:46:45 myapi uwsgi[4853]: [pid: 4861|app: 0|req: 883/1570] <redacted> () {56 vars in 1203 bytes} [Tue Apr 23 18:46:44 2024] POST /my_api => generated 1364 bytes in 1309 msecs (HTTP/1.1 200) 2 headers in 82 bytes (3 switches on core 901)
...

However, with more requests it seems that the clients are not able to receive messages, hence not producing any response.
The outcome is the one I described above, with requests timing out and creeping up over time:

...
Apr 23 18:49:57 myapi uwsgi[5000]: zhNYWcaf25HW98zkAABG: Sending packet MESSAGE data 0/my_api,{"sid":"CoSRI9vep55nYpEnAABV"}
Apr 23 18:50:00 myapi uwsgi[5000]: zhNYWcaf25HW98zkAABG: Sending packet MESSAGE data 2/my_api,2["handle",{"arg1": "arg1", "arg2": "arg2"}]
...
# No response is ever received?!
Apr 23 18:50:27 myapi uwsgi[5000]: zhNYWcaf25HW98zkAABG: Sending packet MESSAGE data 2/my_api,12["handle",{"arg1": "arg1", "arg2": "arg2"}]
...

Just for reference, the way that I'm storing/retrieving sids for the socketio clients is as follows (updated version of the code I posted above) from a database:

class MyApiNamespace(Namespace):
    name = '/my_api'

    @staticmethod
    @socketio.on('connect')
    def on_connect(data):
    	# Validate input data or disconnect

    	entry = MySocketIoClientModel.get_by_unique_identifier(data.unique_identifier)
    	entry.sid = request.sid
    	entry.save()

    @staticmethod
    @socketio.on('disconnect')
    def on_disconnect():
        entry = MySocketIoClientModel.get_by_sid(request.sid)
        entry.sid = None
        entry.save()
    
    @staticmethod
    def handle(request):
        name = '<request_name>'
        body = '<request_body>'
        to = '<random_client_sid_from_db>'

        return call(name, body, namespace=MyApiNamespace.name, to=to, timeout=10)


@rest_api.route('/my_api', methods=['POST'])
def my_api():
    return MyApiNamespace.handle(request.data)

At this point I feel like there's just too many requests for this to work the way that I expect (I doubt it, considering it's just few hundred clients) or there's some other state management issue that's not handled properly.

[miguelgrinberg]

It's really hard for me to say because I don't have a complete picture. I don't know what is this Namespace base class that you are using, for example. Are you able to create minimal but complete server and clients that I can use to reproduce this?