uvicorn doesn't seem to pass websocket 'subprotocol' correctly back to client

[Kludex]

Discussed in #1777

^{Originally posted by villekr November 26, 2022}
Full example demonstrating the problem is here https://github.com/villekr/uvicorn-websockets-example.

python 3.10.2.
uvicorn 0.20.0
websockets 10.4

During websocket connection I'm sending "websocket.accept" with specific "subprotocol" value. Looks like that uvicorn correctly gets that value and sends it to client as 'Sec-WebSocket-Protocol' header but it also sends 'sec-websocket-protocol' header with all supported subprotocols. Websockets library requires exactly one subprotocol value and therefore errors out in this situation.

Is this a bug or should I use uvicorn differently?

Logs from server (uvicorn with debug loglevel):

INFO:     Started server process [31158]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:9000 (Press CTRL+C to quit)
DEBUG:    = connection is CONNECTING
DEBUG:    < GET / HTTP/1.1
DEBUG:    < host: localhost:9000
DEBUG:    < upgrade: websocket
DEBUG:    < connection: Upgrade
DEBUG:    < sec-websocket-key: ncSN1OGo9LCGhQIV+O8ukg==
DEBUG:    < sec-websocket-version: 13
DEBUG:    < sec-websocket-extensions: permessage-deflate; client_max_window_bits
DEBUG:    < sec-websocket-protocol: ocpp2.0.1
DEBUG:    < user-agent: Python/3.10 websockets/10.4
2022-11-26 13:19:18.635 | DEBUG    | uvicorn_websockets_example.asgi:handler:92 - scope={'type': 'websocket', 'asgi': {'version': '3.0', 'spec_version': '2.3'}, 'http_version': '1.1', 'scheme': 'ws', 'server': ('127.0.0.1', 9000), 'client': ('127.0.0.1', 54220), 'root_path': '', 'path': '/', 'raw_path': b'/', 'query_string': b'', 'headers': [(b'host', b'localhost:9000'), (b'upgrade', b'websocket'), (b'connection', b'Upgrade'), (b'sec-websocket-key', b'ncSN1OGo9LCGhQIV+O8ukg=='), (b'sec-websocket-version', b'13'), (b'sec-websocket-extensions', b'permessage-deflate; client_max_window_bits'), (b'sec-websocket-protocol', b'ocpp2.0.1'), (b'user-agent', b'Python/3.10 websockets/10.4')], 'subprotocols': ['ocpp2.0.1']}
2022-11-26 13:19:18.635 | DEBUG    | uvicorn_websockets_example.asgi:handler:95 - event={'type': 'websocket.connect'}
INFO:     ('127.0.0.1', 54220) - "WebSocket /" [accepted]
DEBUG:    > HTTP/1.1 101 Switching Protocols
DEBUG:    > Upgrade: websocket
DEBUG:    > Connection: Upgrade
DEBUG:    > Sec-WebSocket-Accept: RTByXq2XHmPDpnv6NpdnP12aqEs=
DEBUG:    > Sec-WebSocket-Extensions: permessage-deflate
DEBUG:    > Sec-WebSocket-Protocol: ocpp2.0.1
DEBUG:    > date: Sat, 26 Nov 2022 11:19:17 GMT
DEBUG:    > server: uvicorn
DEBUG:    > sec-websocket-protocol: ocpp2.0.1, ocpp2.0, ocpp1.6
INFO:     connection open
DEBUG:    = connection is OPEN
DEBUG:    ! failing connection with code 1006
DEBUG:    = connection is CLOSED
DEBUG:    x half-closing TCP connection
2022-11-26 13:19:18.636 | DEBUG    | uvicorn_websockets_example.asgi:handler:95 - event={'type': 'websocket.disconnect', 'code': 1006}
INFO:     connection closed

logs from client:

= connection is CONNECTING
> GET / HTTP/1.1
> Host: localhost:9000
> Upgrade: websocket
> Connection: Upgrade
> Sec-WebSocket-Key: uU1gy8fzdEP9Hf4z1lnsGQ==
> Sec-WebSocket-Version: 13
> Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
> Sec-WebSocket-Protocol: ocpp2.0.1
> User-Agent: Python/3.10 websockets/10.4
< HTTP/1.1 101 Switching Protocols
< Upgrade: websocket
< Connection: Upgrade
< Sec-WebSocket-Accept: Lfxa3NBPkfrDN87wlkv1oAtLS+k=
< Sec-WebSocket-Extensions: permessage-deflate
< Sec-WebSocket-Protocol: ocpp2.0.1
< date: Sat, 26 Nov 2022 11:27:07 GMT
< server: uvicorn
< sec-websocket-protocol: ocpp2.0.1, ocpp2.0, ocpp1.6
! failing connection with code 1006
x half-closing TCP connection
= connection is CLOSED
Traceback (most recent call last):
  File ".../lib/python3.10/site-packages/websockets/legacy/client.py", line 258, in process_subprotocol
    raise InvalidHandshake(f"multiple subprotocols: {subprotocols}")
websockets.exceptions.InvalidHandshake: multiple subprotocols: ocpp2.0.1, ocpp2.0.1, ocpp2.0, ocpp1.6
```</div>

[Kludex]

@villekr What happens on the wsproto implementation?

We should make use of the protocols parameter from websockets.

[villekr]

I tested the example with 'wsproto' (on the asgi server side) and the result is identical. Example code is also updated to have ws="wsproto" argument by default for now.

[villekr]

This seems to be an issue in the latest 0.20.0 release. In 0.19.0 (and also in 0.18.3) there are no extra 'sec-websocket-protocol: ocpp2.0.1, ocpp2.0, ocpp1.6' sent from server.

logs from client with uvicorn 0.20.0:

= connection is CONNECTING
> GET / HTTP/1.1
> Host: localhost:9000
> Upgrade: websocket
> Connection: Upgrade
> Sec-WebSocket-Key: 0HvnEW9ZdZu5A90nR1x7iQ==
> Sec-WebSocket-Version: 13
> Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
> Sec-WebSocket-Protocol: ocpp2.0.1
> User-Agent: Python/3.10 websockets/10.4
< HTTP/1.1 101 Switching Protocols
< Upgrade: websocket
< Connection: Upgrade
< Sec-WebSocket-Accept: 2Tl32J6ZBVtFCh1uC0Schgr4Zdg=
< Sec-WebSocket-Extensions: permessage-deflate
< Sec-WebSocket-Protocol: ocpp2.0.1
< Date: Sun, 27 Nov 2022 07:38:55 GMT
< Server: Python/3.10 websockets/10.4
= connection is OPEN
= connection is CLOSING
> CLOSE 1000 (OK) [2 bytes]
< CLOSE 1000 (OK) [2 bytes]
= connection is CLOSED

[Kludex]

It was probably introduced on #1606.

[Kludex]

You aren't supposed to send the Sec-Websocket-Protocol yourself.

The server should be in charge of doing it. It's the subprotocol the server is able to use from the list the client proposed.

[villekr]

Thanks, that's correct. My mistake.