[Serusers] buggy CANCEL hangling?

[Antanas Masevicius]

yes, in normal situation, i get "200 cancelling" and "487 Request
cancelled". In my case i just get "200 ok -- no more pending
branches", INVITE IS forwarded further and tries to establish a call, but
i don't see any forwarded CANCEL messages. Activity would look like this:

A client     SER                    B client

INVITE ----> INVITE       ------->
CANCEL ---->(doesn't forward)
       <---- [100 trying -- your call is important to us]
       <---- [200 ok no more pending br..]
       <---- [487 Request cancelled]

does this 100 trying means that SER doesn't intend to
cancel transaction?

On Thu, 16 Sep 2004, Jan Janak wrote:

> SER does not send 100 to CANCEL. It tries to lookup the original INVITE
> transaction and sends back 200 (immediately) if found. Then it sends 487
> when all downstream branches have been cancelled.
>
>    Jan.
>
> On 15-09 17:56, 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
>