[Libwebsockets] RX Flow Control

Ralf Dreesen rdre80x at gmail.com
Tue Apr 23 15:58:25 CEST 2019


Hi,
I'm using libwebsocket 3.1.0 on Windows. After adding rx flow control to my
code (calls of lws_rx_flow_control), I encounter message-loss. I check the
server-echo example for differences to my code, but it looks similar.
I activated logging and spend quite some time debugging LWS. As far as I
can see, LWS discards cached, but unprocessed data. I'm not sure, if this
is a bug in LWS or a misuse in my application-code.

In the following log, you see the LWS debug messages (prefix LWSL), debug
messages from my application code (prefix IO) and some comments (prefix
***). I also added a log message for socket I/O in lws.
This is, what I saw during debugging: When rxflow is active in
'lws_parse_ws'  the 'buf' pointer is incremented to the end of the buffer.
'lws_read_h1' then returns the size of the entire buffer, including the
unprocessed bytes. In 'rops_handle_POLLIN_ws', this result is then passed
as 'used' parameter to 'lws_buflist_aware_consume', which discard that many
bytes from the buflist.
Is this correct and reasonable?

Thanks in advance,
   Ralf

1556018788.850    IO: [0001] RX enable
1556018788.850  LWSL: INFO   : lws_rx_flow_control: 0083F860 0x1
1556018788.850  LWSL: INFO   : lws_rx_flow_control: 0083F860: bitmap 0x0:
en 0x6001, ch 0x3
1556018788.854    IO: [0001] ws transmitted 87 bytes (5ms)
1556018788.854  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 0 -> 2
1556018788.854  LWSL: INFO   : draining buflist (len 411)
1556018788.855  LWSL: DEBUG  : lws_read_h1: h1 path: wsi state 0x117
1556018788.855  LWSL: DEBUG  : lws_parse_ws: received 411 byte packet
**** PROCESS 129 of 403 BYTES, 274 REMAINING TO BE PROCESSED*
1556018788.855  LWSL: INFO   : lws_ws_frame_rest_is_payload: using 129 of
raw input (total 403 on offer)
1556018788.855    IO: [0001] ws received 129 bytes
1556018788.858  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 2 -> 2
1556018788.859  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 2 -> 2
1556018788.859    IO: [0001] RX disable
1556018788.859  LWSL: INFO   : lws_rx_flow_control: 0083F860 0x0
1556018788.859  LWSL: INFO   : lws_rx_flow_control: 0083F860: bitmap 0x1:
en 0x4001, ch 0x2
1556018788.859  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 2 -> 2
1556018788.859  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 2 -> 2
1556018788.859  LWSL: DEBUG  : lws_ws_rx_sm: ws fragment length exhausted
1556018788.860  LWSL: PARSER : spill on flare
1556018788.860  LWSL: INFO   : lws_parse_ws: doing rxflow
1556018788.860  LWSL: INFO   : lws_rxflow_cache: staying in rxflow buf
**** CACHE 274 REMAINING BYTES*
1556018788.860  LWSL: PARSER : lws_parse_ws: cached 274
**** DISCARDS CACHED BYTES?*
1556018788.860  LWSL: INFO   : lws_buflist_aware_consume: draining rxflow:
used 411, next 0
1556018788.860  LWSL: INFO   : lws_buflist_aware_consume: removed 0083F860
from dll_buflist
1556018788.860  LWSL: INFO   : rops_handle_POLLIN_ws: 0083F860 flow buf:
drained
1556018788.862  LWSL: INFO   : rxflow: wsi 0083F860 change_to 0
1556018788.862  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 2 -> 2
1556018788.862  LWSL: DEBUG  : _lws_plat_service_tsi: recv -1 bytes from
socket 136
1556018788.863  LWSL: DEBUG  : _lws_plat_service_tsi: recv 0 bytes from
socket 372
1556018788.863  LWSL: INFO   : flowcontrolled
1556018788.863  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 2 -> 0
1556018788.865  LWSL: DEBUG  : lws_handle_POLLOUT_event: 0083F860: non mux:
wsistate 0x20000117, ops ws
1556018788.865  LWSL: INFO   : lws_issue_raw: ssl_capable_write (24419)
says 24419
1556018788.865  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 0 -> 2
1556018788.865    IO: [0001] ws transmitted 24415 bytes (0ms)
1556018788.865  LWSL: INFO   : flowcontrolled
1556018788.865  LWSL: DEBUG  : _lws_plat_service_tsi: recv -1 bytes from
socket 136
1556018788.865  LWSL: DEBUG  : _lws_plat_service_tsi: recv 0 bytes from
socket 372
1556018788.867  LWSL: INFO   : flowcontrolled
1556018788.867  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 2 -> 0
1556018788.867  LWSL: DEBUG  : lws_handle_POLLOUT_event: 0083F860: non mux:
wsistate 0x20000117, ops ws
1556018788.868  LWSL: INFO   : lws_issue_raw: ssl_capable_write (89) says 89
1556018788.868    IO: [0001] RX enable
1556018788.868  LWSL: INFO   : lws_rx_flow_control: 0083F860 0x1
1556018788.868  LWSL: INFO   : lws_rx_flow_control: 0083F860: bitmap 0x0:
en 0x6001, ch 0x3
1556018788.872    IO: [0001] ws transmitted 87 bytes (5ms)
1556018788.873  LWSL: INFO   : rxflow: wsi 0083F860 change_to 1
1556018788.873  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 0 -> 9
1556018788.873  LWSL: DEBUG  : _lws_plat_service_tsi: recv -1 bytes from
socket 136
1556018788.873  LWSL: DEBUG  : _lws_plat_service_tsi: recv 0 bytes from
socket 372
**** RECEIVE 959 BYTES FROM SOCKET*
1556018788.873  LWSL: DEBUG  : lws_ssl_capable_read_no_ssl: recv 959 bytes
from socket 372
1556018788.873  LWSL: DEBUG  : lws_read_h1: h1 path: wsi state 0x117
1556018788.877  LWSL: DEBUG  : lws_parse_ws: received 959 byte packet
**** PROCESS 129 OF 951 BYTES RECENTLY READ FROM SOCKET (INSTEAD OF CACHED
BYTES)*
1556018788.878  LWSL: INFO   : lws_ws_frame_rest_is_payload: using 129 of
raw input (total 951 on offer)
1556018788.878    IO: [0001] ws received 129 bytes
1556018788.880  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 9 -> 11
1556018788.881  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372
events 11 -> 11
1556018788.881    IO: [0001] RX disable
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://libwebsockets.org/pipermail/libwebsockets/attachments/20190423/bf36971a/attachment.htm>


More information about the Libwebsockets mailing list