search

miguelgrinberg / Flask-SocketIO

Socket.IO integration for Flask applications.
MIT License
5.36k stars 890 forks source link

Not firing events on server when using Blueprints #1201

Closed vijuarez closed 4 years ago

vijuarez commented 4 years ago

Your question I want to implement Socket.io on an application with many Blueprints, using 2 namespaces (for now). However, even when my client is connecting to the server, the server is refusing to fire the events.

Additional context I recently refractored from a non-blueprint architecture, where everything was working correctly. The changes are way too massive to properly debug on what changed and what not, however. I'm also using PeerJS on the client side for WebRTC, Socket.io was supposed to help as a "broker" here (alongside other things). However, I have tried in other blueprints where I'm not using PeerJS to no avail. I'm exclusively talking about the route that I need the most in this issue, so I inform about PeerJS just in case.

Project Structure -> app --> blueprints ----> people ------ __init__.py ------ people.html ------ people.js ----> (...) -- __init__.py -- config.py project.py

There are many other files ommited for brevity.

Code Here are the relevant snippets from the code. I don't want to post the whole thing, but I can provide access to the code if needed.

project.py

from app import create_app, SCKT

DEBUG = True

app = create_app(debug=DEBUG)

if __name__ == '__main__':
    SCKT.run(app, debug=DEBUG)

app/__init__.py

from gevent import monkey
monkey.patch_all()

from flask import Flask
from flask_migrate import Migrate
from flask_sqlalchemy import SQLAlchemy

from .config import config_all, get_socketio

SCKT= get_socketio()

def create_app(debug=False) -> Flask:
    """Create an application."""
    app = Flask(__name__, template_folder='templates', static_folder='static')
    app.debug = debug

    config_all(app, debug)

    DB = SQLAlchemy(app)
    migrate = Migrate(app, DB)

    # Many other blueprints initiated here

    from .blueprints import people
    app.register_blueprint(people.PP)
    people.PP_DB.init_app(app)
    people.PP_BA.init_app(app)
    SCKT.on_event('new_friend', people.new_friend, namespace="/people")

    SCKT.init_app(app)

    return app

app/config.py

from dotenv import load_dotenv
from engineio.payload import Payload
from flask import Flask
from flask_socketio import SocketIO
import sqreen
import os

load_dotenv('.env')

def get_socketio() -> SocketIO:
    # Returns an unitialized SocketIO client
    return SocketIO(message_queue=os.environ.get('REDIS_URL'), async_mode='gevent', engineio_logger=True)

def config_all(app: Flask, debug=False):
    # Add configuration and keys to the app
    app.config['REDIS_URL'] = os.environ.get('REDIS_URL')

app/blueprints/people/__init__.py

from flask import Blueprint
from flask_basicauth import BasicAuth
from flask_sqlalchemy import SQLAlchemy

PP_BA = BasicAuth()
PP_DB = SQLAlchemy()
PP = Blueprint('people', __name__, template_folder='templates', static_folder="static", static_url_path='/static/people')

# Many routes declared here
# Some socket events should happen as well, I haven't got that far though

def new_friend(sid):
    print('new friend', sid) # This never gets called
    emit('new_peer_reg', {"peer_id": sid}, broadcast=True)

people.js


const peer_self = new Peer(); // PeerJS client starting BEFORE Socket.io

const init_app = () => {
    // ...
    const socket = io('/people');

    peer_self.on('open', (id) => {
        console.log('we connected');
        socket.emit('new_friend', id);
    });
   // ..
}

Runtime Enviroment

I'm running the server on gunicorn with gevent. It should eventually go up into Heroku.

gunicorn -k geventwebsocket.gunicorn.workers.GeventWebSocketWorker -w 1 ufoshock:app

Some relevant versions:

Flask_SocketIO=="4.2.1"
gevent=="1.4.0"
Flask=="1.1.1"
redis=="3.4.1"
gevent-websocket=="0.10.1"
gunicorn=="20.0.0"
python_engineio=="3.11.2"
socketio=="2.2.0"
peerjs=="0.3.20"
> python --version
Python 3.8.1

