[Serusers] buggy CANCEL hangling?

Antanas Masevicius antanas.masevicius at z1sys.com
Thu Sep 16 12:53:22 CEST 2004 

adding ngrep dumps for both sides. In my setup:

82.135.142.16 A client
213.226.186.250 SER
213.226.186.195 SIP proxy
82.135.142.22 B client

On Thu, 16 Sep 2004, Jan Janak wrote:

> Could you send me SIP message dumps ?
>
>   Jan.
>
> On 16-09 12:28, Antanas Masevicius wrote:
> > 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
> > >
>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: B_CANCEL_prob.txt
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20040916/3cce06d0/attachment.txt>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: A_CANCEL_prob.txt
URL: <http://lists.sip-router.org/pipermail/sr-users/attachments/20040916/3cce06d0/attachment-0001.txt>

More information about the sr-users mailing list