[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:56:13 CET 2020


I did fix my problem by changing the return value in extension-
permessage-deflate.c:

	case LWS_EXT_CB_PAYLOAD_RX:
		lwsl_ext(" %s: LWS_EXT_CB_PAYLOAD_RX: in %d, existing
in %d\n",
			 __func__, pmdrx->eb_in.len, priv-
>rx.avail_in);

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

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



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




More information about the Libwebsockets mailing list