sid's don't match

[cbasavaraj]

Hi Miguel,
I have a flask-socketio server which must communicate with web browsers (JavaScript) as well as an API for mobile users. In order to test the API socketio functions, I've written a small python-socketio client. But the sid shown in this client is not the same as the sid reported on the server. To make it clearer:

Server side blueprint for API:

"""SocketIO Events."""

import logging

from flask import request, session

from app import socketio, redis_store


logger = logging.getLogger(__name__)


@socketio.on('connect', namespace='/api')
def connect():
    """Log connect."""
    logger.info(f"Connect from api: {request.sid}")
    session['room'] = request.sid


@socketio.on('disconnect', namespace='/api')
def disconnect():
    """Log disconnect."""
    logger.info(f"Disconn from api: {session.get('room')}")


@socketio.on('join', namespace='/api')
def join(data):
    """Join with id."""
    id = data['id']
    room = session.setdefault('room', request.sid)
    logger.info(f"user_{id} has joined: {room}")

Client simulation:

"""Simulate a mobile app user."""

import requests
import json

import socketio

import logging

from config import ServerConfig


logging.basicConfig(level=logging.INFO,
                    format="[%(asctime)s] %(levelname)s %(name)-32s "
                           "%(message)s")

logging.getLogger('socketio').setLevel(logging.WARNING)
logging.getLogger('engineio').setLevel(logging.WARNING)

logger = logging.getLogger('sio')


IP = ['192.168.1.12', '10.164.0.2'][0]
SERVER = f'http://{IP}:{ServerConfig.PORT}'

sio = socketio.Client()


@sio.on("connect", namespace="/api")
def connect():
    """Log connect."""
    logger.info(f"Connected: {sio.sid}")


@sio.on("disconnect", namespace="/api")
def disconnect():
    """Log disconnect."""
    logger.info("Disconnected.")


def main():
    """Simulate a mobile app user."""
    response = requests.post(SERVER + '/api/v2/auth', data={},
                             auth=('xxxx@gmail.com', 'yyyy'))
    user = json.loads(response.content)
    print(user)

    sio.connect(f'http://{IP}:{ServerConfig.PORT}',
                namespaces=["/api"])
    logger.info(f"sid: {sio.sid}")
    sio.sleep(1)
    sio.emit('join', {'id': user['customerID']},
             namespace="/api")

    sio.send('hola, que tal?',
             namespace="/api")

    sio.sleep(5)
    sio.disconnect()


if __name__ == '__main__':
    main()

