Server event handlers failing silently without logging exceptions

[justinhaaheim]

I have a socketio Async server setup with logging enabled, and I realized yesterday that when an exception is raised inside an event handler the handler fails silently and nothing is logged. This makes debugging very difficult!

Is there a way to change this behavior? Or am I missing something about how exceptions should be handled? It seems strange to wrap the contents of all my event handlers in big try/except blocks , but I suppose I could do that.

My server is configured like this:

sio = socketio.AsyncServer(
    async_mode="asgi", cors_allowed_origins="*", logger=True, engineio_logger=True
)
app = socketio.ASGIApp(sio)

And I'm running it with uvicorn:
uvicorn --reload app_pubsub:app

[miguelgrinberg]

I've added a division by zero in one of the ASGI examples to try to reproduce this. Python itself logs the exception when the task running the handler ends. I can agree that this can be done better, I could catch the exception and log it on the configured logger, for example, but in any case the exception does appear to be reported.

❯ uvicorn --reload app:app
INFO:     Will watch for changes in these directories: ['/home/miguel/Documents/dev/python-socketio/examples/server/asgi']
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO:     Started reloader process [216389] using StatReload
INFO:     Started server process [216391]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     127.0.0.1:37672 - "GET / HTTP/1.1" 200 OK
INFO:     127.0.0.1:37672 - "GET /favicon.ico HTTP/1.1" 404 Not Found
INFO:     127.0.0.1:37672 - "GET /socket.io/?EIO=4&transport=polling&t=OfI_Ax4 HTTP/1.1" 200 OK
INFO:     127.0.0.1:37672 - "POST /socket.io/?EIO=4&transport=polling&t=OfI_Axr&sid=rA6xxQAi7ynkKFmCAAAA HTTP/1.1" 200 OK
INFO:     ('127.0.0.1', 37678) - "WebSocket /socket.io/?EIO=4&transport=websocket&sid=rA6xxQAi7ynkKFmCAAAA" [accepted]
INFO:     127.0.0.1:37676 - "GET /socket.io/?EIO=4&transport=polling&t=OfI_Axs&sid=rA6xxQAi7ynkKFmCAAAA HTTP/1.1" 200 OK
INFO:     127.0.0.1:37676 - "GET /socket.io/?EIO=4&transport=polling&t=OfI_Ay7&sid=rA6xxQAi7ynkKFmCAAAA HTTP/1.1" 200 OK
Task exception was never retrieved
future: <Task finished name='Task-40' coro=<AsyncServer._handle_event_internal() done, defined at /home/miguel/Documents/dev/python-socketio/src/socketio/asyncio_server.py:513> exception=ZeroDivisionError('division by zero')>
Traceback (most recent call last):
  File "/home/miguel/Documents/dev/python-socketio/src/socketio/asyncio_server.py", line 515, in _handle_event_internal
    r = await server._trigger_event(data[0], namespace, sid, *data[1:])
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/miguel/Documents/dev/python-socketio/src/socketio/asyncio_server.py", line 549, in _trigger_event
    ret = await handler(*args)
          ^^^^^^^^^^^^^^^^^^^^
  File "/home/miguel/Documents/dev/python-socketio/examples/server/asgi/app.py", line 34, in join
    1/0
    ~^~
ZeroDivisionError: division by zero

[justinhaaheim]

Thanks for the quick reply, @miguelgrinberg . Could you share your repro code? For some reason I am not seeing the same thing you are.

[miguelgrinberg]

Take this example app and apply the following patch:

diff --git a/examples/server/asgi/app.py b/examples/server/asgi/app.py
index c606823..631d36c 100644
--- a/examples/server/asgi/app.py
+++ b/examples/server/asgi/app.py
@@ -31,6 +31,7 @@ async def test_broadcast_message(sid, message):

 @sio.on('join')
 async def join(sid, message):
+    1/0
     sio.enter_room(sid, message['room'])
     await sio.emit('my_response', {'data': 'Entered room: ' + message['room']},
                    room=sid)

Then whenever you click the "Join Room" button the division by zero will trigger.