{"action":"opened","issue":{"url":"https://api.github.com/repos/warmcat/libwebsockets/issues/1550","repository_url":"https://api.github.com/repos/warmcat/libwebsockets","labels_url":"https://api.github.com/repos/warmcat/libwebsockets/issues/1550/labels{/name}","comments_url":"https://api.github.com/repos/warmcat/libwebsockets/issues/1550/comments","events_url":"https://api.github.com/repos/warmcat/libwebsockets/issues/1550/events","html_url":"https://github.com/warmcat/libwebsockets/issues/1550","id":434449907,"node_id":"MDU6SXNzdWU0MzQ0NDk5MDc=","number":1550,"title":"lws_rx_flow_control causing connection to close under load","user":{"login":"kcunningham","id":6931377,"node_id":"MDQ6VXNlcjY5MzEzNzc=","avatar_url":"https://avatars0.githubusercontent.com/u/6931377?v=4","gravatar_id":"","url":"https://api.github.com/users/kcunningham","html_url":"https://github.com/kcunningham","followers_url":"https://api.github.com/users/kcunningham/followers","following_url":"https://api.github.com/users/kcunningham/following{/other_user}","gists_url":"https://api.github.com/users/kcunningham/gists{/gist_id}","starred_url":"https://api.github.com/users/kcunningham/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kcunningham/subscriptions","organizations_url":"https://api.github.com/users/kcunningham/orgs","repos_url":"https://api.github.com/users/kcunningham/repos","events_url":"https://api.github.com/users/kcunningham/events{/privacy}","received_events_url":"https://api.github.com/users/kcunningham/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2019-04-17T19:32:34Z","updated_at":"2019-04-17T19:32:34Z","closed_at":null,"author_association":"NONE","body":"I am using the libwebsockets 3.1 release. I am seeing a problem where the websocket connection closes when attempting to use lws_rx_flow_control. When traffic is flowing, it seems like something gets corrupted and the connection closes.\r\n\r\nIn my app, the data is being written to another file descriptor when received from the websocket. If the file descriptor is not writable, then it uses flow control to stop receiving from the websocket. Once the file descriptor is writable again, then the flow control is turned off so the app can receive from the websocket again. The app is adopting the other file descriptor and using the RAW callbacks to determine when it is writable.\r\n\r\nWhen seeing the failure in my app, I usually see a message about \"illegal opcode\" and then the connection closes:\r\n\r\n```\r\n[2019/04/17 15:30:14:1870] DEBUG: lws_read_h1: h1 path: wsi state 0x117\r\n[2019/04/17 15:30:14:1870] DEBUG: post inflate ebuf len 224\r\n[2019/04/17 15:30:14:1870] INFO: lws_rx_flow_control: 0x7db15b5e380 0x0\r\n[2019/04/17 15:30:14:1870] INFO: lws_rx_flow_control: 0x7db15b5e380: bitmap 0x1: en 0x4001, ch 0x2\r\n[2019/04/17 15:30:14:1870] DEBUG: _lws_change_pollfd: wsi 0x7db15b5e380: fd 73 events 4 -> 4\r\n[2019/04/17 15:30:14:1870] DEBUG: _lws_change_pollfd: wsi 0x7db15b5e700: fd 55 events 1 -> 5\r\n[2019/04/17 15:30:14:1870] INFO: lws_rxflow_cache: staying in rxflow buf\r\n[2019/04/17 15:30:14:1870] INFO: lws_buflist_aware_consume: draining rxflow: used 2729, next 0\r\n[2019/04/17 15:30:14:1871] INFO: lws_buflist_aware_consume: removed 0x7db15b5e380 from dll_buflist\r\n[2019/04/17 15:30:14:1871] INFO: rops_handle_POLLIN_ws: 0x7db15b5e380 flow buf: drained\r\n[2019/04/17 15:30:14:1871] INFO: rxflow: wsi 0x7db15b5e380 change_to 0\r\n[2019/04/17 15:30:14:1871] DEBUG: _lws_change_pollfd: wsi 0x7db15b5e380: fd 73 events 4 -> 4\r\n[2019/04/17 15:30:14:1871] DEBUG: rops_handle_POLLOUT_ws: my-protocol-client: wsi->ws->tx_draining_ext 0\r\n[2019/04/17 15:30:14:1871] DEBUG: _lws_change_pollfd: wsi 0x7db15b5e380: fd 73 events 4 -> 0\r\n[2019/04/17 15:30:14:1871] DEBUG: lws_handle_POLLOUT_event: 0x7db15b5e380: non mux: wsistate 0x10000117, ops ws\r\n[2019/04/17 15:30:14:1871] INFO: lws_rx_flow_control: 0x7db15b5e700 0x1\r\n[2019/04/17 15:30:14:1871] INFO: lws_rx_flow_control: 0x7db15b5e700: bitmap 0x0: en 0x6001, ch 0x3\r\n[2019/04/17 15:30:14:1871] INFO: rxflow: wsi 0x7db15b5e700 change_to 1\r\n[2019/04/17 15:30:14:1871] DEBUG: _lws_change_pollfd: wsi 0x7db15b5e700: fd 55 events 5 -> 5\r\n[2019/04/17 15:30:14:1871] INFO: flowcontrolled\r\n[2019/04/17 15:30:14:1872] INFO: lws_rx_flow_control: 0x7db15b5e380 0x1\r\n[2019/04/17 15:30:14:1872] INFO: lws_rx_flow_control: 0x7db15b5e380: bitmap 0x0: en 0x6001, ch 0x3\r\n[2019/04/17 15:30:14:1872] INFO: rxflow: wsi 0x7db15b5e380 change_to 1\r\n[2019/04/17 15:30:14:1872] DEBUG: _lws_change_pollfd: wsi 0x7db15b5e380: fd 73 events 0 -> 1\r\n[2019/04/17 15:30:14:1872] DEBUG: _lws_change_pollfd: wsi 0x7db15b5e700: fd 55 events 5 -> 1\r\n[2019/04/17 15:30:14:1872] DEBUG: lws_read_h1: h1 path: wsi state 0x117\r\n[2019/04/17 15:30:14:1872] INFO: illegal opcode\r\n[2019/04/17 15:30:14:1872] NOTICE: lws_ws_handshake_client: client_rx_sm exited, DROPPING 901\r\n[2019/04/17 15:30:14:1872] INFO: __lws_close_free_wsi: 0x7db15b5e380: caller: lws_read_h1 bail\r\n[2019/04/17 15:30:14:1872] INFO: __lws_close_free_wsi: 0x7db15b5e700: caller: general child recurse\r\n[2019/04/17 15:30:14:1872] DEBUG: __remove_wsi_socket_from_fds: wsi=0x7db15b5e700, skt=55, fds pos=3, end guy pos=4, endfd=0\r\n```\r\n\r\nI then tried reproducing this using the minimal examples. I was able to reproduce almost the same behavior with some small modifications to the pmd bulk example. I don't see the message about illegal opcode, but the connection still closes.\r\n\r\nHere is a patch of my changes to the pmd bulk client:\r\n\r\n[pmd_bulk_flow_control.txt](https://github.com/warmcat/libwebsockets/files/3091227/pmd_bulk_flow_control.txt)\r\n\r\nThe output I get when running with these changes:\r\n\r\n```\r\n[2019/04/17 15:27:20:8902] USER: LWS minimal ws client + permessage-deflate + multifragment bulk message\r\n[2019/04/17 15:27:20:8903] USER:    needs minimal-ws-server-pmd-bulk running to communicate with\r\n[2019/04/17 15:27:20:8903] USER:    ./lws-minimal-ws-client-pmd-bulk [-n (no exts)] [-c (compressible)]\r\n[2019/04/17 15:27:20:8904] NOTICE: Creating Vhost 'default' (serving disabled), 2 protocols, IPv6 off\r\n[2019/04/17 15:27:20:8920] USER: LWS_CALLBACK_CLIENT_RECEIVE: 1024 (rpp     0, last 0)\r\n[2019/04/17 15:27:20:8921] USER: Enabling flow control, setting timer\r\n[2019/04/17 15:27:20:8971] USER: Timer called, disabling flow control\r\n[2019/04/17 15:27:20:8972] USER: LWS_CALLBACK_CLIENT_RECEIVE: 1024 (rpp     0, last 0)\r\n[2019/04/17 15:27:20:8972] USER: Enabling flow control, setting timer\r\n[2019/04/17 15:27:20:9022] USER: Timer called, disabling flow control\r\n[2019/04/17 15:27:20:9022] USER: LWS_CALLBACK_CLIENT_RECEIVE: 1024 (rpp     0, last 0)\r\n[2019/04/17 15:27:20:9022] USER: echo'd data doesn't match\r\n[2019/04/17 15:27:20:9022] NOTICE: lws_ws_handshake_client: client_rx_sm exited, DROPPING 3085\r\n[2019/04/17 15:27:20:9023] NOTICE: LWS_CALLBACK_CLIENT_CLOSED\r\n[2019/04/17 15:27:21:9034] NOTICE: callback_minimal_pmd_bulk: LWS_CALLBACK_USER\r\n[2019/04/17 15:27:21:9044] USER: LWS_CALLBACK_CLIENT_RECEIVE: 1024 (rpp     0, last 0)\r\n[2019/04/17 15:27:21:9044] USER: Enabling flow control, setting timer\r\n[2019/04/17 15:27:21:9094] USER: Timer called, disabling flow control\r\n[2019/04/17 15:27:21:9095] USER: LWS_CALLBACK_CLIENT_RECEIVE: 1024 (rpp     0, last 0)\r\n[2019/04/17 15:27:21:9095] USER: Enabling flow control, setting timer\r\n[2019/04/17 15:27:21:9145] USER: Timer called, disabling flow control\r\n[2019/04/17 15:27:21:9146] USER: LWS_CALLBACK_CLIENT_RECEIVE: 1024 (rpp     0, last 0)\r\n[2019/04/17 15:27:21:9146] USER: echo'd data doesn't match\r\n[2019/04/17 15:27:21:9146] NOTICE: lws_ws_handshake_client: client_rx_sm exited, DROPPING 3085\r\n[2019/04/17 15:27:21:9146] NOTICE: LWS_CALLBACK_CLIENT_CLOSED\r\n```\r\nThe connection is closing and establishing again.\r\n\r\nAm I using something incorrectly?\r\n\r\nLet me know if you need any additional information.\r\n\r\nThanks"}}
{"actor":{"display_login":"kcunningham"}}