Flask Socketio upgrade failing in production -- "Invalid websocket upgrade"

[levin-h]

Hi all,
I am quite lost when it comes to deploying my websocket implementation to production.
Namely the production server is failing to upgrade to websocket with error log "Invalid websocket upgrade".
In contrast, everything works perfectly fine on my localhost.

I found similar issues within the discussions already, but none of the solution solved my problems.

Here is what I do:

1. Server Side (app.py)

import asyncio
import os, sys
import threading
import uuid
import datetime
from distutils.util import strtobool
import numpy as np

from flask import Flask, request, jsonify, abort, send_file
from flask_cors import CORS
from flask_sqlalchemy import SQLAlchemy
from sqlalchemy import desc

from flask_migrate import Migrate

from flask_jwt_extended import create_access_token
from flask_jwt_extended import get_jwt_identity
from flask_jwt_extended import jwt_required
from flask_jwt_extended import verify_jwt_in_request
from flask_jwt_extended import JWTManager
from flask_socketio import SocketIO, emit, join_room, leave_room

app = Flask(__name__)
CORS(app)

app.config["SECRET_KEY"] = os.environ.get("SECRET_KEY")
app.config["SQLALCHEMY_DATABASE_URI"] = os.environ.get(
    "EVENTAPP_DATABASE_URL", "sqlite:///database.db"
)
app.config["SQLALCHEMY_TRACK_MODIFICATIONS"] = strtobool(
    os.environ.get("SQLALCHEMY_TRACK_MODIFICATIONS", "False")
)

db.init_app(app)
migrate = Migrate(app, db)

jwt = JWTManager(app)

socketio = SocketIO(app, logger=True, engineio_logger=True, cors_allowed_origins="*")#, message_queue='redis://')

@socketio.on("connect", namespace='/websocket_dynamic_think_tanks')
def connected():
    print("client connected", request.sid)
    emit("connect_response", {"client_id": request.sid})

@socketio.on("disconnect", namespace='/websocket_dynamic_think_tanks')
def disconnected():
    print("client disconnected", request.sid)

@socketio.on("publish_message", namespace='/websocket_dynamic_think_tanks')
def websocket_publish_message(data):
    message = data['message']
    emit("publish_message_response", data)


@socketio.on("join_room", namespace='/websocket_dynamic_think_tanks')
def websocket_join_room(data):
    join_room(data['room_id'])
    emit("join_room_response", {"room_id": data['room_id']})

@socketio.on("leave_room", namespace='/websocket_dynamic_think_tanks')
def websocket_leave_room(data):
    leave_room(data['room_id'])
    emit("leave_room_response", {"room_id": data['room_id']})


if __name__ == "__main__":
    # start flask server
    socketio.run(app,host="0.0.0.0", port=5020, debug=True)

2. requirements.txt:

Flask==2.2.5
flask-cors==4.0.0
flask-jwt-extended==4.3.1
flask_migrate==4.0.5
flask_socketio==5.3.6
flask_sqlalchemy==3.1.1
flask_sse==1.0.0
gunicorn==21.2.0
numpy==1.21.6
psycopg2==2.9.9
requests==2.31.0
werkzeug==3.0.0```

3. Run command:
```powershell
gunicorn --bind 0.0.0.0:5020 -- timeout 600 --worker-class eventlet -w 1 wsgi:app

4. Client side (for testing):

import socketio

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

#request to localhost
#sio.connect("http://localhost:5020", transports=['websocket'], namespaces=['/websocket_dynamic_think_tanks'])

#request to server
sio.connect("https://backend-service-test.some-domain.com", transports=['websocket'], namespaces=['/websocket_dynamic_think_tanks'])

print(sio.sid)

@sio.on('connect_response')
def response(data):
    print('test')
    print(data)
    sio.disconnect()
    exit(0)

Finally, this is what I get when running the test client's request:
1. Request to https://backend-service-test.some-domain.com

• Client logs:

Traceback (most recent call last):
  File "/home/levin/network_circle/small_programs/python/websocket/websocket5/testConnection.py", line 6, in <module>
    sio.connect("https://backend-service-test.some-domain.com", transports=['websocket'], namespaces=['/websocket_dynamic_think_tanks'])
  File "/home/levin/programs_local/anaconda3/envs/testWesocket4/lib/python3.9/site-packages/socketio/client.py", line 338, in connect
    raise exceptions.ConnectionError(exc.args[0]) from None