Logs for Server

[2020-03-04 13:41:13 -0300] [3835] [INFO] Starting gunicorn 20.0.0
[2020-03-04 13:41:13 -0300] [3835] [INFO] Listening at: http://127.0.0.1:8000 (3835)
[2020-03-04 13:41:13 -0300] [3835] [INFO] Using worker: geventwebsocket.gunicorn.workers.GeventWebSocketWorker
[2020-03-04 13:41:13 -0300] [3838] [INFO] Booting worker with pid: 3838
Server initialized for gevent.
Server initialized for gevent.
c7566d95eac44152aceaf475c8754303: Sending packet OPEN data {'sid': 'c7566d95eac44152aceaf475c8754303', 'upgrades': ['websocket'], 'pingTimeout': 60000, 'pingInterval': 25000}
c7566d95eac44152aceaf475c8754303: Sending packet MESSAGE data 0
c7566d95eac44152aceaf475c8754303: Received packet MESSAGE data 0/people,
c7566d95eac44152aceaf475c8754303: Sending packet MESSAGE data 0/people
c7566d95eac44152aceaf475c8754303: Received request to upgrade to websocket
c7566d95eac44152aceaf475c8754303: Received packet MESSAGE data 2/people,["new_friend","9sjg7au965b00000"]
c7566d95eac44152aceaf475c8754303: Upgrade to websocket successful
c7566d95eac44152aceaf475c8754303: Received packet PING data None
c7566d95eac44152aceaf475c8754303: Sending packet PONG data None

Logging from the client

