CRASH AFTER CRITICAL ERRORS IN OPENSIPS 2.2.2

[saurabh-iitrke]

Info:

version: opensips 2.2.2 (x86_64/linux)
flags: STATS: On, DISABLE_NAGLE, USE_MCAST, SHM_MMAP, PKG_MALLOC, F_MALLOC, FAST_LOCK-ADAPTIVE_WAIT
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
git revision: 2bdbbe4
main.c compiled on 13:47:23 Dec 27 2016 with gcc 4.8

Opensips is getting crashed after these logs:

DBG:core:tcpconn_release:  extra_data 0x7fc923152368
DBG:core:handle_tcp_worker: reader response= 7fc9230cdf90, -1 from 7
DBG:core:tcpconn_destroy: destroying connection 0x7fc9230cdf90, flags 0006
DBG:proto_wss:tls_conn_clean: entered
DBG:proto_wss:tls_update_fd: New fd is 154
WARNING:core:timer_ticker: timer task <nh-timer> already scheduled for 678560 ms (now 680560 ms), it may overlap..
INFO:db_mysql:switch_state_to_disconnected: disconnect event for 0x7fca235144e0
INFO:db_mysql:reset_all_statements: reseting all statements on connection: (0x7fca23514b20) 0x7fca235144e0
DBG:db_mysql:reset_all_statements: resetting statement (0x7fca23521a18,0x11e1c80) for context 0x7fca23515530 (location)
DBG:db_mysql:db_mysql_connect: opening connection: mysql://xxxx:xxxx@localhost/opensips
DBG:db_mysql:db_mysql_connect: connection type is Localhost via UNIX socket
DBG:db_mysql:db_mysql_connect: protocol version is 10
DBG:db_mysql:db_mysql_connect: server version is 5.5.53-0ubuntu0.14.04.1
INFO:db_mysql:connect_with_retry: re-connected successful for 0x7fca235144e0
INFO:db_mysql:db_mysql_do_prepared_query: reconnected to mysql server -> re-init the statement
DBG:db_mysql:re_init_statement:  query  is <update location set expires=?,q=?,cseq=?,flags=?,cflags=?,user_agent=?,received=?,path=?,socket=?,methods=?,last_modified=?,attr=?,callid=? where contact_id=?>, ptr=(nil)
DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
CRITICAL:db_mysql:db_mysql_do_prepared_query: too many mysql server reconnection failures
ERROR:usrloc:db_update_ucontact: updating database failed
ERROR:usrloc:wb_timer: updating contact in db failed
CRITICAL:core:sig_alarm_abort: BUG - shutdown timeout triggered, dying...

please help me out.

[razvancrainea]

Can you also provide the timestamp of each command?

Also, can you connect to the mysql server and run commands in the sql console?

[saurabh-iitrke]

Hi, Here are more detailed logs. hope this is useful. Also i am able to connect to mysql. i have registered 30 clients. opensips is getting crashed at interval of 5 minutes .

