Receiving events seems to be unreliable

[matthew-at-qamcom]

I've most likely done something wrong and would love assistance please. Thanks in advance.

I have both a client and server written using python-socketio, with the server running under Tornado and the client running under pytest.

When I ran the client, the server saw 3 events out of 10 trials.
When I ran the client with a wait() call (i.e. option 1 is uncommented), I see no major change, 2 events received out of 10 trials.
When I add a time.sleep() call (i.e. option 2 is uncommented), I see 10 events received out of 10 trials. In other words, things seem to be working fine.

However, irrespective of whether the server receives the event, I also regularly see errors reported in the client, for example Unexpected error decoding packet: "Invalid empty packet received", aborting after it tries to disconnect.

Below is the code for both the client and server.

Client:

import socketio
import time

@pytest.fixture
def sio_client():
    # Set up a socket.io client for testing
    sio = socketio.Client(logger=True, engineio_logger=True)
    sio.connect('http://localhost:4000')
    yield sio
    sio.disconnect()
    # OPTION 1
    # print("Waiting")
    # sio.wait()

def test_change_detected_event(sio_client):
    # Simulate a changeDetected event
    test_data = {
        'data': "test"
    }
    sio_client.emit('changeDetected', test_data)

    # OPTION 2
    # print("Sleeping")
    # time.sleep(1)

Server:

import socketio
import tornado.web
import tornado.ioloop

# Set up basic logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)


logger.info("Starting socketIO server")
sio = socketio.AsyncServer(async_mode='tornado')

@sio.event
async def connect(sid, environ, auth):
    logger.info('socket.io connection %s', sid)

@sio.event
async def disconnect(sid):
    logger.info('socket.io disconnect %s', sid)

@sio.on('changeDetected')
async def change_detected(sid, message):
    logger.info('Change detected')
    # Do some important work here
    return


app = tornado.web.Application([
    (r"/socket.io/", socketio.get_tornado_handler(sio))
])

if __name__ == "__main__":
    app.listen(4000)
    logger.info("Starting socketIO server on port 4000")
    tornado.ioloop.IOLoop.instance().start()

[matthew-at-qamcom]

This is what I have installed in the Python environment.

$ pip list | grep socket
python-socketio               5.10.1.dev0
simple-websocket              0.10.1
websocket-client              1.5.2
websockets                    11.0.3

[matthew-at-qamcom]

I saw that there's an updated version of python-socketio. I've just updated to 5.11.0 but the above results remain valid.

[miguelgrinberg]

The difference between option 1 and option 2 is that in option 1 you are disconnecting and in option 2 you aren't. The disconnect call interrupts the work that happens in the background to send events. The wait() call exists to maintain the client connected while this work occurs, so disconnecting right before waiting makes no sense.

You should consider using acknowledgements for your emitted events. The easiest way is to switch from emit() to call() to send an event. The emit() method schedules the emit and returns while the data is sent in the background, while call() schedules the emits and then blocks until the server receives the emit and returns an acknowledgement response.

If you use call(), then control will return to your fixture after all the events have been sent and acknowledged, so you can just disconnect and leave, without waiting.

[matthew-at-qamcom]

Absolutely awesome. Thanks for your super quick response. call() does indeed solve my problem, and is far faster an option than sleeping.

Do you have any idea why I'm still seeing Unexpected error decoding packet: "Invalid empty packet received", aborting in the client?

Thanks again.

[matthew-at-qamcom]

To be specific, here is the complete client output:

platform linux -- Python 3.10.12, pytest-7.4.2, pluggy-1.3.0
rootdir: /home/matthew/recap-search
configfile: pytest.ini
plugins: timeout-2.1.0, asyncio-0.21.1, anyio-3.7.1
asyncio: mode=strict
collected 1 item                                                                                        

