25 Nov
2022
25 Nov
'22
5:09 p.m.
Hello!
We use Kamailio in conjunction with the cloud Azure Database for MySQL 5.7.
It has been noticed that Kamailio does not always start after restarting.
It happens to restart a couple of times and everything starts normally.
From the pickup trace I collect on our side, it can be
seen that Kamailio
connects to MySQL, requests and gets data, and then sends a
Request Quit.
On another server with a different configuration (slightly different set of
modules) and connected to the same database, this issue is not reproduced.
How to determine the source of the problem?
Below, the logs are filtered by PID of processes in which an error occurred:
ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection(): driver error:
Can't connect to MySQL server on '10.1.128.4' (110)
11(588460) DEBUG: <core> [core/pt.c:308]: fork_process(): seeding PRNG with
893384711
11(588460) DEBUG: <core> [core/rand/cryptorand.c:36]: cryptorand_seed():
seeding cryptorand generator with 893384711
11(588460) DEBUG: <core> [core/rand/fortuna/random.c:175]:
sr_add_entropy(): additional 4 bytes entropy added to cryptographic PRNG
11(588460) DEBUG: <core> [core/pt.c:313]: fork_process(): test random
numbers 289569343 1482836098 4036842274 2495827489
11(588460) DEBUG: <core> [core/sr_module.c:926]: init_child(): initializing
PROC_RPC with rank -2
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: jsonrpcs [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: kex [DMQ WORKER]
11(588460) DEBUG: kex [kex_mod.c:155]: child_init(): rank is (-2)
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [srid-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: corex [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: tm [DMQ WORKER]
11(588460) DEBUG: tm [callid.c:136]: child_init_callid(): callid: '
558fadb265b2cc20-588460(a)10.1.15.12'
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: tmx [DMQ WORKER]
11(588460) DEBUG: tmx [tmx_mod.c:262]: child_init(): rank is (-2)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: sl [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: usrloc [DMQ WORKER]
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [ulcx-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: registrar [DMQ WORKER]
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [uloc-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: ctl [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: dmq [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: auth_db [DMQ WORKER]
11(588460) DEBUG: <core> [db.c:315]: db_do_init2(): connection 0x
7f96e7d58880 not found in pool
11(588460) DEBUG: db_mysql [km_my_con.c:110]: db_mysql_new_connection():
opening connection: mysql://xxxx:xxxx@10.1.128.4/kamailio
11(588460) ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection():
driver error: Can't connect to MySQL server on '10.1.128.4' (110)
11(588460) ERROR: <core> [db.c:319]: db_do_init2(): could not add
connection to the pool
11(588460) ERROR: auth_db [auth_db_mod.c:161]: child_init(): unable to
connect to the database
11(588460) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error
while initializing module auth_db
(/usr/lib/x86_64-linux-gnu/kamailio/modules/auth_db.so) (idx: 11 rank: -2
desc: [DMQ WORKER])
11(588460) ERROR: <core> [core/pt.c:338]: fork_process(): init_child failed
for process 11, pid 588460, "DMQ WORKER"
11(588460) ERROR: dmq [dmq.c:314]: child_init(): failed to fork worker
process 0
11(588460) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error
while initializing module dmq
(/usr/lib/x86_64-linux-gnu/kamailio/modules/dmq.so) (idx: 11 rank: 0 desc:
[DMQ WORKER])
11(588460) ERROR: <core> [main.c:1842]: main_loop(): error in init_child
17(588466) DEBUG: <core> [core/pt.c:308]: fork_process(): seeding PRNG with
2018260302
17(588466) DEBUG: <core> [core/rand/cryptorand.c:36]: cryptorand_seed():
seeding cryptorand generator with 2018260302
17(588466) DEBUG: <core> [core/rand/fortuna/random.c:175]:
sr_add_entropy(): additional 4 bytes entropy added to cryptographic PRNG
17(588466) DEBUG: <core> [core/pt.c:313]: fork_process(): test random
numbers 1395463366 918020172 18663197 531231393
17(588466) DEBUG: <core> [core/sr_module.c:926]: init_child(): initializing
PROC_TIMER with rank -1
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: jsonrpcs [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: kex [Dialog Clean Timer]
17(588466) DEBUG: kex [kex_mod.c:155]: child_init(): rank is (-1)
17(588466) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [srid-6380d27f-8fab2-] (0 / 20)
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: corex [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: tm [Dialog Clean Timer]
17(588466) DEBUG: tm [callid.c:136]: child_init_callid(): callid: '
558fadb265b2cc20-588466(a)10.1.15.12'
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: tmx [Dialog Clean Timer]
17(588466) DEBUG: tmx [tmx_mod.c:262]: child_init(): rank is (-1)
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: sl [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: usrloc [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [ulcx-6380d27f-8fab2-] (0 / 20)
17(588466) DEBUG: <core> [db.c:315]: db_do_init2(): connection 0x
7f96e7d58880 not found in pool
17(588466) DEBUG: db_mysql [km_my_con.c:110]: db_mysql_new_connection():
opening connection: mysql://xxxx:xxxx@10.1.128.4/kamailio
17(588466) ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection():
driver error: Can't connect to MySQL server on '10.1.128.4' (110)
17(588466) ERROR: <core> [db.c:319]: db_do_init2(): could not add
connection to the pool
17(588466) ERROR: usrloc [usrloc_mod.c:485]: child_init(): child(-1):
failed to connect to database
17(588466) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error
while initializing module usrloc
(/usr/lib/x86_64-linux-gnu/kamailio/modules/usrloc.so) (idx: 17 rank: -1
desc: [Dialog Clean Timer])
17(588466) ERROR: <core> [core/pt.c:338]: fork_process(): init_child failed
for process 17, pid 588466, "Dialog Clean Timer"
17(588466) ERROR: dialog [dialog.c:782]: child_init(): failed to start
clean timer routine as process
17(588466) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error
while initializing module dialog
(/usr/lib/x86_64-linux-gnu/kamailio/modules/dialog.so) (idx: 17 rank: 0
desc: [Dialog Clean Timer])
17(588466) ERROR: <core> [main.c:1842]: main_loop(): error in init_child
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f84650), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f84900), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_malloc(293) -
ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2fd50b0), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f820e0), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
- Debian 11.5
- libmariadb version 3.1.16
-modules: auth_db, permissions, domain, rtpengine, dispatcher, dialog,
uac, carrierroute, topos, acc
- kamailio 5.6.2 (x86_64/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_BLOCKLIST,
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 with gcc 10.2.1
--
BR,
Denys Pozniak
28 Nov
28 Nov
10:56 a.m.
Hello,
if you system has many network interfaces, be sure that you grant proper
rights based on local ip addresses to access the MySQL server or have ip
routing rules that ensures the kernel will use only the allowed local ip
address to open connection to MySQL server.
Cheers,
Daniel
On 25.11.22 17:09, Denys Pozniak wrote:
Hello!
We use Kamailio in conjunction with the cloud Azure Database for MySQL
5.7. It has been noticed that Kamailio does not always start after
restarting.
It happens to restart a couple of times and everything starts normally.
From the pickup trace I collect on our side, it can be seen that
Kamailio connects to MySQL, requests and gets data, and then sends a
Request Quit.
On another server with a different configuration (slightly different
set of modules) and connected to the same database, this issue is not
reproduced.
How to determine the source of the problem?
Below, the logs are filtered by PID of processes in which an error
occurred:
ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection(): driver
error: Can't connect to MySQL server on '10.1.128.4' (110)
11(588460) DEBUG: <core> [core/pt.c:308]: fork_process(): seeding PRNG
with 893384711
11(588460) DEBUG: <core> [core/rand/cryptorand.c:36]:
cryptorand_seed(): seeding cryptorand generator with 893384711
11(588460) DEBUG: <core> [core/rand/fortuna/random.c:175]:
sr_add_entropy(): additional 4 bytes entropy added to cryptographic PRNG
11(588460) DEBUG: <core> [core/pt.c:313]: fork_process(): test random
numbers 289569343 1482836098 4036842274 2495827489
11(588460) DEBUG: <core> [core/sr_module.c:926]: init_child():
initializing PROC_RPC with rank -2
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: jsonrpcs [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: kex [DMQ WORKER]
11(588460) DEBUG: kex [kex_mod.c:155]: child_init(): rank is (-2)
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root
for sruid is [srid-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: corex [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: tm [DMQ WORKER]
11(588460) DEBUG: tm [callid.c:136]: child_init_callid(): callid:
'558fadb265b2cc20-588460(a)10.1.15.12'
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: tmx [DMQ WORKER]
11(588460) DEBUG: tmx [tmx_mod.c:262]: child_init(): rank is (-2)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: sl [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: usrloc [DMQ WORKER]
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root
for sruid is [ulcx-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: registrar [DMQ WORKER]
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root
for sruid is [uloc-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: ctl [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: dmq [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
11 rank -2: auth_db [DMQ WORKER]
11(588460) DEBUG: <core> [db.c:315]: db_do_init2(): connection
0x7f96e7d58880 not found in pool
11(588460) DEBUG: db_mysql [km_my_con.c:110]:
db_mysql_new_connection(): opening connection:
mysql://xxxx:xxxx@10.1.128.4/kamailio
11(588460) ERROR: db_mysql [km_my_con.c:163]:
db_mysql_new_connection(): driver error: Can't connect to MySQL server
on '10.1.128.4' (110)
11(588460) ERROR: <core> [db.c:319]: db_do_init2(): could not add
connection to the pool
11(588460) ERROR: auth_db [auth_db_mod.c:161]: child_init(): unable to
connect to the database
11(588460) ERROR: <core> [core/sr_module.c:882]: init_mod_child():
error while initializing module auth_db
(/usr/lib/x86_64-linux-gnu/kamailio/modules/auth_db.so) (idx: 11 rank:
-2 desc: [DMQ WORKER])
11(588460) ERROR: <core> [core/pt.c:338]: fork_process(): init_child
failed for process 11, pid 588460, "DMQ WORKER"
11(588460) ERROR: dmq [dmq.c:314]: child_init(): failed to fork worker
process 0
11(588460) ERROR: <core> [core/sr_module.c:882]: init_mod_child():
error while initializing module dmq
(/usr/lib/x86_64-linux-gnu/kamailio/modules/dmq.so) (idx: 11 rank: 0
desc: [DMQ WORKER])
11(588460) ERROR: <core> [main.c:1842]: main_loop(): error in init_child
17(588466) DEBUG: <core> [core/pt.c:308]: fork_process(): seeding PRNG
with 2018260302
17(588466) DEBUG: <core> [core/rand/cryptorand.c:36]:
cryptorand_seed(): seeding cryptorand generator with 2018260302
17(588466) DEBUG: <core> [core/rand/fortuna/random.c:175]:
sr_add_entropy(): additional 4 bytes entropy added to cryptographic PRNG
17(588466) DEBUG: <core> [core/pt.c:313]: fork_process(): test random
numbers 1395463366 918020172 18663197 531231393
17(588466) DEBUG: <core> [core/sr_module.c:926]: init_child():
initializing PROC_TIMER with rank -1
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
17 rank -1: jsonrpcs [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
17 rank -1: kex [Dialog Clean Timer]
17(588466) DEBUG: kex [kex_mod.c:155]: child_init(): rank is (-1)
17(588466) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root
for sruid is [srid-6380d27f-8fab2-] (0 / 20)
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
17 rank -1: corex [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
17 rank -1: tm [Dialog Clean Timer]
17(588466) DEBUG: tm [callid.c:136]: child_init_callid(): callid:
'558fadb265b2cc20-588466(a)10.1.15.12'
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
17 rank -1: tmx [Dialog Clean Timer]
17(588466) DEBUG: tmx [tmx_mod.c:262]: child_init(): rank is (-1)
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
17 rank -1: sl [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx
17 rank -1: usrloc [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root
for sruid is [ulcx-6380d27f-8fab2-] (0 / 20)
17(588466) DEBUG: <core> [db.c:315]: db_do_init2(): connection
0x7f96e7d58880 not found in pool
17(588466) DEBUG: db_mysql [km_my_con.c:110]:
db_mysql_new_connection(): opening connection:
mysql://xxxx:xxxx@10.1.128.4/kamailio
17(588466) ERROR: db_mysql [km_my_con.c:163]:
db_mysql_new_connection(): driver error: Can't connect to MySQL server
on '10.1.128.4' (110)
17(588466) ERROR: <core> [db.c:319]: db_do_init2(): could not add
connection to the pool
17(588466) ERROR: usrloc [usrloc_mod.c:485]: child_init(): child(-1):
failed to connect to database
17(588466) ERROR: <core> [core/sr_module.c:882]: init_mod_child():
error while initializing module usrloc
(/usr/lib/x86_64-linux-gnu/kamailio/modules/usrloc.so) (idx: 17 rank:
-1 desc: [Dialog Clean Timer])
17(588466) ERROR: <core> [core/pt.c:338]: fork_process(): init_child
failed for process 17, pid 588466, "Dialog Clean Timer"
17(588466) ERROR: dialog [dialog.c:782]: child_init(): failed to start
clean timer routine as process
17(588466) ERROR: <core> [core/sr_module.c:882]: init_mod_child():
error while initializing module dialog
(/usr/lib/x86_64-linux-gnu/kamailio/modules/dialog.so) (idx: 17 rank:
0 desc: [Dialog Clean Timer])
17(588466) ERROR: <core> [main.c:1842]: main_loop(): error in init_child
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f84650), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f84900), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_malloc(293)
- ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2fd50b0), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f820e0), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
- Debian 11.5
- libmariadb version 3.1.16
-modules: auth_db, permissions, domain, rtpengine, dispatcher, dialog,
uac, carrierroute, topos, acc
- kamailio 5.6.2 (x86_64/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_BLOCKLIST, 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 with gcc 10.2.1
--
BR,
Denys Pozniak
__________________________________________________________
Kamailio - Users Mailing List - Non Commercial Discussions
sr-users(a)lists.kamailio.org
Important: keep the mailing list in the recipients, do not reply only to the sender!
Edit mailing list options or unsubscribe:
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
10:57 a.m.
Hello,
Interesting issue. Probably worth a try to look closer to the mysql protocol traces (e.g.,
with wireshark) and try to spot differences in the exchange at Kamailio startup for the
working and non-working setup.
Might be a slight incompatibility with the azure database implementation, observed
something like this in the past with one project.
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/
Kamailio services – https://gilawa.com<https://gilawa.com/>
From: sr-users <sr-users-bounces(a)lists.kamailio.org> On Behalf Of Denys Pozniak
Sent: Friday, November 25, 2022 5:09 PM
To: Kamailio (SER) - Users Mailing List <sr-users(a)lists.kamailio.org>
Subject: [SR-Users] db_mysql_new_connection(): driver error: Can't connect to MySQL
server
Hello!
We use Kamailio in conjunction with the cloud Azure Database for MySQL 5.7. It has been
noticed that Kamailio does not always start after restarting.
It happens to restart a couple of times and everything starts normally.
From the pickup trace I collect on our side, it can be seen that Kamailio connects to
MySQL, requests and gets data, and then sends a Request Quit.
On another server with a different configuration (slightly different set of modules) and
connected to the same database, this issue is not reproduced.
How to determine the source of the problem?
Below, the logs are filtered by PID of processes in which an error occurred:
ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection(): driver error: Can't
connect to MySQL server on '10.1.128.4' (110)
11(588460) DEBUG: <core> [core/pt.c:308]: fork_process(): seeding PRNG with
893384711
11(588460) DEBUG: <core> [core/rand/cryptorand.c:36]: cryptorand_seed(): seeding
cryptorand generator with 893384711
11(588460) DEBUG: <core> [core/rand/fortuna/random.c:175]: sr_add_entropy():
additional 4 bytes entropy added to cryptographic PRNG
11(588460) DEBUG: <core> [core/pt.c:313]: fork_process(): test random numbers
289569343 1482836098 4036842274 2495827489
11(588460) DEBUG: <core> [core/sr_module.c:926]: init_child(): initializing PROC_RPC
with rank -2
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
jsonrpcs [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
kex [DMQ WORKER]
11(588460) DEBUG: kex [kex_mod.c:155]: child_init(): rank is (-2)
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for sruid is
[srid-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
corex [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
tm [DMQ WORKER]
11(588460) DEBUG: tm [callid.c:136]: child_init_callid(): callid:
'558fadb265b2cc20-588460@10.1.15.12<mailto:558fadb265b2cc20-588460@10.1.15.12>'
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
tmx [DMQ WORKER]
11(588460) DEBUG: tmx [tmx_mod.c:262]: child_init(): rank is (-2)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
sl [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
usrloc [DMQ WORKER]
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for sruid is
[ulcx-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
registrar [DMQ WORKER]
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for sruid is
[uloc-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
ctl [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
dmq [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11 rank -2:
auth_db [DMQ WORKER]
11(588460) DEBUG: <core> [db.c:315]: db_do_init2(): connection 0x7f96e7d58880 not
found in pool
11(588460) DEBUG: db_mysql [km_my_con.c:110]: db_mysql_new_connection(): opening
connection: mysql://xxxx:xxxx@10.1.128.4/kamailio
11(588460) ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection(): driver error:
Can't connect to MySQL server on '10.1.128.4' (110)
11(588460) ERROR: <core> [db.c:319]: db_do_init2(): could not add connection to the
pool
11(588460) ERROR: auth_db [auth_db_mod.c:161]: child_init(): unable to connect to the
database
11(588460) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error while
initializing module auth_db (/usr/lib/x86_64-linux-gnu/kamailio/modules/auth_db.so) (idx:
11 rank: -2 desc: [DMQ WORKER])
11(588460) ERROR: <core> [core/pt.c:338]: fork_process(): init_child failed for
process 11, pid 588460, "DMQ WORKER"
11(588460) ERROR: dmq [dmq.c:314]: child_init(): failed to fork worker process 0
11(588460) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error while
initializing module dmq (/usr/lib/x86_64-linux-gnu/kamailio/modules/dmq.so) (idx: 11 rank:
0 desc: [DMQ WORKER])
11(588460) ERROR: <core> [main.c:1842]: main_loop(): error in init_child
17(588466) DEBUG: <core> [core/pt.c:308]: fork_process(): seeding PRNG with
2018260302
17(588466) DEBUG: <core> [core/rand/cryptorand.c:36]: cryptorand_seed(): seeding
cryptorand generator with 2018260302
17(588466) DEBUG: <core> [core/rand/fortuna/random.c:175]: sr_add_entropy():
additional 4 bytes entropy added to cryptographic PRNG
17(588466) DEBUG: <core> [core/pt.c:313]: fork_process(): test random numbers
1395463366 918020172 18663197 531231393
17(588466) DEBUG: <core> [core/sr_module.c:926]: init_child(): initializing
PROC_TIMER with rank -1
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17 rank -1:
jsonrpcs [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17 rank -1:
kex [Dialog Clean Timer]
17(588466) DEBUG: kex [kex_mod.c:155]: child_init(): rank is (-1)
17(588466) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for sruid is
[srid-6380d27f-8fab2-] (0 / 20)
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17 rank -1:
corex [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17 rank -1:
tm [Dialog Clean Timer]
17(588466) DEBUG: tm [callid.c:136]: child_init_callid(): callid:
'558fadb265b2cc20-588466@10.1.15.12<mailto:558fadb265b2cc20-588466@10.1.15.12>'
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17 rank -1:
tmx [Dialog Clean Timer]
17(588466) DEBUG: tmx [tmx_mod.c:262]: child_init(): rank is (-1)
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17 rank -1:
sl [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17 rank -1:
usrloc [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for sruid is
[ulcx-6380d27f-8fab2-] (0 / 20)
17(588466) DEBUG: <core> [db.c:315]: db_do_init2(): connection 0x7f96e7d58880 not
found in pool
17(588466) DEBUG: db_mysql [km_my_con.c:110]: db_mysql_new_connection(): opening
connection: mysql://xxxx:xxxx@10.1.128.4/kamailio
17(588466) ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection(): driver error:
Can't connect to MySQL server on '10.1.128.4' (110)
17(588466) ERROR: <core> [db.c:319]: db_do_init2(): could not add connection to the
pool
17(588466) ERROR: usrloc [usrloc_mod.c:485]: child_init(): child(-1): failed to connect to
database
17(588466) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error while
initializing module usrloc (/usr/lib/x86_64-linux-gnu/kamailio/modules/usrloc.so) (idx: 17
rank: -1 desc: [Dialog Clean Timer])
17(588466) ERROR: <core> [core/pt.c:338]: fork_process(): init_child failed for
process 17, pid 588466, "Dialog Clean Timer"
17(588466) ERROR: dialog [dialog.c:782]: child_init(): failed to start clean timer routine
as process
17(588466) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error while
initializing module dialog (/usr/lib/x86_64-linux-gnu/kamailio/modules/dialog.so) (idx: 17
rank: 0 desc: [Dialog Clean Timer])
17(588466) ERROR: <core> [main.c:1842]: main_loop(): error in init_child
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing
already freed pointer (0x7f96e2f84650), called from tls: tls_init.c: ser_free(323), first
free tls: tls_init.c: ser_free(323) - ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing
already freed pointer (0x7f96e2f84900), called from tls: tls_init.c: ser_free(323), first
free tls: tls_init.c: ser_malloc(293) - ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing
already freed pointer (0x7f96e2fd50b0), called from tls: tls_init.c: ser_free(323), first
free tls: tls_init.c: ser_free(323) - ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG: freeing
already freed pointer (0x7f96e2f820e0), called from tls: tls_init.c: ser_free(323), first
free tls: tls_init.c: ser_free(323) - ignoring
- Debian 11.5
- libmariadb version 3.1.16
-modules: auth_db, permissions, domain, rtpengine, dispatcher, dialog, uac, carrierroute,
topos, acc
- kamailio 5.6.2 (x86_64/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_BLOCKLIST, 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 with gcc 10.2.1
--
BR,
Denys Pozniak
29 Nov
29 Nov
9:43 a.m.
Hello!
It also seems to me that there are differences in the implementation of the
protocol, but so far I have not been able to find a significant difference
in the traces.
Tried some tests with an intermediate ProxySQL and it looks encouraging.
пн, 28 нояб. 2022 г. в 11:57, Henning Westerholt <hw(a)gilawa.com>om>:
Hello,
Interesting issue. Probably worth a try to look closer to the mysql
protocol traces (e.g., with wireshark) and try to spot differences in the
exchange at Kamailio startup for the working and non-working setup.
Might be a slight incompatibility with the azure database implementation,
observed something like this in the past with one project.
Cheers,
Henning
--
Henning Westerholt – https://skalatan.de/blog/
Kamailio services – https://gilawa.com
*From:* sr-users <sr-users-bounces(a)lists.kamailio.org> *On Behalf Of *Denys
Pozniak
*Sent:* Friday, November 25, 2022 5:09 PM
*To:* Kamailio (SER) - Users Mailing List <sr-users(a)lists.kamailio.org>
*Subject:* [SR-Users] db_mysql_new_connection(): driver error: Can't
connect to MySQL server
Hello!
We use Kamailio in conjunction with the cloud Azure Database for MySQL
5.7. It has been noticed that Kamailio does not always start after
restarting.
It happens to restart a couple of times and everything starts normally.
From the pickup trace I collect on our side, it can be seen that Kamailio
connects to MySQL, requests and gets data, and then sends a Request Quit.
On another server with a different configuration (slightly different set
of modules) and connected to the same database, this issue is not
reproduced.
How to determine the source of the problem?
Below, the logs are filtered by PID of processes in which an error
occurred:
ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection(): driver
error: Can't connect to MySQL server on '10.1.128.4' (110)
11(588460) DEBUG: <core> [core/pt.c:308]: fork_process(): seeding PRNG
with 893384711
11(588460) DEBUG: <core> [core/rand/cryptorand.c:36]: cryptorand_seed():
seeding cryptorand generator with 893384711
11(588460) DEBUG: <core> [core/rand/fortuna/random.c:175]:
sr_add_entropy(): additional 4 bytes entropy added to cryptographic PRNG
11(588460) DEBUG: <core> [core/pt.c:313]: fork_process(): test random
numbers 289569343 1482836098 4036842274 2495827489
11(588460) DEBUG: <core> [core/sr_module.c:926]: init_child():
initializing PROC_RPC with rank -2
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: jsonrpcs [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: kex [DMQ WORKER]
11(588460) DEBUG: kex [kex_mod.c:155]: child_init(): rank is (-2)
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [srid-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: corex [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: tm [DMQ WORKER]
11(588460) DEBUG: tm [callid.c:136]: child_init_callid(): callid: '
558fadb265b2cc20-588460(a)10.1.15.12'
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: tmx [DMQ WORKER]
11(588460) DEBUG: tmx [tmx_mod.c:262]: child_init(): rank is (-2)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: sl [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: usrloc [DMQ WORKER]
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [ulcx-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: registrar [DMQ WORKER]
11(588460) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [uloc-6380d27f-8faac-] (0 / 20)
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: ctl [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: dmq [DMQ WORKER]
11(588460) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 11
rank -2: auth_db [DMQ WORKER]
11(588460) DEBUG: <core> [db.c:315]: db_do_init2(): connection 0x
7f96e7d58880 not found in pool
11(588460) DEBUG: db_mysql [km_my_con.c:110]: db_mysql_new_connection():
opening connection: mysql://xxxx:xxxx@10.1.128.4/kamailio
11(588460) ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection():
driver error: Can't connect to MySQL server on '10.1.128.4' (110)
11(588460) ERROR: <core> [db.c:319]: db_do_init2(): could not add
connection to the pool
11(588460) ERROR: auth_db [auth_db_mod.c:161]: child_init(): unable to
connect to the database
11(588460) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error
while initializing module auth_db
(/usr/lib/x86_64-linux-gnu/kamailio/modules/auth_db.so) (idx: 11 rank: -2
desc: [DMQ WORKER])
11(588460) ERROR: <core> [core/pt.c:338]: fork_process(): init_child
failed for process 11, pid 588460, "DMQ WORKER"
11(588460) ERROR: dmq [dmq.c:314]: child_init(): failed to fork worker
process 0
11(588460) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error
while initializing module dmq
(/usr/lib/x86_64-linux-gnu/kamailio/modules/dmq.so) (idx: 11 rank: 0
desc: [DMQ WORKER])
11(588460) ERROR: <core> [main.c:1842]: main_loop(): error in init_child
17(588466) DEBUG: <core> [core/pt.c:308]: fork_process(): seeding PRNG
with 2018260302
17(588466) DEBUG: <core> [core/rand/cryptorand.c:36]: cryptorand_seed():
seeding cryptorand generator with 2018260302
17(588466) DEBUG: <core> [core/rand/fortuna/random.c:175]:
sr_add_entropy(): additional 4 bytes entropy added to cryptographic PRNG
17(588466) DEBUG: <core> [core/pt.c:313]: fork_process(): test random
numbers 1395463366 918020172 18663197 531231393
17(588466) DEBUG: <core> [core/sr_module.c:926]: init_child():
initializing PROC_TIMER with rank -1
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: jsonrpcs [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: kex [Dialog Clean Timer]
17(588466) DEBUG: kex [kex_mod.c:155]: child_init(): rank is (-1)
17(588466) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [srid-6380d27f-8fab2-] (0 / 20)
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: corex [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: tm [Dialog Clean Timer]
17(588466) DEBUG: tm [callid.c:136]: child_init_callid(): callid: '
558fadb265b2cc20-588466(a)10.1.15.12'
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: tmx [Dialog Clean Timer]
17(588466) DEBUG: tmx [tmx_mod.c:262]: child_init(): rank is (-1)
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: sl [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/sr_module.c:878]: init_mod_child(): idx 17
rank -1: usrloc [Dialog Clean Timer]
17(588466) DEBUG: <core> [core/utils/sruid.c:121]: sruid_init(): root for
sruid is [ulcx-6380d27f-8fab2-] (0 / 20)
17(588466) DEBUG: <core> [db.c:315]: db_do_init2(): connection 0x
7f96e7d58880 not found in pool
17(588466) DEBUG: db_mysql [km_my_con.c:110]: db_mysql_new_connection():
opening connection: mysql://xxxx:xxxx@10.1.128.4/kamailio
17(588466) ERROR: db_mysql [km_my_con.c:163]: db_mysql_new_connection():
driver error: Can't connect to MySQL server on '10.1.128.4' (110)
17(588466) ERROR: <core> [db.c:319]: db_do_init2(): could not add
connection to the pool
17(588466) ERROR: usrloc [usrloc_mod.c:485]: child_init(): child(-1):
failed to connect to database
17(588466) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error
while initializing module usrloc
(/usr/lib/x86_64-linux-gnu/kamailio/modules/usrloc.so) (idx: 17 rank: -1
desc: [Dialog Clean Timer])
17(588466) ERROR: <core> [core/pt.c:338]: fork_process(): init_child
failed for process 17, pid 588466, "Dialog Clean Timer"
17(588466) ERROR: dialog [dialog.c:782]: child_init(): failed to start
clean timer routine as process
17(588466) ERROR: <core> [core/sr_module.c:882]: init_mod_child(): error
while initializing module dialog
(/usr/lib/x86_64-linux-gnu/kamailio/modules/dialog.so) (idx: 17 rank: 0
desc: [Dialog Clean Timer])
17(588466) ERROR: <core> [main.c:1842]: main_loop(): error in init_child
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f84650), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f84900), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_malloc(293) -
ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2fd50b0), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
17(588466) CRITICAL: <core> [core/mem/q_malloc.c:519]: qm_free(): BUG:
freeing already freed pointer (0x7f96e2f820e0), called from tls:
tls_init.c: ser_free(323), first free tls: tls_init.c: ser_free(323) -
ignoring
- Debian 11.5
- libmariadb version 3.1.16
-modules: auth_db, permissions, domain, rtpengine, dispatcher, dialog,
uac, carrierroute, topos, acc
- kamailio 5.6.2 (x86_64/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_BLOCKLIST,
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 with gcc 10.2.1
--
BR,
Denys Pozniak
--
BR,
Denys Pozniak
522
days inactive
526
days old
3 comments
3 participants
participants (3)
-
Daniel-Constantin Mierla -
Denys Pozniak -
Henning Westerholt