Slow to connect inbound and outbound calls

I am seeing some serious delays, like around 20-25 seconds on both incoming calls, outgoing calls, and internal extension to extension calls. I’ve tried rebooting the system and my network with no fix. Below is a log of an outgoing call. I’m not great at reading these logs, but it looks like the system does some work for awhile (09:41:05) then pauses for 9 seconds and does some more (09:41:14), then pauses 6 seconds and does some more (09:41:20)

Any idea where to start looking for a fix?

[2016-08-12 09:41:04] VERBOSE[2083][C-0000004f] netsock2.c: == Using SIP RTP CoS mark 5
[2016-08-12 09:41:04] VERBOSE[2067] chan_sip.c: == Extension Changed auto_hint_9008[from-internal] new state InUse for Notify User 9146
[2016-08-12 09:41:04] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] Macro("SIP/9008-00000081", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2016-08-12 09:41:04] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] Set("SIP/9008-00000081", "TOUCH_MONITOR=1471012864.162") in new stack
[2016-08-12 09:41:04] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:2] Set("SIP/9008-00000081", "AMPUSER=9008") in new stack
[2016-08-12 09:41:04] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/9008-00000081", "0?report") in new stack
[2016-08-12 09:41:04] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/9008-00000081", "1?Set(REALCALLERIDNUM=9008)") in new stack
[2016-08-12 09:41:05] VERBOSE[2067] chan_sip.c: == Extension Changed auto_hint_9009[from-internal] new state Unavailable for Notify User 9146
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:5] Set("SIP/9008-00000081", "AMPUSER=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:6] GotoIf("SIP/9008-00000081", "0?limit") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:7] Set("SIP/9008-00000081", "AMPUSERCIDNAME=Brad Phillips") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:8] GotoIf("SIP/9008-00000081", "0?report") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:9] Set("SIP/9008-00000081", "AMPUSERCID=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:10] Set("SIP/9008-00000081", "__DIAL_OPTIONS=Ttr") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:11] Set("SIP/9008-00000081", "CALLERID(all)="Brad Phillips" <9008>") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:12] GotoIf("SIP/9008-00000081", "0?limit") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:13] ExecIf("SIP/9008-00000081", "1?Set(GROUP(concurrency_limit)=9008)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:14] ExecIf("SIP/9008-00000081", "0?Set(CHANNEL(language)=)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:15] GotoIf("SIP/9008-00000081", "1?continue") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (macro-user-callerid,s,29)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:29] Set("SIP/9008-00000081", "CALLERID(number)=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:30] Set("SIP/9008-00000081", "CALLERID(name)=Brad Phillips") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:31] Set("SIP/9008-00000081", "CDR(cnum)=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:32] Set("SIP/9008-00000081", "CDR(cnam)=Brad Phillips") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:33] Set("SIP/9008-00000081", "CHANNEL(language)=en") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:2] Gosub("SIP/9008-00000081", "sub-record-check,s,1(out,5158682015,force)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] GotoIf("SIP/9008-00000081", "0?initialized") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:2] Set("SIP/9008-00000081", "__REC_STATUS=INITIALIZED") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:3] Set("SIP/9008-00000081", "NOW=1471012865") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:4] Set("SIP/9008-00000081", "__DAY=12") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:5] Set("SIP/9008-00000081", "__MONTH=08") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:6] Set("SIP/9008-00000081", "__YEAR=2016") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:7] Set("SIP/9008-00000081", "__TIMESTR=20160812-094105") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:8] Set("SIP/9008-00000081", "__FROMEXTEN=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:9] Set("SIP/9008-00000081", "__MON_FMT=wav") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:10] NoOp("SIP/9008-00000081", "Recordings initialized") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:11] ExecIf("SIP/9008-00000081", "0?Set(ARG3=dontcare)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:12] Set("SIP/9008-00000081", "REC_POLICY_MODE_SAVE=") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:13] ExecIf("SIP/9008-00000081", "0?Set(REC_STATUS=NO)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:14] GotoIf("SIP/9008-00000081", "3?checkaction") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (sub-record-check,s,17)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:17] GotoIf("SIP/9008-00000081", "1?sub-record-check,out,1") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (sub-record-check,out,1)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] NoOp("SIP/9008-00000081", "Outbound Recording Check from 9008 to 5158682015") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:2] Set("SIP/9008-00000081", "RECMODE=force") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/9008-00000081", "0?Goto(routewins)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/9008-00000081", "1?Goto(routewins)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (sub-record-check,out,7)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:7] Gosub("SIP/9008-00000081", "recordcheck,1(force,out,5158682015)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] NoOp("SIP/9008-00000081", "Starting recording check against force") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:2] Goto("SIP/9008-00000081", "force") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (sub-record-check,recordcheck,5)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:5] Set("SIP/9008-00000081", "__REC_POLICY_MODE=FORCE") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:6] GotoIf("SIP/9008-00000081", "1?startrec") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (sub-record-check,recordcheck,16)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:16] NoOp("SIP/9008-00000081", "Starting recording: out, 5158682015") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:17] Set("SIP/9008-00000081", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:18] Set("SIP/9008-00000081", "__CALLFILENAME=out-5158682015-9008-20160812-094105-1471012864.162") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:19] MixMonitor("SIP/9008-00000081", "2016/08/12/out-5158682015-9008-20160812-094105-1471012864.162.wav,ai(LOCAL_MIXMON_ID),") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:20] Set("SIP/9008-00000081", "__MIXMON_ID=0x7fb3e8004700") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:21] Set("SIP/9008-00000081", "__RECORD_ID=SIP/9008-00000081") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:22] Set("SIP/9008-00000081", "__REC_STATUS=RECORDING") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:23] Set("SIP/9008-00000081", "CDR(recordingfile)=out-5158682015-9008-20160812-094105-1471012864.162.wav") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:24] Return("SIP/9008-00000081", "") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:8] Return("SIP/9008-00000081", "") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/9008-00000081", "0 ?Set(CDR(accountcode)=)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:4] Set("SIP/9008-00000081", "MOHCLASS=default") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:5] Set("SIP/9008-00000081", "_NODEST=") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:6] Macro("SIP/9008-00000081", "dialout-trunk,4,5158682015,,off") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] Set("SIP/9008-00000081", "DIAL_TRUNK=4") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:2] GosubIf("SIP/9008-00000081", "0?sub-pincheck,s,1()") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:3] GotoIf("SIP/9008-00000081", "0?disabletrunk,1") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:4] Set("SIP/9008-00000081", "DIAL_NUMBER=5158682015") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:5] Set("SIP/9008-00000081", "DIAL_TRUNK_OPTIONS=Ttr") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:6] Set("SIP/9008-00000081", "OUTBOUND_GROUP=OUT_4") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:7] GotoIf("SIP/9008-00000081", "1?nomax") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (macro-dialout-trunk,s,9)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:9] GotoIf("SIP/9008-00000081", "0?skipoutcid") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:10] Set("SIP/9008-00000081", "DIAL_TRUNK_OPTIONS=Tt") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:11] Macro("SIP/9008-00000081", "outbound-callerid,4") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/9008-00000081", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:2] ExecIf("SIP/9008-00000081", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:3] ExecIf("SIP/9008-00000081", "0?Set(REALCALLERIDNUM=9008)") in new stack
[2016-08-12 09:41:05] VERBOSE[7005][C-0000004f] app_mixmonitor.c: == Begin MixMonitor Recording SIP/9008-00000081
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:4] GotoIf("SIP/9008-00000081", "1?normcid") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (macro-outbound-callerid,s,7)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:7] Set("SIP/9008-00000081", "USEROUTCID=5159789008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:8] Set("SIP/9008-00000081", "EMERGENCYCID=") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:9] Set("SIP/9008-00000081", "TRUNKOUTCID=5159789010") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:10] GotoIf("SIP/9008-00000081", "1?trunkcid") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (macro-outbound-callerid,s,15)
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:15] ExecIf("SIP/9008-00000081", "1?Set(CALLERID(all)=5159789010)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:16] ExecIf("SIP/9008-00000081", "1?Set(CALLERID(all)=5159789008)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:17] ExecIf("SIP/9008-00000081", "0?Set(CALLERID(all)=)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:18] ExecIf("SIP/9008-00000081", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:19] ExecIf("SIP/9008-00000081", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:20] Set("SIP/9008-00000081", "CDR(outbound_cnum)=5159789008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:21] Set("SIP/9008-00000081", "CDR(outbound_cnam)=") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:12] GosubIf("SIP/9008-00000081", "0?sub-flp-4,s,1()") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:13] Set("SIP/9008-00000081", "OUTNUM=5158682015") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:14] Set("SIP/9008-00000081", "custom=SIP/Incoming9009") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:15] ExecIf("SIP/9008-00000081", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:16] ExecIf("SIP/9008-00000081", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:17] Macro("SIP/9008-00000081", "dialout-trunk-predial-hook,") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] MacroExit("SIP/9008-00000081", "") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:18] GotoIf("SIP/9008-00000081", "0?bypass,1") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:19] ExecIf("SIP/9008-00000081", "1?Set(CONNECTEDLINE(num,i)=5158682015)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:20] ExecIf("SIP/9008-00000081", "1?Set(CONNECTEDLINE(name,i)=CID:5159789008)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]o-dialout-trunk:21] ExecIf("SIP/9008-00000081", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)5159789008)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:22] GotoIf("SIP/9008-00000081", "0?customtrunk") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:23] Dial("SIP/9008-00000081", "SIP/Incoming9009/5158682015,300,Tt") in new stack
[2016-08-12 09:41:14] VERBOSE[7004][C-0000004f] netsock2.c: == Using SIP RTP CoS mark 5
[2016-08-12 09:41:14] VERBOSE[7004][C-0000004f] app_dial.c: -- Called SIP/Incoming9009/5158682015
[2016-08-12 09:41:16] VERBOSE[7004][C-0000004f] app_dial.c: -- SIP/Incoming9009-00000082 is making progress passing it to SIP/9008-00000081
[2016-08-12 09:41:20] VERBOSE[2067] chan_sip.c: == Extension Changed auto_hint_9008[from-internal] new state Idle for Notify User 9146
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] app_macro.c: == Spawn extension (macro-dialout-trunk, s, 23) exited non-zero on 'SIP/9008-00000081' in macro 'dialout-trunk'
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: == Spawn extension (from-internal, 5158682015, 6) exited non-zero on 'SIP/9008-00000081'
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] Macro("SIP/9008-00000081", "hangupcall") in new stack
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:1] ExecIf("SIP/9008-00000081", "0?Set(CDR(recordingfile)=out-5158682015-9008-20160812-094105-1471012864.162.wav)") in new stack
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/9008-00000081", "1?theend") in new stack
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: -- Goto (macro-hangupcall,s,4)
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:4] ExecIf("SIP/9008-00000081", "0?Set(CDR(recordingfile)=)") in new stack
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [[email protected]:5] Hangup("SIP/9008-00000081", "") in new stack
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] app_macro.c: == Spawn extension (macro-hangupcall, s, 5) exited non-zero on 'SIP/9008-00000081' in macro 'hangupcall'
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/9008-00000081'
[2016-08-12 09:41:20] VERBOSE[7005][C-0000004f] app_mixmonitor.c: == MixMonitor close filestream (mixed)
[2016-08-12 09:41:21] VERBOSE[7005][C-0000004f] app_mixmonitor.c: == End MixMonitor Recording SIP/9008-00000081

