5 second delay for outbound calls from any phone (Softphone and Physical Phone)

Hello all.

When placing outbound call there is a 5 second delay before making a call. internal calls are fine, checked DNS everything looks fine, brand new install. Firewall functioning normal I guess, no troubles.

Any suggestions?

Sounds like something to do with your trunk settings or carrier but we will need more information or logs before we can help you

It is almost certainly the “dial-strings” you have set on your physical or virtual phones, maybe you need to terminate an undefined string with #

Here is the Trunk config for the outbound:

host=IP
type=friend
insecure=port,invite
disallow=all
allow=ulaw&alaw
dtmfmode=rfc2833

Which logs do you need exactly, here is a logs of when I am placing a call:

  == Using SIP RTP TOS bits 184
  == Using SIP RTP CoS mark 5
  -- Called SIP/Voip-outbound/number

And then it sits for about 5 seconds and places a call.

Do you have a “dial plan” set on your phone, that determines that certain digit strings will get sent immediately if they match a specific pattern?
If not, your phone may wait those 5 seconds before it sends the digits.

Tested from 5 different configurations:
Softphone no dialplan as there is no way to configure it (MAC and Windows)
From Cisco Phone
Dialplan 1: (xx|[x#].)
Dialplan 2: (*xx|[3469]11|0|00|[2-9]xxxxxx|1xxx[2-9]xxxxxxS0|xxxxxxxxxxxx.)
Dialplan 3: none

Result the same.

So I am guessing everyone out of ideas.

Until you post a call trace with time stamps all you are going to get are vague guesses.

If you need more staff just tell me what you need. Here is a Log trace of the call:

<--- SIP read from UDP:"PEER IP":49384 --->

<------------->
[2017-04-11 08:02:13] VERBOSE[8815] chan_sip.c:
<--- SIP read from UDP:"PEER IP":49384 --->
INVITE sip:"NUMBER"@"PBX IP" SIP/2.0
Via: SIP/2.0/UDP "PEER IP":49384;rport;branch=z9hG4bKPj6diTs76itkVwky.aFwylJqXQXPg3Ouae
Max-Forwards: 70
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">
Contact: "USER" <sip:[email protected]"PEER IP":49384;ob>
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21417 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, norefersub
User-Agent: Telephone 1.2.6
Content-Type: application/sdp
Content-Length: 535

v=0
o=- 3700900932 3700900932 IN IP4 "PEER IP"
s=pjmedia
b=AS:117
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 103 102 104 125 109 3 0 8 9 101
c=IN IP4 "PEER IP"
b=TIAS:96000
a=rtcp:4001 IN IP4 "PEER IP"
a=sendrecv
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:104 speex/32000
a=rtpmap:125 opus/48000/2
a=fmtp:125 useinbandfec=1
a=rtpmap:109 iLBC/8000
a=fmtp:109 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
<------------->
[2017-04-11 08:02:13] VERBOSE[8815] chan_sip.c: --- (13 headers 24 lines) ---
[2017-04-11 08:02:13] VERBOSE[8815] chan_sip.c: Sending to "PEER IP":49384 (no NAT)
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Sending to "PEER IP":49384 (no NAT)
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Using INVITE request as basis request - gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found peer 'EXT' for 'EXT' from "PEER IP":49384
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c:
<--- Reliably Transmitting (NAT) to "PEER IP":49384 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP "PEER IP":49384;branch=z9hG4bKPj6diTs76itkVwky.aFwylJqXQXPg3Ouae;received="PEER IP";rport=49384
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">;tag=as0a209b1f
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21417 INVITE
Server: FPBX-13.0.190.19(13.14.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="4beddd80"
Content-Length: 0


<------------>
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Scheduling destruction of SIP dialog 'gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR' in 6400 ms (Method: INVITE)
[2017-04-11 08:02:13] VERBOSE[8815] chan_sip.c:
<--- SIP read from UDP:"PEER IP":49384 --->
ACK sip:"NUMBER"@"PBX IP" SIP/2.0
Via: SIP/2.0/UDP "PEER IP":49384;rport;branch=z9hG4bKPj6diTs76itkVwky.aFwylJqXQXPg3Ouae
Max-Forwards: 70
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">;tag=as0a209b1f
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21417 ACK
Content-Length: 0

<------------->
[2017-04-11 08:02:13] VERBOSE[8815] chan_sip.c: --- (8 headers 0 lines) ---
[2017-04-11 08:02:13] VERBOSE[8815] chan_sip.c:
<--- SIP read from UDP:"PEER IP":49384 --->
INVITE sip:"NUMBER"@"PBX IP" SIP/2.0
Via: SIP/2.0/UDP "PEER IP":49384;rport;branch=z9hG4bKPjUYR.BIij5f6KmhqwAiIyyC5HLqAhJekX
Max-Forwards: 70
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">
Contact: "USER" <sip:[email protected]"PEER IP":49384;ob>
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21418 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, norefersub
User-Agent: Telephone 1.2.6
Authorization: Digest username="EXT", realm="asterisk", nonce="4beddd80", uri="sip:"NUMBER"@"PBX IP"", response="a719ed256fb4e61aaecfb325a0f5aed5", algorithm=MD5
Content-Type: application/sdp
Content-Length: 535

v=0
o=- 3700900932 3700900932 IN IP4 "PEER IP"
s=pjmedia
b=AS:117
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 103 102 104 125 109 3 0 8 9 101
c=IN IP4 "PEER IP"
b=TIAS:96000
a=rtcp:4001 IN IP4 "PEER IP"
a=sendrecv
a=rtpmap:103 speex/16000
a=rtpmap:102 speex/8000
a=rtpmap:104 speex/32000
a=rtpmap:125 opus/48000/2
a=fmtp:125 useinbandfec=1
a=rtpmap:109 iLBC/8000
a=fmtp:109 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
<------------->
[2017-04-11 08:02:13] VERBOSE[8815] chan_sip.c: --- (14 headers 24 lines) ---
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Sending to "PEER IP":49384 (NAT)
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Using INVITE request as basis request - gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found peer 'EXT' for 'EXT' from "PEER IP":49384
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 103
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 102
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 104
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 125
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 109
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 3
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 0
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 8
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 9
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found RTP audio format 101
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format speex for ID 103
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format speex for ID 102
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format speex for ID 104
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format opus for ID 125
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format iLBC for ID 109
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format GSM for ID 3
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format PCMU for ID 0
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format PCMA for ID 8
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format G722 for ID 9
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Found audio description format telephone-event for ID 101
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Capabilities: us - (ulaw|alaw|gsm|g726), peer - audio=(ulaw|gsm|alaw|g722|speex|speex16|speex32|ilbc|opus)/video=(nothing)/text=(nothing), combined - (ulaw|alaw|gsm)
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Peer audio RTP is at port "PEER IP":4000
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c: Looking for "NUMBER" in from-internal (domain "PBX IP")
[2017-04-11 08:02:13] VERBOSE[8295] chan_sip.c: Extension Changed EXT[ext-local] new state InUse for Notify User 289
[2017-04-11 08:02:13] VERBOSE[8295] chan_sip.c: Extension Changed EXT[ext-local] new state InUse for Notify User 277
[2017-04-11 08:02:13] VERBOSE[8295] chan_sip.c: Extension Changed EXT[ext-local] new state InUse for Notify User 300
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] sip/route.c: sip_route_dump: route/path hop: <sip:[email protected]"PEER IP":49384;ob>
[2017-04-11 08:02:13] VERBOSE[8815][C-00002ae7] chan_sip.c:
<--- Transmitting (NAT) to "PEER IP":49384 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP "PEER IP":49384;branch=z9hG4bKPjUYR.BIij5f6KmhqwAiIyyC5HLqAhJekX;received="PEER IP";rport=49384
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21418 INVITE
Server: FPBX-13.0.190.19(13.14.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:"NUMBER"@"PBX IP":5060>
Content-Length: 0


<------------>
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing ["NUMBER"@from-internal:1] Macro("SIP/EXT-00008c03", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] Set("SIP/EXT-00008c03", "TOUCH_MONITOR=1491912133.83656") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:2] Set("SIP/EXT-00008c03", "AMPUSER=EXT") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:3] GotoIf("SIP/EXT-00008c03", "0?report") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:4] ExecIf("SIP/EXT-00008c03", "1?Set(REALCALLERIDNUM=EXT)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:5] Set("SIP/EXT-00008c03", "AMPUSER=EXT") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:6] GotoIf("SIP/EXT-00008c03", "0?limit") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:7] Set("SIP/EXT-00008c03", "AMPUSERCIDNAME=USER") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:8] GotoIf("SIP/EXT-00008c03", "0?report") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:9] Set("SIP/EXT-00008c03", "AMPUSERCID=EXT") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:10] Set("SIP/EXT-00008c03", "__DIAL_OPTIONS=Ttr") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:11] Set("SIP/EXT-00008c03", "CALLERID(all)="USER" <EXT>") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:12] GotoIf("SIP/EXT-00008c03", "0?limit") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:13] ExecIf("SIP/EXT-00008c03", "1?Set(GROUP(concurrency_limit)=EXT)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:14] ExecIf("SIP/EXT-00008c03", "0?Set(CHANNEL(language)=)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:15] GotoIf("SIP/EXT-00008c03", "1?continue") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:29] Set("SIP/EXT-00008c03", "CALLERID(number)=EXT") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:30] Set("SIP/EXT-00008c03", "CALLERID(name)=USER") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:31] GotoIf("SIP/EXT-00008c03", "0?cnum") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:32] Set("SIP/EXT-00008c03", "CDR(cnam)=USER") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:33] Set("SIP/EXT-00008c03", "CDR(cnum)=EXT") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:34] Set("SIP/EXT-00008c03", "CHANNEL(language)=en") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing ["NUMBER"@from-internal:2] Gosub("SIP/EXT-00008c03", "sub-record-check,s,1(out,"NUMBER",dontcare)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] GotoIf("SIP/EXT-00008c03", "0?initialized") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:2] Set("SIP/EXT-00008c03", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:3] Set("SIP/EXT-00008c03", "NOW=1491912133") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:4] Set("SIP/EXT-00008c03", "__DAY=11") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:5] Set("SIP/EXT-00008c03", "__MONTH=04") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:6] Set("SIP/EXT-00008c03", "__YEAR=2017") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:7] Set("SIP/EXT-00008c03", "__TIMESTR=20170411-080213") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:8] Set("SIP/EXT-00008c03", "__FROMEXTEN=EXT") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:9] Set("SIP/EXT-00008c03", "__MON_FMT=wav") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:10] NoOp("SIP/EXT-00008c03", "Recordings initialized") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:11] ExecIf("SIP/EXT-00008c03", "0?Set(ARG3=dontcare)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:12] Set("SIP/EXT-00008c03", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:13] ExecIf("SIP/EXT-00008c03", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:14] GotoIf("SIP/EXT-00008c03", "3?checkaction") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:17] GotoIf("SIP/EXT-00008c03", "1?sub-record-check,out,1") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx_builtins.c: Goto (sub-record-check,out,1)
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] NoOp("SIP/EXT-00008c03", "Outbound Recording Check from EXT to "NUMBER"") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:2] Set("SIP/EXT-00008c03", "RECMODE=dontcare") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:3] ExecIf("SIP/EXT-00008c03", "1?Goto(routewins)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx_builtins.c: Goto (sub-record-check,out,7)
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:7] Gosub("SIP/EXT-00008c03", "recordcheck,1(dontcare,out,"NUMBER")") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] NoOp("SIP/EXT-00008c03", "Starting recording check against dontcare") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:2] Goto("SIP/EXT-00008c03", "dontcare") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:3] Return("SIP/EXT-00008c03", "") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:8] Return("SIP/EXT-00008c03", "") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing ["NUMBER"@from-internal:3] ExecIf("SIP/EXT-00008c03", "0 ?Set(CDR(accountcode)=)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing ["NUMBER"@from-internal:4] Set("SIP/EXT-00008c03", "MOHCLASS=default") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing ["NUMBER"@from-internal:5] Set("SIP/EXT-00008c03", "_NODEST=") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing ["NUMBER"@from-internal:6] Macro("SIP/EXT-00008c03", "dialout-trunk,14,"NUMBER",,off") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] Set("SIP/EXT-00008c03", "DIAL_TRUNK=14") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:2] GosubIf("SIP/EXT-00008c03", "0?sub-pincheck,s,1()") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:3] GotoIf("SIP/EXT-00008c03", "0?disabletrunk,1") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:4] Set("SIP/EXT-00008c03", "DIAL_NUMBER="NUMBER"") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:5] Set("SIP/EXT-00008c03", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:6] Set("SIP/EXT-00008c03", "OUTBOUND_GROUP=OUT_14") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:7] GotoIf("SIP/EXT-00008c03", "0?nomax") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:8] GotoIf("SIP/EXT-00008c03", "0?chanfull") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:9] GotoIf("SIP/EXT-00008c03", "0?skipoutcid") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:10] Set("SIP/EXT-00008c03", "DIAL_TRUNK_OPTIONS=T") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:11] Macro("SIP/EXT-00008c03", "outbound-callerid,14") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] ExecIf("SIP/EXT-00008c03", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:2] ExecIf("SIP/EXT-00008c03", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:3] ExecIf("SIP/EXT-00008c03", "0?Set(REALCALLERIDNUM=EXT)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:4] GotoIf("SIP/EXT-00008c03", "1?normcid") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx_builtins.c: Goto (macro-outbound-callerid,s,7)
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:7] Set("SIP/EXT-00008c03", "USEROUTCID=Visaplace<4164107484>") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:8] Set("SIP/EXT-00008c03", "EMERGENCYCID=") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:9] Set("SIP/EXT-00008c03", "TRUNKOUTCID=Niren and Assosiates<4164107484>") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:10] GotoIf("SIP/EXT-00008c03", "1?trunkcid") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx_builtins.c: Goto (macro-outbound-callerid,s,15)
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:15] ExecIf("SIP/EXT-00008c03", "1?Set(CALLERID(all)=Niren and Assosiates<4164107484>)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:16] ExecIf("SIP/EXT-00008c03", "1?Set(CALLERID(all)=Visaplace<4164107484>)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:17] ExecIf("SIP/EXT-00008c03", "0?Set(CALLERID(all)=)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:18] ExecIf("SIP/EXT-00008c03", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:19] ExecIf("SIP/EXT-00008c03", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:20] Set("SIP/EXT-00008c03", "CDR(outbound_cnum)=4164107484") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:21] Set("SIP/EXT-00008c03", "CDR(outbound_cnam)=Visaplace") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:12] GosubIf("SIP/EXT-00008c03", "0?sub-flp-14,s,1()") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:13] Set("SIP/EXT-00008c03", "OUTNUM="NUMBER"") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:14] Set("SIP/EXT-00008c03", "custom=SIP/vitel-outbound") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:15] ExecIf("SIP/EXT-00008c03", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:16] ExecIf("SIP/EXT-00008c03", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:17] Macro("SIP/EXT-00008c03", "dialout-trunk-predial-hook,") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] MacroExit("SIP/EXT-00008c03", "") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:18] GotoIf("SIP/EXT-00008c03", "0?bypass,1") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:19] ExecIf("SIP/EXT-00008c03", "1?Set(CONNECTEDLINE(num,i)="NUMBER")") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:20] ExecIf("SIP/EXT-00008c03", "1?Set(CONNECTEDLINE(name,i)=CID:4164107484)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:21] ExecIf("SIP/EXT-00008c03", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)4164107484)") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:22] GotoIf("SIP/EXT-00008c03", "0?customtrunk") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:23] Dial("SIP/EXT-00008c03", "SIP/vitel-outbound/"NUMBER",300,T") in new stack
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] app_dial.c: Called SIP/vitel-outbound/"NUMBER"
[2017-04-11 08:02:15] VERBOSE[15969][C-00002ae7] app_dial.c: SIP/vitel-outbound-00008c04 is making progress passing it to SIP/EXT-00008c03
[2017-04-11 08:02:15] VERBOSE[15969][C-00002ae7] chan_sip.c: Audio is at 17800
[2017-04-11 08:02:15] VERBOSE[15969][C-00002ae7] chan_sip.c: Adding codec ulaw to SDP
[2017-04-11 08:02:15] VERBOSE[15969][C-00002ae7] chan_sip.c: Adding codec alaw to SDP
[2017-04-11 08:02:15] VERBOSE[15969][C-00002ae7] chan_sip.c: Adding codec gsm to SDP
[2017-04-11 08:02:15] VERBOSE[15969][C-00002ae7] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2017-04-11 08:02:15] VERBOSE[15969][C-00002ae7] chan_sip.c:
<--- Transmitting (NAT) to "PEER IP":49384 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP "PEER IP":49384;branch=z9hG4bKPjUYR.BIij5f6KmhqwAiIyyC5HLqAhJekX;received="PEER IP";rport=49384
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">;tag=as12403141
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21418 INVITE
Server: FPBX-13.0.190.19(13.14.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:"NUMBER"@"PBX IP":5060>
Content-Type: application/sdp
Content-Length: 291

v=0
o=root 840722556 840722556 IN IP4 "PBX IP"
s=Asterisk PBX 13.14.0
c=IN IP4 "PBX IP"
t=0 0
m=audio 17800 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<------------>
[2017-04-11 08:02:23] VERBOSE[8815] chan_sip.c:
<--- SIP read from UDP:"PEER IP":49384 --->
CANCEL sip:"NUMBER"@"PBX IP" SIP/2.0
Via: SIP/2.0/UDP "PEER IP":49384;rport;branch=z9hG4bKPjUYR.BIij5f6KmhqwAiIyyC5HLqAhJekX
Max-Forwards: 70
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21418 CANCEL
User-Agent: Telephone 1.2.6
Content-Length: 0

<------------->
[2017-04-11 08:02:23] VERBOSE[8815] chan_sip.c: --- (9 headers 0 lines) ---
[2017-04-11 08:02:23] VERBOSE[8815][C-00002ae7] chan_sip.c: Sending to "PEER IP":49384 (NAT)
[2017-04-11 08:02:23] VERBOSE[8815][C-00002ae7] chan_sip.c:
<--- Reliably Transmitting (NAT) to "PEER IP":49384 --->
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP "PEER IP":49384;branch=z9hG4bKPjUYR.BIij5f6KmhqwAiIyyC5HLqAhJekX;received="PEER IP";rport=49384
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">;tag=as12403141
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21418 INVITE
Server: FPBX-13.0.190.19(13.14.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[2017-04-11 08:02:23] VERBOSE[8815][C-00002ae7] chan_sip.c:
<--- Transmitting (NAT) to "PEER IP":49384 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP "PEER IP":49384;branch=z9hG4bKPjUYR.BIij5f6KmhqwAiIyyC5HLqAhJekX;received="PEER IP";rport=49384
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">;tag=as12403141
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21418 CANCEL
Server: FPBX-13.0.190.19(13.14.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


<------------>
[2017-04-11 08:02:23] VERBOSE[8295] chan_sip.c: Extension Changed EXT[ext-local] new state Idle for Notify User 289
[2017-04-11 08:02:23] VERBOSE[8295] chan_sip.c: Extension Changed EXT[ext-local] new state Idle for Notify User 277
[2017-04-11 08:02:23] VERBOSE[8295] chan_sip.c: Extension Changed EXT[ext-local] new state Idle for Notify User 300
[2017-04-11 08:02:23] VERBOSE[8815] chan_sip.c:
<--- SIP read from UDP:"PEER IP":49384 --->
ACK sip:"NUMBER"@"PBX IP" SIP/2.0
Via: SIP/2.0/UDP "PEER IP":49384;rport;branch=z9hG4bKPjUYR.BIij5f6KmhqwAiIyyC5HLqAhJekX
Max-Forwards: 70
From: "USER" <sip:[email protected]"PBX IP">;tag=spgo.hY3fjhZWCP-44CJHec9V.oc9rJb
To: <sip:"NUMBER"@"PBX IP">;tag=as12403141
Call-ID: gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR
CSeq: 21418 ACK
Content-Length: 0

<------------->
[2017-04-11 08:02:23] VERBOSE[8815] chan_sip.c: --- (8 headers 0 lines) ---
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] app_macro.c: Spawn extension (macro-dialout-trunk, s, 23) exited non-zero on 'SIP/EXT-00008c03' in macro 'dialout-trunk'
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] pbx.c: Spawn extension (from-internal, "NUMBER", 6) exited non-zero on 'SIP/EXT-00008c03'
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] Macro("SIP/EXT-00008c03", "hangupcall") in new stack
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:1] GotoIf("SIP/EXT-00008c03", "1?theend") in new stack
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:3] ExecIf("SIP/EXT-00008c03", "0?Set(CDR(recordingfile)=)") in new stack
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] pbx.c: Executing [[email protected]:4] Hangup("SIP/EXT-00008c03", "") in new stack
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/EXT-00008c03' in macro 'hangupcall'
[2017-04-11 08:02:23] VERBOSE[15969][C-00002ae7] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/EXT-00008c03'
[2017-04-11 08:02:23] VERBOSE[8815] chan_sip.c: Really destroying SIP dialog 'gJZcP0DLGp2lRmlDXmW88dDPPCxP5VVR' Method: ACK

The delay happens here:

[2017-04-11 08:02:13] VERBOSE[15969][C-00002ae7] app_dial.c: Called SIP/vitel-outbound/"NUMBER"
[2017-04-11 08:02:23] VERBOSE[8815] chan_sip.c: --- (9 headers 0 lines) ---

I can’t see where the call was even answered, but there is a 10 second lapse from the moment you initiate the dial to vitelity until the next line logged in Asterisk. The delay is your provider, possibly due to a misconfigured trunk or just general slowness on their part, I can’t say I don’t use them.

The call was not answered I just hanged up. Ok thank you for the insight I will try to reach provider to see what is up with them.