AssertionError in protocol.py

[truthrally]

I have a client program that occasionally receives an AssertionError. This occurs with both websockets 7.0 and websockets 8.0. Following is the stack trace for the latter version:

Traceback (most recent call last):
  File <snip>, line 34, in connect
    async for message in websocket:
  File "/usr/local/lib/python3.6/dist-packages/websockets/protocol.py", line 414, in __aiter__
    yield await self.recv()
  File "/usr/local/lib/python3.6/dist-packages/websockets/protocol.py", line 482, in recv
    assert self.state in [State.CLOSING, State.CLOSED]
AssertionError

When this occurs, self.state equals State.OPEN and self.messages equals zero. There does not appear to be any relationship between the occurrence of this AssertionError and the rate of messages received (i.e., it has occurred during times of both light and heavy message traffic).

[truthrally]

I enabled logging in protocol.py and added log messages just before and after the failing assertion. I also added timestamps to all of the existing log messages (not shown in the following diff output) to determine the likelihood of a race condition:

45a46
> from time import time as now
482c483,488
<         assert self.state in [State.CLOSING, State.CLOSED]
---
>         logger.debug("%s - state = %s prior to assert [%f]", self.side, self.state.name, now())
>         try:
>             assert self.state in [State.CLOSING, State.CLOSED]
>         except:
>             logger.debug("%s - state = %s assert failed [%f]", self.side, self.state.name, now())
>             raise

This is the log output when an AssertionError occurred (the final log message is printed by my code):

DEBUG:websockets.protocol:client - event = eof_received() [1563292611.387163]
DEBUG:websockets.protocol:client ! failing OPEN WebSocket connection with code 1006 [1563292611.387561]
DEBUG:websockets.protocol:client - state = OPEN prior to assert [1563292611.387824]
DEBUG:websockets.protocol:client - state = OPEN assert failed [1563292611.387904]
DEBUG:websockets.protocol:client - event = connection_lost(None) [1563292611.388148]
DEBUG:websockets.protocol:client - state = CLOSED [1563292611.388213]
DEBUG:websockets.protocol:client x code = 1006, reason = [no reason] [1563292611.388265]
ERROR: Exception occurred: <class 'AssertionError'>: () [1563292611.3884506]

The state is set to CLOSED approximately 300 microseconds after it is tested in the assertion. I realize that enabling and adding log messages changes the timing, but the behavior matches what was observed without logging.

[aaugustin]

Thank you very much for the additional information.

[aaugustin]

Here's what's happening.

eof_received() means that the network connection drops or is closed by the remote endpoint. It's a TCP half-close. This causes transfer_data to take the except EOFError branch and to call fail_connection(1006), which is visible is failing OPEN WebSocket connection with code 1006.

Since close code 1006 means the network connection is broken, fail_connection(1006) doesn't take the if code != 1006 and self.state is State.OPEN branch which sends a Close frame. As a consequence, it doesn't set self.state = State.CLOSING.

The state only changes to CLOSED with connection_lost(), which is a TCP close.

---

The state attribute is well defined in RFC 6455:

Upon either sending or receiving a Close control frame, it is said
that The WebSocket Closing Handshake is Started and that the
WebSocket connection is in the CLOSING state.

=> not appropriate: we didn't send or receive a Close frame

When the underlying TCP connection is closed, it is said that The
WebSocket Connection is Closed and that the WebSocket connection is
in the CLOSED state.

=> not appropriate: the TCP connection isn't closed

---

I think that the state attribute is a bit coarse for the internal implementation. That's why I filed #497.

---

Interestingly, the implementation of ensure_open deals with this situation, where transfer_data_task terminates while state is still OPEN:

        if self.state is State.OPEN:
            # If self.transfer_data_task exited without a closing handshake,
            # self.close_connection_task may be closing the connection, going
            # straight from OPEN to CLOSED.
            if self.transfer_data_task.done():
                await asyncio.shield(self.close_connection_task)
                raise self.connection_closed_exc()

The assertion was there to guarantee that ensure_open() would raise an exception. It predates this improvement in ensure_open(). As a consequence, I think we can simply drop it.

[aaugustin]

8.0.2 is available on PyPI with this fix.