Long delay on inbound calls

When I call my FreePBX box it takes 8 to 12 seconds for the IVR voice recording to welcome the caller. Consequently I get a lot of hangups and redials from people thinking the “call is not going thru.”

Years ago I had some experience with a Trixbox setup and do not remember experiencing this delay on inbound. I would like to reduce this time but have been unable to post a copy of a recent “asterisk -vvvr” log.

How can I attach a *.txt file for someone to look at?

Are these Dahdi Calls?

Are these analogue calls it sounds to me like it’s your caller id detection settings make sure they are correct for your provider

Jason

I have sanitized the “asterisk -vvvr” printout:

[[email protected]*****host ~]# asterisk -vvvr
Asterisk 13.14.0, Copyright © 1999 - 2014, Digium, Inc. and others.
Created by Mark Spencer [email protected]
Asterisk comes with ABSOLUTELY NO WARRANTY; type ‘core show warranty’ for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type ‘core show license’ for details.

Connected to Asterisk 13.14.0 currently running on localhost (pid = 2173)
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– Executing [1[email protected]:1] Set(“SIP/VPFIVE01VA-000000d7”, “__DIRECTION=INBOUND”) in new stack
– Executing [1
[email protected]:2] Gosub(“SIP/VPFIVE01VA-000000d7”, “sub-record-check,s,1(in,1*********6,dontcare)”) in new stack
– Executing [[email protected]:1] GotoIf(“SIP/VPFIVE01VA-000000d7”, “0?initialized”) in new stack
– Executing [[email protected]:2] Set(“SIP/VPFIVE01VA-000000d7”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [[email protected]:3] Set(“SIP/VPFIVE01VA-000000d7”, “NOW=1487957108”) in new stack
– Executing [[email protected]:4] Set(“SIP/VPFIVE01VA-000000d7”, “__DAY=24”) in new stack
– Executing [[email protected]:5] Set(“SIP/VPFIVE01VA-000000d7”, “__MONTH=02”) in new stack
– Executing [[email protected]:6] Set(“SIP/VPFIVE01VA-000000d7”, “__YEAR=2017”) in new stack
– Executing [[email protected]:7] Set(“SIP/VPFIVE01VA-000000d7”, “__TIMESTR=20170224-112508”) in new stack
– Executing [[email protected]:8] Set(“SIP/VPFIVE01VA-000000d7”, “__FROMEXTEN=unknown”) in new stack
– Executing [[email protected]:9] Set(“SIP/VPFIVE01VA-000000d7”, “__MON_FMT=wav”) in new stack
– Executing [[email protected]:10] NoOp(“SIP/VPFIVE01VA-000000d7”, “Recordings initialized”) in new stack
– Executing [[email protected]:11] ExecIf(“SIP/VPFIVE01VA-000000d7”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [[email protected]:12] Set(“SIP/VPFIVE01VA-000000d7”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [[email protected]:13] ExecIf(“SIP/VPFIVE01VA-000000d7”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [[email protected]:14] GotoIf(“SIP/VPFIVE01VA-000000d7”, “2?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [[email protected]:17] GotoIf(“SIP/VPFIVE01VA-000000d7”, “1?sub-record-check,in,1”) in new stack
– Goto (sub-record-check,in,1)
– Executing [[email protected]:1] NoOp(“SIP/VPFIVE01VA-000000d7”, “Inbound Recording Check to 1*********6”) in new stack
– Executing [[email protected]:2] Set(“SIP/VPFIVE01VA-000000d7”, “FROMEXTEN=unknown”) in new stack
– Executing [[email protected]:3] ExecIf(“SIP/VPFIVE01VA-000000d7”, “10?Set(FROMEXTEN=*********0)”) in new stack
– Executing [[email protected]:4] Gosub(“SIP/VPFIVE01VA-000000d7”, “recordcheck,1(dontcare,in,1*********6)”) in new stack
– Executing [[email protected]:1] NoOp(“SIP/VPFIVE01VA-000000d7”, “Starting recording check against dontcare”) in new stack
– Executing [[email protected]:2] Goto(“SIP/VPFIVE01VA-000000d7”, “dontcare”) in new stack
– Goto (sub-record-check,recordcheck,3)
– Executing [[email protected]:3] Return(“SIP/VPFIVE01VA-000000d7”, “”) in new stack
– Executing [[email protected]:5] Return(“SIP/VPFIVE01VA-000000d7”, “”) in new stack
– Executing [1*[email protected]:3] Gosub(“SIP/VPFIVE01VA-000000d7”, “app-blacklist-check,s,1()”) in new stack
– Executing [[email protected]:1] GotoIf(“SIP/VPFIVE01VA-000000d7”, “0?blacklisted”) in new stack
– Executing [[email protected]:2] Set(“SIP/VPFIVE01VA-000000d7”, “CALLED_BLACKLIST=1”) in new stack
– Executing [[email protected]:3] Return(“SIP/VPFIVE01VA-000000d7”, “”) in new stack
– Executing [1
[email protected]:4] Set(“SIP/VPFIVE01VA-000000d7”, “__FROM_DID=1*********6”) in new stack
– Executing [1*********[email protected]:5] Set(“SIP/VPFIVE01VA-000000d7”, “CDR(did)=1*********6”) in new stack
– Executing [1*********[email protected]:6] ExecIf(“SIP/VPFIVE01VA-000000d7”, “0 ?Set(CALLERID(name)=*********0)”) in new stack
– Executing [1*********[email protected]:7] Set(“SIP/VPFIVE01VA-000000d7”, “__MOHCLASS=”) in new stack
– Executing [1*********[email protected]:8] Ringing(“SIP/VPFIVE01VA-000000d7”, “”) in new stack
– Executing [1*********[email protected]:9] Set(“SIP/VPFIVE01VA-000000d7”, “__RINGINGSENT=TRUE”) in new stack
– Executing [1*********[email protected]:10] Set(“SIP/VPFIVE01VA-000000d7”, “__REVERSAL_REJECT=FALSE”) in new stack
– Executing [1*********[email protected]:11] GotoIf(“SIP/VPFIVE01VA-000000d7”, “1?post-reverse-charge”) in new stack
– Goto (from-pstn,1*********6,13)
– Executing [1*********[email protected]:13] NoOp(“SIP/VPFIVE01VA-000000d7”, “”) in new stack
– Executing [1*********[email protected]:14] Set(“SIP/VPFIVE01VA-000000d7”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
– Executing [1*********[email protected]:15] Set(“SIP/VPFIVE01VA-000000d7”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
– Executing [1*********[email protected]:16] Set(“SIP/VPFIVE01VA-000000d7”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
– Executing [1*********[email protected]:17] Set(“SIP/VPFIVE01VA-000000d7”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
– Executing [1*********[email protected]:18] NoOp(“SIP/VPFIVE01VA-000000d7”, “CallerID Entry Point”) in new stack
– Executing [1*********[email protected]:19] Set(“SIP/VPFIVE01VA-000000d7”, “FAX_DEST=ext-fax^s^1”) in new stack
– Executing [1*********[email protected]:20] Set(“SIP/VPFIVE01VA-000000d7”, "[email protected]") in new stack
– Executing [1*********[email protected]:21] Set(“SIP/VPFIVE01VA-000000d7”, “FAXOPT(faxdetect)=yes”) in new stack
– Executing [1*********[email protected]:22] Answer(“SIP/VPFIVE01VA-000000d7”, “”) in new stack
– Executing [1*****[email protected]:23] Wait(“SIP/VPFIVE01VA-000000d7”, “3”) in new stack
– Executing [1[email protected]:24] Goto(“SIP/VPFIVE01VA-000000d7”, “timeconditions,3,1”) in new stack
– Goto (timeconditions,3,1)
– Executing [[email protected]:1] Set(“SIP/VPFIVE01VA-000000d7”, “DB(TC/3/INUSESTATE)=INUSE”) in new stack
– Executing [[email protected]:2] Set(“SIP/VPFIVE01VA-000000d7”, “DB(TC/3/NOT_INUSESTATE)=NOT_INUSE”) in new stack
– Executing [[email protected]:3] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "
,mon,15-19,feb,America/Chicago?truestate") in new stack
– Executing [[email protected]:4] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "
,mon,1-7,sep,America/Chicago?truestate") in new stack
– Executing [[email protected]:5] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "
,mon,25-31,may,America/Chicago?truestate") in new stack
– Executing [[email protected]:6] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "
,
,25,dec,America/Chicago?truestate") in new stack
– Executing [[email protected]:7] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "
,
,4,jul,America/Chicago?truestate") in new stack
– Executing [[email protected]:8] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "
,
,1,jan,America/Chicago?truestate") in new stack
– Executing [[email protected]:9] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "
,thu,22-28,nov,America/Chicago?truestate") in new stack
– Executing [[email protected]:10] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "
,mon,15-21,jan,America/Chicago?truestate") in new stack
– Executing [[email protected]:11] GotoIf(“SIP/VPFIVE01VA-000000d7”, “0?truegoto”) in new stack
– Executing [[email protected]:12] ExecIf(“SIP/VPFIVE01VA-000000d7”, “0?Set(DB(TC/3)=)”) in new stack
– Executing [[email protected]:13] Set(“SIP/VPFIVE01VA-000000d7”, “DEVICE_STATE(Custom:TC3)=INUSE”) in new stack
– Executing [[email protected]:14] ExecIf(“SIP/VPFIVE01VA-000000d7”, “0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)”) in new stack
– Executing [[email protected]:15] GotoIf(“SIP/VPFIVE01VA-000000d7”, “1?timeconditions,1,1”) in new stack
– Goto (timeconditions,1,1)
– Executing [[email protected]:1] Set(“SIP/VPFIVE01VA-000000d7”, “DB(TC/1/INUSESTATE)=INUSE”) in new stack
– Executing [[email protected]:2] Set(“SIP/VPFIVE01VA-000000d7”, “DB(TC/1/NOT_INUSESTATE)=NOT_INUSE”) in new stack
– Executing [[email protected]:3] GotoIfTime(“SIP/VPFIVE01VA-000000d7”, "09:00-17:00,mon-fri,
,
,America/Chicago?truestate") in new stack
– Goto (timeconditions,1,12)
– Executing [[email protected]:12] GotoIf(“SIP/VPFIVE01VA-000000d7”, “0?falsegoto”) in new stack
– Executing [[email protected]:13] ExecIf(“SIP/VPFIVE01VA-000000d7”, “0?Set(DB(TC/1)=)”) in new stack
– Executing [[email protected]:14] Set(“SIP/VPFIVE01VA-000000d7”, “DEVICE_STATE(Custom:TC1)=NOT_INUSE”) in new stack
– Executing [[email protected]:15] ExecIf(“SIP/VPFIVE01VA-000000d7”, “0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)”) in new stack
– Executing [[email protected]:16] GotoIf(“SIP/VPFIVE01VA-000000d7”, “1?app-announcement-1,s,1”) in new stack
– Goto (app-announcement-1,s,1)
– Executing [[email protected]:1] GotoIf(“SIP/VPFIVE01VA-000000d7”, “1?begin”) in new stack
– Goto (app-announcement-1,s,4)
– Executing [[email protected]:4] NoOp(“SIP/VPFIVE01VA-000000d7”, “Playing announcement please-wait”) in new stack
– Executing [[email protected]:5] Playback(“SIP/VPFIVE01VA-000000d7”, “custom/please-wait,noanswer”) in new stack
– <SIP/VPFIVE01VA-000000d7> Playing ‘custom/please-wait.ulaw’ (language ‘en’)

I have two time conditions. One for holidays and one for the hours we are open.

As I am unfamiliar with the “asterisk -vvvr” output, I am not sure what I am looking at or what for?
Now that I have attached this information, what can I do too reduce the time of silence I am experiencing?

Stripping out the time stamps on the lines made this way harder. I don’t suppose you could try again, but leave the timestamps in so we can see where the delay is actually happening?

I am sorry. I rarely review files of this type and missed that the time stamps were not included. This is a learn as I go type project.

I tried various combinations of the “-vrrrr” switches and have not found any that attach time stamps. That moved me to find the "/var/log/asterisk/* directory and begin “tailing” there. These log files are too large to post here.

From what I have “Internet searched” this is a rather unique problem and I have begun researching ssh support options that are responsibly priced to resolve my issue.

If needed, I’ll be back . . . .

You can add

timestamp=yes

To the options section of /etc/asterisk/asterisk.conf and restart asterisk