Hi,
I'm running SER V0.9.6 and I'm having a problem with CANCELs.
A client sends and invite to SER that relays it on to a gateway. In this particular scenario, a CANCEL is send by the client after SER responds with the 100 trying. I had thought that SER would match the INVITE based on the branch tag and automatically send a CANCEL on to the gateway. Unfortunately, SER cannot find a matching transaction and, thus, the GATEWAY never receives a CANCEL..
Here's a snippet from the debugging output:
... 0(28802) SIP Request: 0(28802) method: <INVITE> 0(28802) uri: sip:4027160348@wic.west.com 0(28802) version: <SIP/2.0> 0(28802) parse_headers: flags=1 0(28802) Found param type 232, <branch> = <z9hG4bK1249933199>; state=16 0(28802) end of header reached, state=5 0(28802) Header Type: 1 0(28802) parse_headers: Via found, flags=1 0(28802) parse_headers: this is the first via 0(28802) header field type 1, name=<Via>, body=<SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK1249933199> 0(28802) preparing to run routing scripts... 0(28802) parse_headers: flags=128 0(28802) Header Type: 8 0(28802) header field type 8, name=<From>, body=<sip:4027161000@10.27.192.94;tag=3673666958> 0(28802) end of header reached, state=9 0(28802) DEBUG: get_hdr_field: <To> [31]; uri=[sip:4027160348@wic.west.com] 0(28802) DEBUG: to body [sip:4027160348@wic.west.com ] 0(28802) Header Type: 4 0(28802) header field type 4, name=<To>, body=<sip:4027160348@wic.west.com> 0(28802) Header Type: 32 0(28802) header field type 32, name=<Call-ID>, body=514+43+1215800190+24+t1b@10.27.192.94 0(28802) get_hdr_field: cseq <CSeq>: <2> <INVITE> 0(28802) Header Type: 16 0(28802) header field type 16, name=<CSeq>, body=<2 INVITE> 0(28802) Header Type: 64 0(28802) header field type 64, name=<Contact>, body=<sip:e514@10.27.192.94> 0(28802) Header Type: 33554432 0(28802) header field type 33554432, name=<user-agent>, body=<oSIP/wicsip-3.3.4> 0(28802) Header Type: 1073741824 0(28802) header field type 1073741824, name=<x-west-rg>, body=<0:17> 0(28802) Header Type: 1024 0(28802) header field type 1024, name=<Content-Type>, body=<application/sdp> 0(28802) DEBUG: get_hdr_body : content_length=111 0(28802) Header Type: 2048 0(28802) header field type 2048, name=<Content-Length>, body=<111 > 0(28802) found end of header 0(28802) Header Type: -1 0(28802) DEBUG: is_maxfwd_present: max_forwards header not found! 0(28802) grep_sock_info - checking if host==us: 12==13 && [wic.west.com] == [10.27.193.119] 0(28802) grep_sock_info - checking if port 5060 matches port 5060 0(28802) grep_sock_info - checking if host==us: 12==13 && [wic.west.com] == [10.27.193.119] 0(28802) grep_sock_info - checking if port 5060 matches port 5060 0(28802) check_self: host != me 0(28802) subst_run: running. r=0 0(28802) subst_run: matched (0, 0): [] 0(28802) subst_run: running. r=1 0(28802) subst_f: lst was (nil) 0(28802) subst_run: running. r=0 0(28802) subst_run: matched (0, 36): [sip:9990001254027160348@wic.west.com] 0(28802) textops: subst_uri_f: match - old uri= [sip:9990001254027160348@wic.west.com], new uri= [sip:9990001254027160348@10.27.202.157] 0(28802) DEBUG: t_newtran: msg id=36 , global msg id=35 , T on entrance=(nil) 0(28802) parse_headers: flags=-1 0(28802) parse_headers: flags=60 0(28802) t_lookup_request: start searching: hash=34792, isACK=0 0(28802) DEBUG: RFC3261 transaction matching failed 0(28802) DEBUG: t_lookup_request: no transaction found 0(28802) DEBUG: add_param: tag=3673666958 0(28802) end of header reached, state=29 0(28802) SER: new INVITE 0(28802) parse_headers: flags=-1 0(28802) check_via_address(10.27.192.94, 10.27.192.94, 0) 0(28802) WARNING:vqm_resize: resize(0) called 0(28802) DEBUG: reply sent out. buf=0x810be30: SIP/2.0 1..., shmem=0x422c3c60: SIP/2.0 1 0(28802) DEBUG: _reply_light: finished 0(28802) DEBUG: mk_proxy: doing DNS lookup... 0(28802) check_via_address(10.27.192.94, 10.27.192.94, 0) 0(28802) DEBUG: add_to_tail_of_timer[4]: 0x422c2ac0 0(28802) DEBUG: add_to_tail_of_timer[0]: 0x422c2ad0 0(28802) SER: new transaction fwd'ed 0(28802) DEBUG:destroy_avp_list: destroying list (nil) 0(28802) receive_msg: cleaning up 0(28802)
...
0(28802) SIP Request: 0(28802) method: <CANCEL> 0(28802) uri: sip:4027160348@wic.west.com 0(28802) version: <SIP/2.0> 0(28802) parse_headers: flags=1 0(28802) Found param type 232, <branch> = <z9hG4bK1249933199>; state=16 0(28802) end of header reached, state=5 0(28802) Header Type: 1 0(28802) parse_headers: Via found, flags=1 0(28802) parse_headers: this is the first via 0(28802) header field type 1, name=<Via>, body=<SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK1249933199> 0(28802) preparing to run routing scripts... 0(28802) parse_headers: flags=128 0(28802) Header Type: 8 0(28802) header field type 8, name=<From>, body=<sip:4027161000@10.27.192.94;tag=3673666958> 0(28802) end of header reached, state=9 0(28802) DEBUG: get_hdr_field: <To> [31]; uri=[sip:4027160348@wic.west.com] 0(28802) DEBUG: to body [sip:4027160348@wic.west.com ] 0(28802) Header Type: 4 0(28802) header field type 4, name=<To>, body=<sip:4027160348@wic.west.com> 0(28802) Header Type: 32 0(28802) header field type 32, name=<Call-ID>, body=514+43+1215800190+24+t1b@10.27.192.94 0(28802) get_hdr_field: cseq <CSeq>: <2> <CANCEL> 0(28802) Header Type: 16 0(28802) header field type 16, name=<CSeq>, body=<2 CANCEL> 0(28802) Header Type: 64 0(28802) header field type 64, name=<Contact>, body=<sip:514+43+1215800190+24+t1b@10.27.192.94> 0(28802) Header Type: 33554432 0(28802) header field type 33554432, name=<user-agent>, body=<oSIP/wicsip-3.3.4> 0(28802) Header Type: 1073741824 0(28802) header field type 1073741824, name=<x-west-rg>, body=<0:0> 0(28802) DEBUG: get_hdr_body : content_length=0 0(28802) Header Type: 2048 0(28802) header field type 2048, name=<Content-Length>, body=<0> 0(28802) found end of header 0(28802) Header Type: -1 0(28802) DEBUG: is_maxfwd_present: max_forwards header not found! 0(28802) grep_sock_info - checking if host==us: 12==13 && [wic.west.com] == [10.27.193.119] 0(28802) grep_sock_info - checking if port 5060 matches port 5060 0(28802) grep_sock_info - checking if host==us: 12==13 && [wic.west.com] == [10.27.193.119] 0(28802) grep_sock_info - checking if port 5060 matches port 5060 0(28802) check_self: host != me 0(28802) subst_run: running. r=0 0(28802) subst_run: matched (0, 27): [sip:4027160348@wic.west.com] 0(28802) textops: subst_uri_f: match - old uri= [sip:4027160348@wic.west.com], new uri= [sip:4027160348@10.27.202.157] 0(28802) subst_run: running. r=0 0(28802) subst_run: matched (0, 0): [] 0(28802) XLOG: xl_print_log: final buffer length 99 0(28802) time [Fri Jul 11 14:15:52 2008] KLP: CANCEL REQUEST - ruri sip:9990001254027160348@10.27.202.157 0(28802) DEBUG: t_check: msg id=40 global id=37 T start=0xffffffff 0(28802) parse_headers: flags=-1 0(28802) parse_headers: flags=60 0(28802) t_lookup_request: start searching: hash=34792, isACK=0 0(28802) DEBUG: RFC3261 transaction matching failed 0(28802) DEBUG: t_lookup_request: no transaction found 0(28802) DEBUG: t_check: msg id=40 global id=40 T end=(nil) 0(28802) XLOG: xl_print_log: final buffer length 64 0(28802) time [Fri Jul 11 14:15:52 2008] KLP: CANCEL REQUEST -- ignoring 0(28802) DEBUG:destroy_avp_list: destroying list (nil) 0(28802) receive_msg: cleaning up 0(28802)
I've verified that the branchID of the INVITE matches that of the CANCEL so I had expected the t_lookup_request() to succeed.
Do I misunderstand the way transactions work? Any suggestions on how I might get this to work?
Any help is appreciated.
Thanks!
Pauba, Kevin L wrote:
A client sends and invite to SER that relays it on to a gateway. In this particular scenario, a CANCEL is send by the client after SER responds with the 100 trying. I had thought that SER would match the INVITE based on the branch tag and automatically send a CANCEL on to the gateway. Unfortunately, SER cannot find a matching transaction and, thus, the GATEWAY never receives a CANCEL..
Very odd. Can you possibly supply a trace of the entire interchange? They usually help more then debug output.
Regards, Martin
Thank you for your response, Martin!
Here's the output from "ngrep -T -W byline -I tcpdump.pcap z9hG4bK2689300793 port 5060" and the Graph output from Wireshark (hopefully, Outlook doesn't screw up any of the formatting):
input: tcpdump.pcap filter: (ip or ip6) and ( port 5060 ) match: z9hG4bK2689300793 ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ######################################################################## ##### U +4294720244.814738 10.27.192.94:5060 -> 10.27.193.119:5060 INVITE sip:4027160348@wic.west.com SIP/2.0. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 INVITE. Contact: sip:e514@10.27.192.94. user-agent: oSIP/wicsip-3.3.4. x-west-rg: 0:17. Content-Type: application/sdp. Content-Length: 111 . . v=0. o=WestInteractive 299 0 IN IP4 10.27.202.94. s=t1b. c=IN IP4 10.27.202.94. t=0 0. m=audio 2326 RTP/AVP 0.
# U +0.002405 10.27.193.119:5060 -> 10.27.192.94:5060 SIP/2.0 100 trying -- your call is important to us. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 INVITE. Server: Sip EXpress router (0.9.6 (i386/linux)). Content-Length: 0. Warning: 392 10.27.193.119:5060 "Noisy feedback tells: pid=26790 req_src_ip=10.27.192.94 req_src_port=5060 in_uri=sip:4027160348@wic.west.com out_uri=sip:9990001254027160348@10.27.202.157 via_cnt==1". .
# U +0.000082 10.27.193.119:5060 -> 10.27.202.157:5060 INVITE sip:9990001254027160348@10.27.202.157 SIP/2.0. Max-Forwards: 10. Via: SIP/2.0/UDP 10.27.193.119;branch=z9hG4bKf70c.02c6082.0. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 INVITE. Contact: sip:e514@10.27.192.94. user-agent: oSIP/wicsip-3.3.4. x-west-rg: 0:17. Content-Type: application/sdp. Content-Length: 111 . . v=0. o=WestInteractive 299 0 IN IP4 10.27.202.94. s=t1b. c=IN IP4 10.27.202.94. t=0 0. m=audio 2326 RTP/AVP 0.
# U +0.007012 10.27.202.157:5060 -> 10.27.193.119:5060 SIP/2.0 100 Trying. Via: SIP/2.0/UDP 10.27.193.119;branch=z9hG4bKf70c.02c6082.0. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com;tag=gK09857929. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 INVITE. Content-Length: 0. .
###### U +1.011362 10.27.192.94:5060 -> 10.27.193.119:5060 CANCEL sip:4027160348@wic.west.com SIP/2.0. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 CANCEL. Contact: sip:514+50+1215794994+24+t1b@10.27.192.94. user-agent: oSIP/wicsip-3.3.4. x-west-rg: 0:0. Content-Length: 0. .
# U +0.519930 10.27.202.157:5060 -> 10.27.193.119:5060 SIP/2.0 180 Ringing. Via: SIP/2.0/UDP 10.27.193.119;branch=z9hG4bKf70c.02c6082.0. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com;tag=gK09857929. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 INVITE. Contact: sip:9990001254027160348@10.27.202.157:5060. Allow: INVITE,ACK,CANCEL,BYE,REGISTER,REFER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE, OPTIONS,MESSAGE,PUBLISH. Content-Length: 181. Content-Disposition: session; handling=optional. Content-Type: application/sdp. . v=0. o=Sonus_UAC 12186 15921 IN IP4 10.27.202.157. s=SIP Media Capabilities. c=IN IP4 10.27.202.153. t=0 0. m=audio 8682 RTP/AVP 0. a=rtpmap:0 PCMU/8000. a=sendrecv. a=maxptime:20.
# U +0.000162 10.27.193.119:5060 -> 10.27.192.94:5060 SIP/2.0 180 Ringing. Max-Forwards: 10. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com;tag=gK09857929. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 INVITE. Contact: sip:9990001254027160348@10.27.202.157:5060. Allow: INVITE,ACK,CANCEL,BYE,REGISTER,REFER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE, OPTIONS,MESSAGE,PUBLISH. Content-Length: 181. Content-Disposition: session; handling=optional. Content-Type: application/sdp. . v=0. o=Sonus_UAC 12186 15921 IN IP4 10.27.202.157. s=SIP Media Capabilities. c=IN IP4 10.27.202.153. t=0 0. m=audio 8682 RTP/AVP 0. a=rtpmap:0 PCMU/8000. a=sendrecv. a=maxptime:20.
### U +0.796229 10.27.192.94:5060 -> 10.27.193.119:5060 CANCEL sip:4027160348@wic.west.com SIP/2.0. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 CANCEL. Contact: sip:514+50+1215794994+24+t1b@10.27.192.94. user-agent: oSIP/wicsip-3.3.4. x-west-rg: 0:0. Content-Length: 0. .
##################### U +2.989828 10.27.192.94:5060 -> 10.27.193.119:5060 CANCEL sip:4027160348@wic.west.com SIP/2.0. Via: SIP/2.0/UDP 10.27.192.94:5060;branch=z9hG4bK2689300793. From: sip:4027161000@10.27.192.94;tag=2553218672. To: sip:4027160348@wic.west.com. Call-ID: 514+50+1215794994+24+t1b@10.27.192.94. CSeq: 1 CANCEL. Contact: sip:514+50+1215794994+24+t1b@10.27.192.94. user-agent: oSIP/wicsip-3.3.4. x-west-rg: 0:0. Content-Length: 0. .
####exit
|Time | 10.27.192.94 | 10.27.193.119 | 10.27.202.157 | |273.380 | INVITE SDP ( g711U) | |SIP From: sip:4027161000@10.27.192.94 To:sip:4027160348@wic.west.com | |(5060) ------------------> (5060) | | |273.382 | 100 trying -- your call is important to us | |SIP Status | |(5060) <------------------ (5060) | | |273.383 | | INVITE SDP ( g711U) |SIP Request | | |(5060) ------------------> (5060) | |273.390 | | 100 Trying| |SIP Status | | |(5060) <------------------ (5060) | |274.401 | CANCEL | | |SIP Request | |(5060) ------------------> (5060) | | |274.921 | | 180 Ringing SDP ( g711U) |SIP Status | | |(5060) <------------------ (5060) | |274.921 | 180 Ringing SDP ( g711U) | |SIP Status | |(5060) <------------------ (5060) | | |275.717 | CANCEL | | |SIP Request | |(5060) ------------------> (5060) | | |278.707 | CANCEL | | |SIP Request | |(5060) ------------------> (5060) | |
Pauba, Kevin L wrote:
Here's the output from "ngrep -T -W byline -I tcpdump.pcap z9hG4bK2689300793 port 5060" and the Graph output from Wireshark (hopefully, Outlook doesn't screw up any of the formatting):
Looks like SER is just simply dropping the CANCEL. Doesn't look like there is anything wrong with it. Maybe you are doing something wrong in your config. Make sure that the CANCEL actually goes into a t_relay() (or possibly some other function from tm, I always keep forgetting which does what when it comes to CANCELs and ACKs).
Just to see if it is something with your config, you may add a
if (method == "CANCEL") { t_relay(); break; }
somewhere very early in your config. If that makes it work, there is something wrong further down. If that doesn't help either, than I am at a bit of a loss.
Best regards, Martin
-
Martin Hoffmann -
Pauba, Kevin L