search

warmcat / libwebsockets

canonical libwebsockets.org networking library
https://libwebsockets.org
Other
4.79k stars 1.49k forks source link

i686-w64-mingw32 websocket LWS_CALLBACK_CLIENT_RECEIVE not get called #2339

Closed calvin2021y closed 3 years ago

calvin2021y commented 3 years ago

I build this app work on other platform but not windows:

reason2 RX2 TX2 is from websocket, reason RX TX is from raw-skt.

listen on raw socket, forward traffic to remote websocket server.

lws-team commented 3 years ago

Dunno... if I understand you, the difference starts at

[2021/07/09 13:26:47:2338] D: [wsicli|0|WS/h1/10.0.0.66]: lws_handle_POLLOUT_event: non mux: wsistate 0x10000119, ops ws

after that on Linux, it becomes a WRITEABLE callback that you handle. But it doesn't seem to happen on your windows log.

You'll need to look at lws_callback_as_writable() ./lib/core-net/service.c:28 which is called just after the last log, and see why that doesn't result in your WRITEABLE callback getting called.

calvin2021y commented 3 years ago

I use lws with libuv, libuv use IOCP (https://docs.microsoft.com/en-us/windows/win32/fileio/i-o-completion-ports). I am not sure this work with the poll method used in lws.

the debug patch:

diff --git a/lib/core-net/service.c b/lib/core-net/service.c
index 8e99f327..6f45b6b2 100644
--- a/lib/core-net/service.c
+++ b/lib/core-net/service.c
@@ -29,11 +29,11 @@ lws_callback_as_writeable(struct lws *wsi)
 {
        int n, m;

-       n = wsi->role_ops->writeable_cb[lwsi_role_server(wsi)];
+       n = wsi->role_ops->writeable_cb[lwsi_role_server(wsi)];         printf("protocol=%s callback=%p, n=%d from ./lib/core-net/service.c lws_callback_as_writeable line %d\n", wsi->a.protocol->name, wsi->a.protocol->callback, n,  __LINE__);
        m = user_callback_handle_rxflow(wsi->a.protocol->callback,
                                        wsi, (enum lws_callback_reasons) n,
                                        wsi->user_space, NULL, 0);
-
+       printf("callback=%p, m=%d, n=%d from ./lib/core-net/service.c lws_callback_as_writeable line %d\n", wsi->a.protocol->callback, m, n,  __LINE__);
        return m;
 }

diff --git a/lib/core-net/wsi.c b/lib/core-net/wsi.c
index 84c6723e..9eeeaa82 100644
--- a/lib/core-net/wsi.c
+++ b/lib/core-net/wsi.c
@@ -499,7 +499,7 @@ int user_callback_handle_rxflow(lws_callback_function callback_function,
        wsi->rxflow_will_be_applied = 0;
        if (!n)
                n = __lws_rx_flow_control(wsi);
-
+       printf("callback_function=%p, n=%d from lib/core-net/wsi.c user_callback_handle_rxflow line %d\n", callback_function, n, __LINE__);
        return n;
 }

window logs

[2021/07/09 15:39:59:4531] D: accepted new conn port 65016 on fd=1180
[ws_proxy.c:275] on_raw_server=00B7D8D0 reason: 17
[ws_proxy.c:289] 00B7D8D0 reason: 17,
[2021/07/09 15:39:59:4688] D: lws_get_idlest_tsi: 3 29999
[2021/07/09 15:39:59:4688] D: _realloc: size 900: __lws_wsi_create_with_role
[2021/07/09 15:39:59:4688] D: : lws_role_transition: wsistate 0x200, ops (unset)
[2021/07/09 15:39:59:4688] N:  ++ [wsisrv|0|adopted] (1)
[2021/07/09 15:39:59:4688] D: [wsisrv|0|adopted]: lws_create_new_server_wsi: joining vh default, tsi 0
[2021/07/09 15:39:59:4688] D: [wsisrv|0|adopted]: lws_vhost_bind_wsi: vh default: wsi none/none, count_bound_wsi 3
[2021/07/09 15:39:59:4844] D: [wsisrv|0|adopted]: lwsi_set_state: lwsi_set_state 0x20000200 -> 0x20000200
[ws_proxy.c:275] on_raw_server=00B7D8D0 reason: 29
[2021/07/09 15:39:59:4844] D: [wsisrv|0|adopted]: lws_role_transition: wsistate 0x119, ops raw-skt
[2021/07/09 15:39:59:4844] D: [wsisrv|0|adopted]: lws_ensure_user_space: protocol pss 0, user_space=00000000
[ws_proxy.c:275] on_raw_server=00B7D8D0 reason: 81
[ws_proxy.c:289] 00B7D8D0 reason: 81,
[2021/07/09 15:39:59:4844] D: _realloc: size 256: uvh
[2021/07/09 15:39:59:5001] D: [wsisrv|0|adopted]: elops_accept_uv: thr 0: sa left 2: dyn left: 4
[2021/07/09 15:39:59:5001] D: [wsisrv|0|adopted]: __insert_wsi_socket_into_fds: tsi=0, sock=1180, pos-in-fds=3
[ws_proxy.c:275] on_raw_server=00B7D8D0 reason: 62
[2021/07/09 15:39:59:5001] D: _realloc: size 900: __lws_wsi_create_with_role
[2021/07/09 15:39:59:5001] D: : lws_role_transition: wsistate 0x200, ops (unset)
[2021/07/09 15:39:59:5001] D: : lws_vhost_bind_wsi: vh default: wsi none/none, count_bound_wsi 4
[2021/07/09 15:39:59:5157] D: _realloc: size 212: client ws struct
[2021/07/09 15:39:59:5157] D: : lws_role_transition: wsistate 0x10000200, ops h1
[2021/07/09 15:39:59:5157] D: : lws_ensure_user_space: protocol pss 0, user_space=00000000
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 85
[ws_proxy.c:167] 00B7EC90 reason2: 85,
[2021/07/09 15:39:59:5157] D: _realloc: size 104: client stash
[2021/07/09 15:39:59:5157] N:  ++ [wsicli|0|WS/h1/10.0.0.66] (1)
[2021/07/09 15:39:59:5157] D: _realloc: size 948: ah struct
[2021/07/09 15:39:59:5314] D: _realloc: size 4096: ah data
[2021/07/09 15:39:59:5314] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 10 secs, reason 25
[2021/07/09 15:39:59:5314] D: [wsicli|0|WS/h1/10.0.0.66]: lws_http_client_connect_via_info2: stash 04acb610
[2021/07/09 15:39:59:5314] D: _realloc: size 10: strdup
[2021/07/09 15:39:59:5314] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_2_dnsreq: new conn on no pipeline flag
[2021/07/09 15:39:59:5314] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000200 -> 0x10000201
[2021/07/09 15:39:59:5470] D: _realloc: size 124: lws_sort_dns
[2021/07/09 15:39:59:5470] W: lws_plat_set_socket_options_ip: not implemented on windows platform
[2021/07/09 15:39:59:5470] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: WAITING_CONNECT
[2021/07/09 15:39:59:5470] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000201 -> 0x10000202
[2021/07/09 15:39:59:5626] D: _realloc: size 256: uvh
[2021/07/09 15:39:59:5626] D: [wsicli|0|WS/h1/10.0.0.66]: elops_accept_uv: thr 0: sa left 2: dyn left: 5
[2021/07/09 15:39:59:5626] D: [wsicli|0|WS/h1/10.0.0.66]: __insert_wsi_socket_into_fds: tsi=0, sock=1160, pos-in-fds=4
[2021/07/09 15:39:59:5626] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 768 -> 768
[2021/07/09 15:39:59:5626] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 5
[2021/07/09 15:39:59:5782] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 20 secs, reason 2
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 105
[ws_proxy.c:167] 00B7EC90 reason2: 105,
callback_function=00b7ec90, n=0 from lib/core-net/wsi.c user_callback_handle_rxflow line 502
[2021/07/09 15:39:59:5782] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: connect: fd 1160 errno: 10035
[2021/07/09 15:39:59:5782] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 768 -> 784
[2021/07/09 15:39:59:5782] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 15:39:59:5939] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_via_info: adoption cb 19 to h1 ws-client
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 19
[ws_proxy.c:167] 00B7EC90 reason2: 19,
[2021/07/09 15:39:59:5939] D: [wsisrv|0|adopted]: lws_role_call_adoption_bind: leaving bound to role raw-skt
[2021/07/09 15:39:59:5939] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 784 -> 768
[2021/07/09 15:39:59:5939] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 29
[ws_proxy.c:167] 00B7EC90 reason2: 29,
[2021/07/09 15:39:59:5939] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: going into connect_4
[2021/07/09 15:39:59:6095] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000202 -> 0x10000012
[2021/07/09 15:39:59:6095] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 8
[2021/07/09 15:39:59:6095] D: lws_http_client_socket_service: LRS_H1C_ISSUE_HANDSHAKE
[2021/07/09 15:39:59:6095] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 768 -> 768
[2021/07/09 15:39:59:6251] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 24
[ws_proxy.c:167] 00B7EC90 reason2: 24, quTO
[2021/07/09 15:39:59:6251] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000012 -> 0x1000020b
[2021/07/09 15:39:59:6251] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 4
[2021/07/09 15:39:59:6251] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 768 -> 784
[2021/07/09 15:39:59:6251] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 15:39:59:6407] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x1000020b -> 0x1000020b
[2021/07/09 15:39:59:6407] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 4
[2021/07/09 15:39:59:6407] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 784 -> 768
[2021/07/09 15:39:59:6407] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 15:39:59:6407] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 768 -> 768
[2021/07/09 15:39:59:6564] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 15:39:59:6564] D: [wsicli|0|WS/h1/10.0.0.66]: lws_buflist_aware_read: lws_http_client_socket_service: ssl_capable_read 213
[2021/07/09 15:39:59:6564] D: lws_http_client_socket_service: buflist-aware-read 0 213
[2021/07/09 15:39:59:6564] D: lws_client_interpret_server_handshake: no content length
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 44
[ws_proxy.c:167] 00B7EC90 reason2: 44,
[2021/07/09 15:39:59:6564] D: Selected protocol ws-client
[2021/07/09 15:39:59:6564] D: [wsicli|0|WS/h1/10.0.0.66]: lws_ensure_user_space: protocol pss 0, user_space=00000000
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 2
[ws_proxy.c:167] 00B7EC90 reason2: 2,
[2021/07/09 15:39:59:6720] D: [wsicli|0|WS/h1/10.0.0.66]: lws_role_transition: wsistate 0x10000119, ops ws
[2021/07/09 15:39:59:6720] D: _realloc: size 16404: client frame buffer
[2021/07/09 15:39:59:6720] D: handshake OK for protocol ws-client
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 3
[ws_proxy.c:171] ws connected: wsi=04ACB1A0
[2021/07/09 15:39:59:6720] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 768 -> 784
[2021/07/09 15:39:59:6876] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 15:39:59:6876] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1160 events 784 -> 768
[2021/07/09 15:39:59:6876] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 15:39:59:6876] D: [wsicli|0|WS/h1/10.0.0.66]: lws_handle_POLLOUT_event: non mux: wsistate 0x10000119, ops ws
protocol=ws-client callback=00b7ec90, n=10 from ./lib/core-net/service.c lws_callback_as_writeable line 32
[ws_proxy.c:148] on_ws_proxy=00B7EC90 reason: 10
callback_function=00b7ec90, n=0 from lib/core-net/wsi.c user_callback_handle_rxflow line 502
callback=00b7ec90, m=0, n=10 from ./lib/core-net/service.c lws_callback_as_writeable line 36

