Daniel-Constantin Mierla writes:

what happens when you send a sip message and have debug=3? Do you see any logs printed?

Nothing comes to syslog when register request arrives. Also kamailio does not respond to ctl command. Below is sample on what comes to syslog after start.

-- Juha

root@char:/var/www/manager# Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: ERROR: rtpengine [rtpengine.c:2667]: send_rtpp_command(): timeout waiting reply for command "" from RTP proxy udp:192.26.134.10:6050 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: ERROR: rtpengine [rtpengine.c:2541]: rtpp_test(): proxy did not respond to ping Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: rtpengine [rtpengine.c:2518]: rtpp_test(): rtpp udp:192.26.134.10:6050 disabled for ever Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: mtree [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f324a610 not found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20315]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy Dec 24 12:29:41 char /usr/bin/sip-proxy[20315]: INFO: rtpengine [rtpengine.c:2551]: rtpp_test(): rtp proxy udp:127.0.0.1:6050 found, support for it enabled Dec 24 12:29:41 char /usr/bin/sip-proxy[20315]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: mtree [mtree_mod.c:344]: child_init(): #3: database connection opened successfully Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: sipdump [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: siptrace [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f32b19b0 not found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy_usage Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:119]: db_new_result(): allocate 56 bytes for result set at 0x7f72f32fd570 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_res.c:67]: db_mysql_get_columns(): 1 columns returned from the query Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:156]: db_allocate_columns(): allocate 8 bytes for result names at 0x7f72f32ed3b0 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:167]: db_allocate_columns(): allocate 4 bytes for result types at 0x7f72f3495140 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_res.c:84]: db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[0] at 0x7f72f3495170 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_res.c:91]: db_mysql_get_columns(): RES_NAMES(0x7f72f3495170)[0]=[table_version] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_res.c:105]: db_mysql_get_columns(): use DB1_INT result type Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:188]: db_allocate_rows(): allocate 16 bytes for rows at 0x7f72f305b780 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_row.c:117]: db_allocate_row(): allocate 32 bytes for row values at 0x7f72f305b4c0 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_val.c:74]: db_str2val(): converting INT [4] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 1 columns Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at 0x7f72f3495170 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:96]: db_free_columns(): freeing result names at 0x7f72f32ed3b0 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:101]: db_free_columns(): freeing result types at 0x7f72f3495140 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:52]: db_free_rows(): freeing 1 rows Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_row.c:95]: db_free_row(): freeing row values at 0x7f72f305b4c0 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:60]: db_free_rows(): freeing rows at 0x7f72f305b780 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7f72f32fd570 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: sl [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: tls [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: websocket [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: tmx [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: tmx [tmx_mod.c:258]: child_init(): rank is (3) Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: sqlops [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f32b0a80 found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f32b0a80 not found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy_cache Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: domain [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: usrloc [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [ulcx-5c20b515-4f5d-] (0 / 19) Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: registrar [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [uloc-5c20b515-4f5d-] (0 / 19) Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: acc [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: auth_db [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: permissions [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: uac_redirect [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [rdir-5c20b515-4f5d-] (0 / 19) Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: nathelper [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: msilo [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: msilo [msilo.c:458]: child_init(): rank #3 / pid <20317> Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: msilo [msilo.c:477]: child_init(): #3 database connection opened successfully Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: htable [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: htable [htable.c:245]: child_init(): rank is (3) Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: kex [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: kex [kex_mod.c:155]: child_init(): rank is (3) Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [srid-5c20b515-4f5d-] (0 / 19) Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: rtimer [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: pua [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: pua [pua.c:312]: child_init(): child 3: Database connection opened successfully Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: local [udp receiver child=2 sock=192.168.43.107:5060] Dec 24 12:29:41 char /usr/bin/sip-proxy[20317]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 3 rank 3: tcpops [udp receiver child=2 sock=192.168.43.107:5060] ^C root@char:/var/www/manager# Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: ERROR: rtpengine [rtpengine.c:2667]: send_rtpp_command(): timeout waiting reply for command "" from RTP proxy udp:192.26.134.10:6050 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: ERROR: rtpengine [rtpengine.c:2541]: rtpp_test(): proxy did not respond to ping Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: rtpengine [rtpengine.c:2518]: rtpp_test(): rtpp udp:192.26.134.10:6050 disabled for ever Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: mtree [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f324a610 not found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy Dec 24 12:29:46 char /usr/bin/sip-proxy[20316]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:46 char /usr/bin/sip-proxy[20316]: INFO: rtpengine [rtpengine.c:2551]: rtpp_test(): rtp proxy udp:127.0.0.1:6050 found, support for it enabled Dec 24 12:29:46 char /usr/bin/sip-proxy[20316]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: mtree [mtree_mod.c:344]: child_init(): #1: database connection opened successfully Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: sipdump [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: siptrace [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f32b19b0 not found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy_usage Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:119]: db_new_result(): allocate 56 bytes for result set at 0x7f72f32fd570 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_res.c:67]: db_mysql_get_columns(): 1 columns returned from the query Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:156]: db_allocate_columns(): allocate 8 bytes for result names at 0x7f72f32ed3b0 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:167]: db_allocate_columns(): allocate 4 bytes for result types at 0x7f72f3495140 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_res.c:84]: db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[0] at 0x7f72f3495170 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_res.c:91]: db_mysql_get_columns(): RES_NAMES(0x7f72f3495170)[0]=[table_version] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_res.c:105]: db_mysql_get_columns(): use DB1_INT result type Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:188]: db_allocate_rows(): allocate 16 bytes for rows at 0x7f72f305b780 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_row.c:117]: db_allocate_row(): allocate 32 bytes for row values at 0x7f72f305b4c0 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_val.c:74]: db_str2val(): converting INT [4] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 1 columns Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at 0x7f72f3495170 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:96]: db_free_columns(): freeing result names at 0x7f72f32ed3b0 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:101]: db_free_columns(): freeing result types at 0x7f72f3495140 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:52]: db_free_rows(): freeing 1 rows Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_row.c:95]: db_free_row(): freeing row values at 0x7f72f305b4c0 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:60]: db_free_rows(): freeing rows at 0x7f72f305b780 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7f72f32fd570 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: sl [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: tls [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: websocket [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: tmx [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: tmx [tmx_mod.c:258]: child_init(): rank is (1) Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: sqlops [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f32b0a80 found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f32b0a80 not found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy_cache Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: domain [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: usrloc [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [ulcx-5c20b51a-4f5b-] (0 / 19) Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: registrar [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [uloc-5c20b51a-4f5b-] (0 / 19) Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: acc [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: auth_db [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: permissions [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: uac_redirect [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [rdir-5c20b51a-4f5b-] (0 / 19) Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: nathelper [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: msilo [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: msilo [msilo.c:458]: child_init(): rank #1 / pid <20315> Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: msilo [msilo.c:477]: child_init(): #1 database connection opened successfully Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: htable [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: htable [htable.c:245]: child_init(): rank is (1) Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: kex [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: kex [kex_mod.c:155]: child_init(): rank is (1) Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [srid-5c20b51a-4f5b-] (0 / 19) Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: rtimer [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: pua [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: pua [pua.c:312]: child_init(): child 1: Database connection opened successfully Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: local [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 1 rank 1: tcpops [udp receiver child=0 sock=192.168.43.107:5060] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/action.c:1664]: run_child_one_init_route(): attempting to run event_route[core:worker-one-init] Dec 24 12:29:46 char /usr/bin/sip-proxy[20315]: DEBUG: <core> [core/route.c:129]: route_add(): mapping routing block (0x5643cd4f2080)[core:worker-one-init] to 10 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: ERROR: rtpengine [rtpengine.c:2667]: send_rtpp_command(): timeout waiting reply for command "" from RTP proxy udp:192.26.134.10:6050 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: ERROR: rtpengine [rtpengine.c:2541]: rtpp_test(): proxy did not respond to ping Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: rtpengine [rtpengine.c:2518]: rtpp_test(): rtpp udp:192.26.134.10:6050 disabled for ever Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: mtree [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f324a610 not found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy Dec 24 12:29:51 char /usr/bin/sip-proxy[20318]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: mtree [mtree_mod.c:344]: child_init(): #2: database connection opened successfully Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: sipdump [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: siptrace [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f32b19b0 not found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy_usage Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:119]: db_new_result(): allocate 56 bytes for result set at 0x7f72f32fd570 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_res.c:67]: db_mysql_get_columns(): 1 columns returned from the query Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:156]: db_allocate_columns(): allocate 8 bytes for result names at 0x7f72f32ed3b0 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:167]: db_allocate_columns(): allocate 4 bytes for result types at 0x7f72f3495140 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_res.c:84]: db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[0] at 0x7f72f3495170 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_res.c:91]: db_mysql_get_columns(): RES_NAMES(0x7f72f3495170)[0]=[table_version] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_res.c:105]: db_mysql_get_columns(): use DB1_INT result type Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:188]: db_allocate_rows(): allocate 16 bytes for rows at 0x7f72f305b780 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_row.c:117]: db_allocate_row(): allocate 32 bytes for row values at 0x7f72f305b4c0 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_val.c:74]: db_str2val(): converting INT [4] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 1 columns Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at 0x7f72f3495170 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:96]: db_free_columns(): freeing result names at 0x7f72f32ed3b0 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:101]: db_free_columns(): freeing result types at 0x7f72f3495140 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:52]: db_free_rows(): freeing 1 rows Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_row.c:95]: db_free_row(): freeing row values at 0x7f72f305b4c0 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:60]: db_free_rows(): freeing rows at 0x7f72f305b780 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7f72f32fd570 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: sl [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: tls [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: websocket [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: tmx [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: tmx [tmx_mod.c:258]: child_init(): rank is (2) Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: sqlops [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f32b0a80 found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f32b0a80 not found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy_cache Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: domain [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: usrloc [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [ulcx-5c20b51f-4f5c-] (0 / 19) Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: registrar [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [uloc-5c20b51f-4f5c-] (0 / 19) Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: acc [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: auth_db [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: permissions [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: uac_redirect [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [rdir-5c20b51f-4f5c-] (0 / 19) Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: nathelper [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: msilo [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: msilo [msilo.c:458]: child_init(): rank #2 / pid <20316> Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: msilo [msilo.c:477]: child_init(): #2 database connection opened successfully Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: htable [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: htable [htable.c:245]: child_init(): rank is (2) Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: kex [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: kex [kex_mod.c:155]: child_init(): rank is (2) Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [sruid.c:105]: sruid_init(): root for sruid is [srid-5c20b51f-4f5c-] (0 / 19) Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: rtimer [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: pua [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: pua [pua.c:312]: child_init(): child 2: Database connection opened successfully Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: local [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20316]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 2 rank 2: tcpops [udp receiver child=1 sock=192.168.43.107:5060] Dec 24 12:29:51 char /usr/bin/sip-proxy[20318]: INFO: rtpengine [rtpengine.c:2551]: rtpp_test(): rtp proxy udp:127.0.0.1:6050 found, support for it enabled Dec 24 12:29:51 char /usr/bin/sip-proxy[20318]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: ERROR: rtpengine [rtpengine.c:2667]: send_rtpp_command(): timeout waiting reply for command "" from RTP proxy udp:192.26.134.10:6050 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: ERROR: rtpengine [rtpengine.c:2541]: rtpp_test(): proxy did not respond to ping Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: rtpengine [rtpengine.c:2518]: rtpp_test(): rtpp udp:192.26.134.10:6050 disabled for ever Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 4 rank 4: mtree [udp receiver child=3 sock=192.168.43.107:5060] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f324a610 not found in pool Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy Dec 24 12:29:56 char /usr/bin/sip-proxy[20321]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:56 char /usr/bin/sip-proxy[20321]: INFO: rtpengine [rtpengine.c:2551]: rtpp_test(): rtp proxy udp:127.0.0.1:6050 found, support for it enabled Dec 24 12:29:56 char /usr/bin/sip-proxy[20321]: DEBUG: rtpengine [rtpengine.c:668]: bind_force_send_ip(): force_send_ip_str not specified in .cfg file! Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: mtree [mtree_mod.c:344]: child_init(): #4: database connection opened successfully Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 4 rank 4: sipdump [udp receiver child=3 sock=192.168.43.107:5060] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 4 rank 4: siptrace [udp receiver child=3 sock=192.168.43.107:5060] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f32b19b0 not found in pool Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy_usage Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:119]: db_new_result(): allocate 56 bytes for result set at 0x7f72f32fd570 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_res.c:67]: db_mysql_get_columns(): 1 columns returned from the query Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:156]: db_allocate_columns(): allocate 8 bytes for result names at 0x7f72f32ed3b0 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:167]: db_allocate_columns(): allocate 4 bytes for result types at 0x7f72f3495140 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_res.c:84]: db_mysql_get_columns(): allocate 16 bytes for RES_NAMES[0] at 0x7f72f3495170 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_res.c:91]: db_mysql_get_columns(): RES_NAMES(0x7f72f3495170)[0]=[table_version] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_res.c:105]: db_mysql_get_columns(): use DB1_INT result type Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:188]: db_allocate_rows(): allocate 16 bytes for rows at 0x7f72f305b780 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_row.c:117]: db_allocate_row(): allocate 32 bytes for row values at 0x7f72f305b4c0 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_val.c:74]: db_str2val(): converting INT [4] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:79]: db_free_columns(): freeing 1 columns Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:83]: db_free_columns(): freeing RES_NAMES[0] at 0x7f72f3495170 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:96]: db_free_columns(): freeing result names at 0x7f72f32ed3b0 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:101]: db_free_columns(): freeing result types at 0x7f72f3495140 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:52]: db_free_rows(): freeing 1 rows Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_row.c:95]: db_free_row(): freeing row values at 0x7f72f305b4c0 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:60]: db_free_rows(): freeing rows at 0x7f72f305b780 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db_res.c:138]: db_free_result(): freeing result set at 0x7f72f32fd570 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 4 rank 4: sl [udp receiver child=3 sock=192.168.43.107:5060] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 4 rank 4: tls [udp receiver child=3 sock=192.168.43.107:5060] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 4 rank 4: websocket [udp receiver child=3 sock=192.168.43.107:5060] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 4 rank 4: tmx [udp receiver child=3 sock=192.168.43.107:5060] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: tmx [tmx_mod.c:258]: child_init(): rank is (4) Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:841]: init_mod_child(): idx 4 rank 4: sqlops [udp receiver child=3 sock=192.168.43.107:5060] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f32b0a80 found in pool Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db.c:314]: db_do_init2(): connection 0x7f72f32b0a80 not found in pool Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:107]: db_mysql_new_connection(): opening connection: mysql://xxxx:xxxx@127.0.0.1/sip_proxy_cache Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:146]: db_mysql_new_connection(): connection type is 127.0.0.1 via TCP/IP Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:147]: db_mysql_new_connection(): protocol version is 10 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: db_mysql [km_my_con.c:148]: db_mysql_new_connection(): server version is 10.1.37-MariaDB-0+deb9u1 Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [core/sr_module.c:618]: find_mod_export_record(): found export of <db_bind_api> in module db_mysql [/usr/lib/x86_64-linux-gnu/sip-proxy/modules/db_mysql.so] Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db.c:209]: db_bind_mod(): using db bind api for db_mysql Dec 24 12:29:56 char /usr/bin/sip-proxy[20318]: DEBUG: <core> [db.c:323]: db_do_init2(): connection 0x7f72f332e090 found in pool

