<div dir="ltr"><div dir="ltr"><div dir="ltr"><div>Hi Andy,</div><div> thanks for your help.</div><div><br></div><div></div><div dir="ltr">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);'.</div><div dir="ltr">headlen-headpos is 3968, but len is 4062. The latter originates from rops_handle_POLLIN_ws (result of lws_read_h1).</div><div dir="ltr"><br></div><div>Here is the log:</div><div>[...]<br></div><div>1557141846.793    IO: [0001] RX disable<br>1557141846.793  LWSL: INFO   : lws_rx_flow_control: 00DB87C0 0x0<br>1557141846.793  LWSL: INFO   : lws_rx_flow_control: 00DB87C0: bitmap 0x1: en 0x4001, ch 0x2<br>1557141846.793  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 11 -> 11<br>1557141846.793  LWSL: INFO   : rxflow: wsi 00DB87C0 change_to 0<br>1557141846.793  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 11 -> 2<br>1557141846.793  LWSL: DEBUG  : lws_ws_rx_sm: ws fragment length exhausted<br>1557141846.793  LWSL: PARSER : spill on flare<br>1557141846.793  LWSL: INFO   : lws_parse_ws: doing rxflow<br>1557141846.793  LWSL: INFO   : lws_buflist_append_segment: len 4062 first 1 00000000<br>1557141846.794  LWSL: DEBUG  : _realloc: size 4078: lws_buflist_append_segment<br>1557141846.794  LWSL: DEBUG  : lws_rxflow_cache: added 00DB87C0 to rxflow list<br>1557141846.794  LWSL: PARSER : lws_parse_ws: cached 4062<br>1557141846.794  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 2 -> 0<br>1557141846.794  LWSL: DEBUG  : lws_handle_POLLOUT_event: 00DB87C0: non mux: wsistate 0x20000117, ops ws<br>1557141846.794  LWSL: INFO   : lws_issue_raw: ssl_capable_write (103) says 103<br>1557141846.794  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 0 -> 2<br>1557141846.794    IO: [0001] ws transmitted 101 bytes (0ms)<br>1557141846.795  LWSL: INFO   : rops_handle_POLLIN_ws: flowcontrolled, ignoring rx<br>1557141846.795  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 2 -> 2<br>1557141846.795  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 2 -> 0<br>1557141846.795  LWSL: DEBUG  : lws_handle_POLLOUT_event: 00DB87C0: non mux: wsistate 0x20000117, ops ws<br>1557141846.795  LWSL: INFO   : lws_issue_raw: ssl_capable_write (58) says 58<br>1557141846.795    IO: [0001] RX enable<br>1557141846.795  LWSL: INFO   : lws_rx_flow_control: 00DB87C0 0x1<br>1557141846.795  LWSL: INFO   : lws_rx_flow_control: 00DB87C0: bitmap 0x0: en 0x6001, ch 0x3<br>1557141846.795  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 0 -> 2<br>1557141846.796    IO: [0001] ws transmitted 56 bytes (1ms)<br>1557141846.796  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 2 -> 2<br>1557141846.796  LWSL: INFO   : draining buflist (len 4062)<br>1557141846.796  LWSL: DEBUG  : lws_read_h1: h1 path: wsi state 0x117<br>1557141846.796  LWSL: DEBUG  : lws_parse_ws: received 4062 byte packet<br>1557141846.796  LWSL: INFO   : lws_ws_frame_rest_is_payload: using 88 of raw input (total 4056 on offer)<br>1557141846.796    IO: [0001] ws received 88 bytes<br>1557141846.808   CMD: [0001][000001] Finished bufferLoad (11ms)<br>1557141846.808  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 2 -> 2<br>1557141846.809  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 2 -> 2<br>1557141846.810    IO: [0001] RX disable<br>1557141846.810  LWSL: INFO   : lws_rx_flow_control: 00DB87C0 0x0<br>1557141846.810  LWSL: INFO   : lws_rx_flow_control: 00DB87C0: bitmap 0x1: en 0x4001, ch 0x2<br>1557141846.810  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 2 -> 2<br>1557141846.811  LWSL: DEBUG  : _lws_change_pollfd: wsi 00DB87C0: fd 376 events 2 -> 2<br>1557141846.811  LWSL: DEBUG  : lws_ws_rx_sm: ws fragment length exhausted<br>1557141846.811  LWSL: PARSER : spill on flare<br>1557141846.811  LWSL: INFO   : lws_parse_ws: doing rxflow<br>1557141846.811  LWSL: DEBUG  : lws_rxflow_cache: trim existing rxflow 4062 -> 3968<br>1557141846.811  LWSL: PARSER : lws_parse_ws: cached 3968<br><br></div><div><br></div></div></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">Am Di., 23. Apr. 2019 um 15:58 Uhr schrieb Ralf Dreesen <<a href="mailto:rdre80x@gmail.com">rdre80x@gmail.com</a>>:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Hi,</div><div>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.</div><div>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.<br></div><div><br></div><div>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.</div><div>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.</div><div>Is this correct and reasonable?<br></div><div><br></div><div>Thanks in advance,</div><div>   Ralf<br></div><div dir="ltr"><br></div><div dir="ltr">1556018788.850    IO: [0001] RX enable<br>1556018788.850  LWSL: INFO   : lws_rx_flow_control: 0083F860 0x1<br>1556018788.850  LWSL: INFO   : lws_rx_flow_control: 0083F860: bitmap 0x0: en 0x6001, ch 0x3<br>1556018788.854    IO: [0001] ws transmitted 87 bytes (5ms)<br>1556018788.854  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 0 -> 2<br>1556018788.854  LWSL: INFO   : draining buflist (len 411)<br>1556018788.855  LWSL: DEBUG  : lws_read_h1: h1 path: wsi state 0x117<br>1556018788.855  LWSL: DEBUG  : lws_parse_ws: received 411 byte packet<br><i>*** PROCESS 129 of 403 BYTES, 274 REMAINING TO BE PROCESSED</i><br>1556018788.855  LWSL: INFO   : lws_ws_frame_rest_is_payload: using 129 of raw input (total 403 on offer)<br>1556018788.855    IO: [0001] ws received 129 bytes<br>1556018788.858  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 2 -> 2<br>1556018788.859  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 2 -> 2<br>1556018788.859    IO: [0001] RX disable<br>1556018788.859  LWSL: INFO   : lws_rx_flow_control: 0083F860 0x0<br>1556018788.859  LWSL: INFO   : lws_rx_flow_control: 0083F860: bitmap 0x1: en 0x4001, ch 0x2<br>1556018788.859  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 2 -> 2<br>1556018788.859  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 2 -> 2<br>1556018788.859  LWSL: DEBUG  : lws_ws_rx_sm: ws fragment length exhausted<br>1556018788.860  LWSL: PARSER : spill on flare<br>1556018788.860  LWSL: INFO   : lws_parse_ws: doing rxflow<br>1556018788.860  LWSL: INFO   : lws_rxflow_cache: staying in rxflow buf<br><i>*** CACHE 274 REMAINING BYTES</i><br>1556018788.860  LWSL: PARSER : lws_parse_ws: cached 274<br><i>*** DISCARDS CACHED BYTES?</i><br>1556018788.860  LWSL: INFO   : lws_buflist_aware_consume: draining rxflow: used 411, next 0<br>1556018788.860  LWSL: INFO   : lws_buflist_aware_consume: removed 0083F860 from dll_buflist<br>1556018788.860  LWSL: INFO   : rops_handle_POLLIN_ws: 0083F860 flow buf: drained<br>1556018788.862  LWSL: INFO   : rxflow: wsi 0083F860 change_to 0<br>1556018788.862  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 2 -> 2<br>1556018788.862  LWSL: DEBUG  : _lws_plat_service_tsi: recv -1 bytes from socket 136<br>1556018788.863  LWSL: DEBUG  : _lws_plat_service_tsi: recv 0 bytes from socket 372<br>1556018788.863  LWSL: INFO   : flowcontrolled<br>1556018788.863  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 2 -> 0<br>1556018788.865  LWSL: DEBUG  : lws_handle_POLLOUT_event: 0083F860: non mux: wsistate 0x20000117, ops ws<br>1556018788.865  LWSL: INFO   : lws_issue_raw: ssl_capable_write (24419) says 24419<br>1556018788.865  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 0 -> 2<br>1556018788.865    IO: [0001] ws transmitted 24415 bytes (0ms)<br>1556018788.865  LWSL: INFO   : flowcontrolled<br>1556018788.865  LWSL: DEBUG  : _lws_plat_service_tsi: recv -1 bytes from socket 136<br>1556018788.865  LWSL: DEBUG  : _lws_plat_service_tsi: recv 0 bytes from socket 372<br>1556018788.867  LWSL: INFO   : flowcontrolled<br>1556018788.867  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 2 -> 0<br>1556018788.867  LWSL: DEBUG  : lws_handle_POLLOUT_event: 0083F860: non mux: wsistate 0x20000117, ops ws<br>1556018788.868  LWSL: INFO   : lws_issue_raw: ssl_capable_write (89) says 89<br>1556018788.868    IO: [0001] RX enable<br>1556018788.868  LWSL: INFO   : lws_rx_flow_control: 0083F860 0x1<br>1556018788.868  LWSL: INFO   : lws_rx_flow_control: 0083F860: bitmap 0x0: en 0x6001, ch 0x3<br>1556018788.872    IO: [0001] ws transmitted 87 bytes (5ms)<br>1556018788.873  LWSL: INFO   : rxflow: wsi 0083F860 change_to 1<br>1556018788.873  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 0 -> 9<br>1556018788.873  LWSL: DEBUG  : _lws_plat_service_tsi: recv -1 bytes from socket 136<br>1556018788.873  LWSL: DEBUG  : _lws_plat_service_tsi: recv 0 bytes from socket 372<br><i>*** RECEIVE 959 BYTES FROM SOCKET</i><br>1556018788.873  LWSL: DEBUG  : lws_ssl_capable_read_no_ssl: recv 959 bytes from socket 372<br>1556018788.873  LWSL: DEBUG  : lws_read_h1: h1 path: wsi state 0x117<br>1556018788.877  LWSL: DEBUG  : lws_parse_ws: received 959 byte packet<br><i>*** PROCESS 129 OF 951 BYTES RECENTLY READ FROM SOCKET (INSTEAD OF CACHED BYTES)</i><br>1556018788.878  LWSL: INFO   : lws_ws_frame_rest_is_payload: using 129 of raw input (total 951 on offer)<br>1556018788.878    IO: [0001] ws received 129 bytes<br>1556018788.880  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 9 -> 11<br>1556018788.881  LWSL: DEBUG  : _lws_change_pollfd: wsi 0083F860: fd 372 events 11 -> 11<br>1556018788.881    IO: [0001] RX disable<br><br></div></div>
</blockquote></div>