Inbound call to webRTC failing with TCP/TLS connection (id: 0) for WebSocket could not be found
We're seeing an issue where some webRTC clients are not receiving inbound calls. Kamailio logs show the following error: WARNING: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: <core> [core/msg_translator.c:3007]: via_builder(): TCP/TLS connection (id: 0) for WebSocket could not be found ERROR: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: <core> [core/msg_translator.c:2086]: build_req_buf_from_sip_req(): could not create Via header ERROR: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: tm [t_fwd.c:484]: prepare_new_uac(): could not build request ERROR: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: tm [t_fwd.c:1764]: t_forward_nonack(): failure to add branches DEBUG: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: tm [t_funcs.c:358]: t_relay_to(): t_forward_nonack returned error -2 (-2) DEBUG: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: tm [t_funcs.c:376]: t_relay_to(): -2 error reply generation delayed It seems to be happening after the client has been connected to Kamailio for more than 24 hours. The socket connection details look correct in the external DB and in the output of ws.dump, core.tcp_list, and ul.dump. A restart of Kamailio or a reload of the webRTC client, triggering a new websocket connection, will clear the issue. However, we haven't been able to determine exactly when and why a client ends up in this state. While a client is in this state, REGISTER requests are still handled successfully, they can make outbound calls and TCP keepalives from the client are working. I'm still working on trying to debug this with GDB so I can see what the value of send_info is in https://github.com/kamailio/kamailio/blob/master/src/core/msg_translator.c#L..., but I wasn't having luck with multiple child processes running, and now my client has reloaded and is working again. I've restarted Kamailio with a single child process, so when it does start failing again, I may have better luck with GDB. Any thoughts on what might be causing clients to get into this state? Whatever additional information I can provide that might help, I'm happy to share. Thanks!
Hello, This is not really a Kamailio-side issue, and I think you're going down the wrong path looking at Kamailio source code. There are many reasons why browser-based clients become unreachable after a while, and they can be OS and browser-specific. It's a long and complex topic that is widely discussed in the industry. One common reason is that all browsers tend to idle inactive tabs after a while, to reduce resource consumption. This has the effect of breaking connections they maintain, including WebSocket connections. If that is indeed the problem here--and it seems quite likely that it is--then solutions include turning your client application into a PWA (Progressive Web App), or using one of the various cross-platform web application development frameworks (e.g. Electron), which allow you to use web technologies (HTML/CSS/JS/etc) inside a browser control to build a "native" application. This removes most of the restrictions browsers impose on applications running inside native browser tabs. In general, you need to tackle this from the client side. There's nothing to debug on the server. You said it yourself: "a reload of the webRTC client, triggering a new websocket connection, will clear the issue". -- Alex
On Aug 13, 2024, at 1:38 PM, hollis.rhonda--- via sr-users <sr-users@lists.kamailio.org> wrote:
We're seeing an issue where some webRTC clients are not receiving inbound calls. Kamailio logs show the following error:
WARNING: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: <core> [core/msg_translator.c:3007]: via_builder(): TCP/TLS connection (id: 0) for WebSocket could not be found ERROR: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: <core> [core/msg_translator.c:2086]: build_req_buf_from_sip_req(): could not create Via header ERROR: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: tm [t_fwd.c:484]: prepare_new_uac(): could not build request ERROR: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: tm [t_fwd.c:1764]: t_forward_nonack(): failure to add branches DEBUG: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: tm [t_funcs.c:358]: t_relay_to(): t_forward_nonack returned error -2 (-2) DEBUG: {1 609669922 INVITE BW152025538120824-895739618@10.103.43.11}: tm [t_funcs.c:376]: t_relay_to(): -2 error reply generation delayed
It seems to be happening after the client has been connected to Kamailio for more than 24 hours. The socket connection details look correct in the external DB and in the output of ws.dump, core.tcp_list, and ul.dump. A restart of Kamailio or a reload of the webRTC client, triggering a new websocket connection, will clear the issue. However, we haven't been able to determine exactly when and why a client ends up in this state. While a client is in this state, REGISTER requests are still handled successfully, they can make outbound calls and TCP keepalives from the client are working.
I'm still working on trying to debug this with GDB so I can see what the value of send_info is in https://github.com/kamailio/kamailio/blob/master/src/core/msg_translator.c#L..., but I wasn't having luck with multiple child processes running, and now my client has reloaded and is working again. I've restarted Kamailio with a single child process, so when it does start failing again, I may have better luck with GDB.
Any thoughts on what might be causing clients to get into this state? Whatever additional information I can provide that might help, I'm happy to share. Thanks! __________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions To unsubscribe send an email to sr-users-leave@lists.kamailio.org Important: keep the mailing list in the recipients, do not reply only to the sender! Edit mailing list options or unsubscribe:
-- Alex Balashov Principal Consultant Evariste Systems LLC Web: https://evaristesys.com Tel: +1-706-510-6800
Hi Alex. Our app already is PWA in Electron, and I can see keepalives from the client to Kamailio when the client is in this state. We are running network traces though to see what we can find there. It's just been a pain to debug, because we haven't figured out what's triggering the error, so it's a lot of waiting for a client to start showing the behavior again. Our issue looks similar to this one, but the linked issue on there shows "tcp connection has been lost" errors, which we are not seeing. https://lists.kamailio.org/mailman3/hyperkitty/list/sr-users@lists.kamailio.... The log snippets below show a successful registration and keepalive followed by the Websocket error on an inbound INVITE. -- handling REGISTER --- 2024-08-12T16:31:33.798220+00:00 kamailio02 /usr/local/sbin/kamailio[124476]: DEBUG: {1 787 REGISTER lh2ov51675v0k9abroklui}: app_jsdt [app_jsdt_api.c:780]: sr_kemi_jsdt_exec_func_ex(): param[0] for: lookup_uri is str: location 2024-08-12T16:31:33.798264+00:00 kamailio02 /usr/local/sbin/kamailio[124476]: DEBUG: {1 787 REGISTER lh2ov51675v0k9abroklui}: app_jsdt [app_jsdt_api.c:780]: sr_kemi_jsdt_exec_func_ex(): param[1] for: lookup_uri is str: sip:rhollis7717@devsip.lab.com 2024-08-12T16:31:33.798307+00:00 kamailio02 /usr/local/sbin/kamailio[124476]: DEBUG: {1 787 REGISTER lh2ov51675v0k9abroklui}: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 4 2024-08-12T16:31:33.798840+00:00 kamailio02 /usr/local/sbin/kamailio[124476]: INFO: {1 787 REGISTER lh2ov51675v0k9abroklui}: <core> [core/kemi.c:107]: sr_kemi_core_info(): saving user:rhollis7717 in registrar DB --- keepalive from webrtc client --- 2024-08-12T16:33:33.268238+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_read.c:1776]: handle_io(): received n=8 con=0x7faf57fae7a0, fd=7 2024-08-12T16:33:33.268286+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_read.c:1250]: ws_process_msg(): WebSocket Message: [[>>> <81><82>cí<84>Înç<<<]] 2024-08-12T16:33:33.268320+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 4 2024-08-12T16:33:33.268346+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 4 2024-08-12T16:33:33.268378+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:2618]: tcpconn_send_put(): send from reader (124471 (48)), reusing fd 2024-08-12T16:33:33.268416+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:2849]: tcpconn_do_send(): sending... 2024-08-12T16:33:33.268451+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:2885]: tcpconn_do_send(): after real write: c= 0x7faf57fae7a0 n=4 fd=7 2024-08-12T16:33:33.268485+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:2886]: tcpconn_do_send(): buf= <81>^B^M 2024-08-12T16:33:33.268515+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/io_wait.h:368]: io_watch_add(): processing io_watch_add(0x559d06b58b80, 7, 2, 0x7faf57fae7a0) - fd_no=1 -- handling INVITE, connection found by ID -- 2024-08-12T16:33:34.824883+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/kemi.c:87]: sr_kemi_core_dbg(): in function: ksr_route_location() 2024-08-12T16:33:34.824935+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: app_jsdt [app_jsdt_api.c:780]: sr_kemi_jsdt_exec_func_ex(): param[0] for: is_proto is str: TVW 2024-08-12T16:33:34.824963+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: app_jsdt [app_jsdt_api.c:780]: sr_kemi_jsdt_exec_func_ex(): param[0] for: lookup is str: location 2024-08-12T16:33:34.824997+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 4 2024-08-12T16:33:34.825032+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: registrar [lookup.c:352]: lookup_helper(): contact for [rhollis7717] found by address 2024-08-12T16:33:34.825062+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: app_jsdt [app_jsdt_api.c:785]: sr_kemi_jsdt_exec_func_ex(): param[0] for: setflag is int: 2 -- preparing to forward INVITE, Websocket could not be found -- 2024-08-12T16:33:34.847693+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: tm [uac.c:715]: send_prepared_request_impl(): uac: 0x7faf57fd3740 branch: 0 to 10.101.114.38:5090 2024-08-12T16:33:34.847755+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/onsend.c:50]: run_onsend(): required parameters are not available - ignoring 2024-08-12T16:33:34.847814+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: dmq [dmq_funcs.c:183]: bcast_dmq_message1(): skipping node sip:10.101.114.39:5090 2024-08-12T16:33:34.847865+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: dialog [dlg_hash.c:1088]: dlg_unref_helper(): unref op on 0x7faf57f98bf0 with 1 from dlg_handlers.c:772 2024-08-12T16:33:34.847992+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: dialog [dlg_hash.c:1092]: dlg_unref_helper(): unref dlg 0x7faf57f98bf0 with 1 -> 1 2024-08-12T16:33:34.848134+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: tm [h_table.c:551]: tm_xdata_swap(): restore X/AVPs msg context from txdata 2024-08-12T16:33:34.848407+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/msg_translator.c:1845]: check_boundaries(): no multi-part body 2024-08-12T16:33:34.848473+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/msg_translator.c:428]: clen_builder(): content-length: 866 (866) 2024-08-12T16:33:34.848752+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: WARNING: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/msg_translator.c:3007]: via_builder(): TCP/TLS connection (id: 0) for WebSocket could not be found 2024-08-12T16:33:34.848915+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: ERROR: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/msg_translator.c:2086]: build_req_buf_from_sip_req(): could not create Via header
It's an insidious problem, but it's definitely client-side. Sadly, I lack the expertise in Electron apps required to properly advise you on what to do to improve the situation. However, speaking rather generally, in WebRTC land it is pretty much up to the clients to maintain the connection dependably. That can be a tall order, depending on the execution environment. -- Alex
On Aug 15, 2024, at 1:48 PM, hollis.rhonda--- via sr-users <sr-users@lists.kamailio.org> wrote:
Hi Alex.
Our app already is PWA in Electron, and I can see keepalives from the client to Kamailio when the client is in this state. We are running network traces though to see what we can find there. It's just been a pain to debug, because we haven't figured out what's triggering the error, so it's a lot of waiting for a client to start showing the behavior again.
Our issue looks similar to this one, but the linked issue on there shows "tcp connection has been lost" errors, which we are not seeing. https://lists.kamailio.org/mailman3/hyperkitty/list/sr-users@lists.kamailio....
The log snippets below show a successful registration and keepalive followed by the Websocket error on an inbound INVITE.
-- handling REGISTER --- 2024-08-12T16:31:33.798220+00:00 kamailio02 /usr/local/sbin/kamailio[124476]: DEBUG: {1 787 REGISTER lh2ov51675v0k9abroklui}: app_jsdt [app_jsdt_api.c:780]: sr_kemi_jsdt_exec_func_ex(): param[0] for: lookup_uri is str: location 2024-08-12T16:31:33.798264+00:00 kamailio02 /usr/local/sbin/kamailio[124476]: DEBUG: {1 787 REGISTER lh2ov51675v0k9abroklui}: app_jsdt [app_jsdt_api.c:780]: sr_kemi_jsdt_exec_func_ex(): param[1] for: lookup_uri is str: sip:rhollis7717@devsip.lab.com 2024-08-12T16:31:33.798307+00:00 kamailio02 /usr/local/sbin/kamailio[124476]: DEBUG: {1 787 REGISTER lh2ov51675v0k9abroklui}: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 4 2024-08-12T16:31:33.798840+00:00 kamailio02 /usr/local/sbin/kamailio[124476]: INFO: {1 787 REGISTER lh2ov51675v0k9abroklui}: <core> [core/kemi.c:107]: sr_kemi_core_info(): saving user:rhollis7717 in registrar DB
--- keepalive from webrtc client --- 2024-08-12T16:33:33.268238+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_read.c:1776]: handle_io(): received n=8 con=0x7faf57fae7a0, fd=7 2024-08-12T16:33:33.268286+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_read.c:1250]: ws_process_msg(): WebSocket Message: [[>>> <81><82>cí<84>Înç<<<]] 2024-08-12T16:33:33.268320+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 4 2024-08-12T16:33:33.268346+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 4 2024-08-12T16:33:33.268378+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:2618]: tcpconn_send_put(): send from reader (124471 (48)), reusing fd 2024-08-12T16:33:33.268416+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:2849]: tcpconn_do_send(): sending... 2024-08-12T16:33:33.268451+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:2885]: tcpconn_do_send(): after real write: c= 0x7faf57fae7a0 n=4 fd=7 2024-08-12T16:33:33.268485+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/tcp_main.c:2886]: tcpconn_do_send(): buf= <81>^B^M 2024-08-12T16:33:33.268515+00:00 kamailio02 /usr/local/sbin/kamailio[124471]: DEBUG: <core> [core/io_wait.h:368]: io_watch_add(): processing io_watch_add(0x559d06b58b80, 7, 2, 0x7faf57fae7a0) - fd_no=1
-- handling INVITE, connection found by ID -- 2024-08-12T16:33:34.824883+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/kemi.c:87]: sr_kemi_core_dbg(): in function: ksr_route_location() 2024-08-12T16:33:34.824935+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: app_jsdt [app_jsdt_api.c:780]: sr_kemi_jsdt_exec_func_ex(): param[0] for: is_proto is str: TVW 2024-08-12T16:33:34.824963+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: app_jsdt [app_jsdt_api.c:780]: sr_kemi_jsdt_exec_func_ex(): param[0] for: lookup is str: location 2024-08-12T16:33:34.824997+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 4 2024-08-12T16:33:34.825032+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: registrar [lookup.c:352]: lookup_helper(): contact for [rhollis7717] found by address 2024-08-12T16:33:34.825062+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: app_jsdt [app_jsdt_api.c:785]: sr_kemi_jsdt_exec_func_ex(): param[0] for: setflag is int: 2
-- preparing to forward INVITE, Websocket could not be found -- 2024-08-12T16:33:34.847693+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: tm [uac.c:715]: send_prepared_request_impl(): uac: 0x7faf57fd3740 branch: 0 to 10.101.114.38:5090 2024-08-12T16:33:34.847755+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/onsend.c:50]: run_onsend(): required parameters are not available - ignoring 2024-08-12T16:33:34.847814+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: dmq [dmq_funcs.c:183]: bcast_dmq_message1(): skipping node sip:10.101.114.39:5090 2024-08-12T16:33:34.847865+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: dialog [dlg_hash.c:1088]: dlg_unref_helper(): unref op on 0x7faf57f98bf0 with 1 from dlg_handlers.c:772 2024-08-12T16:33:34.847992+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: dialog [dlg_hash.c:1092]: dlg_unref_helper(): unref dlg 0x7faf57f98bf0 with 1 -> 1 2024-08-12T16:33:34.848134+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: tm [h_table.c:551]: tm_xdata_swap(): restore X/AVPs msg context from txdata 2024-08-12T16:33:34.848407+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/msg_translator.c:1845]: check_boundaries(): no multi-part body 2024-08-12T16:33:34.848473+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: DEBUG: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/msg_translator.c:428]: clen_builder(): content-length: 866 (866) 2024-08-12T16:33:34.848752+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: WARNING: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/msg_translator.c:3007]: via_builder(): TCP/TLS connection (id: 0) for WebSocket could not be found 2024-08-12T16:33:34.848915+00:00 kamailio02 /usr/local/sbin/kamailio[124436]: ERROR: {1 599264557 INVITE BW093334808120824-485445593}: <core> [core/msg_translator.c:2086]: build_req_buf_from_sip_req(): could not create Via header __________________________________________________________ Kamailio - Users Mailing List - Non Commercial Discussions To unsubscribe send an email to sr-users-leave@lists.kamailio.org Important: keep the mailing list in the recipients, do not reply only to the sender! Edit mailing list options or unsubscribe:
-- Alex Balashov Principal Consultant Evariste Systems LLC Web: https://evaristesys.com Tel: +1-706-510-6800
I appreciate you responding! I'll update here when we get this sorted out. -r
participants (2)
-
Alex Balashov -
hollis.rhonda＠gmail.com