Daniel-Constantin Mierla writes:

Can you see how many kamailio processes are running (w.g., with ps)? Are there expected number of there?

Same number of processes when I start K with proper rtpengine set and with one that has an rtpengine that does not respond.

If yes, take the PID of few of them and attach with gdb, then grab the back trace in order to see what they do.

There is 41 processes. Below is a few different ones.

-- Juha

--------------- #0 0x00007f9958d04210 in __pause_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x000055ce69f98509 in main_loop () at main.c:1755 #2 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958d359c3 in __recvfrom_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x000055ce6a029443 in udp_rcv_loop () at core/udp_server.c:460 #2 0x000055ce69f969cf in main_loop () at main.c:1621 #3 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958c7fe89 in __GI___sigwaitinfo (set=<optimized out>, info=0x0) at ../sysdeps/unix/sysv/linux/sigwaitinfo.c:56 #1 0x000055ce6a04c36a in slow_timer_main () at core/timer.c:1093 #2 0x000055ce69f971ab in main_loop () at main.c:1677 #3 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958d359c3 in __recvfrom_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x000055ce6a153168 in async_task_run (idx=1) at core/async_task.c:269 #2 0x000055ce6a151f9c in async_task_child_init (rank=0) at core/async_task.c:185 #3 0x000055ce6a0d5e3a in init_child (rank=0) at core/sr_module.c:867 #4 0x000055ce69f977cc in main_loop () at main.c:1703 #5 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958d350a3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x00007f99554117e7 in io_wait_loop_epoll (h=0x7f9955643340 <io_h>, t=10, repeat=0) at ../../core/io_wait.h:1034 #2 0x00007f9955415d1a in io_listen_loop (fd_no=1, cs_lst=0x55ce6c6b6680) at io_listener.c:281 #3 0x00007f9955431c4c in mod_child (rank=0) at ctl.c:338 #4 0x000055ce6a0d5a84 in init_mod_child (m=0x7f99580b0ea0, rank=0) at core/sr_module.c:843 #5 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b12d0, rank=0) at core/sr_module.c:839 #6 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b1600, rank=0) at core/sr_module.c:839 #7 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b1ac0, rank=0) at core/sr_module.c:839 #8 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b1ee0, rank=0) at core/sr_module.c:839 #9 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b2720, rank=0) at core/sr_module.c:839 #10 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b2a30, rank=0) at core/sr_module.c:839 #11 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b3210, rank=0) at core/sr_module.c:839 #12 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b34a0, rank=0) at core/sr_module.c:839 #13 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b36f0, rank=0) at core/sr_module.c:839 #14 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b3a20, rank=0) at core/sr_module.c:839 #15 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b4270, rank=0) at core/sr_module.c:839 #16 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b44c0, rank=0) at core/sr_module.c:839 #17 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b47f0, rank=0) at core/sr_module.c:839 #18 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b4c80, rank=0) at core/sr_module.c:839 #19 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b5250, rank=0) at core/sr_module.c:839 #20 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b6e20, rank=0) at core/sr_module.c:839 #21 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b7490, rank=0) at core/sr_module.c:839 #22 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b77a0, rank=0) at core/sr_module.c:839 #23 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b7b20, rank=0) at core/sr_module.c:839 #24 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b7d70, rank=0) at core/sr_module.c:839 #25 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b87d0, rank=0) at core/sr_module.c:839 #26 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b8f50, rank=0) at core/sr_module.c:839 #27 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b95d0, rank=0) at core/sr_module.c:839 #28 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580be830, rank=0) at core/sr_module.c:839 #29 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580beeb0, rank=0) at core/sr_module.c:839 #30 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bf220, rank=0) at core/sr_module.c:839 #31 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bf5c0, rank=0) at core/sr_module.c:839 #32 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bf810, rank=0) at core/sr_module.c:839 #33 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bfea0, rank=0) at core/sr_module.c:839 #34 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c01a0, rank=0) at core/sr_module.c:839 #35 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c0580, rank=0) at core/sr_module.c:839 #36 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c0f90, rank=0) at core/sr_module.c:839 #37 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c14c0, rank=0) at core/sr_module.c:839 #38 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c17d0, rank=0) at core/sr_module.c:839 #39 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c1d90, rank=0) at core/sr_module.c:839 #40 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c1fe0, rank=0) at core/sr_module.c:839 #41 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c2310, rank=0) at core/sr_module.c:839 #42 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c2cf0, rank=0) at core/sr_module.c:839 #43 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c3340, rank=0) at core/sr_module.c:839 #44 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c3700, rank=0) at core/sr_module.c:839 #45 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c4590, rank=0) at core/sr_module.c:839 #46 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c47b0, rank=0) at core/sr_module.c:839 #47 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c49d0, rank=0) at core/sr_module.c:839 #48 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c4c90, rank=0) at core/sr_module.c:839 #49 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c5230, rank=0) at core/sr_module.c:839 #50 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c5530, rank=0) at core/sr_module.c:839 #51 0x000055ce6a0d5e59 in init_child (rank=0) at core/sr_module.c:870 #52 0x000055ce69f977cc in main_loop () at main.c:1703 #53 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958d2d3a3 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x000055ce6a185727 in sleep_us (nusecs=100) at core/ut.h:513 #2 0x000055ce6a185898 in fork_basic_utimer (child_id=-1, desc=0x7f994f19434a "SIPDUMP WRITE TIMER", make_sock=1, f=0x7f994f192e3c <sipdump_timer_exec>, param=0x0, uinterval=100) at core/timer_proc.c:116 #3 0x00007f994f18e782 in child_init (rank=0) at sipdump_mod.c:126 #4 0x000055ce6a0d5a84 in init_mod_child (m=0x7f99580b4270, rank=0) at core/sr_module.c:843 #5 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b44c0, rank=0) at core/sr_module.c:839 #6 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b47f0, rank=0) at core/sr_module.c:839 #7 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b4c80, rank=0) at core/sr_module.c:839 #8 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b5250, rank=0) at core/sr_module.c:839 #9 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b6e20, rank=0) at core/sr_module.c:839 #10 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b7490, rank=0) at core/sr_module.c:839 #11 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b77a0, rank=0) at core/sr_module.c:839 #12 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b7b20, rank=0) at core/sr_module.c:839 #13 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b7d70, rank=0) at core/sr_module.c:839 #14 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b87d0, rank=0) at core/sr_module.c:839 #15 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b8f50, rank=0) at core/sr_module.c:839 #16 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580b95d0, rank=0) at core/sr_module.c:839 #17 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580be830, rank=0) at core/sr_module.c:839 #18 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580beeb0, rank=0) at core/sr_module.c:839 #19 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bf220, rank=0) at core/sr_module.c:839 #20 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bf5c0, rank=0) at core/sr_module.c:839 #21 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bf810, rank=0) at core/sr_module.c:839 #22 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bfea0, rank=0) at core/sr_module.c:839 #23 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c01a0, rank=0) at core/sr_module.c:839 #24 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c0580, rank=0) at core/sr_module.c:839 #25 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c0f90, rank=0) at core/sr_module.c:839 #26 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c14c0, rank=0) at core/sr_module.c:839 #27 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c17d0, rank=0) at core/sr_module.c:839 #28 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c1d90, rank=0) at core/sr_module.c:839 #29 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c1fe0, rank=0) at core/sr_module.c:839 #30 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c2310, rank=0) at core/sr_module.c:839 #31 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c2cf0, rank=0) at core/sr_module.c:839 #32 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c3340, rank=0) at core/sr_module.c:839 #33 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c3700, rank=0) at core/sr_module.c:839 #34 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c4590, rank=0) at core/sr_module.c:839 #35 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c47b0, rank=0) at core/sr_module.c:839 #36 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c49d0, rank=0) at core/sr_module.c:839 #37 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c4c90, rank=0) at core/sr_module.c:839 #38 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c5230, rank=0) at core/sr_module.c:839 #39 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c5530, rank=0) at core/sr_module.c:839 #40 0x000055ce6a0d5e59 in init_child (rank=0) at core/sr_module.c:870 #41 0x000055ce69f977cc in main_loop () at main.c:1703 #42 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958d2d3a3 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x000055ce6a185727 in sleep_us (nusecs=60000000) at core/ut.h:513 #2 0x000055ce6a185a8b in fork_sync_timer (child_id=-1, desc=0x7f994466af8a "USRLOC Timer", make_sock=1, f=0x7f9944646573 <ul_local_timer>, param=0x0, interval=60000) at core/timer_proc.c:221 #3 0x00007f994464538a in child_init (_rank=0) at usrloc_mod.c:398 #4 0x000055ce6a0d5a84 in init_mod_child (m=0x7f99580bf5c0, rank=0) at core/sr_module.c:843 #5 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bf810, rank=0) at core/sr_module.c:839 #6 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580bfea0, rank=0) at core/sr_module.c:839 #7 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c01a0, rank=0) at core/sr_module.c:839 #8 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c0580, rank=0) at core/sr_module.c:839 #9 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c0f90, rank=0) at core/sr_module.c:839 #10 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c14c0, rank=0) at core/sr_module.c:839 #11 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c17d0, rank=0) at core/sr_module.c:839 #12 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c1d90, rank=0) at core/sr_module.c:839 #13 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c1fe0, rank=0) at core/sr_module.c:839 #14 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c2310, rank=0) at core/sr_module.c:839 #15 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c2cf0, rank=0) at core/sr_module.c:839 #16 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c3340, rank=0) at core/sr_module.c:839 #17 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c3700, rank=0) at core/sr_module.c:839 #18 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c4590, rank=0) at core/sr_module.c:839 #19 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c47b0, rank=0) at core/sr_module.c:839 #20 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c49d0, rank=0) at core/sr_module.c:839 #21 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c4c90, rank=0) at core/sr_module.c:839 #22 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c5230, rank=0) at core/sr_module.c:839 #23 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c5530, rank=0) at core/sr_module.c:839 #24 0x000055ce6a0d5e59 in init_child (rank=0) at core/sr_module.c:870 #25 0x000055ce69f977cc in main_loop () at main.c:1703 #26 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958d04270 in __nanosleep_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x00007f9958d041da in __sleep (seconds=0) at ../sysdeps/posix/sleep.c:55 #2 0x000055ce6a1857d1 in fork_basic_timer (child_id=-1, desc=0x7ffd8be61540 "RTIMER EXEC child=0 timer=minute_timer", make_sock=1, f=0x7f994275d35a <stm_timer_exec>, param=0x7f99580d0190, interval=60) at core/timer_proc.c:77 #3 0x00007f994275cfd6 in child_init (rank=0) at rtimer_mod.c:166 #4 0x000055ce6a0d5a84 in init_mod_child (m=0x7f99580c4590, rank=0) at core/sr_module.c:843 #5 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c47b0, rank=0) at core/sr_module.c:839 #6 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c49d0, rank=0) at core/sr_module.c:839 #7 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c4c90, rank=0) at core/sr_module.c:839 #8 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c5230, rank=0) at core/sr_module.c:839 #9 0x000055ce6a0d5707 in init_mod_child (m=0x7f99580c5530, rank=0) at core/sr_module.c:839 #10 0x000055ce6a0d5e59 in init_child (rank=0) at core/sr_module.c:870 #11 0x000055ce69f977cc in main_loop () at main.c:1703 #12 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958d350a3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x000055ce6a1d2713 in io_wait_loop_epoll (h=0x55ce6a653fc0 <io_w>, t=2, repeat=0) at core/io_wait.h:1034 #2 0x000055ce6a1e77bb in tcp_receive_loop (unix_sock=45) at core/tcp_read.c:1974 #3 0x000055ce6a09ae90 in tcp_init_children () at core/tcp_main.c:4853 #4 0x000055ce69f97ab2 in main_loop () at main.c:1711 #5 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

