We have a crash in kamailio 4.4.4 after t_next_contacts() has been called from failure route, if at this very moment when kamailio is preparing new INVITE the caller sends a cancel.
#0 build_res_buf_from_sip_req (code=3186024432, code@entry=487, text=0x25, new_tag=0x7f8dcf5fb2b0 <tm_tag>, msg=0x7f8dbde6cf78, returned_len=0xb7, bmark=0x4) at msg_translator.c:2395 #1 0x00007f8dcf35f7b2 in _reply (trans=0x7f8dbde70960, p_msg=0x7f8dbde6cf78, code=487, text=<optimized out>, lock=1) at t_reply.c:712 #2 0x00007f8dcf3b5e8b in e2e_cancel (cancel_msg=0x7f8dbde6dff0, cancel_msg@entry=0x7f8dd26bb750, t_cancel=0x25, t_invite=0x7f8dbde70960) at t_fwd.c:1278
So the scheme is the following: proxy > INVITE < 486 > INVITE* < CANCEL Victor has investigated this and found that the issue seems to be related to the reply lumps added by append_to_reply when processing initial invite. In order to reproduce this you need children>=2.
When first target replies 486 the proxy calls t_next_contacts() and starts preparing invite to the next target and at this time another process receives cancel and destroys the transaction, the process handling that invite message(*) gets crashed.
While we are investigating the possibility to move the append_to_reply calls to the branch route, would it be possible to avoid crash by some kind of lock mechanism? The thing is that it's not always possible to move append_to_reply to the branch route, e.g. our proxy is deployed behind stateless lb with multiple interfaces and proxy needs to tell lb which interface to use already in the 100 Trying reply it sends to lb as a first thing when receiving a message.
version: kamailio 4.4.2
@sergey19 your issue is here: https://github.com/kamailio/kamailio/issues/870
log related to the process that crashes ``` 2016-11-30T16:28:41.159163+01:00 spce proxy[21490]: NOTICE: <script>: New request on proxy - M=CANCEL R=sip:4311003@spce.test:5060 F=sip:004321001@127.0.2.1 T=sip:4311003@spce.test IP=127.0.2.1:51602 (127.0.0.1:5060) ID=NGCP%incoming_peer_user_404%///1-22573@127.0.2.1 UA='<null>' 2016-11-30T16:28:41.159296+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 41721 2016-11-30T16:28:41.159333+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=9f2a.7af5bb99ad99ededed23ef8c4fa645f2.0 2016-11-30T16:28:41.159337+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f185dfbc060)! 2016-11-30T16:28:41.159340+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed 2016-11-30T16:28:41.159344+01:00 spce proxy[21490]: DEBUG: tm [tm.c:992]: w_t_lookup_cancel(): lookup_original: t_lookupOriginalT returned: 0x7f185dfbc060 2016-11-30T16:28:41.159349+01:00 spce proxy[21490]: NOTICE: <script>: Request leaving server via local route - R=sip:4311003@spce.test:5060 ID=NGCP%incoming_peer_user_404%///1-22573@127.0.2.1 UA='<null>' 2016-11-30T16:28:41.159456+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg id=6 , global msg id=3 , T on entrance=0xffffffffffffffff 2016-11-30T16:28:41.159465+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request: start searching: hash=41721, isACK=0 2016-11-30T16:28:41.159469+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261 transaction matching failed 2016-11-30T16:28:41.159472+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found 2016-11-30T16:28:41.159479+01:00 spce proxy[21490]: DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f185dfb7950, callback type 1, id 0 entered 2016-11-30T16:28:41.159483+01:00 spce proxy[21490]: DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f185dfb7950, callback type 1, id 0 entered 2016-11-30T16:28:41.159507+01:00 spce proxy[21490]: DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated: 5784ab728e62bcded75a225f515946f2 2016-11-30T16:28:41.159532+01:00 spce proxy[21490]: DEBUG: <core> [forward.c:702]: update_sock_struct_from_via(): trying SRV lookup 2016-11-30T16:28:41.159538+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 41721 2016-11-30T16:28:41.159542+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=9f2a.7af5bb99ad99ededed23ef8c4fa645f2.0 2016-11-30T16:28:41.159545+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f185dfbc060)! 2016-11-30T16:28:41.159610+01:00 spce proxy[21490]: DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed 2016-11-30T16:28:41.159630+01:00 spce proxy[21490]: DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0) ``` the other related log: ``` 2016-11-30T16:28:41.166920+01:00 spce proxy[21489]: NOTICE: <script>: Forcing request via B2BUA 'sip:127.0.0.1:5080' - R=sip:4311003@127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-22573@127.0.2.1 UA='<null>' 2016-11-30T16:28:41.166943+01:00 spce proxy[21489]: NOTICE: <script>: Request leaving server, D-URI='sip:127.0.0.1:5080' - R=sip:4311003@127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-22573@127.0.2.1 UA='<null>' 2016-11-30T16:28:41.166959+01:00 spce proxy[21489]: DEBUG: <core> [msg_translator.c:423]: clen_builder(): content-length: 168 (168) 2016-11-30T16:28:41.166966+01:00 spce proxy[21489]: DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0) 2016-11-30T16:28:41.166996+01:00 spce proxy[21489]: DEBUG: tm [t_fwd.c:1766]: t_forward_nonack(): t_forward_non_ack: no forwarding on a canceled transaction 2016-11-30T16:28:41.167001+01:00 spce proxy[21489]: ERROR: tm [tm.c:1415]: _w_t_relay_to(): ERROR: w_t_relay_to: t_relay_to failed 2016-11-30T16:28:41.167190+01:00 spce proxy[21489]: DEBUG: <core> [forward.c:702]: update_sock_struct_from_via(): trying SRV lookup 2016-11-30T16:28:41.167203+01:00 spce proxy[21489]: DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0) 2016-11-30T16:28:41.168010+01:00 spce proxy[21489]: ERROR: sl [sl_funcs.c:363]: sl_reply_error(): ERROR: sl_reply_error used: transaction canceled (487/SL) 2016-11-30T16:28:41.168024+01:00 spce proxy[21489]: INFO: <script>: No mediaproxy engaged for this branch, no need for stopping - R=sip:testuser1003@127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-22573@127.0.2.1 UA='<null>' 2016-11-30T16:28:41.168037+01:00 spce proxy[21489]: DEBUG: <core> [parser/sdp/sdp.c:794]: free_sdp(): _sdp = 0x7f186f7612a0 2016-11-30T16:28:41.168037+01:00 spce proxy[21489]: DEBUG: <core> [parser/sdp/sdp.c:796]: free_sdp(): sdp = 0x7f1872477de0 2016-11-30T16:28:41.168061+01:00 spce proxy[21489]: DEBUG: <core> [parser/sdp/sdp.c:798]: free_sdp(): session = 0x7f1872477ae0 2016-11-30T16:28:41.168072+01:00 spce proxy[21489]: DEBUG: tm [t_reply.c:1752]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=-1 icode=0 2016-11-30T16:28:41.168078+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-11-30T16:28:41.168081+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-11-30T16:28:41.168084+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-11-30T16:28:41.168087+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-11-30T16:28:41.168090+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-11-30T16:28:41.168155+01:00 spce proxy[21489]: DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-11-30T16:28:41.168163+01:00 spce proxy[21489]: DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) 2016-11-30T16:28:41.168167+01:00 spce proxy[21489]: DEBUG: <core> [receive.c:322]: receive_msg(): cleaning up 2016-11-30T16:28:41.362881+01:00 spce proxy[21499]: CRITICAL: <core> [pass_fd.c:277]: receive_fd(): EOF on 11 2016-11-30T16:28:41.362888+01:00 spce proxy[21499]: DEBUG: <core> [tcp_main.c:3456]: handle_ser_child(): dead child 4, pid 21490 (shutting down?) 2016-11-30T16:28:41.362898+01:00 spce proxy[21499]: DEBUG: <core> [io_wait.h:602]: io_watch_del(): DBG: io_watch_del (0x9fec80, 11, -1, 0x0) fd_no=14 called 2016-11-30T16:28:41.389837+01:00 spce proxy[21485]: ALERT: <core> [main.c:740]: handle_sigs(): child process 21490 exited by a signal 11 2016-11-30T16:28:41.389851+01:00 spce proxy[21485]: ALERT: <core> [main.c:743]: handle_sigs(): core was generated 2016-11-30T16:28:41.389864+01:00 spce proxy[21485]: INFO: <core> [main.c:755]: handle_sigs(): terminating due to SIGCHLD 2016-11-30T16:28:41.389870+01:00 spce proxy[21485]: DEBUG: <core> [main.c:757]: handle_sigs(): terminating due to SIGCHLD ```
sip flow:
[872.txt](https://github.com/kamailio/kamailio/files/622184/872.txt)
``` #0 build_res_buf_from_sip_req (code=1576798744, code@entry=487, text=0x25, new_tag=0x7f186f74d2b0 <tm_tag>, msg=0x7f185dfbf9a0, returned_len=0xb7, bmark=0x8548c03148244489) at msg_translator.c:2395 lump = 0x0 received_len = 0 rport_len = 0 warning_len = 0 after_body = 0x0 totags = 0x0 __FUNCTION__ = "build_res_buf_from_sip_req" #1 0x00007f186f4b17b2 in _reply (trans=0x7f185dfbc060, p_msg=0x7f185dfbf9a0, code=487, text=<optimized out>, lock=1) at t_reply.c:712 len = 31474 buf = <optimized out> dset = <optimized out> bm = {to_tag_val = {s = 0x7ffeab147e2c "", len = 0}} dset_len = 0 reason = {s = 0x7f186f535472 "Request canceled", len = 16} #2 0x00007f186f507e8b in e2e_cancel (cancel_msg=0x7f185dfc0a18, t_cancel=0x25, t_invite=0x7f185dfbc060) at t_fwd.c:1278 cancel_bm = 0 reason = 0x7f185dfbc060 i = 1921036208 tmcb = {req = 0x6f1ddb, rpl = 0x5e3437 <dns_srv_sip_resolvehost+279>, param = 0x2e, code = -1424720300, flags = 32766, branch = 0, t_rbuf = 0x7f185dfb7b38, dst = 0x7f185dfb7a68, send_buf = {s = 0x7f1872477a18 "\001", len = 69206528}} __FUNCTION__ = "e2e_cancel" #3 0x00007f186f50d2c2 in t_forward_nonack (t=0x7f185dfb7950, p_msg=0x7f187280afb0, proxy=0x0, proto=307) at t_fwd.c:1619 current_uri = {s = 0x0, len = 1921036208} q = 32536 t_invite = 0x7f185dfbc060 success_branch = 0 lock_replies = 1576779872 dst_uri = {s = 0x0, len = 10482636} path = {s = 0x7f186f74d1f0 <tm_cfg> "\b\235\372]\030\177", len = 1869926896} instance = {s = 0x7f186f7624d0 <user_rt_t1_timeout_ms> "", len = 1866962556} ruid = {s = 0x7ffe00000007 <error: Cannot access memory at address 0x7ffe00000007>, len = 7282139} location_ua = {s = 0x6 <error: Cannot access memory at address 0x6>, len = -1424718544} si = 0xb65c050904200200 backup_bflags = 0 bflags = 0 __FUNCTION__ = "t_forward_nonack" #4 0x00007f186f50df6b in t_forward_cancel (p_msg=0x7f187280afb0, proxy=0x0, proto=0, tran=0x7ffeab148240) at t_fwd.c:1816 t_invite = 0x0 t = 0xb7 ret = 1 dst = {send_sock = 0x7f18702e80b6, to = {s = {sa_family = 6554, sa_data = "_s\030\177\000\000\000\000\000\000\000\000\000"}, sin = {sin_family = 6554, sin_port = 29535, sin_addr = {s_addr = 32536}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 6554, sin6_port = 29535, sin6_flowinfo = 32536, sin6_addr = {__in6_u = { __u6_addr8 = "\000\000\000\000\000\000\000\000(\000\000\000\060\000\000", __u6_addr16 = {0, 0, 0, 0, 40, 0, 48, 0}, __u6_addr32 = {0, 0, 40, 48}}}, sin6_scope_id = 2870249136}}, id = 32766, proto = -63 '\301', send_flags = { f = 177 '\261', blst_imask = 112 'p'}} host = {s = 0xffffffffffffffff <error: Cannot access memory at address 0xffffffffffffffff>, len = 1} __FUNCTION__ = "t_forward_cancel" #5 0x00007f186f4f117a in t_relay_to (p_msg=0x7f187280afb0, proxy=0x0, proto=0, replicate=0) at t_funcs.c:238 ret = 1911489832 t = 0x7f187370b1c8 dst = {send_sock = 0x7f18735f199a <vfprintf+22490>, to = {s = {sa_family = 6554, sa_data = "_s\030\177\000\000\377\377\377\377\377\377\377\377"}, sin = {sin_family = 6554, sin_port = 29535, sin_addr = { s_addr = 32536}, sin_zero = "\377\377\377\377\377\377\377\377"}, sin6 = {sin6_family = 6554, sin6_port = 29535, sin6_flowinfo = 32536, sin6_addr = {__in6_u = {__u6_addr8 = "\377\377\377\377\377\377\377\377űps\030\177\000", __u6_addr16 = {65535, 65535, 65535, 65535, 45509, 29552, 32536, 0}, __u6_addr32 = {4294967295, 4294967295, 1936765381, 32536}}}, sin6_scope_id = 2870248224}}, id = 32766, proto = 7 '\a', send_flags = {f = 0 '\000', blst_imask = 0 '\000'}} host = {s = 0x7ffeab148350 " \210\024\253\376\177", len = 1935612314} __FUNCTION__ = "t_relay_to" #6 0x0000000000446650 in do_action (h=0x7ffeab148960, a=0x7f1871ef0528, msg=0x7f187280afb0) at action.c:1060 ret = -5 v = 0 dst = {send_sock = 0xc8, to = {s = {sa_family = 35200, sa_data = "\244", '\000' <repeats 12 times>}, sin = { ``` ``` (gdb) p *msg->reply_lump $2 = {text = {s = 0x7f185dfbb3c0 "P-Out-Socket: udp:127.0.0.1:5060\r\n", len = 34}, flags = 34, next = 0x7f185dfbb3e8} (gdb) p *msg->reply_lump->next $3 = {text = {s = 0x7f185dfbb408 "P-NGCP-Auth-IP: 127.0.2.1\r\n]\030\177", len = 27}, flags = 34, next = 0x7f185dfbb428} (gdb) p *msg->reply_lump->next->next $4 = {text = {s = 0x7f185dfbb448 "P-NGCP-Auth-UA: <null>\r\n\200\264\373]\030\177", len = 24}, flags = 34, next = 0x7f185dfbb460} (gdb) p *msg->reply_lump->next->next->next $5 = {text = {s = 0x7f185dfbb480 "P-Callee-Uuid: fe3366a8-8b5b-4ec9-81e4-ba5a4f8bd124\r\n", len = 53}, flags = 34, next = 0x0} ```
Maybe related to 8814e5fc2e44f792cbff8e83d184034b3d1ebc59 ?
Are you doing async (suspend/continue) in the config? The 8814e5f is somehow related to that and I couldn't spot any relation with the report details of the issue.
Back to the issue -- can it be reproduced, or it was like one time event?
Are you doing async (suspend/continue) in the config?
No
Back to the issue -- can it be reproduced
Yes, We can
Are you getting only a corefile (dumping corefiles per pid should be enabled)? Because this one looks a bit clean and I want to be sure it is not because another core dump was done first and then overwriten.
I'm getting core per pid, no other core was generated.
Can you add in kamailio.cfg:
``` log_prefix="{$mt $hdr(CSeq) $ci} " ```
Then reproduce the issue and grab again the log messages with debug=3. It will help to track better the messages printed for invite or cancel.
Would be a easy way that I can reproduce it easy without a need to build a complex testbed?
core: core.kamailio.sig11.29831 log from pid that crash: ``` 2016-12-01T16:16:21.463526+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:595]: parse_msg(): SIP Request: 2016-12-01T16:16:21.463531+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:597]: parse_msg(): method: <CANCEL> 2016-12-01T16:16:21.463534+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:599]: parse_msg(): uri: sip:4311003@spce.test:5060 2016-12-01T16:16:21.463538+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:601]: parse_msg(): version: <SIP/2.0> 2016-12-01T16:16:21.463548+01:00 spce proxy[29831]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKed7a.bc0c3a7e71de87e4c6127fda1fd1b048.0>; state=16 2016-12-01T16:16:21.463562+01:00 spce proxy[29831]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 2016-12-01T16:16:21.463567+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:486]: parse_headers(): Via found, flags=2 2016-12-01T16:16:21.463570+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:488]: parse_headers(): this is the first via 2016-12-01T16:16:21.463574+01:00 spce proxy[29831]: DEBUG: <core> [receive.c:178]: receive_msg(): After parse_msg... 2016-12-01T16:16:21.463583+01:00 spce proxy[29831]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 234, <received> = <127.0.2.1>; state=6 2016-12-01T16:16:21.463638+01:00 spce proxy[29831]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 235, <rport> = <51602>; state=6 2016-12-01T16:16:21.463653+01:00 spce proxy[29831]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-30543-1-0>; state=16 2016-12-01T16:16:21.463657+01:00 spce proxy[29831]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 2016-12-01T16:16:21.463661+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:486]: parse_headers(): Via found, flags=ffffffffffffffff 2016-12-01T16:16:21.463664+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:499]: parse_headers(): this is the second via 2016-12-01T16:16:21.463671+01:00 spce proxy[29831]: DEBUG: <core> [parser/parse_addr_spec.c:871]: parse_addr_spec(): end of header reached, state=10 2016-12-01T16:16:21.463675+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:171]: get_hdr_field(): <To> [25]; uri=[sip:4311003@spce.test] 2016-12-01T16:16:21.463678+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:172]: get_hdr_field(): to body [sip:4311003@spce.test#015#012] 2016-12-01T16:16:21.463704+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <CANCEL> 2016-12-01T16:16:21.463720+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:183]: get_hdr_field(): content_length=0 2016-12-01T16:16:21.463727+01:00 spce proxy[29831]: DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end of header 2016-12-01T16:16:21.463734+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [receive.c:221]: receive_msg(): preparing to run routing scripts... 2016-12-01T16:16:21.463784+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [forward.c:702]: update_sock_struct_from_via(): trying SRV lookup 2016-12-01T16:16:21.463800+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0) 2016-12-01T16:16:21.463839+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [parser/parse_addr_spec.c:171]: parse_to_param(): DEBUG: add_param: tag=30543SIPpTag001 2016-12-01T16:16:21.463881+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [parser/parse_addr_spec.c:871]: parse_addr_spec(): end of header reached, state=29 2016-12-01T16:16:21.463891+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} NOTICE: <script>: New request on proxy - M=CANCEL R=sip:4311003@spce.test:5060 F=sip:004321001@127.0.2.1 T=sip:4311003@spce.test IP=127.0.2.1:51602 (127.0.0.1:5060) ID=NGCP%incoming_peer_user_404%///1-30543@127.0.2.1 UA='<null>' 2016-12-01T16:16:21.463963+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 42974 2016-12-01T16:16:21.463980+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=ed7a.bc0c3a7e71de87e4c6127fda1fd1b048.0 2016-12-01T16:16:21.463985+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f85207f3680)! 2016-12-01T16:16:21.463988+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed 2016-12-01T16:16:21.463992+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [tm.c:992]: w_t_lookup_cancel(): lookup_original: t_lookupOriginalT returned: 0x7f85207f3680 2016-12-01T16:16:21.463997+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} NOTICE: <script>: Request leaving server via local route - R=sip:4311003@spce.test:5060 ID=NGCP%incoming_peer_user_404%///1-30543@127.0.2.1 UA='<null>' 2016-12-01T16:16:21.464004+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:1312]: t_newtran(): DEBUG: t_newtran: msg id=10 , global msg id=9 , T on entrance=0xffffffffffffffff 2016-12-01T16:16:21.464008+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:466]: t_lookup_request(): t_lookup_request: start searching: hash=42974, isACK=0 2016-12-01T16:16:21.464012+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:424]: matching_3261(): DEBUG: RFC3261 transaction matching failed 2016-12-01T16:16:21.464037+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:648]: t_lookup_request(): DEBUG: t_lookup_request: no transaction found 2016-12-01T16:16:21.464045+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f85207efe58, callback type 1, id 0 entered 2016-12-01T16:16:21.464049+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_hooks.c:358]: run_reqin_callbacks_internal(): DBG: trans=0x7f85207efe58, callback type 1, id 0 entered 2016-12-01T16:16:21.464062+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [md5utils.c:67]: MD5StringArray(): MD5 calculated: 62ec5b8389d2cbfd0b410a84d83a829a 2016-12-01T16:16:21.464068+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [forward.c:702]: update_sock_struct_from_via(): trying SRV lookup 2016-12-01T16:16:21.464083+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:701]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: searching on hash entry 42974 2016-12-01T16:16:21.464087+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:409]: matching_3261(): DEBUG: RFC3261 transaction matched, tid=ed7a.bc0c3a7e71de87e4c6127fda1fd1b048.0 2016-12-01T16:16:21.464091+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:798]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT: canceled transaction found (0x7f85207f3680)! 2016-12-01T16:16:21.464094+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:801]: t_lookupOriginalT(): DEBUG: t_lookupOriginalT completed 2016-12-01T16:16:21.464101+01:00 spce proxy[29831]: {1 1 CANCEL NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0) ```
log from pid that received the 404 ``` 2016-12-01T16:16:21.460389+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:605]: parse_msg(): SIP Reply (status): 2016-12-01T16:16:21.460395+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:607]: parse_msg(): version: <SIP/2.0> 2016-12-01T16:16:21.460399+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:609]: parse_msg(): status: <404> 2016-12-01T16:16:21.460402+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:611]: parse_msg(): reason: <Not Found> 2016-12-01T16:16:21.460407+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKed7a.62ec5b8389d2cbfd0b410a84d83a829a.0>; state=16 2016-12-01T16:16:21.460421+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 2016-12-01T16:16:21.460426+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:486]: parse_headers(): Via found, flags=2 2016-12-01T16:16:21.460430+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:488]: parse_headers(): this is the first via 2016-12-01T16:16:21.460433+01:00 spce proxy[29830]: DEBUG: <core> [receive.c:178]: receive_msg(): After parse_msg... 2016-12-01T16:16:21.460442+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKed7a.bc0c3a7e71de87e4c6127fda1fd1b048.0>; state=16 2016-12-01T16:16:21.460446+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 2016-12-01T16:16:21.460494+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:486]: parse_headers(): Via found, flags=ffffffffffffffff 2016-12-01T16:16:21.460502+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:499]: parse_headers(): this is the second via 2016-12-01T16:16:21.460508+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 235, <rport> = <51602>; state=6 2016-12-01T16:16:21.460513+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_via.c:1254]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-30543-1-0>; state=16 2016-12-01T16:16:21.460516+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_via.c:2642]: parse_via(): end of header reached, state=5 2016-12-01T16:16:21.460519+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:486]: parse_headers(): Via found, flags=ffffffffffffffff 2016-12-01T16:16:21.460526+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_addr_spec.c:171]: parse_to_param(): DEBUG: add_param: tag=6FD1D24D-58403EC500061CBC-B71CF700 2016-12-01T16:16:21.460529+01:00 spce proxy[29830]: DEBUG: <core> [parser/parse_addr_spec.c:871]: parse_addr_spec(): end of header reached, state=29 2016-12-01T16:16:21.460534+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:171]: get_hdr_field(): <To> [64]; uri=[sip:4311003@spce.test] 2016-12-01T16:16:21.460537+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:172]: get_hdr_field(): to body [sip:4311003@spce.test] 2016-12-01T16:16:21.460543+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE> 2016-12-01T16:16:21.460587+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:183]: get_hdr_field(): content_length=0 2016-12-01T16:16:21.460595+01:00 spce proxy[29830]: DEBUG: <core> [parser/msg_parser.c:89]: get_hdr_field(): found end of header 2016-12-01T16:16:21.460608+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:1011]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=8 T start=0xffffffffffffffff 2016-12-01T16:16:21.460615+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:888]: t_reply_matching(): DEBUG: t_reply_matching: hash 42974 label 0 branch 0 2016-12-01T16:16:21.460621+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:943]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7f85207f3680)! 2016-12-01T16:16:21.460626+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f85207f3680, callback type 2, id 0 entered 2016-12-01T16:16:21.460633+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [parser/parse_addr_spec.c:171]: parse_to_param(): DEBUG: add_param: tag=30543SIPpTag001 2016-12-01T16:16:21.460636+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [parser/parse_addr_spec.c:871]: parse_addr_spec(): end of header reached, state=29 2016-12-01T16:16:21.460642+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f85207f3680, callback type 2, id 0 entered 2016-12-01T16:16:21.460648+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_hooks.c:266]: run_trans_callbacks_internal(): DBG: trans=0x7f85207f3680, callback type 2, id 0 entered 2016-12-01T16:16:21.460656+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_lookup.c:1080]: t_check_msg(): DEBUG: t_check_msg: msg id=9 global id=9 T end=0x7f85207f3680 2016-12-01T16:16:21.460703+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_reply.c:2161]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=100 local=0 is_invite=1) 2016-12-01T16:16:21.460792+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} NOTICE: <script>: NAT-Reply - S=404 - Not Found M=INVITE IP=127.0.2.1:51602 (127.0.0.1:5080) ID=NGCP%incoming_peer_user_404%///1-30543@127.0.2.1 UA='<null>' 2016-12-01T16:16:21.460829+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_reply.c:1233]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=404 [...] 2016-12-01T16:16:21.466199+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} INFO: <script>: Adding P-NGCP-Callee-Info 'sip:4311003@spce.test;ip=127.0.0.1;port=5060;primary=4311003' - R=sip:4311003@127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-30543@127.0.2.1 UA='<null>' 2016-12-01T16:16:21.466386+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} NOTICE: <script>: Appending P-D-URI 'sip:lb@127.0.0.1;lr;socket=sip:127.0.0.1:5060' - R=sip:4311003@127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-30543@127.0.2.1 UA='<null>' 2016-12-01T16:16:21.466406+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} NOTICE: <script>: Forcing request via B2BUA 'sip:127.0.0.1:5080' - R=sip:4311003@127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-30543@127.0.2.1 UA='<null>' 2016-12-01T16:16:21.466414+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} NOTICE: <script>: Request leaving server, D-URI='sip:127.0.0.1:5080' - R=sip:4311003@127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-30543@127.0.2.1 UA='<null>' 2016-12-01T16:16:21.466436+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [msg_translator.c:423]: clen_builder(): content-length: 168 (168) 2016-12-01T16:16:21.466447+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0) 2016-12-01T16:16:21.466501+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_fwd.c:1766]: t_forward_nonack(): t_forward_non_ack: no forwarding on a canceled transaction 2016-12-01T16:16:21.466510+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} ERROR: tm [tm.c:1415]: _w_t_relay_to(): ERROR: w_t_relay_to: t_relay_to failed 2016-12-01T16:16:21.466522+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [forward.c:702]: update_sock_struct_from_via(): trying SRV lookup 2016-12-01T16:16:21.466529+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [msg_translator.c:158]: check_via_address(): (127.0.0.1, 127.0.0.1, 0) 2016-12-01T16:16:21.467761+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} ERROR: sl [sl_funcs.c:363]: sl_reply_error(): ERROR: sl_reply_error used: transaction canceled (487/SL) 2016-12-01T16:16:21.467789+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} INFO: <script>: No mediaproxy engaged for this branch, no need for stopping - R=sip:testuser1003@127.1.0.2:50604 ID=NGCP%incoming_peer_user_404%///1-30543@127.0.2.1 UA='<null>' 2016-12-01T16:16:21.467807+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [parser/sdp/sdp.c:794]: free_sdp(): _sdp = 0x7f8531f9b2a0 2016-12-01T16:16:21.467812+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [parser/sdp/sdp.c:796]: free_sdp(): sdp = 0x7f8533fbd738 2016-12-01T16:16:21.467816+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [parser/sdp/sdp.c:798]: free_sdp(): session = 0x7f8533f7cdf0 2016-12-01T16:16:21.467830+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: tm [t_reply.c:1752]: relay_reply(): DEBUG: relay_reply: branch=0, save=0, relay=-1 icode=0 2016-12-01T16:16:21.467837+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-12-01T16:16:21.467841+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-12-01T16:16:21.467845+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-12-01T16:16:21.467850+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-12-01T16:16:21.467854+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-12-01T16:16:21.467994+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [usr_avp.c:631]: destroy_avp_list(): destroying list (nil) 2016-12-01T16:16:21.468015+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [xavp.c:446]: xavp_destroy_list(): destroying xavp list (nil) 2016-12-01T16:16:21.468030+01:00 spce proxy[29830]: {2 1 INVITE NGCP%incoming_peer_user_404%///1-30543@127.0.2.1} DEBUG: <core> [receive.c:322]: receive_msg(): cleaning up 2016-12-01T16:16:21.822718+01:00 spce proxy[29830]: INFO: <core> [main.c:810]: sig_usr(): signal 15 received ``` pcap txt [872_2.txt](https://github.com/kamailio/kamailio/files/624999/872_2.txt)
full log [kamailio.txt](https://github.com/kamailio/kamailio/files/624993/kamailio.txt)
Are you adding the reply headers in the failure_route? Or in the request_route?
The transaction is not deleted immediately once it is cancelled (or sends out a negative response), but it is kept in memory for wait_time to absorb the retransmissions.
So this situation might be in the case one adds reply lumps (headers to replies) in a failure route, which are deleted once the failure route is executed...
Hi @miconda, thanks for the good point. There was indeed another call to append_to_reply in failure_route, rather due to an oversight than by intention. After removing it I'm not getting any new crashes.
now we are getting crashes when CANCEL from caller is received at the same time as 487 from callee by another process.
This core is from the process of the 487 ``` Core was generated by `/usr/sbin/kamailio -f /etc/kamailio/proxy/kamailio.cfg -P /var/run/kamailio/kam'. Program terminated with signal SIGSEGV, Segmentation fault. #0 atomic_get (v=<optimized out>) at ../../mem/../atomic/atomic_common.h:74 74 ../../mem/../atomic/atomic_common.h: No such file or directory. (gdb) bt #0 atomic_get (v=<optimized out>) at ../../mem/../atomic/atomic_common.h:74 #1 dlg_unref_helper (dlg=0x7f59490bcdf8, cnt=1, fname=0x5335 <error: Cannot access memory at address 0x5335>, fline=1637) at dlg_hash.c:925 #2 0x00007f59f8a0ce12 in dlg_run_event_route (dlg=0x7f59490bcdf8, msg=0x7f5a040d3138, ostate=983121128, nstate=4) at dlg_handlers.c:1637 #3 0x00007f59f8a0d157 in dlg_onreply (t=0x7f5948ee57a8, type=6, param=0x7ffea05ae620) at dlg_handlers.c:458 #4 0x00007f5a00ea2c16 in run_trans_callbacks_internal (cb_lst=0x7f5948e46938, type=1048576, trans=0x7f5948ee57a8, params=0x7ffea05ae620) at t_hooks.c:268 #5 0x00007f5a00ea2fa5 in run_trans_callbacks_with_buf (type=<optimized out>, rbuf=<optimized out>, req=<optimized out>, repl=<optimized out>, flags=<optimized out>) at t_hooks.c:314 #6 0x00007f5a00e5ef53 in relay_reply (t=0x7f5948ee57a8, p_msg=0x6, branch=983121128, msg_status=700, cancel_data=0x1, do_put_on_wait=100) at t_reply.c:1915 #7 0x00007f5a00e61d43 in reply_received (p_msg=0x7f5a040d3138) at t_reply.c:2466 #8 0x00000000004f7306 in do_forward_reply (msg=0x7f5a040d3138, mode=0) at forward.c:747 #9 0x0000000000556f03 in receive_msg (buf=0x0, len=67973432, rcv_info=0x7f5a03da93f8) at receive.c:299 #10 0x0000000000479f10 in udp_rcv_loop () at udp_server.c:495 #11 0x00000000004ffe39 in main_loop () at main.c:1614 #12 0x000000000041cd6c in main (argc=0, argv=0x0) at main.c:2631 (gdb) f 1 #1 dlg_unref_helper (dlg=0x7f59490bcdf8, cnt=1, fname=0x5335 <error: Cannot access memory at address 0x5335>, fline=1637) at dlg_hash.c:925 925 dlg_hash.c: No such file or directory. (gdb) p d_entry $1 = (dlg_entry_t *) 0x7f644ccda358 (gdb) p *d_entry Cannot access memory at address 0x7f644ccda358 ``` This is kamailio 4.4.4 @apogrebennyk
``` (gdb) f 3 #3 0x00007f59f8a0d157 in dlg_onreply (t=0x7f5948ee57a8, type=6, param=0x7ffea05ae620) at dlg_handlers.c:458 458 dlg_handlers.c: No such file or directory. (gdb) p type $3 = 6 (gdb) p new_state $4 = 5 ``` ``type == TMCB_ON_FAILURE_RO_N`` and ``new_state == DLG_STATE_DELETED``
``` (gdb) f 2 #2 0x00007f59f8a0ce12 in dlg_run_event_route (dlg=0x7f59490bcdf8, msg=0x7f5a040d3138, ostate=983121128, nstate=4) at dlg_handlers.c:1637 1637 in dlg_handlers.c (gdb) p ostate $5 = 983121128 (gdb) p nstate $6 = 4 ``` How can this be?
I think this will be fixed by edb9df8
Closed #872.
-
apogrebennyk -
Daniel-Constantin Mierla
-
sergey19
-
Victor Seva