Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Segmentation fault on tm:t_should_relay_response #1875

Closed
Fernandojdk opened this issue Feb 28, 2019 · 10 comments

Comments

Projects
None yet
2 participants
@Fernandojdk
Copy link

commented Feb 28, 2019

Description

I have a segfault in an average of 3 to 6 per day on tm module always on the t_should_relay_response.
I'm using kamailio 5.2.0 (x86_64/linux) 535e13 on CentOS Linux release 7.6.1810 (Core) x86_64 runing on a XenServer.

Troubleshooting

No troubleshooting was done, since it happened on a production server.

Reproduction

The problem is random and has happened a couple of times per day. My kamailio uses tm, dialog, htable. All calls is using topoh. The server run with an average of 1000-1200 concurrent calls. I've seen this segfault happen with less than 400 concurrent calls too.
One very curious thing, when the fifth or sixth time the segfault occurs, it does not happen again, even reaching 3000 concurrent calls.

Debugging Data

(gdb) bt
#0  0x00007f685674a84d in t_should_relay_response (Trans=0x7f683d86a3e0, new_code=503, branch=0, should_store=0x7fffed6c323c, should_relay=0x7fffed6c3240, cancel_data=0x7fffed6c3490, reply=0x7f685b6cafa0) at t_reply.c:1279
#1  0x00007f685674ee6b in relay_reply (t=0x7f683d86a3e0, p_msg=0x7f685b6cafa0, branch=0, msg_status=503, cancel_data=0x7fffed6c3490, do_put_on_wait=1) at t_reply.c:1804
#2  0x00007f6856754ac3 in reply_received (p_msg=0x7f685b6cafa0) at t_reply.c:2563
#3  0x00000000005291a9 in do_forward_reply (msg=0x7f685b6cafa0, mode=0) at core/forward.c:747
#4  0x000000000052ad21 in forward_reply (msg=0x7f685b6cafa0) at core/forward.c:852
#5  0x000000000059e89e in receive_msg (
    buf=0xa6c2a0 <buf.6868> "SIP/2.0 503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;bra"..., len=565, 
    rcv_info=0x7fffed6c3c30) at core/receive.c:433
#6  0x0000000000481690 in udp_rcv_loop () at core/udp_server.c:541
#7  0x0000000000424a27 in main_loop () at main.c:1621
#8  0x000000000042c078 in main (argc=9, argv=0x7fffed6c4178) at main.c:2645

(gdb) list
1274			/* except the exception above, too late  messages will be discarded */
1275			goto discard;
1276		}
1277	
1278		/* if final response received at this branch, allow only INVITE 2xx */
1279		if (Trans->uac[branch].last_received>=200 
1280			    && !(inv_through && Trans->uac[branch].last_received<300)) {
1281			/* don't report on retransmissions */
1282			if (Trans->uac[branch].last_received==new_code) {
1283				LM_DBG("final reply retransmission\n");
1284				goto discard;

(gdb) info locals
branch_cnt = 32767
picked_code = 0
new_branch = -311676496
inv_through = 0
extra_flags = 0
i = 32616
replies_dropped = 1143247665
__FUNCTION__ = "t_should_relay_response"

(gdb) bt full
#0  0x00007f685674a84d in t_should_relay_response (Trans=0x7f683d86a3e0, new_code=503, branch=0, should_store=0x7fffed6c323c, should_relay=0x7fffed6c3240, cancel_data=0x7fffed6c3490, reply=0x7f685b6cafa0) at t_reply.c:1279
        branch_cnt = 32767
        picked_code = 0
        new_branch = -311676496
        inv_through = 0
        extra_flags = 0
        i = 32616
        replies_dropped = 1143247665
        __FUNCTION__ = "t_should_relay_response"
#1  0x00007f685674ee6b in relay_reply (t=0x7f683d86a3e0, p_msg=0x7f685b6cafa0, branch=0, msg_status=503, cancel_data=0x7fffed6c3490, do_put_on_wait=1) at t_reply.c:1804
        relay = -311676288
        save_clone = 0
        buf = 0x0
        res_len = 0
        relayed_code = 0
        relayed_msg = 0x0
        reply_bak = 0x7fffed6c3290
        bm = {to_tag_val = {s = 0x1 <Address 0x1 out of bounds>, len = 1032234408}}
        totag_retr = 0
        reply_status = RPS_ERROR
        uas_rb = 0x68924f <futex_release+29>
        to_tag = 0x7f685e8ffed0 <__syslog>
        reason = {s = 0x0, len = 0}
        onsend_params = {req = 0x7f685b6cafa0, rpl = 0x7f685b597870, param = 0x7f68567e0c50, code = 0, flags = 2288, branch = 0, t_rbuf = 0x7f68567e6edb <__FUNCTION__.12468>, dst = 0x7f68567e23ab, send_buf = {
            s = 0x7f68440006f0 "SIP/2.0 183 Session Progress\r\nVia: SIP/2.0/UDP X.X.X.35:5060;received=X.X.X.35;TH=div;rport=5060;branch=z9hG4bK-97cc84683b6011e980ec0cc47a0ad35a;sig=7970278d\r\nVia: SIP/2.0/UDP X.X.X.35:"..., len = 841211904}}
        ip = {af = 3983291088, len = 32767, u = {addrl = {5867152, 11367808}, addr32 = {5867152, 0, 11367808, 0}, addr16 = {34448, 89, 0, 0, 30080, 173, 0, 0}, addr = "\220\206Y\000\000\000\000\000\200u\255\000\000\000\000"}}
        __FUNCTION__ = "relay_reply"
#2  0x00007f6856754ac3 in reply_received (p_msg=0x7f685b6cafa0) at t_reply.c:2563
        msg_status = 503
        last_uac_status = 408
        ack = 0x7f68440006f0 "SIP/2.0 183 Session Progress\r\nVia: SIP/2.0/UDP X.X.X.35:5060;received=X.X.X.35;TH=div;rport=5060;branch=z9hG4bK-97cc84683b6011e980ec0cc47a0ad35a;sig=7970278d\r\nVia: SIP/2.0/UDP X.X.X.35:"...
        ack_len = 406
        branch = 0
        reply_status = 67108864
        onreply_route = 3
        cancel_data = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len = 1586495184}, e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = 1586495184}}}}
        uac = 0x7f683d86a5f0
        t = 0x7f683d86a3e0
        lack_dst = {send_sock = 0x20000000, to = {s = {sa_family = 0, sa_data = "\000\004\000\000\000\000p5l\355\377\177\000"}, sin = {sin_family = 0, sin_port = 1024, sin_addr = {s_addr = 0}, sin_zero = "p5l\355\377\177\000"}, sin6 = {sin6_family = 0, sin6_port = 1024, 
              sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 = "p5l\355\377\177\000\000\201\020\342Uh\177\000", __u6_addr16 = {13680, 60780, 32767, 0, 4225, 21986, 32616, 0}, __u6_addr32 = {3983291760, 32767, 1440878721, 32616}}}, sin6_scope_id = 11693840}}, 
          id = 0, proto = 0 '\000', send_flags = {f = 0, blst_imask = 0}}
        backup_user_from = 0xad7390 <def_list+16>
        backup_user_to = 0xad7398 <def_list+24>
        backup_domain_from = 0xad73a0 <def_list+32>
        backup_domain_to = 0xad73a8 <def_list+40>
        backup_uri_from = 0xad7380 <def_list>
        backup_uri_to = 0xad7388 <def_list+8>
        backup_xavps = 0xa6b250 <_xavp_list_head>
        replies_locked = 1
        branch_ret = 536870912
        prev_branch = 0
        blst_503_timeout = 90
        hf = 0x7c7213
        onsend_params = {req = 0x7f685b3af890, rpl = 0xa6c4d5 <buf.6868+565>, param = 0x0, code = 10929363, flags = 0, branch = 0, t_rbuf = 0xa6c4d5 <buf.6868+565>, dst = 0x7f685e8ffed0 <__syslog>, send_buf = {s = 0x7c7213 "INFO", len = 90}}
        ctx = {rec_lev = 0, run_flags = 0, last_retcode = -1, jmp_env = {{__jmpbuf = {140086239821520, -3528413356315156285, 8155667, 90, 536870912, 67108864, -3528413356269018941, 3528382109948141763}, __mask_was_saved = 0, __saved_mask = {__val = {67108864, 
                  140737176679536, 7233135, 140737176679600, 6865256, 140086183963912, 140086183963896, 15482808, 8, 18446744073709551615, 140086187175840, 8155667, 90, 140737176679668, 140737176679672, 140086183985368}}}}}
        bctx = 0x7f685b6cafa0
        keng = 0x0
        __FUNCTION__ = "reply_received"