socket.io-client:url protocol-less url 127.0.0.1:8000/people +0ms
index.js:83 socket.io-client:url parse http://127.0.0.1:8000/people +4ms
index.js:83 socket.io-client new io instance for http://127.0.0.1:8000/people +0ms
index.js:83 socket.io-client:manager readyState closed +0ms
index.js:83 socket.io-client:manager opening http://127.0.0.1:8000/people +14ms
index.js:83 engine.io-client:socket creating transport "polling" +0ms
index.js:83 engine.io-client:polling polling +0ms
index.js:83 engine.io-client:polling-xhr xhr poll +0ms
index.js:83 engine.io-client:polling-xhr xhr open GET: http://127.0.0.1:8000/socket.io/?EIO=3&transport=polling&t=N2cR4ei +5ms
index.js:83 engine.io-client:polling-xhr xhr data null +5ms
index.js:83 engine.io-client:socket setting transport polling +33ms
index.js:83 socket.io-client:manager connect attempt will timeout after 20000 +44ms
index.js:83 socket.io-client:manager readyState opening +3ms
painter.js?q=1583339291:638 we connected
index.js:83 engine.io-client:polling polling got data ArrayBuffer(119) +10s
index.js:83 engine.io-client:socket socket receive: type "open", data "{"sid":"c7566d95eac44152aceaf475c8754303","upgrades":["websocket"],"pingTimeout":60000,"pingInterval":25000}" +10s
index.js:83 engine.io-client:socket socket open +13ms
index.js:83 socket.io-client:manager open +10s
index.js:83 socket.io-client:manager cleanup +6ms
index.js:83 socket.io-client:socket transport is open - connecting +0ms
index.js:83 socket.io-client:manager writing packet {"type":0,"nsp":"/people"} +3ms
index.js:83 socket.io-parser encoding packet {"type":0,"nsp":"/people"} +0ms
index.js:83 socket.io-parser encoded {"type":0,"nsp":"/people"} as 0/people, +1ms
index.js:83 engine.io-client:socket flushing 1 packets in socket +45ms
index.js:83 engine.io-client:polling-xhr xhr open POST: http://127.0.0.1:8000/socket.io/?EIO=3&transport=polling&t=N2cR6_S&sid=c7566d95eac44152aceaf475c8754303 +10s
index.js:83 engine.io-client:polling-xhr xhr data 10:40/people, +8ms
index.js:83 engine.io-client:socket starting upgrade probes +25ms
index.js:83 engine.io-client:socket probing transport "websocket" +18ms
index.js:83 engine.io-client:socket creating transport "websocket" +3ms
index.js:83 engine.io-client:socket socket receive: type "message", data "0" +12ms
index.js:83 socket.io-parser decoded 0 as {"type":0,"nsp":"/"} +90ms
index.js:83 engine.io-client:polling polling +151ms
index.js:83 engine.io-client:polling-xhr xhr poll +75ms
index.js:83 engine.io-client:polling-xhr xhr open GET: http://127.0.0.1:8000/socket.io/?EIO=3&transport=polling&t=N2cR70n&sid=c7566d95eac44152aceaf475c8754303 +3ms
index.js:83 engine.io-client:polling-xhr xhr data null +3ms
favicon.ico:1 GET http://127.0.0.1:8000/favicon.ico 404 (NOT FOUND)
index.js:83 engine.io-client:polling polling got data ArrayBuffer(12) +57ms
index.js:83 engine.io-client:socket socket receive: type "message", data "0/people" +90ms
index.js:83 socket.io-parser decoded 0/people as {"type":0,"nsp":"/people"} +71ms
index.js:83 socket.io-client:manager writing packet {"type":2,"data":["new_friend","9sjg7au965b00000"],"options":{"compress":true},"nsp":"/people"} +178ms
index.js:83 socket.io-parser encoding packet {"type":2,"data":["new_friend","9sjg7au965b00000"],"options":{"compress":true},"nsp":"/people"} +9ms
index.js:83 socket.io-parser encoded {"type":2,"data":["new_friend","9sjg7au965b00000"],"options":{"compress":true},"nsp":"/people"} as 2/people,["new_friend","9sjg7au965b00000"] +7ms
index.js:83 engine.io-client:socket flushing 1 packets in socket +24ms
index.js:83 engine.io-client:polling-xhr xhr open POST: http://127.0.0.1:8000/socket.io/?EIO=3&transport=polling&t=N2cR72C&sid=c7566d95eac44152aceaf475c8754303 +87ms
index.js:83 engine.io-client:polling-xhr xhr data 43:42/people,["new_friend","9sjg7au965b00000"] +14ms
index.js:83 engine.io-client:polling polling +69ms
index.js:83 engine.io-client:polling-xhr xhr poll +26ms
index.js:83 engine.io-client:polling-xhr xhr open GET: http://127.0.0.1:8000/socket.io/?EIO=3&transport=polling&t=N2cR72t&sid=c7566d95eac44152aceaf475c8754303 +3ms
index.js:83 engine.io-client:polling-xhr xhr data null +4ms
index.js:83 engine.io-client:socket probe transport "websocket" opened +85ms
index.js:83 engine.io-client:socket probe transport "websocket" pong +31ms
index.js:83 engine.io-client:socket pausing current transport "polling" +10ms
index.js:83 engine.io-client:polling we are currently polling - waiting to pause +91ms
index.js:83 engine.io-client:polling polling got data ArrayBuffer(4) +6ms
index.js:83 engine.io-client:socket socket receive: type "noop", data "undefined" +14ms
index.js:83 engine.io-client:polling pre-pause polling complete +3ms
index.js:83 engine.io-client:polling paused +1ms
index.js:83 engine.io-client:socket changing transport and sending upgrade packet +3ms
index.js:83 engine.io-client:socket setting transport websocket +1ms
index.js:83 engine.io-client:socket clearing existing transport polling +1ms
index.js:83 engine.io-client:polling ignoring poll - transport state "paused" +4ms
index.js:83 engine.io-client:socket writing ping packet - expecting pong within 60000ms +25s
index.js:83 engine.io-client:socket flushing 1 packets in socket +3ms
index.js:83 engine.io-client:socket socket receive: type "pong", data "undefined" +7ms

