[OpenSIPS-Users] Issues with DB Async query

[Exequiel leite]

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: #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

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
<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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20200217/a227c7c3/attachment.html>