#3  0x00000000005291a9 in do_forward_reply (msg=0x7f685b6cafa0, mode=0) at core/forward.c:747
        new_buf = 0x0
        dst = {send_sock = 0x0, to = {s = {sa_family = 0, sa_data = '\000' <repeats 13 times>}, sin = {sin_family = 0, sin_port = 0, sin_addr = {s_addr = 0}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 0, sin6_port = 0, sin6_flowinfo = 0, 
              sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}}, id = 0, proto = 0 '\000', send_flags = {f = 0, blst_imask = 0}}
        new_len = 0
        r = 1
        ip = {af = 3983291952, len = 32767, u = {addrl = {140086109025369, 8278245420}, addr32 = {1455699033, 32616, 3983278124, 1}, addr16 = {13401, 22212, 32616, 0, 44, 60780, 1, 0}, addr = "Y4\304Vh\177\000\000,\000l\355\001\000\000"}}
        s = 0x6f8 <Address 0x6f8 out of bounds>
        len = 0
        __FUNCTION__ = "do_forward_reply"
#4  0x000000000052ad21 in forward_reply (msg=0x7f685b6cafa0) at core/forward.c:852
No locals.
#5  0x000000000059e89e in receive_msg (
    buf=0xa6c2a0 <buf.6868> "SIP/2.0 503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;bra"..., len=565, 
    rcv_info=0x7fffed6c3c30) at core/receive.c:433
        msg = 0x7f685b6cafa0
        ctx = {rec_lev = 70, run_flags = 0, last_retcode = 8, jmp_env = {{__jmpbuf = {2314885530818453536, 2314885530818453536, 0, 0, 0, 0, 0, 0}, __mask_was_saved = 0, __saved_mask = {__val = {65280, 1099807431579733077, 3183208866038363301, 17755792806188831655, 
                  4262298206711962970, 11302123416292502927, 212649150131803653, 8808588017067063289, 17812784738947474131, 170888629502, 10994336, 140737176681528, 0, 55834574851, 140086239821520, 8155667}}}}}
        bctx = 0x3b26b9a2e9d9dd5a
        ret = 0
        stats_on = 0
        tvb = {tv_sec = 9, tv_usec = 26651291}
        tve = {tv_sec = -16777216, tv_usec = 0}
        tz = {tz_minuteswest = 0, tz_dsttime = 0}
        diff = 0
        inb = {s = 0xa6c2a0 <buf.6868> "SIP/2.0 503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;bra"..., len = 565}
        netinfo = {data = {s = 0x0, len = 0}, rcv = 0x0, dst = 0x0}
        keng = 0x0
        evp = {data = 0x7fffed6c37b0, rcv = 0x7fffed6c3c30, dst = 0x0}
        cidlockidx = 0
        cidlockset = 0
        errsipmsg = 0
        __FUNCTION__ = "receive_msg"
#6  0x0000000000481690 in udp_rcv_loop () at core/udp_server.c:541
        len = 628
        buf = "SIP/2.0 503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;bra"...
        tmp = 0xa7c2a0 <buff.5595> "177.99.230.99"
        from = 0x7f685b3bdba8
        fromlen = 16
        ri = {src_ip = {af = 2, len = 4, u = {addrl = {39569941286, 140737176681744}, addr32 = {915235622, 9, 3983293712, 32767}, addr16 = {25382, 13965, 9, 0, 15632, 60780, 32767, 0}, addr = "&c\215\066\t\000\000\000\020=l\355\377\177\000"}}, dst_ip = {af = 2, len = 4, 
            u = {addrl = {646919601, 0}, addr32 = {646919601, 0, 0, 0}, addr16 = {13745, 9871, 0, 0, 0, 0, 0, 0}, addr = "\261\065\217&", '\000' <repeats 11 times>}}, src_port = 5060, dst_port = 5060, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {
              sa_family = 2, sa_data = "\023\304&c\215\066\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 50195, sin_addr = {s_addr = 915235622}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, 
              sin6_flowinfo = 915235622, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}}, bind_address = 0x7f685a89bb28, proto = 1 '\001'}
        evp = {data = 0x0, rcv = 0x0, dst = 0x0}
        printbuf = "\023r|\000\b\000\000\000\326*\250Rh\177\000\000\000\000\000 \000\000\000\000\020\266\215\001\000\000\000\000\000\000\000\000\002\000\000\000\002", '\000' <repeats 39 times>, "\300\214\001\062h\177\000\000\210V\213Z(\a\000\000\336=\002\062h\177\000\000\373\252\001\062h\177\000\000\360", '\000' <repeats 11 times>, "h\177\000\000\250\333;[h\177\000\000\001\000\000\000\003", '\000' <repeats 19 times>, "\266\333;[h\177\000\000\020p\200Z\000\000\000\000\177\000\000\000\000\000\000\000\204\020\204\062h\177\000\000\023r|\000\000\000\000\000"...
        i = -1
        j = 4579542
        l = 258781216
        __FUNCTION__ = "udp_rcv_loop"
#7  0x0000000000424a27 in main_loop () at main.c:1621
        i = 8
        pid = 0
        si = 0x7f685a89bb28
        si_desc = "udp receiver child=8 sock=X.X.X.38:5060\000\177\000\000\300=l\355\377\177\000\000\320\376\217^h\177\000\000\220@l\355\377\177\000\000\023r|\000\000\000\000\000Z\000\000\000\000\000\000\000\000\000\000 \000\000\000\000\000\000\000\004\000\000\000\000_\377\217^h\177\000\000\200bx\000\000\000\000\000@\032F[h\177\000"
        nrprocs = 32
        woneinit = 1
        __FUNCTION__ = "main_loop"
#8  0x000000000042c078 in main (argc=9, argv=0x7fffed6c4178) at main.c:2645
        cfg_stream = 0x16f8010
        c = -1
        r = 0
        tmp = 0x7fffed6c5f66 ""
        tmp_len = 0
        port = 0
        proto = 0
        options = 0x768aa0 ":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 = 1705952777
        rfd = 4
        debug_save = 0
        debug_flag = 0
        dont_fork_cnt = 0
        n_lst = 0x0
        p = 0x0
        st = {st_dev = 20, st_ino = 32456, st_nlink = 2, st_mode = 16832, st_uid = 0, st_gid = 2, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1551072083, tv_nsec = 812037328}, st_mtim = {tv_sec = 1551360053, 
            tv_nsec = 958825627}, st_ctim = {tv_sec = 1551360053, tv_nsec = 958825627}, __unused = {0, 0, 0}}
        __FUNCTION__ = "main"