Jan  6 17:06:21 DBG:core:io_wait_loop_epoll: [TCP_main] EPOLLHUP on IN ->connection closed by the remote peer!
Jan  6 17:06:21 DBG:core:io_wait_loop_epoll: [TCP_main] EPOLLHUP on IN ->connection closed by the remote peer!
Jan  6 17:06:21 DBG:core:handle_tcp_worker: dead tcp worker 0 (pid 20737, no 0) (shutting down?)
Jan  6 17:06:21 DBG:core:io_watch_del: [TCP_main] io_watch_del op on index 107 64 (0x81a160, 64, 107, 0x0,0x1) fd_no=157 called
Jan  6 17:06:21 CRITICAL:core:receive_fd: EOF on 66
Jan  6 17:06:21 DBG:core:handle_worker: dead child 54, pid 20737 (shutting down?)
Jan  6 17:06:21 DBG:core:io_watch_del: [TCP_main] io_watch_del op on index 56 66 (0x81a160, 66, 56, 0x0,0x1) fd_no=156 called
Jan  6 17:06:22 DBG:core:probe_max_sock_buff: getsockopt: snd is initially 425984
Jan  6 17:06:22 INFO:core:probe_max_sock_buff: using snd buffer of 416 kb
Jan  6 17:06:22 INFO:core:init_sock_keepalive: TCP keepalive enabled on socket 168
Jan  6 17:06:22 INFO:db_mysql:db_mysql_do_prepared_query: reconnected to mysql server -> re-init the statement
Jan  6 17:06:22 DBG:db_mysql:re_init_statement:  query  is <update location set expires=?,q=?,cseq=?,flags=?,cflags=?,user_agent=?,received=?,path=?,socket=?,methods=?,last_modified=?,attr=?,callid=? where contact_id=?>, ptr=(nil)
Jan  6 17:06:22 DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
Jan  6 17:06:22 DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
Jan  6 17:06:22 CRITICAL:db_mysql:db_mysql_do_prepared_query: too many mysql server reconnection failures
Jan  6 17:06:22 ERROR:usrloc:db_update_ucontact: updating database failed
Jan  6 17:06:22 ERROR:usrloc:wb_timer: updating contact in db failed
Jan  6 17:06:22 DBG:db_mysql:has_stmt_ctx: ctx found for location
Jan  6 17:06:22 DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7f5affd22108 (tail=140028815743472) MC=0x7f5affd21ab0
Jan  6 17:06:22 DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Jan  6 17:06:22 DBG:db_mysql:db_mysql_val2bind: added val (0): len=40; type=12; is_null=0
Jan  6 17:06:22 DBG:db_mysql:db_mysql_val2bind: added val (1): len=8; type=5; is_null=0
Jan  6 17:06:23 DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
Jan  6 17:06:24 DBG:core:handle_sigs: status = 139
Jan  6 17:06:24 INFO:core:handle_sigs: child process 20737 exited by a signal 11
Jan  6 17:06:24 INFO:core:handle_sigs: core was generated
Jan  6 17:06:24 INFO:core:handle_sigs: terminating due to SIGCHLD
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:24 INFO:core:sig_usr: signal 15 received
Jan  6 17:06:25 DBG:core:pool_remove: removing connection from the pool
Jan  6 17:06:25 DBG:tm:tm_shutdown: tm_shutdown : start
Jan  6 17:06:25 DBG:tm:unlink_timer_lists: emptying DELETE list for set 0
Jan  6 17:06:25 DBG:tm:tm_shutdown: emptying hash table
Jan  6 17:06:25 DBG:tm:tm_shutdown: releasing timers
Jan  6 17:06:25 DBG:tm:tm_shutdown: removing semaphores
Jan  6 17:06:25 DBG:tm:tm_shutdown: destroying callback lists
Jan  6 17:06:25 DBG:tm:tm_shutdown: tm_shutdown : done
Jan  6 17:06:25 DBG:tls_mgm:mod_destroy: entered
Jan  6 17:07:24 CRITICAL:core:sig_alarm_abort: BUG - shutdown timeout triggered, dying...

[saurabh-iitrke]

Please reply. I am stuck.

[razvancrainea]

It looks like either your mysql server is really slow, that OpenSIPS can't use that connection, or it is something wrong with the library/server. Can you provide the entire log? It seems there are other ERRORs before what you've printed, and they would be useful.

I also see there is a core dump generated, can you provide the info here? You can find more info about how to read the core dump here.

Best regards,
Răzvan

[saurabh-iitrke]

Please find the complete opensips log
http://pastebin.com/BiS3QCag

Here is the core dump output.

GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.2) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/local/sbin/opensips...done.
[New LWP 20648]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/local/sbin/opensips -P /var/run/opensips/opensips.pid -m 4096 -M 4096 -u r'.
Program terminated with signal SIGABRT, Aborted.
#0  0x00007f5c00512c37 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
56	../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt full
#0  0x00007f5c00512c37 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
        resultvar = 0
        pid = 20648
        selftid = 20648
