[Libwebsockets] RX Flow Control

Andy Green andy at warmcat.com
Mon May 6 14:54:06 CEST 2019



On May 6, 2019 1:31:11 PM GMT+01:00, Ralf Dreesen <rdre80x at gmail.com> wrote:
>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).

Does master act any differently?

-Andy

>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
>>
>>


More information about the Libwebsockets mailing list