=======================================================================
(gdb) p Trans
$1 = (struct cell *) 0x7f683d86a3e0

(gdb) p *Trans
$2 = {next_c = 0x7f68323e7b50, prev_c = 0x7f68323e7b50, hash_index = 36580, label = 151969688, flags = 321, nr_of_outgoings = 1, fcount = 0, ref_count = {val = 1}, from = {
    s = 0x7f683558283b "From: \"6654588489\" <sip:6654588489@X.X.X.28>;tag=11-C6F1DC43\r\nMax-Forwards: 67\r\nSession-ID: 4d22ebbbfcedf4c1da9aff86b1c1b1ae\r\nSupported: 100rel,timer,replaces\r\nTo: <sip:5566996495302@X.X.X.28:"..., len = 66}, callid = {
    s = 0x7f68355827b3 "Call-ID: 9BkwYi6R3gjI6VRy@X.X.X.28\r\nContact: <sip:X.X.X.19;did=e5b.89a103e>\r\nContent-Type: application/sdp\r\nCSeq: 19054 INVITE\r\nFrom: \"6654588489\" <sip:6654588489@X.X.X.28>;tag=11-C6F1DC43"..., len = 40}, cseq_n = {
    s = 0x7f6835582827 "CSeq: 19054 INVITE\r\nFrom: \"6654588489\" <sip:6654588489@X.X.X.28>;tag=11-C6F1DC43\r\nMax-Forwards: 67\r\nSession-ID: 4d22ebbbfcedf4c1da9aff86b1c1b1ae\r\nSupported: 100rel,timer,replaces\r\nTo: <sip:5566996"..., len = 11}, to = {
    s = 0x7f68355828df "To: <sip:5566996495302@X.X.X.28:5060>\r\nVia: SIP/2.0/UDP X.X.X.19:5060;TH=div;branch=z9hG4bK4ee8.13eb8d24.0\r\nContent-Length: 294\r\nTH: dih\r\n\r\nv=0\r\no=- 1012292 0 IN IP4 177.220.255.123\r\ns=-\r\nc=IN"..., len = 43}, method = {
    s = 0x7f6835582780 "INVITE sip:11#5566996495302@X.X.X.38 SIP/2.0\r\nCall-ID: 9BkwYi6R3gjI6VRy@X.X.X.28\r\nContact: <sip:X.X.X.19;did=e5b.89a103e>\r\nContent-Type: application/sdp\r\nCSeq: 19054 INVITE\r\nFrom: \"665458"..., len = 6}, tmcb_hl = {
    first = 0x7f68422880a8, reg_types = 1048738}, wait_timer = {next = 0x0, prev = 0x0, expire = 0, initial_timeout = 0, data = 0x7f683d86a3e0, f = 0x7f685679d50b <wait_handler>, flags = 1, slow_idx = 0}, uas = {request = 0x7f6835582060,
    end_request = 0x7f6835583318 "\300\300\300\300", response = {rbtype = 100, flags = 0, t_active = 0, branch = 0, buffer_len = 334,
      buffer = 0x7f683b50fc38 "SIP/2.0 100 Trying\r\nCall-ID: 9BkwYi6R3gjI6VRy@X.X.X.28\r\nCSeq: 19054 INVITE\r\nFrom: \"6654588489\" <sip:6654588489@X.X.X.28>;tag=11-C6F1DC43\r\nTo: <sip:5566996495302@X.X.X.28:5060>\r\nVia: SIP/2."...,
      my_T = 0x7f683d86a3e0, timer = {next = 0x0, prev = 0x0, expire = 0, initial_timeout = 0, data = 0x0, f = 0x7f685679cfda <retr_buf_handler>, flags = 0, slow_idx = 0}, dst = {send_sock = 0x7f685a89bb28, to = {s = {sa_family = 2,
            sa_data = "\023\304\310GM\023\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 50195, sin_addr = {s_addr = 323831752}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, sin6_flowinfo = 323831752,
            sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}}, id = 0, proto = 1 '\001', send_flags = {f = 0, blst_imask = 0}}, retr_expire = 0, fr_expire = 0},
    local_totag = {s = 0x7f683b50fcf3 "\r\nVia: SIP/2.0/UDP X.X.X.19:5060;TH=div;branch=z9hG4bK4ee8.13eb8d24.0;rport=5060\r\nServer: NextRouter SoftSWITCH Pro v4.1\r\nContent-Length: 0\r\n\r\n956a5b272923f34-7a86\r\nCall-ID: 2ff99aa726a3a3082660e2"..., len = 0},
    cancel_reas = 0x0, status = 100}, uac = 0x7f683d86a5f0, async_backup = {backup_route = 0, backup_branch = 0, blind_uac = 0, ruri_new = 0}, fwded_totags = 0x0, uri_avps_from = 0x7f6834c993b0, uri_avps_to = 0x0, user_avps_from = 0x0, user_avps_to = 0x0,
  domain_avps_from = 0x0, domain_avps_to = 0x0, xavps_list = 0x0, reply_mutex = {val = 0}, reply_locker_pid = {val = 0}, reply_rec_lock_level = 0, fr_timeout = 32, fr_inv_timeout = 112, rt_t1_timeout_ms = 500, rt_t2_timeout_ms = 4000, end_of_life = 474292144,
  relayed_reply_branch = -2, on_failure = 3, on_branch_failure = 0, on_reply = 3, on_branch = 0, on_branch_delayed = 3, md5 = 0x7f683d86a5d0 "9bc5c0acdc87d6654d5368cad5906e3e"}

(gdb) p *should_store
$3 = 0

(gdb) p should_store
$4 = (int *) 0x7fffed6c323c

(gdb) p cancel_data
$5 = (struct cancel_info *) 0x7fffed6c3490

(gdb) p *cancel_data
$6 = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len = 1586495184}, e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = 1586495184}}}}