#1  0x00007f5c00516028 in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0, 140728525733616, 140033127150887, 5, 0, 0, 
              140033118842160, 20646, 140728525733616, 4266688, 140033127179477, 1, 140033119843419, 0, 0, 140033122740064}}, sa_flags = 0, 
          sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x000000000043292e in sig_alarm_abort (signo=14) at main.c:414
        __FUNCTION__ = "sig_alarm_abort"
#3  <signal handler called>
No locals.
#4  0x00007f5c005a72a7 in sched_yield () at ../sysdeps/unix/syscall-template.S:81
No locals.
#5  0x00007f59ff20b6b9 in get_lock (lock=0x7f5a000d0574) at ../../net/../fastlock.h:221
        i = 0
#6  0x00007f59ff210348 in tls_blocking_write (c=0x7f5a000d0568, fd=69, buf=0x7f59ff4437ae <hdr_buf> "\210\002", len=2, 
    api=0x7f59ff4437e0 <tls_mgm_api>) at ../tls_mgm/tls_conn_server.h:425
        written = 0
        n = 0
        timeout = 24
        retries = 0
        pf = {fd = 69, events = 32601, revents = 0}
        __FUNCTION__ = "tls_blocking_write"
#7  0x00007f59ff21aae5 in wss_raw_writev (c=0x7f5a000d0568, fd=69, iov=0x7f59ff4235a0 <v>, iovcnt=2, tout=0) at proto_wss.c:450
        i = 0
        n = 32604
        ret = 0
#8  0x00007f59ff217684 in ws_send (con=0x7f5a000d0568, fd=69, op=8, body=0x7ffde9c945f2 "\003\350\002", len=2) at ../proto_ws/ws_common.h:261
        body_buf = 0x0
        hdr_buf = "\210\002", '\000' <repeats 11 times>
        v = {{iov_base = 0x7f59ff4437ae <hdr_buf>, iov_len = 2}, {iov_base = 0x7ffde9c945f2, iov_len = 2}}
        mask = 2078483506
        __FUNCTION__ = "ws_send"
#9  0x00007f59ff217747 in ws_send_close (con=0x7f5a000d0568) at ../proto_ws/ws_common.h:284
        code = 59395
        len = 2
        buf = 0x7ffde9c945f2 "\003\350\002"
#10 0x00007f59ff21965e in ws_close (c=0x7f5a000d0568) at ../proto_ws/ws_common.h:638
---Type <return> to continue, or q <return> to quit---
No locals.
#11 0x00007f59ff219a3d in ws_conn_clean (c=0x7f5a000d0568) at proto_wss.c:205
        d = 0x7f5a000d0810
        __FUNCTION__ = "ws_conn_clean"
#12 0x0000000000519ff0 in _tcpconn_rm (c=0x7f5a000d0568) at net/net_tcp.c:688
        r = 1
        __FUNCTION__ = "_tcpconn_rm"
#13 0x000000000051d5f8 in __tcpconn_lifetime (force=1) at net/net_tcp.c:1452
        c = 0x7f5a000d0568
        next = 0x0
        ticks = 1027
        part = 9
        h = 521
        fd = 165
        __FUNCTION__ = "__tcpconn_lifetime"
#14 0x000000000051e4dc in tcp_destroy () at net/net_tcp.c:1626
        part = 0
        __FUNCTION__ = "tcp_destroy"
#15 0x0000000000432418 in cleanup (show_status=1) at main.c:321
        __FUNCTION__ = "cleanup"
#16 0x0000000000433367 in handle_sigs () at main.c:522
        chld = 0
        chld_status = 139
        overall_status = 139
        i = 54
        do_exit = 1
        shutdown_time = 60
        __FUNCTION__ = "handle_sigs"
