[Serusers] buggy CANCEL hangling?

Antanas Masevicius antanas.masevicius at z1sys.com
Thu Sep 16 08:49:19 CEST 2004


i don't claim it is buggy, i asked "if it means buggy"? You are ones who
know if it may mean a bug or it is just a normal situation.

thank you,

Antanas

On Thu, 16 Sep 2004, Jiri Kuthan wrote:

> 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/
>




More information about the sr-users mailing list