search

warmcat / libwebsockets

canonical libwebsockets.org networking library
https://libwebsockets.org
Other
4.76k stars 1.48k forks source link

CLIENT_CONNECTION_ERROR: closed before established #2634

Closed phpmooc closed 2 years ago

phpmooc commented 2 years ago

LWS Vsersion: v4.3

Use LWS (all sides are deployed locally) as the role of websocket client, when I try to connect to the remote websocket server, the debug terminal gives me detailed logs listed as below:

[2022/05/06 13:03:10:0511] D: _realloc: size 1192: __lws_wsi_create_with_role
[2022/05/06 13:03:10:0586] D: : lws_role_transition: wsistate 0x200, ops pipe
[2022/05/06 13:03:10:0661] N: __lws_lc_tag:  ++ [wsi|0|pipe] (1)
[2022/05/06 13:03:10:0731] I: lws_plat_pipe_create: cancel UDP skt port 54974
[2022/05/06 13:03:10:0796] D: [wsi|0|pipe]: __insert_wsi_socket_into_fds: tsi=0, sock=1492, pos-in-fds=0
[2022/05/06 13:03:10:0896] I: lws_context_init_ssl_library:  Compiled with OpenSSL support
[2022/05/06 13:03:10:0981] I: lws_context_init_ssl_library: Doing SSL library init
[2022/05/06 13:03:11:4082] D: _realloc: size 72: client ctx tcr
[2022/05/06 13:03:11:4132] I: lws_tls_client_create_vhost_context: vh default: created new client ctx 0
[2022/05/06 13:03:11:4212] I: created client ssl context for default
[2022/05/06 13:03:11:4262] I: lws_create_context:  mem: per-conn:         1192 bytes + protocol rx buf
[2022/05/06 13:03:11:4333] D: lws_cancel_service:
[2022/05/06 13:03:11:4378] I: lws_protocol_init:
[2022/05/06 13:03:11:4413] D: [vh|0|default||-1]: lws_protocol_init_vhost: not instantiating dumb-increment-protocol
[2022/05/06 13:03:11:4493] I: [vh|0|default||-1]: lws_protocol_init_vhost: init default.dumb-increment-protocol
[2022/05/06 13:03:11:4598] D: [vh|0|default||-1]: lws_protocol_init_vhost: not instantiating lws-secstream-h1
[2022/05/06 13:03:11:4713] I: [vh|0|default||-1]: lws_protocol_init_vhost: init default.lws-secstream-h1
[2022/05/06 13:03:11:4813] D: [vh|0|default||-1]: lws_protocol_init_vhost: not instantiating lws-secstream-h2
[2022/05/06 13:03:11:4913] I: [vh|0|default||-1]: lws_protocol_init_vhost: init default.lws-secstream-h2
[2022/05/06 13:03:11:5063] D: [vh|0|default||-1]: lws_protocol_init_vhost: not instantiating lws-secstream-ws
[2022/05/06 13:03:11:5218] I: [vh|0|default||-1]: lws_protocol_init_vhost: init default.lws-secstream-ws
[2022/05/06 13:03:11:5548] D: [vh|0|default||-1]: lws_protocol_init_vhost: not instantiating lws-secstream-raw
[2022/05/06 13:03:11:5648] I: [vh|0|default||-1]: lws_protocol_init_vhost: init default.lws-secstream-raw
[2022/05/06 13:03:11:5728] D: _realloc: size 1192: __lws_wsi_create_with_role
[2022/05/06 13:03:11:5788] D: : lws_role_transition: wsistate 0x200, ops (unset)
[2022/05/06 13:03:11:5853] D: : lws_vhost_bind_wsi: vh default: wsi none/none, count_bound_wsi 1
[2022/05/06 13:03:11:5928] D: _realloc: size 336: client ws struct
[2022/05/06 13:03:11:5978] D: : lws_role_transition: wsistate 0x10000200, ops h1
[2022/05/06 13:03:11:6033] I: : lws_client_connect_via_info: role binding to h1
[2022/05/06 13:03:11:6088] I: : lws_client_connect_via_info: vh default protocol binding to dumb-increment-protocol
[2022/05/06 13:03:11:6203] D: : lws_ensure_user_space: protocol pss 0, user_space=0000000000000000
[2022/05/06 13:03:11:6293] I: : lws_client_connect_via_info: : h1 dumb-increment-protocol entry
[2022/05/06 13:03:11:6378] D: _realloc: size 151: client stash
[2022/05/06 13:03:11:6443] N: __lws_lc_tag:  ++ [wsicli|0|WS/h1/default/192.168.0.100] (1)
[2022/05/06 13:03:11:6528] I: lws_header_table_attach: [wsicli|0|WS/h1/default/192.168.0.100]: ah 0000000000000000 (tsi 0, count = 0) in
[2022/05/06 13:03:11:6663] D: _realloc: size 992: ah struct
[2022/05/06 13:03:11:6713] D: _realloc: size 4096: ah data
[2022/05/06 13:03:11:6778] I: _lws_create_ah: created ah 000000000ce953a0 (size 4096): pool length 1
[2022/05/06 13:03:11:6863] I: lws_header_table_attach: did attach wsi [wsicli|0|WS/h1/default/192.168.0.100]: ah 000000000ce953a0: count 1 (on exit)
[2022/05/06 13:03:11:7018] D: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_set_timeout: 10 secs, reason 25
[2022/05/06 13:03:11:7113] D: [wsicli|0|WS/h1/default/192.168.0.100]: lws_http_client_connect_via_info2: stash 000000000449bf10
[2022/05/06 13:03:11:7238] D: _realloc: size 14: strdup
[2022/05/06 13:03:11:7288] D: [wsicli|0|WS/h1/default/192.168.0.100]: lws_client_connect_2_dnsreq: new conn on no pipeline flag
[2022/05/06 13:03:11:7413] D: [wsicli|0|WS/h1/default/192.168.0.100]: lwsi_set_state: lwsi_set_state 0x10000200 -> 0x10000201
[2022/05/06 13:03:11:7528] I: [wsicli|0|WS/h1/default/192.168.0.100]: lws_client_connect_2_dnsreq: lookup 192.168.0.100:2345
[2022/05/06 13:03:11:7648] I: [wsicli|0|WS/h1/default/192.168.0.100]: lws_getaddrinfo46: getaddrinfo '192.168.0.100' says 0
[2022/05/06 13:03:11:7768] I: [wsicli|0|WS/h1/default/192.168.0.100]: lws_sort_dns: sort_dns: 00000000029d9f70
[2022/05/06 13:03:11:7878] D: _realloc: size 104: lws_sort_dns
[2022/05/06 13:03:11:7938] I: [wsicli|0|WS/h1/default/192.168.0.100]: lws_sort_dns: unsorted entry (af 2) 192.168.0.100
[2022/05/06 13:03:11:8053] I: [wsicli|0|WS/h1/default/192.168.0.100]: lws_sort_dns_dump: 1: (2)192.168.0.100, gw (0)(unset), idi: 0, lbl: 0, prec: 0
[2022/05/06 13:03:11:8198] W: lws_plat_set_socket_options_ip: priority and ip sockets options not implemented on windows platform
[2022/05/06 13:03:11:8323] N: lws_plat_set_socket_options_ip: set use exclusive addresses
[2022/05/06 13:03:11:8423] D: [wsicli|0|WS/h1/default/192.168.0.100]: lws_client_connect_3_connect: WAITING_CONNECT
[2022/05/06 13:03:11:8528] D: [wsicli|0|WS/h1/default/192.168.0.100]: lwsi_set_state: lwsi_set_state 0x10000201 -> 0x10000202
[2022/05/06 13:03:11:8648] D: [wsicli|0|WS/h1/default/192.168.0.100]: __insert_wsi_socket_into_fds: tsi=0, sock=816, pos-in-fds=1
[2022/05/06 13:03:11:8778] D: [wsicli|0|WS/h1/default/192.168.0.100]: _lws_change_pollfd: fd 816 events 768 -> 768
[2022/05/06 13:03:11:8893] D: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_set_timeout: 30 secs, reason 2
[2022/05/06 13:03:11:9003] N: [wsicli|0|WS/h1/default/192.168.0.100]: lws_client_connect_3_connect: trying 192.168.0.100
[2022/05/06 13:03:11:9123] D: [wsicli|0|WS/h1/default/192.168.0.100]: lws_client_connect_3_connect: connect: fd 816, wsaerrno 10035
[2022/05/06 13:03:11:9253] D: [wsicli|0|WS/h1/default/192.168.0.100]: _lws_change_pollfd: fd 816 events 768 -> 784
[2022/05/06 13:03:11:9358] D: [wsicli|0|WS/h1/default/192.168.0.100]: lws_client_connect_via_info: adoption cb 19 to h1 dumb-increment-protocol
[2022/05/06 13:03:11:9508] I: lws_context_destroy: destroy_state 0
[2022/05/06 13:03:11:9573] I: lws_context_destroy: starting context destroy flow
[2022/05/06 13:03:11:9653] I: [vh|0|default||-1]: lws_context_destroy: start close
[2022/05/06 13:03:11:9738] I: [vh|0|default||-1]: lws_vhost_destroy1:
[2022/05/06 13:03:11:9793] D: lws_context_destroy: pt 0: closing wsi 000000000b54d360: role pipe
[2022/05/06 13:03:11:9878] I: [wsi|0|pipe]: __lws_close_free_wsi: caller: ctx destroy
[2022/05/06 13:03:11:9958] D: [wsi|0|pipe]: __lws_close_free_wsi: real just_kill_connection A: (sockfd 1492)
[2022/05/06 13:03:12:0038] I: [wsi|0|pipe]: __lws_close_free_wsi: real just_kill_connection: sockfd 1492
[2022/05/06 13:03:12:0133] D: [wsi|0|pipe]: lwsi_set_state: lwsi_set_state 0x200 -> 0x20
[2022/05/06 13:03:12:0198] I: [wsi|0|pipe]: __lws_close_free_wsi: cce=0
[2022/05/06 13:03:12:0258] D: [wsi|0|pipe]: __lws_close_free_wsi_final: fd 1492
[2022/05/06 13:03:12:0313] D: Failed to find fd 1492 requested for delete in hashtable
[2022/05/06 13:03:12:0373] D: [wsi|0|pipe]: __lws_free_wsi: tsi fds count 1
[2022/05/06 13:03:12:0433] N: __lws_lc_untag:  -- [wsi|0|pipe] (0) 1.977s
[2022/05/06 13:03:12:0483] D: lws_context_destroy: pt 0: closing wsi 0000000006cc8a80: role h1
[2022/05/06 13:03:12:0553] I: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_close_free_wsi: caller: ctx destroy
[2022/05/06 13:03:12:0628] D: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_close_free_wsi: real just_kill_connection A: (sockfd 816)
[2022/05/06 13:03:12:0733] D: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_close_free_wsi: closing in unestablished state 0x202
[2022/05/06 13:03:12:0818] E: CLIENT_CONNECTION_ERROR: closed before established