#17 0x00000000004342a4 in main_loop () at main.c:718
        chd_rank = 101
        startup_done = 0x0
        __FUNCTION__ = "main_loop"
#18 0x00000000004369a2 in main (argc=13, argv=0x7ffde9c949a8) at main.c:1279
        cfg_log_stderr = 1
        cfg_stream = 0x13cecc0
        c = -1
        r = 0
        tmp = 0x7ffde9c968ef ""
        tmp_len = 5161464
        port = 32604
        proto = 15532032
---Type <return> to continue, or q <return> to quit---
        protos_no = 3
        options = 0x5516a8 "f:cCm:M:b:l:n:N:rRvdDFETSVhw:t:u:g:P:G:W:o:"
        ret = -1
        seed = 803332701
        rfd = 4
        __FUNCTION__ = "main"

[razvancrainea]

Regarding the logs you provided: did you modify OpenSIPS sources in any way? Because I think you are missing some CRITICAL messages.

The coredump you attached is during destroy cleanup. Can you find a different one?

[saurabh-iitrke]

Hi @razvancrainea ,
These are the only logs i am getting. i did not modify sources.
Sorry i did not mention earlier, these are the logs and core dumps of opensips 2.3.0-dev (x86_64/linux).
I was getting same errors and crash in both opensips 2.2.2. and 2.3.0-dev

CRITICAL messages are starting from below only every time.
Jan 6 17:06:21 [20838]: CRITICAL:core:receive_fd: EOF on 66

Please find core dump logs.
pre cleanup:
http://pastebin.com/sEzW2aff
destroy cleanup:
http://pastebin.com/wgwCxuQK

[razvancrainea]

Can you tell me what version of openssl you are using?

[saurabh-iitrke]

I am using OpenSSL 1.0.1f 6 Jan 2014

[saurabh-iitrke]

any update please ?

[razvancrainea]

The core dump you sent here looks like a OpenSIPS 2.2.2. Can you also send the associated logs?
If not, can you make another test for 2.2.2 or 2.3 and send me the 'bt full' gdb output as well as the logs?
Also, is this reproduce-able? Or can you give me access to your environment so I can do further debugging?

[saurabh-iitrke]

Hi @razvancrainea ,
I sent you the core dump logs of opensips 2.3 only. anyways, here are the fresh core dump of 2.3.
pre cleanup:
http://pastebin.com/Xg2sUPmH

cleanup:
http://pastebin.com/JNvFtrZm

After changing db_mode to 0 i am not getting mysql errors.
i.e. Jan 6 17:06:22 CRITICAL:db_mysql:db_mysql_do_prepared_query: too many mysql server reconnection failures

changes:

USeR LOCation module

loadmodule "usrloc.so"
modparam("usrloc", "nat_bflag", "NAT")
modparam("usrloc", "db_mode", 0)
modparam("usrloc", "db_url",
"mysql://opensips:opensipsrw@localhost/opensips")

but opensips is still crashing at SSL_accept(ssl). but frequency of crashing is reduced.
i could not capture the logs in full debug. next time when it crashes, i will update you.

i could not reproduce it. i tried the same setup in testing environment, opensips did not crash.

[razvancrainea]

I need the log files for this specific run. You sent me logs from a completely different run, but those are not helpful, because there are other call flows, other memory addresses, etc. Can you send it?

[saurabh-iitrke]

Hi @razvancrainea ,
I could not capture the logs in debug mode. Hope this is useful:
http://pastebin.com/C8Fx2NKQ

I will provide you dump and debug logs after next crash (if occurs).

[saurabh-iitrke]

Hi @razvancrainea ,
please find latest crash debug.
opensips log:
http://pastebin.com/aWUJh9yW

core dump pre cleanup:
http://pastebin.com/sBCuq2Um

core dump cleanup:
http://pastebin.com/rLDvNYBK

these logs are for opensips:
version: opensips 2.3.0-dev (x86_64/linux)