The sid reported by the server at the line logger.info(f"Connect from api: {request.sid}") is not the same as the sid reported by the client at logger.info(f"Connected: {sio.sid}") (which is the same sid at logger.info(f"sid: {sio.sid}")

For the equivalent in JavaScript, I don't have any problem. (The sids match). Can you see why this could be happening? Thanks

[miguelgrinberg]

To get the sid of your client you have to use the sio.get_sid(namespace='/api') method.

[cbasavaraj]

Thanks, I'll try on Monday and let you know.

[cbasavaraj]

It works, but I had to move the sio.sleep(1) line before the logger line, which is now logger.info(f"sid: {sio.get_sid(namespace='/api')}"). Without the sleep, I was getting None. Thanks.

[cbasavaraj]

On the server side though, I store the sid in my flask session. And when I try to read it later in the join event, the room key isn't present in session. I've worked around this, not a big issue, but don't have this problem with a JS socketio client.

[miguelgrinberg]

@cbasavaraj the documentation explains what the limitations of the user session are when it is used from a Socket.IO event.

[cbasavaraj]

I just went back and read the limitations again. They talk mostly about the socketio session fork not being available to HTTP routes. (I am already using redis for this purpose).

Here, if you see my server side code (above), the room key which is written in the connect event handler is not available in the join event handler one second later. So both are socketio events, no mixing with HTTP.

But like I said, not a big issue.

[miguelgrinberg]

Can you share how you initialize your socketio object?

[cbasavaraj]

I use the factory pattern. Here are the relevant portions:

from flask import Flask
from flask_session import Session
from flask_socketio import SocketIO
from flask_cors import CORS

from celery import Celery
from werkzeug.middleware.proxy_fix import ProxyFix

socketio = SocketIO()
cors = CORS()

celeri = Celery(__name__, broker=ServerConfig.REDIS_URL,
                backend=ServerConfig.REDIS_URL)
celeri.config_from_object(CeleryConfig)


def create_app():
    """Create Flask app."""
    app = Flask(__name__, static_folder='static')
    app.wsgi_app = ProxyFix(app.wsgi_app)
    app.config.from_object(ServerConfig)

    socketio.init_app(
        app, manage_session=False,
        message_queue=ServerConfig.REDIS_URL,
        cors_allowed_origins='*'
    )
    Session(app)
    cors.init_app(app)

    # more stuff

    from app.api.v2 import bp as api_bp_v2
    app.register_blueprint(api_bp_v2, url_prefix='/api/v2')

    return app

ServerConfig is a dict with various config elements. Thanks!

[miguelgrinberg]

Which server-side session type are you using? Have you checked if the changes that you are making are being saved to the session?

[cbasavaraj]

I'm using filesystem. Haven't actually checked if the changes are being written. Can check tomorrow and let you know. But with the web / JS client, there were no issues.

class ServerConfig(object):
    """Config for the Server."""

    IP = SERVER_IP
    PORT = 8084

    SECRET_KEY = os.environ.get('SECRET_KEY') or 'random-string!'
    PREFERRED_URL_SCHEME = 'https'

    SESSION_TYPE = 'filesystem'

    SQLALCHEMY_DATABASE_URI = 'sqlite:///' + os.path.join(root_dir, 'data',
                                                          'app.db')
    SQLALCHEMY_TRACK_MODIFICATIONS = False

    REDIS_URL = f"redis://:{os.environ.get('REDIS_PASSWORD')}@{SERVER_IP}:6379/0"  # noqa: E501

[miguelgrinberg]

Somehow I missed this before. So you are saying that the same server records the session correctly with the client is JS, and it doesn't when the client is Python?

That has to be caused by some different in the logic of your client, right? It has to be that the sequence of event handlers called by each client is different. In that case, my suggestion is that you enable logging in the server, and then capture a log session for the JS client and another for the Python client. Then we can look at the differences and hopefully understand what's happening.

[cbasavaraj]

Yes, works with JS but not with a dummy client in Python (the real api client will be a mobile app).
I added a logger line in the join event handler to make it more explicit:

@socketio.on('connect', namespace='/api')
def connect():
    """Log connect."""
    logger.info(f"Connect from api: {request.sid}")
    session['room'] = request.sid

@socketio.on('join', namespace='/api')
def join(data):
    """Join with id."""
    id = data['id']
    logger.info(f"Room already set to: {session.get('room')}")
    room = session.setdefault('room', request.sid)
    logger.info(f"User_{id} has joined: {room}")
    redis_store[f"User_{id}"] = room

Logs for JS first. Note that /live is another namespace that is meant for communicating with the browser.

[2021-02-26 13:19:35,423] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:35] "GET / HTTP/1.0" 302 634 0.003184
[2021-02-26 13:19:35,467] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:35] "GET /auth/login?next=%2F HTTP/1.0" 200 7189 0.041886
[2021-02-26 13:19:37,542] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "GET /live HTTP/1.0" 200 10218 0.005821
[2021-02-26 13:19:37,584] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "GET /live.js HTTP/1.0" 200 12110 0.001949
[2021-02-26 13:19:37,598] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "GET /socket.io/?EIO=4&transport=polling&t=NVUHxNy HTTP/1.1" 200 253 0.000281
[2021-02-26 13:19:37,654] INFO app.live.events                  Connect from live: l0yEHi2EW5JZpeNhAAAB
[2021-02-26 13:19:37,656] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "POST /socket.io/?EIO=4&transport=polling&t=NVUHxOq&sid=6UfXfPmV_QEoFfIrAAAA HTTP/1.1" 200 191 0.002464
[2021-02-26 13:19:37,657] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "GET /socket.io/?EIO=4&transport=polling&t=NVUHxOs&sid=6UfXfPmV_QEoFfIrAAAA HTTP/1.1" 200 195 0.001162
[2021-02-26 13:19:37,661] INFO app.api.v2.events                Connect from api: cRiQDzzpLEfuWwDdAAAC
[2021-02-26 13:19:37,661] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "POST /socket.io/?EIO=4&transport=polling&t=NVUHxOx&sid=6UfXfPmV_QEoFfIrAAAA HTTP/1.1" 200 191 0.001434
[2021-02-26 13:19:37,662] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "GET /socket.io/?EIO=4&transport=polling&t=NVUHxOy&sid=6UfXfPmV_QEoFfIrAAAA HTTP/1.1" 200 194 0.000158
[2021-02-26 13:19:37,664] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "POST /socket.io/?EIO=4&transport=polling&t=NVUHxO_&sid=6UfXfPmV_QEoFfIrAAAA HTTP/1.1" 200 191 0.000216
[2021-02-26 13:19:37,665] INFO app.live.events                  Message from live: up
[2021-02-26 13:19:37,667] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "POST /socket.io/?EIO=4&transport=polling&t=NVUHxP1&sid=6UfXfPmV_QEoFfIrAAAA HTTP/1.1" 200 191 0.000511
[2021-02-26 13:19:37,668] INFO app.api.v2.events                Room already set to: cRiQDzzpLEfuWwDdAAAC
[2021-02-26 13:19:37,668] INFO app.api.v2.events                User_007 has joined: cRiQDzzpLEfuWwDdAAAC
[2021-02-26 13:19:37,670] INFO geventwebsocket.handler          127.0.0.1 - - [2021-02-26 13:19:37] "GET /socket.io/?EIO=4&transport=polling&t=NVUHxP0&sid=6UfXfPmV_QEoFfIrAAAA HTTP/1.1" 200 157 0.004292