Update: I switched to my warm spare and the delay is gone. So I’m sure it can be narrowed down to my production server.

Check the DNS settings for your production server. This 9-second delay sounds disturbingly close to the “standard 5-second timeout and 10-second failure delay caused by DNS failure” the list was talking about yesterday.

Here’s what I have in my DNS settings (system admin>DNS) on the production server.

127.0.0.1 8.8.8.8 8.8.4.4 192.168.1.1

Surprisingly, my warm spare only has

192.168.1.1

I would have thought those settings would have been copied over. Should I remove the top three entries on my production server?

Personally, I would probably go with 127.0.0.1, 192.168.1.1, and 8.8.8.8.

If your ISP has a recommended DNS, I’d add that before the Google DNS at 8.8.8.8.

Note that if your DNS is the actual problem, it’s probably a problem on your 192.168.1.1 DNS server is broken. I’m going to go out on a limb and suggest that this is also your production phone system?

Thanks, I’ll try your suggestion.

I don’t know a ton about DNS settings. Can you explain what you mean in your last paragraph? My warm spare and production server are both on the same network with the same router. There is no delay when using my warm spare but there is on the production server.

You are using 127.0.0.1 on both servers. That means “me” to the server. if you are not running an actual DNS daemon (look for ‘bind’ in a ‘ps ax’ from the console) on the backup server, the DNS request will fail in five seconds. If the service is working, it will fail or succeed instantly.

