Delay when setting up a call

Hi, I was expereincing large delays in my system. So for testing I installed asterisk 11.15 and Linphone on one computer. It is a clean instalation with a simple dialplan and only Linphone in sip.conf.
I call echo test. I type 600 and I press the green “call” button on Linphone. Now, there is about 2-3 seconds from the moment I press the botton to the moment when Asterisk starts doing anything.
There is not even any messege in the CLI for 2-3 sec.
Is it possible to get rid of this delay? To my understanding, if Asterisk and Linphone are on the same computer, the connection to echo should be instantanous.
I noticed that when Liphone registers it prints a messege . Is that 2000ms related to the problem? Is it configrable?
NOTICE[1774]: chan_sip.c:23584 handle_response_peerpoke: Peer ‘33222’ is now Reachable. (13ms / 2000ms)

Robert

No The 13ms is. That’s rather long for the same machine, but tolerable.

You need to uncomment full in logger.conf, enable milllisecond logging, do sip set debug on at the CLI, then look at the timing in the various steps of the call setup.

My suspicion is that you don’t have valid reverse DNS for one of the addresses being used, and aren’t even getting definitive “not known” response from the DNS server.

This is a part of the log when I call 1111 (Hello world) from Linphone (dialing: 1111@127.0.0.1:5060)
Parts of the log that look suspicious to me:

SIP/2.0 401 Unauthorized

