[Serusers] buggy CANCEL hangling?

[Jiri Kuthan]

If you claim that CANCEL processing is buggy, the burden is on you 
to demonstrate there is RFC3261 violation. I am not aware of such.

-jiri

At 04:56 PM 9/15/2004, Antanas Masevicius wrote:
>Hello,
>
>my configuration follows:
>
>SIPclientA <--> SER(0.8.14) <--> SIPproxy <--> SIPclientB
>
>SER performs authorization and forwards all REGISTER requets to SIPproxy.
>
>Scenario:
>SIPclientA calls to SIPclientB, then changes his mind and releases call.
>SIPclientA generates CANCEL, but this CANCEL isn't forwarded to SIPproxy
>by SER and SIPproxy continues its conversation with SIPclientB by
>forwarding "180 Ringing" to SIPclientA.
>
>This isn't the case if SIPclientA receives "180 Ringing" by the time it
>sends CANCEL.
>
>What client gets in first case is:
>t_reply( t_cancel, cancel_msg, 200, "ok, no more pending branches" );
>
>and to my understanding is should be:
>t_reply( t_cancel, cancel_msg, 100, "trying to cancel" );
>
>ngrep looks like:
>
>U 82.135.142.16:5060 -> 213.226.186.195:5060
>CANCEL sip:70000037 at 213.226.186.195 SIP/2.0..
>From: <sip:70000031 at 213.226.186.195>;tag=0-13c4-4148435c-1f825298-792d..
>To: <sip:70000037 at 213.226.186.195>..
>  Call-ID: cc4698-0-13c4-4148435c-1f825298-157 at 213.226.186.195..CSeq: 2
>CANCEL..Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-4148435c-1f82552c-60b0..
>Max-Forwards: 70..
>Supported: 100rel..
>User-Agent: SIP-RG..
>Authorization: Digest username="70000031", realm="213.226.186.195",
>nonce="414844890f0b1edbefcbd
>  badce4c02ed59f058ef", uri="sip:70000037 at 213.226.186.195",
>response="5d22fe8fe3517aa72a51b8abc83bd9f2",
>algorithm=MD5..Content-Length: 0....
>
>#
>U 213.226.186.195:5060 -> 82.135.142.16:5060
>  SIP/2.0 200 ok -- no more pending branches..
>From: <sip:70000031 at 213.226.186.195>;tag=0-13c4-4148435c-1f825298-792d..
>To: <sip:70000037 at 213.226.186.195>;tag=855fc458e92794ef4dd58c58d38d34d1-0196..Call-ID:
>cc4698-0-13c4-4148435c-1f825298-157 at 213.226.186.195..CSeq: 2 CANCEL..
>Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-4148435c-1f82552c-60b0..Server: Sip EXpress router
>(0.8.14 (i386/linux))..Content-Length: 0..Warning: 392
>213.226.186.250:5060 "Noisy feedback tells:  pid=17371 req_src_ip=82.135.142.16 req_src_port=5060
>in_uri=sip:70000037 at 213.226.186.195 out_uri=sip:70000037 at 213.226.186.195
>via_cnt==1".
>
>Somehow SER doesn't detect in this case that it already forwarded INVITE
>and that is needs to be CANCEL'ed.
>
>Here i provide logs for both cases. If more logs are needed, tell me.
>What could be the reason of such behaviour?
>
>SER handling of CANCEL in case of proper termination:
>
>ser[17364]:  method:  <CANCEL>
>ser[17364]:  uri:     <sip:70000037 at 213.226.186.195>
>ser[17364]:  version: <SIP/2.0>
>ser[17364]: parse_headers: flags=1
>ser[17364]: end of header reached, state=9
>ser[17364]: DEBUG: get_hdr_field: <To> [32];
>uri=[sip:70000037 at 213.226.186.195]
>ser[17364]: DEBUG: to body [<sip:70000037 at 213.226.186.195>^M ]
>ser[17364]: get_hdr_field: cseq <CSeq>: <2> <CANCEL>
>ser[17364]: Found param type 232, <branch> =
><z9hG4bK-41483835-1f56c420-429>; state=16
>ser[17364]: end of header reached, state=5
>ser[17364]: parse_headers: Via found, flags=1
>ser[17364]: parse_headers: this is the first via
>ser[17364]: After parse_msg...
>ser[17364]: preparing to run routing scripts...
>ser[17364]: DEBUG: add_param: tag=0-13c4-41483835-1f56c394-362
>ser[17364]: end of header reached, state=29
>ser[17364]: parse_headers: flags=256
>ser[17364]: DEBUG: get_hdr_body : content_length=0
>ser[17364]: found end of header
>ser[17364]: find_first_route(): No Route headers found
>ser[17364]: loose_route(): There is no Route HF
>ser[17364]: DEBUG: t_addifnew: msg id=14502 , global msg id=14501 , T on
>entrance=0xffffffff
>ser[17364]: parse_headers: flags=-1
>ser[17364]: parse_headers: flags=60
>ser[17364]: t_lookup_request: start searching: hash=21608, isACK=0
>ser[17364]: DEBUG: RFC3261 transaction matching failed
>ser[17364]: DEBUG: t_lookup_request: no transaction found
>ser[17364]: DEBUG: t_lookupOriginalT: searching on hash entry 21608
>ser[17364]: DEBUG: RFC3261 transaction matched, tid=-41483835-1f56c420-429
>ser[17364]: DEBUG: t_lookupOriginalT: canceled transaction found
>(0x402ea680)!
>ser[17364]: DEBUG: t_lookupOriginalT completed
>ser[17364]: check_via_address(82.135.142.16, 82.135.142.16, 0)
>ser[17364]: DEBUG: add_to_tail_of_timer[4]: 0x402ed988
>ser[17364]: DEBUG: add_to_tail_of_timer[0]: 0x402ed99c
>ser[17364]: DEBUG: e2e_cancel: e2e cancel proceeding
>ser[17364]: parse_headers: flags=-1
>ser[17364]: check_via_address(82.135.142.16, 82.135.142.16, 0)
>ser[17364]: WARNING:vqm_resize: resize(0) called
>ser[17364]: DEBUG: cleanup_uacs: RETR/FR timers reset
>ser[17364]: DEBUG: add_to_tail_of_timer[2]: 0x402ed8a8
>ser[17364]: DEBUG: reply sent out. buf=0x80e07f0: SIP/2.0 2...,
>shmem=0x402cc9b8: SIP/2.0 2
>ser[17364]: DEBUG: t_reply: finished
>ser[17364]: DEBUG: e2e_cancel: sending 487
>ser[17364]: parse_headers: flags=-1
>ser[17364]: check_via_address(82.135.142.16, 82.135.142.16, 0)
>ser[17364]: DEBUG: cleanup_uacs: RETR/FR timers reset
>ser[17364]: DEBUG: add_to_tail_of_timer[4]: 0x402ea734
>ser[17364]: DEBUG: add_to_tail_of_timer[0]: 0x402ea748
>ser[17364]: DEBUG: reply sent out. buf=0x80e07f0: SIP/2.0 4...,
>shmem=0x402d14b8: SIP/2.0 4
>ser[17364]: DEBUG: t_reply: finished
>ser[17364]: SER: new transaction fwd'ed
>ser[17364]: DEBUG:destroy_avp_list: destroing list (nil)
>ser[17364]: receive_msg: cleaning up
>
>
>SER handling of CANCEL in case of inproper termination:
>
>ser[17359]: SIP Request:
>ser[17359]:  method:  <CANCEL>
>ser[17359]:  uri:     <sip:70000037 at 213.226.186.195>
>ser[17359]:  version: <SIP/2.0>
>ser[17359]: parse_headers: flags=1
>ser[17359]: end of header reached, state=9
>ser[17359]: DEBUG: get_hdr_field: <To> [32];
>uri=[sip:70000037 at 213.226.186.195]
>ser[17359]: DEBUG: to body [<sip:70000037 at 213.226.186.195>^M ]
>ser[17359]: get_hdr_field: cseq <CSeq>: <2> <CANCEL>
>ser[17359]: Found param type 232, <branch> =
><z9hG4bK-414837ae-1f54b338-47f1>; state=16
>ser[17359]: end of header reached, state=5
>ser[17359]: parse_headers: Via found, flags=1
>ser[17359]: parse_headers: this is the first via
>ser[17359]: After parse_msg...
>ser[17359]: preparing to run routing scripts...
>ser[17359]: DEBUG: add_param: tag=0-13c4-414837ad-1f54b1bc-5d0a
>ser[17359]: end of header reached, state=29
>ser[17359]: parse_headers: flags=256
>ser[17359]: DEBUG: get_hdr_body : content_length=0
>ser[17359]: found end of header
>ser[17359]: find_first_route(): No Route headers found
>ser[17359]: loose_route(): There is no Route HF
>ser[17359]: DEBUG: t_addifnew: msg id=14611 , global msg id=14608 , T on
>entrance=(nil)
>ser[17359]: parse_headers: flags=-1
>ser[17359]: parse_headers: flags=60
>ser[17359]: t_lookup_request: start searching: hash=36669, isACK=0
>ser[17359]: DEBUG: RFC3261 transaction matching failed
>ser[17359]: DEBUG: t_lookup_request: no transaction found
>ser[17359]: DEBUG: t_lookupOriginalT: searching on hash entry 36669
>ser[17359]: DEBUG: RFC3261 transaction matched,
>tid=-414837ae-1f54b338-47f1
>ser[17359]: DEBUG: t_lookupOriginalT: canceled transaction found
>(0x402ea680)!
>ser[17359]: DEBUG: t_lookupOriginalT completed
>ser[17359]: DEBUG: e2e_cancel: e2e cancel -- no more pending branches
>ser[17359]: parse_headers: flags=-1
>ser[17359]: check_via_address(82.135.142.16, 82.135.142.16, 0)
>ser[17359]: WARNING:vqm_resize: resize(0) called
>ser[17359]: DEBUG: cleanup_uacs: RETR/FR timers reset
>ser[17359]: DEBUG: add_to_tail_of_timer[2]: 0x402e4f98
>ser[17359]: DEBUG: reply sent out. buf=0x80e1540: SIP/2.0 2...,
>shmem=0x402d0828: SIP/2.0 2
>ser[17359]: DEBUG: t_reply: finished
>ser[17359]: DEBUG: e2e_cancel: sending 487
>ser[17359]: parse_headers: flags=-1
>ser[17359]: check_via_address(82.135.142.16, 82.135.142.16, 0)
>ser[17359]: DEBUG: cleanup_uacs: RETR/FR timers reset
>ser[17359]: DEBUG: add_to_tail_of_timer[4]: 0x402ea734
>ser[17359]: DEBUG: add_to_tail_of_timer[0]: 0x402ea748
>ser[17359]: DEBUG: reply sent out. buf=0x80e0c90: SIP/2.0 4...,
>shmem=0x402dada0: SIP/2.0 4
>ser[17359]: DEBUG: t_reply: finished
>ser[17359]: SER: new transaction fwd'ed
>ser[17359]: DEBUG:destroy_avp_list: destroing list (nil)
>
>
>Antanas
>
>_______________________________________________
>Serusers mailing list
>serusers at lists.iptel.org
>http://lists.iptel.org/mailman/listinfo/serusers

--
Jiri Kuthan            http://iptel.org/~jiri/