Hello guys,
We are running FREEPBX 2.8.0.4 and having some intermittent issues where we call the main line and get BEEPS then you call maybe twice gain and on the second try the call will go through. Below is an extraction of log file where I think we have identified where thing are a bit different between a call going through and one failing. Hoping someone can assist us it finding the error as I know inconsistent errors are a hard one.
It seems the difference is here - [Oct 24 09:57:59] VERBOSE[30390] logger.c: == Spawn extension (ivr-2, s, 12) exited non-zero on ‘IAX2/416XXXXXXX-12454’
And when it worked this should have happened - [Oct 24 11:20:28] VERBOSE[32688] logger.c: == CDR updated on IAX2/416XXXXXXX-9604
CAll to main line goes to BEEP BEEP BEEP
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [416XXXXXXX@from-pstn:2] ExecIf(“IAX2/416XXXXXXX-12454”, “0 |Set|CALLERID(name)=905XXXXXXX”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [416XXXXXXX@from-pstn:3] Set(“IAX2/416XXXXXXX-12454”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [416XXXXXXX@from-pstn:4] SetCallerPres(“IAX2/416XXXXXXX-12454”, “allowed_not_screened”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [416XXXXXXX@from-pstn:5] Goto(“IAX2/416XXXXXXX-12454”, “ivr-2|s|1”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Goto (ivr-2,s,1)
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [s@ivr-2:1] Set(“IAX2/416XXXXXXX-12454”, “MSG=clarity_menu_2”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [s@ivr-2:2] Set(“IAX2/416XXXXXXX-12454”, “LOOPCOUNT=0”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [s@ivr-2:3] Set(“IAX2/416XXXXXXX-12454”, “__DIR-CONTEXT=”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [s@ivr-2:4] Set(“IAX2/416XXXXXXX-12454”, “_IVR_CONTEXT_ivr-2=”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [s@ivr-2:5] Set(“IAX2/416XXXXXXX-12454”, “_IVR_CONTEXT=ivr-2”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [s@ivr-2:6] GotoIf(“IAX2/416XXXXXXX-12454”, “0?begin”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [s@ivr-2:7] Answer(“IAX2/416XXXXXXX-12454”, “”) in new stack
[Oct 24 09:57:54] VERBOSE[30390] logger.c: – Executing [s@ivr-2:8] Wait(“IAX2/416XXXXXXX-12454”, “1”) in new stack
[Oct 24 09:57:55] VERBOSE[30390] logger.c: – Executing [s@ivr-2:9] Set(“IAX2/416XXXXXXX-12454”, “TIMEOUT(digit)=3”) in new stack
[Oct 24 09:57:55] VERBOSE[30390] logger.c: – Digit timeout set to 3
[Oct 24 09:57:55] VERBOSE[30390] logger.c: – Executing [s@ivr-2:10] Set(“IAX2/416XXXXXXX-12454”, “TIMEOUT(response)=10”) in new stack
[Oct 24 09:57:55] VERBOSE[30390] logger.c: – Response timeout set to 10
[Oct 24 09:57:55] VERBOSE[30390] logger.c: – Executing [s@ivr-2:11] Set(“IAX2/416XXXXXXX-12454”, “__IVR_RETVM=”) in new stack
[Oct 24 09:57:55] VERBOSE[30390] logger.c: – Executing [s@ivr-2:12] ExecIf(“IAX2/416XXXXXXX-12454”, “1|Background|clarity_menu_2”) in new stack
[Oct 24 09:57:55] VERBOSE[30390] logger.c: – <IAX2/416XXXXXXX-12454> Playing ‘clarity_menu_2’ (language ‘en’)
[Oct 24 09:57:59] VERBOSE[30390] logger.c: == Spawn extension (ivr-2, s, 12) exited non-zero on ‘IAX2/416XXXXXXX-12454’
[Oct 24 09:57:59] VERBOSE[30390] logger.c: – Executing [h@ivr-2:1] Hangup(“IAX2/416XXXXXXX-12454”, “”) in new stack
[Oct 24 09:57:59] VERBOSE[30390] logger.c: == Spawn extension (ivr-2, h, 1) exited non-zero on ‘IAX2/416XXXXXXX-12454’
[Oct 24 09:57:59] VERBOSE[30390] logger.c: – Hungup ‘IAX2/416XXXXXXX-12454’
[Oct 24 09:59:16] VERBOSE[2582] logger.c: – Accepting AUTHENTICATED call from 209.217.98.134:
requested format = ulaw,
requested prefs = (ulaw|gsm),
actual format = ulaw,
host prefs = (ulaw|alaw),
priority = mine
[Oct 24 09:59:16] VERBOSE[30394] logger.c: – Executing [416XXXXXXX@from-pstn:1] Set(“IAX2/416XXXXXXX-797”, “__FROM_DID=416XXXXXXX”) in new stack
CAll went through and user pressed option 5 to enter password to route call.
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [416XXXXXXX@from-pstn:2] ExecIf(“IAX2/416XXXXXXX-9604”, “0 |Set|CALLERID(name)=905XXXXXXX”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [416XXXXXXX@from-pstn:3] Set(“IAX2/416XXXXXXX-9604”, “__CALLINGPRES_SV=allowed_not_screened”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [416XXXXXXX@from-pstn:4] SetCallerPres(“IAX2/416XXXXXXX-9604”, “allowed_not_screened”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [416XXXXXXX@from-pstn:5] Goto(“IAX2/416XXXXXXX-9604”, “ivr-2|s|1”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Goto (ivr-2,s,1)
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [s@ivr-2:1] Set(“IAX2/416XXXXXXX-9604”, “MSG=clarity_menu_2”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [s@ivr-2:2] Set(“IAX2/416XXXXXXX-9604”, “LOOPCOUNT=0”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [s@ivr-2:3] Set(“IAX2/416XXXXXXX-9604”, “__DIR-CONTEXT=”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [s@ivr-2:4] Set(“IAX2/416XXXXXXX-9604”, “_IVR_CONTEXT_ivr-2=”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [s@ivr-2:5] Set(“IAX2/416XXXXXXX-9604”, “_IVR_CONTEXT=ivr-2”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [s@ivr-2:6] GotoIf(“IAX2/416XXXXXXX-9604”, “0?begin”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [s@ivr-2:7] Answer(“IAX2/416XXXXXXX-9604”, “”) in new stack
[Oct 24 11:20:25] VERBOSE[32688] logger.c: – Executing [s@ivr-2:8] Wait(“IAX2/416XXXXXXX-9604”, “1”) in new stack
[Oct 24 11:20:26] VERBOSE[32688] logger.c: – Executing [s@ivr-2:9] Set(“IAX2/416XXXXXXX-9604”, “TIMEOUT(digit)=3”) in new stack
[Oct 24 11:20:26] VERBOSE[32688] logger.c: – Digit timeout set to 3
[Oct 24 11:20:26] VERBOSE[32688] logger.c: – Executing [s@ivr-2:10] Set(“IAX2/416XXXXXXX-9604”, “TIMEOUT(response)=10”) in new stack
[Oct 24 11:20:26] VERBOSE[32688] logger.c: – Response timeout set to 10
[Oct 24 11:20:26] VERBOSE[32688] logger.c: – Executing [s@ivr-2:11] Set(“IAX2/416XXXXXXX-9604”, “__IVR_RETVM=”) in new stack
[Oct 24 11:20:26] VERBOSE[32688] logger.c: – Executing [s@ivr-2:12] ExecIf(“IAX2/416XXXXXXX-9604”, “1|Background|clarity_menu_2”) in new stack
[Oct 24 11:20:26] VERBOSE[32688] logger.c: – <IAX2/416XXXXXXX-9604> Playing ‘clarity_menu_2’ (language ‘en’)
[Oct 24 11:20:28] VERBOSE[32688] logger.c: == CDR updated on IAX2/416XXXXXXX-9604
[Oct 24 11:20:28] WARNING[32688] func_db.c: DB_DELETE requires an argument, DB_DELETE(/)
[Oct 24 11:20:28] VERBOSE[32688] logger.c: – Executing [5@ivr-2:1] NoOp(“IAX2/416XXXXXXX-9604”, "Deleting: ") in new stack
[Oct 24 11:20:28] VERBOSE[32688] logger.c: – Executing [5@ivr-2:2] Set(“IAX2/416XXXXXXX-9604”, “__NODEST=”) in new stack
[Oct 24 11:20:28] VERBOSE[32688] logger.c: – Executing [5@ivr-2:3] Goto(“IAX2/416XXXXXXX-9604”, “disa|2|1”) in new stack
[Oct 24 11:20:28] VERBOSE[32688] logger.c: – Goto (disa,2,1)
[Oct 24 11:20:28] VERBOSE[32688] logger.c: – Executing [2@disa:1] Authenticate(“IAX2/416XXXXXXX-9604”, “830556|”) in new stack
[Oct 24 11:20:28] VERBOSE[32688] logger.c: – <IAX2/416XXXXXXX-9604> Playing ‘agent-pass’ (language ‘en’)
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – <IAX2/416XXXXXXX-9604> Playing ‘auth-thankyou’ (language ‘en’)
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Executing [2@disa:2] Set(“IAX2/416XXXXXXX-9604”, “_DISA=“disa|2|newcall””) in new stack
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Executing [2@disa:3] Set(“IAX2/416XXXXXXX-9604”, “_DISACONTEXT=from-internal”) in new stack
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Executing [2@disa:4] Set(“IAX2/416XXXXXXX-9604”, “_KEEPCID=TRUE”) in new stack
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Executing [2@disa:5] Set(“IAX2/416XXXXXXX-9604”, “_HANGUP=”) in new stack
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Executing [2@disa:6] Set(“IAX2/416XXXXXXX-9604”, “TIMEOUT(digit)=5”) in new stack
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Digit timeout set to 5
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Executing [2@disa:7] Set(“IAX2/416XXXXXXX-9604”, “TIMEOUT(response)=10”) in new stack
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Response timeout set to 10
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Executing [2@disa:8] Set(“IAX2/416XXXXXXX-9604”, “CALLERID(all)=“Clarity”<416XXXXXXX>”) in new stack
[Oct 24 11:20:31] VERBOSE[32688] logger.c: – Executing [2@disa:9] DISA(“IAX2/416XXXXXXX-9604”, “no-password|disa-dial”) in new stack
[Oct 24 11:20:31] DEBUG[32688] app_disa.c: Digittimeout: 5000
[Oct 24 11:20:31] DEBUG[32688] app_disa.c: Responsetimeout: 10000
[Oct 24 11:20:31] DEBUG[32688] app_disa.c: Mailbox:
[Oct 24 11:20:31] DEBUG[32688] app_disa.c: Context: disa-dial
[Oct 24 11:20:31] DEBUG[32688] app_disa.c: DISA no-password login success
[Oct 24 11:20:38] VERBOSE[32688] logger.c: == Spawn extension (disa, 2, 9) exited non-zero on ‘IAX2/416XXXXXXX-9604’
[Oct 24 11:20:38] VERBOSE[32688] logger.c: – Hungup ‘IAX2/416XXXXXXX-9604’
[Oct 24 11:21:08] VERBOSE[32691] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Oct 24 11:21:08] VERBOSE[32691] logger.c: Found
[Oct 24 11:21:08] VERBOSE[32691] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Oct 24 11:21:08] VERBOSE[32691] logger.c: Found
[Oct 24 11:21:08] VERBOSE[32691] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Oct 24 11:21:08] VERBOSE[32691] logger.c: Found
[Oct 24 11:21:08] VERBOSE[32691] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Oct 24 11:21:09] VERBOSE[32691] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Oct 24 11:21:10] VERBOSE[32693] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Oct 24 11:21:10] VERBOSE[32693] logger.c: Found
[Oct 24 11:21:10] VERBOSE[32693] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Oct 24 11:21:10] VERBOSE[32693] logger.c: Found
[Oct 24 11:21:10] VERBOSE[32693] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Oct 24 11:21:10] VERBOSE[32693] logger.c: Found
[Oct 24 11:21:10] VERBOSE[32693] logger.c: == Manager ‘admin’ logged on from 127.0.0.1