16 Sep
2004
16 Sep
'04
12:56 a.m.
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@213.226.186.195 SIP/2.0..
From: <sip:70000031@213.226.186.195>;tag=0-13c4-4148435c-1f825298-792d..
To: <sip:70000037@213.226.186.195>..
Call-ID: cc4698-0-13c4-4148435c-1f825298-157@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@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@213.226.186.195>;tag=0-13c4-4148435c-1f825298-792d..
To:
<sip:70000037@213.226.186.195>;tag=855fc458e92794ef4dd58c58d38d34d1-0196..Call-ID:
cc4698-0-13c4-4148435c-1f825298-157@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@213.226.186.195 out_uri=sip:70000037@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@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@213.226.186.195]
ser[17364]: DEBUG: to body [<sip:70000037@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@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@213.226.186.195]
ser[17359]: DEBUG: to body [<sip:70000037@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