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
If you claim that CANCEL processing is buggy, the burden is on you to demonstrate there is RFC3261 violation. I am not aware of such.
-jiri
At 04:56 PM 9/15/2004, 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
-- Jiri Kuthan http://iptel.org/~jiri/
i don't claim it is buggy, i asked "if it means buggy"? You are ones who know if it may mean a bug or it is just a normal situation.
thank you,
Antanas
On Thu, 16 Sep 2004, Jiri Kuthan wrote:
If you claim that CANCEL processing is buggy, the burden is on you to demonstrate there is RFC3261 violation. I am not aware of such.
-jiri
At 04:56 PM 9/15/2004, 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
-- Jiri Kuthan http://iptel.org/~jiri/
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
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
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
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
B_CANCEL_prob does not contain contain any CANCEL, the last message I can see is 18
In A_CANCEL_prob SER forwards the INVITE to itself but different number, what happens next I do not know because I do not see the messages being sent over the loopback. The request probably did not make it to the callee and so ser sends "no more pending branches". That's correct.
Jan.
On 16-09 13:53, Antanas Masevicius wrote:
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
interface: eth2 (213.226.186.250/255.255.255.255) match: 82.135.142.16 ######################## U 213.226.186.250:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
## U 213.226.186.250:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
############ U 213.226.186.195:5060 -> 213.226.186.250:5060 SIP/2.0 180 Ringing. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, REFER, NOTIFY, REGISTER. Supported: timer . Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. To: sip:70000037@213.226.186.195. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. X-SHOUT-Channel: INBOUND 1:15:26:1. CSeq: 2 INVITE. User-Agent: SHOUT 3.3.4v6. Content-Length: 0. .
###############exit 55 received, 0 dropped
interface: eth1 (213.226.186.224/255.255.255.224) match: 82.135.142.16 ##################################### U 82.135.142.16:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 401 Unauthorized. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=58451be0870a0a50b35bf0ab28a442d9.032c. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. WWW-Authenticate: Digest realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f". Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20513 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". .
# U 82.135.142.16:5060 -> 213.226.186.195:5060 ACK sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=58451be0870a0a50b35bf0ab28a442d9.032c. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 ACK. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. Max-Forwards: 70. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Length: 0. .
# U 82.135.142.16:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 100 trying -- your call is important to us. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20518 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". .
############# 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-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 CANCEL. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="da3636f2b421718f7e47bb1a1b3ad7f1", 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-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 CANCEL. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20519 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". .
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 487 Request cancelled. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20519 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". .
## U 82.135.142.16:5060 -> 213.226.186.195:5060 ACK sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 ACK. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Length: 0. .
###########################################exit 122 received, 0 dropped
On Thu, 16 Sep 2004, Jan Janak wrote:
B_CANCEL_prob does not contain contain any CANCEL, the last message I can see is 18
Yes, this is exaclty what it is. Last message SER sends to 213.226.186.195 is INVITE and last what SER gets is 180 Ringing.
In A_CANCEL_prob SER forwards the INVITE to itself but different number, what happens next I do not know because I do not see the messages being sent over the loopback. The request probably did not make it to the callee and so ser sends "no more pending branches". That's correct.
SER in our setup works as transparent proxy (iptables redirects all traffic to SER and after authorization SER forwards it to original destination (213.226.186.195). After sniffing all interfaces i didn't detected any other messages i sent you last time. I added a cut from SER log to this CANCEL related transaction if it may be of any help.
Could it be some sort of delay related?
Antanas
Jan.
On 16-09 13:53, Antanas Masevicius wrote:
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
interface: eth2 (213.226.186.250/255.255.255.255) match: 82.135.142.16 ######################## U 213.226.186.250:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
## U 213.226.186.250:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
############ U 213.226.186.195:5060 -> 213.226.186.250:5060 SIP/2.0 180 Ringing. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, REFER, NOTIFY, REGISTER. Supported: timer . Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. To: sip:70000037@213.226.186.195. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. X-SHOUT-Channel: INBOUND 1:15:26:1. CSeq: 2 INVITE. User-Agent: SHOUT 3.3.4v6. Content-Length: 0. .
###############exit 55 received, 0 dropped
interface: eth1 (213.226.186.224/255.255.255.224) match: 82.135.142.16 ##################################### U 82.135.142.16:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 401 Unauthorized. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=58451be0870a0a50b35bf0ab28a442d9.032c. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. WWW-Authenticate: Digest realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f". Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20513 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". .
# U 82.135.142.16:5060 -> 213.226.186.195:5060 ACK sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=58451be0870a0a50b35bf0ab28a442d9.032c. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 ACK. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. Max-Forwards: 70. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Length: 0. .
# U 82.135.142.16:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 100 trying -- your call is important to us. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20518 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". .
############# 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-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 CANCEL. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="da3636f2b421718f7e47bb1a1b3ad7f1", 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-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 CANCEL. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20519 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". .
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 487 Request cancelled. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20519 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". .
## U 82.135.142.16:5060 -> 213.226.186.195:5060 ACK sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 ACK. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Length: 0. .
###########################################exit 122 received, 0 dropped
Serusers mailing list serusers@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serusers
I am pretty sure that the dumps are not complete, 100 is missing in B_CANCEL which SER would send for sure before it relays the INVITE.
Neither the second dump is complete, in the Warning header field you can see that ser relays the message to itself over loopback (see out_uri).
Jan.
On 17-09 11:19, Antanas Masevicius wrote:
On Thu, 16 Sep 2004, Jan Janak wrote:
B_CANCEL_prob does not contain contain any CANCEL, the last message I can see is 18
Yes, this is exaclty what it is. Last message SER sends to 213.226.186.195 is INVITE and last what SER gets is 180 Ringing.
In A_CANCEL_prob SER forwards the INVITE to itself but different number, what happens next I do not know because I do not see the messages being sent over the loopback. The request probably did not make it to the callee and so ser sends "no more pending branches". That's correct.
SER in our setup works as transparent proxy (iptables redirects all traffic to SER and after authorization SER forwards it to original destination (213.226.186.195). After sniffing all interfaces i didn't detected any other messages i sent you last time. I added a cut from SER log to this CANCEL related transaction if it may be of any help.
Could it be some sort of delay related?
Antanas
Jan.
On 16-09 13:53, Antanas Masevicius wrote:
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
interface: eth2 (213.226.186.250/255.255.255.255) match: 82.135.142.16 ######################## U 213.226.186.250:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
## U 213.226.186.250:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
############ U 213.226.186.195:5060 -> 213.226.186.250:5060 SIP/2.0 180 Ringing. Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, REFER, NOTIFY, REGISTER. Supported: timer . Via: SIP/2.0/UDP 213.226.186.250;branch=z9hG4bKa706.a59b4431.0. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Record-Route: sip:70000037@213.226.186.250;ftag=0-13c4-41496c88-66b7b4-cac;lr=on. To: sip:70000037@213.226.186.195. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. X-SHOUT-Channel: INBOUND 1:15:26:1. CSeq: 2 INVITE. User-Agent: SHOUT 3.3.4v6. Content-Length: 0. .
###############exit 55 received, 0 dropped
interface: eth1 (213.226.186.224/255.255.255.224) match: 82.135.142.16 ##################################### U 82.135.142.16:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 401 Unauthorized. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=58451be0870a0a50b35bf0ab28a442d9.032c. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. WWW-Authenticate: Digest realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f". Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20513 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". .
# U 82.135.142.16:5060 -> 213.226.186.195:5060 ACK sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=58451be0870a0a50b35bf0ab28a442d9.032c. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 1 ACK. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b7b4-7d75. Max-Forwards: 70. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Length: 0. .
# U 82.135.142.16:5060 -> 213.226.186.195:5060 INVITE sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="492b8c270b7c7a570a5d5d1b32342ca5", algorithm=MD5. Content-Type: application/sdp. Content-Length: 227. . v=0. o=SIP-TA 0 0 IN IP4 82.135.142.16. s=52878E10 07D0 52878E10 07D0 02 0. c=IN IP4 82.135.142.16. t=0 0. m=audio 4014 RTP/AVP 18 8 0 4. a=rtpmap:18 G729/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:0 PCMU/8000. a=rtpmap:4 G723/8000.
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 100 trying -- your call is important to us. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20518 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". .
############# 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-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 CANCEL. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. Supported: 100rel. User-Agent: SIP-RG. Authorization: Digest username="70000031", realm="213.226.186.195", nonce="41496db50f6ff90e24656717077421318025d85f", uri="sip:70000037@213.226.186.195", response="da3636f2b421718f7e47bb1a1b3ad7f1", 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-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 CANCEL. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20519 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". .
# U 213.226.186.195:5060 -> 82.135.142.16:5060 SIP/2.0 487 Request cancelled. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 INVITE. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Server: Sip EXpress router (0.8.14 (i386/linux)). Content-Length: 0. Warning: 392 213.226.186.250:5060 "Noisy feedback tells: pid=20519 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". .
## U 82.135.142.16:5060 -> 213.226.186.195:5060 ACK sip:70000037@213.226.186.195 SIP/2.0. From: sip:70000031@213.226.186.195;tag=0-13c4-41496c88-66b7b4-cac. To: sip:70000037@213.226.186.195;tag=855fc458e92794ef4dd58c58d38d34d1-da37. Call-ID: cc4544-0-13c4-41496c88-66b7b4-72fe@213.226.186.195. CSeq: 2 ACK. Via: SIP/2.0/UDP 82.135.142.16:5060;branch=z9hG4bK-41496c88-66b840-6d7b. Max-Forwards: 70. User-Agent: SIP-RG. Contact: sip:70000031@82.135.142.16. Content-Length: 0. .
###########################################exit 122 received, 0 dropped
Serusers mailing list serusers@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serusers
Sep 17 10:54:45 siege ./ser[20518]: SIP Request: Sep 17 10:54:45 siege ./ser[20518]: method: <INVITE> Sep 17 10:54:45 siege ./ser[20518]: uri: sip:70000037@213.226.186.195 Sep 17 10:54:45 siege ./ser[20518]: version: <SIP/2.0> Sep 17 10:54:45 siege ./ser[20518]: parse_headers: flags=1 Sep 17 10:54:45 siege ./ser[20518]: end of header reached, state=9 Sep 17 10:54:45 siege ./ser[20518]: DEBUG: get_hdr_field: <To> [32]; uri=[sip:70000037@213.226.186.195] Sep 17 10:54:45 siege ./ser[20518]: DEBUG: to body [sip:70000037@213.226.186.195^M ] Sep 17 10:54:45 siege ./ser[20518]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Sep 17 10:54:45 siege ./ser[20518]: Found param type 232, <branch> = <z9hG4bK-414a9843-402bb98-1030>; state=16 Sep 17 10:54:45 siege ./ser[20518]: end of header reached, state=5 Sep 17 10:54:45 siege ./ser[20518]: parse_headers: Via found, flags=1 Sep 17 10:54:45 siege ./ser[20518]: parse_headers: this is the first via Sep 17 10:54:45 siege ./ser[20518]: After parse_msg... Sep 17 10:54:45 siege ./ser[20518]: preparing to run routing scripts... Sep 17 10:54:45 siege ./ser[20518]: DEBUG: add_param: tag=0-13c4-414a9843-402bb98-1973 Sep 17 10:54:45 siege ./ser[20518]: end of header reached, state=29 Sep 17 10:54:45 siege ./ser[20518]: parse_headers: flags=256 Sep 17 10:54:45 siege ./ser[20518]: DEBUG: get_hdr_body : content_length=227 Sep 17 10:54:45 siege ./ser[20518]: found end of header Sep 17 10:54:45 siege ./ser[20518]: find_first_route(): No Route headers found Sep 17 10:54:45 siege ./ser[20518]: loose_route(): There is no Route HF Sep 17 10:54:45 siege ./ser[20518]: parse_headers: flags=4096 Sep 17 10:54:45 siege ./ser[20518]: pre_auth(): Credentials with given realm not found Sep 17 10:54:45 siege ./ser[20518]: build_auth_hf(): 'WWW-Authenticate: Digest realm="213.226.186.195", nonce="414a99719d77734549ab6e83f2227bdb0db8218d"^M ' Sep 17 10:54:45 siege ./ser[20518]: parse_headers: flags=-1 Sep 17 10:54:45 siege ./ser[20518]: check_via_address(82.135.142.16, 82.135.142.16, 0) Sep 17 10:54:45 siege ./ser[20518]: DEBUG: get_out_socket: socket determined: 0 Sep 17 10:54:45 siege ./ser[20518]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:45 siege ./ser[20518]: receive_msg: cleaning up Sep 17 10:54:45 siege ./ser[20507]: SIP Request: Sep 17 10:54:45 siege ./ser[20507]: method: <ACK> Sep 17 10:54:45 siege ./ser[20507]: uri: sip:70000037@213.226.186.195 Sep 17 10:54:45 siege ./ser[20507]: version: <SIP/2.0> Sep 17 10:54:45 siege ./ser[20507]: parse_headers: flags=1 Sep 17 10:54:45 siege ./ser[20507]: DEBUG: add_param: tag=58451be0870a0a50b35bf0ab28a442d9.7dfd Sep 17 10:54:45 siege ./ser[20507]: end of header reached, state=29 Sep 17 10:54:45 siege ./ser[20507]: DEBUG: get_hdr_field: <To> [74]; uri=[sip:70000037@213.226.186.195] Sep 17 10:54:45 siege ./ser[20507]: DEBUG: to body [sip:70000037@213.226.186.195] Sep 17 10:54:45 siege ./ser[20507]: get_hdr_field: cseq <CSeq>: <1> <ACK> Sep 17 10:54:45 siege ./ser[20507]: Found param type 232, <branch> = <z9hG4bK-414a9843-402bb98-1030>; state=16 Sep 17 10:54:45 siege ./ser[20507]: end of header reached, state=5 Sep 17 10:54:45 siege ./ser[20507]: parse_headers: Via found, flags=1 Sep 17 10:54:45 siege ./ser[20507]: parse_headers: this is the first via Sep 17 10:54:45 siege ./ser[20507]: After parse_msg... Sep 17 10:54:45 siege ./ser[20507]: preparing to run routing scripts... Sep 17 10:54:45 siege ./ser[20507]: parse_headers: flags=4 Sep 17 10:54:45 siege ./ser[20507]: DEBUG: sl_filter_ACK : local ACK found -> dropping it! Sep 17 10:54:45 siege ./ser[20507]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:45 siege ./ser[20507]: receive_msg: cleaning up Sep 17 10:54:45 siege ./ser[20512]: SIP Request: Sep 17 10:54:45 siege ./ser[20512]: method: <INVITE> Sep 17 10:54:45 siege ./ser[20512]: uri: sip:70000037@213.226.186.195 Sep 17 10:54:45 siege ./ser[20512]: version: <SIP/2.0> Sep 17 10:54:45 siege ./ser[20512]: parse_headers: flags=1 Sep 17 10:54:45 siege ./ser[20512]: end of header reached, state=9 Sep 17 10:54:45 siege ./ser[20512]: DEBUG: get_hdr_field: <To> [32]; uri=[sip:70000037@213.226.186.195] Sep 17 10:54:45 siege ./ser[20512]: DEBUG: to body [sip:70000037@213.226.186.195^M ] Sep 17 10:54:45 siege ./ser[20512]: get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 17 10:54:45 siege ./ser[20512]: Found param type 232, <branch> = <z9hG4bK-414a9843-402bc24-1a2e>; state=16 Sep 17 10:54:45 siege ./ser[20512]: end of header reached, state=5 Sep 17 10:54:45 siege ./ser[20512]: parse_headers: Via found, flags=1 Sep 17 10:54:45 siege ./ser[20512]: parse_headers: this is the first via Sep 17 10:54:45 siege ./ser[20512]: After parse_msg... Sep 17 10:54:45 siege ./ser[20512]: preparing to run routing scripts... Sep 17 10:54:45 siege ./ser[20512]: DEBUG: add_param: tag=0-13c4-414a9843-402bb98-1973 Sep 17 10:54:45 siege ./ser[20512]: end of header reached, state=29 Sep 17 10:54:45 siege ./ser[20512]: parse_headers: flags=256 Sep 17 10:54:45 siege ./ser[20512]: DEBUG: get_hdr_body : content_length=227 Sep 17 10:54:45 siege ./ser[20512]: found end of header Sep 17 10:54:45 siege ./ser[20512]: find_first_route(): No Route headers found Sep 17 10:54:45 siege ./ser[20512]: loose_route(): There is no Route HF Sep 17 10:54:45 siege ./ser[20512]: check_nonce(): comparing [414a99719d77734549ab6e83f2227bdb0db8218d] and [414a99719d77734549ab6e83f2227bdb0db8218d] Sep 17 10:54:45 siege ./ser[20512]: query="select password from subscriber where username='70000031' AND domain='213.226.186.195' AND acc_ip='82.135.142.16'" Sep 17 10:54:45 siege ./ser[20512]: HA1 string calculated: ef55dba3f323e9dd829e746d56c34938 Sep 17 10:54:45 siege ./ser[20512]: check_response(): Our result = 'df8104e1577572762333556115d2b8e3' Sep 17 10:54:45 siege ./ser[20512]: check_response(): Authorization is OK Sep 17 10:54:45 siege ./ser[20512]: save_rpid(): rpid value is '' Sep 17 10:54:45 siege ./ser[20512]: DEBUG: t_addifnew: msg id=5816 , global msg id=5815 , T on entrance=0xffffffff Sep 17 10:54:45 siege ./ser[20512]: parse_headers: flags=-1 Sep 17 10:54:45 siege ./ser[20512]: parse_headers: flags=60 Sep 17 10:54:45 siege ./ser[20512]: t_lookup_request: start searching: hash=32382, isACK=0 Sep 17 10:54:45 siege ./ser[20512]: DEBUG: RFC3261 transaction matching failed Sep 17 10:54:45 siege ./ser[20512]: DEBUG: t_lookup_request: no transaction found Sep 17 10:54:45 siege ./ser[20512]: DEBUG: get_out_socket: socket determined: 0 Sep 17 10:54:45 siege ./ser[20512]: SER: new INVITE Sep 17 10:54:45 siege ./ser[20512]: parse_headers: flags=-1 Sep 17 10:54:45 siege ./ser[20512]: check_via_address(82.135.142.16, 82.135.142.16, 0) Sep 17 10:54:45 siege ./ser[20512]: WARNING:vqm_resize: resize(0) called Sep 17 10:54:45 siege ./ser[20512]: DEBUG: reply sent out. buf=0x80e1200: SIP/2.0 1..., shmem=0x402e4d80: SIP/2.0 1 Sep 17 10:54:45 siege ./ser[20512]: DEBUG: t_reply: finished Sep 17 10:54:45 siege ./ser[20512]: DEBUG: mk_proxy: doing DNS lookup... Sep 17 10:54:45 siege ./ser[20512]: DEBUG: get_out_socket: socket determined: 0 Sep 17 10:54:45 siege ./ser[20512]: check_via_address(82.135.142.16, 82.135.142.16, 0) Sep 17 10:54:45 siege ./ser[20512]: DEBUG: add_to_tail_of_timer[4]: 0x402f8c28 Sep 17 10:54:45 siege ./ser[20512]: DEBUG: add_to_tail_of_timer[0]: 0x402f8c3c Sep 17 10:54:45 siege ./ser[20512]: SER: new transaction fwd'ed Sep 17 10:54:45 siege ./ser[20512]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:45 siege ./ser[20512]: receive_msg: cleaning up Sep 17 10:54:46 siege ./ser[20525]: DEBUG: timer routine:4,tl=0x402f8c28 next=(nil) Sep 17 10:54:46 siege ./ser[20525]: DEBUG: retransmission_handler : request resending (t=0x402f8b00, INVITE si ... ) Sep 17 10:54:46 siege ./ser[20525]: DEBUG: add_to_tail_of_timer[5]: 0x402f8c28 Sep 17 10:54:46 siege ./ser[20525]: DEBUG: retransmission_handler : done Sep 17 10:54:46 siege ./ser[20513]: SIP Request: Sep 17 10:54:46 siege ./ser[20513]: method: <CANCEL> Sep 17 10:54:46 siege ./ser[20513]: uri: sip:70000037@213.226.186.195 Sep 17 10:54:46 siege ./ser[20513]: version: <SIP/2.0> Sep 17 10:54:46 siege ./ser[20513]: parse_headers: flags=1 Sep 17 10:54:46 siege ./ser[20513]: end of header reached, state=9 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: get_hdr_field: <To> [32]; uri=[sip:70000037@213.226.186.195] Sep 17 10:54:46 siege ./ser[20513]: DEBUG: to body [sip:70000037@213.226.186.195^M ] Sep 17 10:54:46 siege ./ser[20513]: get_hdr_field: cseq <CSeq>: <2> <CANCEL> Sep 17 10:54:46 siege ./ser[20513]: Found param type 232, <branch> = <z9hG4bK-414a9843-402bc24-1a2e>; state=16 Sep 17 10:54:46 siege ./ser[20513]: end of header reached, state=5 Sep 17 10:54:46 siege ./ser[20513]: parse_headers: Via found, flags=1 Sep 17 10:54:46 siege ./ser[20513]: parse_headers: this is the first via Sep 17 10:54:46 siege ./ser[20513]: After parse_msg... Sep 17 10:54:46 siege ./ser[20513]: preparing to run routing scripts... Sep 17 10:54:46 siege ./ser[20513]: DEBUG: add_param: tag=0-13c4-414a9843-402bb98-1973 Sep 17 10:54:46 siege ./ser[20513]: end of header reached, state=29 Sep 17 10:54:46 siege ./ser[20513]: parse_headers: flags=256 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: get_hdr_body : content_length=0 Sep 17 10:54:46 siege ./ser[20513]: found end of header Sep 17 10:54:46 siege ./ser[20513]: find_first_route(): No Route headers found Sep 17 10:54:46 siege ./ser[20513]: loose_route(): There is no Route HF Sep 17 10:54:46 siege ./ser[20513]: DEBUG: t_addifnew: msg id=5747 , global msg id=5746 , T on entrance=(nil) Sep 17 10:54:46 siege ./ser[20513]: parse_headers: flags=-1 Sep 17 10:54:46 siege ./ser[20513]: parse_headers: flags=60 Sep 17 10:54:46 siege ./ser[20513]: t_lookup_request: start searching: hash=32382, isACK=0 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: RFC3261 transaction matching failed Sep 17 10:54:46 siege ./ser[20513]: DEBUG: t_lookup_request: no transaction found Sep 17 10:54:46 siege ./ser[20513]: DEBUG: get_out_socket: socket determined: 0 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: t_lookupOriginalT: searching on hash entry 32382 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: RFC3261 transaction matched, tid=-414a9843-402bc24-1a2e Sep 17 10:54:46 siege ./ser[20513]: DEBUG: t_lookupOriginalT: canceled transaction found (0x402f8b00)! Sep 17 10:54:46 siege ./ser[20513]: DEBUG: t_lookupOriginalT completed Sep 17 10:54:46 siege ./ser[20513]: DEBUG: e2e_cancel: e2e cancel -- no more pending branches Sep 17 10:54:46 siege ./ser[20513]: parse_headers: flags=-1 Sep 17 10:54:46 siege ./ser[20513]: check_via_address(82.135.142.16, 82.135.142.16, 0) Sep 17 10:54:46 siege ./ser[20513]: WARNING:vqm_resize: resize(0) called Sep 17 10:54:46 siege ./ser[20513]: DEBUG: cleanup_uacs: RETR/FR timers reset Sep 17 10:54:46 siege ./ser[20513]: DEBUG: add_to_tail_of_timer[2]: 0x402dff60 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: reply sent out. buf=0x80e1040: SIP/2.0 2..., shmem=0x402d3bc0: SIP/2.0 2 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: t_reply: finished Sep 17 10:54:46 siege ./ser[20513]: DEBUG: e2e_cancel: sending 487 Sep 17 10:54:46 siege ./ser[20513]: parse_headers: flags=-1 Sep 17 10:54:46 siege ./ser[20513]: check_via_address(82.135.142.16, 82.135.142.16, 0) Sep 17 10:54:46 siege ./ser[20513]: DEBUG: cleanup_uacs: RETR/FR timers reset Sep 17 10:54:46 siege ./ser[20513]: DEBUG: add_to_tail_of_timer[4]: 0x402f8bb4 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: add_to_tail_of_timer[0]: 0x402f8bc8 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: reply sent out. buf=0x80e1040: SIP/2.0 4..., shmem=0x402e2938: SIP/2.0 4 Sep 17 10:54:46 siege ./ser[20513]: DEBUG: t_reply: finished Sep 17 10:54:46 siege ./ser[20513]: SER: new transaction fwd'ed Sep 17 10:54:46 siege ./ser[20513]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:46 siege ./ser[20513]: receive_msg: cleaning up Sep 17 10:54:46 siege ./ser[20507]: SIP Request: Sep 17 10:54:46 siege ./ser[20507]: method: <ACK> Sep 17 10:54:46 siege ./ser[20507]: uri: sip:70000037@213.226.186.195 Sep 17 10:54:46 siege ./ser[20507]: version: <SIP/2.0> Sep 17 10:54:46 siege ./ser[20507]: parse_headers: flags=1 Sep 17 10:54:46 siege ./ser[20507]: DEBUG: add_param: tag=855fc458e92794ef4dd58c58d38d34d1-1dcd Sep 17 10:54:46 siege ./ser[20507]: end of header reached, state=29 Sep 17 10:54:46 siege ./ser[20507]: DEBUG: get_hdr_field: <To> [74]; uri=[sip:70000037@213.226.186.195] Sep 17 10:54:46 siege ./ser[20507]: DEBUG: to body [sip:70000037@213.226.186.195] Sep 17 10:54:46 siege ./ser[20507]: get_hdr_field: cseq <CSeq>: <2> <ACK> Sep 17 10:54:46 siege ./ser[20507]: Found param type 232, <branch> = <z9hG4bK-414a9843-402bc24-1a2e>; state=16 Sep 17 10:54:46 siege ./ser[20507]: end of header reached, state=5 Sep 17 10:54:46 siege ./ser[20507]: parse_headers: Via found, flags=1 Sep 17 10:54:46 siege ./ser[20507]: parse_headers: this is the first via Sep 17 10:54:46 siege ./ser[20507]: After parse_msg... Sep 17 10:54:46 siege ./ser[20507]: preparing to run routing scripts... Sep 17 10:54:46 siege ./ser[20507]: parse_headers: flags=4 Sep 17 10:54:46 siege ./ser[20507]: DEBUG: add_param: tag=0-13c4-414a9843-402bb98-1973 Sep 17 10:54:46 siege ./ser[20507]: end of header reached, state=29 Sep 17 10:54:46 siege ./ser[20507]: parse_headers: flags=256 Sep 17 10:54:46 siege ./ser[20507]: DEBUG: get_hdr_body : content_length=0 Sep 17 10:54:46 siege ./ser[20507]: found end of header Sep 17 10:54:46 siege ./ser[20507]: find_first_route(): No Route headers found Sep 17 10:54:46 siege ./ser[20507]: loose_route(): There is no Route HF Sep 17 10:54:46 siege ./ser[20507]: DEBUG: t_addifnew: msg id=5729 , global msg id=5727 , T on entrance=0xffffffff Sep 17 10:54:46 siege ./ser[20507]: parse_headers: flags=-1 Sep 17 10:54:46 siege ./ser[20507]: parse_headers: flags=60 Sep 17 10:54:46 siege ./ser[20507]: t_lookup_request: start searching: hash=32382, isACK=1 Sep 17 10:54:46 siege ./ser[20507]: DEBUG: RFC3261 transaction matched, tid=-414a9843-402bc24-1a2e Sep 17 10:54:46 siege ./ser[20507]: DEBUG: t_lookup_request: transaction found (T=0x402f8b00) Sep 17 10:54:46 siege ./ser[20507]: DEBUG: cleanup_uacs: RETR/FR timers reset Sep 17 10:54:46 siege ./ser[20507]: DEBUG: add_to_tail_of_timer[2]: 0x402f8b48 Sep 17 10:54:46 siege ./ser[20507]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:46 siege ./ser[20507]: receive_msg: cleaning up Sep 17 10:54:47 siege ./ser[20525]: DEBUG: timer routine:0,tl=0x402f8c3c next=0x402f8bc8 Sep 17 10:54:47 siege ./ser[20525]: DEBUG: timer routine:0,tl=0x402f8bc8 next=(nil) Sep 17 10:54:47 siege ./ser[20525]: DEBUG: timer routine:4,tl=0x402f8bb4 next=(nil) Sep 17 10:54:47 siege ./ser[20525]: DEBUG: timer routine:5,tl=0x402f8c28 next=(nil) Sep 17 10:54:47 siege ./ser[20519]: SIP Request: Sep 17 10:54:47 siege ./ser[20519]: method: <INVITE> Sep 17 10:54:47 siege ./ser[20519]: uri: sip:70000037@82.135.142.22 Sep 17 10:54:47 siege ./ser[20519]: version: <SIP/2.0> Sep 17 10:54:47 siege ./ser[20519]: parse_headers: flags=1 Sep 17 10:54:47 siege ./ser[20519]: end of header reached, state=2 Sep 17 10:54:47 siege ./ser[20519]: parse_headers: Via found, flags=1 Sep 17 10:54:47 siege ./ser[20519]: parse_headers: this is the first via Sep 17 10:54:47 siege ./ser[20519]: After parse_msg... Sep 17 10:54:47 siege ./ser[20519]: preparing to run routing scripts... Sep 17 10:54:47 siege ./ser[20519]: parse_headers: flags=8 Sep 17 10:54:47 siege ./ser[20519]: end of header reached, state=9 Sep 17 10:54:47 siege ./ser[20519]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:70000037@82.135.142.22] Sep 17 10:54:47 siege ./ser[20519]: DEBUG: to body [sip:70000037@82.135.142.22^M ] Sep 17 10:54:47 siege ./ser[20519]: DEBUG: add_param: tag=b960e3f Sep 17 10:54:47 siege ./ser[20519]: end of header reached, state=29 Sep 17 10:54:47 siege ./ser[20519]: parse_headers: flags=256 Sep 17 10:54:47 siege ./ser[20519]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Sep 17 10:54:47 siege ./ser[20519]: DEBUG: get_hdr_body : content_length=180 Sep 17 10:54:47 siege ./ser[20519]: found end of header Sep 17 10:54:47 siege ./ser[20519]: find_first_route(): No Route headers found Sep 17 10:54:47 siege ./ser[20519]: loose_route(): There is no Route HF Sep 17 10:54:47 siege ./ser[20519]: DEBUG: t_addifnew: msg id=5712 , global msg id=5711 , T on entrance=0xffffffff Sep 17 10:54:47 siege ./ser[20519]: parse_headers: flags=-1 Sep 17 10:54:47 siege ./ser[20519]: parse_headers: flags=60 Sep 17 10:54:47 siege ./ser[20519]: t_lookup_request: start searching: hash=12319, isACK=0 Sep 17 10:54:47 siege ./ser[20519]: DEBUG: proceeding to pre-RFC3261 transaction matching Sep 17 10:54:47 siege ./ser[20519]: DEBUG: t_lookup_request: no transaction found Sep 17 10:54:47 siege ./ser[20519]: DEBUG: get_out_socket: socket determined: 0 Sep 17 10:54:47 siege ./ser[20519]: SER: new INVITE Sep 17 10:54:47 siege ./ser[20519]: parse_headers: flags=-1 Sep 17 10:54:47 siege ./ser[20519]: check_via_address(213.226.186.195, 213.226.186.195, 0) Sep 17 10:54:47 siege ./ser[20519]: WARNING:vqm_resize: resize(0) called Sep 17 10:54:47 siege ./ser[20519]: DEBUG: reply sent out. buf=0x80de4a8: SIP/2.0 1..., shmem=0x402dd670: SIP/2.0 1 Sep 17 10:54:47 siege ./ser[20519]: DEBUG: t_reply: finished Sep 17 10:54:47 siege ./ser[20519]: DEBUG: mk_proxy: doing DNS lookup... Sep 17 10:54:47 siege ./ser[20519]: DEBUG: get_out_socket: socket determined: 0 Sep 17 10:54:47 siege ./ser[20519]: check_via_address(213.226.186.195, 213.226.186.195, 0) Sep 17 10:54:47 siege ./ser[20519]: DEBUG: add_to_tail_of_timer[4]: 0x402f6610 Sep 17 10:54:47 siege ./ser[20519]: DEBUG: add_to_tail_of_timer[0]: 0x402f6624 Sep 17 10:54:47 siege ./ser[20519]: SER: new transaction fwd'ed Sep 17 10:54:47 siege ./ser[20519]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:47 siege ./ser[20519]: receive_msg: cleaning up Sep 17 10:54:47 siege ./ser[20511]: SIP Reply (status): Sep 17 10:54:47 siege ./ser[20511]: version: <SIP/2.0> Sep 17 10:54:47 siege ./ser[20511]: status: <100> Sep 17 10:54:47 siege ./ser[20511]: reason: <trying> Sep 17 10:54:47 siege ./ser[20511]: parse_headers: flags=1 Sep 17 10:54:47 siege ./ser[20511]: Found param type 232, <branch> = <z9hG4bKf103.8f202116.0>; state=16 Sep 17 10:54:47 siege ./ser[20511]: end of header reached, state=5 Sep 17 10:54:47 siege ./ser[20511]: parse_headers: Via found, flags=1 Sep 17 10:54:47 siege ./ser[20511]: parse_headers: this is the first via Sep 17 10:54:47 siege ./ser[20511]: After parse_msg... Sep 17 10:54:47 siege ./ser[20511]: forward_reply: found module tm, passing reply to it Sep 17 10:54:47 siege ./ser[20511]: DEBUG: t_check: msg id=5909 global id=5908 T start=0xffffffff Sep 17 10:54:47 siege ./ser[20511]: parse_headers: flags=17 Sep 17 10:54:47 siege ./ser[20511]: end of header reached, state=2 Sep 17 10:54:47 siege ./ser[20511]: parse_headers: Via found, flags=17 Sep 17 10:54:47 siege ./ser[20511]: parse_headers: this is the second via Sep 17 10:54:47 siege ./ser[20511]: end of header reached, state=9 Sep 17 10:54:47 siege ./ser[20511]: DEBUG: get_hdr_field: <To> [30]; uri=[sip:70000037@82.135.142.22] Sep 17 10:54:47 siege ./ser[20511]: DEBUG: to body [sip:70000037@82.135.142.22^M ] Sep 17 10:54:47 siege ./ser[20511]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Sep 17 10:54:47 siege ./ser[20511]: parse_headers: flags=4 Sep 17 10:54:47 siege ./ser[20511]: DEBUG: t_reply_matching: hash 12319 label 1628570360 branch 0 Sep 17 10:54:47 siege ./ser[20511]: DEBUG: t_reply_matching: reply matched (T=0x402f64e8)! Sep 17 10:54:47 siege ./ser[20511]: DEBUG: t_check: msg id=5909 global id=5909 T end=0x402f64e8 Sep 17 10:54:47 siege ./ser[20511]: DEBUG: t_on_reply: org. status uas=100, uac[0]=0 local=0 is_invite=1) Sep 17 10:54:47 siege ./ser[20511]: ->>>>>>>>> T_code=100, new_code=100 Sep 17 10:54:47 siege ./ser[20511]: DEBUG: relay_reply: branch=0, save=0, relay=-1 Sep 17 10:54:47 siege ./ser[20511]: DEBUG: add_to_tail_of_timer[1]: 0x402f6624 Sep 17 10:54:47 siege ./ser[20511]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:47 siege ./ser[20511]: receive_msg: cleaning up Sep 17 10:54:47 siege ./ser[20517]: SIP Reply (status): Sep 17 10:54:47 siege ./ser[20517]: version: <SIP/2.0> Sep 17 10:54:47 siege ./ser[20517]: status: <180> Sep 17 10:54:47 siege ./ser[20517]: reason: <ringing> Sep 17 10:54:47 siege ./ser[20517]: parse_headers: flags=1 Sep 17 10:54:47 siege ./ser[20517]: Found param type 232, <branch> = <z9hG4bKf103.8f202116.0>; state=16 Sep 17 10:54:47 siege ./ser[20517]: end of header reached, state=5 Sep 17 10:54:47 siege ./ser[20517]: parse_headers: Via found, flags=1 Sep 17 10:54:47 siege ./ser[20517]: parse_headers: this is the first via Sep 17 10:54:47 siege ./ser[20517]: After parse_msg... Sep 17 10:54:47 siege ./ser[20517]: forward_reply: found module tm, passing reply to it Sep 17 10:54:47 siege ./ser[20517]: DEBUG: t_check: msg id=5678 global id=5677 T start=(nil) Sep 17 10:54:47 siege ./ser[20517]: parse_headers: flags=17 Sep 17 10:54:47 siege ./ser[20517]: end of header reached, state=2 Sep 17 10:54:47 siege ./ser[20517]: parse_headers: Via found, flags=17 Sep 17 10:54:47 siege ./ser[20517]: parse_headers: this is the second via Sep 17 10:54:47 siege ./ser[20517]: DEBUG: add_param: tag=f292f2202d771805 Sep 17 10:54:47 siege ./ser[20517]: end of header reached, state=29 Sep 17 10:54:47 siege ./ser[20517]: DEBUG: get_hdr_field: <To> [51]; uri=[sip:70000037@82.135.142.22] Sep 17 10:54:47 siege ./ser[20517]: DEBUG: to body [sip:70000037@82.135.142.22] Sep 17 10:54:47 siege ./ser[20517]: get_hdr_field: cseq <CSeq>: <1> <INVITE> Sep 17 10:54:47 siege ./ser[20517]: parse_headers: flags=4 Sep 17 10:54:47 siege ./ser[20517]: DEBUG: t_reply_matching: hash 12319 label 1628570360 branch 0 Sep 17 10:54:47 siege ./ser[20517]: DEBUG: t_reply_matching: reply matched (T=0x402f64e8)! Sep 17 10:54:47 siege ./ser[20517]: DEBUG: t_check: msg id=5678 global id=5678 T end=0x402f64e8 Sep 17 10:54:47 siege ./ser[20517]: DEBUG: t_on_reply: org. status uas=100, uac[0]=100 local=0 is_invite=1) Sep 17 10:54:47 siege ./ser[20517]: ->>>>>>>>> T_code=100, new_code=180 Sep 17 10:54:47 siege ./ser[20517]: DEBUG: relay_reply: branch=0, save=0, relay=0 Sep 17 10:54:47 siege ./ser[20517]: old size: 402, new size: 338 Sep 17 10:54:47 siege ./ser[20517]: build_res_from_sip_res: copied size: orig:85, new: 21, rest: 317 msg= SIP/2.0 180 ringing^M Via: SIP/2.0/UDP 213.226.186.195^M Record-Route: sip:70000037@213.226.186.250;ftag=b960e3f;lr=on^M From: sip:70000031@213.226.186.195;tag=b960e3f^M To: sip:70000037@82.135.142.22;tag=f292f2202d771805^M Call-ID: 3647-4a64@213.226.186.195^M CSeq: 1 INVITE^M User-Agent: Grandstream BT100 1.0.5.10^M Content-Length: 0^M ^M Sep 17 10:54:47 siege ./ser[20517]: DEBUG: reply relayed. buf=0x80dcc68: SIP/2.0 1..., shmem=0x402d9b30: SIP/2.0 1 Sep 17 10:54:47 siege ./ser[20517]: DEBUG: add_to_tail_of_timer[1]: 0x402f6624 Sep 17 10:54:47 siege ./ser[20517]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:47 siege ./ser[20517]: receive_msg: cleaning up Sep 17 10:54:47 siege ./ser[20513]: SIP Reply (status): Sep 17 10:54:47 siege ./ser[20513]: version: <SIP/2.0> Sep 17 10:54:47 siege ./ser[20513]: status: <180> Sep 17 10:54:47 siege ./ser[20513]: reason: <Ringing> Sep 17 10:54:47 siege ./ser[20513]: parse_headers: flags=1 Sep 17 10:54:47 siege ./ser[20513]: Found param type 232, <branch> = <z9hG4bKe7e7.554d6d51.0>; state=16 Sep 17 10:54:47 siege ./ser[20513]: end of header reached, state=5 Sep 17 10:54:47 siege ./ser[20513]: parse_headers: Via found, flags=1 Sep 17 10:54:47 siege ./ser[20513]: parse_headers: this is the first via Sep 17 10:54:47 siege ./ser[20513]: After parse_msg... Sep 17 10:54:47 siege ./ser[20513]: forward_reply: found module tm, passing reply to it Sep 17 10:54:47 siege ./ser[20513]: DEBUG: t_check: msg id=5748 global id=5747 T start=0xffffffff Sep 17 10:54:47 siege ./ser[20513]: parse_headers: flags=17 Sep 17 10:54:47 siege ./ser[20513]: Found param type 232, <branch> = <z9hG4bK-414a9843-402bc24-1a2e>; state=16 Sep 17 10:54:47 siege ./ser[20513]: end of header reached, state=5 Sep 17 10:54:47 siege ./ser[20513]: parse_headers: Via found, flags=17 Sep 17 10:54:47 siege ./ser[20513]: parse_headers: this is the second via Sep 17 10:54:47 siege ./ser[20513]: end of header reached, state=9 Sep 17 10:54:47 siege ./ser[20513]: DEBUG: get_hdr_field: <To> [32]; uri=[sip:70000037@213.226.186.195] Sep 17 10:54:47 siege ./ser[20513]: DEBUG: to body [sip:70000037@213.226.186.195^M ] Sep 17 10:54:47 siege ./ser[20513]: get_hdr_field: cseq <CSeq>: <2> <INVITE> Sep 17 10:54:47 siege ./ser[20513]: parse_headers: flags=4 Sep 17 10:54:47 siege ./ser[20513]: DEBUG: t_reply_matching: hash 32382 label 366400597 branch 0 Sep 17 10:54:47 siege ./ser[20513]: DEBUG: t_reply_matching: reply matched (T=0x402f8b00)! Sep 17 10:54:47 siege ./ser[20513]: DEBUG: t_check: msg id=5748 global id=5748 T end=0x402f8b00 Sep 17 10:54:47 siege ./ser[20513]: DEBUG: t_on_reply: org. status uas=487, uac[0]=0 local=0 is_invite=1) Sep 17 10:54:47 siege ./ser[20513]: ->>>>>>>>> T_code=487, new_code=180 Sep 17 10:54:47 siege ./ser[20513]: DEBUG: relay_reply: branch=0, save=0, relay=-1 Sep 17 10:54:47 siege ./ser[20513]: WARNING: set_timer called on a "detached" timer -- ignoring: 0x402f8c3c Sep 17 10:54:47 siege ./ser[20513]: DEBUG:destroy_avp_list: destroing list (nil) Sep 17 10:54:47 siege ./ser[20513]: receive_msg: cleaning up Sep 17 10:54:48 siege ./ser[20525]: DEBUG: timer routine:4,tl=0x402f6610 next=(nil)
-
Antanas Masevicius -
Antanas Masevicius -
Jan Janak -
Jiri Kuthan