#0 0x00007f9958d350a3 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x000055ce6a05f47a in io_wait_loop_epoll (h=0x55ce6a60adc0 <io_h>, t=5, repeat=0) at core/io_wait.h:1034 #2 0x000055ce6a0971d1 in tcp_main_loop () at core/tcp_main.c:4547 #3 0x000055ce69f97e0c in main_loop () at main.c:1719 #4 0x000055ce69f9eb39 in main (argc=17, argv=0x7ffd8be61d18) at main.c:2645

Daniel-Constantin Mierla writes:

It waits for packets from the network. Did you send registration via UDP?

No, via tcp and there was also tcp listener processes.

-- Juha

Daniel-Constantin Mierla writes:

Can you see the packet being sent over the network (with ngrep, tcpdump, ...)?

Yes, UDP register is sent, but kamailio does not respond to it.

Then I did this.

1) Started K where rtpengine udp:192.26.134.10:6050 is enabled but is not running.

2) Gave kamcmd command. It two about two minutes before I got the prompt.

3) Gave 'rtpengine.show all' command. It took perhaps 30 seconds to produce:

{ url: udp:127.0.0.1:6050 set: 0 index: 0 weight: 10 disabled: 0 recheck_ticks: 0 } { url: udp:192.26.134.10:6050 set: 0 index: 2 weight: 1 disabled: 1 recheck_ticks: 60 } { url: udp:192.26.134.10:6050 set: 1 index: 1 weight: 1 disabled: 1(permanent) recheck_ticks: N/A }

