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

Olivier Langlois olivier at olivierlanglois.net
Thu Nov 12 21:35:02 CET 2020


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","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","stat
> > > 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




More information about the Libwebsockets mailing list