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@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
Serusers mailing list serusers@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serusers