The logs are quite verbose, but we can clearly see that the client and server get connected, and then the client sends a message, which is recieved by the server. However, we get no callback on the server, only PINGing.

miguelgrinberg commented 4 years ago

Do you see any difference in behavior if you connect from your client directly with WebSocket?

vijuarez commented 4 years ago

Hi, thanks for quick reply. I don't see any difference, I'm assuming Socket.io is honoring my request, which seems to be the case based on the logs.

Code changes app/blueprints/people/people.js

const socket = io('/people', {
        transports: ['websocket']
      });

Client Log

socket.io-client:url protocol-less url 127.0.0.1:8000/people +0ms
index.js:83 socket.io-client:url parse http://127.0.0.1:8000/people +8ms
index.js:83 socket.io-client new io instance for http://127.0.0.1:8000/people +0ms
index.js:83 socket.io-client:manager readyState closed +0ms
index.js:83 socket.io-client:manager opening http://127.0.0.1:8000/people +4ms
index.js:83 engine.io-client:socket creating transport "websocket" +0ms
index.js:83 engine.io-client:socket setting transport websocket +13ms
index.js:83 socket.io-client:manager connect attempt will timeout after 20000 +19ms
index.js:83 socket.io-client:manager readyState opening +4ms
painter.js?q=1583366338:640 we connected
favicon.ico:1 GET http://127.0.0.1:8000/favicon.ico 404 (NOT FOUND)
index.js:83 engine.io-client:socket socket receive: type "open", data "{"sid":"da261d8ea04a4a64b2e51202cf5ceee6","upgrades":[],"pingTimeout":60000,"pingInterval":25000}" +12s
index.js:83 engine.io-client:socket socket open +5ms
index.js:83 socket.io-client:manager open +12s
index.js:83 socket.io-client:manager cleanup +3ms
index.js:83 socket.io-client:socket transport is open - connecting +0ms
index.js:83 socket.io-client:manager writing packet {"type":0,"nsp":"/people"} +7ms
index.js:83 socket.io-parser encoding packet {"type":0,"nsp":"/people"} +0ms
index.js:83 socket.io-parser encoded {"type":0,"nsp":"/people"} as 0/people, +3ms
index.js:83 engine.io-client:socket flushing 1 packets in socket +32ms
index.js:83 engine.io-client:socket socket receive: type "message", data "0" +12ms
index.js:83 socket.io-parser decoded 0 as {"type":0,"nsp":"/"} +19ms
index.js:83 engine.io-client:socket socket receive: type "message", data "0/people" +7ms
index.js:83 socket.io-parser decoded 0/people as {"type":0,"nsp":"/people"} +8ms
index.js:83 socket.io-client:manager writing packet {"type":2,"data":["new_friend","ycwctp7zsf000000"],"options":{"compress":true},"nsp":"/people"} +53ms
index.js:83 socket.io-parser encoding packet {"type":2,"data":["new_friend","ycwctp7zsf000000"],"options":{"compress":true},"nsp":"/people"} +14ms
index.js:83 socket.io-parser encoded {"type":2,"data":["new_friend","ycwctp7zsf000000"],"options":{"compress":true},"nsp":"/people"} as 2/people,["new_friend","ycwctp7zsf000000"] +0ms
index.js:83 engine.io-client:socket flushing 1 packets in socket +654ms
index.js:83 engine.io-client:socket writing ping packet - expecting pong within 60000ms +25s
index.js:83 engine.io-client:socket flushing 1 packets in socket +3ms
index.js:83 engine.io-client:socket socket receive: type "pong", data "undefined" +4ms

Server Log

