Sanic AsyncHandler frequently generates websocket exceptions

[eirikrye]

Hi,

python-engineio (2.0.2)
python-socketio (1.8.4)
sanic (0.7.0)

I am running a websocket service using the Sanic AsyncHandler, however I have noticed in the logs that I am frequently getting the following exception:

Jan 26 16:25:36 python3[4729]: [2018-01-26 16:25:36 +0000] [4729] [ERROR] Traceback (most recent call last):
Jan 26 16:25:36 python3[4729]:   File "/usr/local/lib/python3.5/dist-packages/sanic/app.py", line 556, in handle_request
Jan 26 16:25:36 python3[4729]:     response = await response
Jan 26 16:25:36 python3[4729]:   File "/usr/local/lib/python3.5/dist-packages/engineio/asyncio_server.py", line 146, in handle_request
Jan 26 16:25:36 python3[4729]:     packets = await socket.handle_get_request(environ)
Jan 26 16:25:36 python3[4729]:   File "/usr/local/lib/python3.5/dist-packages/engineio/asyncio_socket.py", line 76, in handle_get_request
Jan 26 16:25:36 python3[4729]:     return await getattr(self, '_upgrade_' + transport)(environ)
Jan 26 16:25:36 python3[4729]:   File "/usr/local/lib/python3.5/dist-packages/engineio/asyncio_socket.py", line 118, in _upgrade_websocket
Jan 26 16:25:36 python3[4729]:     return await ws(environ)
Jan 26 16:25:36 python3[4729]:   File "/usr/local/lib/python3.5/dist-packages/engineio/async_sanic.py", line 122, in __call__
Jan 26 16:25:36 python3[4729]:     await self.handler(self)
Jan 26 16:25:36 python3[4729]:   File "/usr/local/lib/python3.5/dist-packages/engineio/asyncio_socket.py", line 138, in _websocket_handler
Jan 26 16:25:36 python3[4729]:     pkt = await ws.wait()
Jan 26 16:25:36 python3[4729]:   File "/usr/local/lib/python3.5/dist-packages/engineio/async_sanic.py", line 131, in wait
Jan 26 16:25:36 python3[4729]:     data = await self._sock.recv()
Jan 26 16:25:36 python3[4729]:   File "/usr/local/lib/python3.5/dist-packages/websockets/protocol.py", line 323, in recv
Jan 26 16:25:36 python3[4729]:     raise ConnectionClosed(self.close_code, self.close_reason)
Jan 26 16:25:36 python3[4729]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1005 (no status code [internal]), no reason

The app keeps running, so it's not a big deal, however it's annoying having these messages filling up the error log.

[miguelgrinberg]

Based on the stack trace, it appears that your client is connecting over WebScoket and then immediately disconnecting, without following through with the initial handshake to establish the connection.

I can make this code more robust to prevent the stack traces to be dumped, but this seems to indicate you have clients that for some reason are deciding to go away in the middle of an exchange with the server.

[eirikrye]

For what it's worth, the clients are regular web-based socket.io connections. I guess it may just be users immediately closing the browser tab or something. With dozens of simultaneous connections, I only see this stack trace emitted a couple times per hour, so it's barely a minor nuisance.

Thanks for the response!

[miguelgrinberg]

I thought I'd mention it, because this isn't an established connection that is closed, those errors are being handled and suppressed from the log. This is during the initial handshake, so you have a client that connected over HTTP, and while it started to go through the handshake to upgrade the connection to WebSocket it went away. I'm actually going to have to get creative to reproduce this, since it requires very quick and precise timing.

[eirikrye]

Just by spamming the refresh button on my website, I am able to quite consistently reproduce a stack trace, albeit not the exact same one as above (code 1001 (going away) instead of code 1005):

Jan 29 18:28:56 python3[9197]: [2018-01-29 18:28:56 +0000] [9197] [ERROR] Traceback (most recent call last):
Jan 29 18:28:56 python3[9197]:   File "/usr/local/lib/python3.5/dist-packages/sanic/app.py", line 556, in handle_request
Jan 29 18:28:56 python3[9197]:     response = await response
Jan 29 18:28:56 python3[9197]:   File "/usr/local/lib/python3.5/dist-packages/engineio/asyncio_server.py", line 146, in handle_request
Jan 29 18:28:56 python3[9197]:     packets = await socket.handle_get_request(environ)
Jan 29 18:28:56 python3[9197]:   File "/usr/local/lib/python3.5/dist-packages/engineio/asyncio_socket.py", line 76, in handle_get_request
Jan 29 18:28:56 python3[9197]:     return await getattr(self, '_upgrade_' + transport)(environ)
Jan 29 18:28:56 python3[9197]:   File "/usr/local/lib/python3.5/dist-packages/engineio/asyncio_socket.py", line 118, in _upgrade_websocket
Jan 29 18:28:56 python3[9197]:     return await ws(environ)
Jan 29 18:28:56 python3[9197]:   File "/usr/local/lib/python3.5/dist-packages/engineio/async_sanic.py", line 122, in __call__
Jan 29 18:28:56 python3[9197]:     await self.handler(self)
Jan 29 18:28:56 python3[9197]:   File "/usr/local/lib/python3.5/dist-packages/engineio/asyncio_socket.py", line 138, in _websocket_handler
Jan 29 18:28:56 python3[9197]:     pkt = await ws.wait()
Jan 29 18:28:56 python3[9197]:   File "/usr/local/lib/python3.5/dist-packages/engineio/async_sanic.py", line 131, in wait
Jan 29 18:28:56 python3[9197]:     data = await self._sock.recv()
Jan 29 18:28:56 python3[9197]:   File "/usr/local/lib/python3.5/dist-packages/websockets/protocol.py", line 323, in recv
Jan 29 18:28:56 python3[9197]:     raise ConnectionClosed(self.close_code, self.close_reason)
Jan 29 18:28:56 python3[9197]: websockets.exceptions.ConnectionClosed: WebSocket connection is closed: code = 1001 (going away), no reason

[miguelgrinberg]

Okay, maybe that's all this is, just someone getting refresh-happy. Thanks, I'll see that these messages are suppressed.

[speence]

Hi Miguel, I've encountered the same messages, reproducible by quickly toggling between views (and, like you mentioned above, would be quickly connecting and disconnecting the socket connection). Were these messages suppressed in a recent release? I'm currently using:

python-engineio==2.2.0 python-socketio==2.0.0 sanic==0.7.0

Not a huge deal however, like @eirikrye mentioned it's a minor nuisance.

[miguelgrinberg]

I haven't addressed these at this point, so I expect they'll still occur with the latest release.

[SacreBleuXCVII]

Any updates on this? Also been encountering these errors for around a year.

[miguelgrinberg]

Not planning to invest more time in the Sanic integration. Use the Sanic as an ASGI app instead.