[Libwebsockets] sporadic connection close on Rx

Roman Nikiforov rnikiforov at gmx.net
Fri Nov 5 14:05:54 CET 2021


> What I suggest is enable the cmake option LWS_TLS_LOG_PLAINTEXT_RX and 
> see what is actually read from the server, and if we can see the 
> breakage, confirm what the server thinks it sent on tls for those 
> packets.
>
I recompiled with this define. In case RX fails usually there is 
"illegal opcode" message from lws_ws_client_rx_sm. But I also had 
"disordered continuation" and "illegal rsv bits set". I added opcode and 
c function parameter output in log and they have different values every 
time:

lws_ws_client_rx_sm: opcode=4, c=100

lws_ws_client_rx_sm: opcode=13, c=109

lws_ws_client_rx_sm: opcode=12, c=108

lws_ws_client_rx_sm: opcode=3, c=67

lws_ws_client_rx_sm: opcode=11, c=107

Usual log output before connection close:

[2021/11/05 12:17:16:4626] N: 0FD0: 69 35 72 6A 75 4F 56 63 66 54 5A 35 
68 59 63 2B    i5rjuOVcfTZ5hYc+
[2021/11/05 12:17:16:4626] N: 0FE0: 30 4C 4C 6C 47 58 68 36 62 4E 76 70 
46 4B 5A 2B    0LLlGXh6bNvpFKZ+
[2021/11/05 12:17:16:4626] N: 0FF0: 6A 38 44 4F 59 6B 68 69 76 6C 4D 72 
4E 55 66 7A    j8DOYkhivlMrNUfz
[2021/11/05 12:17:16:4626] N:
[2021/11/05 12:17:16:4626] D: lws_read_h1: h1 path: wsi state 0x119
[2021/11/05 12:17:16:4626] D: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_handshake_client: hs 
client feels it has 4096 in
[2021/11/05 12:17:16:4626] D: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: 
spilling as we have the whole frame
[2021/11/05 12:17:16:4626] D: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: 
starting disbursal of 2048 deframed rx
[2021/11/05 12:17:16:4627] X: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: +++ 
passing 2048 0x7f60080084b0 to ext
[2021/11/05 12:17:16:4627] X: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: Ext RX 
returned 0
[2021/11/05 12:17:16:4627] X: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: post 
inflate ebuf in len 2048 / out len 2048
[2021/11/05 12:17:16:4627] X: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: 
removing from draining ext list
[2021/11/05 12:17:16:4627] U: [lwshelper.cpp:88 callback()] < 2048 chars
[2021/11/05 12:17:16:4627] U: [lwshelper.cpp:89 callback()] < 
4kaYgzIySwc+BNtGzwBeAxYdQBM0zAJ8vnJYEoq6w1xJgQupg4
[2021/11/05 12:17:16:4627] D: lws_is_final_fragment: final 1, rx pk 
length 0, draining 0
[2021/11/05 12:17:16:4627] U: [lwshelper.cpp:97 callback()] got final 
fragment. rx size: 696320
[2021/11/05 12:17:16:4628] D: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: bulk 
ws rx: inp used 2048, output 2048
[2021/11/05 12:17:16:4628] I: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: 
illegal opcode
[2021/11/05 12:17:16:4628] I: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_client_rx_sm: 
opcode=4, c=100
[2021/11/05 12:17:16:4628] I: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lws_ws_handshake_client: 
client_rx_sm exited, DROPPING 3824
[2021/11/05 12:17:16:4628] I: 
[wsicli|0|WS/h1/default/medrepo.de|default]: __lws_close_free_wsi: 
caller: lws_read_h1 bail
[2021/11/05 12:17:16:4629] D: 
[wsicli|0|WS/h1/default/medrepo.de|default]: __lws_close_free_wsi: real 
just_kill_connection A: (sockfd 8)
[2021/11/05 12:17:16:4629] I: 
[wsicli|0|WS/h1/default/medrepo.de|default]: __lws_close_free_wsi: real 
just_kill_connection: sockfd 8
[2021/11/05 12:17:16:4629] D: 
[wsicli|0|WS/h1/default/medrepo.de|default]: lwsi_set_state: 
lwsi_set_state 0x10000119 -> 0x10000020
[2021/11/05 12:17:16:4629] I: 
[wsicli|0|WS/h1/default/medrepo.de|default]: __lws_close_free_wsi: cce=1
[2021/11/05 12:17:16:4629] U: [lwshelper.cpp:142 callback()] Connection 
closed



More information about the Libwebsockets mailing list