[Libwebsockets] sporadic connection close on Rx

[Roman Nikiforov]

Hi Andy,

I have a test in CI/CD pipeline where the client generates 10 Mb binary 
file, sends it via lws to server in base64 format and then receives this 
file back. There is no problem with send part, but receive part works 
unstable. Sometimes connection gets closed from client side. In server 
log I always see that file was transmitted completely. May be some 
buffer gets overflowed or something like that. I turned lws logs on. It 
seems this message reveals the problem "lws_ws_handshake_client: 
client_rx_sm exited, DROPPING 1868". Is it because processing inside 
LWS_CALLBACK_CLIENT_RECEIVE too slow? Below is the log output. Version: 
LWS: 4.2.99-v4.2.0-184-g2950fe72, NET CLI SRV H1 H2 WS ConMon IPv6-absent.

[2021/11/04 13:10:50:3489] D: [wsicli|0|WS/h1/medrepo.de|default]: 
SSL_read says 4096
[2021/11/04 13:10:50:3487] D: lws_ws_client_rx_sm: bulk ws rx: inp used 
4096, output 4096
[2021/11/04 13:10:50:3489] D: lws_read_h1: h1 path: wsi state 0x119
[2021/11/04 13:10:50:3489] D: lws_ws_handshake_client: hs client feels 
it has 4096 in
[2021/11/04 13:10:50:3490] D: lws_ws_client_rx_sm: spilling as we filled 
our rx buffer
[2021/11/04 13:10:50:3490] D: lws_ws_client_rx_sm: starting disbursal of 
4096 deframed rx
[2021/11/04 13:10:50:3490] X: lws_ws_client_rx_sm: post inflate ebuf in 
len 4096 / out len 4096
[2021/11/04 13:10:50:3490] U: [lwshelper.cpp:88 callback()] < 4096 chars 
-> LWS_CALLBACK_CLIENT_RECEIVE
[2021/11/04 13:10:50:3490] U: [lwshelper.cpp:89 callback()] < 
V9wEfIepCJeInJv78y1sv0bm7xQdyVGg47qxOaIECcMLcPwgAu
[2021/11/04 13:10:50:3491] D: lws_ws_client_rx_sm: bulk ws rx: inp used 
4096, output 4096
[2021/11/04 13:10:50:3491] D: lws_ws_client_rx_sm: spilling as we have 
the whole frame
[2021/11/04 13:10:50:3491] D: lws_ws_client_rx_sm: starting disbursal of 
2048 deframed rx
[2021/11/04 13:10:50:3491] X: lws_ws_client_rx_sm: post inflate ebuf in 
len 2048 / out len 2048
[2021/11/04 13:10:50:3492] U: [lwshelper.cpp:88 callback()] < 2048 chars 
-> LWS_CALLBACK_CLIENT_RECEIVE
[2021/11/04 13:10:50:3492] U: [lwshelper.cpp:89 callback()] < 
Oe7axoUIXi5IBIqwF5GbKPaUdv77M0IyM8smiuK1NlCbwD+pV4
[2021/11/04 13:10:50:3492] U: [lwshelper.cpp:97 callback()] got final 
fragment. rx size: 460800
[2021/11/04 13:10:50:3493] D: lws_ws_client_rx_sm: bulk ws rx: inp used 
2048, output 2048
[2021/11/04 13:10:50:3493] I: illegal rsv bits set
[2021/11/04 13:10:50:3493] I: lws_ws_handshake_client: client_rx_sm 
exited, DROPPING 1868
[2021/11/04 13:10:50:3494] I: [wsicli|0|WS/h1/medrepo.de|default]: 
__lws_close_free_wsi: caller: lws_read_h1 bail
[2021/11/04 13:10:50:3494] D: [wsicli|0|WS/h1/medrepo.de|default]: 
__lws_close_free_wsi: real just_kill_connection A: (sockfd 8)
[2021/11/04 13:10:50:3494] I: [wsicli|0|WS/h1/medrepo.de|default]: 
__lws_close_free_wsi: real just_kill_connection: sockfd 8
[2021/11/04 13:10:50:3494] D: [wsicli|0|WS/h1/medrepo.de|default]: 
lwsi_set_state: lwsi_set_state 0x10000119 -> 0x10000020
[2021/11/04 13:10:50:3494] I: [wsicli|0|WS/h1/medrepo.de|default]: 
__lws_close_free_wsi: cce=1

[2021/11/04 13:10:50:3495] U: [lwshelper.cpp:142 callback()] Connection 
closed -> LWS_CALLBACK_CLIENT_CLOSED

-- 

Roman
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://libwebsockets.org/pipermail/libwebsockets/attachments/20211104/1886a5b4/attachment-0001.htm>