linux logs:

[2021/07/09 15:36:43:5857] D: accepted new conn port 51658 on fd=15
[ws_proxy.c:275] on_raw_server=0x4eda90 reason: 17
[ws_proxy.c:289] 0x4eda90 reason: 17, 
[2021/07/09 15:36:43:5858] D: lws_get_idlest_tsi: 3 1023
[2021/07/09 15:36:43:5858] D: _realloc: size 1256: __lws_wsi_create_with_role
[2021/07/09 15:36:43:5858] D: : lws_role_transition: wsistate 0x200, ops (unset)
[2021/07/09 15:36:43:5858] N:  ++ [wsisrv|0|adopted] (1)
[2021/07/09 15:36:43:5858] D: [wsisrv|0|adopted]: lws_create_new_server_wsi: joining vh default, tsi 0
[2021/07/09 15:36:43:5858] D: [wsisrv|0|adopted]: lws_vhost_bind_wsi: vh default: wsi none/none, count_bound_wsi 3
[2021/07/09 15:36:43:5858] D: [wsisrv|0|adopted]: lwsi_set_state: lwsi_set_state 0x20000200 -> 0x20000200
[ws_proxy.c:275] on_raw_server=0x4eda90 reason: 29
[ws_proxy.c:293] CREATE: wsi=0x61a000001880, pc=(nil)
[2021/07/09 15:36:43:5858] D: [wsisrv|0|adopted]: lws_role_transition: wsistate 0x119, ops raw-skt
[2021/07/09 15:36:43:5858] D: [wsisrv|0|adopted]: lws_ensure_user_space: protocol pss 0, user_space=(nil)
[ws_proxy.c:275] on_raw_server=0x4eda90 reason: 81
[ws_proxy.c:289] 0x4eda90 reason: 81, 
[2021/07/09 15:36:43:5858] D: _realloc: size 160: uvh
[2021/07/09 15:36:43:5859] D: [wsisrv|0|adopted]: elops_accept_uv: thr 0: sa left 2: dyn left: 4
[2021/07/09 15:36:43:5859] D: [wsisrv|0|adopted]: __insert_wsi_socket_into_fds: tsi=0, sock=15, pos-in-fds=3
[2021/07/09 15:36:43:5859] D: [wsisrv|0|adopted]: elops_io_uv: 5
[ws_proxy.c:275] on_raw_server=0x4eda90 reason: 62
[ws_proxy.c:297] ADOPT: wsi=0x61a000001880, pc=(nil)
[2021/07/09 15:36:43:5860] D: _realloc: size 1256: __lws_wsi_create_with_role
[2021/07/09 15:36:43:5860] D: : lws_role_transition: wsistate 0x200, ops (unset)
[2021/07/09 15:36:43:5860] D: : lws_vhost_bind_wsi: vh default: wsi none/none, count_bound_wsi 4
[2021/07/09 15:36:43:5860] D: _realloc: size 240: client ws struct
[2021/07/09 15:36:43:5860] D: : lws_role_transition: wsistate 0x10000200, ops h1
[2021/07/09 15:36:43:5860] D: : lws_ensure_user_space: protocol pss 0, user_space=(nil)
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 85
[ws_proxy.c:167] 0x4eeb30 reason2: 85, 
[2021/07/09 15:36:43:5860] D: _realloc: size 128: client stash
[2021/07/09 15:36:43:5860] N:  ++ [wsicli|0|WS/h1/10.0.0.66] (1)
[2021/07/09 15:36:43:5860] D: _realloc: size 968: ah struct
[2021/07/09 15:36:43:5860] D: _realloc: size 4096: ah data
[2021/07/09 15:36:43:5861] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 10 secs, reason 25
[2021/07/09 15:36:43:5861] D: [wsicli|0|WS/h1/10.0.0.66]: lws_http_client_connect_via_info2: stash 0x60c000000280
[2021/07/09 15:36:43:5861] D: _realloc: size 10: strdup
[2021/07/09 15:36:43:5861] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_2_dnsreq: new conn on no pipeline flag
[2021/07/09 15:36:43:5861] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000200 -> 0x10000201
[2021/07/09 15:36:43:5861] D: _realloc: size 144: lws_sort_dns
[2021/07/09 15:36:43:5861] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: WAITING_CONNECT
[2021/07/09 15:36:43:5861] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000201 -> 0x10000202
[2021/07/09 15:36:43:5862] D: _realloc: size 160: uvh
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: elops_accept_uv: thr 0: sa left 2: dyn left: 5
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: __insert_wsi_socket_into_fds: tsi=0, sock=16, pos-in-fds=4
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 5
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 1 -> 1
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 5
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 20 secs, reason 2
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 105
[ws_proxy.c:167] 0x4eeb30 reason2: 105, 
callback_function=0x4eeb30, n=0 from lib/core-net/wsi.c user_callback_handle_rxflow line 502
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: connect: fd 16 errno: 115
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 1 -> 5
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 15:36:43:5862] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_via_info: adoption cb 19 to h1 ws-client
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 19
[ws_proxy.c:167] 0x4eeb30 reason2: 19, 
[2021/07/09 15:36:43:5862] D: [wsisrv|0|adopted]: lws_role_call_adoption_bind: leaving bound to role raw-skt
[ws_proxy.c:275] on_raw_server=0x4eda90 reason: 71
[ws_proxy.c:289] 0x4eda90 reason: 71, 
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 71
[ws_proxy.c:167] 0x4eeb30 reason2: 71, 
[2021/07/09 15:36:43:5863] D: [wsisrv|0|adopted]: rops_handle_POLLIN_raw_skt: POLLIN: state 0x119
[2021/07/09 15:36:43:5863] D: [wsisrv|0|adopted]: lws_buflist_aware_read: rops_handle_POLLIN_raw_skt: ssl_capable_read 78
[ws_proxy.c:275] on_raw_server=0x4eda90 reason: 59
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 5 -> 5
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
callback_function=0x4eda90, n=0 from lib/core-net/wsi.c user_callback_handle_rxflow line 502
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 5 -> 1
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_check: getsockopt: conn OK errno 0
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 29
[ws_proxy.c:167] 0x4eeb30 reason2: 29, 
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: going into connect_4
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000202 -> 0x10000012
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 8
[2021/07/09 15:36:43:5869] D: lws_http_client_socket_service: LRS_H1C_ISSUE_HANDSHAKE
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 1 -> 1
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 24
[ws_proxy.c:167] 0x4eeb30 reason2: 24, ?X
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000012 -> 0x1000020b
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 4
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 1 -> 5
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x1000020b -> 0x1000020b
[2021/07/09 15:36:43:5869] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 4
[2021/07/09 15:36:43:5870] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 5 -> 1
[2021/07/09 15:36:43:5870] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 15:36:43:5870] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 1 -> 1
[2021/07/09 15:36:43:5870] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 15:36:43:5871] D: [wsicli|0|WS/h1/10.0.0.66]: lws_buflist_aware_read: lws_http_client_socket_service: ssl_capable_read 213
[2021/07/09 15:36:43:5871] D: lws_http_client_socket_service: buflist-aware-read 0 213
[2021/07/09 15:36:43:5871] D: lws_client_interpret_server_handshake: no content length
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 44
[ws_proxy.c:167] 0x4eeb30 reason2: 44, 
[2021/07/09 15:36:43:5871] D: Selected protocol ws-client
[2021/07/09 15:36:43:5871] D: [wsicli|0|WS/h1/10.0.0.66]: lws_ensure_user_space: protocol pss 0, user_space=(nil)
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 2
[ws_proxy.c:167] 0x4eeb30 reason2: 2, 
[2021/07/09 15:36:43:5871] D: [wsicli|0|WS/h1/10.0.0.66]: lws_role_transition: wsistate 0x10000119, ops ws
[2021/07/09 15:36:43:5871] D: _realloc: size 16404: client frame buffer
[2021/07/09 15:36:43:5871] D: handshake OK for protocol ws-client
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 3
[ws_proxy.c:171] ws connected: wsi=0x61a000001e80
[2021/07/09 15:36:43:5871] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 1 -> 5
[2021/07/09 15:36:43:5871] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 15:36:43:5872] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 16 events 5 -> 1
[2021/07/09 15:36:43:5872] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 15:36:43:5872] D: [wsicli|0|WS/h1/10.0.0.66]: lws_handle_POLLOUT_event: non mux: wsistate 0x10000119, ops ws
protocol=ws-client callback=0x4eeb30, n=10 from ./lib/core-net/service.c lws_callback_as_writeable line 32
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 10
callback_function=0x4eeb30, n=0 from lib/core-net/wsi.c user_callback_handle_rxflow line 502
callback=0x4eeb30, m=0, n=10 from ./lib/core-net/service.c lws_callback_as_writeable line 36
[2021/07/09 15:36:43:5874] D: lws_read_h1: h1 path: wsi state 0x119
[2021/07/09 15:36:43:5875] D: lws_ws_handshake_client: hs client feels it has 361 in
[2021/07/09 15:36:43:5875] D: lws_ws_client_rx_sm: spilling as we have the whole frame
[2021/07/09 15:36:43:5875] D: lws_ws_client_rx_sm: starting disbursal of 357 deframed rx
[ws_proxy.c:148] on_ws_proxy=0x4eeb30 reason: 8
[2021/07/09 15:36:43:5875] D: [wsisrv|0|adopted]: _lws_change_pollfd: fd 15 events 1 -> 5
[2021/07/09 15:36:43:5875] D: [wsisrv|0|adopted]: elops_io_uv: 6
[2021/07/09 15:36:43:5875] D: lws_ws_client_rx_sm: bulk ws rx: inp used 357, output 357
[2021/07/09 15:36:43:5875] D: [wsisrv|0|adopted]: _lws_change_pollfd: fd 15 events 5 -> 1
[2021/07/09 15:36:43:5875] D: [wsisrv|0|adopted]: elops_io_uv: 10
[ws_proxy.c:275] on_raw_server=0x4eda90 reason: 61
callback_function=0x4eda90, n=0 from lib/core-net/wsi.c user_callback_handle_rxflow line 502
lws-team commented 3 years ago