[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Looking for 1111 in sip-local (domain 127.0.0.1)
[2015-02-08 12:31:00.820] VERBOSE[7855][C-00000000] chan_sip.c: list_route: hop: sip:lenovo@127.0.0.1:5066

, but I don’t know whether it is something to be worry about. There is 19ms when asterisk is looking for 1111, but still the impression is that it takes at least 20x longer. I press the call button on Linphone and I feel like there is at least 0.5sec untill something happens.
Can you see anything strange in this log?

exten => 1111,1,NoOp()  ;A hello world if you dial 1111     
same  => n,Set(MONITOR_FILENAME=/var/spool/asterisk/monitor/${STRFTIME(${EPOCH},,%Y%m%d-%H%M%S)}-FROM-${CALLERID(num)}-TO-${EXTEN}-${UNIQUEID})
same  => n,MixMonitor(${MONITOR_FILENAME}.wav,aW(0))
same  => n,Playback(hello-world)
same  => n,StopMixMonitor()
same  => n,Hangup()
[2015-02-08 12:31:00.797] VERBOSE[7855] chan_sip.c: 
<--- SIP read from UDP:127.0.0.1:5066 --->
INVITE sip:1111@127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.101:5066;rport;branch=z9hG4bK56689903
From: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
To: <sip:1111@127.0.0.1:5060>
Call-ID: 1314412951
CSeq: 20 INVITE
Contact: <sip:lenovo@127.0.0.1:5066>
Content-Type: application/sdp
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Max-Forwards: 70
User-Agent: Linphone/3.3.2 (eXosip2/3.3.0)
Subject: Phone call
Content-Length: 408

v=0
o=lenovo 123456 654321 IN IP4 192.168.0.101
s=A conversation
c=IN IP4 192.168.0.101
t=0 0
m=audio 7078 RTP/AVP 112 111 110 3 0 8 101
a=rtpmap:112 speex/32000/1
a=fmtp:112 vbr=on
a=rtpmap:111 speex/16000/1
a=fmtp:111 vbr=on
a=rtpmap:110 speex/8000/1
a=fmtp:110 vbr=on
a=rtpmap:3 GSM/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000/1
a=fmtp:101 0-11
<------------->
[2015-02-08 12:31:00.797] VERBOSE[7855] chan_sip.c: --- (13 headers 17 lines) ---
[2015-02-08 12:31:00.797] VERBOSE[7855] chan_sip.c: Sending to 127.0.0.1:5066 (NAT)
[2015-02-08 12:31:00.797] VERBOSE[7855][C-00000000] chan_sip.c: Sending to 127.0.0.1:5066 (NAT)
[2015-02-08 12:31:00.797] VERBOSE[7855][C-00000000] chan_sip.c: Using INVITE request as basis request - 1314412951
[2015-02-08 12:31:00.797] VERBOSE[7855][C-00000000] chan_sip.c: Found peer 'lenovo' for 'lenovo' from 127.0.0.1:5066
[2015-02-08 12:31:00.797] VERBOSE[7855][C-00000000] chan_sip.c: 
<--- Reliably Transmitting (no NAT) to 127.0.0.1:5066 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.0.101:5066;branch=z9hG4bK56689903;received=127.0.0.1;rport=5066
From: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
To: <sip:1111@127.0.0.1:5060>;tag=as02e0ecfe
Call-ID: 1314412951
CSeq: 20 INVITE
Server: Asterisk PBX 11.15.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="Dictador", nonce="17879f1b"
Content-Length: 0


<------------>
[2015-02-08 12:31:00.797] VERBOSE[7855][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '1314412951' in 6400 ms (Method: INVITE)
[2015-02-08 12:31:00.799] VERBOSE[7855] chan_sip.c: 
<--- SIP read from UDP:127.0.0.1:5066 --->
ACK sip:1111@127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.101:5066;rport;branch=z9hG4bK56689903
From: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
To: <sip:1111@127.0.0.1:5060>;tag=as02e0ecfe
Call-ID: 1314412951
CSeq: 20 ACK
Content-Length: 0

<------------->
[2015-02-08 12:31:00.799] VERBOSE[7855] chan_sip.c: --- (7 headers 0 lines) ---
[2015-02-08 12:31:00.799] VERBOSE[7855] chan_sip.c: 
<--- SIP read from UDP:127.0.0.1:5066 --->
INVITE sip:1111@127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.101:5066;rport;branch=z9hG4bK491557974
From: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
To: <sip:1111@127.0.0.1:5060>
Call-ID: 1314412951
CSeq: 21 INVITE
Contact: <sip:lenovo@127.0.0.1:5066>
Authorization: Digest username="lenovo", realm="Dictador", nonce="17879f1b", uri="sip:1111@127.0.0.1:5060", response="8ec1b83bd44b05dab35f787ddf599163", algorithm=MD5
Content-Type: application/sdp
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Max-Forwards: 70
User-Agent: Linphone/3.3.2 (eXosip2/3.3.0)
Subject: Phone call
Content-Length: 408

v=0
o=lenovo 123456 654321 IN IP4 192.168.0.101
s=A conversation
c=IN IP4 192.168.0.101
t=0 0
m=audio 7078 RTP/AVP 112 111 110 3 0 8 101
a=rtpmap:112 speex/32000/1
a=fmtp:112 vbr=on
a=rtpmap:111 speex/16000/1
a=fmtp:111 vbr=on
a=rtpmap:110 speex/8000/1
a=fmtp:110 vbr=on
a=rtpmap:3 GSM/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000/1
a=fmtp:101 0-11
<------------->
[2015-02-08 12:31:00.799] VERBOSE[7855] chan_sip.c: --- (14 headers 17 lines) ---
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Sending to 127.0.0.1:5066 (no NAT)
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Using INVITE request as basis request - 1314412951
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found peer 'lenovo' for 'lenovo' from 127.0.0.1:5066
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found RTP audio format 112
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found RTP audio format 111
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found RTP audio format 110
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found RTP audio format 3
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found RTP audio format 0
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found RTP audio format 8
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found RTP audio format 101
[2015-02-08 12:31:00.800] VERBOSE[7855][C-00000000] chan_sip.c: Found audio description format speex for ID 112
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Found audio description format speex for ID 111
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Found audio description format speex for ID 110
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Found audio description format GSM for ID 3
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Found audio description format PCMU for ID 0
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Found audio description format PCMA for ID 8
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Found audio description format telephone-event for ID 101
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Capabilities: us - (gsm|ulaw|alaw), peer - audio=(gsm|ulaw|alaw|speex|speex16|speex32)/video=(nothing)/text=(nothing), combined - (gsm|ulaw|alaw)
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x1 (telephone-event|), combined - 0x0 (nothing)
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Peer audio RTP is at port 192.168.0.101:7078
[2015-02-08 12:31:00.801] VERBOSE[7855][C-00000000] chan_sip.c: Looking for 1111 in sip-local (domain 127.0.0.1)
[2015-02-08 12:31:00.820] VERBOSE[7855][C-00000000] chan_sip.c: list_route: hop: <sip:lenovo@127.0.0.1:5066>
[2015-02-08 12:31:00.820] VERBOSE[7855][C-00000000] chan_sip.c:
<--- Transmitting (no NAT) to 127.0.0.1:5066 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.101:5066;branch=z9hG4bK491557974;received=127.0.0.1;rport=5066
From: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
To: <sip:1111@127.0.0.1:5060>
Call-ID: 1314412951
CSeq: 21 INVITE
Server: Asterisk PBX 11.15.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:1111@127.0.0.1:5060>
Content-Length: 0


<------------>
[2015-02-08 12:31:00.822] VERBOSE[8223][C-00000000] chan_sip.c: Audio is at 21606
[2015-02-08 12:31:00.822] VERBOSE[8223][C-00000000] chan_sip.c: Adding codec 100002 (gsm) to SDP
[2015-02-08 12:31:00.822] VERBOSE[8223][C-00000000] chan_sip.c: Adding codec 100003 (ulaw) to SDP
[2015-02-08 12:31:00.822] VERBOSE[8223][C-00000000] chan_sip.c: Adding codec 100004 (alaw) to SDP
[2015-02-08 12:31:00.822] VERBOSE[8223][C-00000000] chan_sip.c: 
<--- Reliably Transmitting (no NAT) to 127.0.0.1:5066 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.101:5066;branch=z9hG4bK491557974;received=127.0.0.1;rport=5066
From: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
To: <sip:1111@127.0.0.1:5060>;tag=as3c4112fa
Call-ID: 1314412951
CSeq: 21 INVITE
Server: Asterisk PBX 11.15.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:1111@127.0.0.1:5060>
Content-Type: application/sdp
Content-Length: 246

v=0
o=root 686143697 686143697 IN IP4 127.0.0.1
s=Asterisk PBX 11.15.0
c=IN IP4 127.0.0.1
t=0 0
m=audio 21606 RTP/AVP 3 0 8
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[2015-02-08 12:31:00.829] VERBOSE[7855] chan_sip.c: 
<--- SIP read from UDP:127.0.0.1:5066 --->
ACK sip:1111@127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.101:5066;rport;branch=z9hG4bK1513183882
From: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
To: <sip:1111@127.0.0.1:5060>;tag=as3c4112fa
Call-ID: 1314412951
CSeq: 21 ACK
Contact: <sip:lenovo@127.0.0.1:5066>
Max-Forwards: 70
User-Agent: Linphone/3.3.2 (eXosip2/3.3.0)
Content-Length: 0

<------------->
[2015-02-08 12:31:00.829] VERBOSE[7855] chan_sip.c: --- (10 headers 0 lines) ---
[2015-02-08 12:31:02.453] VERBOSE[8223][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '1314412951' in 6400 ms (Method: ACK)
[2015-02-08 12:31:02.453] VERBOSE[8223][C-00000000] chan_sip.c: set_destination: Parsing <sip:lenovo@127.0.0.1:5066> for address/port to send to
[2015-02-08 12:31:02.453] VERBOSE[8223][C-00000000] chan_sip.c: set_destination: set destination to 127.0.0.1:5066
[2015-02-08 12:31:02.453] VERBOSE[8223][C-00000000] chan_sip.c: Reliably Transmitting (no NAT) to 127.0.0.1:5066:
BYE sip:lenovo@127.0.0.1:5066 SIP/2.0
Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK66229553;rport
Max-Forwards: 70
From: <sip:1111@127.0.0.1:5060>;tag=as3c4112fa
To: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
Call-ID: 1314412951
CSeq: 102 BYE
User-Agent: Asterisk PBX 11.15.0
Proxy-Authorization: Digest username="lenovo", realm="Dictador", algorithm=MD5, uri="sip:127.0.0.1", nonce="17879f1b", response="6c65f186a9ed9c165328ea759fb141f5"
Reason: Q.850;cause=16
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[2015-02-08 12:31:02.453] VERBOSE[7855] chan_sip.c: 
<--- SIP read from UDP:127.0.0.1:5066 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK66229553;rport=5060
From: <sip:1111@127.0.0.1:5060>;tag=as3c4112fa
To: <sip:lenovo@127.0.0.1:5066>;tag=1602773833
Call-ID: 1314412951
CSeq: 102 BYE
User-Agent: Linphone/3.3.2 (eXosip2/3.3.0)
Content-Length: 0