[Libwebsockets] Connection issue since uWebSockets server starts accepting permessage-deflate; client_no_context_takeover extensions

Olivier Langlois olivier at olivierlanglois.net
Thu Nov 12 16:12:27 CET 2020


Hi,

I have a lws client app that did work flawlessly for months. Yesterday,
the protocol server got upgraded and the only difference that I can see
is that now they are accepting ws extensions that my client did always
offer.

The server is using https://github.com/uNetworking/uWebSockets
at least v.0.17.6 as can be seen in the server reply header
https://github.com/uNetworking/uWebSockets/releases/tag/v0.17.6

before yesterday upgrade, I suppose that they were using an older
release not supporting those extensions as the only mention of
uWbeSockets in the header was:
WebSocket-Server: uWebSockets

Here is the sequence of events:
1. WS HS completes successfully
2. Server sends a greeting message
3. LWS client sends back 2 messages which are written successfully
4. I would expect a server reply instead but I get

[2020-11-12 09:46:02] INFO WSCONT/log_emit_function 66220:
lws_ws_handshake_client: client_rx_sm exited, DROPPING 32

I will continue investigating but does someone has any idea what
'client_rx_sm exited, DROPPING 32' means?

Here are the relevant collected debug logs:
[2020-11-12 09:46:01] INFO WSCONT/log_emit_function 66220: client
request:
GET / HTTP/1.1
Pragma: no-cache
Cache-Control: no-cache
Host: ws-auth.kraken.com:443
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Key: SSG1YjpFWcFcL0qQD6BWpA==
Sec-WebSocket-Extensions: permessage-deflate;
client_no_context_takeover; client_max_window_bits
Sec-WebSocket-Version: 13

[2020-11-12 09:46:02] INFO WSCONT/log_emit_function 66220: Server
reply:
HTTP/1.1 101 Switching Protocols
Date: Thu, 12 Nov 2020 14:46:02 GMT
Connection: upgrade
Upgrade: websocket
Sec-WebSocket-Accept: nY2mx8XMJCxUurJJOWwZy2MsIpg=
Sec-WebSocket-Extensions: permessage-deflate;
client_no_context_takeover
uWebSockets: 17
CF-Cache-Status: DYNAMIC
Expect-CT: max-age=604800, report-
uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
Server: cloudflare
CF-RAY: 5f110a463ebc3fab-YUL


[2020-11-12 09:46:02] INFO WSBASE/callback
LWS_CALLBACK_ESTABLISHED_CLIENT_HTTP: 66220
[2020-11-12 09:46:02] INFO WSCONT/log_emit_function 66220: checking
client ext permessage-deflate

[2020-11-12 09:46:02] INFO WSCONT/log_emit_function 66220:
instantiating client ext permessage-deflate

[2020-11-12 09:46:02] INFO WSBASE/callback
LWS_CALLBACK_CLIENT_ESTABLISHED: 66220
[2020-11-12 09:46:02] DBUG WSBASE/client_receive
LWS_CALLBACK_CLIENT_RECEIVE:   16 (rpp    80, first 1, final 0, bin 0)
[2020-11-12 09:46:02] DBUG WSBASE/client_receive partial packet:
{"connectionID":
[2020-11-12 09:46:02] DBUG WSBASE/client_receive
LWS_CALLBACK_CLIENT_RECEIVE:   16 (rpp    64, first 0, final 0, bin 0)
[2020-11-12 09:46:02] DBUG WSBASE/client_receive partial packet:
{"connectionID":1727580561052006
[2020-11-12 09:46:02] DBUG WSBASE/client_receive
LWS_CALLBACK_CLIENT_RECEIVE:   16 (rpp    48, first 0, final 0, bin 0)
[2020-11-12 09:46:02] DBUG WSBASE/client_receive partial packet:
{"connectionID":17275805610520064599,"event":"sy
[2020-11-12 09:46:02] DBUG WSBASE/client_receive
LWS_CALLBACK_CLIENT_RECEIVE:   16 (rpp    32, first 0, final 0, bin 0)
[2020-11-12 09:46:02] DBUG WSBASE/client_receive partial packet:
{"connectionID":17275805610520064599,"event":"systemStatus","sta
[2020-11-12 09:46:02] DBUG WSBASE/client_receive
LWS_CALLBACK_CLIENT_RECEIVE:   16 (rpp    16, first 0, final 0, bin 0)
[2020-11-12 09:46:02] DBUG WSBASE/client_receive partial packet:
{"connectionID":17275805610520064599,"event":"systemStatus","status":"o
nline","v
[2020-11-12 09:46:02] DBUG WSBASE/client_receive
LWS_CALLBACK_CLIENT_RECEIVE:   16 (rpp     0, first 0, final 1, bin 0)
[2020-11-12 09:46:02] INFO KRAKENWS/processSystemStatus 66220
Connection 17275805610520064599 with Kraken v1.4.1 status: online
[2020-11-12 09:46:02] DBUG KRAKENWS/Initial Received signal
CLIENT_ESTABLISHED in state initial
[2020-11-12 09:46:02] DBUG WSBASE/sendPayload Added a 112 msg with
lws_ring_insert(). ring_free_num: 15
[2020-11-12 09:46:02] DBUG WSBASE/sendPayload Added a 128 msg with
lws_ring_insert(). ring_free_num: 14
[2020-11-12 09:46:02] DBUG WSBASE/client_writeable
LWS_CALLBACK_CLIENT_WRITEABLE
[2020-11-12 09:46:02] DBUG WSBASE/client_writeable wrote 112: flags:
0x0 first: 1 final 1
[2020-11-12 09:46:02] DBUG WSBASE/client_writeable
LWS_CALLBACK_CLIENT_WRITEABLE
[2020-11-12 09:46:02] DBUG WSBASE/client_writeable wrote 128: flags:
0x0 first: 1 final 1
[2020-11-12 09:46:02] DBUG WSBASE/client_writeable
LWS_CALLBACK_CLIENT_WRITEABLE
[2020-11-12 09:46:02] DBUG WSBASE/client_writeable nothing in ring
[2020-11-12 09:46:02] INFO WSCONT/log_emit_function 66220:
lws_ws_handshake_client: client_rx_sm exited, DROPPING 32

[2020-11-12 09:46:02] INFO WSBASE/client_closed
LWS_CALLBACK_CLIENT_CLOSED: 66220

P.S.: I am still with lws v3.2.2

Thx,
Olivier



More information about the Libwebsockets mailing list