<!-- Kamailio Project uses GitHub Issues only for bugs in the code or feature requests. Please use this template only for bug reports.
If you have questions about using Kamailio or related to its configuration file, ask on sr-users mailing list:
* http://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
If you have questions about developing extensions to Kamailio or its existing C code, ask on sr-dev mailing list:
* http://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-dev
Please try to fill this template as much as possible for any issue. It helps the developers to troubleshoot the issue.
If there is no content to be filled in a section, the entire section can be removed.
You can delete the comments from the template sections when filling.
You can delete next line and everything above before submitting (it is a comment). -->
### 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. We simply restarted the 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
<!-- If you got a core dump, use gdb to extract troubleshooting data - full backtrace, local variables and the list of the code at the issue location.
gdb /path/to/kamailio /path/to/corefile bt full info locals list
If you are familiar with gdb, feel free to attach more of what you consider to be relevant. -->
``` (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
<!-- Check the syslog file and if there are relevant log messages printed by Kamailio, add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site). -->
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
<!-- If the issue is exposed by processing specific SIP messages, grab them with ngrep or save in a pcap file, then add them next, or attach to issue, or provide a link to download them (e.g., to a pastebin site). --> No SIP traffic available. ``` (paste your sip traffic here) ```
### Possible Solutions
<!-- If you found a solution or workaround for the issue, describe it. Ideally, provide a pull request with a fix. -->
### 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**:
<!-- Details about the operating system, the type: Linux (e.g.,: Debian 8.4, Ubuntu 16.04, CentOS 7.1, ...), MacOS, xBSD, Solaris, ...; Kernel details (output of `uname -a`) -->
``` 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 ```
Likely to be the same issue I hunted recently and actually I just pushed a commit for it:
* 814d5cc1f4f5b1e4b95737108dffc1e7d7bd566f
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.
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.
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" ```
Can you get from gdb the output for:
``` frame 0 p *t ```
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 ""} ```
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.
Ok, i'll try with master branch.
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.
I compiled the master branch and i'm waiting to activate on my environment. I'll report a feedback soon.
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.
Closed #1875.
-
Daniel-Constantin Mierla -
Fernando S. Santos