WebSockets 11.0 broke Uvicorn test suite

[Kludex]

As the title says... Changelog: https://websockets.readthedocs.io/en/stable/project/changelog.html

[aaugustin]

I bisected the failure to: python-websockets/websockets@5113cd3

This commit creates a subtle change in the timing of how connections are closed: it's happening faster in 11.0 because the overhead of creating an asyncio task is removed.

This would explain why #1929 (comment) reports that the connection reaches the CLOSING state with 11.0 while it's still OPEN with 10.4.

[aaugustin]

The docstring says:

The ASGI callable should return 'None'. If it doesn't make sure that
the connection is closed with an error condition.

The test includes an ASGI callable that returns something other than None. So we expect the connection to be closed with an error condition, but it doesn't anymore. I believe that the test is still valid and the code no longer works as expected with websockets 11.0.

In this context, "error condition" could be interpreted in different ways. It could mean "no closing handshake" (which was the behavior with websockets 10.4) or "closing handshake with an error code" (close code 1011 with an explicit error message would make sense here). As a reminder, close code 1006 is a synthetic code for "TCP connection was closed brutally, there was no close coed". I looked at the ASGI spec but didn't find anything about the return value of the ASGI callable. I'm mentioning this in case it opens easier ways to fix the issue.

[Kludex]

I looked at the ASGI spec but didn't find anything about the return value of the ASGI callable.

It's just that we enforce the interface:

async def app(scope, receive, send) -> None:
   ...

Thanks. I'll take a look.

[aaugustin]

I bumped the log level and captured these logs of a failing test:

---------------------------------------------------------------------- Captured stderr call -----------------------------------------------------------------------
INFO:     Started server process [55815]
INFO:     Uvicorn running on http://127.0.0.1:60244 (Press CTRL+C to quit)
INFO:     ('127.0.0.1', 60245) - "WebSocket /" [accepted]
ERROR:    ASGI callable should return None, but returned '123'.
INFO:     connection open
INFO:     connection closed
INFO:     Shutting down
------------------------------------------------------------------------ Captured log call ------------------------------------------------------------------------
INFO     uvicorn.error:server.py:76 Started server process [55815]
INFO     uvicorn.error:server.py:218 Uvicorn running on http://127.0.0.1:60244 (Press CTRL+C to quit)
DEBUG    websockets.client:protocol.py:254 = connection is CONNECTING
DEBUG    websockets.client:client.py:114 > GET / HTTP/1.1
DEBUG    websockets.client:client.py:116 > Host: 127.0.0.1:60244
DEBUG    websockets.client:client.py:116 > Upgrade: websocket
DEBUG    websockets.client:client.py:116 > Connection: Upgrade
DEBUG    websockets.client:client.py:116 > Sec-WebSocket-Key: aL2ozbdvr0t2kdXx2bc98Q==
DEBUG    websockets.client:client.py:116 > Sec-WebSocket-Version: 13
DEBUG    websockets.client:client.py:116 > Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
DEBUG    websockets.client:client.py:116 > User-Agent: Python/3.11 websockets/11.0.dev76+g5113cd3
INFO     uvicorn.error:websockets_impl.py:276 ('127.0.0.1', 60245) - "WebSocket /" [accepted]
ERROR    uvicorn.error:websockets_impl.py:266 ASGI callable should return None, but returned '123'.
INFO     uvicorn.error:server.py:648 connection open
DEBUG    websockets.client:client.py:147 < HTTP/1.1 101 Switching Protocols
DEBUG    websockets.client:client.py:149 < Upgrade: websocket
DEBUG    websockets.client:client.py:149 < Connection: Upgrade
DEBUG    websockets.client:client.py:149 < Sec-WebSocket-Accept: 8jRMXkzBdu0WgMB4tm/5VF3OG5M=
DEBUG    websockets.client:client.py:149 < Sec-WebSocket-Extensions: permessage-deflate
DEBUG    websockets.client:client.py:149 < date: Fri, 28 Jul 2023 14:05:42 GMT
DEBUG    websockets.client:client.py:149 < server: uvicorn
DEBUG    websockets.client:protocol.py:355 = connection is OPEN
DEBUG    websockets.client:protocol.py:1167 < CLOSE 1000 (OK) [2 bytes]
DEBUG    websockets.client:protocol.py:1222 = connection is CLOSING
DEBUG    websockets.client:protocol.py:1173 > CLOSE 1000 (OK) [2 bytes]
INFO     uvicorn.error:server.py:270 connection closed
DEBUG    websockets.client:protocol.py:1492 = connection is CLOSED
INFO     uvicorn.error:server.py:264 Shutting down

We have the debug logs of the client but not of the server. I see the following sequence here with websockets 11.0:

• client (test harness) sends the opening handshake request
• server (being tested) runs the ASGI callable, sends what the client will receive, see below and reaches the path we're trying to test
• client receives the opening handshake response <-- OK
• client receives a close frame <-- this is the problem: a normal closure is initiated immediately after processing the handshake and before the connection is closed Previously, this was scheduled in a task. Presumably, this gave uvicorn time to close the TCP connection first.
• server closes the connection

---

With websockets 10.4, I'm getting this:

INFO:     Uvicorn running on http://127.0.0.1:64969 (Press CTRL+C to quit)
INFO:     ('127.0.0.1', 64970) - "WebSocket /" [accepted]
ERROR:    ASGI callable should return None, but returned '123'.
INFO:     connection open
ERROR:    closing handshake failed
Traceback (most recent call last):
  File "/Users/myk/dev/websockets/src/websockets/legacy/server.py", line 244, in handler
    await self.close()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 768, in close
    await asyncio.wait_for(
  File "/Users/myk/.pyenv/versions/3.11.2/lib/python3.11/asyncio/tasks.py", line 479, in wait_for
    return fut.result()
           ^^^^^^^^^^^^
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 1241, in write_close_frame
    await self.write_frame(True, OP_CLOSE, data, _state=State.CLOSING)
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 1214, in write_frame
    await self.drain()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 1203, in drain
    await self.ensure_open()
  File "/Users/myk/dev/websockets/src/websockets/legacy/protocol.py", line 944, in ensure_open
    raise self.connection_closed_exc()
websockets.exceptions.ConnectionClosedError: sent 1000 (OK); no close frame received

This error looks like the server attempts a closing handshake but closes the TCP connection before he can get the handshake response from the client. This wasn't a good behavior in the first place: if we're going to close the connection brutally, we shouldn't send a "1000 normal closure" close code.