Logs with the python-socketio client:

[2021-02-26 13:21:17,712] INFO app                              Logged in [Chandrachud Xxyy].
[2021-02-26 13:21:17,713] INFO geventwebsocket.handler          192.168.1.12 - - [2021-02-26 13:21:17] "POST /api/v2/auth HTTP/1.1" 200 513 0.081926
[2021-02-26 13:21:17,716] INFO geventwebsocket.handler          192.168.1.12 - - [2021-02-26 13:21:17] "GET /socket.io/?transport=polling&EIO=4&t=1614342077.7143707 HTTP/1.1" 200 253 0.000201
[2021-02-26 13:21:17,717] INFO app.api.v2.events                Connect from api: vPHDGJVnHuP5P2egAAAE
[2021-02-26 13:21:18,719] INFO app.api.v2.events                Room already set to: None
[2021-02-26 13:21:18,719] INFO app.api.v2.events                User_1 has joined: vPHDGJVnHuP5P2egAAAE

[miguelgrinberg]

You haven't enabled Socket.IO logs in the server. See the troubleshooting section of the logs for help on doing this.

[cbasavaraj]

Ah, it's true that when I first added Socket.IO, I had a lot of logs. Then I kinda disabled them by setting the level to Warning, but later I never got back so many logs. Did the defaults change? I mean was it True by default here a few months ago?

socketio = SocketIO(logger=True, engineio_logger=True)

In any case, I'll check on Monday and let you know. Thanks for the patience!
By the way, the logs above show transport=polling. Shouldn't the Upgrade to websockets happen pretty fast?

[miguelgrinberg]

@cbasavaraj Yes, but WebSocket has a single request, you are not going to see anything in the log until the end of the connection, since requests are logged when they end, not when they start.

[cbasavaraj]

Hi Miguel, I am unable to get any more logs than what I've pasted above. I updated my SocketIO initialization to:

    socketio.init_app(
        app,
        manage_session=False,
        message_queue=ServerConfig.REDIS_URL,
        cors_allowed_origins='*',
        logger=True,
        engineio_logger=True,
    )

and this is my socketion.run call:

    try:
        socketio.run(app, host='0.0.0.0', port=ServerConfig.PORT, debug=False,
                              log_output=True)
    except KeyboardInterrupt:
        logger.info("Hasta la vista, baby!")
        sys.exit(0)

Tried eventlet instead of gevent + gevent-websocket. With eventlet, I get just a bit more detail:

(24950) accepted ('127.0.0.1', 34178)
(24950) accepted ('127.0.0.1', 34182)

but that's it. Don't know what else I can try. I am using the latest versions of all the relevant libraries.
From the logs above, we are getting socket.io logs right? It's the engine.io logs which are not appearing.

[miguelgrinberg]

There should be additional logs when you add the logger and engineio_logger options. You may want to double check that you are doing this correctly. Try to add logging to one of the examples in this repository if you want to have an idea of what output you should see.

[cbasavaraj]

Kinda busy this week at work. Will get back to this a bit later, thanks!