[OpenSIPS-Users] Help: Understanding ACK loop

spady spady77 at gmail.com
Tue Nov 6 20:41:40 CET 2012 

Hi Qasim, i tried but same issue. 
SIP trace is changed a bit,like below, but issue not. i also get this errors
into opensips logs but i cannot uderstand them.

U 2012/11/06 20:33:25.046107 10.9.6.3:5060 -> 172.16.55.100:5060
SIP/2.0 200 OK.
Record-Route: <sip:172.16.55.100;lr;did=2b.a230b8e6>.
Record-Route: <sip:10.9.6.40>.
Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS,
UPDATE.
Contact: sip:10.9.6.3.
Supported: replaces,timer,path,100rel.
User-Agent: OmniPCX Enterprise R10.0 j1.410.45.a.
Session-Expires: 1800;refresher=uas.
P-Asserted-Identity: "Mussini Andrea" <sip:5222541 at 10.9.6.3;user=phone>.
Content-Type: application/sdp.
To: <sip:2541 at 172.16.55.100>;tag=4f663091f6d6b5553461b0b4c9c2df35.
From: <sip:+393480806946 at 10.9.6.40>;tag=q-7313-a941.
Call-ID: 1352226984035420 at 10.9.6.40.
CSeq: 25311 INVITE.
Via: SIP/2.0/UDP 172.16.55.100;branch=z9hG4bK7b8e.1a54d8a2.0.
Via: SIP/2.0/UDP 10.9.6.40:5060;branch=z9hG4bKcdkyjpbC17142343480756.
Content-Length: 194.
.
v=0.
o=OXE 1352230298 1352230298 IN IP4 10.9.6.3.
s=abs.
c=IN IP4 10.9.6.111.
t=0 0.
m=audio 32514 RTP/AVP 18.
a=sendrecv.
a=rtpmap:18 G729/8000.
a=fmtp:18 annexb=no.
a=ptime:30.
a=maxptime:40.


U 2012/11/06 20:33:25.046911 172.16.55.100:5060 -> 10.9.6.40:5060
SIP/2.0 200 OK.
Record-Route: <sip:172.16.55.100;lr;did=2b.a230b8e6>.
Record-Route: <sip:10.9.6.40>.
Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS,
UPDATE.
Contact: sip:10.9.6.3.
Supported: replaces,timer,path,100rel.
User-Agent: OmniPCX Enterprise R10.0 j1.410.45.a.
Session-Expires: 1800;refresher=uas.
P-Asserted-Identity: "Mussini Andrea" <sip:5222541 at 10.9.6.3;user=phone>.
Content-Type: application/sdp.
To: <sip:2541 at 172.16.55.100>;tag=4f663091f6d6b5553461b0b4c9c2df35.
From: <sip:+393480806946 at 10.9.6.40>;tag=q-7313-a941.
Call-ID: 1352226984035420 at 10.9.6.40.
CSeq: 25311 INVITE.
Via: SIP/2.0/UDP 10.9.6.40:5060;branch=z9hG4bKcdkyjpbC17142343480756.
Content-Length: 194.
.
v=0.
o=OXE 1352230298 1352230298 IN IP4 10.9.6.3.
s=abs.
c=IN IP4 10.9.6.111.
t=0 0.
m=audio 32514 RTP/AVP 18.
a=sendrecv.
a=rtpmap:18 G729/8000.
a=fmtp:18 annexb=no.
a=ptime:30.
a=maxptime:40.


U 2012/11/06 20:33:25.052071 10.9.6.40:5060 -> 172.16.55.100:5060
ACK sip:172.16.55.100;lr;did=2b.a230b8e6 SIP/2.0.
From: <sip:+393480806946 at 10.9.6.40>;tag=q-7313-a941.
To: <sip:2541 at 172.16.55.100>;tag=4f663091f6d6b5553461b0b4c9c2df35.
Call-ID: 1352226984035420 at 10.9.6.40.
CSeq: 25311 ACK.
Max-Forwards: 70.
Content-Length: 0.
Contact: <sip:+393480806946 at 10.9.6.40>.
Route: sip:10.9.6.3.
Via: SIP/2.0/UDP 10.9.6.40:5060;branch=z9hG4bKypebcqkC17142343496466.
.