(gdb) p *reply
$7 = {id = 55770, pid = 121295, tval = {tv_sec = 1551362168, tv_usec = 692071}, fwd_send_flags = {f = 0, blst_imask = 0}, rpl_send_flags = {f = 0, blst_imask = 0}, first_line = {type = 2, flags = 1, len = 33, u = {request = {method = {
          s = 0xa6c2a0 <buf.6868> "SIP/2.0 503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;bra"..., len = 7}, uri = {
          s = 0xa6c2a8 <buf.6868+8> "503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;branch=z9hG"..., len = 3}, version = {
          s = 0xa6c2ac <buf.6868+12> "Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;branch=z9hG4bK4"..., len = 19},
        method_value = 503}, reply = {version = {
          s = 0xa6c2a0 <buf.6868> "SIP/2.0 503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;bra"..., len = 7}, status = {
          s = 0xa6c2a8 <buf.6868+8> "503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;branch=z9hG"..., len = 3}, reason = {
          s = 0xa6c2ac <buf.6868+12> "Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;branch=z9hG4bK4"..., len = 19},
        statuscode = 503}}}, via1 = 0x7f685b3af740, via2 = 0x7f685b3af9e0, headers = 0x7f685b3b1ec8, last_header = 0x7f685b3adf68, parsed_flag = 18446744073709551615, h_via1 = 0x7f685b3b1ec8, h_via2 = 0x7f685b3bbf98, callid = 0x7f685b3b9c50, to = 0x7f685b3b9ba8,
  cseq = 0x7f685b3adec0, from = 0x7f685b3b2f28, contact = 0x0, maxforwards = 0x0, route = 0x0, record_route = 0x0, content_type = 0x0, content_length = 0x7f685b3b7468, authorization = 0x0, expires = 0x0, proxy_auth = 0x0, supported = 0x0, require = 0x0,
  proxy_require = 0x0, unsupported = 0x0, allow = 0x0, event = 0x0, accept = 0x0, accept_language = 0x0, organization = 0x0, priority = 0x0, subject = 0x0, user_agent = 0x0, server = 0x7f685b3bdf70, content_disposition = 0x0, diversion = 0x0, rpid = 0x0, refer_to = 0x0,
  session_expires = 0x0, min_se = 0x0, sipifmatch = 0x0, subscription_state = 0x0, date = 0x0, identity = 0x0, identity_info = 0x0, pai = 0x0, ppi = 0x0, path = 0x0, privacy = 0x0, min_expires = 0x0, body = 0x0, eoh = 0xa6c4d3 <buf.6868+563> "\r\n",
  unparsed = 0xa6c4d3 <buf.6868+563> "\r\n", rcv = {src_ip = {af = 2, len = 4, u = {addrl = {39569941286, 140737176681744}, addr32 = {915235622, 9, 3983293712, 32767}, addr16 = {25382, 13965, 9, 0, 15632, 60780, 32767, 0},
        addr = "&c\215\066\t\000\000\000\020=l\355\377\177\000"}}, dst_ip = {af = 2, len = 4, u = {addrl = {646919601, 0}, addr32 = {646919601, 0, 0, 0}, addr16 = {13745, 9871, 0, 0, 0, 0, 0, 0}, addr = "\261\065\217&", '\000' <repeats 11 times>}}, src_port = 5060,
    dst_port = 5060, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 2, sa_data = "\023\304&c\215\066\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 50195, sin_addr = {s_addr = 915235622},
        sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, sin6_flowinfo = 915235622, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}},
        sin6_scope_id = 0}}, bind_address = 0x7f685a89bb28, proto = 1 '\001'},
  buf = 0xa6c2a0 <buf.6868> "SIP/2.0 503 Service Unavailable\r\nVia: SIP/2.0/UDP X.X.X.38:5060;TH=ucv;branch=z9hG4bKf581.18dae6287b86c3ef95ba52c12f282865.0\r\nVia: SIP/2.0/UDP X.X.X.69:5060;received=X.X.X.69;TH=div;bra"..., len = 565, new_uri = {s = 0x0,
    len = 0}, dst_uri = {s = 0x0, len = 0}, parsed_uri_ok = 0, parsed_uri = {user = {s = 0x0, len = 0}, passwd = {s = 0x0, len = 0}, host = {s = 0x0, len = 0}, port = {s = 0x0, len = 0}, params = {s = 0x0, len = 0}, sip_params = {s = 0x0, len = 0}, headers = {s = 0x0,
      len = 0}, port_no = 0, proto = 0, type = ERROR_URI_T, flags = (unknown: 0), transport = {s = 0x0, len = 0}, ttl = {s = 0x0, len = 0}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0, len = 0}, lr = {s = 0x0, len = 0}, r2 = {s = 0x0,
      len = 0}, gr = {s = 0x0, len = 0}, transport_val = {s = 0x0, len = 0}, ttl_val = {s = 0x0, len = 0}, user_param_val = {s = 0x0, len = 0}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 0}, lr_val = {s = 0x0, len = 0}, r2_val = {s = 0x0, len = 0},
    gr_val = {s = 0x0, len = 0}}, parsed_orig_ruri_ok = 0, parsed_orig_ruri = {user = {s = 0x0, len = 0}, passwd = {s = 0x0, len = 0}, host = {s = 0x0, len = 0}, port = {s = 0x0, len = 0}, params = {s = 0x0, len = 0}, sip_params = {s = 0x0, len = 0}, headers = {s = 0x0,
      len = 0}, port_no = 0, proto = 0, type = ERROR_URI_T, flags = (unknown: 0), transport = {s = 0x0, len = 0}, ttl = {s = 0x0, len = 0}, user_param = {s = 0x0, len = 0}, maddr = {s = 0x0, len = 0}, method = {s = 0x0, len = 0}, lr = {s = 0x0, len = 0}, r2 = {s = 0x0,
      len = 0}, gr = {s = 0x0, len = 0}, transport_val = {s = 0x0, len = 0}, ttl_val = {s = 0x0, len = 0}, user_param_val = {s = 0x0, len = 0}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 0}, lr_val = {s = 0x0, len = 0}, r2_val = {s = 0x0, len = 0},
    gr_val = {s = 0x0, len = 0}}, add_rm = 0x7f685b3abb88, body_lumps = 0x0, reply_lump = 0x0, add_to_branch_s = '\000' <repeats 57 times>, add_to_branch_len = 0, hash_index = 0, msg_flags = 32768, flags = 2692743168, xflags = {0, 0}, set_global_address = {s = 0x0,
    len = 0}, set_global_port = {s = 0x0, len = 0}, force_send_socket = 0x0, path_vec = {s = 0x0, len = 0}, instance = {s = 0x0, len = 0}, reg_id = 0, ruid = {s = 0x0, len = 0}, location_ua = {s = 0x0, len = 0}, ldv = {flow = {decoded = 0, rcv = {src_ip = {af = 0,
          len = 0, u = {addrl = {0, 0}, addr32 = {0, 0, 0, 0}, addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, addr = '\000' <repeats 15 times>}}, dst_ip = {af = 0, len = 0, u = {addrl = {0, 0}, addr32 = {0, 0, 0, 0}, addr16 = {0, 0, 0, 0, 0, 0, 0, 0},
            addr = '\000' <repeats 15 times>}}, src_port = 0, dst_port = 0, proto_reserved1 = 0, proto_reserved2 = 0, src_su = {s = {sa_family = 0, sa_data = '\000' <repeats 13 times>}, sin = {sin_family = 0, sin_port = 0, sin_addr = {s_addr = 0},
            sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 0, sin6_port = 0, sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}},
        bind_address = 0x0, proto = 0 '\000'}}}}

Log Messages

No logs available.

[29069.581044] kamailio[12322]: segfault at 190 ip 00007f5985ad884d sp 00007ffcea744f00 error 4 in tm.so[7f5985a61000+135000]
[49907.558580] kamailio[84693]: segfault at 1a0 ip 00007fc37b75ef90 sp 00007fff954b5880 error 4 in tm.so[7fc37b742000+135000]
[86413.184058] sh (123233): drop_caches: 3
[172811.546070] sh (99955): drop_caches: 3
[201459.115194] kamailio[106801]: segfault at 190 ip 00007f3528cac84d sp 00007ffdf8d27c50 error 4 in tm.so[7f3528c35000+135000]
[259248.603313] sh (34334): drop_caches: 3
[287619.734155] kamailio[40824]: segfault at 190 ip 00007f03ce01984d sp 00007ffe869650f0 error 4 in tm.so[7f03cdfa2000+135000]
[287870.066030] kamailio[119402]: segfault at 1a0 ip 00007fbf4ff34f90 sp 00007ffd1f8cc190 error 4 in tm.so[7fbf4ff18000+135000]
[287952.567590] kamailio[120541]: segfault at 190 ip 00007f20f616684d sp 00007ffc9c760630 error 4 in tm.so[7f20f60ef000+135000]
[288012.343497] kamailio[120947]: segfault at 340 ip 00007fa90abac84d sp 00007ffe8ca01160 error 4 in tm.so[7fa90ab35000+135000]
[290128.570063] kamailio[121295]: segfault at 190 ip 00007f685674a84d sp 00007fffed6c3050 error 4 in tm.so[7f68566d3000+135000]

