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