Now udp:192.26.134.10:6050 shows as disabled and kamailio started to accept sip requests.

How is it possible that one non-responding rtpengine can paralyze the whole sip proxy?

-- Juha

* Paolo Visintin - evosip.cloud writes:

we solved starting with no rtpengine this produces at startup: WARNING: rtpengine [rtpengine_db.c:100]: rtpp_load_db(): No rtpproxy instances in database and then, after rtpengine instances are up and correctly running we send an `rtpengine.reload` to kamailio

That would work for me too. Also starting with all rtpproxies disabled and then enabling them after start.

Note that after the startup, if an rtpengine instance fails no hangs in kamailio just put in disabled state and everything works!

Exactly, but all these are hacks. This is a VERY serious issue and needs to be properly fixed.

-- Juha

David Villasmil writes:

You could also ask politely, as this IS open source, after all.

I didn't notice any impoliteness in my message. I just mentioned that a proper fix is needed.

-- Juha

Daniel-Constantin Mierla writes:

I tried quickly with a rtpengine that was not running, and kamailio started fine and then was responding fast for sip requests.

To clarify: you actually have more rtpengine configured (at least two) in a set and one is not available, right?

Yes, I have two in one set:

udp:127.0.0.1:6050 (running) udp:192.26.134.10:6050 (host 192.26.134.10 is down)