SIP Traffic

No SIP traffic available.

Possible Solutions

Additional Information

  • Kamailio Version - output of kamailio -v
version: kamailio 5.2.0 (x86_64/linux) 535e13
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, USE_FUTEX, 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_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: 535e13
compiled on 22:16:55 Feb 20 2019 with gcc 4.8.5
  • Operating System:
LSB Version:    :core-4.1-amd64:core-4.1-noarch:cxx-4.1-amd64:cxx-4.1-noarch:desktop-4.1-amd64:desktop-4.1-noarch:languages-4.1-amd64:languages-4.1-noarch:printing-4.1-amd64:printing-4.1-noarch
Distributor ID: CentOS
Description:    CentOS Linux release 7.6.1810 (Core)
Release:        7.6.1810
Codename:       Core
-----------------
Linux sip 3.10.0-957.1.3.el7.x86_64 #1 SMP Thu Nov 29 14:49:43 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
@miconda

This comment has been minimized.

Copy link
Member

commented Feb 28, 2019

Likely to be the same issue I hunted recently and actually I just pushed a commit for it:

No much testing so far, will do more tomorrow -- anyhow, hopefully it fixes the issue.

In what I troubleshooted, the crash happened due to a race in accessing transaction when a reply for a terminated transaction (which already had a final reply received before) came at the moment wait timer was fired for that transaction (5sec later than the final reply), which resulted in destroying the transaction by the timer process, while another process was handling the late reply.

@Fernandojdk

This comment has been minimized.

Copy link
Author

commented Feb 28, 2019

I'll apply this patch tonight and see if this is fixed tomorrow on a production server and provides a feedback about this issue.

Thanks for your fast response.

@Fernandojdk

This comment has been minimized.

Copy link
Author

commented Mar 1, 2019

Hello @miconda , i think this patch introduced a new bug on tmx module.
Now i'm getting a segfault on tmx.so:

Log

[345284.567219] kamailio[88343]: segfault at 1f4 ip 00007fa4b771f934 sp 00007ffd06a1e710 error 4 in tmx.so[7fa4b770c000+1d000]
[345332.406311] kamailio[88635]: segfault at 1f4 ip 00007fcb136e0934 sp 00007ffeda371e60 error 4 in tmx.so[7fcb136cd000+1d000]
[345488.107701] kamailio[88940]: segfault at 1f4 ip 00007f2fffba9934 sp 00007fff2bf8b7f0 error 4 in tmx.so[7f2fffb96000+1d000]
[345517.133371] kamailio[89337]: segfault at 244 ip 00007f7ae3d19934 sp 00007fff6f699350 error 4 in tmx.so[7f7ae3d06000+1d000]
[345546.632373] kamailio[89602]: segfault at 1f4 ip 00007f02d6019934 sp 00007ffe5d33ac50 error 4 in tmx.so[7f02d6006000+1d000]
[345568.432423] kamailio[89742]: segfault at 1f4 ip 00007f4e5094a934 sp 00007fffd5915930 error 4 in tmx.so[7f4e50937000+1d000]

###GDB info



(gdb) frame 0
#0  0x00007f4e5094a934 in pv_get_tm_reply_code (msg=0x7f4e2cd14cb8, param=0x7f4e55a61328, res=0x7fffd5915aa0) at t_var.c:528
528                     code = t->uac[branch].last_received;


(gdb) info locals
t = 0x7f4e2cd0d928
code = 32590
branch = 0
__FUNCTION__ = "pv_get_tm_reply_code"


