rare crash at kamailio 5.0.1 - sr-users

30 Mar 2018


      Hello all
last March 26th we experienced a crash on a 5.0.1 kamailio server and a core was generated.
Seems that the call involved in the core generated was doing several retransmisions of a request (expected) and when it finally forwarded the request upstream, seems fter receiving a 481 from a-side, it crashed.
here you have the backtrace
<154>Mar 26 19:54:03 mad-proxy-inout-1 /usr/local/kamailio/sbin/kamailio[24992]: : <core> [core/mem/q_malloc.c:469]: qm_free(): BUG: qm_free: bad pointer 0x7f247acb5878 (out of memory block!) called from tm: h_table.c: free_cell_helper(187) - aborting
(gdb) bt
#0 0x00000036e8a32925 in raise () from /lib64/libc.so.6
#1 0x00000036e8a34105 in abort () from /lib64/libc.so.6
#2 0x0000000000654c24 in qm_free (qmp=0x7f23b9cba000, p=0x7f247acb5878, file=0x7f2479e3cd86 "tm: h_table.c", func=0x7f2479e3d070 "free_cell_helper", line=187, 
mname=0x7f2479e3c780 "tm") at core/mem/q_malloc.c:471
#3 0x00007f2479d6bf16 in free_cell_helper (dead_cell=0x7f23c54fea50, silent=0, fname=0x7f2479e4da80 "timer.c", fline=651) at h_table.c:187
#4 0x00007f2479db8148 in wait_handler (ti=1503818844, wait_tl=0x7f23c54fead0, data=0x7f23c54fea50) at timer.c:651
#5 0x0000000000629578 in timer_list_expire (t=1503818844, h=0x7f23b9d38dc0, slow_l=0x7f23b9d3b0c8, slow_mark=43533) at core/timer.c:874
#6 0x00000000006299d4 in timer_handler () at core/timer.c:939
#7 0x0000000000629e73 in timer_main () at core/timer.c:978
#8 0x0000000000422d4e in main_loop () at main.c:1690
#9 0x0000000000429732 in main (argc=13, argv=0x7fff2b9f8088) at main.c:2639
(gdb) frame 4
#4 0x00007f2479db8148 in wait_handler (ti=1503818844, wait_tl=0x7f23c54fead0, data=0x7f23c54fea50) at timer.c:651
651 UNREF_FREE(p_cell);
(gdb) info locals
p_cell = 0x7f23c54fea50
ret = 1
(gdb) p *p_cell
$1 = {next_c = 0x0, prev_c = 0x0, hash_index = 28196, label = 341555146, flags = 4132, nr_of_outgoings = 2, ref_count = {val = 0}, from = {
s = 0x7f23c87c79ed "From: sip:932687220@100.100.100.177;user=phone;noa=national;tag=50aa4a46-co11146-INS002\r\nCall-ID: b8997821-2814-46d3-b8f7-cf690f50f640\r\nCSeq: 1114601 BYE\r\nUser-Agent: ENSR3.0.67.10-IS2-RMRG1119-RG2040"..., len = 89}, callid = {
s = 0x7f23c87c7a46 "Call-ID: b8997821-2814-46d3-b8f7-cf690f50f640\r\nCSeq: 1114601 BYE\r\nUser-Agent: ENSR3.0.67.10-IS2-RMRG1119-RG2040-CPI1-CPO2612\r\nContent-Length: 0\r\n\r\n", len = 47}, cseq_n = {
s = 0x7f23c87c7a75 "CSeq: 1114601 BYE\r\nUser-Agent: ENSR3.0.67.10-IS2-RMRG1119-RG2040-CPI1-CPO2612\r\nContent-Length: 0\r\n\r\n", len = 13}, to = {
s = 0x7f23c87c799e "To: "34676893111"sip:34676893111@100.100.100.134;user=phone;tag=64jNUpSZK8mSp\r\nFrom: sip:932687220@100.100.100.177;user=phone;noa=national;tag=50aa4a46-co11146-INS002\r\nCall-ID: b8997821-2814-46d3-b8f7"..., len = 79}, method = {
s = 0x7f23c87c78c8 "BYE sip:34676893111@100.100.100.134:5080 SIP/2.0\r\nVia: SIP/2.0/UDP 200.200.200.78:5060;branch=z9hG4bK2d5c0cb4e11bb1503BYE50aa466c2b8a\r\nMax-Forwards: 34\r\nRoute: <sip:100.100.100.177;lr;ftag=64jNUpSZK8mSp;d"..., len = 3}, tmcb_hl = {first = 0x7f23bd9f7818, reg_types = 131714}, wait_timer = {
next = 0x0, prev = 0x0, expire = 1503818844, initial_timeout = 80, data = 0x7f23c54fea50, f = 0x7f2479db8097 <wait_handler>, flags = 513, slow_idx = 0}, 
uas = {request = 0x7f23c87c71d8, end_request = 0x7f23c87c8288 "\300\300\300\300", response = {activ_type = 481, flags = 128, t_active = 0 '\000', branch = 0, 
buffer_len = 526, 
buffer = 0x7f23bef07b18 "SIP/2.0 481 Call Does Not Exist\r\nVia: SIP/2.0/UDP 200.200.200.78:5060;branch=z9hG4bK2d5c0cb4e11bb1503BYE50aa466c2b8a\r\nFrom: sip:932687220@100.100.100.177;user=phone;noa=national;tag=50aa4a46-co11146-I"..., my_T = 0x7f23c54fea50, timer = {next = 0x0, prev = 0x0, expire = 0, 
initial_timeout = 0, data = 0x0, f = 0x7f2479db7b4b <retr_buf_handler>, flags = 0, slow_idx = 0}, dst = {send_sock = 0x7f247a95be78, to = {s = {
sa_family = 2, sa_data = "\023\304\325\300\313N\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 50195, sin_addr = {
s_addr = 1321976021}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 50195, sin6_flowinfo = 1321976021, 
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 '\000', blst_imask = 0 '\000'}}, retr_expire = 0, fr_expire = 0}, local_totag = {
s = 0x0, len = 0}, cancel_reas = 0x0, status = 481}, uac = 0x7f23c54fec58, async_backup = {backup_route = 1, backup_branch = 4294967295, blind_uac = 0, 
ruri_new = 1}, fwded_totags = 0x0, uri_avps_from = 0x0, 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 = 480, 
fr_inv_timeout = 1920, rt_t1_timeout_ms = 650, rt_t2_timeout_ms = 4000, end_of_life = 1503819200, relayed_reply_branch = 1, on_failure = 0, 
on_branch_failure = 0, on_reply = 0, on_branch = 0, on_branch_delayed = 0, md5 = 0x7f23c54fea50 ""}
(gdb) frame 3
#3 0x00007f2479d6bf16 in free_cell_helper (dead_cell=0x7f23c54fea50, silent=0, fname=0x7f2479e4da80 "timer.c", fline=651) at h_table.c:187
187 sip_msg_free_unsafe(rpl);
(gdb) info locals
b = 0x0
i = 1
rpl = 0x7f247acb4fc0
tt = 0x0
foo = 0x7f23b9e2bd90
cbs = 0x0
cbs_tmp = 0x7f23c60c16b0
__FUNCTION__ = "free_cell_helper"
(gdb) p *rpl
$3 = {id = 2060145040, pid = 32548, tval = {tv_sec = 72, tv_usec = 139794652378712}, fwd_send_flags = {f = 1 '\001', blst_imask = 0 '\000'}, rpl_send_flags = {
f = 0 '\000', blst_imask = 0 '\000'}, first_line = {type = -347, flags = 30263, len = 32548, u = {request = {method = {s = 0x2 <Address 0x2 out of bounds>, 
len = 1983381159}, uri = {s = 0x5 <Address 0x5 out of bounds>, len = 2}, version = {s = 0x2b <Address 0x2b out of bounds>, len = 2057435688}, 
method_value = 0}, reply = {version = {s = 0x2 <Address 0x2 out of bounds>, len = 1983381159}, status = {s = 0x5 <Address 0x5 out of bounds>, len = 2}, 
reason = {s = 0x2b <Address 0x2b out of bounds>, len = 2057435688}, statuscode = 0}}}, via1 = 0x0, via2 = 0x7f247acb5038, headers = 0x7fff2b9f3e50, 
last_header = 0x4, parsed_flag = 139794576763810, h_via1 = 0x1, h_via2 = 0x7f247616eba0, callid = 0x1, to = 0x270000000b, cseq = 0x1, from = 0x7f247aa1fa28, 
contact = 0x7f247acb5258, maxforwards = 0x7f247acb54d8, route = 0x0, record_route = 0x7fff2b9f3e50, content_type = 0x7f247acb5318, content_length = 0x0, 
authorization = 0x0, expires = 0x0, proxy_auth = 0x0, supported = 0x0, require = 0x0, proxy_require = 0x0, unsupported = 0x7f247acb5258, allow = 0x0, 
event = 0x7f247acb53d8, accept = 0x0, accept_language = 0x0, organization = 0x0, priority = 0x0, subject = 0x0, user_agent = 0x0, server = 0x0, 
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 = 0x7f247a98b6d0, privacy = 0x0, min_expires = 0x0, body = 0x7f247acb5258, 
eoh = 0x7fff2b9f3e50 "@f\313z$\177", unparsed = 0x0, 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 = 3233857728, len = 0, u = {addrl = {2882400237, 0}, addr32 = {2882400237, 0, 0, 0}, 
addr16 = {61421, 43981, 0, 0, 0, 0, 0, 0}, addr = "\355\357ͫ", '\000' <repeats 11 times>}}, src_port = 0, dst_port = 0, proto_reserved1 = 0, 
proto_reserved2 = 536, src_su = {s = {sa_family = 0, sa_data = "\000\000 \266\230z$\177\000\000\030\002\000"}, sin = {sin_family = 0, sin_port = 0, 
sin_addr = {s_addr = 2056828448}, sin_zero = "$\177\000\000\030\002\000"}, sin6 = {sin6_family = 0, sin6_port = 0, sin6_flowinfo = 2056828448, 
sin6_addr = {__in6_u = {__u6_addr8 = "$\177\000\000\030\002\000\000\000\000\000\000\210T\313z", __u6_addr16 = {32548, 0, 536, 0, 0, 0, 21640, 31435}, 
__u6_addr32 = {32548, 536, 0, 2060145800}}}, sin6_scope_id = 32548}}, bind_address = 0x7f247616ebb0, proto = 32 ' '}, 
buf = 0x7f247616eba6 "rtpengine", len = 139, new_uri = {s = 0xf0f0f0f0 <Address 0xf0f0f0f0 out of bounds>, len = 2060145720}, dst_uri = {
s = 0x20 <Address 0x20 out of bounds>, len = 2060144576}, parsed_uri_ok = 1, parsed_uri = {user = {
s = 0x7f247637fead "7:packetsi32e5:bytesi1896e6:errorsi0eeee5:flagsl11:initialized4:send4:recveeeee6:totalsd3:RTPd7:packetsi4951e5:bytesi158432e6:errorsi0ee4:RTCPd7:packetsi32e5:bytesi1896e6:errorsi0eee6:result2:oke", len = 2}, passwd = {
s = 0x7f247637feaf "packetsi32e5:bytesi1896e6:errorsi0eeee5:flagsl11:initialized4:send4:recveeeee6:totalsd3:RTPd7:packetsi4951e5:bytesi158432e6:errorsi0ee4:RTCPd7:packetsi32e5:bytesi1896e6:errorsi0eee6:result2:oke", len = 7}, host = {s = 0x900000002 <Address 0x900000002 out of bounds>, len = 1}, port = {
s = 0x7f247acb5038 "\004", len = 0}, params = {s = 0x0, len = 2060145336}, sip_params = {s = 0x7fff2b9f3e50 "@f\313z$\177", len = 2}, headers = {
s = 0x7f247637feb6 "i32e5:bytesi1896e6:errorsi0eeee5:flagsl11:initialized4:send4:recveeeee6:totalsd3:RTPd7:packetsi4951e5:bytesi158432e6:errorsi0ee4:RTCPd7:packetsi32e5:bytesi1896e6:errorsi0eee6:result2:oke", len = 4}, port_no = 0, proto = 0, type = ERROR_URI_T, flags = 0, transport = {
s = 0x400000001 <Address 0x400000001 out of bounds>, len = 32}, ttl = {s = 0x7f247acb5038 "\004", len = 0}, user_param = {s = 0x0, len = 2060145432}, 
maddr = {s = 0x7fff2b9f3e50 "@f\313z$\177", len = 1}, method = {
s = 0x7f247637feba "5:bytesi1896e6:errorsi0eeee5:flagsl11:initialized4:send4:recveeeee6:totalsd3:RTPd7:packetsi4951e5:bytesi158432e6:errorsi0ee4:RTCPd7:packetsi32e5:bytesi1896e6:errorsi0eee6:result2:oke", len = 2}, lr = {
s = 0x7f247637febc "bytesi1896e6:errorsi0eeee5:flagsl11:initialized4:send4:recveeeee6:totalsd3:RTPd7:packetsi4951e5:bytesi158432e6:errorsi0ee4:RTCPd7:packetsi32e5:bytesi1896e6:errorsi0eee6:result2:oke", len = 5}, r2 = {s = 0x700000002 <Address 0x700000002 out of bounds>, len = 1522079939}, gr = {
s = 0x7f247acb5038 "\004", len = 0}, transport_val = {s = 0x0, len = 2060145528}, ttl_val = {s = 0x7fff2b9f3e50 "@f\313z$\177", len = 2}, 
user_param_val = {
s = 0x7f247637fec1 "i1896e6:errorsi0eeee5:flagsl11:initialized4:send4:recveeeee6:totalsd3:RTPd7:packetsi4951e5:bytesi158432e6:errorsi0ee4:RTCPd7:packetsi32e5:bytesi1896e6:errorsi0eee6:result2:oke", len = 6}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x600000001 <Address 0x600000001 out of bounds>, 
len = 1896}, lr_val = {s = 0x7f247acb5038 "\004", len = 0}, r2_val = {s = 0x0, len = 2060145624}, gr_val = {s = 0x7fff2b9f3e50 "@f\313z$\177", len = 1}}, 
parsed_orig_ruri_ok = 1983381191, parsed_orig_ruri = {user = {s = 0x2 <Address 0x2 out of bounds>, len = 1983381193}, passwd = {
s = 0x6 <Address 0x6 out of bounds>, len = 2}, host = {s = 0x0, len = 2060144696}, port = {s = 0x0, len = 0}, params = {s = 0x7f247acb54d8 "\002", 
---Type <return> to continue, or q <return> to quit--- 
len = 731856464}, sip_params = {s = 0x0, len = 0}, headers = {s = 0x0, len = 0}, port_no = 49344, proto = 49344, type = ERROR_URI_T, flags = 2882400237, 
transport = {s = 0x0, len = 0}, ttl = {s = 0x218 <Address 0x218 out of bounds>, len = 2060144520}, user_param = {s = 0x218 <Address 0x218 out of bounds>, 
len = 2060146440}, maddr = {s = 0x7f247616ebb0 "rtpengine: bencode.c", len = 1981214752}, method = {s = 0x7f247616eba6 "rtpengine", len = 139}, lr = {
s = 0xf0f0f0f0 <Address 0xf0f0f0f0 out of bounds>, len = 2060146360}, r2 = {s = 0x20 <Address 0x20 out of bounds>, len = 2060145216}, gr = {
s = 0x2 <Address 0x2 out of bounds>, len = 1983381199}, transport_val = {s = 0x3 <Address 0x3 out of bounds>, len = 0}, ttl_val = {s = 0x0, len = 1}, 
user_param_val = {s = 0x0, len = 2060144696}, maddr_val = {s = 0x0, len = 0}, method_val = {s = 0x0, len = 731856464}, lr_val = {
s = 0x1 <Address 0x1 out of bounds>, len = 1983381205}, r2_val = {s = 0x2 <Address 0x2 out of bounds>, len = 1983381207}, gr_val = {
s = 0x5 <Address 0x5 out of bounds>, len = 2}}, add_rm = 0x7f247acb5878, body_lumps = 0x7f247aa43300, reply_lump = 0x0, 
add_to_branch_s = "\000\000\000\000\000\000\000\000\230U\313z$\177\000\000P>\237+\377\177\000\000\003\000\000\000\000\000\000\000\244\353\026v$\177\000\000\001\000\000\000\000\000\000\000\240\353\026v$\177\000\000\001", add_to_branch_len = 0, hash_index = 8, msg_flags = 28, flags = 2060162240, set_global_address = {
s = 0x7f247aa43300 "\004", len = 2060146168}, set_global_port = {s = 0x7f247acb5758 "\001", len = 0}, force_send_socket = 0x7fff2b9f3e50, path_vec = {
s = 0x1 <Address 0x1 out of bounds>, len = 1983381213}, instance = {s = 0x3 <Address 0x3 out of bounds>, len = 1983381216}, reg_id = 11, ruid = {
s = 0xe00000002 <Address 0xe00000002 out of bounds>, len = 0}, location_ua = {s = 0x7f247acb5598 "\003", len = 0}, ldv = {flow = {decoded = 0, rcv = {
src_ip = {af = 2060146264, len = 32548, u = {addrl = {140733925244496, 30064771073}, addr32 = {731856464, 32767, 1, 7}, addr16 = {15952, 11167, 32767, 
0, 1, 0, 7, 0}, addr = "P>\237+\377\177\000\000\001\000\000\000\a\000\000"}}, dst_ip = {af = 1983381227, len = 32548, u = {addrl = {2, 
139794578931437}, addr32 = {2, 0, 1983381229, 32548}, addr16 = {2, 0, 0, 0, 65261, 30263, 32548, 0}, 
addr = "\002\000\000\000\000\000\000\000\355\376\067v$\177\000"}}, src_port = 4, dst_port = 0, proto_reserved1 = 0, proto_reserved2 = 2, src_su = {
s = {sa_family = 6, sa_data = "\000\000P>\237+\377\177\000\000\230U\313z"}, sin = {sin_family = 6, sin_port = 0, sin_addr = {s_addr = 731856464}, 
sin_zero = "\377\177\000\000\230U\313z"}, sin6 = {sin6_family = 6, sin6_port = 0, sin6_flowinfo = 731856464, sin6_addr = {__in6_u = {
__u6_addr8 = "\377\177\000\000\230U\313z$\177\000\000\000\000\000", __u6_addr16 = {32767, 0, 21912, 31435, 32548, 0, 0, 0}, __u6_addr32 = {
32767, 2060146072, 32548, 0}}}, sin6_scope_id = 0}}, bind_address = 0x0, proto = 88 'X'}}}}
(gdb)
(gdb) bt full
#0 0x00000036e8a32925 in raise () from /lib64/libc.so.6
No symbol table info available.
#1 0x00000036e8a34105 in abort () from /lib64/libc.so.6
No symbol table info available.
#2 0x0000000000654c24 in qm_free (qmp=0x7f23b9cba000, p=0x7f247acb5878, file=0x7f2479e3cd86 "tm: h_table.c", func=0x7f2479e3d070 "free_cell_helper", line=187, 
mname=0x7f2479e3c780 "tm") at core/mem/q_malloc.c:471
qm = 0x7f23b9cba000
f = 0x7f23bc87a2c8
size = 528
next = 0x400
prev = 0x7fff2b9f7920
__FUNCTION__ = "qm_free"
#3 0x00007f2479d6bf16 in free_cell_helper (dead_cell=0x7f23c54fea50, silent=0, fname=0x7f2479e4da80 "timer.c", fline=651) at h_table.c:187
b = 0x0
i = 1
rpl = 0x7f247acb4fc0
tt = 0x0
foo = 0x7f23b9e2bd90
cbs = 0x0
cbs_tmp = 0x7f23c60c16b0
__FUNCTION__ = "free_cell_helper"
#4 0x00007f2479db8148 in wait_handler (ti=1503818844, wait_tl=0x7f23c54fead0, data=0x7f23c54fea50) at timer.c:651
p_cell = 0x7f23c54fea50
ret = 1
#5 0x0000000000629578 in timer_list_expire (t=1503818844, h=0x7f23b9d38dc0, slow_l=0x7f23b9d3b0c8, slow_mark=43533) at core/timer.c:874
tl = 0x7f23c54fead0
ret = 0
#6 0x00000000006299d4 in timer_handler () at core/timer.c:939
saved_ticks = 1503818844
run_slow_timer = 0
i = 525
__FUNCTION__ = "timer_handler"
#7 0x0000000000629e73 in timer_main () at core/timer.c:978
No locals.
#8 0x0000000000422d4e in main_loop () at main.c:1690
i = 1
pid = 0
si = 0x0
si_desc = "udp receiver child=0 sock=100.100.100.169:5060", '\000' <repeats 16 times>, "\001\000\000\000\340|\237+\377\177\000\000W\327e\000\000\000\000\000\200\335u\000\000\000\000\000\250\065\313zo\000\000\000\316\357u\000\000\000\000\000\205\335u\000\000\000\000\000\004\000\000\000\000\000\000\000\000\240˹#\177---Type <return> to continue, or q <return> to quit--- 
\000"
nrprocs = 1
woneinit = 1
__FUNCTION__ = "main_loop"
#9 0x0000000000429732 in main (argc=13, argv=0x7fff2b9f8088) at main.c:2639
cfg_stream = 0x1f8f010
c = -1
r = 0
tmp = 0x7fff2b9f8742 ""
tmp_len = 54
port = -398323320
proto = 54
options = 0x732e78 ":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 = 3083103015
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x36e8a90687
p = 0x7fff2b9f7f88 "\200\200\237+\377\177"
st = {st_dev = 2307, st_ino = 9183277, st_nlink = 3, st_mode = 16832, st_uid = 522, st_gid = 501, __pad0 = 0, st_rdev = 0, st_size = 4096, 
st_blksize = 4096, st_blocks = 8, st_atim = {tv_sec = 1496231473, tv_nsec = 0}, st_mtim = {tv_sec = 1520405673, tv_nsec = 0}, st_ctim = {
tv_sec = 1520405673, tv_nsec = 0}, __unused = {0, 0, 0}}
__FUNCTION__ = "main"
(gdb)
i dont know if you can help us to know the reason of the crash, because the call trace seemed quite normal, and we don't know if the cause was from the rtpengine responses of the bye requests, or was caused by the request retransmisions, which would be rare because we sometimes have those type of calls.
thanks a lot and regards
david