Like I said, I assume your production server is on 192.168.1.1. That means your backup is “something else” (like 192.168.1.2.) So, on your production server, you are telling the machine to go to “localhost” (the server itself), then Two different Google servers (8.x.x.x) and then back to 192.168.1.1 (the same server again).

If the DNS is running, but broken (not answering requests, for example) it will take 5 seconds to fail. If your requests to Google fail, they should take about 5 seconds each. After that, the DNS check to 192.168.1.1 (which would be the same as 127.0.0.1 on the primary host) will fail again. That whole sequence is going to take 5 seconds if Google works and 20 seconds if it doesn’t.

As I recall, FreePBX installs a “caching DNS” on the local server that the system can then use. The caching DNS on your backup is probably working fine, but the one on your production server is broken, which is causing the DNS requests from Asterisk to fail.

So,

The DNS settings aren’t the important part - the DNS software is. O’Reilly sells a really good book about “Berkeley Internet Name Daemon (BIND)” that I highly recommend.

Another approach would be to set up the DNS server list on the primary as “127.0.0.1, 192.168.1.2” and the DNS server list on the backup as “127.0.0.1, 192.168.1.1”. This way, the caching DNS running on each can back each other up, and you avoid the problem of asking the same potentially dead daemon the same question over and over.

Now, all of this is based on as little information as possible, and since you haven’t actually provided us with more than “my server hurts”, I could be completely wrong.

Thanks, that makes sense! I’m assuming this is the issue as the delay is about 20 seconds. I’ll have to work on this over the weekend when the phones aren’t needed.

Thanks for the help!