(GTKWebsocketProject.exe:17856): Gtk-CRITICAL **: 13:03:12.089: gtk_widget_set_sensitive: assertion 'GTK_IS_WIDGET (widget)' failed
[2022/05/06 13:03:12:0963] I: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_close_free_wsi: real just_kill_connection: sockfd 816
[2022/05/06 13:03:12:1068] D: [wsicli|0|WS/h1/default/192.168.0.100]: lwsi_set_state: lwsi_set_state 0x10000202 -> 0x10000020
[2022/05/06 13:03:12:1148] I: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_close_free_wsi: cce=0
[2022/05/06 13:03:12:1228] D: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_close_free_wsi_final: fd 816
[2022/05/06 13:03:12:1308] D: Failed to find fd 816 requested for delete in hashtable
[2022/05/06 13:03:12:1378] I: rops_destroy_role_h1: ah det due to close
[2022/05/06 13:03:12:1428] I: __lws_header_table_detach: [wsicli|0|WS/h1/default/192.168.0.100]: ah 000000000ce953a0 (tsi=0, count = 1)
[2022/05/06 13:03:12:1533] I: __lws_header_table_detach: nobody usable waiting
[2022/05/06 13:03:12:1588] I: _lws_destroy_ah: freed ah 000000000ce953a0 : pool length 0
[2022/05/06 13:03:12:1653] I: __lws_header_table_detach: [wsicli|0|WS/h1/default/192.168.0.100]: ah 000000000ce953a0 (tsi=0, count = 0)
[2022/05/06 13:03:12:1753] D: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_vhost_unbind_wsi: vh default: count_bound_wsi 0
[2022/05/06 13:03:12:1843] D: [vh|0|default||-1]: __lws_vhost_destroy2: protocol destroy
[2022/05/06 13:03:12:1903] D: [vh|0|default||-1]: __lws_vhost_destroy2: protocol destroy
[2022/05/06 13:03:12:1973] D: [vh|0|default||-1]: __lws_vhost_destroy2: protocol destroy
[2022/05/06 13:03:12:2048] D: [vh|0|default||-1]: __lws_vhost_destroy2: protocol destroy
[2022/05/06 13:03:12:2108] D: [vh|0|default||-1]: __lws_vhost_destroy2: protocol destroy
[2022/05/06 13:03:12:2173] N: __lws_lc_untag:  -- [vh|0|default||-1] (0) 2.094s
[2022/05/06 13:03:12:2239] D: [wsicli|0|WS/h1/default/192.168.0.100]: __lws_free_wsi: tsi fds count 0
[2022/05/06 13:03:12:2314] N: __lws_lc_untag:  -- [wsicli|0|WS/h1/default/192.168.0.100] (0) 587.074ms
[2022/05/06 13:03:12:2384] I: lws_context_destroy: manually destroying pts
[2022/05/06 13:03:12:2444] I: lws_context_destroy: PT_WAIT_ALL_DESTROYED: 0 alive
[2022/05/06 13:03:12:2499] D: _lws_state_transition: system: changed 1 'CONTEXT_CREATED' -> 14 'POLICY_INVALID'
[2022/05/06 13:03:12:2589] I: lws_context_destroy: pt destroy 0
[2022/05/06 13:03:12:2634] D: _lws_state_transition: system: changed 14 'POLICY_INVALID' -> 15 'DESTROYING'
[2022/05/06 13:03:12:2709] I: lws_state_transition_steps: POLICY_INVALID -> DESTROYING
[2022/05/06 13:03:12:2779] I: lws_context_destroy: pt 0 fully destroyed
[2022/05/06 13:03:12:2829] U: Completed Failed

