Re: [SR-Users] rare crash at kamailio 5.0.1

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 _______________________________________________ Kamailio (SER) - Users Mailing List sr-users(a)lists.kamailio.org https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users