U 2012/11/06 20:33:25.054039 172.16.55.100:5060 -> 172.16.55.100:5060
ACK sip:172.16.55.100;lr;did=2b.a230b8e6 SIP/2.0.
From: <sip:+393480806946 at 10.9.6.40>;tag=q-7313-a941.
To: <sip:2541 at 172.16.55.100>;tag=4f663091f6d6b5553461b0b4c9c2df35.
Call-ID: 1352226984035420 at 10.9.6.40.
CSeq: 25311 ACK.
Max-Forwards: 69.
Content-Length: 0.
Contact: <sip:+393480806946 at 10.9.6.40>.
Route: sip:10.9.6.3.
Via: SIP/2.0/UDP 172.16.55.100;branch=z9hG4bK7b8e.1a54d8a2.2.
Via: SIP/2.0/UDP 10.9.6.40:5060;branch=z9hG4bKypebcqkC17142343496466.
. 

After them, 10.9.6.3 try to send again 200 OK until it sends BYE ( because
it has not recived ACK ).

Here logs:

Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_msg: SIP
Request:
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_msg: 
method:  <ACK>
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_msg: 
uri:     <sip:172.16.55.100;lr;did=99d.779fa501>
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_msg: 
version: <SIP/2.0>
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_headers:
flags=2
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
DBG:core:parse_to_param: tag=b67d1f231c591c0d3a3ec185f23148eb
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_to: end
of header reached, state=29
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_to:
display={}, ruri={sip:2541 at 172.16.55.100}
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:get_hdr_field:
<To> [63]; uri=[sip:2541 at 172.16.55.100]
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:get_hdr_field:
to body [<sip:2541 at 172.16.55.100>]
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:get_hdr_field:
cseq <CSeq>: <25317> <ACK>
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:get_hdr_field:
content_length=0
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
DBG:core:parse_via_param: found param type 232, <branch> =
<z9hG4bKflkekrjC17172343804901>; state=16
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_via: end
of header reached, state=5
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_headers:
via found, flags=2
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_headers:
this is the first via
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:receive_msg:
After parse_msg...
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:receive_msg:
preparing to run routing scripts...
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:sl:sl_filter_ACK:
to late to be a local ACK!
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
DBG:maxfwd:is_maxfwd_present: value = 70
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:uri:has_totag:
totag found
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: ######LOG: Individuo
TO_TAG
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_headers:
flags=200
*Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
ERROR:core:parse_nameaddr: no < found
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
ERROR:core:do_parse_rr_body: failed to parse name-addr
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
ERROR:core:do_parse_rr_body: failed to parse RR headers
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:set_err_info:
ec: 1, el: 3, ei: 'error parsing RR headers'
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
ERROR:rr:find_first_route: failed to parse Route HF
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:rr:loose_route:
There is no Route HF*
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_headers:
flags=78
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
DBG:tm:t_lookup_request: start searching: hash=30105, isACK=1
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_headers:
flags=38
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
DBG:core:parse_to_param: tag=q-7313-aa7e
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_to: end
of header reached, state=29
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_to:
display={}, ruri={sip:+393480806946 at 10.9.6.40}
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
DBG:tm:t_lookup_request: REF_UNSAFE:[0xaeee89c4] after is 2
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]:
DBG:tm:t_lookup_request: e2e proxy ACK found
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:tm:t_newtran:
transaction on entrance=(nil)
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:parse_headers:
flags=ffffffffffffffff
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:core:get_hdr_field:
found end of header
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:tm:t_newtran:
building branch for end2end ACK - flags=1
Nov  6 20:38:33 opensips
/usr/local/opensips_proxy_1.8.2/sbin/opensips[7865]: DBG:tm:t_relay_to:
forwarding ACK 



--
View this message in context: http://opensips-open-sip-server.1449251.n2.nabble.com/Help-Understanding-ACK-loop-tp7582796p7582817.html
Sent from the OpenSIPS - Users mailing list archive at Nabble.com.

More information about the Users mailing list