[OpenSIPS-Users] Opensips 2.1.2 crash using db_virtual

[Jeremiah Penery]

Opensips 2.1.2 occasionally crashes when connection to database fails when using db_virtual module.  In this case, there is only one backend.
It's a rare problem - usually when the query fails, it doesn't cause a crash.  But the crash has happened multiple times, on different machines connected to different databases.

This query is generated by a timer route that runs every minute.  I'm waiting for it to happen again so I can get a core dump file.

The configuration for db_virtual is as follows:

modparam("db_virtual", "db_urls", "define set1 FAILOVER")
modparam("db_virtual", "db_urls", "postgres://xxx:xxx@172.20.20.39:5433/xxx")
modparam("db_virtual", "db_max_consec_retrys", 5)
modparam("db_virtual", "db_probe_time", 10)

And the log:

Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:db_postgres:db_postgres_submit_query: 0x7f054ab9a770 PQsendQuery failed: could not rec
eive data from server: Connection timed out#012 Query: select ip,grp,mask,port,proto,pattern,context_info,id from opensips_permissions
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:db_postgres:free_query: PQclear(0xce33f0) result set
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: ERROR:db_postgres:db_postgres_submit_query: 0x7f054ab9a770 PQsendQuery Error: could not re
ceive data from server: Connection timed out#012 Query: select ip,grp,mask,port,proto,pattern,context_info,id from opensips_permissions
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: ERROR:core:db_do_query: error while submitting query - [select ip,grp,mask,port,proto,pattern,context_info,id from opensips_permissions ]
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:db_virtual:db_virtual_query: failover call failed
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:core:pool_remove: removing connection from the pool
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:db_postgres:db_postgres_free_connection: PQfinish(0xcdaf50)
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:db_postgres:db_postgres_free_connection: pkg_free(0x7f054ab9a898)
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:db_virtual:db_virtual_query: curent_con = 0
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:db_virtual:db_virtual_query: flags2 = 2
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10815]: DBG:db_virtual:db_virtual_query: curent_con = 0
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10817]: NOTICE:core:io_wait_loop_epoll: EPOLLIN(read) event: epollwait() set event EPOLLHUP - connection closed by the remote peer!
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10817]: DBG:core:handle_tcp_worker: dead tcp worker 6 (pid 10815, no 0) (shutting down?)
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10817]: DBG:core:io_watch_del: [TCP_main] io_watch_del op on index 25 32 (0x84b1e0, 32, 25, 0x0,0x1) fd_no=27 called
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10817]: NOTICE:core:io_wait_loop_epoll: EPOLLIN(read) event: epollwait() set event EPOLLHUP - connection closed by the remote peer!
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10817]: CRITICAL:core:receive_fd: EOF on 35
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10817]: DBG:core:handle_worker: dead child 17, pid 10815 (shutting down?)
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10817]: DBG:core:io_watch_del: [TCP_main] io_watch_del op on index 17 35 (0x84b1e0, 35, 17, 0x0,0x1) fd_no=26 called
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:core:handle_sigs: status = 139
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: INFO:core:handle_sigs: child process 10815 exited by a signal 11
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: INFO:core:handle_sigs: core was generated
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: INFO:core:handle_sigs: terminating due to SIGCHLD
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10817]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10816]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10814]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10813]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10812]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10811]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10810]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10809]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10808]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10807]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10806]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10802]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10801]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10803]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10804]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10800]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10799]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10805]: INFO:core:sig_usr: signal 15 received
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: INFO:core:cleanup: cleanup
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: INFO:pike:pike_exit: destroying...
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:tm:tm_shutdown: tm_shutdown : start
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:tm:unlink_timer_lists: emptying DELETE list for set 0
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:tm:tm_shutdown: emptying hash table
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:tm:tm_shutdown: releasing timers
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:tm:tm_shutdown: removing semaphores
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:tm:tm_shutdown: destroying callback lists
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:tm:tm_shutdown: tm_shutdown : done
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: NOTICE:db_virtual:destroy: destroying module...
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:core:shm_mem_destroy: destroying the shared memory lock
Oct 24 18:32:10 rst-lab-gw /usr/sbin/opensips[10798]: DBG:core:handle_sigs: terminating due to SIGCHLD

Thanks,
Jeremiah