Debugging lost connections?

[mortoray]

Is there a way I can figure out why a websocket connection has been closed? I'm having a problem where connections to my AWS EC2 host are being disconnected. Both the high-level message on the client and server show a disconnection, without too much detail as to what happened.

Is there some logging I can enable, or codes I can watch to determine what may be happening?

SSH connections to the same machine are stable for a long-period, so I don't think I have an underlying TCP issue. I'm suspecting something at the WebSocket level, but I can't be positive, and I'm unsure of how to figure where the problem is.

NOTE: only some WebSockets are closed, and if I have a lot of them they are slowly closed over time.

[aaugustin]

https://websockets.readthedocs.io/en/stable/cheatsheet.html#debugging can help, although it will be very verbose at the DEBUG level if you have a ton of connections.

You can look at the close_code and close_reason of the protocol, once the connection is closed. Per the spec, it's the close code received from the remote endpoint, so it's often useless if the connection drops without a proper closing handshake.

[mortoray]

Argh, this issue is being complicated by the Motor MongoDB library throwing empty exceptions! No info, no stack trace, just an error. These are currently standing out as the most likely reason for disconnects. I'll have to figure them out first.

[mortoray]

Turning on DEBUG seems to prevent the error from happening.

Without DEBUG, using my own print statements, I find the disconnect tends to happen in a call to send with the exception <class 'websockets.exceptions.ConnectionClosedError'> code = 1011 (unexpected error), no reason

On the Python client I get this stack trace at the time of the disconnect. There's no way I can tell which happened first -- though keep in mind the disconnect also happens from a web browser.

future: <Task finished name='Task-5' coro=<reader() done, defined at ws_client.py:27> exception=ConnectionClosedError('code = 1006 (connection closed abnormally [internal]), no reason')>
Traceback (most recent call last):
  File "/src/escape-live/env/lib/python3.8/site-packages/websockets/protocol.py", line 827, in transfer_data
    message = await self.read_message()
  File "/src/escape-live/env/lib/python3.8/site-packages/websockets/protocol.py", line 895, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/src/escape-live/env/lib/python3.8/site-packages/websockets/protocol.py", line 971, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/src/escape-live/env/lib/python3.8/site-packages/websockets/protocol.py", line 1047, in read_frame
    frame = await Frame.read(
  File "/src/escape-live/env/lib/python3.8/site-packages/websockets/framing.py", line 105, in read
    data = await reader(2)
  File "/usr/lib/python3.8/asyncio/streams.py", line 723, in readexactly
    await self._wait_for_data('readexactly')
  File "/usr/lib/python3.8/asyncio/streams.py", line 517, in _wait_for_data
    await self._waiter
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "ws_client.py", line 35, in reader
    async for message_raw in websocket:
  File "/src/escape-live/env/lib/python3.8/site-packages/websockets/protocol.py", line 439, in __aiter__
    yield await self.recv()
  File "/src/escape-live/env/lib/python3.8/site-packages/websockets/protocol.py", line 509, in recv
    await self.ensure_open()
  File "/src/escape-live/env/lib/python3.8/site-packages/websockets/protocol.py", line 812, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: code = 1006 (connection closed abnormally [internal]), no reason

I'll try with DEBUG once more.

[aaugustin]

1011 is the equivalent of HTTP 500 internal server error — which doesn't really help.

websockets closes the connection with an error 1011 in these circumstances:

• if it sent a ping and the pong doesn't come back in a timely fashion; you can set ping_timeout=None to disable pings and see if that's the issue
• if it's half-way through a fragmented message and is unable finish it, which is irrecoverable; the exception is propagated back to the caller
• if an internal task fails; this is logged at the ERROR level; search for Error in data transfer in logs
• on the server side, if the connection handler crashes; this is logged at the ERROR level; search for Error in connection handler in logs

When you're hitting ConnectionClosed in send(), the connection is already closed, so the error likely happened earlier.

I hope this can help you narrow it down.

Finally, others tracked down issues of this kind to other parts of their app, like a misbehavior connection pool for their database. I'm not entirely surprised to see you mention Motor.

[mortoray]

The only option appears to be the Ping timeout, as there were no "Error..." in the logs and I wasn't using fragments. Could we get a log output, perhaps a Warning, for a timeout? Or some way in the API to detect a timeout, so that I can log it appropriately (or is another error code allowed by the standard?). I'd like to track how often it happens. It's not critical though.

I have a longer timeout and did a test serving 500 concurrent WebSocket connections doing ping-pong messaging. None of them disconnected, even via the load balancer.

*Motor was causing issues on initial connection, but I don't look at the DB after that. So it wasn't likely the issue here. If it intereferes with other connections I'll see it now, as I log the exception better.

[aaugustin]

A log message containing timed out waiting for pong is emitted at the DEBUG level when a ping times out.

Since WebSocket connections are long lived, this tends to happen quite often, which is why it's only at the DEBUG level.

[aaugustin]

The suggested improvement here would be to raise a specific ConnectionClosed exception when a ping timed out.

[aaugustin]

This is easily reproduced as follows:

• add , ping_interval=1, ping_timeout=1 to the example/server.py script and run it
• run the example/client.py script — it will block on the input call and the server will timeout

This gives the same stack trace:

Traceback (most recent call last):
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 756, in transfer_data
    message = await self.read_message()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 825, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 901, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 977, in read_frame
    frame = await Frame.read(
  File "/Users/myk/dev/websockets/src/websockets/legacy/framing.py", line 55, in read
    data = await reader(2)
  File "/Users/myk/.pyenv/versions/3.10-dev/lib/python3.10/asyncio/streams.py", line 708, in readexactly
    await self._wait_for_data('readexactly')
  File "/Users/myk/.pyenv/versions/3.10-dev/lib/python3.10/asyncio/streams.py", line 502, in _wait_for_data
    await self._waiter
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/myk/dev/websockets/src/websockets/legacy/server.py", line 293, in handler
    await self.ws_handler(self, path)
  File "/Users/myk/dev/websockets/example/server.py", line 10, in hello
    name = await websocket.recv()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 417, in recv
    await self.ensure_open()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 741, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: code = 1006 (connection closed abnormally [internal]), no reason

[aaugustin]

We'll need to solve #587 first.

Indeed, we need to know why the connection was closed, and we don't have this information in the close code and reason, because we never receive them when we fail the connection.

[aaugustin]

After 0cce70a and #998 this should be fixed.

[aaugustin]

It is reported as:

connection handler failed
Traceback (most recent call last):
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 813, in transfer_data
    message = await self.read_message()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 882, in read_message
    frame = await self.read_data_frame(max_size=self.max_size)
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 958, in read_data_frame
    frame = await self.read_frame(max_size)
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 1012, in read_frame
    frame = await Frame.read(
  File "/Users/myk/dev/websockets/src/websockets/legacy/framing.py", line 83, in read
    data = await reader(2)
  File "/Users/myk/.pyenv/versions/3.10-dev/lib/python3.10/asyncio/streams.py", line 708, in readexactly
    await self._wait_for_data('readexactly')
  File "/Users/myk/.pyenv/versions/3.10-dev/lib/python3.10/asyncio/streams.py", line 502, in _wait_for_data
    await self._waiter
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/myk/dev/websockets/src/websockets/legacy/server.py", line 305, in handler
    await self.ws_handler(self, path)
  File "/Users/myk/dev/websockets/example/server.py", line 9, in hello
    name = await websocket.recv()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 461, in recv
    await self.ensure_open()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 798, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: sent 1011 (unexpected error) keepalive ping timeout; no close frame received

which is clear.

So closing as a duplicate of #587.