No, the WSApoll thing in lws is just a default. If you tell lws to use libuv, it uses libuv directly and does not use the WSA stuff at all. So there is no conflict.

Also in your case, it does not fail to get the POLLOUT event, it gets it, and understands it needs to call WRITEABLE. It just doesn't seem to make it into your callback. So it should not be related to libuv or poll loops or whatever.

n = 10 = LWS_CALLBACK_CLIENT_WRITEABLE

I would check what protocol the wsi is bound to, print wsi->a.protocol->name, see if it is actually what you expect.

Does your ws server provide subprotocol names for ws protocols it offers or it's missing?

calvin2021y commented 3 years ago

Thanks for the explain, now I find LWS_CALLBACK_RAW_RX never get called so the websocket has no message to send.

all callback from windows raw socket ( no LWS_CALLBACK_EVENT_WAIT_CANCELLED callbak ):

[ws_proxy.c:278] on_raw_server=00729220 reason: 27
[ws_proxy.c:278] on_raw_server=00729220 reason: 17
[ws_proxy.c:278] on_raw_server=00729220 reason: 29
[ws_proxy.c:278] on_raw_server=00729220 reason: 81
[ws_proxy.c:278] on_raw_server=00729220 reason: 62

all callback from linux raw socket:

[ws_proxy.c:278] on_raw_server=0x477ba0 reason: 27
[ws_proxy.c:278] on_raw_server=0x477ba0 reason: 71
[ws_proxy.c:278] on_raw_server=0x477ba0 reason: 17
[ws_proxy.c:278] on_raw_server=0x477ba0 reason: 29
[ws_proxy.c:278] on_raw_server=0x477ba0 reason: 81
[ws_proxy.c:278] on_raw_server=0x477ba0 reason: 62
[ws_proxy.c:278] on_raw_server=0x477ba0 reason: 71
[ws_proxy.c:278] on_raw_server=0x477ba0 reason: 59
[ws_proxy.c:379] RX(0x7f15f8b76010, 78): GET / HTTP/1.1
Host: 127.0.0.1:1089
User-Agent: curl/7.74.0
Accept: */*

and curl send the request for windows:

curl 127.0.0.1:1080 -v    
*   Trying 127.0.0.1:1080...                       
* Connected to 127.0.0.1 (127.0.0.1) port 1080 (#0)
> GET / HTTP/1.1                                   
> Host: 127.0.0.1:1080                             
> User-Agent: curl/7.77.0
> Accept: */*
>
lws-team commented 3 years ago