Tks a lot Sir.

LilMouse commented 2 years ago

I see you closed the issue. But I have the same error and was wondering if you found a way to reconnect without an error?

lws-team commented 2 years ago

But I have the same error

There are many reasons you might not be able to complete a connect to something that are not "the same error". What exactly do your logs say?

LilMouse commented 2 years ago

I first get a validity timeout that causes the connection drop, then I reconnect but get errno 115, and closed before established

2022-08-01T10:31:10.794 cpa: rops_handle_POLLOUT_ws: ocpp1.6: wsi->ws->tx_draining_ext 0 2022-08-01T10:31:10.795 cpa: _lws_change_pollfd: wsi 0x760007b8: fd 33 events 5 -> 1 2022-08-01T10:31:10.795 cpa: lws_handle_POLLOUT_event: 0x760007b8: non mux: wsistate 0x10000119, ops ws 2022-08-01T10:31:20.794 cpa: lws_validity_cb: wsi 0x760007b8: validity too old 2022-08-01T10:31:20.795 cpa: lws_close_free_wsi: 0x760007b8: caller: validity timeout 2022-08-01T10:31:20.795 cpa: __lws_close_free_wsi: real just_kill_connection: 0x760007b8 (sockfd 33) 2022-08-01T10:31:20.795 cpa: lwsi_set_state(0x760007b8, 0x10000020) 2022-08-01T10:31:20.795 cpa: lws_close_free_wsi_final: wsi 0x760007b8: fd 33 2022-08-01T10:31:20.796 cpa: lws_vhost_unbind_wsi: vh default: count_bound_wsi 0 2022-08-01T10:31:20.796 cpa: lws_free_wsi: 0x760007b8, remaining wsi 1, tsi fds count 1 2022-08-01T10:31:37.164 cpa: _realloc: size 496: client wsi 2022-08-01T10:31:37.165 cpa: lws_vhost_bind_wsi: vh default: wsi none/none, count_bound_wsi 1 2022-08-01T10:31:37.165 cpa: _realloc: size 192: client ws struct 2022-08-01T10:31:37.165 cpa: lws_role_transition: 0x760007b8: wsistate 0x10000200, ops h1 2022-08-01T10:31:37.165 cpa: lws_client_connect_via_info: role binding to h1 2022-08-01T10:31:37.165 cpa: lws_client_connect_via_info: protocol binding to ocpp1.6 2022-08-01T10:31:37.165 cpa: _realloc: size 4: user space 2022-08-01T10:31:37.165 cpa: lws_client_connect_via_info: wsi 0x760007b8: h1 ocpp1.6 entry 2022-08-01T10:31:37.165 cpa: _realloc: size 128: client stash 2022-08-01T10:31:37.165 cpa: lws_header_table_attach: wsi 0x760007b8: ah (nil) (tsi 0, count = 0) in 2022-08-01T10:31:37.165 cpa: _realloc: size 952: ah struct 2022-08-01T10:31:37.167 cpa: _realloc: size 4096: ah data 2022-08-01T10:31:37.168 cpa: _lws_create_ah: created ah 0x76001248 (size 4096): pool length 1 2022-08-01T10:31:37.168 cpa: lws_header_table_attach: did attach wsi 0x760007b8: ah 0x76001248: count 1 (on exit) 2022-08-01T10:31:37.168 cpa: lws_set_timeout: 0x760007b8: 10 secs, reason 25 2022-08-01T10:31:37.168 cpa: lws_http_client_connect_via_info2: 0x760007b8 (stash 0x76000d18) 2022-08-01T10:31:37.168 cpa: _realloc: size 19: strdup 2022-08-01T10:31:37.168 cpa: lwsi_set_state(0x760007b8, 0x10000201) 2022-08-01T10:31:37.168 cpa: lws_client_connect_2_dnsreq: 0x760007b8: lookup 192.168.255.254:80 2022-08-01T10:31:37.168 cpa: lws_getaddrinfo46: getaddrinfo '192.168.255.254' says 0 2022-08-01T10:31:37.168 cpa: lws_client_connect_3_connect: result 0x76003538 result->ai_next (nil) 2022-08-01T10:31:37.168 cpa: lws_client_connect_3_connect: 192.168.255.254 ipv4 192.168.255.254 2022-08-01T10:31:37.170 cpa: lws_client_connect_3_connect: 0x760007b8: WAITING_CONNECT 2022-08-01T10:31:37.171 cpa: lwsi_set_state(0x760007b8, 0x10000202) 2022-08-01T10:31:37.171 cpa: insert_wsi_socket_into_fds: 0x760007b8: tsi=0, sock=33, pos-in-fds=1 2022-08-01T10:31:37.171 cpa: _lws_change_pollfd: wsi 0x760007b8: fd 33 events 1 -> 1 2022-08-01T10:31:37.173 cpa: __lws_set_timeout: 0x760007b8: 20 secs, reason 2 2022-08-01T10:31:37.174 cpa: lws_client_connect_3_connect: connect says errno: 115 2022-08-01T10:31:37.174 cpa: _lws_change_pollfd: wsi 0x760007b8: fd 33 events 1 -> 5 2022-08-01T10:31:37.174 cpa: lws_client_connect_via_info: wsi 0x760007b8: adoption cb 19 to h1 ocpp1.6 2022-08-01T10:31:37.174 cpa: ocpp client: (re-)connecting to '192.168.255.254:80' 2022-08-01T10:31:57.174 cpa: wsi 0x760007b8: TIMEDOUT WAITING on 2 (did hdr 0, ah 0x76001248, wl 0) 2022-08-01T10:31:57.174 cpa: lws_close_free_wsi: 0x760007b8: caller: timeout 2022-08-01T10:31:57.174 cpa: lws_close_free_wsi: 0x760007b8: DROP_PROTOCOL ocpp1.6 2022-08-01T10:31:57.175 cpa: ocpp client: cannot connect to server: closed before established (connecting) 2022-08-01T10:31:57.175 cpa: lws_close_free_wsi: real just_kill_connection: 0x760007b8 (sockfd 33) 2022-08-01T10:31:57.175 cpa: lwsi_set_state(0x760007b8, 0x10000020) 2022-08-01T10:31:57.175 cpa: lws_close_free_wsi_final: wsi 0x760007b8: fd 33 2022-08-01T10:31:57.175 cpa: rops_destroy_role_h1: ah det due to close 2022-08-01T10:31:57.177 cpa: __lws_header_table_detach: wsi 0x760007b8: ah 0x76001248 (tsi=0, count = 1) 2022-08-01T10:31:57.177 cpa: lws_header_table_detach: wsi 0x760007b8: ah held 20s, role/state 0x10000000 0x20, 2022-08-01T10:31:57.178 cpa: lws_header_table_detach: nobody usable waiting 2022-08-01T10:31:57.178 cpa: _lws_destroy_ah: freed ah 0x76001248 : pool length 0 2022-08-01T10:31:57.178 cpa: lws_header_table_detach: wsi 0x760007b8: ah 0x76001248 (tsi=0, count = 0) 2022-08-01T10:31:57.178 cpa: lws_vhost_unbind_wsi: vh default: count_bound_wsi 0 2022-08-01T10:31:57.178 cpa: __lws_free_wsi: 0x760007b8, remaining wsi 1, tsi fds count 1 2022-08-01T10:32:14.204 cpa: _realloc: size 496: client wsi

lws-team commented 2 years ago

115 is EINPROGRESS on Linux, it isn't an error, it just means it doesn't think it has connected yet but is trying.

It will wait until it hears an event to say that it is connected, failed, or times out waiting for the connection to happen.

And indeed 20s later he times out.

I would use tcpdump to watch what actually happens, from this information, it's compatible with the server just not responding to the connection the second time (perhaps for whatver reason that the first connection was not responsive).

LilMouse commented 2 years ago

Thank you, I will do that!