Possible race condition between `websocket.sync.client.ClientConnection::send` & keepalive ping about websockets HOT 4 CLOSED

That's really weird. The opcode is 0110 which is 6. websockets doesn't declare an opcode 6.

Are you sure that this frame is sent by the websockets client to the server, rather than the opposite?

Are you able to enable debug logs and share them when the error happens? That would help me a lot.

For a quick workaround, I tried to disable the keepalive ping by setting ping_timeout=None, however, websockets.sync.client.connect does not expose this parameter, unlike its asyncio counterpart. Is it possible to disable keepalive pings for the threading variant of the library?

They aren't implemented yet in the threading variant :-) So it's not that!

from websockets.

Thanks for the speedy reply 😊

I ran the test suite again, and recorded the log file as requested. The following is what was generated (with the GET url and host redacted by myself):

= connection is CONNECTING
> GET ... HTTP/1.1
> Host: ...
> Upgrade: websocket
> Connection: Upgrade
> Sec-WebSocket-Key: TjKDbdIYPkfnFeLXFvkNJQ==
> Sec-WebSocket-Version: 13
> Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
> User-Agent: Python/3.11 websockets/11.0.3
< HTTP/1.1 101 Switching Protocols
< Alt-Svc: h3=":443"; ma=2592000
< Connection: Upgrade
< Sec-Websocket-Accept: +WjrN8tmvMfDxaJVpCvPh/V5SdM=
< Server: Caddy
< Upgrade: websocket
< Date: Tue, 16 Jan 2024 13:27:12 GMT
= connection is OPEN
> BINARY 82 a4 74 79 70 65 a8 4e 61 76 69 67 61 74 65 a4 ... 6f 61 64 2e 68 74 6d 6c [99 bytes]
< CLOSE 1005 (no status code [internal]) [0 bytes]
> CLOSE 1005 (no status code [internal]) [0 bytes]
= connection is CLOSING
< EOF
> EOF
= connection is CLOSED

This time, the websocket server complained that an invalid opcode of 3 was received. The following is another screenshot from wireshark, notice the client sending the invalid message after the server sends a close message:

from websockets.

From the client's perspective, the logs show:

1. A binary frame with a payload of 99 bytes sent from the client to the server
2. A close frame without payload sent from the server to the client (that might be the server closing the connection because it disliked what the client sent)
3. A close frame without payload sent from the client to the server (which is the proper way to complete the closing handshake)

This looks proper.

Your wireshark screenshot must be read bottom-to-top (based on timestamps). It shows:

1. A binary frame sent from the client (172.26.0.8) to the server (172.26.0.10). Its length is 86, which is less than 99, and compression isn't enabled (the server doesn't support) so we aren't looking at the same frame as in the debug logs.
2. A binary frame sent from the server to the client (length 275). This frame doesn't appear in the debug logs.
3. A close frame sent from the server to the client.
4. What looks essentially like random data sent from the client to the server. (The unknown opcode is a red herring. Some reserved bits are set too and that's illegal. Overall it looks like random data.) I have no idea how you could do that with websockets, especially after the socket is closed, which the debug logs are clearly showing.
5. A second close from the server to the client, which is illegal.

I'm unconvinced by your claim that this is generated by the websockets library. I understand that you cannot share the full code; perhaps you can share at least how you invoke connect and how you build all arguments passed to connect? Also, can you confirm that you you aren't mocking anything on which websockets depends?

from websockets.

I apologize for the delay for getting back to you; I appreciate your patience and the help that you have provided!

I guess it's back to the drawing board for me, however, I think that you are correct about the bug having nothing to do with the websocket client itself.

I will close this issue, and re-open it in case I find anything else that might be of interest to this repo 😊

from websockets.