socketio.exceptions.ConnectionError: Connection error

• Server logs:

Invalid websocket upgrade

2. Request to https://backend-service-test.some-domain.com (if transports is not explicitly specified in client request)

• Client logs:

Polling connection accepted with {'sid': '9C8eDo18gklNfcXGAAAC', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Engine.IO connection established
Sending packet MESSAGE data 0/websocket_dynamic_think_tanks,{}
Attempting WebSocket upgrade to wss://backend-service-test.some-domain.com/socket.io/?transport=websocket&EIO=4
WebSocket upgrade failed: connection error
Sending polling GET request to https://backend-service-test.some-domain.com/socket.io/?transport=polling&EIO=4&sid=9C8eDo18gklNfcXGAAAC
Sending packet CLOSE data None
Engine.IO connection dropped
Traceback (most recent call last):
  File "/home/levin/network_circle/small_programs/python/websocket/websocket5/testConnection.py", line 6, in <module>
    sio.connect("https://backend-service-test.networkcircle.com", namespaces=['/websocket_dynamic_think_tanks'])
  File "/home/levin/programs_local/anaconda3/envs/testWesocket4/lib/python3.9/site-packages/socketio/client.py", line 347, in connect
    raise exceptions.ConnectionError(
socketio.exceptions.ConnectionError: One or more namespaces failed to connect

• Server logs:

9C8eDo18gklNfcXGAAAC: Sending packet OPEN data {'sid': '9C8eDo18gklNfcXGAAAC', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
9C8eDo18gklNfcXGAAAC: Received packet MESSAGE data 0/websocket_dynamic_think_tanks,{}
emitting event "connect_response" to WuAOMROdqbb_eRuwAAAD [/websocket_dynamic_think_tanks]
9C8eDo18gklNfcXGAAAC: Sending packet MESSAGE data 2/websocket_dynamic_think_tanks,["connect_response",{"client_id":"WuAOMROdqbb_eRuwAAAD"}]
9C8eDo18gklNfcXGAAAC: Sending packet MESSAGE data 0/websocket_dynamic_think_tanks,{"sid":"WuAOMROdqbb_eRuwAAAD"}

3. Verification that everything is working when running the app.py on localhost (transports specified explicitly):

• Client logs:

Attempting WebSocket connection to ws://localhost:5020/socket.io/?transport=websocket&EIO=4
WebSocket connection accepted with {'sid': 'UY9X-PKOPzRd6uvRAAAb', 'upgrades': [], 'pingTimeout': 20000, 'pingInterval': 25000}
Engine.IO connection established
Sending packet MESSAGE data 0/websocket_dynamic_think_tanks,{}
Received packet MESSAGE data 2/websocket_dynamic_think_tanks,["connect_response",{"client_id":"fo4rvtWp6_sSO0NOAAAc"}]
Received event "connect_response" [/websocket_dynamic_think_tanks]
Received packet MESSAGE data 0/websocket_dynamic_think_tanks,{"sid":"fo4rvtWp6_sSO0NOAAAc"}
Namespace /websocket_dynamic_think_tanks is connected

• Server logs:

UY9X-PKOPzRd6uvRAAAb: Received request to upgrade to websocket
UY9X-PKOPzRd6uvRAAAb: Upgrade to websocket successful
UY9X-PKOPzRd6uvRAAAb: Received packet MESSAGE data 0/websocket_dynamic_think_tanks,{}
emitting event "connect_response" to fo4rvtWp6_sSO0NOAAAc [/websocket_dynamic_think_tanks]
UY9X-PKOPzRd6uvRAAAb: Sending packet MESSAGE data 2/websocket_dynamic_think_tanks,["connect_response",{"client_id":"fo4rvtWp6_sSO0NOAAAc"}]
UY9X-PKOPzRd6uvRAAAb: Sending packet MESSAGE data 0/websocket_dynamic_think_tanks,{"sid":"fo4rvtWp6_sSO0NOAAAc"}

Thanks a lot for your help already.

Best,

Levin

[miguelgrinberg]

Your client and server logs under section 1 above are incomplete. Please provide the full logs for both sides.

[levin-h]

Thanks a lot for the quick reqply.
Here is the complete server log related to section 1 (I also assumed to have get more, but that is all what the docker container prints out):
Server Log:

backend-service-test_1            | 2023-10-11T15:09:10.765843811Z [2023-10-11 15:09:10 +0000] [1] [INFO] Starting gunicorn 21.2.0
backend-service-test_1            | 2023-10-11T15:09:10.766881369Z [2023-10-11 15:09:10 +0000] [1] [INFO] Listening at: http://0.0.0.0:5020 (1)
backend-service-test_1            | 2023-10-11T15:09:10.767026639Z [2023-10-11 15:09:10 +0000] [1] [INFO] Using worker: eventlet
backend-service-test_1            | 2023-10-11T15:09:10.885067703Z [2023-10-11 15:09:10 +0000] [6] [INFO] Booting worker with pid: 6
backend-service-test_1            | 2023-10-11T15:09:19.183504174Z Server initialized for eventlet.
backend-service-test_1            | 2023-10-11T15:10:55.697490105Z Invalid websocket upgrade (further occurrences of this error will be logged with level INFO)

Client Log:

Attempting WebSocket connection to wss://backend-service-test.some-domain.com/socket.io/?transport=websocket&EIO=4
Traceback (most recent call last):
  File "/home/levin/network_circle/small_programs/python/websocket/websocket5/testConnection.py", line 6, in <module>
    sio.connect("https://backend-service-test.some-domain.com", transports=['websocket'], namespaces=['/websocket_dynamic_think_tanks'])
  File "/home/levin/programs_local/anaconda3/envs/testWesocket4/lib/python3.9/site-packages/socketio/client.py", line 338, in connect
    raise exceptions.ConnectionError(exc.args[0]) from None
socketio.exceptions.ConnectionError: Connection error

[miguelgrinberg]

I'm not sure there is going to be additional info, but you should add the access log to your Gunicorn. Right now you only have Socket/Engine.IO but nothing from the HTTP layer.

[levin-h]

Ah, I see, true that.
On the http layer, I get the following (If I understood it correctly; Please ignore the time, I just made a test request right now again, to double check if this log entry indeed corresponds to the corresponding request):
212.114.128.50 - - [11/Oct/2023:18:06:01 +0200] "GET /socket.io/?transport=websocket&EIO=4&t=1697040361.2302146 HTTP/1.1" 400 6086 "-" "-"

[miguelgrinberg]

Do you have anything between the client and the Gunicorn server? Maybe nginx? If you do, you may have an issue in the intermediary component, possibly that it does not forward standard headers that come with a websocket upgrade request. See https://github.com/miguelgrinberg/python-engineio/blob/main/src/engineio/server.py#L256-L257, this is the condition that is False in your case. This should evaluate to true for a successful connection.

[levin-h]

Thank you for that hint.
I asked my provider, and indeed, there is an Apache/2.4.38 server in front of the gunicorn server.
I am now researching on how to ProxyPass websocket upgrade requests here.

[levin-h]

Hi all,
again, thanks Miguel for your hints and help. The issue was indeed the Apache server serving as a Reverse Proxy in front of the backend.
The solution to get things working was to change the Apache configuration (here for Apache/2.4.38):

1. Enable modules proxy, proxy_http (only if also serving as http reverse proxy), proxy_wstunnel, and rewrite (to rewrite the request)

a2enmod proxy proxy_http proxy_wstunnel rewrite

2. Rewrite the request and forward websocket and http requests (e.g., in /etc/apache2/sites-enabled/000-default.conf):

#Rewrite Websocket request
  RewriteEngine on
  RewriteCond %{QUERY_STRING} transport=polling
  RewriteRule /(.*)$ http://127.0.0.1:5001/$1 [P]

#Forward Websocket request to local gunicorn server running at port 5001
  ProxyPass /socket.io/ ws://127.0.0.1:5001/socket.io/
  ProxyPassReverse /socket.io/ ws://127.0.0.1:5001/socket.io/  

#Forward Http request to local gunicorn server running at port 5001
ProxyPass / http://127.0.0.1:5001/
ProxyPassReverse / http://127.0.0.1:5001/

3. Restart apache server

/etc/init.d/apache2 restart