Slow to connect inbound and outbound calls

Bradbpw · August 12, 2016, 2:52pm

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 [5158682015@from-internal: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 [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("SIP/9008-00000081", "AMPUSER=9008") in new stack
[2016-08-12 09:41:04] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/9008-00000081", "0?report") in new stack
[2016-08-12 09:41:04] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/9008-00000081", "AMPUSER=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/9008-00000081", "0?limit") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/9008-00000081", "AMPUSERCIDNAME=Brad Phillips") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/9008-00000081", "0?report") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/9008-00000081", "AMPUSERCID=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/9008-00000081", "__DIAL_OPTIONS=Ttr") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:12] GotoIf("SIP/9008-00000081", "0?limit") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:29] Set("SIP/9008-00000081", "CALLERID(number)=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:31] Set("SIP/9008-00000081", "CDR(cnum)=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-user-callerid: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 [s@macro-user-callerid:33] Set("SIP/9008-00000081", "CHANNEL(language)=en") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [5158682015@from-internal: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 [s@sub-record-check:1] GotoIf("SIP/9008-00000081", "0?initialized") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:2] Set("SIP/9008-00000081", "__REC_STATUS=INITIALIZED") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:3] Set("SIP/9008-00000081", "NOW=1471012865") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:4] Set("SIP/9008-00000081", "__DAY=12") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:5] Set("SIP/9008-00000081", "__MONTH=08") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:6] Set("SIP/9008-00000081", "__YEAR=2016") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/9008-00000081", "__TIMESTR=20160812-094105") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:8] Set("SIP/9008-00000081", "__FROMEXTEN=9008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:9] Set("SIP/9008-00000081", "__MON_FMT=wav") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check:10] NoOp("SIP/9008-00000081", "Recordings initialized") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [out@sub-record-check: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 [out@sub-record-check:2] Set("SIP/9008-00000081", "RECMODE=force") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [out@sub-record-check:3] ExecIf("SIP/9008-00000081", "0?Goto(routewins)") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [out@sub-record-check: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 [out@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check:20] Set("SIP/9008-00000081", "__MIXMON_ID=0x7fb3e8004700") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [recordcheck@sub-record-check: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 [recordcheck@sub-record-check:22] Set("SIP/9008-00000081", "__REC_STATUS=RECORDING") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [recordcheck@sub-record-check: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 [recordcheck@sub-record-check:24] Return("SIP/9008-00000081", "") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [out@sub-record-check:8] Return("SIP/9008-00000081", "") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [5158682015@from-internal: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 [5158682015@from-internal:4] Set("SIP/9008-00000081", "MOHCLASS=default") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [5158682015@from-internal:5] Set("SIP/9008-00000081", "_NODEST=") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [5158682015@from-internal: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 [s@macro-dialout-trunk:1] Set("SIP/9008-00000081", "DIAL_TRUNK=4") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:3] GotoIf("SIP/9008-00000081", "0?disabletrunk,1") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/9008-00000081", "DIAL_NUMBER=5158682015") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:9] GotoIf("SIP/9008-00000081", "0?skipoutcid") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:11] Macro("SIP/9008-00000081", "outbound-callerid,4") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:7] Set("SIP/9008-00000081", "USEROUTCID=5159789008") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/9008-00000081", "EMERGENCYCID=") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-outbound-callerid:9] Set("SIP/9008-00000081", "TRUNKOUTCID=5159789010") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:21] Set("SIP/9008-00000081", "CDR(outbound_cnam)=") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:13] Set("SIP/9008-00000081", "OUTNUM=5158682015") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/9008-00000081", "custom=SIP/Incoming9009") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/9008-00000081", "") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/9008-00000081", "0?bypass,1") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-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 [s@macro-dialout-trunk:22] GotoIf("SIP/9008-00000081", "0?customtrunk") in new stack
[2016-08-12 09:41:05] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-dialout-trunk: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 [h@from-internal:1] Macro("SIP/9008-00000081", "hangupcall") in new stack
[2016-08-12 09:41:20] VERBOSE[7004][C-0000004f] pbx.c: -- Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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

Bradbpw · August 12, 2016, 3:06pm

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.

cynjut · August 12, 2016, 3:58pm

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.

Bradbpw · August 12, 2016, 4:12pm

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?

cynjut · August 12, 2016, 6:31pm

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?

Bradbpw · August 12, 2016, 6:50pm

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.

cynjut · August 12, 2016, 7:28pm

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.

Bradbpw · August 12, 2016, 7:37pm

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!