30 Nov
2016
30 Nov
'16
8:03 p.m.
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.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872
30 Nov
30 Nov
8:03 p.m.
version: kamailio 4.4.2
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-263895549
8:19 p.m.
@sergey19 your issue is here: https://github.com/kamailio/kamailio/issues/870
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-263899594
8:42 p.m.
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(a)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(a)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(a)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(a)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(a)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)
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-263906377
8:50 p.m.
```
#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}
```
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-263908731
1 Dec
1 Dec
1:51 p.m.
Maybe related to 8814e5fc2e44f792cbff8e83d184034b3d1ebc59 ?
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264115643
2:47 p.m.
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?
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264127452
2:54 p.m.
Are you doing async (suspend/continue) in the config?
No
Back to the issue -- can it be reproduced
Yes, We can
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264128890
5:52 p.m.
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.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264166126
6:32 p.m.
I'm getting core per pid, no other core was generated.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264173705
6:55 p.m.
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?
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264178684
8:29 p.m.
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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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(a)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.tx…
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264203248
2 Dec
2 Dec
3:49 p.m.
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...
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264427030
5:56 p.m.
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.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-264448340
2 Feb
2 Feb
6:37 p.m.
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
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-276958892
6:45 p.m.
```
(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``
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-276960593
7:09 p.m.
```
(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?
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-276966807
16 Feb
16 Feb
4:43 p.m.
I think this will be fixed by edb9df8
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#issuecomment-280308975
23 Feb
23 Feb
3:47 a.m.
Closed #872.
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/872#event-973461863
2623
days inactive
2707
days old
18 comments
4 participants
participants (4)
-
apogrebennyk -
Daniel-Constantin Mierla
-
sergey19
-
Victor Seva