Is the CPU usage very high? Because it is strange that is responding, but with long delay ...

top does not show any kamailio processes in the top.

In addition to not responding to sip requests, kamailio does not respond to kamcmd command either.

It stars to respond when rtpengine module gives up on trying and declares udp:192.26.134.10:6050 disabled.

-- Juha

I forgot to say that if the patch makes it work for you, then you can go ahead and backport to branch 5.2.

Cheers, Daniel

On 26.12.18 12:01, Daniel-Constantin Mierla wrote:

I was able to figure out what could be the cause with:

modparam("rtpengine", "rtpengine_sock", "udp:127.0.0.1:2223 udp:192.168.64.4:2224")

Host 192.168.64.4 is not running (not existing in my case, just made up that ip to be on the same network with the kamailio running on 192.168.64.2).

It was starting a slower, iterating over each child, but then all ok, requests were handled very fast.

When I ran with:

modparam("rtpengine", "rtpengine_sock", "udp:127.0.0.1:2223 udp:127.0.0.1:2224")

with no rtpengine on port 2224, start was very fast, expecting to be due to detecting very quickly that port was not open.

The cause for slower start was the code for ability to reload from database. There are some locks that are enabled while initializing rtpengine sockets, so each child had to wait for the one that acquired the lock.

I pushed a quick fix for the case when db support is not enabled, because these locks are useless in that case, so all children will do the rtpengine init at the same time, without waiting for the others:

* https://github.com/kamailio/kamailio/commit/99250f758e6deb90a5852599f831a53a...

Maybe you would also want to tune the timeout with the modparam:

modparam("rtpengine", "rtpengine_disable_tout", 5)

So detection of unavailable rtpproxy is fast, otherwise it is 60 sec by default, so you may still experience some slow start per child process.

Once I get more time, I will optimize the reload from db as well, so the build of rtpengine sockets is going to be done in parallel, by copying first inside locking the addresses from shared memory to private (should be fast) and then do the connect test  (which can be slower) outside of locking.

I may also discovered an issue with reload from db, not sure if works right now if there is the same number of rtpengine instances at reload. But I need to verify if I understood the mechanism so far, not being the one that coded db support and reload.

Cheers, Daniel

On 26.12.18 10:59, Juha Heinanen wrote:

...

Daniel-Constantin Mierla writes:

...

I tried quickly with a rtpengine that was not running, and kamailio started fine and then was responding fast for sip requests.

To clarify: you actually have more rtpengine configured (at least two) in a set and one is not available, right?

Yes, I have two in one set:

udp:127.0.0.1:6050 (running) udp:192.26.134.10:6050 (host 192.26.134.10 is down)

...

Is the CPU usage very high? Because it is strange that is responding, but with long delay ...

