Search code examples
socket.iosveltekitpython-socketio

socket.io client does not receive events


I have a SvelteKit application that is using the socket.io client, and a python application that is using the python-socket.io server with eventlet.

The problem is, that messages from the server to the client are not processed in the client.

The important code is in the two files shown below. If you need more, you can check out the repository or ask me.

Backend

logger = logging.getLogger('weckpi.core.main')
sio_logger = logging.getLogger('weckpi.core.main.socket')

sio = socketio.Server(
    async_mode='eventlet',
    logger=sio_logger,
    engineio_logger=sio_logger,
    cors_allowed_origins='*'
)

...

player = MpvPlayer()

@sio.on('initial-data-request')
def on_initial_data_request(sid):
    logger.info('Client %s requested initial data', sid)

    return {...}

@sio.on('property-change')
def on_property_change(sid, data: dict):
    prop, value = data.get('prop'), data.get('value')
    logger.info('Client %s changed property %s to %s', sid, prop, value)
    ...

player.set_on_queue_position_change(lambda value: sio.emit('property-change', {'prop': 'music.metadata', 'value': asdict(player.metadata)}))
player.set_on_position_change(lambda value: sio.emit('property-change', {'prop': 'music.position', 'value': value}))

...

app = socketio.WSGIApp(sio)
eventlet.wsgi.server(eventlet.listen(('', 8000)), app)

The player is basically a wrapper around the python-mpv library. python-mpv seems to use the threading library for emitting events. These handlers do work, I can see the following output in the python console:

[12:12:29 | weckpi.core.main.socket | INFO] emitting event "property-change" to all [/]
[12:12:29 | weckpi.core.main.socket | INFO] LgIpfA6MWuwv3sK8AAAE: Sending packet MESSAGE data 2["property-change",{"prop":"music.position","value":0.005773007180650037}]

The messages from the second mpv handler are sent about every 1/10 second. The messages from the first mpv handler are sent when a new song is played (with 4 to 5 minutes per song). Both events are not received / processed by the client, so I guess it's not a timing issue.

I have the same thing also in the other direction, except it works there. The property-change sio handler changes e.g. the volume, if the slider in the UI is changes.

Another thing is the initial-data-request handler, that uses a callback emit a message to the client. This also works.

Frontend Code

import {io, type Socket} from "socket.io-client";

import {musicMetadata, musicPlaying, musicPosition, musicRepeat, musicShuffle, musicVolume} from "$lib/BackendConnection/ParameterStore";

import {debug} from "debug";

const log = debug("weckpiWeb:weckpiCoreConnection");

export class WeckPiCoreConnection {
    public sio: Socket;
    private disabled: boolean;

    public constructor() {
        log("Initializing weckpi core connection");
        this.sio = io("ws://localhost:8000/");
        this.disabled = true;

        // Set the handler for incoming messages
        this.sio.on("property-change", ({prop, value}) => {
            this.disable();
            log("Received property change of %s to %O", prop, value);

            switch (prop) {
                case "music.metadata":
                    musicMetadata.set(value);
                    break;

                case "music.is_playing":
                    musicPlaying.set(value);
                    break;

                case "music.repeat":
                    musicRepeat.set(value);
                    break;

                case "music.shuffle":
                    musicShuffle.set(value);
                    break;

                case "music.volume":
                    musicVolume.set(value);
                    break;

                case "music.position":
                    musicPosition.set(value);
                    break;
            }

            this.enable();
        });

        // Set the handlers for outgoing messages (changes in stores)
        musicPlaying.subscribe((value) => this.propertyChange("music.is_playing", value));
        musicRepeat.subscribe((value) => this.propertyChange("music.repeat", value));
        musicShuffle.subscribe((value) => this.propertyChange("music.shuffle", value));
        musicVolume.subscribe((value) => this.propertyChange("music.volume", value));
        musicPosition.subscribe((value) => this.propertyChange("music.position", value));

        // Request the initial dataset
        this.sio.emit("initial-data-request", (initialData: any) => {
            musicMetadata.set(initialData.music.metadata);
            musicPlaying.set(initialData.music.playing);
            musicRepeat.set(initialData.music.repeat);
            musicShuffle.set(initialData.music.shuffle);
            musicVolume.set(initialData.music.volume);
            musicPosition.set(initialData.music.position);

            this.enable();
        });

        this.sio.prependAny((name, data) => log("Received event %s with data %O", name, data));
    }