OK then that can be related to libuv / event loop, if the first problem is not POLLOUT as it looks from the logs, then the next deviation is

[2021/07/09 15:36:43:5874] D: lws_read_h1: h1 path: wsi state 0x119
[2021/07/09 15:36:43:5875] D: lws_ws_handshake_client: hs client feels it has 361 in

this is basically POLLIN notification for the first ws data from the server is not coming.

I don't understand what you mean about curl, the logs show ws data coming or not coming.

calvin2021y commented 3 years ago

The curl logs show it send the request to lws raw socket.

the lws logs show no LWS_CALLBACK_RAW_RX callback for raw get called.

lws-team commented 3 years ago

How about this

diff --git a/lib/plat/windows/windows-sockets.c b/lib/plat/windows/windows-sockets.c
index c77cc0f7cf..bb191caba9 100644
--- a/lib/plat/windows/windows-sockets.c
+++ b/lib/plat/windows/windows-sockets.c
@@ -200,6 +200,9 @@ lws_plat_insert_socket_into_fds(struct lws_context *context, struct lws *wsi)
        }
 #endif

+       if (context->event_loop_ops->io)
+               context->event_loop_ops->io(wsi, LWS_EV_START | LWS_EV_READ);
+
        pt->fds[pt->fds_count++].revents = 0;

        lws_plat_change_pollfd(context, wsi, &pt->fds[pt->fds_count - 1]);
