[Serusers] buggy CANCEL hangling?

Antanas Masevicius zolia at z1sys.com
Wed Sep 15 16:56:20 CEST 2004


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




More information about the sr-users mailing list