Incorrect websocket close code on server shutdown

[jalaziz]

Checklist

• The bug is reproducible against the latest release or master.
• There are no similar issues or pull requests to fix it yet.

Describe the bug

This seems related to #1140 but may be a simpler issue.

When the server is shutdown with SIGTERM, websocket connections are terminated with a close code of 1006. This is seen on both the server and the client.

According to RFC 6455, 1006 indicates an abnormal connection termination (no Close control frame) and 1001 indicates Going Away.

Steps to reproduce the bug

1. Create websocket_test.py with:

   class App:
       def __init__(self, scope, receive, send):
           self.scope = scope
           self.receive = receive
           self.send = send
   
       def __await__(self):
           return self.asgi().__await__()
   
       async def asgi(self):
           while True:
               message = await self.receive()
               message_type = message["type"].replace(".", "_")
               print(message)
               handler = getattr(self, message_type, None)
               if handler is not None:
                   await handler(message)
               if message_type == "websocket_disconnect":
                   break
   
       async def websocket_connect(self, message):
           await self.send({"type": "websocket.accept"})
   

2. Run uvicorn --ws-ping-interval 5 --ws-ping-timeout 5 --log-level debug --lifespan off websocket_test:App
3. Connect using a websocket client
4. Kill the server with Ctrl+C or sending a SIGTERM signal
5. Observe that both the server and client connections are closed with code 1006.

Expected behavior

uvicorn should send a Close frame and the client connection should be closed with code 1001.

Actual behavior

Client connection is closed with code 1006.

Debugging material

No response

Environment

• uvicorn 0.17.1 with CPython 3.10.1 on Darwin
• uvicorn --ws-ping-interval 5 --ws-ping-timeout 5 --log-level debug --lifespan off websocket_test:App

Additional context

When testing with daphne, the server close code is 1001 and the client close code is 1006.

Looking at the WebSocketCommonProtocol, there is a close method that properly implements the close handshake. However, it is not called from the WebSocketProtocol class on shutdown in uvicorn (although it is called as part of unwinding handler in WebSocketServerProtocol). Not calling transport.close from shutdown may solve the problem, but need to test it.

[jkklapp]

I just reproduced the issue and confirmed the code 1006 is used even after commenting out

diff --git a/uvicorn/protocols/websockets/websockets_impl.py b/uvicorn/protocols/websockets/websockets_impl.py
index 9a07a5d..a90dc1c 100644
--- a/uvicorn/protocols/websockets/websockets_impl.py
+++ b/uvicorn/protocols/websockets/websockets_impl.py
@@ -97,7 +97,7 @@ class WebSocketProtocol(websockets.WebSocketServerProtocol):
 
     def shutdown(self):
         self.ws_server.closing = True
-        self.transport.close()
+        # self.transport.close()
 
     def on_task_complete(self, task):
         self.tasks.discard(task)

The terminal output

^CINFO:     Shutting down
INFO:     Waiting for connections to close. (CTRL+C to force quit)
DEBUG:    ! failing connection with code 1006
DEBUG:    = connection is CLOSED
DEBUG:    x half-closing TCP connection
INFO:     connection closed
INFO:     Finished server process [3676]

[Kludex]

• This was closed by Check if handshake is completed before sending frame on wsproto shutdown #1737.

It will be available on Uvicorn 0.20.0.

[jalaziz]

@Kludex this is still an issue unfortunately, even with 0.20.0.

Here's what I'm seeing:

1. Start server using example above with uvicorn --ws-ping-interval 5 --ws-ping-timeout 5 --log-level debug --lifespan off websocket_test:App.
2. Connect a client with python -m websockets "ws://127.0.0.1:8000"
3. Terminate server gracefully (Ctrl+C or TERM)

Server output:

INFO:     Started server process [51276]
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
DEBUG:    = connection is CONNECTING
DEBUG:    < GET / HTTP/1.1
DEBUG:    < host: 127.0.0.1:8000
DEBUG:    < upgrade: websocket
DEBUG:    < connection: Upgrade
DEBUG:    < sec-websocket-key: b3JBG07qZaR91p1Wh6jx6Q==
DEBUG:    < sec-websocket-version: 13
DEBUG:    < sec-websocket-extensions: permessage-deflate; client_max_window_bits
DEBUG:    < user-agent: Python/3.9 websockets/8.1
{'type': 'websocket.connect'}
INFO:     ('127.0.0.1', 54434) - "WebSocket /" [accepted]
DEBUG:    > HTTP/1.1 101 Switching Protocols
DEBUG:    > Upgrade: websocket
DEBUG:    > Connection: Upgrade
DEBUG:    > Sec-WebSocket-Accept: p0F1WTQ9R+c4afLilnTByg0oBZQ=
DEBUG:    > Sec-WebSocket-Extensions: permessage-deflate
DEBUG:    > date: Mon, 26 Dec 2022 10:35:34 GMT
DEBUG:    > server: uvicorn
INFO:     connection open
DEBUG:    = connection is OPEN
^CINFO:     Shutting down
DEBUG:    = connection is CLOSED
DEBUG:    ! failing connection with code 1006
DEBUG:    x half-closing TCP connection
{'type': 'websocket.disconnect', 'code': 1012}
INFO:     connection closed
INFO:     Finished server process [51276]

Client output:

Connected to ws://127.0.0.1:8000.
Connection closed: code = 1006 (connection closed abnormally [internal]), no reason.

This is happening for both the websockets and wsproto implementations.

[Kludex]

Can you please try with another client? The server logs point out that we are sending 1012, which is the intention.

[Kludex]

I've tested with https://github.com/websockets/wscat, and indeed, this is still happening, but only on websockets implementation. The wsproto works as expected.

[Kludex]

@jalaziz can you check if #1816 solves the issue?

[Kludex]

It does solve.

I've added tests to check what the client receives. 🙏

[jalaziz]

It does solve.

I've added tests to check what the client receives. 🙏

Indeed, it solves it with wscat, but not websockets (trying to understand why). I'm trying a few other clients, will report back shortly.

Update: nevermind, the websockets issue appears to be a bug in the __main__.py script. I was accidentally using an testing with an older version of websockets. The latest version (10.4) shows the correct codes.