top does not show any kamailio processes in the top.

In addition to not responding to sip requests, kamailio does not respond to kamcmd command either.

It stars to respond when rtpengine module gives up on trying and declares udp:192.26.134.10:6050 disabled.

-- Juha

No, it is for no-db. For db, it requires another solution, but I don't have time for it right now. I explanined in my previous email what would be a solution.

You can make a fix yourself if you want and have the time. It is not a module I coded, nor the one that added db support for it, so I am also coding by learning what was done there.

Cheers, Daniel

On 26.12.18 12:09, Juha Heinanen wrote:

Daniel-Constantin Mierla writes:

...

I was able to figure out what could be the cause with:

modparam("rtpengine", "rtpengine_sock", "udp:127.0.0.1:2223 udp:192.168.64.4:2224")

In my test, I use rtpengine in db mode, i.e., db_url param is set. Would your patch also fix the delay in that mode?

I'll give it a try anyway.

-- Juha

There are many situations that can block a proxy, including writing to syslog, dns and DB queries,... At the end you cannot rely on a single app to have a smooth runtime, the ecosystem has to be also in good parameters.

The current implementation is like this now, the choice of developer. You can improve it if you want, or use the old no-db mode. My patch ensured that the old mode work as it was before adding db support. That was a regression. But what is offered with db support, is what the developer added, and apparently he did it for all instances to be available at that moment. Maybe a note about that can be added in the docs.

