[Serusers] Need help to better understand transactions

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=&lt;514+43+1215800190+24+t1b(a)10.27.192.94&gt; 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=&lt;514+43+1215800190+24+t1b(a)10.27.192.94&gt; 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!