[Libwebsockets] RX Flow Control

Ralf Dreesen rdre80x at gmail.com
Mon May 6 14:31:11 CEST 2019


Hi Andy,
thanks for your help.

I've now compiled latest v3.1-stable. I'm now getting an assertion in
lws_buflist_use_segment in line 'assert((*head)->pos + len <=
(*head)->len);'.
headlen-headpos is 3968, but len is 4062. The latter originates from
rops_handle_POLLIN_ws (result of lws_read_h1).

Here is the log:
[...]
1557141846.793    IO: [0001] RX disable
1557141846.793  LWSL: INFO   : lws_rx_flow_control: 00DB87C0 0x0
1557141846.793  LWSL: INFO   : lws_rx_flow_control: 00DB87C0: bitmap 0x1:
en 0x4001, ch 0x2
1557141846.793  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 11 -> 11
1557141846.793  LWSL: INFO   : rxflow: wsi 00DB87C0 change_to 0
1557141846.793  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 11 -> 2
1557141846.793  LWSL: DEBUG  : lws_ws_rx_sm: ws fragment length exhausted
1557141846.793  LWSL: PARSER : spill on flare
1557141846.793  LWSL: INFO   : lws_parse_ws: doing rxflow
1557141846.793  LWSL: INFO   : lws_buflist_append_segment: len 4062 first 1
00000000
1557141846.794  LWSL: DEBUG  : _realloc: size 4078:
lws_buflist_append_segment
1557141846.794  LWSL: DEBUG  : lws_rxflow_cache: added 00DB87C0 to rxflow
list
1557141846.794  LWSL: PARSER : lws_parse_ws: cached 4062
1557141846.794  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 2 -> 0
1557141846.794  LWSL: DEBUG  : lws_handle_POLLOUT_event: 00DB87C0: non mux:
wsistate 0x20000117, ops ws
1557141846.794  LWSL: INFO   : lws_issue_raw: ssl_capable_write (103) says
103
1557141846.794  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 0 -> 2
1557141846.794    IO: [0001] ws transmitted 101 bytes (0ms)
1557141846.795  LWSL: INFO   : rops_handle_POLLIN_ws: flowcontrolled,
ignoring rx
1557141846.795  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 2 -> 2
1557141846.795  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 2 -> 0
1557141846.795  LWSL: DEBUG  : lws_handle_POLLOUT_event: 00DB87C0: non mux:
wsistate 0x20000117, ops ws
1557141846.795  LWSL: INFO   : lws_issue_raw: ssl_capable_write (58) says 58
1557141846.795    IO: [0001] RX enable
1557141846.795  LWSL: INFO   : lws_rx_flow_control: 00DB87C0 0x1
1557141846.795  LWSL: INFO   : lws_rx_flow_control: 00DB87C0: bitmap 0x0:
en 0x6001, ch 0x3
1557141846.795  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 0 -> 2
1557141846.796    IO: [0001] ws transmitted 56 bytes (1ms)
1557141846.796  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 2 -> 2
1557141846.796  LWSL: INFO   : draining buflist (len 4062)
1557141846.796  LWSL: DEBUG  : lws_read_h1: h1 path: wsi state 0x117
1557141846.796  LWSL: DEBUG  : lws_parse_ws: received 4062 byte packet
1557141846.796  LWSL: INFO   : lws_ws_frame_rest_is_payload: using 88 of
raw input (total 4056 on offer)
1557141846.796    IO: [0001] ws received 88 bytes
1557141846.808   CMD: [0001][000001] Finished bufferLoad (11ms)
1557141846.808  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 2 -> 2
1557141846.809  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 2 -> 2
1557141846.810    IO: [0001] RX disable
1557141846.810  LWSL: INFO   : lws_rx_flow_control: 00DB87C0 0x0
1557141846.810  LWSL: INFO   : lws_rx_flow_control: 00DB87C0: bitmap 0x1:
en 0x4001, ch 0x2
1557141846.810  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 2 -> 2
1557141846.811  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376
events 2 -> 2
1557141846.811  LWSL: DEBUG  : lws_ws_rx_sm: ws fragment length exhausted
1557141846.811  LWSL: PARSER : spill on flare
1557141846.811  LWSL: INFO   : lws_parse_ws: doing rxflow
1557141846.811  LWSL: DEBUG  : lws_rxflow_cache: trim existing rxflow 4062
-> 3968
1557141846.811  LWSL: PARSER : lws_parse_ws: cached 3968



Am Di., 23. Apr. 2019 um 15:58 Uhr schrieb Ralf Dreesen <rdre80x at gmail.com>:

> 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/20190506/6ea3e555/attachment.htm>


More information about the Libwebsockets mailing list