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