calvin2021y commented 3 years ago

fixed but with a 300ms delay: 

[2021/07/09 17:23:23:3118] D: _realloc: size 7976: context
[2021/07/09 17:23:23:3275] N: lws_create_context: LWS: 4.2.99-root@linux, NET CLI SRV H1 H2 WS ConMon IPV6-on
[2021/07/09 17:23:23:3275] D: _realloc: size 240000: fds table
[2021/07/09 17:23:23:3275] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3275] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3275] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3275] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3431] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3431] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3431] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3431] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3431] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3431] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3431] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3587] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3587] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3587] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3587] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3587] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3587] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3587] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3743] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3743] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3743] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3743] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3743] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3743] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3900] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3900] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3900] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3900] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3900] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3900] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:3900] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:4056] D: _realloc: size 120000: win hashtable
[2021/07/09 17:23:23:4056] N: elops_init_pt_uv:  Using foreign event loop...
[2021/07/09 17:23:23:4056] D: _realloc: size 900: __lws_wsi_create_with_role
[2021/07/09 17:23:23:4056] D: : lws_role_transition: wsistate 0x200, ops pipe
[2021/07/09 17:23:23:4056] N:  ++ [wsi|0|pipe] (1)
[2021/07/09 17:23:23:4056] D: _realloc: size 256: uvh
[2021/07/09 17:23:23:4056] D: [wsi|0|pipe]: elops_accept_uv: thr 0: sa left 2: dyn left: 1
[2021/07/09 17:23:23:4213] D: [wsi|0|pipe]: __insert_wsi_socket_into_fds: tsi=0, sock=292, pos-in-fds=0
[2021/07/09 17:23:23:4213] D: [wsi|0|pipe]: elops_io_uv: 5
[2021/07/09 17:23:23:4213] D: _realloc: size 1024: lws_create_vhost
[2021/07/09 17:23:23:4213] N:  ++ [vh|0|default||1080] (1)
[2021/07/09 17:23:23:4213] D: _realloc: size 112: vh plugin table
[2021/07/09 17:23:23:4369] D: _realloc: size 36: same vh list
[2021/07/09 17:23:23:4369] N:  Vhost 'default' using non-TLS mode
[2021/07/09 17:23:23:4369] N: [null wsi]: lws_socket_bind: source ads 0.0.0.0
[2021/07/09 17:23:23:4369] D: _realloc: size 900: __lws_wsi_create_with_role
[2021/07/09 17:23:23:4369] D: : lws_role_transition: wsistate 0x200, ops listen
[2021/07/09 17:23:23:4369] D: _lws_vhost_init_server_af: lws_socket_bind says 1080
[2021/07/09 17:23:23:4525] D: : lws_vhost_bind_wsi: vh default: wsi listen/ws-server, count_bound_wsi 1
[2021/07/09 17:23:23:4525] D: _realloc: size 256: uvh
[2021/07/09 17:23:23:4525] D: : elops_init_vhost_listen_wsi_uv: thr 0: sa left 2: dyn left: 2
[2021/07/09 17:23:23:4525] D: : elops_io_uv: 5
[2021/07/09 17:23:23:4525] D: : __insert_wsi_socket_into_fds: tsi=0, sock=1168, pos-in-fds=1
[2021/07/09 17:23:23:4525] D: : elops_io_uv: 5
[2021/07/09 17:23:23:4682] N:  ++ [wsi|1|listen|default||1080] (2)
[2021/07/09 17:23:23:4682] N: [null wsi]: lws_socket_bind: source ads ::
[2021/07/09 17:23:23:4682] D: _realloc: size 900: __lws_wsi_create_with_role
[2021/07/09 17:23:23:4682] D: : lws_role_transition: wsistate 0x200, ops listen
[2021/07/09 17:23:23:4682] D: _lws_vhost_init_server_af: lws_socket_bind says 1080
[2021/07/09 17:23:23:4682] D: : lws_vhost_bind_wsi: vh default: wsi listen/ws-server, count_bound_wsi 2
[2021/07/09 17:23:23:4838] D: _realloc: size 256: uvh
[2021/07/09 17:23:23:4838] D: : elops_init_vhost_listen_wsi_uv: thr 0: sa left 2: dyn left: 3
[2021/07/09 17:23:23:4838] D: : elops_io_uv: 5
[2021/07/09 17:23:23:4838] D: : __insert_wsi_socket_into_fds: tsi=0, sock=1160, pos-in-fds=2
[2021/07/09 17:23:23:4838] D: : elops_io_uv: 5
[2021/07/09 17:23:23:4838] N:  ++ [wsi|2|listen|default||1080] (3)
[2021/07/09 17:23:23:4994] D: lws_cancel_service:
[2021/07/09 17:23:23:4994] D: [vh|0|default||1080]: lws_protocol_init_vhost: not instantiating ws-server
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 27
[2021/07/09 17:23:23:4994] D: [vh|0|default||1080]: lws_protocol_init_vhost: not instantiating ws-client
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 27
[2021/07/09 17:23:23:4994] D: [vh|0|default||1080]: lws_protocol_init_vhost: not instantiating lws-ws-proxy
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 71
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 71
[2021/07/09 17:23:25:8590] D: accepted new conn port 65051 on fd=1176
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 17
[2021/07/09 17:23:25:8590] D: lws_get_idlest_tsi: 3 29999
[2021/07/09 17:23:25:8590] D: _realloc: size 900: __lws_wsi_create_with_role
[2021/07/09 17:23:25:8590] D: : lws_role_transition: wsistate 0x200, ops (unset)
[2021/07/09 17:23:25:8590] N:  ++ [wsisrv|0|adopted] (1)
[2021/07/09 17:23:25:8746] D: [wsisrv|0|adopted]: lws_create_new_server_wsi: joining vh default, tsi 0
[2021/07/09 17:23:25:8746] D: [wsisrv|0|adopted]: lws_vhost_bind_wsi: vh default: wsi none/none, count_bound_wsi 3
[2021/07/09 17:23:25:8746] D: [wsisrv|0|adopted]: lwsi_set_state: lwsi_set_state 0x20000200 -> 0x20000200
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 29
[2021/07/09 17:23:25:8746] D: [wsisrv|0|adopted]: lws_role_transition: wsistate 0x119, ops raw-skt
[2021/07/09 17:23:25:8746] D: [wsisrv|0|adopted]: lws_ensure_user_space: protocol pss 0, user_space=00000000
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 81
[2021/07/09 17:23:25:8902] D: _realloc: size 256: uvh
[2021/07/09 17:23:25:8902] D: [wsisrv|0|adopted]: elops_accept_uv: thr 0: sa left 2: dyn left: 4
[2021/07/09 17:23:25:8902] D: [wsisrv|0|adopted]: __insert_wsi_socket_into_fds: tsi=0, sock=1176, pos-in-fds=3
[2021/07/09 17:23:25:8902] D: [wsisrv|0|adopted]: elops_io_uv: 5
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 62
[2021/07/09 17:23:25:8902] D: _realloc: size 900: __lws_wsi_create_with_role
[2021/07/09 17:23:25:9059] D: : lws_role_transition: wsistate 0x200, ops (unset)
[2021/07/09 17:23:25:9059] D: : lws_vhost_bind_wsi: vh default: wsi none/none, count_bound_wsi 4
[2021/07/09 17:23:25:9059] D: _realloc: size 212: client ws struct
[2021/07/09 17:23:25:9059] D: : lws_role_transition: wsistate 0x10000200, ops h1
[2021/07/09 17:23:25:9059] D: : lws_ensure_user_space: protocol pss 0, user_space=00000000
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 85
[2021/07/09 17:23:25:9059] D: _realloc: size 104: client stash
[2021/07/09 17:23:25:9215] N:  ++ [wsicli|0|WS/h1/10.0.0.66] (1)
[2021/07/09 17:23:25:9215] D: _realloc: size 948: ah struct
[2021/07/09 17:23:25:9215] D: _realloc: size 4096: ah data
[2021/07/09 17:23:25:9215] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 10 secs, reason 25
[2021/07/09 17:23:25:9215] D: [wsicli|0|WS/h1/10.0.0.66]: lws_http_client_connect_via_info2: stash 0560b610
[2021/07/09 17:23:25:9215] D: _realloc: size 10: strdup
[2021/07/09 17:23:25:9371] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_2_dnsreq: new conn on no pipeline flag
[2021/07/09 17:23:25:9371] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000200 -> 0x10000201
[2021/07/09 17:23:25:9371] D: _realloc: size 124: lws_sort_dns
[2021/07/09 17:23:25:9371] W: lws_plat_set_socket_options_ip: not implemented on windows platform
[2021/07/09 17:23:25:9371] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: WAITING_CONNECT
[2021/07/09 17:23:25:9527] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000201 -> 0x10000202
[2021/07/09 17:23:25:9527] D: _realloc: size 256: uvh
[2021/07/09 17:23:25:9527] D: [wsicli|0|WS/h1/10.0.0.66]: elops_accept_uv: thr 0: sa left 2: dyn left: 5
[2021/07/09 17:23:25:9527] D: [wsicli|0|WS/h1/10.0.0.66]: __insert_wsi_socket_into_fds: tsi=0, sock=1180, pos-in-fds=4
[2021/07/09 17:23:25:9684] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 5
[2021/07/09 17:23:25:9684] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 768 -> 768
[2021/07/09 17:23:25:9684] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 5
[2021/07/09 17:23:25:9684] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 20 secs, reason 2
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 105
[2021/07/09 17:23:25:9684] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: connect: fd 1180 errno: 10035
[2021/07/09 17:23:25:9840] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 768 -> 784
[2021/07/09 17:23:25:9840] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 17:23:25:9840] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_via_info: adoption cb 19 to h1 ws-client
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 19
[2021/07/09 17:23:25:9840] D: [wsisrv|0|adopted]: lws_role_call_adoption_bind: leaving bound to role raw-skt
[2021/07/09 17:23:25:9996] D: [wsisrv|0|adopted]: rops_handle_POLLIN_raw_skt: POLLIN: state 0x119
[2021/07/09 17:23:25:9996] D: [wsisrv|0|adopted]: lws_buflist_aware_read: rops_handle_POLLIN_raw_skt: ssl_capable_read 78
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 59
[ws_proxy.c:379] RX(05B18020, 78): GET / HTTP/1.1
Host: 127.0.0.1:1080
User-Agent: curl/7.77.0
Accept: */*

[2021/07/09 17:23:25:9996] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 784 -> 784
[2021/07/09 17:23:25:9996] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 17:23:26:0152] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 784 -> 768
[2021/07/09 17:23:26:0152] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 29
[2021/07/09 17:23:26:0152] D: [wsicli|0|WS/h1/10.0.0.66]: lws_client_connect_3_connect: going into connect_4
[2021/07/09 17:23:26:0152] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000202 -> 0x10000012
[2021/07/09 17:23:26:0152] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 8
[2021/07/09 17:23:26:0309] D: lws_http_client_socket_service: LRS_H1C_ISSUE_HANDSHAKE
[2021/07/09 17:23:26:0309] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 768 -> 768
[2021/07/09 17:23:26:0309] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 24
[2021/07/09 17:23:26:0309] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000012 -> 0x1000020b
[2021/07/09 17:23:26:0309] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 4
[2021/07/09 17:23:26:0465] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 768 -> 784
[2021/07/09 17:23:26:0465] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 17:23:26:0465] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x1000020b -> 0x1000020b
[2021/07/09 17:23:26:0465] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 15 secs, reason 4
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 71
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 71
[2021/07/09 17:23:26:0465] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 784 -> 768
[2021/07/09 17:23:26:0621] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 17:23:26:0621] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 768 -> 768
[2021/07/09 17:23:26:0621] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 17:23:26:0621] D: [wsicli|0|WS/h1/10.0.0.66]: lws_buflist_aware_read: lws_http_client_socket_service: ssl_capable_read 213
[2021/07/09 17:23:26:0777] D: lws_http_client_socket_service: buflist-aware-read 0 213
[2021/07/09 17:23:26:0777] D: lws_client_interpret_server_handshake: no content length
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 44
[2021/07/09 17:23:26:0777] D: Selected protocol ws-client
[2021/07/09 17:23:26:0777] D: [wsicli|0|WS/h1/10.0.0.66]: lws_ensure_user_space: protocol pss 0, user_space=00000000
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 2
[2021/07/09 17:23:26:0777] D: [wsicli|0|WS/h1/10.0.0.66]: lws_role_transition: wsistate 0x10000119, ops ws
[2021/07/09 17:23:26:0934] D: _realloc: size 16404: client frame buffer
[2021/07/09 17:23:26:0934] D: handshake OK for protocol ws-client
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 3
[ws_proxy.c:173] ws connected: wsi=0560B1A0
[2021/07/09 17:23:26:0934] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 768 -> 784
[2021/07/09 17:23:26:0934] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 6
[2021/07/09 17:23:26:0934] D: [wsicli|0|WS/h1/10.0.0.66]: _lws_change_pollfd: fd 1180 events 784 -> 768
[2021/07/09 17:23:26:1090] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: 10
[2021/07/09 17:23:26:1090] D: [wsicli|0|WS/h1/10.0.0.66]: lws_handle_POLLOUT_event: non mux: wsistate 0x10000119, ops ws
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 10
[ws_proxy.c:224] ws LWS_CALLBACK_CLIENT_WRITEABLE, to_ws_empty=0
6ɨH
   O}õHI
        }žLǜ6(05B18020, 78): h
[2021/07/09 17:23:26:1090] D: lws_read_h1: h1 path: wsi state 0x119
[2021/07/09 17:23:26:1090] D: lws_ws_handshake_client: hs client feels it has 361 in
[2021/07/09 17:23:26:1090] D: lws_ws_client_rx_sm: spilling as we have the whole frame
[2021/07/09 17:23:26:1246] D: lws_ws_client_rx_sm: starting disbursal of 357 deframed rx
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 8
[ws_proxy.c:218] RX2(05B18020, 357): HTTP/1.1 200 OK
Server: nginx
Date: Fri, 09 Jul 2021 09:23:26 GMT
Content-Type: text/html; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Keep-Alive: timeout=120
Vary: Accept-Encoding

87
<html>
<head><title>Index of /</title></head>
<body>
<h1>Index of /</h1><hr><pre><a href="../">../</a>
</pre><hr></body>
</html>

0

[2021/07/09 17:23:26:1246] D: [wsisrv|0|adopted]: _lws_change_pollfd: fd 1176 events 768 -> 784
[2021/07/09 17:23:26:1246] D: [wsisrv|0|adopted]: elops_io_uv: 6
[2021/07/09 17:23:26:1246] D: lws_ws_client_rx_sm: bulk ws rx: inp used 357, output 357
[2021/07/09 17:23:26:1246] D: [wsisrv|0|adopted]: _lws_change_pollfd: fd 1176 events 784 -> 768
[2021/07/09 17:23:26:1403] D: [wsisrv|0|adopted]: elops_io_uv: 10
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 61
[ws_proxy.c:413] TX(05B18020, 357): HTTP/1.1 200 OK
Server: nginx
Date: Fri, 09 Jul 2021 09:23:26 GMT
Content-Type: text/html; charset=utf-8
Transfer-Encoding: chunked
Connection: keep-alive
Keep-Alive: timeout=120
Vary: Accept-Encoding

87
<html>
<head><title>Index of /</title></head>
<body>
<h1>Index of /</h1><hr><pre><a href="../">../</a>
</pre><hr></body>
</html>

0

[2021/07/09 17:23:26:1403] D: [wsisrv|0|adopted]: rops_handle_POLLIN_raw_skt: POLLIN: state 0x119
[2021/07/09 17:23:26:1559] D: [wsisrv|0|adopted]: lws_buflist_aware_read: rops_handle_POLLIN_raw_skt: ssl_capable_read -1
[2021/07/09 17:23:26:1559] D: lws_buflist_aware_read: SSL_CAPABLE_ERROR
[2021/07/09 17:23:26:1559] D: [wsisrv|0|adopted]: __lws_close_free_wsi: real just_kill_connection A: (sockfd 1176)
[2021/07/09 17:23:26:1559] D: [wsisrv|0|adopted]: elops_io_uv: -2147483637
[2021/07/09 17:23:26:1559] D: [wsi|1|listen|default||1080]: _lws_change_pollfd: fd 1168 events 768 -> 768
[2021/07/09 17:23:26:1559] D: [wsi|1|listen|default||1080]: elops_io_uv: 5
[2021/07/09 17:23:26:1559] D: [wsi|2|listen|default||1080]: _lws_change_pollfd: fd 1160 events 768 -> 768
[2021/07/09 17:23:26:1559] D: [wsi|2|listen|default||1080]: elops_io_uv: 5
[2021/07/09 17:23:26:1715] D: [wsisrv|0|adopted]: lwsi_set_state: lwsi_set_state 0x20000119 -> 0x20000020
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 60
[2021/07/09 17:23:26:1715] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_set_timeout: 0 secs, reason 1
[2021/07/09 17:23:26:1715] D: [wsisrv|0|adopted]: elops_wsi_logical_close_uv: lws_libuv_closehandle
[2021/07/09 17:23:26:1715] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_close_free_wsi: real just_kill_connection A: (sockfd 1180)
[2021/07/09 17:23:26:1715] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: -2147483637
[2021/07/09 17:23:26:1715] D: [wsi|1|listen|default||1080]: _lws_change_pollfd: fd 1168 events 768 -> 768
[2021/07/09 17:23:26:1715] D: [wsi|1|listen|default||1080]: elops_io_uv: 5
[2021/07/09 17:23:26:1871] D: [wsi|2|listen|default||1080]: _lws_change_pollfd: fd 1160 events 768 -> 768
[2021/07/09 17:23:26:1871] D: [wsi|2|listen|default||1080]: elops_io_uv: 5
[2021/07/09 17:23:26:1871] D: [wsicli|0|WS/h1/10.0.0.66]: lwsi_set_state: lwsi_set_state 0x10000119 -> 0x10000020
[ws_proxy.c:150] on_ws_proxy=00E6ECE0 reason: 75
[ws_proxy.c:180] ws closed: 0560B1A0, reason=75, (null)
[2021/07/09 17:23:26:1871] D: [wsicli|0|WS/h1/10.0.0.66]: elops_wsi_logical_close_uv: lws_libuv_closehandle
[2021/07/09 17:23:26:1871] D: [wsisrv|0|adopted]: __lws_close_free_wsi_final: fd 1176
[2021/07/09 17:23:26:2028] D: [wsisrv|0|adopted]: elops_io_uv: -2147483637
[2021/07/09 17:23:26:2028] D: [wsi|1|listen|default||1080]: _lws_change_pollfd: fd 1168 events 768 -> 768
[2021/07/09 17:23:26:2028] D: [wsi|1|listen|default||1080]: elops_io_uv: 5
[2021/07/09 17:23:26:2028] D: [wsi|2|listen|default||1080]: _lws_change_pollfd: fd 1160 events 768 -> 768
[2021/07/09 17:23:26:2028] D: [wsi|2|listen|default||1080]: elops_io_uv: 5
[2021/07/09 17:23:26:2184] D: Failed to find fd 1176 requested for delete in hashtable
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 30
[2021/07/09 17:23:26:2184] D: [wsisrv|0|adopted]: __lws_vhost_unbind_wsi: vh default: count_bound_wsi 3
[2021/07/09 17:23:26:2184] D: [wsisrv|0|adopted]: __lws_free_wsi: tsi fds count 3
[2021/07/09 17:23:26:2184] N:  -- [wsisrv|0|adopted] (0) 359.390ms
[2021/07/09 17:23:26:2184] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_close_free_wsi_final: fd 1180
[2021/07/09 17:23:26:2340] D: [wsicli|0|WS/h1/10.0.0.66]: elops_io_uv: -2147483637
[2021/07/09 17:23:26:2340] D: [wsi|1|listen|default||1080]: _lws_change_pollfd: fd 1168 events 768 -> 768
[2021/07/09 17:23:26:2340] D: [wsi|1|listen|default||1080]: elops_io_uv: 5
[2021/07/09 17:23:26:2340] D: [wsi|2|listen|default||1080]: _lws_change_pollfd: fd 1160 events 768 -> 768
[2021/07/09 17:23:26:2340] D: [wsi|2|listen|default||1080]: elops_io_uv: 5
[2021/07/09 17:23:26:2340] D: Failed to find fd 1180 requested for delete in hashtable
[ws_proxy.c:278] on_raw_server=00E6D8D0 reason: 30
[2021/07/09 17:23:26:2496] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_vhost_unbind_wsi: vh default: count_bound_wsi 2
[2021/07/09 17:23:26:2496] D: [wsicli|0|WS/h1/10.0.0.66]: __lws_free_wsi: tsi fds count 3
[2021/07/09 17:23:26:2496] N:  -- [wsicli|0|WS/h1/10.0.0.66] (0) 328.156ms
lws-team commented 3 years ago

Sorry where should I look to see this 300ms delay?

calvin2021y commented 3 years ago

build in release mode there is no such delay any more.

lws-team commented 3 years ago

Aside from the verbose logs, there are some extra explicit sanity checks and suchlike in debug mode, if it, eg, walks all possible fds it looks like your platform allows a lot of fds, probably this kind of thing.

calvin2021y commented 3 years ago

compare to linux debug mode return in 0.009ms, this is wired.

I will close this issue since I have no problem in release mode.

calvin2021y commented 3 years ago

after long time run, there is logs like this: (can i remove this logs from release code?)

(hexdump: zero length)

Windows release mode stop working, enable debug can not recreate this issue.

calvin2021y commented 3 years ago

find a problem, but not sure this cause the windows stop working issue. https://github.com/warmcat/libwebsockets/blob/main/minimal-examples/ws-server/minimal-ws-raw-proxy/minimal-ws-raw-proxy.c#L219

if(pc->wsi_raw) lws_callback_on_writable(pc->wsi_raw);
lws-team commented 3 years ago

Where is the hexdump that makes the log?

pc->wsi_raw

that chunk of code looks like

    case LWS_CALLBACK_RECEIVE:
        if (!pc || !pc->wsi_raw)
            break;

        /* notice we over-allocate by LWS_PRE + rx len */
        msg = (proxy_msg_t *)malloc(sizeof(*msg) + LWS_PRE + len);
        data = (uint8_t *)&msg[1] + LWS_PRE;

        if (!msg) {
            lwsl_user("OOM: dropping\n");
            break;
        }

        memset(msg, 0, sizeof(*msg));
        msg->len = len;
        memcpy(data, in, len);

        /* add us on to the list of packets to send to the onward conn */
        lws_dll2_add_tail(&msg->list, &pc->pending_msg_to_raw);

        /* ask to send on the onward proxy client conn */
        lws_callback_on_writable(pc->wsi_raw);

