thr3ads.net - asterisk users - [asterisk-users] Asterisk uses 3 seconds to send ACK after OK [Mar 2013]

If this information is useful, please help other people find it:
Share via:

Pan B. Christensen

2013-Mar-15 14:21 UTC

[asterisk-users] Asterisk uses 3 seconds to send ACK after OK

Hello!

We recently upgraded one of our customers from 1.4.44 to 1.8.15-cert1. We have
several other customers running both versions.
The customer in question does not use us as their provider as they?re located in
a different country.

When they make outgoing calls, there is a 3 second delay between answering the
call and the call being established. When debugging this, I found that Asterisk
waits 3 seconds after receiving 200 OK before returning the ACK. See attached
image. There?s no verbose output in the CLI during this time. I turned on full
debugging. This seems to produce around a hundred lines of debug per second
until suddenly I see a full 3 seconds stop just before sending the ACK.

[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  0 [ 14]: SIP/2.0 200 Ok
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  1 [ 57]: Via: SIP/2.0/UDP
xxx.xxx.xxx.xxx:xxxx;branch=z9hG4bK135effb0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  2 [ 66]: From: "a"
<sip:a at xxx.xxx.xxx.xxx:xxxx>;tag=as6b9fcf86
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  3 [ 61]: To: <sip:b at
FQDNy:5060>;tag=1014243474
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  4 [ 59]: Call-ID:
03dffd7b5ecd7eb47c2bae6b101ba1aa at 62.109.37.34:5088
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  5 [ 16]: CSeq: 102 INVITE
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  6 [ 51]: Contact: <sip:b
at FQDNz:5060>
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  7 [117]: Record-Route:
<sip:yyy.yyy.yyy.yyy;lr=on;ftag=as6b9fcf86;d=b49.b0ae2a82;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA6NTA4OA-->
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  8 [ 69]: Allow:
INVITE,ACK,PRACK,SUBSCRIBE,BYE,CANCEL,NOTIFY,INFO,REFER,UPDATE
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header  9 [ 24]: Supported: timer,
100rel
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header 10 [ 29]: Content-Type:
application/sdp
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header 11 [ 19]: Content-Length: 352
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:  Header 12 [  0]:
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  0 [  3]: v=0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  1 [ 35]: o=- 25469059 0 IN
IP4 ccc.ccc.ccc.ccc
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  2 [ 13]: s=Cisco SDP 0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  3 [ 22]: c=IN IP4
ccc.ccc.ccc.ccc
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  4 [  5]: t=0 0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  5 [ 31]: m=audio 21252
RTP/AVP 8 101 100
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  6 [ 33]: a=rtpmap:101
telephone-event/8000
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  7 [ 15]: a=fmtp:101 0-15
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  8 [ 23]: a=rtpmap:100
X-NSE/8000
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body  9 [ 18]: a=fmtp:100 200-202
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 10 [  9]: a=X-sqn:0
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 11 [ 28]: a=X-cap: 1 audio
RTP/AVP 100
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 12 [ 33]: a=X-cpar:
a=rtpmap:100 X-NSE/8000
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 13 [ 28]: a=X-cpar:
a=fmtp:100 200-202
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c:    Body 14 [ 26]: a=X-cap: 2 image
udptl t38
[Mar 15 13:16:05] VERBOSE[27947] chan_sip.c: [Mar 15 13:16:05] --- (12 headers
15 lines) ---
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: = Looking for  Call ID:
03dffd7b5ecd7eb47c2bae6b101ba1aa at xxx.xxx.xxx.xxx:xxxx (Checking To) --From
tag as6b9fcf86 --To-tag 1014243474
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Acked pending invite 102
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Stopping retransmission on
'03dffd7b5ecd7eb47c2bae6b101ba1aa at xxx.xxx.xxx.xxx:xxxx' of Request
102: Match Found
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: SIP response 200 to standard invite
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: SIP response 200 to standard invite
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Processing session-level SDP v=0...
UNSUPPORTED OR FAILED.
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Call 03dffd7b5ecd7eb47c2bae6b101ba1aa
at xxx.xxx.xxx.xxx:xxxx responded to our reinvite without changing SDP version;
ignoring SDP.
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: Updating call counter for outgoing
call
[Mar 15 13:16:05] DEBUG[27947] chan_sip.c: build_route: Record-Route hop:
<sip:yyy.yyy.yyy.yyy;lr=on;ftag=as6b9fcf86;d=b49.b0ae2a82;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA6NTA4OA-->
[Mar 15 13:16:05] VERBOSE[27947] chan_sip.c: [Mar 15 13:16:05] list_route: hop:
<sip:yyy.yyy.yyy.yyy;lr=on;ftag=as6b9fcf86;d=b49.b0ae2a82;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA6NTA4OA-->
[Mar 15 13:16:05] DEBUG[27947] netsock2.c: Splitting 'FQDNz:5060'
into...
[Mar 15 13:16:05] DEBUG[27947] netsock2.c: ...host 'FQDNz' and port
'5060'.
[Mar 15 13:16:05] DEBUG[27931] devicestate.c: No provider found, checking
channel drivers for SIP ? FQDNy
[Mar 15 13:16:05] DEBUG[27931] chan_sip.c: Checking device state for peer FQDNy
[Mar 15 13:16:05] DEBUG[27931] devicestate.c: Changing state for SIP/FQDNy -
state 2 (In use)
[Mar 15 13:16:05] DEBUG[27931] devicestate.c: device 'SIP/FQDNy' state
'2'
[Mar 15 13:16:05] DEBUG[27967] app_queue.c: Device 'SIP/FQDNy' changed
to state '2' (In use) but we don't care because they're not a
member of any queue.
[Mar 15 13:16:08] DEBUG[27947] netsock2.c: Splitting 'yyy.yyy.yyy.yyy'
into...
[Mar 15 13:16:08] DEBUG[27947] netsock2.c: ...host 'yyy.yyy.yyy.yyy' and
port ''.
[Mar 15 13:16:08] VERBOSE[27947] chan_sip.c: [Mar 15 13:16:08] Transmitting (no
NAT) to yyy.yyy.yyy.yyy:5060:
ACK sip:004741888800 at FQDNz:5060 SIP/2.0


Could it be a parsing issue because the Record-Route header doesn?t include a
port?

With kind regards,
Pan
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20130315/b66f71f3/attachment.htm>

Matthew Jordan

2013-Mar-18 00:40 UTC

head link

[asterisk-users] Asterisk uses 3 seconds to send ACK after OK

On 03/15/2013 09:21 AM, Pan B. Christensen wrote:> Hello!
>  
> We recently upgraded one of our customers from 1.4.44 to 1.8.15-cert1.
> We have several other customers running both versions.
> The customer in question does not use us as their provider as they?re
> located in a different country.
>  
> When they make outgoing calls, there is a 3 second delay between
> answering the call and the call being established. When debugging this,
> I found that Asterisk waits 3 seconds after receiving 200 OK before
> returning the ACK. See attached image. There?s no verbose output in the
> CLI during this time. I turned on full debugging. This seems to produce
> around a hundred lines of debug per second until suddenly I see a full 3
> seconds stop just before sending the ACK.
>  
<snip>>  
> Could it be a parsing issue because the Record-Route header doesn?t
> include a port?
>  
> With kind regards,
> Pan
>  
Taking a look at the DEBUG statements that are associated with the
thread processing the SIP response:

[Mar 15 13:16:05] DEBUG[27947] netsock2.c: Splitting 'FQDNz:5060'
into...
[Mar 15 13:16:05] DEBUG[27947] netsock2.c: ...host 'FQDNz' and port
'5060'.
[Mar 15 13:16:08] DEBUG[27947] netsock2.c: Splitting 'yyy.yyy.yyy.yyy'
 into...
[Mar 15 13:16:08] DEBUG[27947] netsock2.c: ...host 'yyy.yyy.yyy.yyy' and
 port ''.
[Mar 15 13:16:08] VERBOSE[27947] chan_sip.c: [Mar 15 13:16:08]
 Transmitting (no NAT) to yyy.yyy.yyy.yyy:5060:
 ACK sip:004741888800 at FQDNz:5060 SIP/2.0

If I had to guess, the DNS resolution of 'FQDNz' probably took 3
seconds. You may want to consider a local DNS cache to help speed up
results.

Matt

-- 
Matthew Jordan
Digium, Inc. | Engineering Manager
445 Jan Davis Drive NW - Huntsville, AL 35806 - USA
Check us out at: http://digium.com & http://asterisk.org

Reasonably Related Threads

Search for more reasonably related threads

asterisk users - Mar 2013 - Asterisk uses 3 seconds to send ACK after OK

[asterisk-users] Asterisk uses 3 seconds to send ACK after OK

[asterisk-users] Asterisk uses 3 seconds to send ACK after OK

Reasonably Related Threads