Segmentation fault in TM module while processing SIP status 408

[mshary]

Description

We have segfault in Kamailio v5.0.7 rev. 7ab0b1 installed on Debain 7.x 32bit KVM when processing sip reply 408 due to RING Timeout.

Troubleshooting

No troubleshooting was done, since it happened on a production server. We simply restarted the server.

Reproduction

The problem is random and has happened a couple of times within a month.

Debugging Data

Here is back trace from core dump generated by kamailio.

Core was generated by `/usr/local/adx-webrtc/sbin/kamailio -f /usr/local/adx-webrtc/etc/kamailio/kamai'.
Program terminated with signal 11, Segmentation fault.
#0  0xb4f9bcb9 in run_failure_handlers (t=0x92d6111c, rpl=0xffffffff, code=408, extra_flags=96) at t_reply.c:1013
1013    t_reply.c: No such file or directory.
(gdb) bt
#0  0xb4f9bcb9 in run_failure_handlers (t=0x92d6111c, rpl=0xffffffff, code=408, extra_flags=96) at t_reply.c:1013
#1  0xb4f9ea32 in t_should_relay_response (Trans=0x92d6111c, new_code=408, branch=0, should_store=0xbf90fba4, should_relay=0xbf90fba8, cancel_data=0xbf90fc28, reply=0xffffffff) at t_reply.c:1382
#2  0xb4fa1431 in relay_reply (t=0x92d6111c, p_msg=0xffffffff, branch=0, msg_status=408, cancel_data=0xbf90fc28, do_put_on_wait=0) at t_reply.c:1785
#3  0xb4f4bbca in fake_reply (t=0x92d6111c, branch=0, code=408) at timer.c:340
#4  0xb4f4bfe7 in final_response_handler (r_buf=0x92d61288, t=0x92d6111c) at timer.c:506
#5  0xb4f4c07e in retr_buf_handler (ticks=368965158, tl=0x92d6129c, p=0xfffffffe) at timer.c:562
#6  0x08250eb4 in slow_timer_main () at core/timer.c:1131
#7  0x08069a4e in main_loop () at main.c:1679
#8  0x08070868 in main (argc=13, argv=0xbf9103a4) at main.c:2642

Here is full back trace.

(gdb) bt full
#0  0xb4f9bcb9 in run_failure_handlers (t=0x92d6111c, rpl=0xffffffff, code=408, extra_flags=96) at t_reply.c:1013
        faked_req = 0x984311f4
        faked_req_len = 4512
        shmem_msg = 0x94ed18b8
        on_failure = 2
        keng = 0x0
        __FUNCTION__ = "run_failure_handlers"
#1  0xb4f9ea32 in t_should_relay_response (Trans=0x92d6111c, new_code=408, branch=0, should_store=0xbf90fba4, should_relay=0xbf90fba8, cancel_data=0xbf90fc28, reply=0xffffffff) at t_reply.c:1382
        branch_cnt = 1
        picked_code = 408
        new_branch = -1755505652
        inv_through = 0
        extra_flags = 96
        i = 0
        replies_dropped = 0
        __FUNCTION__ = "t_should_relay_response"
#2  0xb4fa1431 in relay_reply (t=0x92d6111c, p_msg=0xffffffff, branch=0, msg_status=408, cancel_data=0xbf90fc28, do_put_on_wait=0) at t_reply.c:1785
        relay = -65536
        save_clone = 0
        buf = 0x0
        res_len = 0
        relayed_code = 0
        relayed_msg = 0x0
        reply_bak = 0xb5002368
        bm = {to_tag_val = {s = 0xb5a847f7 "ation", len = 10}}
        totag_retr = 0
        reply_status = RPS_ERROR
        uas_rb = 0x0
        to_tag = 0x0
        reason = {s = 0x0, len = 1946659428}
        onsend_params = {req = 0xb5002368, rpl = 0x0, param = 0xbf910234, code = -1081017352, flags = 56659, branch = 46322, t_rbuf = 0xb4fd5a10, dst = 0x2, send_buf = {
            s = 0xbf90fce8 "\030\375\220\277\034\021֒\210\022֒\240", len = 1946588245}}
        ip = {af = 0, len = 3213949832, u = {addrl = {4294967295, 0, 3213951540, 3213949832}, addr32 = {4294967295, 0, 3213951540, 3213949832}, addr16 = {65535, 65535, 0, 0, 564, 49041, 64392,
              49040}, addr = "\377\377\377\377\000\000\000\000\064\002\221\277\210", <incomplete sequence \373\220\277>}}
        __FUNCTION__ = "relay_reply"
#3  0xb4f4bbca in fake_reply (t=0x92d6111c, branch=0, code=408) at timer.c:340
        cancel_data = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len = 5}, e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = 5}}}}
        do_cancel_branch = 1
        reply_status = 29068
#4  0xb4f4bfe7 in final_response_handler (r_buf=0x92d61288, t=0x92d6111c) at timer.c:506
        silent = 0
        branch_ret = -1258282136
        prev_branch = 0
        now = 0
#5  0xb4f4c07e in retr_buf_handler (ticks=368965158, tl=0x92d6129c, p=0xfffffffe) at timer.c:562
        rbuf = 0x92d61288
        fr_remainder = 0
        retr_remainder = 12
        retr_interval = 1674326491
        new_retr_interval_ms = 160
        crt_retr_interval_ms = 3213950232
        t = 0x92d6111c
        __FUNCTION__ = "retr_buf_handler"
#6  0x08250eb4 in slow_timer_main () at core/timer.c:1131
        n = 12
        ret = 0
        tl = 0x92d6129c
        i = 516
        __FUNCTION__ = "slow_timer_main"
#7  0x08069a4e in main_loop () at main.c:1679
        i = 4
        pid = 0
        si = 0x0
        si_desc = "udp receiver child=3 sock=xx.xx.xx.xx:5060\000\000\000\000\000\004\000\000\000\030\000\221\277\333\061\314c\001\000\000\000\333\061\314c\230\377\220\277\264\n(\bd\024<t\004\000\000\000\331\332\066\b\260\354\066\bq\000\000\000t\331\066\b\v\020\000\000Y\222\350\264D\221\257\265;\031B\264\\\"C\264\214#\000\000\000\000\000"
        nrprocs = 4
        woneinit = 1
        __FUNCTION__ = "main_loop"
#8  0x08070868 in main (argc=13, argv=0xbf9103a4) at main.c:2642
        cfg_stream = 0x8a4a008
        c = -1
        r = 0
        tmp = 0xbf910903 ""
        tmp_len = -1218121696
        port = 2209
        proto = 1
        options = 0x8344f9c ":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
        ret = -1
        seed = 3093231387
        rfd = 4
        debug_save = 0
        debug_flag = 0
        dont_fork_cnt = 0
        n_lst = 0xbf9103a4
        p = 0x805d60c "[\201\303\354\253<"
        st = {st_dev = 14, __pad1 = 0, st_ino = 10259, st_mode = 16832, st_nlink = 2, st_uid = 0, st_gid = 0, st_rdev = 0, __pad2 = 0, st_size = 60, st_blksize = 4096, st_blocks = 0, st_atim = {
            tv_sec = 1542580403, tv_nsec = 128163439}, st_mtim = {tv_sec = 1542580752, tv_nsec = 236241520}, st_ctim = {tv_sec = 1542580752, tv_nsec = 236241520}, __unused4 = 0, __unused5 = 0}
        __FUNCTION__ = "main"

Log Messages

No logs available since it happend on a production server.

Jan 10 16:00:53 webrtc-as kernel: [25983771.956320] kamailio[29068]: segfault at 36c ip b4f9bcb9 sp bf90f7a0 error 6 in tm.so[b4eeb000+117000]

SIP Traffic

No SIP traffic available.

Additional Information

• Kamailio Version - output of kamailio -v

version: kamailio 5.0.7 (i386/linux) 7ab0b1
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, select.
id: 7ab0b1 
compiled on 22:43:08 Aug 27 2018 with gcc 4.7.2

• Operating System:

Linux webrtc-as1 3.16.0-0.bpo.4-686-pae #1 SMP Debian 3.16.36-1+deb8u2~bpo70+1 (2016-10-19) i686 GNU/Linux

[miconda]

This might be something that was fixed by 39b89a1 -- the trace looks a bit similar to the other reports. If you have a chance to try it, a report of result would be appreciated. Iirc, patch not ported to branch 5.0 yet, but should be done when releasing the last version in 5.0.x series, and that should be in the near future.

[mshary]

OK, I will plan production upgrade with this patch and get back to you if problem happens again.

BTW, we are already testing Kamailio v5.2 on QA setup. Is this patch already ported to v5.2 or should i apply it to QA setup as well.

Thank you.

[miconda]

It should be already in 5.2 branch.

[miconda]

Closing it, with 5.2.1 being released yesterday. If you still get issues, reopen.