Otherwise similar case can be that sqlops (or db_cluster, not sure by heart) didn't start without all db servers available. Recently someone proposed a patch to allow sqlops even when connection fails. We had blocking tcp for years, it was not disabled because of that. So things can be improved as one needs something different, it is open source...

Cheers, Daniel

On Wed, 26 Dec 2018, 14:04 Juha Heinanen <jh@tutpro.com wrote:

Daniel-Constantin Mierla writes:

...

You can make a fix yourself if you want and have the time. It is not a module I coded, nor the one that added db support for it, so I am also coding by learning what was done there.

Understand. Perhaps the solution for now is to disable db mode in the code, since it is not a good idea to allow modules in K that freeze the whole sip proxy.

-- Juha

Indeed I stopped at the wrong param for the timeout, should have been another one:

modparam("rtpengine", "rtpengine_tout_ms", 500)

Cheers, Daniel

On 26.12.18 12:16, Juha Heinanen wrote:

Daniel-Constantin Mierla writes:

...

Maybe you would also want to tune the timeout with the modparam:

modparam("rtpengine", "rtpengine_disable_tout", 5)

So detection of unavailable rtpproxy is fast, otherwise it is 60 sec by default, so you may still experience some slow start per child process.

I understand from the param description that it tells how to behave AFTER rtp proxy has been marked disabled:

Once an RTP proxy was found unreachable and marked as disabled, the rtpengine module will not attempt to establish communication to that RTP proxy for rtpengine_disable_tout seconds.

The problem that I have experienced is that it takes long time (2 minutes or so) before rtpengine modules disables a non-responding rtp proxy.

Also, no matter what the module does, it must not make the whole sip proxy non-responsive for any number of seconds.

-- Juha

I just pushed a series of commits trying to rework how loading (and reloading) of rtpegines list is done, to avoid that sync'ed probing, which can take long if any of the rtpengines is down.

Now, building the local (per process) structures/sockets for rtpengines during kamailio start up is done without locking. This is guarded by the fact a reload command can be executed only after all children were initialized (added also with these commits). Moreover, the probing of rtpeningesis done only by child process 1, because the status is stored in shared memory list, so it is visible in all children. Based on my understanding there, doing probing from all processes is useless now, that was probably kept from the time when the list was not stored in shared memory, from the early rtpproxy times.

There is also a restriction on how often the rtpengine list can be reloaded, now having a 10 seconds interval guard. I added this because the reload is done over the old list, not building a new list to swap with the old one. So it requires some time to walk through the existing list and update based on the new records. I went this way for now, even building a new list may be better/safer in long term, but it would require more work. I also wanted to avoid being very intrusive right now, given that those patches would need to be backported.

The last relevant change was to use a version number to discover when a reload was done. So far, as I understood, it was relying on the number of rtpengines, but one may trigger a reload with same rtpengines, but different attributes (e.g., disabled or not). Having a version number is better in detecting when each worker needs to rebuild its local list of sockets, as well as for troubleshooting, because a value is increased with each reload, so easier to track if it was done or now.

I didn't have time for any tests, so it would be good if you can test and report if works as expected.

All related commits are in master, if they prove to work fine, we can backport all those patches.

Cheers, Daniel

On 26.12.18 12:46, Juha Heinanen wrote:

Daniel-Constantin Mierla writes:

...

I pushed a quick fix for the case when db support is not enabled, because these locks are useless in that case, so all children will do the rtpengine init at the same time, without waiting for the others:

Still took in rtpengine db mode about 2 minutes before kamailio became responsive after start.

-- Juha

On Fri, 28 Dec 2018 at 10:32, Daniel-Constantin Mierla miconda@gmail.com wrote:

I just pushed a series of commits trying to rework how loading (and reloading) of rtpegines list is done, to avoid that sync'ed probing, which can take long if any of the rtpengines is down.

I just want to thank you for this great new year gift. :-)