test.py Attempting polling connection to http://localhost:4000/socket.io/?transport=polling&EIO=4
Polling connection accepted with {'sid': '1AZIuhTXuiVb1giIAAAS', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Engine.IO connection established
Sending packet MESSAGE data 0{}
Attempting WebSocket upgrade to ws://localhost:4000/socket.io/?transport=websocket&EIO=4
WebSocket upgrade was successful
Received packet NOOP data 
Received packet MESSAGE data 0{"sid":"uV7PE1zerAvOyeNMAAAT"}
Namespace / is connected
Emitting event "changeDetected" [/]
Sending packet MESSAGE data 21["changeDetected",{"data":"test"}]
Received packet MESSAGE data 31[]
Received ack [/]
.Sending packet MESSAGE data 1
Sending packet CLOSE data None
Engine.IO connection dropped
Exiting write loop task
Unexpected error decoding packet: "Invalid empty packet received", aborting
Waiting for write loop task to end
Exiting read loop task


=========================================== 1 passed in 0.07s ===========================================

[miguelgrinberg]

I'm not sure, I will need to investigate. To be honest I haven't used the Tornado integration in a long time, I wonder if something in its WebSocket implementation causes this. The client is in the process of trying to exit cleanly when the server appears to send something unexpected.

[miguelgrinberg]

Update on this issue: It's not related to the Tornado server, it is a bug in the connection cleanup logic of the client that is triggered for client-initiated disconnects (at least I do not see it when the server issues the disconnection).

miguelgrinberg/python-engineio#342

[miguelgrinberg]

If anybody is interested in testing out the fix, please install the main branch of the python-engineio package. Thanks!

[mati22124]

Hey, just stumbled upon this thread. Want to let you know that you are not alone. I am getting this same error. I could be wrong, but I am pretty sure the "Unexpected error decoding packet: "Invalid empty packet received", aborting" message has to do with ping errors. Here is my code:

#modules & vars

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

@sio.on('change')
def on_message(data):
    # Implementation

@sio.event
def connect():
    print("I'm connected!")

#Irrelavent functions

while True: #I have in while loop so it stays working, even though it reconnects and disconnects frequently.
    sio.connect('http://localhost:5008', transports=['websocket'])
    sio.wait()
    sio.disconnect()

And the output during the error is

Attempting WebSocket connection to ws://localhost:5008/socket.io/?transport=websocket&EIO=4
WebSocket connection accepted with {'sid': 'yDevKJGgnJENp-OHAAAC', 'upgrades': [], 'pingInterval': 25000, 'pingTimeout': 60000}
Engine.IO connection established
Sending packet MESSAGE data 0{}
Received packet MESSAGE data 0
Namespace / is connected
I'm connected!
Received packet MESSAGE data 0
packet queue is empty, aborting
Exiting write loop task
Unexpected error decoding packet: "Invalid empty packet received", aborting
Waiting for write loop task to end
Engine.IO connection dropped
Connection failed, new attempt in 1.38 seconds
Exiting read loop task

If I change pingTimeout and pingInterval to be less, then the error message happens on the 2nd ping. Maybe you can try it out. If anyone finds a solution I will be eternally grateful. I will keep working on it as well.

[matthew-at-qamcom]

@miguelgrinberg Thanks greatly for having a look at this. I attempted to test out the change you made. I ran:

pip install --upgrade python-engineio

This upgraded the package to version 4.8.2.

However I still see the same message: Unexpected error decoding packet: "Invalid empty packet received", aborting.

Perhaps the code changes haven't made it to pip's archive? Or were you wanting us to install from the GitHub repo?

The updated client code I ran was:

import pytest
import socketio
import time

@pytest.fixture
def sio_client():
    # Set up a socket.io client for testing
    sio = socketio.Client(logger=True, engineio_logger=True)
    sio.connect('http://localhost:4000')
    yield sio
    sio.disconnect()

def test_change_detected_event(sio_client):
    # Simulate a changeDetected event
    test_data = {
        'data': "test"
    }
    sio_client.call('changeDetected', test_data)

The full output of running the test in pytest:

======================================== test session starts ========================================
platform linux -- Python 3.10.12, pytest-7.4.2, pluggy-1.3.0
rootdir: /home/matthew/recap-search
configfile: pytest.ini
plugins: timeout-2.1.0, asyncio-0.21.1, anyio-3.7.1
asyncio: mode=auto
collected 1 item                                                                                    

test_old.py Attempting polling connection to http://localhost:4000/socket.io/?transport=polling&EIO=4
Polling connection accepted with {'sid': 'ZSh_YieQ5Z9962qPAAAE', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Engine.IO connection established
Sending packet MESSAGE data 0{}
Attempting WebSocket upgrade to ws://localhost:4000/socket.io/?transport=websocket&EIO=4
WebSocket upgrade was successful
Received packet NOOP data 
Received packet MESSAGE data 0{"sid":"7TD2h5KbMGkLacr2AAAF"}
Namespace / is connected
Emitting event "changeDetected" [/]
Sending packet MESSAGE data 21["changeDetected",{"data":"test"}]
Received packet MESSAGE data 31[]
Received ack [/]
.Sending packet MESSAGE data 1
Sending packet CLOSE data None
Engine.IO connection dropped
Exiting write loop task
Unexpected error decoding packet: "Invalid empty packet received", aborting
Waiting for write loop task to end
Exiting read loop task


========================================= 1 passed in 0.07s =========================================

[miguelgrinberg]

Sorry yes, I should have been more clear. You need to install the main branch if the repo, this change is not released yet.

[matthew-at-qamcom]

That worked for me. I installed python-engineio-4.8.3.dev0 with

pip install git+https://github.com/miguelgrinberg/python-engineio.git@5b538a74061d893f255ac3544ffe1402ae97b58e

And rather than seeing the previous error, I now see WebSocket connection was closed, aborting.

Thanks again for looking into this.

The full output was:

======================================== test session starts ========================================
platform linux -- Python 3.10.12, pytest-7.4.2, pluggy-1.3.0
rootdir: /home/matthew/recap-search
configfile: pytest.ini
plugins: timeout-2.1.0, asyncio-0.21.1, anyio-3.7.1
asyncio: mode=auto
collected 1 item                                                                                    

test_old.py Attempting polling connection to http://localhost:4000/socket.io/?transport=polling&EIO=4
Polling connection accepted with {'sid': 'IuD4_qegKjmQ_5FpAAAG', 'upgrades': ['websocket'], 'pingTimeout': 20000, 'pingInterval': 25000}
Engine.IO connection established
Sending packet MESSAGE data 0{}
Attempting WebSocket upgrade to ws://localhost:4000/socket.io/?transport=websocket&EIO=4
WebSocket upgrade was successful
Received packet NOOP data 
Received packet MESSAGE data 0{"sid":"KUWGfRiYbQ8pPlNcAAAH"}
Namespace / is connected
Emitting event "changeDetected" [/]
Sending packet MESSAGE data 21["changeDetected",{"data":"test"}]
Received packet MESSAGE data 31[]
Received ack [/]
.Sending packet MESSAGE data 1
Sending packet CLOSE data None
Engine.IO connection dropped
Exiting write loop task
WebSocket connection was closed, aborting
Waiting for write loop task to end
Exiting read loop task


========================================= 1 passed in 0.07s =========================================