[BUG] Async MariaDB queries: strange corner-case (bug?) leads to abort()

[liviuchircu]

OpenSIPS version you are running

2.4.5 + MariaDB cluster

Describe the bug

Hi everyone,

I'm dealing with, at least, one opensips crash a day. For some reason, when Opensips try to restore a dead connection in the DBs connections pool, it can't find it and then it shuts down with the following message:

CRITICAL:core:db_store_async_con: #12>>> DB con 0x7fb857f4d178 not found#012It seems you have hit a programming bug.#012Please help us make OpenSIPS better by reporting it at https://github.com/OpenSIPS/opensips/issues

BTW I'm using Opensips 2.4.5 with a cluster of MariaDB DBs in the same network. I couldn´t relate it with a DB issue, the databases are working fine.

Could anyone give me any clues about this?

Thanks in advance,

10:29:34 Opensips[7213]: DBG:avpops:ops_async_dbquery: query [SELECT (COUNT(*) > 0), user_type FROM app.user_app where client_phone = 'XXXXXXXXXX' AND status = 'ON']
10:29:34 Opensips[7213]: DBG:db_virtual:db_virtual_async_raw_query: f call handle size = 2
10:29:34 Opensips[7213]: DBG:db_virtual:try_reconnect: try reconnect
10:29:34 Opensips[7213]: DBG:db_virtual:db_virtual_async_raw_query: flags1 = 3
10:29:34 Opensips[7213]: DBG:core:db_init_async: >>    1/10 transfers: (6 - 0x7fb857f4d178)
10:29:34 Opensips[7213]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
10:29:34 Opensips[7213]: DBG:tm:t_handle_async: placing async job into reactor
10:29:34 Opensips[7213]: DBG:tm:io_watch_add: [UDP_worker] io_watch_add op (6 on 12) (0x55b578c3dfa0, 6, 16, 0x7fb8181d8dd0,1), fd_no=4/1024
10:29:34 Opensips[7213]: DBG:core:destroy_avp_list: destroying list (nil)
10:29:34 Opensips[7213]: DBG:core:receive_msg: cleaning up
10:29:34 Opensips[7213]: DBG:tm:t_resume_async: resuming on fd 6, transaction 0x7fb8181d7300
10:29:34 Opensips[7213]: DBG:db_mysql:db_mysql_async_resume: mysql_read_query_result: 2013, HY000 - "Lost connection to MySQL server during query"
10:29:34 Opensips[7213]: ERROR:db_mysql:db_mysql_async_resume: error [2013, HY000]: Lost connection to MySQL server during query
10:29:34 Opensips[7213]: DBG:core:db_store_async_con: >> restore conn 0x7fb857f4d178
10:29:34 Opensips[7213]: DBG:core:pool_remove: removing connection from the pool
10:29:34 Opensips[7213]: DBG:db_virtual:db_virtual_async_resume: f call handle size = 2
10:29:34 Opensips[7213]: DBG:db_virtual:try_reconnect: try reconnect
10:29:34 Opensips[7213]: DBG:core:db_do_init: connection 0x7fb857f4aeb0 not found in pool
10:29:34 Opensips[7213]: DBG:db_mysql:db_mysql_connect: opening connection: mysql://xxxx:xxxx@10.200.33.21:3306/app
10:29:34 Opensips[7213]: DBG:db_mysql:db_mysql_connect: connection type is 10.200.33.25 via TCP/IP
10:29:34 Opensips[7213]: DBG:db_mysql:db_mysql_connect: protocol version is 10
10:29:34 Opensips[7213]: DBG:db_mysql:db_mysql_connect: server version is 5.5.5-10.1.34-MariaDB-0ubuntu0.18.04.1
10:29:34 Opensips[7213]: DBG:core:db_do_init: connection 0x7fb857f4aeb0 inserted in pool as 0x7fb857f4a638
10:29:34 Opensips[7213]: DBG:db_virtual:db_virtual_async_resume: flags1 = 3
10:29:34 Opensips[7213]: DBG:core:db_init_async: >>    1/10 transfers: (44 - 0x7fb857f4ad60)
10:29:34 Opensips[7213]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
10:29:34 Opensips[7213]: DBG:tm:io_watch_del: [UDP_worker] io_watch_del op on index -1 6 (0x55b578c3dfa0, 6, -1, 0x10,0x1) fd_no=5 called
10:29:34 Opensips[7213]: ERROR:tm:io_watch_del: [UDP_worker] removing fd from epoll (6 from 12) list failed: No such file or directory [2]
10:29:34 Opensips[7213]: DBG:tm:io_watch_add: [UDP_worker] io_watch_add op (44 on 12) (0x55b578c3dfa0, 44, 16, 0x7fb8181d8dd0,1), fd_no=4/1024
10:29:34 Opensips[7213]: DBG:tm:clean_msg_clone: removing hdr->parsed 7
10:29:34 Opensips[7213]: DBG:tm:t_resume_async: resuming on fd 44, transaction 0x7fb8181d7300
10:29:34 Opensips[7213]: DBG:db_mysql:db_mysql_async_resume: mysql_read_query_result: 2013, HY000 - "Lost connection to MySQL server during query"
10:29:34 Opensips[7213]: ERROR:db_mysql:db_mysql_async_resume: error [2013, HY000]: Lost connection to MySQL server during query
10:29:34 Opensips[7213]: DBG:core:db_store_async_con: >> restore conn 0x7fb857f4d178
10:29:34 Opensips[7213]: CRITICAL:core:db_store_async_con: #012>>> DB con 0x7fb857f4d178 not found#012It seems you have hit a programming bug.#012Please help us make OpenSIPS better by reporting it at https://github.com/OpenSIPS/opensips/issues
10:29:35 Opensips[7206]: DBG:uac_registrant:timer_check: checking ... [1581935375] on htable[0]
10:29:36 Opensips[7209]: WARNING:core:handle_timer_job: utimer job <tm-utimer> has a 90000 us delay in execution
10:29:36 Opensips[7209]: WARNING:core:handle_timer_job: utimer job <tm-utimer> has a 90000 us delay in execution
10:29:36 Opensips[7205]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled for 73696360 ms (now 73696450 ms), it may overlap..
10:29:40 Opensips[7214]: DBG:db_virtual:reconnect_timer: reconnect with timer
10:29:40 Opensips[7200]: DBG:core:handle_sigs: OpenSIPS exit status = 134
10:29:40 Opensips[7200]: INFO:core:handle_sigs: child process 7213 exited by a signal 6
10:29:40 Opensips[7200]: INFO:core:handle_sigs: core was generated
10:29:40 Opensips[7200]: INFO:core:handle_sigs: terminating due to SIGCHLD
10:29:40 Opensips[7200]: DBG:core:shutdown_opensips: Asking process 6 [SIP receiver udp:10.200.33.25:5060 ] to terminate
10:29:40 Opensips[7205]: INFO:core:sig_usr: signal 15 received
10:29:40 Opensips[7201]: INFO:core:sig_usr: signal 15 received
10:29:40 Opensips[7203]: INFO:core:sig_usr: signal 15 received
10:29:40 Opensips[7202]: INFO:core:sig_usr: signal 15 received
10:29:40 Opensips[7204]: INFO:core:sig_usr: signal 15 received
10:29:40 Opensips[7200]: DBG:core:shutdown_opensips: Asking process 7 [SIP receiver udp:10.200.33.25:5060 ] to terminate

[stale]

Any updates here? No progress has been made in the last 15 days, marking as stale. Will close this issue if no further updates are made in the next 30 days.