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@lists.kamailio.org>
On Behalf Of Denys Pozniak
Sent: Friday, November 25, 2022 5:09 PM
To: Kamailio (SER) - Users Mailing List <sr-users@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'
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'
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