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@gilawa.com>:

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

 

 



--

BR,
Denys Pozniak