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

Olivier Langlois olivier at olivierlanglois.net
Thu Nov 12 22:12:20 CET 2020


There seems to be a problem in lws_ws_client_rx_sm():

If there is no extension, lws_ext_cb_active() returns 0 (PMDR_UNKNOWN)

enum pmd_return {
        PMDR_UNKNOWN,
        PMDR_DID_NOTHING,
        PMDR_HAS_PENDING,
        PMDR_EMPTY_NONFINAL,
        PMDR_EMPTY_FINAL,

        PMDR_FAILED = -1
};

If pms ext is active and because the first message appears to not be
compressed, it does return PMDR_DID_NOTHING

		/* if this frame is not marked as compressed, we
ignore it */

		if (!(wsi->ws->rsv_first_msg & 0x40) || (wsi->ws-
>opcode & 8))
			return PMDR_DID_NOTHING;

and this makes lws_ws_client_rx_sm() skip calling the callback for
LWS_CALLBACK_CLIENT_RECEIVE.

I am not sure exactly how yet but maybe this condition in
lws_ws_client_rx_sm():

                        if (n == PMDR_DID_NOTHING)
                                break;
should be modified...

perhaps it should be

                        if (n == PMDR_HAS_PENDING)
                                break;

Comments?


On Thu, 2020-11-12 at 15:35 -0500, Olivier Langlois wrote:
> My last glitch discovery did improve things a bit but I am now
> stumbling into a new problem. After having fixed my rx_buffer_size
> problem, the initial server greeting WS message is passed to the pms
> ext but nothing ever come out of it and the connection eventually
> times
> out:
> 
> [2020-11-12 15:29:23] INFO WSCONT/log_emit_function 79522: Allocating
> client RX buffer 1040
> 
> [2020-11-12 15:29:23] INFO WSBASE/callback
> LWS_CALLBACK_CLIENT_ESTABLISHED: 79522
> [2020-11-12 15:29:23] INFO WSCONT/log_emit_function 79522: SSL
> Capable
> more service
> 
> [2020-11-12 15:29:23] DBUG WSCONT/log_emit_function 79522:
> lws_ws_client_rx_sm:    This RX frame Final 1
> 
> [2020-11-12 15:29:23] DBUG WSCONT/log_emit_function 79522:
> lws_ws_client_rx_sm: +++ passing 96 0x561f0b6a8420 to ext
> 
> [2020-11-12 15:29:23] DBUG WSCONT/log_emit_function 79522: 
> lws_extension_callback_pm_deflate: LWS_EXT_CB_PAYLOAD_RX: in 96,
> existing in 0
> 
> [2020-11-12 15:29:23] DBUG WSCONT/log_emit_function 79522: Ext RX
> returned 1
> 
> [2020-11-12 15:29:53] EROR WSBASE/idle 79522 dead connection
> detected.
> Closing the connection
> [2020-11-12 15:29:54] INFO WSCONT/log_emit_function 79522: wsi
> 0x561f0b6965c0: TIMEDOUT WAITING on 27 (did hdr 1, ah (nil), wl 0)
> 
> [2020-11-12 15:29:54] INFO WSCONT/log_emit_function 79522:
> __lws_close_free_wsi: 0x561f0b6965c0: caller: timeout
> 
> [2020-11-12 15:29:54] DBUG WSCONT/log_emit_function 79522:
> lws_extension_callback_pm_deflate: LWS_EXT_CB_DESTROY
> 
> [2020-11-12 15:29:54] INFO WSBASE/client_closed
> LWS_CALLBACK_CLIENT_CLOSED: 79522
> [2020-11-12 15:29:54] INFO KRAKENWS/getReconnTO Retrying in 2 seconds
> [2020-11-12 15:29:54] INFO WSBASE/callback LWS_CALLBACK_WSI_DESTROY:
> 79522
> [2020-11-12 15:29:54] INFO WSCONT/log_emit_function 79522:
> lws_vhost_unbind_wsi: vh default: count_bound_wsi 0
> 
> 
> On Thu, 2020-11-12 at 14:57 -0500, Olivier Langlois wrote:
> > I have recompiled lws in Debug to get more details about my
> > problem...
> > Not what I was looking for but maybe worth sharing...
> > 
> > I get this trace with the debug build:
> > [2020-11-12 14:29:46] INFO WSCONT/log_emit_function 76192: 
> > permessage-
> > deflate requires the protocol (kraken-priv) to have an RX buffer >=
> > 128
> > 
> > The weird thing is that this trace is enabled in the Release build
> > but
> > doesn't appear in the release run.
> > 
> > This tells me that
> > 
> > context->pt_serv_buf_size
> > or
> > wsi->protocol->rx_buffer_size
> > 
> > is assigned a different value in debug than in release build.
> > 
> > This is unexpected...
> > 
> > I think that I did found my problem...
> > 
> > It comes from the fact that I derived my code from
> > lws_minimal_client_echo.c
> > 
> > where:
> > 
> > #define RING_DEPTH 1024
> > 
> > #define LWS_PLUGIN_PROTOCOL_MINIMAL_CLIENT_ECHO \
> >         { \
> >                 "lws-minimal-client-echo", \
> >                 callback_minimal_client_echo, \
> >                 sizeof(struct
> > per_session_data__minimal_client_echo),
> > \
> >                 1024, \
> >                 0, NULL, 0 \
> >         }
> > 
> > I did 2 consecutive changes spaced by some period of time so they
> > went
> > unnoticed.
> > 
> > First, I did observeve that the protocol rx_buffer_size was the
> > same
> > value than RING_DEPTH, therefore, I did set my protocol
> > rx_buffer_size
> > to RING_DEPTH.
> > 
> > Next, I did figured that my application wasn't sending out that
> > much
> > messages therefore, I did change my RING_DEPTH value to 16...
> > 
> > This makes my lws usage incredibly inefficient as my callback is
> > called
> > for every 16 bytes received and also pmd ext code doesn't like the
> > value at all... 
> > 
> > On Thu, 2020-11-12 at 10:26 -0500, Olivier Langlois wrote:
> > > 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","st
> > > > a
> > > > [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","st
> > > > at
> > > > us
> > > > ":
> > > > "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
> > > 
> > > 
> > > _______________________________________________
> > > Libwebsockets mailing list
> > > Libwebsockets at ml.libwebsockets.org
> > > https://libwebsockets.org/mailman/listinfo/libwebsockets
> > 
> > 
> > _______________________________________________
> > Libwebsockets mailing list
> > Libwebsockets at ml.libwebsockets.org
> > https://libwebsockets.org/mailman/listinfo/libwebsockets
> 
> 
> _______________________________________________
> Libwebsockets mailing list
> Libwebsockets at ml.libwebsockets.org
> https://libwebsockets.org/mailman/listinfo/libwebsockets




More information about the Libwebsockets mailing list