Unexpected delay in message transmission from server to client

[David00]

Hello,

I am trying to track down a tricky issue in my webapp dealing with back-and-forth communication between the client and socketio server.

Environment Details

• Server is a Pi 4 running Ubuntu Server 22.04, kernel 6.1.0-rpi7-rpi-v8
• Python 3.11.2
• Flask and SocketIO libraries:

$ pip list | grep -iE "socket|flask"
Flask              2.3.3
Flask-Bcrypt       1.0.1
Flask-Login        0.6.2
Flask-Migrate      3.1.0
Flask-SocketIO     5.3.6
Flask-SQLAlchemy   2.5.1
Flask-WTF          1.2.1
python-socketio    5.11.0
simple-websocket   1.0.0
websocket-client   1.6.4

I am running this using the built-in Flask/SocketIO server and web connections are reverse proxied from an Nginx frontend. Nginx is handling the connection upgrade for /socket.io:

    location /socket.io {
        include proxy_params;
        proxy_http_version 1.1;
        proxy_buffering off;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "Upgrade";
        proxy_pass http://127.0.0.1:5000/socket.io;
    }

Context

I have not experienced this issue with any other websocket communications elsewhere in my app. Also, this is a single-user app I'm developing that is self-hosted on a Raspberry Pi. This particular websocket exchange is intended to provide information on the execution of a backup routine in my app through three stages - requested, in progress, and done. The impact of this issue is that the web UI jumps from requested to done, due to the delay in the in progress message coming through the websocket.

Debugging

I've enabled logging in the socketio extension and it appears to be sending the message, but it doesn't show up on the client for another 15 seconds (until another message is emitted over the socket, then both show up together).

See the annotated screenshot below for some details from my browser and the application logs. Specifically, it's the 'backup started' message that is delayed.

In the screenshot, you'll also see another log message with no timestamp (the Sent event ... to ... in namespace ... containing args. This is just a quick print statement in the SocketIO class definition's emit method, right after the call to self.server.emit()

The entire websocket for my run-backup-now event is here. You'll see that I've tried running the potentially time-consuming backup routine as a subprocess (commented out in my current attempt) as well, but it makes no difference.

@socketio.on('run-backup-now', namespace='/control')
def run_backup_now():
    '''Initiates an ondemand backup'''

    logger.debug("Backup requested via websocket")    
    try:
        # Check to see if the InfluxDB connection is active
        if current_app.pmc.influx_okay:
            # Make sure this isn't a remote InfluxDB server.
            db_settings = DB_Settings.query.get(1)
            if db_settings.host not in ['127.0.0.1', 'localhost']:
                logger.debug(f"Not starting the requested backup because the InfluxDB host ({db_settings.host}) does not appear to be on this machine")
                socketio.emit('run-backup-now', {'message' : 'remote influx'}, namespace='/control')
                return
                        
            q = Queue()
            # p = Process(target=run_on_demand_backup, args=(q,))
            logger.debug("Sending backup started message over websocket...")
            socketio.emit('run-backup-now', {'message' : 'backup started'}, namespace='/control')
            logger.debug("Sent - starting run_on_demand_backup()")
            # p.start()
            # p.join()            
            run_on_demand_backup(q)
            backup_filename = q.get()
            if backup_filename:
                socketio.emit('run-backup-now', {'message' : 'backup complete', 'filename' : backup_filename}, namespace='/control')
            else:
                socketio.emit('run-backup-now', {'message' : 'backup failed'}, namespace='/control')
                logger.debug("Backup name returned was 'None' - see the backup logs for what happened.")
        else:
            logger.debug("Backup not started - Influx is down.")
            
            socketio.emit('run-backup-now', {'message' : 'influx down'}, namespace='/control')
            
        
    except Exception as e:
        logger.warning(f"There was a problem running the backup. The exception message is: {e}")
        socketio.emit('run-backup-now', {'message' : 'encountered an error'})

So, I'm stumped, and I'm hoping you can help out.

PS - moving from "legacy" GETs and POSTs to websockets for communication between frontend and backend has been such a wonderful change, I can't even put it into words. Thank you for this library!

[miguelgrinberg]