[2020-03-04 21:02:27 -0300] [1974] [INFO] Starting gunicorn 20.0.0
[2020-03-04 21:02:27 -0300] [1974] [INFO] Listening at: http://127.0.0.1:8000 (1974)
[2020-03-04 21:02:27 -0300] [1974] [INFO] Using worker: geventwebsocket.gunicorn.workers.GeventWebSocketWorker
[2020-03-04 21:02:27 -0300] [1977] [INFO] Booting worker with pid: 1977
Server initialized for gevent.
Server initialized for gevent.
da261d8ea04a4a64b2e51202cf5ceee6: Sending packet OPEN data {'sid': 'da261d8ea04a4a64b2e51202cf5ceee6', 'upgrades': [], 'pingTimeout': 60000, 'pingInterval': 25000}
da261d8ea04a4a64b2e51202cf5ceee6: Sending packet MESSAGE data 0
da261d8ea04a4a64b2e51202cf5ceee6: Received request to upgrade to websocket
da261d8ea04a4a64b2e51202cf5ceee6: Upgrade to websocket successful
da261d8ea04a4a64b2e51202cf5ceee6: Received packet MESSAGE data 0/people,
da261d8ea04a4a64b2e51202cf5ceee6: Sending packet MESSAGE data 0/people
da261d8ea04a4a64b2e51202cf5ceee6: Received packet MESSAGE data 2/people,["new_friend","ycwctp7zsf000000"]
da261d8ea04a4a64b2e51202cf5ceee6: Received packet PING data None
da261d8ea04a4a64b2e51202cf5ceee6: Sending packet PONG data None
miguelgrinberg commented 4 years ago

That was the only potential problem I could think of. Since that is not the problem, my guess is that ths is somehow a bug in your application. If you can strip the app down to the bare minimum and share it I can debug it here. If you want to debug it on your side, what I would make sure first is that the event handler for your new_friend event is correctly registered.

vijuarez commented 4 years ago

Hello, thanks for the help! While preparing a bare minimum version of the problem, I stumbled upon a solution and yet another problem.

Solution

I managed to get the events firing in the server by initializing SocketIO with the app before registering the events. This is extremely puzzling to me, because it's not how it's done in the Flask-SocketIO-Chat demo, which worked flawlessly on my enviroment.

app/__init__.py

def create_app(debug=False) -> Flask:
    """Create an application."""
    app = Flask(__name__)
    app.debug = debug

    config_all(app, debug)

    SCKT.init_app(app)

    from .blueprints import people
    app.register_blueprint(people.PP)
    SCKT.on_event('new_friend', people.new_friend, namespace="/people")

    return app

New Problem

However, this breakthrough was only a fleeting moment of happiness. I can't get the server to answer back with an emit. I'm not 100% sure if I should call via the emit function or method, but I've tried with both individually and at the same time to no avail.

app/blueprints/people/__init__.py

def new_friend(sid):
    print('new friend', sid) # This is now firing
    emit('new_friend_reg', {"peer_id": sid}, namespace="/people", broadcast=True, include_self=True)
    SCKT.emit('new_friend_reg', {"peer_id": sid}, namespace="/people")

Client Log

