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

[Olivier Langlois]

Maybe something relevant to my problem. I took the code directly from
lws client example and there is this code that I don't quite fully
understand the implications...

    if (pss->write_consume_pending) {
        /* perform the deferred fifo consume */
        lws_ring_consume_single_tail(pss->ring, &pss->tail, 1);
        pss->write_consume_pending = 0;
    }
...
    /*
     * Workaround deferred deflate in pmd extension by only
     * consuming the fifo entry when we are certain it has been
     * fully deflated at the next WRITABLE callback.  You only need
     * this if you're using pmd.
     */
    pss->write_consume_pending = 1;
    lws_callback_on_writable(wsi);

On Thu, 2020-11-12 at 10:12 -0500, Olivier Langlois wrote:
> 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
> 
> _______________________________________________
> Libwebsockets mailing list
> Libwebsockets at ml.libwebsockets.org
> https://libwebsockets.org/mailman/listinfo/libwebsockets