[kamailio/kamailio] Kamailio not retrieving custom or default socket when sending timed REGISTER messages (#2262)
### Description
When using Kamailio in a multi-homed configuration to register with another device using the uac module, it does not retrieve the custom or default socket information for timed registration attempts. It does, however, use the custom/default socket data for the initial registration.
#### Reproduction
The network is configured for two addresses: 10.9.9.121/24 and 10.9.7.121/24.
Two floating IP addresses are also assigned (via Pacemaker/Corosync): 10.9.9.120/24 and 10.9.7.120/24. For testing, all addresses can be assigned permanently, so it is not necessary to have Pacemaker/Corosync installed.
MySQL database has a user in the uacreg table with the socket column set to udp:10.9.7.120:5060.
kamailio.cfg includes the following to enable sending of REGISTER messages:
mhomed = 1 listen=udp:10.9.9.120 listen=udp:10.9.7.120
#!define DBURL "mysql://kamailio:kamailiorw@10.9.9.101/kamailio"
modparam("rr", "append_fromtag", 1); modparam("uac", "reg_db_url", DBURL); modparam("uac", "reg_contact_addr", "10.9.7.120:5060"); modparam("uac", "reg_keep_callid", 1); modparam("uac", "default_socket", "udp:10.9.7.120:5060"); modparam("uac", "reg_timer_interval", 30);
#### Log Messages
The initial REGISTER outputs the following log data. The registration completes successfully.
Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: uac [uac.c:407]: child_init(): run initial uac registration routine Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: uac [uac_reg.c:1172]: uac_reg_update(): using custom socket udp:10.9.7.120:5060 to send request Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/socket_info.c:628]: grep_sock_info(): checking if host==us: 10==10 && [10.9.7.120] == [10.9.9.120] Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/socket_info.c:635]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/socket_info.c:628]: grep_sock_info(): checking if host==us: 10==10 && [10.9.7.120] == [10.9.7.120] Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/socket_info.c:635]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060 Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: tm [uac.c:435]: t_uac_prepare(): next_hop=sip:10.9.7.102 Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: tm [uac.c:158]: dlg2hash(): hashid 3846 Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: tm [uac.c:244]: t_run_local_req(): executing event_route[tm:local-request] Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/parser/msg_parser.c:612]: parse_msg(): method: <REGISTER> Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): uri: sip:10.9.7.102 Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK60f.6fd7c907000000000000000000000000.0>; state=16 Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via Mar 24 19:09:27 kam_test kamailio[8425]: exec: *** cfgtrace:local_route=[tm:local-request] c=[/usr/local/etc/kamailio/kamailio.cfg] l=229 a=26 n=xlog Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: <script>: In event_route(tm:local-request) Mar 24 19:09:27 kam_test kamailio[8425]: DEBUG: tm [uac.c:664]: send_prepared_request_impl(): uac: 0x7268e184 branch: 0 to 10.9.7.102:5060
When the timer expires, the following is logged. Since the socket is not found, the registration fails:
Mar 24 19:09:57 kam_test kamailio[8425]: DEBUG: tm [uac.c:435]: t_uac_prepare(): next_hop=sip:10.9.7.102 Mar 24 19:09:57 kam_test kamailio[8425]: ERROR: <core> [core/forward.c:181]: get_out_socket(): no socket found Mar 24 19:09:57 kam_test kamailio[8425]: ERROR: <core> [core/forward.c:183]: get_out_socket(): no corresponding socket found for(udp:10.9.7.102:5060) Mar 24 19:09:57 kam_test kamailio[8425]: ERROR: tm [ut.h:316]: uri2dst2(): no corresponding socket found for "10.9.7.102" af 2 (udp:10.9.7.102:5060) Mar 24 19:09:57 kam_test kamailio[8425]: ERROR: tm [uac.c:463]: t_uac_prepare(): no socket found Mar 24 19:09:57 kam_test kamailio[8425]: DEBUG: tm [h_table.c:132]: free_cell_helper(): freeing transaction 0x7268de10 from uac.c:604 Mar 24 19:09:57 kam_test kamailio[8425]: ERROR: uac [uac_reg.c:1196]: uac_reg_update(): failed to send request for [kamailioha]
### Additional Information
version: kamailio 5.3.2 (arm6/linux) flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled on 17:22:05 Mar 18 2020 with gcc 8.3.0
* **Operating System**:
Linux kam_test 4.19.75-v7+ #1270 SMP Tue Sep 24 18:45:11 BST 2019 armv7l GNU/Linux
Thanks for the report. Can you try with the commit referenced above. If tested successful I will backport to stable branches.
The commit resolves the issue for me. Thank you for the prompt attention.
thanks, backported to 5.3 branch
Closed #2262.
I had the same problem,but it did not fix issue commit a752411
**kamailio.cfg uac block below:** #!define DBURL "sqlite:///app-service/cloudland/edge-server/etc/kamailio/kamailio.db"
modparam("rr", "append_fromtag", 1) #modparam("ctl", "binrpc", "unix:/var/run/kamailio/kamailio_ctl") modparam("uac", "reg_db_url", DBURL); modparam("uac", "reg_contact_addr", "172.26.0.83:5060"); #modparam("uac", "reg_keep_callid", 1); modparam("uac", "reg_timer_interval", 10); modparam("uac", "reg_retry_interval", 20);
**sqlite database has a user in the uacreg table with the socket column set to udp:172.26.0.83:5060 details as below** sqlite> select * from uacreg; id|l_uuid|l_username|l_domain|r_username|r_domain|realm|auth_username|auth_password|auth_ha1|auth_proxy|expires|flags|reg_delay|socket 1|1002|1002|172.26.0.83|1002|172.26.0.83|172.26.0.83|1002|1002|23598b35f7c629a6790d79ae72934856|sip:172.26.0.83|360|0|0|udp:172.26.0.83:5060
**Log Messages** 13(21432) DEBUG: db_sqlite [dbase.c:223]: db_sqlite_submit_query(): submit_query: select l_uuid,l_username,l_domain,r_username,r_domain,realm,auth_username,auth_password,auth_ha1,auth_proxy,expires,flags,reg_delay,socket from uacreg 13(21432) DEBUG: <core> [db_query.c:72]: db_do_submit_query(): submitted query: select l_uuid,l_username,l_domain,r_username,r_domain,realm,auth_username,auth_password,auth_ha1,auth_proxy,expires,flags,reg_delay,socket from uacreg , result 0 13(21432) DEBUG: <core> [db_res.c:120]: db_new_result(): allocate 56 bytes for result set at 0x7efd8c53c768 13(21432) DEBUG: <core> [db_res.c:158]: db_allocate_columns(): allocate 112 bytes for result names at 0x7efd8c53c808 13(21432) DEBUG: <core> [db_res.c:169]: db_allocate_columns(): allocate 56 bytes for result types at 0x7efd8c53c8e0 13(21432) DEBUG: <core> [db_row.c:117]: db_allocate_row(): allocate 448 bytes for row values at 0x7efd8c5c5cc8 13(21432) DEBUG: uac [uac_reg.c:581]: reg_ht_add(): added uuid: 1002 - l_user: 1002 13(21432) DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 14 columns 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at 0x7efd8c527cb0 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[1] at 0x7efd8c527d30 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[2] at 0x7efd8c527db8 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[3] at 0x7efd8c527e40 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[4] at 0x7efd8c527ec8 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[5] at 0x7efd8c527f50 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[6] at 0x7efd8c527fd0 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[7] at 0x7efd8c528058 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[8] at 0x7efd8c5280e0 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[9] at 0x7efd8c528168 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[10] at 0x7efd8c5c59d8 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[11] at 0x7efd8c5c5a58 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[12] at 0x7efd8c5c5ad8 13(21432) DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[13] at 0x7efd8c5c5b60 13(21432) DEBUG: <core> [db_res.c:96]: db_free_columns(): freeing result names at 0x7efd8c53c808 13(21432) DEBUG: <core> [db_res.c:101]: db_free_columns(): freeing result types at 0x7efd8c53c8e0 13(21432) DEBUG: <core> [db_res.c:52]: db_free_rows(): freeing 1 rows 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[0] '1002' at 0x7efd8c4fe160 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[1] '1002' at 0x7efd8c4a4160 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[2] '172.26.0.83' at 0x7efd8c4fdba8 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[3] '1002' at 0x7efd8c5c5ef0 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[4] '172.26.0.83' at 0x7efd8c5c5f60 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[5] '172.26.0.83' at 0x7efd8c5c5fd8 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[6] '1002' at 0x7efd8c5c6050 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[7] '1002' at 0x7efd8c5c60c0 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[8] '23598b35f7c629a6790d79ae72934856' at 0x7efd8c5c6130 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[9] 'sip:172.26.0.83' at 0x7efd8c597e60 13(21432) DEBUG: <core> [db_row.c:66]: db_free_row(): free VAL_STRING[13] 'udp:172.26.0.83:5060' at 0x7efd8c597ed8 13(21432) DEBUG: <core> [db_row.c:95]: db_free_row(): freeing row values at 0x7efd8c5c5cc8 13(21432) DEBUG: <core> [db_res.c:60]: db_free_rows(): freeing rows at 0x7efd8c5c5be0 13(21432) DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7efd8c53c768 13(21432) DEBUG: <core> [db_pool.c:100]: pool_remove(): removing connection from the pool 13(21432) DEBUG: uac [uac.c:413]: child_init(): run initial uac registration routine 13(21432) DEBUG: uac [uac_reg.c:1137]: uac_reg_update(): using custom socket udp:172.26.0.83:5060 to send request 13(21432) DEBUG: tm [uac.c:451]: t_uac_prepare(): next_hop=sip:172.26.0.83 13(21432) ERROR: <core> [core/forward.c:182]: get_out_socket(): no socket found 13(21432) ERROR: <core> [core/forward.c:184]: get_out_socket(): no corresponding socket found for(udp:172.26.0.83:5060) 13(21432) ERROR: tm [ut.h:317]: uri2dst2(): no corresponding socket found for "172.26.0.83" af 2 (udp:172.26.0.83:5060) 13(21432) ERROR: tm [uac.c:473]: t_uac_prepare(): no socket found 13(21432) DEBUG: tm [h_table.c:132]: free_cell_helper(): freeing transaction 0x7efd82bfafa8 from uac.c:614 13(21432) ERROR: uac [uac_reg.c:1177]: uac_reg_update(): failed to send request for [1002] 6(21425) DEBUG: ctl [../../core/io_wait.h:375]: io_watch_add(): DBG: io_watch_add(0x7efd894923e0, 9, 3, 0x25115f0), fd_no=1 6(21425) DEBUG: ctl [io_listener.c:442]: handle_new_connect(): handle_stream read: new connection (1) on /var/run/kamailio/kamailio_ctl 6(21425) INFO: <core> [core/cfg/cfg_ctx.c:604]: cfg_set_now(): direction.sip has been changed to "172.26.0.83" 6(21425) DEBUG: ctl [io_listener.c:495]: handle_stream_read(): handle_stream read: eof on /var/run/kamailio/kamailio_ctl
**Additional Information** version: kamailio 5.4.1 (x86_64/linux) 09fd6a flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: 09fd6a compiled on 19:15:47 Jan 25 2021 with gcc 4.8.5
I found that kamailio 5.4.1 included the commit a752411 above mentioned,any one meet same issue ,or maybe somewhere configured wrong in kamailio.cfg,how to selove this issue,thanksssssss !
@lbli - send email to sr-users@lists.kamailio.org, it seems a configuration issue in your side, which can be clarified on users forum.
-
Daniel-Constantin Mierla -
Henning Westerholt
-
kdanderso
-
lbli