(gdb) list
523                 if ( (branch=_tmx_tmb.t_get_picked_branch())<0 ) {
524                     LM_CRIT("no picked branch (%d) for a final response"
525                             " in MODE_ONFAILURE\n", branch);
526                     code = 0;
527                 } else {
528                     code = t->uac[branch].last_received;
529                 }
530                 break;
531             default:
532                 LM_INFO("unsupported route_type %d - code set to 0\n",


(gdb) bt
#0  0x00007f4e5094a934 in pv_get_tm_reply_code (msg=0x7f4e2cd14cb8, param=0x7f4e55a61328, res=0x7fffd5915aa0) at t_var.c:528
#1  0x00000000005d0874 in pv_get_spec_value (msg=0x7f4e2cd14cb8, sp=0x7f4e55a61310, value=0x7fffd5915aa0) at core/pvapi.c:1380
#2  0x0000000000582062 in lval_pvar_assign (h=0x7fffd5916340, msg=0x7f4e2cd14cb8, lv=0x7f4e55a61098, rv=0x7f4e55a61308) at core/lvalue.c:335
#3  0x0000000000582d91 in lval_assign (h=0x7fffd5916340, msg=0x7f4e2cd14cb8, lv=0x7f4e55a61098, rve=0x7f4e55a61300) at core/lvalue.c:400
#4  0x000000000059647d in do_action (h=0x7fffd5916340, a=0x7f4e55a61a30, msg=0x7f4e2cd14cb8) at core/action.c:1443
#5  0x0000000000597f6e in run_actions (h=0x7fffd5916340, a=0x7f4e55a60d68, msg=0x7f4e2cd14cb8) at core/action.c:1564
#6  0x0000000000598683 in run_top_route (a=0x7f4e55a60d68, msg=0x7f4e2cd14cb8, c=0x0) at core/action.c:1646
#7  0x00007f4e50bb877f in run_failure_handlers (t=0x7f4e2cd0d928, rpl=0xffffffffffffffff, code=408, extra_flags=96) at t_reply.c:1002
#8  0x00007f4e50bbbc55 in t_should_relay_response (Trans=0x7f4e2cd0d928, new_code=408, branch=0, should_store=0x7fffd59166fc, should_relay=0x7fffd5916700, cancel_data=0x7fffd59167b0, reply=0xffffffffffffffff) at t_reply.c:1376
#9  0x00007f4e50bbef0b in relay_reply (t=0x7f4e2cd0d928, p_msg=0xffffffffffffffff, branch=0, msg_status=408, cancel_data=0x7fffd59167b0, do_put_on_wait=0) at t_reply.c:1802
#10 0x00007f4e50c20b5b in fake_reply (t=0x7f4e2cd0d928, branch=0, code=408) at timer.c:340
#11 0x00007f4e50c20fe8 in final_response_handler (r_buf=0x7f4e2cd0db50, t=0x7f4e2cd0d928) at timer.c:506
#12 0x00007f4e50c21097 in retr_buf_handler (ticks=262070135, tl=0x7f4e2cd0db70, p=0x3e8) at timer.c:562
#13 0x00000000004a0134 in timer_list_expire (t=262070135, h=0x7f4e2c741690, slow_l=0x7f4e2c7418c8, slow_mark=0) at core/timer.c:874
#14 0x00000000004a0595 in timer_handler () at core/timer.c:939
#15 0x00000000004a0a3f in timer_main () at core/timer.c:978
#16 0x0000000000425416 in main_loop () at main.c:1693
#17 0x000000000042c078 in main (argc=9, argv=0x7fffd5916e18) at main.c:2645


(gdb) bt full
#0  0x00007f4e5094a934 in pv_get_tm_reply_code (msg=0x7f4e2cd14cb8, param=0x7f4e55a61328, res=0x7fffd5915aa0) at t_var.c:528
        t = 0x7f4e2cd0d928
        code = 32590
        branch = 0
        __FUNCTION__ = "pv_get_tm_reply_code"
#1  0x00000000005d0874 in pv_get_spec_value (msg=0x7f4e2cd14cb8, sp=0x7f4e55a61310, value=0x7fffd5915aa0) at core/pvapi.c:1380
        ret = 0
        __FUNCTION__ = "pv_get_spec_value"
#2  0x0000000000582062 in lval_pvar_assign (h=0x7fffd5916340, msg=0x7f4e2cd14cb8, lv=0x7f4e55a61098, rv=0x7f4e55a61308) at core/lvalue.c:335
        pvar = 0x7f4e55a60fb8
        pval = {rs = {s = 0x0, len = 0}, ri = 0, flags = 0}
        r_avp = 0x7fffd5916178
        avp_val = {n = 631, s = {s = 0x277 <Address 0x277 out of bounds>, len = 1490070754}, re = 0x277}
        ret = 0
        v = 110
        destroy_pval = 0
        __FUNCTION__ = "lval_pvar_assign"
#3  0x0000000000582d91 in lval_assign (h=0x7fffd5916340, msg=0x7f4e2cd14cb8, lv=0x7f4e55a61098, rve=0x7f4e55a61300) at core/lvalue.c:400
        rv = 0x7f4e55a61308
        ret = 0
        __FUNCTION__ = "lval_assign"
#4  0x000000000059647d in do_action (h=0x7fffd5916340, a=0x7f4e55a61a30, msg=0x7f4e2cd14cb8) at core/action.c:1443
        ret = -5
        v = -711892832
        dst = {send_sock = 0x3, to = {s = {sa_family = 3328, sa_data = "\261Ĥug\032\001\000\000\000\000\000\000"}, sin = {sin_family = 3328, sin_port = 50353, sin_addr = {s_addr = 442987940}, sin_zero = "\001\000\000\000\000\000\000"}, sin6 = {sin6_family = 3328, 
              sin6_port = 50353, sin6_flowinfo = 442987940, sin6_addr = {__in6_u = {__u6_addr8 = "\001\000\000\000\000\000\000\000\314\025\227,N\177\000", __u6_addr16 = {1, 0, 0, 0, 5580, 11415, 32590, 0}, __u6_addr32 = {1, 0, 748099020, 32590}}}, sin6_scope_id = 0}}, 
          id = -53100608, proto = -112 '\220', send_flags = {f = 54673, blst_imask = 0}}
        tmp = 0x130053c9b5 <Address 0x130053c9b5 out of bounds>
        new_uri = 0xffffffffffffffff <Address 0xffffffffffffffff out of bounds>
        end = 0x7c7213 "INFO"
        crt = 0x7fffd5916210 ""
        cmd = 0x7f4e2c9715b8
        len = 0
        user = 0
        uri = {user = {s = 0x0, len = -1}, passwd = {s = 0x7f4e58cdb14d <_IO_vfprintf_internal+19661> "\200\275\360\372\377\377", len = 4}, host = {s = 0x0, len = 1493518176}, port = {s = 0x278f35b100000002 <Address 0x278f35b100000002 out of bounds>, len = 0}, params = {
            s = 0x7f4e2c4a44e8 "%s: %s%s(): rtp proxy <%s> found, support for it %senabled\n", len = 11}, sip_params = {s = 0x72 <Address 0x72 out of bounds>, len = 3440}, headers = {s = 0x7f4e2c4a4523 "", len = 2}, port_no = 28453, proto = 0, type = ERROR_URI_T, 
          flags = (URI_USER_NORMALIZE | URI_SIP_USER_PHONE | unknown: 1288637520), transport = {s = 0x29a4658 "", len = 44632544}, ttl = {s = 0x0, len = 43664984}, user_param = {s = 0xfffffffe00000280 <Address 0xfffffffe00000280 out of bounds>, len = 0}, maddr = {
            s = 0x80002a6ea061 <Address 0x80002a6ea061 out of bounds>, len = 0}, method = {s = 0x3000000010 <Address 0x3000000010 out of bounds>, len = -711891552}, lr = {s = 0x7fffd59164e0 "\023r|", len = -711892544}, r2 = {s = 0x2ac3b80 "\a", len = 1434729520}, gr = {
            s = 0x7fffd5916000 "\240\071\254\002", len = 2}, transport_val = {s = 0x1 <Address 0x1 out of bounds>, len = 748099020}, ttl_val = {s = 0x7fffd5915f10 "#EJ,N\177", len = 1}, user_param_val = {s = 0x1d5916010 <Address 0x1d5916010 out of bounds>, 
            len = 748099020}, maddr_val = {s = 0x7fffd5916010 "@a\221\325\377\177", len = 1341679493}, method_val = {s = 0x602a92e10 <Address 0x602a92e10 out of bounds>, len = 748099020}, lr_val = {s = 0x2ac39a0 "\001", len = 1490575056}, r2_val = {
            s = 0x7fffd5916140 "`a\221\325\377\177", len = 1341727119}, gr_val = {s = 0x0, len = 44710301}}
        next_hop = {user = {s = 0x7fff00000000 <Address 0x7fff00000000 out of bounds>, len = 0}, passwd = {s = 0x7fffd5916247 "", len = 0}, host = {s = 0x7fffd5915e70 " ", len = 1489875277}, port = {s = 0x3000000018 <Address 0x3000000018 out of bounds>, 
            len = -711891952}, params = {s = 0x7fff00000000 <Address 0x7fff00000000 out of bounds>, len = -5}, sip_params = {s = 0xa00000000 <Address 0xa00000000 out of bounds>, len = 1490071084}, headers = {s = 0x8 <Address 0x8 out of bounds>, len = 0}, port_no = 0, 
          proto = 0, type = 32590, flags = (URI_USER_NORMALIZE | URI_SIP_USER_PHONE | unknown: 743064856), transport = {s = 0x7fffd59163d0 "", len = 1493503968}, ttl = {s = 0x7fffd59164c8 "x\360\320,N\177", len = 743064808}, user_param = {
            s = 0x2a909e0 "\270G\005YN\177", len = 1489855931}, maddr = {s = 0x7f4e58cdb14d <_IO_vfprintf_internal+19661> "\200\275\360\372\377\377", len = 0}, method = {s = 0x7f4e2c49c885 "%d:", len = 11}, lr = {
            s = 0x7f4e00000002 <Address 0x7f4e00000002 out of bounds>, len = 0}, r2 = {s = 0x7f4e58e16532 "%d]", len = 11}, gr = {s = 0x3000000007 <Address 0x3000000007 out of bounds>, len = 3440}, transport_val = {s = 0x7fffd5915f50 "\200\002", len = -711893232}, 
          ttl_val = {s = 0xb0000000a <Address 0xb0000000a out of bounds>, len = -711893276}, user_param_val = {s = 0x5c00000000 <Address 0x5c00000000 out of bounds>, len = 0}, maddr_val = {s = 0x0, len = 0}, method_val = {
            s = 0x3000000020 <Address 0x3000000020 out of bounds>, len = 0}, lr_val = {s = 0x7f4e58cdb14d <_IO_vfprintf_internal+19661> "\200\275\360\372\377\377", len = 0}, r2_val = {s = 0x3000000000 <Address 0x3000000000 out of bounds>, len = 0}, gr_val = {
            s = 0x7f4e00000000 <Address 0x7f4e00000000 out of bounds>, len = 0}}
        u = 0xb26f10 <ut_buf_int2str>
        port = 0
        dst_host = 0x7c2e00 <__FUNCTION__.6168>
        i = 15
        flags = 32590
        avp = 0x7fffd59162c0
        st = {flags = 743055302, id = 32590, name = {n = -1, s = {s = 0xffffffffffffffff <Address 0xffffffffffffffff out of bounds>, len = 0}, re = 0xffffffffffffffff}, avp = 0x7}
        sct = 0x7fffd5916140
        sjt = 0x7f4e50019820
        rve = 0x20000000
        mct = 0x62c6fa6d0
        rv = 0x7f4e58cd65bb <_IO_vfprintf_internal+315>
        rv1 = 0x4000000
        c1 = {cache_type = 3583075336, val_type = 32767, c = {avp_val = {n = 1491166516, s = {s = 0x7f4e58e16534 "]", len = -711892240}, re = 0x7f4e58e16534}, pval = {rs = {s = 0x7f4e58e16534 "]", len = -711892240}, ri = 1493503968, flags = 32590}}, 
          i2s = "\bc\221\325\377\177\000\000\061e\341XN\177\000\000\340\t\251\002\000"}
        s = {s = 0x1 <Address 0x1 out of bounds>, len = 2}
        srevp = {0x0, 0xffffffffffffffff}
        evp = {data = 0x0, rcv = 0x0, dst = 0x0}
        mod_f_params = {{type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {
            type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {
              number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, 
              string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}, {type = NOSUBTYPE, u = {number = 0, string = 0x0, str = {s = 0x0, len = 0}, data = 0x0, attr = 0x0, select = 0x0}}}
        __FUNCTION__ = "do_action"
#5  0x0000000000597f6e in run_actions (h=0x7fffd5916340, a=0x7f4e55a60d68, msg=0x7f4e2cd14cb8) at core/action.c:1564
        t = 0x7f4e55a61a30
        ret = 1
        ms = 4820621
        __FUNCTION__ = "run_actions"
#6  0x0000000000598683 in run_top_route (a=0x7f4e55a60d68, msg=0x7f4e2cd14cb8, c=0x0) at core/action.c:1646
        ctx = {rec_lev = 1, run_flags = 0, last_retcode = 1, jmp_env = {{__jmpbuf = {139974474751696, -8436678796762393242, 8155667, 90, 536870912, 67108864, -8436678796800141978, 8436736086254966118}, __mask_was_saved = 0, __saved_mask = {__val = {139973736090808, 
                  139973736093009, 10, 17179869184, 67108864, 140736776463408, 11373999, 0, 65176423608, 9341819176, 139973736090808, 1073741826, 0, 536870912, 139974474751696, 8155667}}}}}
        p = 0x7fffd5916340
        ret = 536870912
        sfbk = 0
#7  0x00007f4e50bb877f in run_failure_handlers (t=0x7f4e2cd0d928, rpl=0xffffffffffffffff, code=408, extra_flags=96) at t_reply.c:1002
        faked_req = 0x7f4e2cd14cb8
        faked_req_len = 6840
        shmem_msg = 0x7f4e2cd0f078
        on_failure = 3
        keng = 0x0
        __FUNCTION__ = "run_failure_handlers"
#8  0x00007f4e50bbbc55 in t_should_relay_response (Trans=0x7f4e2cd0d928, new_code=408, branch=0, should_store=0x7fffd59166fc, should_relay=0x7fffd5916700, cancel_data=0x7fffd59167b0, reply=0xffffffffffffffff) at t_reply.c:1376
        branch_cnt = 1
        picked_code = 408
        new_branch = 582
        inv_through = 0
        extra_flags = 96
        i = 32590
        replies_dropped = 0
        __FUNCTION__ = "t_should_relay_response"
#9  0x00007f4e50bbef0b in relay_reply (t=0x7f4e2cd0d928, p_msg=0xffffffffffffffff, branch=0, msg_status=408, cancel_data=0x7fffd59167b0, do_put_on_wait=0) at t_reply.c:1802
        relay = 895
        save_clone = 0
        buf = 0x0
        res_len = 0
        relayed_code = 0
        relayed_msg = 0x0
        reply_bak = 0x0
        bm = {to_tag_val = {s = 0x7fffd5916710 "", len = 10879832}}
        totag_retr = 0
        reply_status = RPS_ERROR
        uas_rb = 0x0
        to_tag = 0xffffffffffffffff
        reason = {s = 0x7fffd5916800 "", len = 1354191177}
        onsend_params = {req = 0x1658, rpl = 0x7f4e2c6fb6c8, param = 0x7fffd59168f0, code = 1490575056, flags = 1, branch = 0, t_rbuf = 0x7fffd59166d0, dst = 0x69621b <qm_shm_gunlock+27>, send_buf = {s = 0x20000000 <Address 0x20000000 out of bounds>, len = 745283584}}
        ip = {af = 3583076016, len = 1, u = {addrl = {139973729695432, 140736776464048}, addr32 = {745518792, 32590, 3583076016, 32767}, addr16 = {46792, 11375, 32590, 0, 26288, 54673, 32767, 0}, addr = "ȶo,N\177\000\000\260f\221\325\377\177\000"}}
        __FUNCTION__ = "relay_reply"
#10 0x00007f4e50c20b5b in fake_reply (t=0x7f4e2cd0d928, branch=0, code=408) at timer.c:340
        cancel_data = {cancel_bitmap = 0, reason = {cause = 0, u = {text = {s = 0x0, len = 751884584}, e2e_cancel = 0x0, packed_hdrs = {s = 0x0, len = 751884584}}}}
        do_cancel_branch = 0
        reply_status = 89742
#11 0x00007f4e50c20fe8 in final_response_handler (r_buf=0x7f4e2cd0db50, t=0x7f4e2cd0d928) at timer.c:506
        silent = 0
        branch_ret = 0
        prev_branch = 67108864
        now = 536870912
#12 0x00007f4e50c21097 in retr_buf_handler (ticks=262070135, tl=0x7f4e2cd0db70, p=0x3e8) at timer.c:562
        rbuf = 0x7f4e2cd0db50
        fr_remainder = 3605054132
        retr_remainder = 32590
        retr_interval = 745526704
        new_retr_interval_ms = 4681055710
        crt_retr_interval_ms = 14800566388280090447
        t = 0x7f4e2cd0d928
        __FUNCTION__ = "retr_buf_handler"
#13 0x00000000004a0134 in timer_list_expire (t=262070135, h=0x7f4e2c741690, slow_l=0x7f4e2c7418c8, slow_mark=0) at core/timer.c:874
        tl = 0x7f4e2cd0db70
        ret = 0
#14 0x00000000004a0595 in timer_handler () at core/timer.c:939
        saved_ticks = 262070135
        run_slow_timer = 0
        i = 0
        __FUNCTION__ = "timer_handler"
#15 0x00000000004a0a3f in timer_main () at core/timer.c:978
No locals.
#16 0x0000000000425416 in main_loop () at main.c:1693
        i = 32
        pid = 0
        si = 0x0
        si_desc = "udp receiver child=31 sock=177.53.143.38:5080\000\000\000`j\221\325\377\177\000\000\320^\330XN\177\000\000\060m\221\325\377\177\000\000\023r|\000\000\000\000\000Z\000\000\000\000\000\000\000\000\000\000 \000\000\000\000\000\000\000\004\000\000\000\000__\330XN\177\000\000\200bx\000\000\000\000\000@z\216UN\177\000"
        nrprocs = 32
        woneinit = 1
        __FUNCTION__ = "main_loop"
#17 0x000000000042c078 in main (argc=9, argv=0x7fffd5916e18) at main.c:2645
        cfg_stream = 0x2851010
        c = -1
        r = 0
        tmp = 0x7fffd5917f66 ""
        tmp_len = 0
        port = 0
        proto = 0
        options = 0x768aa0 ":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 = 4016190000
        rfd = 4
        debug_save = 0
        debug_flag = 0
        dont_fork_cnt = 0
        n_lst = 0x0
        p = 0x0
        st = {st_dev = 20, st_ino = 32456, st_nlink = 2, st_mode = 16832, st_uid = 0, st_gid = 2, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1551072083, tv_nsec = 812037328}, st_mtim = {tv_sec = 1551417587, 
            tv_nsec = 481360795}, st_ctim = {tv_sec = 1551417587, tv_nsec = 481360795}, __unused = {0, 0, 0}}
        __FUNCTION__ = "main"
@miconda

This comment has been minimized.

Copy link
Member

commented Mar 1, 2019

Can you get from gdb the output for:

frame 0
p *t

Does this crash happen often?

UPDATE: the backtrace shows that the crash happened during a retransmission timeout handling. I tried to reproduce locally with sipp, with lots of retransmission timeouts, but couldn't get any crash. Have you backported that patch or have you used the master branch?

@Fernandojdk

This comment has been minimized.

Copy link
Author

commented Mar 1, 2019

After applying the patch i started to get this new crash, and with only one transaction the crash was already occurring. When I removed the changes made by #1875, the segfault on tmx stopped happening again.

(gdb) frame 0
#0  0x00007f4e5094a934 in pv_get_tm_reply_code (msg=0x7f4e2cd14cb8, param=0x7f4e55a61328, res=0x7fffd5915aa0) at t_var.c:528
528                                             code = t->uac[branch].last_received;
(gdb) p *t
$2 = {next_c = 0x7f4e2c7ae270, prev_c = 0x7f4e2cd11d88, hash_index = 12317, label = 1021694037, flags = 329, nr_of_outgoings = 1, fcount = 0, ref_count = {val = 1}, from = {
    s = 0x7f4e2cd0f831 "From: \"82065\" <sip:16994660926@X.X.X.132>;tag=as2d23aaa7\r\nTo: <sip:777045516992546314@X.X.X.38>\r\nContact: <sip:16994660926@X.X.X.132:5060>\r\nCall-ID: 7b434108222cd5ef0c4b0b4b4e8ddad2@200"..., len = 63}, callid = {
    s = 0x7f4e2cd0f8cc "Call-ID: 7b434108222cd5ef0c4b0b4b4e8ddad2@X.X.X.132:5060\r\nCSeq: 102 INVITE\r\nUser-Agent: Asterisk PBX 11.22.0\r\nDate: Fri, 01 Mar 2019 05:20:01 GMT\r\nAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER,"..., len = 63}, cseq_n = {
    s = 0x7f4e2cd0f90b "CSeq: 102 INVITE\r\nUser-Agent: Asterisk PBX 11.22.0\r\nDate: Fri, 01 Mar 2019 05:20:01 GMT\r\nAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE\r\nSupported: replaces"..., len = 9}, to = {
    s = 0x7f4e2cd0f870 "To: <sip:777045516992546314@X.X.X.38>\r\nContact: <sip:16994660926@X.X.X.132:5060>\r\nCall-ID: 7b434108222cd5ef0c4b0b4b4e8ddad2@X.X.X.132:5060\r\nCSeq: 102 INVITE\r\nUser-Agent: Asterisk PBX 11"..., len = 44}, method = {
    s = 0x7f4e2cd0f7a0 "INVITE sip:777045516992546314@X.X.X.38 SIP/2.0\r\nVia: SIP/2.0/UDP X.X.X.132:5060;TH=div;branch=z9hG4bK560e0ea1;rport\r\nMax-Forwards: 69\r\nFrom: \"82065\" <sip:16994660926@X.X.X.132>;tag=as2d"..., len = 6}, tmcb_hl = {
    first = 0x7f4e2cd113a8, reg_types = 1048738}, wait_timer = {next = 0x0, prev = 0x0, expire = 0, initial_timeout = 0, data = 0x7f4e2cd0d928, f = 0x7f4e50c2151b <timer_fixup+1251>, flags = 1, slow_idx = 0}, uas = {request = 0x0, end_request = 0x7f4e2cd0f078 "\001",
    response = {rbtype = 1120, flags = 11473, t_active = 32590, branch = 0, buffer_len = 100, buffer = 0x174 <Address 0x174 out of bounds>, my_T = 0x7f4e2cd104c8, timer = {next = 0x7f4e2cd0d928, prev = 0x0, expire = 0, initial_timeout = 0, data = 0x0, f = 0x0,
        flags = 1354895338, slow_idx = 32590}, dst = {send_sock = 0x0, to = {s = {sa_family = 6952, sa_data = "\322TN\177\000\000\002\000\023\304\310b\201\204"}, sin = {sin_family = 6952, sin_port = 21714, sin_addr = {s_addr = 32590},
            sin_zero = "\002\000\023\304\310b\201\204"}, sin6 = {sin6_family = 6952, sin6_port = 21714, sin6_flowinfo = 32590, sin6_addr = {__in6_u = {__u6_addr8 = "\002\000\023\304\310b\201\204\000\000\000\000\000\000\000", __u6_addr16 = {2, 50195, 25288, 33921, 0, 0,
                  0, 0}, __u6_addr32 = {3289579522, 2223071944, 0, 0}}}, sin6_scope_id = 0}}, id = 0, proto = 0 '\000', send_flags = {f = 0, blst_imask = 0}}, retr_expire = 1, fr_expire = 0}, local_totag = {s = 0x0, len = 751895980}, cancel_reas = 0x0, status = 0},
  uac = 0x64, async_backup = {backup_route = 751885120, backup_branch = 32590, blind_uac = 0, ruri_new = 0}, fwded_totags = 0x0, uri_avps_from = 0x0, uri_avps_to = 0x7f4e2cd10ff8, user_avps_from = 0x0, user_avps_to = 0x0, domain_avps_from = 0x0, domain_avps_to = 0x0,
  xavps_list = 0x0, reply_mutex = {val = 0}, reply_locker_pid = {val = 0}, reply_rec_lock_level = 1, fr_timeout = 89742, fr_inv_timeout = 0, rt_t1_timeout_ms = 32, rt_t2_timeout_ms = 0, end_of_life = 96, relayed_reply_branch = 500, on_failure = 4000,
  on_branch_failure = 59989, on_reply = 3998, on_branch = 65534, on_branch_delayed = 0, md5 = 0x7f4e2cd0db18 ""}
@miconda

This comment has been minimized.

Copy link
Member

commented Mar 1, 2019

Would you be able to try with latest master branch on a testbed or so?

The uac field inside the has an invalid value:

uac = 0x64

That is not something I touched, so it looks like an invalid write somewhere, might not be related or could be just because of other changes done meanwhile in master branch and not part of the backport.

@Fernandojdk

This comment has been minimized.

Copy link
Author

commented Mar 1, 2019

Ok, i'll try with master branch.

@miconda

This comment has been minimized.

Copy link
Member

commented Mar 1, 2019

The person that reported a similar crash like your initial post confirmed that first tests with master branch do not crash kamailio anymore. Before, the crash could be reproduced after running specific stress tests for rather short time.

However, your second crash could be due to your config and either not related to the previous one and its fix, or a side effect of the fix specific to your config.

@Fernandojdk

This comment has been minimized.

Copy link
Author

commented Mar 1, 2019

I compiled the master branch and i'm waiting to activate on my environment.
I'll report a feedback soon.

@miconda

This comment has been minimized.

Copy link
Member

commented Mar 7, 2019

Closing this one, the last backtrace doesn't seem related to the initial issue. If you get it again, better open a new issue to track that down.

@miconda miconda closed this Mar 7, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.