Closing the websocket connection takes ~53 secs

[Rajasekhar-topgear]

Hi Experts,

             We followed the below link under the section "Closing connections from the user side" and followed the same. We are invoking the API lws_callback_on_writable() and returning "-1" to the LWS to close the connection. We are expecting the connection to be closed within a few seconds but it takes nearly 53 seconds to close the connection. Please find the logs below.

https://libwebsockets.org/lws-api-doc-master/html/md_README.coding.html#:~:text=When%20you%20want%20to%20close,it%20and%20just%20return%20-1.

    1) Could you please let us know if this is expected behavior (OR) if there is any way that the connection can be closed quickly (~ 5 to 10 secs).
    2)  When I tried the API lws_close_free_wsi() to close the connection, LWS takes milliseconds to close the connection. Can we use the API lws_close_free_wsi() to close the websocket connection from user side (OR) would there be any restrictions that only LWS can only use this API due to any limitations.

Logs with code return '-1' ::

2022/04/11 15:00:38.464978580 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (note): Disconnect_server:: Setting disconnect_needed to TRUE, provoke CALLBACK
2022/04/11 15:00:38.464988400 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 35 - LOCK_POLL
2022/04/11 15:00:38.464993220 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (ERR): Disconnect Needed Set to True, Closing Connection

2022/04/11 15:01:31.172424510 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (debug): LWS_CALLBACK_DEL_POLL_FD::
2022/04/11 15:01:31.172451950 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (note): TPPR/address is NULL
2022/04/11 15:01:31.172454290 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 36 - UNLOCK_POLL
2022/04/11 15:01:31.172458110 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (debug): lwsi_set_state([wsicli|1|WS/h1/10.105.58.33], 0x10000020)
2022/04/11 15:01:31.172466020 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (info): __lws_close_free_wsi: [wsicli|1|WS/h1/10.105.58.33]: cce=1
2022/04/11 15:01:31.172468200 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 75 - CLIENT_CLOSED
2022/04/11 15:01:31.172702430 {ida_ws_R0-0}{1}: [ida_ws] [6775]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 30 - WSI_DESTROY

Logs with code calling API lws_close_free_wsi()::

2022/04/08 16:11:43.550327260 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (note): Keepalive timer cleared
2022/04/08 16:11:43.550329080 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (ERR): Disconnect_server:: CLOSE the connection using CLOSE FREE WSI

2022/04/08 16:11:43.550341050 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (info): lws_close_free_wsi: [wsicli|1|WS/h1/10.105.58.33]: caller: normal disconnect
2022/04/08 16:11:43.550358650 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (debug): lws_close_free_wsi: real just_kill_connection A: [wsicli|1|WS/h1/10.105.58.33] (sockfd 21)
2022/04/08 16:11:43.550364520 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (info): lws_close_free_wsi: real just_kill_connection: [wsicli|1|WS/h1/10.105.58.33] (sockfd 21) 2022/04/08 16:11:43.550398090 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 35 - LOCK_POLL
2022/04/08 16:11:43.550406060 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 33 - DEL_POLL_FD
2022/04/08 16:11:43.550407860 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (debug): LWS_CALLBACK_DEL_POLL_FD::
2022/04/08 16:11:43.550436240 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (note): TPPR/address is NULL
2022/04/08 16:11:43.550438200 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 36 - UNLOCK_POLL
2022/04/08 16:11:43.550445630 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (debug): lwsi_set_state([wsicli|1|WS/h1/10.105.58.33], 0x10000020)
2022/04/08 16:11:43.550455890 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (info): lws_close_free_wsi: [wsicli|1|WS/h1/10.105.58.33]: cce=1
2022/04/08 16:11:43.550457910 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 75 - CLIENT_CLOSED
2022/04/08 16:11:43.550751680 {ida_ws_R0-0}{1}: [ida_ws] [6755]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 30 - WSI_DESTROY

Thanks, Rajasekhar.

[lws-team]

Are you asking for the writeable from a different thread? That's not legal if so. It can break in a variety of ways, including just crashing, but one way it breaks is the event loop thread stays asleep until something else wakes it, whereupon it might notice the new wake event or may overwrite it depending on platform.