index.js:83 socket.io-client:url protocol-less url 127.0.0.1:8000/people +0ms
index.js:83 socket.io-client:url parse http://127.0.0.1:8000/people +1ms
index.js:83 socket.io-client new io instance for http://127.0.0.1:8000/people +0ms
index.js:83 socket.io-client:manager readyState closed +0ms
index.js:83 socket.io-client:manager opening http://127.0.0.1:8000/people +0ms
index.js:83 engine.io-client:socket creating transport "websocket" +0ms
index.js:83 engine.io-client:socket setting transport websocket +3ms
index.js:83 socket.io-client:manager connect attempt will timeout after 20000 +6ms
index.js:83 socket.io-client:manager readyState opening +1ms
index.js:83 engine.io-client:socket socket receive: type "open", data "{"sid":"fb9299360b4e4e3d911c222499a45559","upgrades":[],"pingTimeout":60000,"pingInterval":25000}" +76ms
index.js:83 engine.io-client:socket socket open +12ms
index.js:83 socket.io-client:manager open +87ms
index.js:83 socket.io-client:manager cleanup +0ms
index.js:83 socket.io-client:socket transport is open - connecting +0ms
index.js:83 socket.io-client:manager writing packet {"type":0,"nsp":"/people"} +2ms
index.js:83 socket.io-parser encoding packet {"type":0,"nsp":"/people"} +0ms
index.js:83 socket.io-parser encoded {"type":0,"nsp":"/people"} as 0/people, +1ms
index.js:83 engine.io-client:socket flushing 1 packets in socket +5ms
index.js:83 engine.io-client:socket socket receive: type "message", data "0" +19ms
index.js:83 socket.io-parser decoded 0 as {"type":0,"nsp":"/"} +24ms
index.js:83 engine.io-client:socket socket receive: type "message", data "0/people" +10ms
index.js:83 socket.io-parser decoded 0/people as {"type":0,"nsp":"/people"} +7ms
favicon.ico:1 Failed to load resource: the server responded with a status of 404 (NOT FOUND)
painter.js:12 we connected
index.js:83 socket.io-client:manager writing packet {"type":2,"data":["new_friend","jt5o48zsl2c00000"],"options":{"compress":true},"nsp":"/people"} +1s
index.js:83 socket.io-parser encoding packet {"type":2,"data":["new_friend","jt5o48zsl2c00000"],"options":{"compress":true},"nsp":"/people"} +1s
index.js:83 socket.io-parser encoded {"type":2,"data":["new_friend","jt5o48zsl2c00000"],"options":{"compress":true},"nsp":"/people"} as 2/people,["new_friend","jt5o48zsl2c00000"] +1ms
index.js:83 engine.io-client:socket flushing 1 packets in socket +1s
index.js:83 engine.io-client:socket writing ping packet - expecting pong within 60000ms +24s
index.js:83 engine.io-client:socket flushing 1 packets in socket +7ms
index.js:83 engine.io-client:socket socket receive: type "pong", data "undefined" +6ms

Server Log

[2020-03-05 11:52:25 -0300] [20195] [INFO] Starting gunicorn 20.0.0
[2020-03-05 11:52:25 -0300] [20195] [INFO] Listening at: http://127.0.0.1:8000 (20195)
[2020-03-05 11:52:25 -0300] [20195] [INFO] Using worker: geventwebsocket.gunicorn.workers.GeventWebSocketWorker
[2020-03-05 11:52:25 -0300] [20198] [INFO] Booting worker with pid: 20198
Server initialized for gevent.
Server initialized for gevent.
fb9299360b4e4e3d911c222499a45559: Sending packet OPEN data {'sid': 'fb9299360b4e4e3d911c222499a45559', 'upgrades': [], 'pingTimeout': 60000, 'pingInterval': 25000}
fb9299360b4e4e3d911c222499a45559: Sending packet MESSAGE data 0
fb9299360b4e4e3d911c222499a45559: Received request to upgrade to websocket
fb9299360b4e4e3d911c222499a45559: Upgrade to websocket successful
fb9299360b4e4e3d911c222499a45559: Received packet MESSAGE data 0/people,
fb9299360b4e4e3d911c222499a45559: Sending packet MESSAGE data 0/people
fb9299360b4e4e3d911c222499a45559: Received packet MESSAGE data 2/people,["new_friend","jt5o48zsl2c00000"]
new friend jt5o48zsl2c00000
fb9299360b4e4e3d911c222499a45559: Received packet PING data None
fb9299360b4e4e3d911c222499a45559: Sending packet PONG data None

Bare Minimum Version

I've uploaded a bare minimum version of my problem here. Please take a look.

miguelgrinberg commented 4 years ago

You have to narrow the problem down. For example, does it work if you remove the message queue?

Regarding the first problem I'm really at a loss. The events should register before or after the init_app function is called, and as you say my chat example registers them before.

quiddihub commented 4 years ago

This looks exactly the same as issue #1151. Do you absolutely require the message_queue option in the object creation? If for any reason comms with the Redis server are interrupted (might also manifest itself for other reasons) then the server fails to send messages in the way you describe.