He checks for NULL pc->wsi_raw at the top, how can it need to check it again?

Windows release mode stop working, enable debug can not recreate this issue.

I can't do anything with that... if it's something I can reproduce, how should I reproduce it?

calvin2021y commented 3 years ago

I can not find where is the the hexdump that makes the log, I will enable more logs options and check again.

you are right, I copy your code into my code, forget add if (!pc || !pc->wsi_raw) on the top.

calvin2021y commented 3 years ago

the (hexdump: zero length) show in release call from this path:

lib/core/logs.c

        if (!len) {
                _lws_log_cx(cx, prep, obj, hexdump_level, NULL,
                                        "(hexdump: zero length)\n");

lib/roles/ws/client-parser-ws.c

 lwsl_info("%s: %s received pong\n", __func__, lws_wsi_tag(wsi));
                        lwsl_hexdump(&wsi->ws->rx_ubuf[LWS_PRE],
                                     wsi->ws->rx_ubuf_head);
  #2 0x6ca8cd in lwsl_hexdump_level_cx lib/core/logs.c:539:12
    #3 0x6cace3 in lwsl_hexdump_level lib/core/logs.c:585:2
    #4 0x6cad11 in lwsl_hexdump lib/core/logs.c:592:2
    #5 0x70d19a in lws_ws_client_rx_sm lib/roles/ws/client-parser-ws.c:480:4
    #6 0x709e75 in lws_ws_handshake_client lib/roles/ws/client-ws.c:133:7
    #7 0x6f6e4a in lws_read_h1 lib/roles/h1/ops-h1.c:262:7
    #8 0x708b9f in rops_handle_POLLIN_ws lib/roles/ws/ops-ws.c:1183:9
    #9 0x6e843c in lws_service_fd_tsi core-net/service.c:724:10
    #10 0x71ea6a in lws_io_cb lib/event-libs/libuv/libuv.c:140:2
    #11 0x648201 in uv__poll_io uv/src/unix/poll.c:64:3
    #12 0x67929e in uv__io_poll uv/src/unix/linux-core.c:462:11
    #13 0x61e281 in uv_run uv/src/unix/core.c:385:5