search

warmcat / libwebsockets

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

LWS_CALLBACK_CLIENT_CLOSED is triggered on iOS after LWS_INIT #1808

Closed paulobfsilva closed 4 years ago

paulobfsilva commented 4 years ago

Hi everyone,

I am testing an iOS app that uses libwebsockets to connect to a server. However, while implementing a stop method I noticed that the LWS_CALLBACK_CLIENT_CLOSED is called immediately after the first LWS_INIT callback. If I disregard this callback, however, the connection moves on, as in the log below. This is not happening in Android.

Here is a part of the log: [0m2019-12-27 15:39:13.592158+0000 TestsApp[768:1115846] [M: initiate_lws] URL Parsed. url: wss, urlProtocol: wss, clientConnectInfo.address: IP_ADDRESS, clientConnectInfo.port: 3000, urlPath: / 2019-12-27 15:39:13.592196+0000 TestsApp[768:1115846] [M: initiate_lws] Connecting to wss://IP_ADDRESS:3000/ 2019-12-27 15:39:13.592219+0000 TestsApp[768:1115846] [M: protocol_on_event] [Signalling] Protocol initial setup. (LWS_CALLBACK_PROTOCOL_INIT) 2019-12-27 15:39:13.592279+0000 TestsApp[768:1115846] [M: protocol_on_event] Client closed. (LWS_CALLBACK_CLIENT_CLOSED) 2019-12-27 15:39:13.599199+0000 TestsApp[768:1115846] [M: protocol_on_event] [Protocol] Earliest websocket notification. (LWS_CALLBACK_WSI_CREATE) 2019-12-27 15:39:13.703323+0000 TestsApp[768:1115846] [M: protocol_on_event] [Protocol] Websocket connection to server successfully established. (LWS_CALLBACK_CLIENT_ESTABLISHED)

What is the reason for this behavior? Thanks in advance

lws-team commented 4 years ago

What is the reason for this behavior?

Dunno, since I haven't seen such a thing. Can you maybe drop an assert(0) on the callback or use a debugger to stop it there and get the backtrace (in -DCMAKE_BUILD_TYPE=DEBUG mode with source lines) and tell the exact lws git hash

lws-team commented 4 years ago

... and dump the lws logs for that part at high verbosity...

paulobfsilva commented 4 years ago

Ok, thank you so much for your help. I am not sure how I am going to do it because libwebsockets is an included library on my project. (.a file for iOS) I have built in Debug mode, but there's no more output than before.

lws-team commented 4 years ago

Just the backtrace will probably be useful (if you tell the exact lws git hash).

Whatever sets up the lws_context in your code, there you can call this

https://libwebsockets.org/git/libwebsockets/tree/include/libwebsockets/lws-logs.h#n174

Eg like lws_set_log_level(1151, NULL) will normally send verbose logs on stderr. If there is no stderr or something else overrode it, you can set the second arg to point to this

void emit(int level, const char *line) { }

and "print" line somewhere useful.

paulobfsilva commented 4 years ago

Here is the output of the previous log, now including libwebsockets logs:

[Protocol] Protocol initial setup. (LWS_CALLBACK_PROTOCOL_INIT) [2019/12/27 16:57:56:6124] DEBUG: _realloc: size 472: client wsi [2019/12/27 16:57:56:6124] INFO: lws_vhost_bind_wsi: vh default: count_bound_wsi 1 [2019/12/27 16:57:56:6124] DEBUG: _realloc: size 200: client ws struct [2019/12/27 16:57:56:6124] DEBUG: lws_role_transition: 0x137d0fac0: wsistate 0x10000200, ops h1 [2019/12/27 16:57:56:6124] INFO: lws_client_connect_via_info: protocol binding to SignallingProtocol [2019/12/27 16:57:56:6124] INFO: lws_same_vh_protocol_remove: removing same prot wsi 0x137d0fac0 [2019/12/27 16:57:56:6124] DEBUG: lws_ensure_user_space: 0x137d0fac0 protocol pss 0, user_space=0x0 2019-12-27 16:57:56.612500+0000 TestsApp[3520:2858933] [M: protocol_on_event] Client closed. (LWS_CALLBACK_CLIENT_CLOSED) [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 64: client stash [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 15: strdup [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 2: strdup [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 15: strdup [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 15: strdup [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 22: strdup [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 9: strdup [2019/12/27 16:57:56:6126] INFO: lws_header_table_attach: wsi 0x137d0fac0: ah 0x0 (tsi 0, count = 0) in [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 960: ah struct [2019/12/27 16:57:56:6126] DEBUG: _realloc: size 4096: ah data [2019/12/27 16:57:56:6126] INFO: _lws_create_ah: created ah 0x137e0db10 (size 4096): pool length 1 [2019/12/27 16:57:56:6127] INFO: lws_header_table_attach: did attach wsi 0x137d0fac0: ah 0x137e0db10: count 1 (on exit) [2019/12/27 16:57:56:6127] DEBUG: lws_set_timeout: 0x137d0fac0: 10 secs (reason 25) [2019/12/27 16:57:56:6127] DEBUG: _realloc: size 15: strdup [2019/12/27 16:57:56:6127] INFO: lws_client_connect_2: 0x137d0fac0: address IP_ADDRESS [2019/12/27 16:57:56:6166] DEBUG: lwsi_set_state(0x137d0fac0, 0x10000201) [2019/12/27 16:57:56:6166] DEBUG: insert_wsi_socket_into_fds: 0x137d0fac0: tsi=0, sock=9, pos-in-fds=1 [2019/12/27 16:57:56:6166] DEBUG: _lws_change_pollfd: wsi 0x137d0fac0: fd 9 events 1 -> 1 2019-12-27 16:57:56.616681+0000 TestsApp[3520:2858933][M: protocol_on_event] [Protocol] Earliest websocket notification. (LWS_CALLBACK_WSI_CREATE) [2019/12/27 16:57:56:6167] DEBUG: lws_set_timeout: 0x137d0fac0: 20 secs (reason 2) [2019/12/27 16:57:56:6169] DEBUG: _lws_change_pollfd: wsi 0x137d0fac0: fd 9 events 1 -> 5 [2019/12/27 16:57:56:6695] DEBUG: _lws_change_pollfd: wsi 0x137d0fac0: fd 9 events 5 -> 1 [2019/12/27 16:57:56:6696] INFO: lws_client_connect_2: 0x137d0fac0: address 34.240.140.170 [2019/12/27 16:57:56:6702] INFO: lws_client_connect_2: wsi 0x137d0fac0: client creating own connection [2019/12/27 16:57:56:6703] DEBUG: lwsi_set_state(0x137d0fac0, 0x10000011) [2019/12/27 16:57:56:6703] DEBUG: __lws_set_timeout: 0x137d0fac0: 20 secs (reason 8) [2019/12/27 16:57:56:6703] DEBUG: _lws_change_pollfd: wsi 0x137d0fac0: fd 9 events 1 -> 1 [2019/12/27 16:57:56:6703] DEBUG: lwsi_set_state(0x137d0fac0, 0x10000012) [2019/12/27 16:57:56:6703] DEBUG: lws_set_timeout: 0x137d0fac0: 20 secs (reason 11) [2019/12/27 16:57:56:6703] INFO: lws_client_socket_service: HANDSHAKE2: 0x137d0fac0: sending headers on 0x137d0fac0 (wsistate 0x10000012 0x10000012) [2019/12/27 16:57:56:6704] DEBUG: lwsi_set_state(0x137d0fac0, 0x1000020a) [2019/12/27 16:57:56:6704] DEBUG: lws_set_timeout: 0x137d0fac0: 20 secs (reason 4) [2019/12/27 16:57:56:6704] DEBUG: _lws_change_pollfd: wsi 0x137d0fac0: fd 9 events 1 -> 5 [2019/12/27 16:57:56:6704] DEBUG: lwsi_set_state(0x137d0fac0, 0x1000020a) [2019/12/27 16:57:56:6704] DEBUG: lws_set_timeout: 0x137d0fac0: 20 secs (reason 4) [2019/12/27 16:57:56:6705] DEBUG: _lws_change_pollfd: wsi 0x137d0fac0: fd 9 events 5 -> 1 ... [SOME MORE OUTPUT ABOUT WSI_TOKEN_NAME_PART...] ... [2019/12/27 16:57:56:7213] PARSER: known hdr 8 [2019/12/27 16:57:56:7213] PARSER: v00 hdrs done [2019/12/27 16:57:56:7214] PARSER: lws_client_int_s_hs: protocol list 'Protocol' [2019/12/27 16:57:56:7214] DEBUG: Selected protocol Protocol [2019/12/27 16:57:56:7214] DEBUG: lws_ensure_user_space: 0x137d0fac0 protocol pss 0, user_space=0x0 [2019/12/27 16:57:56:7214] DEBUG: lws_set_timeout: 0x137d0fac0: 0 secs (reason 0) [2019/12/27 16:57:56:7214] INFO: __lws_header_table_detach: wsi 0x137d0fac0: ah 0x137e0db10 (tsi=0, count = 1) [2019/12/27 16:57:56:7214] INFO: lws_header_table_detach: nobody usable waiting [2019/12/27 16:57:56:7214] INFO: _lws_destroy_ah: freed ah 0x137e0db10 : pool length 0 [2019/12/27 16:57:56:7214] INFO: __lws_header_table_detach: wsi 0x137d0fac0: ah 0x137e0db10 (tsi=0, count = 0) [2019/12/27 16:57:56:7214] DEBUG: lws_role_transition: 0x137d0fac0: wsistate 0x10000117, ops ws [2019/12/27 16:57:56:7215] DEBUG: _realloc: size 32788: client frame buffer [2019/12/27 16:57:56:7215] INFO: Allocating client RX buffer 32784 [2019/12/27 16:57:56:7215] DEBUG: handshake OK for protocol Protocol 2019-12-27 16:57:56.721615+0000 TestsApp[3520:2858933] [M: protocol_on_event] [Protocol] Websocket connection to server successfully established. (LWS_CALLBACK_CLIENT_ESTABLISHED)

lws-team commented 4 years ago

It looks like the lws is not very recent (v3.1) 

�[0m�[34;1m[2019/12/27 16:57:56:6124] DEBUG: lws_ensure_user_space: 0x137d0fac0 protocol pss 0, user_space=0x0
�[0m2019-12-27 16:57:56.612500+0000 TestsApp[3520:2858933] [M: protocol_on_event] Client closed. (LWS_CALLBACK_CLIENT_CLOSED)
�[34;1m[2019/12/27 16:57:56:6126] DEBUG: _realloc: size 64: client stash

He really doesn't feel like he's closing anything.

Have you maybe done something like fall thru from the previous case: in your protocol callback, so it accidentally enters the CLOSE: case, so some other callback is triggering this?

lws-team commented 4 years ago

... also maybe add %p for wsi on your debug logging, it's possible this is some previous wsi on the same protocol closing overlapping a new client connection attempt.

paulobfsilva commented 4 years ago

Thank you so much for your help. I will add %p for wsi and get back with the result. The first suggestion is very hard to be the case, as this is not happening in Android, and the core code is the same between both apps. Android may be using a more recent version of libwebsockets, I will have to check that out.

lws-team commented 4 years ago

The first suggestion is very hard to be the case, as this is not happening in Android, and the core code is the same between both apps.

OK. There's no point for anyone chasing ancient bugs it's best to align on recent lws.

paulobfsilva commented 4 years ago

It was a version issue. Problem solved. Sorry about the time wasted...