You can also use lws_wsi_close(wsi, LWS_TO_KILL_ASYNC); - from the event loop thread - to schedule the wsi to close next time around the event loop.

[Rajasekhar-topgear]

Thanks a lot for your response. No, I was asking for the writeable from the same thread only. We have only one thread.

I tried with lws_wsi_close(wsi, LWS_TO_KILL_ASYNC), still takes around 1 minute to close the connection. Please find the logs.

Logs::

2022/04/13 10:39:17.743942450 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (note): Disconnect_server:: Setting disconnect_needed to TRUE, close using LWS_TO_KILL_ASYNC
2022/04/13 10:39:17.743963280 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (debug): __lws_set_timeout: [wsicli|1|WS/h1/10.105.58.33]: 0 secs, reason 1
2022/04/13 10:39:17.743965730 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (info): Sending TPPR CLI's result to IOS

2022/04/13 10:40:19.511825700 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (debug): Ws_read:: FD: 21
2022/04/13 10:40:19.511846320 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (note): Service client fd:: fd(21), n: 1
2022/04/13 10:40:19.511862480 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 35 - LOCK_POLL
2022/04/13 10:40:19.511868270 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (ERR): Disconnect Needed Set to True, Closing Connection
2022/04/13 10:40:19.511875640 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (info): failed at set pollfd
2022/04/13 10:40:19.511881310 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (debug): lws_service_fd_tsi: [wsicli|1|WS/h1/10.105.58.33]: Close and handled
2022/04/13 10:40:19.511885850 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (info): lws_close_free_wsi: [wsicli|1|WS/h1/10.105.58.33]: caller: close_and_handled
2022/04/13 10:40:19.511905970 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (debug): lws_close_free_wsi: real just_kill_connection A: [wsicli|1|WS/h1/10.105.58.33] (sockfd 21) 2022/04/13 10:40:19.511912150 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (info): lws_close_free_wsi: real just_kill_connection: [wsicli|1|WS/h1/10.105.58.33] (sockfd 21)
2022/04/13 10:40:19.511915810 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 35 - LOCK_POLL
2022/04/13 10:40:19.511919830 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 33 - DEL_POLL_FD
2022/04/13 10:40:19.511921480 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (debug): LWS_CALLBACK_DEL_POLL_FD::
2022/04/13 10:40:19.511948870 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (note): TPPR/address is NULL
2022/04/13 10:40:19.511951430 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 36 - UNLOCK_POLL
2022/04/13 10:40:19.511956390 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (debug): lwsi_set_state([wsicli|1|WS/h1/10.105.58.33], 0x10000020)
2022/04/13 10:40:19.511965200 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (info): lws_close_free_wsi: [wsicli|1|WS/h1/10.105.58.33]: cce=1
2022/04/13 10:40:19.511967390 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 75 - CLIENT_CLOSED
2022/04/13 10:40:19.512214660 {ida_ws_R0-0}{1}: [ida_ws] [6756]: UUID: 0, ra: 0 (ERR): LWS Callback:: REASON: 30 - WSI_DESTROY

[lws-team]

Hm... I'm not seeing anything telling me the problem is in lws, and not your code. I can't see (don't particularly want to...) your code, so it's unreasonable to dump this on me.

I think you need to either show the problem coming on a minimal example, so I can reproduce it, or look further yourself into exactly what is happening during that 1 minute.

[Rajasekhar-topgear]

OK. I will try to find out what is happening in 1 minute.

Alternatively, Can I use lws_close_free_wsi() from the application side?

[lws-team]

No, it's an internal api.

Your main problem is you lose control of what's happening for a minute, eg, you're doing something that blocks the event loop for a minute.. If you close a wsi and still lose control for a minute, that's not actually solving anything.

[Rajasekhar-topgear]

ok thanks

[Rajasekhar-topgear]

Can we use the API "lws_set_timeout(wsi, 1, LWS_TO_KILL_SYNC)" from appplication side?

[lws-team]

What does "application side" mean... if it's what we call "user code" then yes, it's a public api.

[Rajasekhar-topgear]

ok sure thanks.....yes, I mean "user code".

[lws-team]

I don't think there's anything for me to do here. If more information comes, feel free to continue.