[Serusers] Need help to better understand transactions

Pauba, Kevin L KLPauba at west.com
Fri Jul 11 21:37:20 CEST 2008


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 at 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 at 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 at wic.west.com]
 0(28802) DEBUG: to body [<sip:4027160348 at wic.west.com>
]
 0(28802) Header Type: 4
 0(28802) header field type 4, name=<To>,
body=<<sip:4027160348 at wic.west.com>>
 0(28802) Header Type: 32
 0(28802) header field type 32, name=<Call-ID>,
body=<514+43+1215800190+24+t1b at 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 at 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 at wic.west.com]
 0(28802) textops: subst_uri_f: match - old uri=
[sip:9990001254027160348 at wic.west.com], new uri=
[sip:9990001254027160348 at 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 at 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 at 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 at wic.west.com]
 0(28802) DEBUG: to body [<sip:4027160348 at wic.west.com>
]
 0(28802) Header Type: 4
 0(28802) header field type 4, name=<To>,
body=<<sip:4027160348 at wic.west.com>>
 0(28802) Header Type: 32
 0(28802) header field type 32, name=<Call-ID>,
body=<514+43+1215800190+24+t1b at 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 at 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 at wic.west.com]
 0(28802) textops: subst_uri_f: match - old uri=
[sip:4027160348 at wic.west.com], new uri= [sip:4027160348 at 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 at 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!
 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20080711/0543913a/attachment.htm>


More information about the sr-users mailing list