Crash in Ratelimit module - Opensips 1.10 - Memdebug on - Centos 6

BT Pasted:

(gdb) bt full
#0  0x0000003b172328a5 in raise () from /lib64/libc.so.6
No symbol table info available.
#1  0x0000003b17234085 in abort () from /lib64/libc.so.6
No symbol table info available.
#2  0x00000000004dcbe5 in qm_free (qm=<value optimized out>, p=0x3039343430303434, file=0x7fa1e15bb8ed "ratelimit_helper.c", func=<value optimized out>, 
    line=<value optimized out>) at mem/q_malloc.c:450
        f = <value optimized out>
        size = <value optimized out>
        __FUNCTION__ = "qm_free"
#3  0x00007fa1e15b8232 in rl_timer (ticks=<value optimized out>, param=<value optimized out>) at ratelimit_helper.c:473
        i = <value optimized out>
        it = {node = 0x0, map = 0x7f9fe0966d90}
        del = {node = 0x0, map = 0x7f9fe0966d90}
        pipe = 0x7f9fe113f940
        key = <value optimized out>
        now = 1380284763
        __FUNCTION__ = "rl_timer"
#4  0x00000000004b9d0e in timer_ticker () at timer.c:384
        t = 0x7fa1e56b6478
        j = 41115
        ij = 41115270000
        ij_marker = 41115270000
#5  run_timer_process () at timer.c:471
        multiple = 1
        cnt = <value optimized out>
        tv = {tv_sec = 0, tv_usec = 0}
        drift = 0
        uinterval = 1000000
        wait = <value optimized out>
#6  start_timer_processes () at timer.c:610
        tpl = 0x7fa1e56b6820
        pid = <value optimized out>
        __FUNCTION__ = "start_timer_processes"
#7  0x0000000000434158 in main_loop (argc=<value optimized out>, argv=<value optimized out>) at main.c:991
        i = <value optimized out>
        pid = <value optimized out>
---Type <return> to continue, or q <return> to quit---
        si = 0x0
        startup_done = 0x7f9fe0b10c80
        chd_rank = 32
        rc = <value optimized out>
        load_p = 0x7f9fe0b120e8
#8  main (argc=<value optimized out>, argv=<value optimized out>) at main.c:1598
        cfg_log_stderr = <value optimized out>
        cfg_stream = <value optimized out>
        c = <value optimized out>
        r = <value optimized out>
        tmp = 0x7fff1480368e ""
        tmp_len = <value optimized out>
        port = <value optimized out>
        proto = <value optimized out>
        options = 0x5519a8 "f:cCm:M:b:l:n:N:rRvdDFETSVhw:t:u:g:P:G:W:o:"
        ret = -1
        seed = 3729286111
        rfd = <value optimized out>
        __FUNCTION__ = "main"

Accompanying opensips.log


Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[27045]: CRITICAL:core:receive_fd: EOF on 53
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[26986]: INFO:core:handle_sigs: child process 27026 exited by a signal 6
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[26986]: INFO:core:handle_sigs: core was generated
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[26986]: INFO:core:handle_sigs: terminating due to SIGCHLD
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[27045]: INFO:core:sig_usr: signal 15 received
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[27045]: Memory status (pkg):
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[27043]: INFO:core:sig_usr: signal 15 received
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[27042]: INFO:core:sig_usr: signal 15 received
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[26986]: INFO:core:handle_sigs: child process 27026 exited by a signal 6

[bogdan-iancu]

Based on the line where the abort happened , it seems the memory debugger reported a double free. In the logs, before the lines you posted, you should have a CRITICAL log from process 27026 like:
freeing already freed pointer, first free: .......... aborting
Please post that line, along with any previous potential err logs from the same process.

Also, are you using shared pipes or just local ones ?

[brettnem]

I'm seeing this:

 Sep 27 12:26:03 server7-node3 /usr/sbin/opensips[27026]: CRITICAL:core:qm_free: bad pointer 0x3039343430303434 (out of memory block!) - aborting

This happens to be with local pipes.

[razvancrainea]

Are you seeing any ERROR logs related to the ratelimit module? Something like "error while deleting key"?

[bogdan-iancu]

Brett, the BT shows frame 2 as "mem/q_malloc.c:450" -> there, in the 1.10 code is a log an a double free.

So the BT info (double free) is not consistent with the log (bad pointer) - are you sure the core and the logs are related ??

[brettnem]

Bogdan / Razvan,
I can confirm this is in fact the right trace. Timestamp of the core and filename of the core correspond to the log message:

Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[27045]: CRITICAL:core:receive_fd: EOF on 53
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[26986]: INFO:core:handle_sigs: child process 27026 exited by a signal 6 <=====
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[26986]: INFO:core:handle_sigs: core was generated
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[26986]: INFO:core:handle_sigs: terminating due to SIGCHLD
Sep 27 12:26:27 server7-node3 /usr/sbin/opensips[27045]: INFO:core:sig_usr: signal 15 received

-rw-------    1 root root 8628969472 Sep 27 12:26 core.27026  <===


(gdb) f 2
#2  0x00000000004dcbe5 in qm_free (qm=<value optimized out>, p=0x3039343430303434, file=0x7fa1e15bb8ed "ratelimit_helper.c",
    func=<value optimized out>, line=<value optimized out>) at mem/q_malloc.c:450
450         abort();

[brettnem]

Hey Guys,
I just made another one of these happen. I can confirm definitively that this is matched up right. Local pipes only. Package memory at the time appears to be leaking.

[razvancrainea]

This should have been fixed in commit razvancrainea/opensips@72ab3f4 . Please open the ticket if there are any other problems with it.