Hi,
I am experiencing a problem regarding CANCEL processing, I have the
normal config file plus the following (I got that in a previous mail)
if (is_method("CANCEL")) {
t_relay();
break;
}
The problem is that openserver is relaying the CANCEL, but putting a
completely new branch tag in the Via header, instead of the same branch
than in the INVITE that is to be cancel. I have debug dump, that shows
that the CANCEL message is matched with the INVITE, but it still put a
new branch in the relayed cancel, and also in the 200 OK response.
If somebody could help me it would be great
0(5309) DEBUG: callid: '2ef6f3df-5309@10.161.14.110'
0(5309) DEBUG:init_mod_child: CHILD , rank=1, module=usrloc
0(5309) DEBUG:init_mod_child: CHILD , rank=1, module=xlog
0(5309) XLOG: init_child [1] pid [5309]
0(5309) SIP Request:
0(5309) method: <INVITE>
0(5309) uri: <sip:user4@home2.jagarvayo.mot.dev>
0(5309) version: <SIP/2.0>
0(5309) parse_headers: flags=2
0(5309) Found param type 232, <branch> = <z9hG4bK4f9932cde5bad6c36f103563aa96f449>; state=6
0(5309) Found param type 238, <xxxST_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK6f59072ad3fe644fcf851c16d3168bee>; state=6
0(5309) Found param type 238, <xxxIT_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK80752856b61f3aaf3f1d17e57067d067>; state=6
0(5309) Found param type 238, <xxxSO_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK8b46a43071f3848c711cb4bcf4b42335>; state=6
0(5309) Found param type 238, <xxxPO_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) end of header reached, state=5
0(5309) parse_headers: Via found, flags=2
0(5309) parse_headers: this is the first via
0(5309) After parse_msg...
0(5309) preparing to run routing scripts...
0(5309) parse_headers: flags=100
0(5309) DEBUG:parse_to:end of header reached, state=9
0(5309) DEBUG: get_hdr_field: <To> [37]; uri=[sip:user4@home2.jagarvayo.mot.dev]
0(5309) DEBUG: to body [<sip:user4@home2.jagarvayo.mot.dev>
]
0(5309) get_hdr_field: cseq <CSeq>: <1> <INVITE>
0(5309) DEBUG: get_hdr_body : content_length=95
0(5309) DEBUG:maxfwd:is_maxfwd_present: value = 66
0(5309) DEBUG: add_param: tag=6661
0(5309) DEBUG:parse_to:end of header reached, state=29
0(5309) xl_printf: final buffer length 112
0(5309) INVITE: 10.161.14.59:5060 ci=1-26284@10.161.14.105
ft=6661 tt=<null> cseq=1 sip:user4@home2.jagarvayo.mot.dev:
0(5309) parse_headers: flags=200
0(5309) is_preloaded: Yes
0(5309) grep_sock_info - checking if host==us: 13==13 && [10.161.14.110] == [10.161.14.110]
0(5309) grep_sock_info - checking if port 7000 matches port 7000
0(5309) after_loose: Topmost route URI: 'sip:10.161.14.110:7000' is me
0(5309) after_loose: URI to be processed: 'sip:csm002_c638dcee898a6df9b8a460a45e020ce4@10.161.14.59;lr'
0(5309) after_loose: Next URI is a loose router
0(5309) xl_printf: final buffer length 78
0(5309) Relying to Route: sip:csm002_c638dcee898a6df9b8a460a45e020ce4@10.161.14.59;lr
0(5309) parse_headers: flags=ffffffffffffffff
0(5309) found end of header
0(5309) DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff
0(5309) parse_headers: flags=ffffffffffffffff
0(5309) parse_headers: flags=78
0(5309) t_lookup_request: start searching: hash=61655, isACK=0
0(5309) DEBUG: RFC3261 transaction matching failed
0(5309) DEBUG: t_lookup_request: no transaction found
0(5309) parse_headers: flags=78
0(5309) DEBUG: MD5 calculated: cf43897e3c46f1bb8c4ab6702426d007
0(5309) DEBUG:tm:t_relay: new INVITE
0(5309) parse_headers: flags=ffffffffffffffff
0(5309) check_via_address(10.161.14.59, 10.161.14.59, 0)
0(5309) WARNING:vqm_resize: resize(0) called
0(5309) DEBUG:tm:_reply_light: reply sent out. buf=0x8137e38: SIP/2.0 1..., shmem=0x40357658: SIP/2.0 1
0(5309) DEBUG:tm:_reply_light: finished
0(5309) DEBUG: mk_proxy: doing DNS lookup...
0(5309) check_via_address(10.161.14.59, 10.161.14.59, 0)
0(5309) DEBUG: add_to_tail_of_timer[4]: 0x40355bf4
0(5309) DEBUG: add_to_tail_of_timer[0]: 0x40355c04
0(5309) SER: new transaction fwd'ed
0(5309) DEBUG:destroy_avp_list: destroying list (nil)
0(5309) receive_msg: cleaning up
0(5309) SIP Reply (status):
0(5309) version: <SIP/2.0>
0(5309) status: <100>
0(5309) reason: <Trying>
0(5309) parse_headers: flags=2
0(5309) DEBUG:parse_to:end of header reached, state=9
0(5309) DEBUG: get_hdr_field: <To> [37]; uri=[sip:user4@home2.jagarvayo.mot.dev]
0(5309) DEBUG: to body [<sip:user4@home2.jagarvayo.mot.dev>
]
0(5309) get_hdr_field: cseq <CSeq>: <1> <INVITE>
0(5309) Found param type 232, <branch> = <z9hG4bK7d0f.cf43897e3c46f1bb8c4ab6702426d007.0>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK4f9932cde5bad6c36f103563aa96f449>; state=6
0(5309) Found param type 238, <xxxST_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK6f59072ad3fe644fcf851c16d3168bee>; state=6
0(5309) Found param type 238, <xxxIT_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK80752856b61f3aaf3f1d17e57067d067>; state=6
0(5309) Found param type 238, <xxxSO_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK8b46a43071f3848c711cb4bcf4b42335>; state=6
0(5309) Found param type 238, <xxxPO_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) end of header reached, state=5
0(5309) parse_headers: Via found, flags=2
0(5309) parse_headers: this is the first via
0(5309) After parse_msg...
0(5309) forward_reply: found module tm, passing reply to it
0(5309) DEBUG: t_check: msg id=2 global id=1 T start=0xffffffff
0(5309) parse_headers: flags=22
0(5309) parse_headers: flags=8
0(5309) DEBUG: t_reply_matching: hash 61655 label 0 branch 0
0(5309) DEBUG: t_reply_matching: reply matched (T=0x40355ae0)!
0(5309) DEBUG: t_check: msg id=2 global id=2 T end=0x40355ae0
0(5309) DEBUG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
0(5309) DEBUG:tm:t_should_relay_response: T_code=100, new_code=100
0(5309) DEBUG:tm:relay_reply: branch=0, save=0, relay=-1
0(5309) DEBUG: add_to_tail_of_timer[1]: 0x40355c04
0(5309) DEBUG:destroy_avp_list: destroying list (nil)
0(5309) receive_msg: cleaning up
0(5309) SIP Reply (status):
0(5309) version: <SIP/2.0>
0(5309) status: <183>
0(5309) reason: <Session Progress>
0(5309) parse_headers: flags=2
0(5309) DEBUG: add_param: tag=9991
0(5309) DEBUG:parse_to:end of header reached, state=29
0(5309) DEBUG: get_hdr_field: <To> [46]; uri=[sip:user4@home2.jagarvayo.mot.dev]
0(5309) DEBUG: to body [<sip:user4@home2.jagarvayo.mot.dev>]
0(5309) get_hdr_field: cseq <CSeq>: <1> <INVITE>
0(5309) Found param type 232, <branch> = <z9hG4bK7d0f.cf43897e3c46f1bb8c4ab6702426d007.0>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK4f9932cde5bad6c36f103563aa96f449>; state=6
0(5309) Found param type 238, <xxxST_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK6f59072ad3fe644fcf851c16d3168bee>; state=6
0(5309) Found param type 238, <xxxIT_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK80752856b61f3aaf3f1d17e57067d067>; state=6
0(5309) Found param type 238, <xxxSO_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK8b46a43071f3848c711cb4bcf4b42335>; state=6
0(5309) Found param type 238, <xxxPO_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) end of header reached, state=5
0(5309) parse_headers: Via found, flags=2
0(5309) parse_headers: this is the first via
0(5309) After parse_msg...
0(5309) forward_reply: found module tm, passing reply to it
0(5309) DEBUG: t_check: msg id=3 global id=2 T start=0xffffffff
0(5309) parse_headers: flags=22
0(5309) parse_headers: flags=8
0(5309) DEBUG: t_reply_matching: hash 61655 label 0 branch 0
0(5309) DEBUG: t_reply_matching: reply matched (T=0x40355ae0)!
0(5309) DEBUG: t_check: msg id=3 global id=3 T end=0x40355ae0
0(5309) DEBUG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
0(5309) DEBUG:tm:t_should_relay_response: T_code=100, new_code=183
0(5309) DEBUG:tm:relay_reply: branch=0, save=0, relay=0
0(5309) old size: 1120, new size: 1035
0(5309) build_res_from_sip_res: copied size: orig:549, new: 464, rest: 571 msg=
SIP/2.0 183 Session Progress
From: <sip:user3@home2.jagarvayo.mot.dev>;tag=6661
To: <sip:user4@home2.jagarvayo.mot.dev>;tag=9991
Call-ID: 1-26284@10.161.14.105
CSeq: 1 INVITE
Contact: <sip:10.161.14.105:6020>
Content-Type: application/sdp
Record-Route:
<sip:xxxPT_002@10.161.14.59;lr>,<sip:xxxST_002@10.161.14.59;lr>,<sip:10.161.14.110:7000
;ftag=6661;lr>,<sip:xxxST_002@10.161.14.59;lr>,<sip:xxxSO_002@10.161.14.59;lr>,<
sip:xxxPO_002@10.161.14.59;lr>
Via: SIP/2.0/UDP
10.161.14.59;branch=z9hG4bK4f9932cde5bad6c36f103563aa96f449;xxxST_002,SIP/2.0/UDP
10.161.14.59;branch=z9hG4bK6f59072ad3fe644fcf851c16d3168bee;xxxIT_002,SIP/2.0/UDP
10.161.14.59;branch=z9hG4bK80752856b61f3aaf3f1d17e57067d067;xxxSO_002,SIP/2.0/UDP
10.161.14.59;branch=z9hG4bK8b46a43071f3848c711cb4bcf4b42335;xxxPO_002,SIP/2.0/UDP
10.161.14.105:6020
P-Charging-Vector: icid-value=43d9d426:f1135:7e37002e@pcscf.home2.jagarvayo.mot.dev;term-ioi=ims.XXX.com
v=0
o=srini - 0 IN IP4 -
s=SIPtest - -
c=IN IP4 10.161.14.59
t=0 0
m=audio 2410 RTP/AVP 0
0(5309) DEBUG:tm:relay_reply: sent buf=0x8138178: SIP/2.0 1..., shmem=0x40357f90: SIP/2.0 1
0(5309) DEBUG: add_to_tail_of_timer[1]: 0x40355c04
0(5309) DEBUG:destroy_avp_list: destroying list (nil)
0(5309) receive_msg: cleaning up
1(5311) DEBUG: timer routine:4,tl=0x40355bf4 next=(nil)
0(5309) SIP Reply (status):
0(5309) version: <SIP/2.0>
0(5309) status: <180>
0(5309) reason: <Ringing>
0(5309) parse_headers: flags=2
0(5309) DEBUG: add_param: tag=9991
0(5309) DEBUG:parse_to:end of header reached, state=29
0(5309) DEBUG: get_hdr_field: <To> [46]; uri=[sip:user4@home2.jagarvayo.mot.dev]
0(5309) DEBUG: to body [<sip:user4@home2.jagarvayo.mot.dev>]
0(5309) get_hdr_field: cseq <CSeq>: <1> <INVITE>
0(5309) DEBUG: get_hdr_body : content_length=0
0(5309) Found param type 232, <branch> = <z9hG4bK7d0f.cf43897e3c46f1bb8c4ab6702426d007.0>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK4f9932cde5bad6c36f103563aa96f449>; state=6
0(5309) Found param type 238, <xxxST_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK6f59072ad3fe644fcf851c16d3168bee>; state=6
0(5309) Found param type 238, <xxxIT_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK80752856b61f3aaf3f1d17e57067d067>; state=6
0(5309) Found param type 238, <xxxSO_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) Found param type 232, <branch> = <z9hG4bK8b46a43071f3848c711cb4bcf4b42335>; state=6
0(5309) Found param type 238, <xxxPO_002> = <n/a>; state=9
0(5309) parse_via: next_via
0(5309) end of header reached, state=5
0(5309) parse_headers: Via found, flags=2
0(5309) parse_headers: this is the first via
0(5309) After parse_msg...
0(5309) forward_reply: found module tm, passing reply to it
0(5309) DEBUG: t_check: msg id=4 global id=3 T start=0xffffffff
0(5309) parse_headers: flags=22
0(5309) parse_headers: flags=8
0(5309) DEBUG: t_reply_matching: hash 61655 label 0 branch 0
0(5309) DEBUG: t_reply_matching: reply matched (T=0x40355ae0)!
0(5309) DEBUG: t_check: msg id=4 global id=4 T end=0x40355ae0
0(5309) DEBUG:tm:reply_received: org. status uas=183, uac[0]=183 local=0 is_invite=1)
0(5309) DEBUG:tm:t_should_relay_response: T_code=183, new_code=180
0(5309) DEBUG:tm:relay_reply: branch=0, save=0, relay=0
0(5309) old size: 1001, new size: 916
0(5309) build_res_from_sip_res: copied size: orig:528, new: 443, rest: 473 msg=
SIP/2.0 180 Ringing
From: <sip:user3@home2.jagarvayo.mot.dev>;tag=6661
To: <sip:user4@home2.jagarvayo.mot.dev>;tag=9991
Call-ID: 1-26284@10.161.14.105
CSeq: 1 INVITE
Contact: <sip:10.161.14.105:6020>
Content-Length: 0
Record-Route:
<sip:xxxPT_002@10.161.14.59;lr>,<sip:xxxST_002@10.161.14.59;lr>,<sip:10.161.14.110:7000
;ftag=6661;lr>,<sip:xxxST_002@10.161.14.59;lr>,<sip:xxxSO_002@10.161.14.59;lr>,<
sip:xxxPO_002@10.161.14.59;lr>
Via: SIP/2.0/UDP
10.161.14.59;branch=z9hG4bK4f9932cde5bad6c36f103563aa96f449;xxxST_002,SIP/2.0/UDP
10.161.14.59;branch=z9hG4bK6f59072ad3fe644fcf851c16d3168bee;xxxIT_002,SIP/2.0/UDP
10.161.14.59;branch=z9hG4bK80752856b61f3aaf3f1d17e57067d067;xxxSO_002,SIP/2.0/UDP
10.161.14.59;branch=z9hG4bK8b46a43071f3848c711cb4bcf4b42335;xxxPO_002,SIP/2.0/UDP
10.161.14.105:6020
P-Charging-Vector: icid-value=43d9d426:f1135:7e37002e@pcscf.home2.jagarvayo.mot.dev;term-ioi=ims.XXX.com
0(5309) DEBUG:tm:relay_reply: sent buf=0x8138178: SIP/2.0 1..., shmem=0x40357f90: SIP/2.0 1
0(5309) DEBUG: add_to_tail_of_timer[1]: 0x40355c04
0(5309) DEBUG:destroy_avp_list: destroying list (nil)
0(5309) receive_msg: cleaning up
0(5309) SIP Request:
0(5309) method: <CANCEL>
0(5309) uri: <sip:10.161.14.104:6030>
0(5309) version: <SIP/2.0>
0(5309) parse_headers: flags=2
0(5309) Found param type 232, <branch> = <z9hG4bK4f9932cde5bad6c36f103563aa96f449>; state=6
0(5309) Found param type 238, <xxxST_002> = <n/a>; state=17
0(5309) end of header reached, state=5
0(5309) parse_headers: Via found, flags=2
0(5309) parse_headers: this is the first via
0(5309) After parse_msg...
0(5309) preparing to run routing scripts...
0(5309) parse_headers: flags=100
0(5309) DEBUG:parse_to:end of header reached, state=9
0(5309) DEBUG: get_hdr_field: <To> [37]; uri=[sip:user4@home2.jagarvayo.mot.dev]
0(5309) DEBUG: to body [<sip:user4@home2.jagarvayo.mot.dev>
]
0(5309) get_hdr_field: cseq <CSeq>: <1> <CANCEL>
0(5309) DEBUG:maxfwd:is_maxfwd_present: value = 70
0(5309) DEBUG: add_param: tag=6661
0(5309) DEBUG:parse_to:end of header reached, state=29
0(5309) xl_printf: final buffer length 101
0(5309) CANCEL: 10.161.14.59:5060 ci=1-26284@10.161.14.105 ft=6661 tt=<null> cseq=1 sip:10.161.14.104:6030
:
0(5309) parse_headers: flags=200
0(5309) DEBUG: get_hdr_body : content_length=0
0(5309) found end of header
0(5309) find_first_route: No Route headers found
0(5309) loose_route: There is no Route HF
0(5309) DEBUG: t_newtran: msg id=5 , global msg id=4 , T on entrance=0xffffffff
0(5309) parse_headers: flags=ffffffffffffffff
0(5309) parse_headers: flags=78
0(5309) t_lookup_request: start searching: hash=61655, isACK=0
0(5309) DEBUG: RFC3261 transaction matching failed
0(5309) DEBUG: t_lookup_request: no transaction found
0(5309) parse_headers: flags=78
0(5309) DEBUG: MD5 calculated: 1b7635cf6840ddd15282505b57290b27
0(5309) DEBUG: t_lookupOriginalT: searching on hash entry 61655
0(5309) DEBUG: RFC3261 transaction matched, tid=4f9932cde5bad6c36f103563aa96f449
0(5309) DEBUG: t_lookupOriginalT: canceled transaction found (0x40355ae0)!
0(5309) DEBUG: t_lookupOriginalT completed
0(5309) check_via_address(10.161.14.59, 10.161.14.59, 0)
0(5309) DEBUG: add_to_tail_of_timer[4]: 0x4035855c
0(5309) DEBUG: add_to_tail_of_timer[0]: 0x4035856c
0(5309) DEBUG: e2e_cancel: e2e cancel proceeding
0(5309) parse_headers: flags=ffffffffffffffff
0(5309) check_via_address(10.161.14.59, 10.161.14.59, 0)
0(5309) WARNING:vqm_resize: resize(0) called
0(5309) DEBUG: cleanup_uac_timers: RETR/FR timers reset
0(5309) DEBUG: add_to_tail_of_timer[2]: 0x40358490
0(5309) DEBUG:tm:_reply_light: reply sent out. buf=0x8138320: SIP/2.0 2..., shmem=0x40359558: SIP/2.0 2
0(5309) DEBUG:tm:_reply_light: finished
0(5309) SER: new transaction fwd'ed
0(5309) DEBUG:destroy_avp_list: destroying list (nil)
0(5309) receive_msg: cleaning up
0(5309) SIP Reply (status):
0(5309) version: <SIP/2.0>
0(5309) status: <481>
0(5309) reason: <Call Leg/Transaction Does Not Exist>
0(5309) parse_headers: flags=2
0(5309) DEBUG:parse_to:end of header reached, state=9
0(5309) DEBUG: get_hdr_field: <To> [37]; uri=[sip:user4@home2.jagarvayo.mot.dev]
0(5309) DEBUG: to body [<sip:user4@home2.jagarvayo.mot.dev>
]