    public enable() {
        log("Enabled sending of events");
        this.disabled = false;
    }

    public disable() {
        log("Disabled sending of events");
        this.disabled = true;
    }

    public propertyChange(prop: string, value: any) {
        if (this.disabled) {
            log("Change of property %s suppressed, because disabled=%s", prop, this.disabled);
            return;
        }

        log("Sent change of property %s to value %O", prop, value);
        this.sio.emit("property-change", {prop, value});
    }

    public action(name: string) {
        if (this.disabled) {
            log("Action %s suppressed, because disabled=%s", name, this.disabled);
            return;
        }
        
        log("Sent action %s", name);
        this.sio.emit("action", {name});
    }
}


const weckpiCore: WeckPiCoreConnection = new WeckPiCoreConnection();
export default weckpiCore;

Here I have a wrapper class around my events that can be sent over socket.io. I create a handler for incoming messages in the constructor, connect the handlers of the Svelte Stores with socket.io and send the initial data request. For debugging, I also added a Any handler.

The enable and disable functions are there because when the server sends property changes, the property change gets sent back to the server.

What I tried

I re-organized the code structure, so everything is now added in the constructor and not in different methods. Also I moved the WeckPiCoreConnection instance from a Svelte Store into a module variable, since the UI doesn't need to update when something in the instance changes.

I added logging using the debug module. While this works fine, I still don't get anything directly from socket.io in the browser console.

I also tried using the vite preview instead of vite dev, but that changed nothing.

I discovered, that the client seems to disconnect / reconnect about every half a minute. Then I see following messages in the browser console:

12:49:38.934 XHR  GET   http://localhost:8000/socket.io/?EIO=4&transport=polling&t=Ob4aZ5p                              [HTTP/1.1 200 OK 1ms]
12:49:38.941 XHR  POST  http://localhost:8000/socket.io/?EIO=4&transport=polling&t=Ob4aZ5w&sid=Ku2h0XjMpkT9VqCiAAAG     [HTTP/1.1 200 OK 1ms]
12:49:38.943      GET   ws://localhost:8000/socket.io/?EIO=4&transport=websocket&sid=Ku2h0XjMpkT9VqCiAAAG               [HTTP/1.1 101 Switching Protocols 1ms]
12:49:38.946 XHR  GET   http://localhost:8000/socket.io/?EIO=4&transport=polling&t=Ob4aZ5y&sid=Ku2h0XjMpkT9VqCiAAAG     [HTTP/1.1 200 OK 0ms]
12:49:38.951 XHR  GET   http://localhost:8000/socket.io/?EIO=4&transport=polling&t=Ob4aZ66&sid=Ku2h0XjMpkT9VqCiAAAG     [HTTP/1.1 200 OK 0ms]

On the server, it looks like this:

[12:49:37 | weckpi.core.main.socket | INFO] vF3keCvNqBmz58Q9AAAE: Unexpected error "timed out", closing connection
[12:49:37 | weckpi.core.main | INFO] Client bPyZS4ntI6O2o18VAAAF disconnected
127.0.0.1 - - [11/Jul/2023 12:49:37] "GET /socket.io/?EIO=4&transport=websocket&sid=vF3keCvNqBmz58Q9AAAE HTTP/1.1" 200 0 345.002576
(27069) accepted ('127.0.0.1', 63076)
127.0.0.1 - - [11/Jul/2023 12:49:38] "GET /socket.io/?EIO=4&transport=polling&t=Ob4aZ5p HTTP/1.1" 200 330 0.000447
127.0.0.1 - - [11/Jul/2023 12:49:38] "POST /socket.io/?EIO=4&transport=polling&t=Ob4aZ5w&sid=Ku2h0XjMpkT9VqCiAAAG HTTP/1.1" 200 219 0.000501
(27069) accepted ('127.0.0.1', 63077)
[12:49:38 | weckpi.core.main.socket | INFO] Ku2h0XjMpkT9VqCiAAAG: Sending packet OPEN data {'sid': 'Ku2h0XjMpkT9VqCiAAAG', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
[12:49:38 | weckpi.core.main.socket | INFO] Ku2h0XjMpkT9VqCiAAAG: Received packet MESSAGE data 0
[12:49:38 | weckpi.core.main | INFO] Client connected with SID 46JVyy2oNFmLVwszAAAH, env {'wsgi.errors': <_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>, 'wsgi.version': (1, 0), 'wsgi.multithread': True, 'wsgi.multiprocess': False, 'wsgi.run_once': False, 'wsgi.url_scheme': 'http', 'REQUEST_METHOD': 'GET', 'SCRIPT_NAME': '', 'RAW_PATH_INFO': '/socket.io/', 'PATH_INFO': '/socket.io/', 'QUERY_STRING': 'EIO=4&transport=polling&t=Ob4aZ5p', 'CONTENT_TYPE': 'text/plain', 'SERVER_PROTOCOL': 'HTTP/1.0', 'SERVER_NAME': '127.0.0.1', 'SERVER_PORT': '8000', 'REMOTE_ADDR': '127.0.0.1', 'REMOTE_PORT': '63076', 'GATEWAY_INTERFACE': 'CGI/1.1', 'headers_raw': (('Host', 'localhost:8000'), ('User-Agent', 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:109.0) Gecko/20100101 Firefox/115.0'), ('Accept', '*/*'), ('Accept-Language', 'de-DE,en-US;q=0.5'), ('Accept-Encoding', 'gzip, deflate, br'), ('Origin', 'http://localhost:5173'), ('DNT', '1'), ('Connection', 'keep-alive'), ('Referer', 'http://localhost:5173/'), ('Sec-Fetch-Dest', 'empty'), ('Sec-Fetch-Mode', 'cors'), ('Sec-Fetch-Site', 'same-site'), ('Pragma', 'no-cache'), ('Cache-Control', 'no-cache')), 'HTTP_HOST': 'localhost:8000', 'HTTP_USER_AGENT': 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:109.0) Gecko/20100101 Firefox/115.0', 'HTTP_ACCEPT': '*/*', 'HTTP_ACCEPT_LANGUAGE': 'de-DE,en-US;q=0.5', 'HTTP_ACCEPT_ENCODING': 'gzip, deflate, br', 'HTTP_ORIGIN': 'http://localhost:5173', 'HTTP_DNT': '1', 'HTTP_CONNECTION': 'keep-alive', 'HTTP_REFERER': 'http://localhost:5173/', 'HTTP_SEC_FETCH_DEST': 'empty', 'HTTP_SEC_FETCH_MODE': 'cors', 'HTTP_SEC_FETCH_SITE': 'same-site', 'HTTP_PRAGMA': 'no-cache', 'HTTP_CACHE_CONTROL': 'no-cache', 'wsgi.input': <eventlet.wsgi.Input object at 0x115ae7b10>, 'eventlet.input': <eventlet.wsgi.Input object at 0x115ae7b10>, 'eventlet.posthooks': []} and auth None
[12:49:38 | weckpi.core.main.socket | INFO] Ku2h0XjMpkT9VqCiAAAG: Sending packet MESSAGE data 0{"sid":"46JVyy2oNFmLVwszAAAH"}
[12:49:38 | weckpi.core.main.socket | INFO] Ku2h0XjMpkT9VqCiAAAG: Received request to upgrade to websocket
127.0.0.1 - - [11/Jul/2023 12:49:38] "GET /socket.io/?EIO=4&transport=polling&t=Ob4aZ5y&sid=Ku2h0XjMpkT9VqCiAAAG HTTP/1.1" 200 233 0.000115
127.0.0.1 - - [11/Jul/2023 12:49:38] "GET /socket.io/?EIO=4&transport=polling&t=Ob4aZ66&sid=Ku2h0XjMpkT9VqCiAAAG HTTP/1.1" 200 233 0.000116
[12:49:38 | weckpi.core.main.socket | INFO] Ku2h0XjMpkT9VqCiAAAG: Upgrade to websocket successful

Somewhere in there it says Unexpected error "timed out", closing connection. What could be the cause of that?

The last thing is: sometimes, the event comes through. But it is not very often, and even then I don't see any message in the browser console.

EDIT: I also tried it using Chrome (my default browser is Firefox), same results


Solution

  • As @miguelgrinberg commented, the problems were caused by eventlet. I switched to Flask for the webserver, now the client gets the events.