Flask Socketio sockets fail to upgrade with multiple gunicorn workers & redis

[dMAC95]

Hello, I have this issue where my socket clients are failing to upgrade. It happens at the start of the page load. If I give it time they'll eventually successfully upgrade. I also receive a lot of "Invalid Session" errors. If one connection is upgraded and another connection is in the error state I can close the upgraded connection and the errored connection will be upgraded.

I recreated this issue on my test server without any emits being administered during the test. At its simplest form in my environment the issue can be recreated by creating a flask factory application, using redis, and using 2 gunicorn workers. Then simply open more connections than there are workers (3 in this test case).

I use python 3.9 here because it works with eventlet.

Here's the application init.py:

from flask import Flask
from flask_socketio import SocketIO

import redis

socketio = SocketIO(message_queue='redis://localhost:6379/5', cors_allowed_origins="*", logger=True, engineio_logger=True)

def create_app(debug=False):

    app = Flask(__name__)
    app.debug = debug
    app.config['SECRET_KEY'] = 'MY SECRET KEY'
    app.config['MAX_CONTENT_LENGTH'] = 1024 * 1024 * 1024

    app.config['SESSION_TYPE'] = 'redis'
    app.config['SESSION_REDIS'] = redis.from_url('redis://localhost:6379/5')

    from .routes.general_routes import general_bp
    app.register_blueprint(general_bp)

    socketio.init_app(app)

    app.debug = True
    app.config['SQLALCHEMY_DATABASE_URI'] = "MY DATABASE URI"
    app.config['SQLALCHEMY_ENGINE_OPTIONS'] = {
        'pool_size': 5,
        'max_overflow':15
    }

    from .models import db
    db.init_app(app)

    return app

Here's the application file:

import eventlet
eventlet.monkey_patch()

import psycogreen.eventlet
psycogreen.eventlet.patch_psycopg()

from app import create_app, socketio

from app.models import db

app = create_app(debug=True)

app.config["SQLALCHEMY_TRACK_MODIFICATIONS"] = False

@app.teardown_appcontext
def shutdown_session(exception=None):
    if exception is not None:
        print("teardown_appcontext: ",exception)

    db.session.remove()

if __name__ == '__main__':
    socketio.run(app, host='0.0.0.0')

Here's the connection logs:

sudo venv3.9/bin/gunicorn -w 2 --worker-class eventlet --bind 0.0.0.0:8590 myapp:app
[2023-03-19 14:30:57 -0400] [72418] [INFO] Starting gunicorn 20.1.0
[2023-03-19 14:30:57 -0400] [72418] [INFO] Listening at: http://0.0.0.0:8590 (72418)
[2023-03-19 14:30:57 -0400] [72418] [INFO] Using worker: eventlet
[2023-03-19 14:30:57 -0400] [72419] [INFO] Booting worker with pid: 72419
[2023-03-19 14:30:57 -0400] [72420] [INFO] Booting worker with pid: 72420
Server initialized for eventlet.
Server initialized for eventlet.
Server initialized for eventlet.
Server initialized for eventlet.
9vp6oJgrn-R4cHE_AAAA: Sending packet OPEN data {'sid': '9vp6oJgrn-R4cHE_AAAA', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
redis backend initialized.
9vp6oJgrn-R4cHE_AAAA: Received packet MESSAGE data 0
9vp6oJgrn-R4cHE_AAAA: Sending packet MESSAGE data 0{"sid":"6U7onoXME6OhJYfWAAAB"}
Invalid session 9vp6oJgrn-R4cHE_AAAA (further occurrences of this error will be logged with level INFO)
9vp6oJgrn-R4cHE_AAAA: Received packet CLOSE data 
nuaXJfV4RHTbicpbAAAC: Sending packet OPEN data {'sid': 'nuaXJfV4RHTbicpbAAAC', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
nuaXJfV4RHTbicpbAAAC: Received packet MESSAGE data 0
Invalid session nuaXJfV4RHTbicpbAAAC
nuaXJfV4RHTbicpbAAAC: Sending packet MESSAGE data 0{"sid":"I3XysLOSrYsziFoYAAAD"}
TCrMutgHFdx8xoD6AAAA: Sending packet OPEN data {'sid': 'TCrMutgHFdx8xoD6AAAA', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
redis backend initialized.
TCrMutgHFdx8xoD6AAAA: Received request to upgrade to websocket
Invalid session TCrMutgHFdx8xoD6AAAA (further occurrences of this error will be logged with level INFO)
TCrMutgHFdx8xoD6AAAA: Received packet MESSAGE data 0
TCrMutgHFdx8xoD6AAAA: Sending packet MESSAGE data 0{"sid":"shIRNlTTkXYvLHpAAAAB"}
TCrMutgHFdx8xoD6AAAA: Failed websocket upgrade, expected UPGRADE packet, received None instead.
TCrMutgHFdx8xoD6AAAA: Received packet CLOSE data 
SSIksTdkSFfH91psAAAC: Sending packet OPEN data {'sid': 'SSIksTdkSFfH91psAAAC', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
SSIksTdkSFfH91psAAAC: Received packet MESSAGE data 0
SSIksTdkSFfH91psAAAC: Sending packet MESSAGE data 0{"sid":"IcQkM6VHVqe931IdAAAD"}
Invalid session SSIksTdkSFfH91psAAAC
Wmy2-X5BtemjIuHWAAAE: Sending packet OPEN data {'sid': 'Wmy2-X5BtemjIuHWAAAE', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Invalid session Wmy2-X5BtemjIuHWAAAE
Wmy2-X5BtemjIuHWAAAE: Received request to upgrade to websocket
Wmy2-X5BtemjIuHWAAAE: Received packet MESSAGE data 0
Wmy2-X5BtemjIuHWAAAE: Sending packet MESSAGE data 0{"sid":"90uVsBl3WJyGz9x9AAAF"}
Wmy2-X5BtemjIuHWAAAE: Failed websocket upgrade, expected UPGRADE packet, received None instead.
Wmy2-X5BtemjIuHWAAAE: Received packet CLOSE data 
iuT1M5LK6BHlBkdwAAAG: Sending packet OPEN data {'sid': 'iuT1M5LK6BHlBkdwAAAG', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
iuT1M5LK6BHlBkdwAAAG: Received packet MESSAGE data 0
Invalid session iuT1M5LK6BHlBkdwAAAG
iuT1M5LK6BHlBkdwAAAG: Sending packet MESSAGE data 0{"sid":"ZwJqCRZ3LuDvwjAAAAAH"}
iuT1M5LK6BHlBkdwAAAG: Received request to upgrade to websocket
iuT1M5LK6BHlBkdwAAAG: Failed websocket upgrade, expected UPGRADE packet, received None instead.
MqWlDXJ20aTS_Dq5AAAE: Sending packet OPEN data {'sid': 'MqWlDXJ20aTS_Dq5AAAE', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
MqWlDXJ20aTS_Dq5AAAE: Received request to upgrade to websocket
Invalid session MqWlDXJ20aTS_Dq5AAAE
MqWlDXJ20aTS_Dq5AAAE: Received packet MESSAGE data 0
MqWlDXJ20aTS_Dq5AAAE: Sending packet MESSAGE data 0{"sid":"9eZ9vxuYsOE1U7XsAAAF"}
MqWlDXJ20aTS_Dq5AAAE: Failed websocket upgrade, expected UPGRADE packet, received None instead.
SskSnUz-a2K3iO-5AAAG: Sending packet OPEN data {'sid': 'SskSnUz-a2K3iO-5AAAG', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Invalid session SskSnUz-a2K3iO-5AAAG
SskSnUz-a2K3iO-5AAAG: Received request to upgrade to websocket
SskSnUz-a2K3iO-5AAAG: Received packet MESSAGE data 0
SskSnUz-a2K3iO-5AAAG: Sending packet MESSAGE data 0{"sid":"lyj18B55Jw6KNme2AAAH"}
SskSnUz-a2K3iO-5AAAG: Failed websocket upgrade, expected UPGRADE packet, received None instead.
SskSnUz-a2K3iO-5AAAG: Received packet CLOSE data 
tzv7EryYxQF1tiSJAAAI: Sending packet OPEN data {'sid': 'tzv7EryYxQF1tiSJAAAI', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
tzv7EryYxQF1tiSJAAAI: Received request to upgrade to websocket
Invalid session tzv7EryYxQF1tiSJAAAI
tzv7EryYxQF1tiSJAAAI: Received packet MESSAGE data 0
tzv7EryYxQF1tiSJAAAI: Sending packet MESSAGE data 0{"sid":"9vZT-kMRN3VLiNHWAAAJ"}
tzv7EryYxQF1tiSJAAAI: Failed websocket upgrade, expected UPGRADE packet, received None instead.
tzv7EryYxQF1tiSJAAAI: Received packet CLOSE data 
DejBCDNZWNN7bTn8AAAK: Sending packet OPEN data {'sid': 'DejBCDNZWNN7bTn8AAAK', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Invalid session DejBCDNZWNN7bTn8AAAK
DejBCDNZWNN7bTn8AAAK: Received packet MESSAGE data 0
DejBCDNZWNN7bTn8AAAK: Sending packet MESSAGE data 0{"sid":"I3IOScPBQzbA1adAAAAL"}
Invalid session DejBCDNZWNN7bTn8AAAK
Invalid session DejBCDNZWNN7bTn8AAAK
47_-GYeW_o-aj-V4AAAI: Sending packet OPEN data {'sid': '47_-GYeW_o-aj-V4AAAI', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
47_-GYeW_o-aj-V4AAAI: Received request to upgrade to websocket
47_-GYeW_o-aj-V4AAAI: Received packet MESSAGE data 0
47_-GYeW_o-aj-V4AAAI: Sending packet MESSAGE data 0{"sid":"SZaxSKH3uEqb3vlSAAAJ"}
Invalid session 47_-GYeW_o-aj-V4AAAI
47_-GYeW_o-aj-V4AAAI: Failed websocket upgrade, expected UPGRADE packet, received None instead.
JAMRPCjEXPLaC5KSAAAM: Sending packet OPEN data {'sid': 'JAMRPCjEXPLaC5KSAAAM', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Invalid session JAMRPCjEXPLaC5KSAAAM
JAMRPCjEXPLaC5KSAAAM: Received packet MESSAGE data 0
JAMRPCjEXPLaC5KSAAAM: Sending packet MESSAGE data 0{"sid":"-mTCaqkrkt_1mf-fAAAN"}
Invalid session JAMRPCjEXPLaC5KSAAAM
Invalid session JAMRPCjEXPLaC5KSAAAM
4bfoQ6LbOnhnG7H0AAAK: Sending packet OPEN data {'sid': '4bfoQ6LbOnhnG7H0AAAK', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
4bfoQ6LbOnhnG7H0AAAK: Received packet MESSAGE data 0
4bfoQ6LbOnhnG7H0AAAK: Sending packet MESSAGE data 0{"sid":"Q7Vh_DairYoxrbARAAAL"}
Invalid session 4bfoQ6LbOnhnG7H0AAAK
4bfoQ6LbOnhnG7H0AAAK: Received request to upgrade to websocket
4bfoQ6LbOnhnG7H0AAAK: Failed websocket upgrade, no PING packet
Invalid session 4bfoQ6LbOnhnG7H0AAAK
BYuhmnVVxNi2xNRxAAAO: Sending packet OPEN data {'sid': 'BYuhmnVVxNi2xNRxAAAO', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Invalid session BYuhmnVVxNi2xNRxAAAO
BYuhmnVVxNi2xNRxAAAO: Received packet MESSAGE data 0
BYuhmnVVxNi2xNRxAAAO: Sending packet MESSAGE data 0{"sid":"aQzjqht48iPrNaKEAAAP"}
Invalid session BYuhmnVVxNi2xNRxAAAO
Invalid session BYuhmnVVxNi2xNRxAAAO
aC-LLGdYoO6PpKSwAAAM: Sending packet OPEN data {'sid': 'aC-LLGdYoO6PpKSwAAAM', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Invalid session aC-LLGdYoO6PpKSwAAAM
aC-LLGdYoO6PpKSwAAAM: Received packet MESSAGE data 0
aC-LLGdYoO6PpKSwAAAM: Sending packet MESSAGE data 0{"sid":"uJJS-EzsUC0Bn-b-AAAN"}
Invalid session aC-LLGdYoO6PpKSwAAAM
Invalid session aC-LLGdYoO6PpKSwAAAM
nk0fM6D_edjHagvyAAAQ: Sending packet OPEN data {'sid': 'nk0fM6D_edjHagvyAAAQ', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
nk0fM6D_edjHagvyAAAQ: Received packet MESSAGE data 0
Invalid session nk0fM6D_edjHagvyAAAQ
nk0fM6D_edjHagvyAAAQ: Sending packet MESSAGE data 0{"sid":"Hj4qRa2bOqP9wTFBAAAR"}
Invalid session nk0fM6D_edjHagvyAAAQ
Invalid session nk0fM6D_edjHagvyAAAQ
df5ggUgc0DkVub2yAAAO: Sending packet OPEN data {'sid': 'df5ggUgc0DkVub2yAAAO', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
df5ggUgc0DkVub2yAAAO: Received packet MESSAGE data 0
df5ggUgc0DkVub2yAAAO: Sending packet MESSAGE data 0{"sid":"-0e7-X1uC47eMtvCAAAP"}
Invalid session df5ggUgc0DkVub2yAAAO
Invalid session df5ggUgc0DkVub2yAAAO
Invalid session df5ggUgc0DkVub2yAAAO
Dib0WeV_0OPIs67EAAAS: Sending packet OPEN data {'sid': 'Dib0WeV_0OPIs67EAAAS', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
^C[2023-03-19 14:31:25 -0400] [72418] [INFO] Handling signal: int
Dib0WeV_0OPIs67EAAAS: Received request to upgrade to websocket
Dib0WeV_0OPIs67EAAAS: Received packet MESSAGE data 0
Invalid session Dib0WeV_0OPIs67EAAAS
Dib0WeV_0OPIs67EAAAS: Sending packet MESSAGE data 0{"sid":"P-l7KYk63RmM3VnWAAAT"}
Dib0WeV_0OPIs67EAAAS: Failed websocket upgrade, expected UPGRADE packet, received None instead.
Invalid session Dib0WeV_0OPIs67EAAAS
[2023-03-19 14:31:25 -0400] [72419] [INFO] Worker exiting (pid: 72419)
[2023-03-19 14:31:25 -0400] [72420] [INFO] Worker exiting (pid: 72420)
[2023-03-19 14:31:25 -0400] [72418] [INFO] Shutting down: Master

[dMAC95]

In my production environment I run this setup with nginx.

Here's my configs:

sites-enabled app config:

server {
    listen 8081;
    server_name 192.168.1.149;

    location / {
        proxy_pass http://127.0.0.1:8090;
        proxy_set_header Host $host;
        proxy_set_header X-Real-IP $remote_addr;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    }

    location /socket.io/ {
        proxy_pass http://127.0.0.1:8090;
        proxy_http_version 1.1;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection "Upgrade";
        proxy_set_header Host $host;
        proxy_set_header X-Real-IP $remote_addr;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    }
}

nginx.conf:

worker_processes 1;

events {
    worker_connections 1024;
    accept_mutex off;
}

http {
    include mime.types;
    default_type application/octet-stream;
    access_log /var/log/nginx/access.log;
    error_log /var/log/nginx/error.log;
    proxy_temp_path /tmp;
    
    client_max_body_size 0;
    client_body_buffer_size 99M;

    upstream flask_socketio {
        ip_hash;
        server 192.168.1.149:8090;
    }

    server {
        listen 8081;

        location /socket.io {
            proxy_read_timeout 600s;
            proxy_pass http://flask_socketio;
            proxy_http_version 1.1;
            proxy_set_header Upgrade $http_upgrade;
            proxy_set_header Connection "upgrade";
            proxy_set_header Host $host;
            proxy_set_header X-Real-IP $remote_addr;
        }

        location / {
            proxy_read_timeout 600s;
            proxy_pass http://flask_socketio;
            proxy_http_version 1.1;
            proxy_set_header Host $host;
            proxy_set_header X-Real-IP $remote_addr;
        }
    }
}

[miguelgrinberg]

Are you reading the documentation? What you are doing is not supported. Gunicorn must always be started with one worker. https://flask-socketio.readthedocs.io/en/latest/deployment.html#gunicorn-web-server

[dMAC95]

That makes sense. Thankyou. I'll leave this up for anyone else trying to do the same lol.

[dMAC95]

You are a life saver dude. I was asking chat GPT about the issues and it kept giving me round about answers that made the fix seem possible with multiple gunicorn workers. If I didn't have chat gpt I probably would have read that opening documentation. I'll be more mindful about using chat gpt and it's limitations in the future.