Are you using a greenlet framework (eventlet or gevent) in this application? If yes, have you monkey patched the standard library? And is the Queue object that you are using a greenlet-aware queue or the standard Python queue?

[miguelgrinberg]

The Flask webserver is not good to use in production. Use Gunicorn with the --threads option instead.

[David00]

Thanks Miguel. I've been having a tough time with Gunicorn - not that I can't start my app with it... but I can't stop my app once it's started with Gunicorn.

I'm starting it with -w 1 --threads 10 and when I stop the app with Ctrl-c, it's getting SIGKILL'd after 30 seconds.

$ gunicorn -w 1 --threads 10 'myapplication.src.app:create_app()' -b 127.0.0.1:5000
[2024-05-12 18:03:56 -0700] [94355] [INFO] Starting gunicorn 22.0.0
[2024-05-12 18:03:56 -0700] [94355] [INFO] Listening at: http://127.0.0.1:5000 (94355)
[2024-05-12 18:03:56 -0700] [94355] [INFO] Using worker: gthread
[2024-05-12 18:03:56 -0700] [94356] [INFO] Booting worker with pid: 94356
05-12-2024 18:03:57 -  - DEBUG -  -  -  - __init__.py: <A bunch of app startup logging output that I've simplified here>
^C[2024-05-12 18:04:07 -0700] [94355] [INFO] Handling signal: int
[2024-05-12 18:04:07 -0700] [94356] [INFO] Worker exiting (pid: 94356)
[2024-05-12 18:04:37 -0700] [94355] [ERROR] Worker (pid:94356) was sent SIGKILL! Perhaps out of memory?
[2024-05-12 18:04:37 -0700] [94355] [INFO] Shutting down: Master

Trying to start the app again says that port 5000 is in use already, and upon investigation, there are two gunicorn processes running still:

$ sudo ps -aux | grep gunicorn
pi         94368  0.0  0.6 221312 55628 pts/1    Sl   18:03   0:00 /home/pi/myapplication/venv/bin/python3 /home/pi/myapplication/venv/bin/gunicorn -w 1 --threads 10 myapplication.src.app:create_app() -b 127.0.0.1:5000
pi         94373  0.0  0.6 221312 55020 pts/1    Sl   18:03   0:00 /home/pi/myapplication/venv/bin/python3 /home/pi/myapplication/venv/bin/gunicorn -w 1 --threads 10 myapplication.src.app:create_app() -b 127.0.0.1:5000

I know this is getting outside your lane, but do you have any ideas on what it could be? My create_app() function is a fairly straightforward app factory that registers a couple Flask blueprints, tries to connect to an InfluxDB server, initializes several Flask extensions (like SQLAlchemy, Flask Login, your very own Flask-Migrate, and SocketIO). It also creates a Python Thread instance, but it doesn't actually start it until the user does so in the UI.

[miguelgrinberg]

This is likely because you have long term active connections that need to timeout when you attempt to stop the server.

You should be using Gunicorn for your production deployment. Even if it takes a bit of work to stop the server you would only be doing it when you perform an upgrade, right? So maybe this isn't a deal breaker, at least it wouldn't be for me. Web servers often have issues stopping, they are not designed to be stopped and for that reason the developers don't spend a lot of time figuring out graceful stopping mechanisms.

[David00]

Interesting - I will have to dig into it more. That's right that the server will only need to be stopped for upgrades, but the challenge is that the user is the one to do the upgrade for my application running on their Pi, and I'm wanting it to be as seamless as possible.

I would be totally okay with dealing with zombie processes if my application was centralized on a server I manage, but having the application deployed on user's private networks poses an interesting challenge that I'll have to either handle in my upgrade routine, or find another solution that doesn't leave orphans when stopped.

I took a look at OctoPrint as this is a very similar concept at a high level (user-controlled application running on a Pi), and they are using both Tornado and Flask. (I haven't dove deeper to look into how each is being utilized)

Thank you so much for the helpful insight, Miguel. Hopefully this discussion helps others in the future!

[miguelgrinberg]

There may be a way to force your web handlers to exit using an event or another synchronization object. Worst case, you can always SIGKILL the process, which will not leave zombie processes. This isn't nice because it does not allow you to perform cleanup and exit gracefully, but if you need a quick way to restart that should do it.