V14 IVR digits won't work "did not receive a valid response"

I recently upgraded from v13 to v14. All IVR programming from v13 is good, adding new digits to my IVR presents a problem. I get “did not receive a valid response” when trying any new digits that I add now that I’m using v14. Log files show that I made a selection but the system will not route the call as defined in the IVR settings.

Example: my previous data entered with v13 works (dial 1 for sales, 2 for service, etc.). However, I added a couple of new digits after the upgrade (dial 9 for a directory, *98 for voicemail) and these will not work. Any new digit entries of any kind are failing with v14.

Thoughts?

Can you supply a call trace

Dialing "9" from the IVR, attempting to go to a directory, call fails:

[2017-04-14 14:01:19] WARNING[1583][C-00001c27] Ext. 7777: Friendly Scanner from
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] Set("PJSIP/200-00000048", "__FROM_DID=7777") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:4] Goto("PJSIP/200-00000048", "ext-did,s,1") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (ext-did,s,1)
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000048", "__DIRECTION=INBOUND") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:2] Gosub("PJSIP/200-00000048", "sub-record-check,s,1(in,s,dontcare)") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/200-00000048", "0?initialized") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000048", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] Set("PJSIP/200-00000048", "NOW=1492196479") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:4] Set("PJSIP/200-00000048", "__DAY=14") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:5] Set("PJSIP/200-00000048", "__MONTH=04") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:6] Set("PJSIP/200-00000048", "__YEAR=2017") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:7] Set("PJSIP/200-00000048", "__TIMESTR=20170414-140119") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:8] Set("PJSIP/200-00000048", "__FROMEXTEN=200") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:9] Set("PJSIP/200-00000048", "__MON_FMT=wav") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:10] NoOp("PJSIP/200-00000048", "Recordings initialized") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:11] ExecIf("PJSIP/200-00000048", "0?Set(ARG3=dontcare)") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:12] Set("PJSIP/200-00000048", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:13] ExecIf("PJSIP/200-00000048", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:14] GotoIf("PJSIP/200-00000048", "2?checkaction") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:17] GotoIf("PJSIP/200-00000048", "1?sub-record-check,in,1") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/200-00000048", "Inbound Recording Check to s") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000048", "FROMEXTEN=unknown") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] ExecIf("PJSIP/200-00000048", "3?Set(FROMEXTEN=200)") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:4] Gosub("PJSIP/200-00000048", "recordcheck,1(dontcare,in,s)") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/200-00000048", "Starting recording check against dontcare") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:2] Goto("PJSIP/200-00000048", "dontcare") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] Return("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:5] Return("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] Gosub("PJSIP/200-00000048", "app-blacklist-check,s,1()") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/200-00000048", "0?blacklisted") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000048", "CALLED_BLACKLIST=1") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] Return("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:4] ExecIf("PJSIP/200-00000048", "0?Set(__FROM_DID=s)") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:5] Set("PJSIP/200-00000048", "CDR(did)=7777") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:6] ExecIf("PJSIP/200-00000048", "0 ?Set(CALLERID(name)=200)") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:7] Set("PJSIP/200-00000048", "__MOHCLASS=") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:8] Set("PJSIP/200-00000048", "__REVERSAL_REJECT=FALSE") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:9] GotoIf("PJSIP/200-00000048", "1?post-reverse-charge") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (ext-did,s,11)
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:11] NoOp("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:12] Set("PJSIP/200-00000048", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:13] Set("PJSIP/200-00000048", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:14] Set("PJSIP/200-00000048", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:15] Set("PJSIP/200-00000048", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:16] NoOp("PJSIP/200-00000048", "CallerID Entry Point") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:17] Set("PJSIP/200-00000048", "FAX_DEST=from-did-direct^209^1") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:18] Set("PJSIP/200-00000048", "FAXOPT(faxdetect)=yes") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:19] Answer("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:20] Wait("PJSIP/200-00000048", "4") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:21] Goto("PJSIP/200-00000048", "app-daynight,0,1") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (app-daynight,0,1)
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/200-00000048", "0?ivr-2,s,1:timeconditions,4,1") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (timeconditions,4,1)
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000048", "DB(TC/4/INUSESTATE)=INUSE") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000048", "DB(TC/4/NOT_INUSESTATE)=NOT_INUSE") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] GotoIfTime("PJSIP/200-00000048", "08:00-17:00,mon-fri,*,*,America/Chicago?truestate") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (timeconditions,4,12)
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:12] GotoIf("PJSIP/200-00000048", "0?falsegoto") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:13] ExecIf("PJSIP/200-00000048", "0?Set(DB(TC/4)=)") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:14] Set("PJSIP/200-00000048", "DEVICE_STATE(Custom:TC4)=NOT_INUSE") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:15] ExecIf("PJSIP/200-00000048", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:16] GotoIf("PJSIP/200-00000048", "1?ivr-1,s,1") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (ivr-1,s,1)
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000048", "TIMEOUT_LOOPCOUNT=0") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000048", "INVALID_LOOPCOUNT=0") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] Set("PJSIP/200-00000048", "_IVR_CONTEXT_ivr-1=") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:4] Set("PJSIP/200-00000048", "_IVR_CONTEXT=ivr-1") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:5] Set("PJSIP/200-00000048", "__IVR_RETVM=RETURN") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:6] GotoIf("PJSIP/200-00000048", "1?skip") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (ivr-1,s,9)
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:9] Set("PJSIP/200-00000048", "IVR_MSG=custom/bizopen") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:10] Set("PJSIP/200-00000048", "TIMEOUT(digit)=3") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] func_timeout.c: Digit timeout set to 3.000
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:11] ExecIf("PJSIP/200-00000048", "1?Background(custom/bizopen)") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] file.c: <PJSIP/200-00000048> Playing 'custom/bizopen.slin' (language 'en')
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Invalid extension '9' in context 'ivr-1' on PJSIP/200-00000048
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000048", "INVALID_LOOPCOUNT=1") in new stack
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:2] GotoIf("PJSIP/200-00000048", "0?final") in new stack
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:3] Set("PJSIP/200-00000048", "IVR_MSG=no-valid-responce-pls-try-again&custom/bizopen") in new stack
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:4] Goto("PJSIP/200-00000048", "s,start") in new stack
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx_builtins.c: Goto (ivr-1,s,10)
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:10] Set("PJSIP/200-00000048", "TIMEOUT(digit)=3") in new stack
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] func_timeout.c: Digit timeout set to 3.000
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:11] ExecIf("PJSIP/200-00000048", "1?Background(no-valid-responce-pls-try-again&custom/bizopen)") in new stack
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] file.c: <PJSIP/200-00000048> Playing 'no-valid-responce-pls-try-again.slin' (language 'en')
[2017-04-14 14:01:33] VERBOSE[1583][C-00001c27] pbx.c: Spawn extension (ivr-1, s, 11) exited non-zero on 'PJSIP/200-00000048'
[2017-04-14 14:01:33] VERBOSE[1583][C-00001c27] pbx.c: Executing [[email protected]:1] Hangup("PJSIP/200-00000048", "") in new stack

IVR digit settings:
0 - voicemail 200 busy
1 - extension 200
2 - voicemail 200 busy
6000 - conference bridge
*98 - dial voicemail
9 - directory

The first 4 entries (0, 1, 2, 6000) all work, they were programmed with v13. Any additional digits added now that I’m on v14 (*98, 9, and others that I have tried) do not work. I get the “we have not received a valid response” message. The log posted above shows attempting to dial option 9 for a directory.

Thanks!

This is a log from successful IVR selection “1” to go to a busy voicemail 200 greeting…this was a setting from the v13 programming that does work. Thought I would add this to compare to the failed attempt when pressing “9” as shown above:

[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Macro("PJSIP/200-00000049", "user-callerid,") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000049", "TOUCH_MONITOR=1492196782.109") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "AMPUSER=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] GotoIf("PJSIP/200-00000049", "0?report") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] ExecIf("PJSIP/200-00000049", "1?Set(__REALCALLERIDNUM=200)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:5] Set("PJSIP/200-00000049", "AMPUSER=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:6] GotoIf("PJSIP/200-00000049", "0?limit") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:7] Set("PJSIP/200-00000049", "AMPUSERCIDNAME=Brian") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:8] GotoIf("PJSIP/200-00000049", "0?report") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:9] Set("PJSIP/200-00000049", "AMPUSERCID=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:10] Set("PJSIP/200-00000049", "__DIAL_OPTIONS=Ttr") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:11] Set("PJSIP/200-00000049", "CALLERID(all)="Brian" <200>") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:12] GotoIf("PJSIP/200-00000049", "0?limit") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:13] ExecIf("PJSIP/200-00000049", "0?Set(GROUP(concurrency_limit)=200)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:14] GotoIf("PJSIP/200-00000049", "0?continue") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:15] ExecIf("PJSIP/200-00000049", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:16] Set("PJSIP/200-00000049", "__TTL=64") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:17] GotoIf("PJSIP/200-00000049", "1?continue") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (macro-user-callerid,s,28)
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:28] Set("PJSIP/200-00000049", "CALLERID(number)=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:29] Set("PJSIP/200-00000049", "CALLERID(name)=Brian") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:30] GotoIf("PJSIP/200-00000049", "0?cnum") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:31] Set("PJSIP/200-00000049", "CDR(cnam)=Brian") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:32] Set("PJSIP/200-00000049", "CDR(cnum)=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:33] Set("PJSIP/200-00000049", "CHANNEL(language)=en") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Goto("PJSIP/200-00000049", "from-pstn,7777,1") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (from-pstn,7777,1)
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/200-00000049", "Catch-All DID Match - Found 7777 - You probably want a DID for this.") in new stack
[2017-04-14 14:06:22] WARNING[1779][C-00001c34] chan_sip.c: This function can only be used on SIP channels.
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Log("PJSIP/200-00000049", "WARNING,Friendly Scanner from ") in new stack
[2017-04-14 14:06:22] WARNING[1779][C-00001c34] Ext. 7777: Friendly Scanner from
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] Set("PJSIP/200-00000049", "__FROM_DID=7777") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] Goto("PJSIP/200-00000049", "ext-did,s,1") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (ext-did,s,1)
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000049", "__DIRECTION=INBOUND") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Gosub("PJSIP/200-00000049", "sub-record-check,s,1(in,s,dontcare)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/200-00000049", "0?initialized") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] Set("PJSIP/200-00000049", "NOW=1492196782") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] Set("PJSIP/200-00000049", "__DAY=14") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:5] Set("PJSIP/200-00000049", "__MONTH=04") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:6] Set("PJSIP/200-00000049", "__YEAR=2017") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:7] Set("PJSIP/200-00000049", "__TIMESTR=20170414-140622") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:8] Set("PJSIP/200-00000049", "__FROMEXTEN=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:9] Set("PJSIP/200-00000049", "__MON_FMT=wav") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:10] NoOp("PJSIP/200-00000049", "Recordings initialized") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:11] ExecIf("PJSIP/200-00000049", "0?Set(ARG3=dontcare)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:12] Set("PJSIP/200-00000049", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:13] ExecIf("PJSIP/200-00000049", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:14] GotoIf("PJSIP/200-00000049", "2?checkaction") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:17] GotoIf("PJSIP/200-00000049", "1?sub-record-check,in,1") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/200-00000049", "Inbound Recording Check to s") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "FROMEXTEN=unknown") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] ExecIf("PJSIP/200-00000049", "3?Set(FROMEXTEN=200)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] Gosub("PJSIP/200-00000049", "recordcheck,1(dontcare,in,s)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/200-00000049", "Starting recording check against dontcare") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Goto("PJSIP/200-00000049", "dontcare") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] Return("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:5] Return("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] Gosub("PJSIP/200-00000049", "app-blacklist-check,s,1()") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/200-00000049", "0?blacklisted") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "CALLED_BLACKLIST=1") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] Return("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] ExecIf("PJSIP/200-00000049", "0?Set(__FROM_DID=s)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:5] Set("PJSIP/200-00000049", "CDR(did)=7777") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:6] ExecIf("PJSIP/200-00000049", "0 ?Set(CALLERID(name)=200)") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:7] Set("PJSIP/200-00000049", "__MOHCLASS=") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:8] Set("PJSIP/200-00000049", "__REVERSAL_REJECT=FALSE") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:9] GotoIf("PJSIP/200-00000049", "1?post-reverse-charge") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (ext-did,s,11)
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:11] NoOp("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:12] Set("PJSIP/200-00000049", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:13] Set("PJSIP/200-00000049", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:14] Set("PJSIP/200-00000049", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:15] Set("PJSIP/200-00000049", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:16] NoOp("PJSIP/200-00000049", "CallerID Entry Point") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:17] Set("PJSIP/200-00000049", "FAX_DEST=from-did-direct^209^1") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:18] Set("PJSIP/200-00000049", "FAXOPT(faxdetect)=yes") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:19] Answer("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] NOTICE[21195] res_pjsip_exten_state.c: Extension state subscription failed: Extension 202 does not exist in context 'from-internal' or has no associated hint
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:20] Wait("PJSIP/200-00000049", "4") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:21] Goto("PJSIP/200-00000049", "app-daynight,0,1") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (app-daynight,0,1)
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/200-00000049", "0?ivr-2,s,1:timeconditions,4,1") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (timeconditions,4,1)
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000049", "DB(TC/4/INUSESTATE)=INUSE") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "DB(TC/4/NOT_INUSESTATE)=NOT_INUSE") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] GotoIfTime("PJSIP/200-00000049", "08:00-17:00,mon-fri,*,*,America/Chicago?truestate") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (timeconditions,4,12)
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:12] GotoIf("PJSIP/200-00000049", "0?falsegoto") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:13] ExecIf("PJSIP/200-00000049", "0?Set(DB(TC/4)=)") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:14] Set("PJSIP/200-00000049", "DEVICE_STATE(Custom:TC4)=NOT_INUSE") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:15] ExecIf("PJSIP/200-00000049", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:16] GotoIf("PJSIP/200-00000049", "1?ivr-1,s,1") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (ivr-1,s,1)
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000049", "TIMEOUT_LOOPCOUNT=0") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "INVALID_LOOPCOUNT=0") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] Set("PJSIP/200-00000049", "_IVR_CONTEXT_ivr-1=") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] Set("PJSIP/200-00000049", "_IVR_CONTEXT=ivr-1") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:5] Set("PJSIP/200-00000049", "__IVR_RETVM=RETURN") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:6] GotoIf("PJSIP/200-00000049", "1?skip") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (ivr-1,s,9)
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:9] Set("PJSIP/200-00000049", "IVR_MSG=custom/bizopen") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:10] Set("PJSIP/200-00000049", "TIMEOUT(digit)=3") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] func_timeout.c: Digit timeout set to 3.000
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:11] ExecIf("PJSIP/200-00000049", "1?Background(custom/bizopen)") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] file.c: <PJSIP/200-00000049> Playing 'custom/bizopen.slin' (language 'en')
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Goto("PJSIP/200-00000049", "ext-local,vmb200,1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (ext-local,vmb200,1)
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Macro("PJSIP/200-00000049", "vm,200,BUSY,RETURN") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Macro("PJSIP/200-00000049", "user-callerid,SKIPTTL") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000049", "TOUCH_MONITOR=1492196782.109") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "AMPUSER=200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] GotoIf("PJSIP/200-00000049", "5?report") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (macro-user-callerid,s,14)
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:14] GotoIf("PJSIP/200-00000049", "1?continue") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (macro-user-callerid,s,28)
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:28] Set("PJSIP/200-00000049", "CALLERID(number)=200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:29] Set("PJSIP/200-00000049", "CALLERID(name)=Brian") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:30] GotoIf("PJSIP/200-00000049", "0?cnum") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:31] Set("PJSIP/200-00000049", "CDR(cnam)=Brian") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:32] Set("PJSIP/200-00000049", "CDR(cnum)=200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:33] Set("PJSIP/200-00000049", "CHANNEL(language)=en") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "VMGAIN=g(12)") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] Macro("PJSIP/200-00000049", "blkvm-check,") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000049", "GOSUB_RETVAL=") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] ExecIf("PJSIP/200-00000049", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] MacroExit("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] GotoIf("PJSIP/200-00000049", "1?vmx,1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (macro-vm,vmx,1)
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000049", "MEXTEN=200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] Set("PJSIP/200-00000049", "MMODE=BUSY") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] Set("PJSIP/200-00000049", "RETVM=RETURN") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] Set("PJSIP/200-00000049", "MODE=busy") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:5] Macro("PJSIP/200-00000049", "get-vmcontext,200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Set("PJSIP/200-00000049", "VMCONTEXT=default") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:2] GotoIf("PJSIP/200-00000049", "0?200:300") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:300] NoOp("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:6] Set("PJSIP/200-00000049", "MODE=busy") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:7] NoOp("PJSIP/200-00000049", "MODE IS: busy") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:8] GotoIf("PJSIP/200-00000049", "0?chknomsg") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:9] Set("PJSIP/200-00000049", "VM_OPTS=s") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:10] GotoIf("PJSIP/200-00000049", "0?s-BUSY,1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:11] GotoIf("PJSIP/200-00000049", "1?notdirect") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (macro-vm,vmx,13)
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:13] NoOp("PJSIP/200-00000049", "Checking if ext 200 is enabled: enabled") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:14] GotoIf("PJSIP/200-00000049", "0?s-BUSY,1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:15] GotoIf("PJSIP/200-00000049", "0?tmpgreet") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:16] GotoIf("PJSIP/200-00000049", "0?nofile") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:17] Set("PJSIP/200-00000049", "VMX_TIMEOUT=2") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:18] Set("PJSIP/200-00000049", "VMX_REPEAT=1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:19] Set("PJSIP/200-00000049", "VMX_LOOPS=1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:20] Set("PJSIP/200-00000049", "LOOPCOUNT=0") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:21] Set("PJSIP/200-00000049", "VMX_REPEAT=1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:22] Set("PJSIP/200-00000049", "VMX_TIMEOUT=2") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:23] Set("PJSIP/200-00000049", "VMX_LOOPS=1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:24] Answer("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:25] Read("PJSIP/200-00000049", "ACTION,/var/spool/asterisk/voicemail/default/200/busy,1,skip,1,2") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] app_read.c: Accepting a maximum of 1 digits.
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] file.c: <PJSIP/200-00000049> Playing '/var/spool/asterisk/voicemail/default/200/busy.slin' (language 'en')
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] app_read.c: User disconnected
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] Macro("PJSIP/200-00000049", "hangupcall,") in new stack
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/200-00000049", "1?theend") in new stack
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:3] ExecIf("PJSIP/200-00000049", "0?Set(CDR(recordingfile)=)") in new stack
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] pbx.c: Executing [[email protected]:4] Hangup("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/200-00000049' in macro 'hangupcall'
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/200-00000049'

So I just tested on 14 and all is working call log below:

-- Executing [[email protected]:1] Set("SIP/fpbx-1-xxxx-00000001", "__DIRECTION=INBOUND") in new stack
-- Executing [[email protected]:2] Gosub("SIP/fpbx-1-xxxx-00000001", "sub-record-check,s,1(in,334XXXXXXX,dontcare)") in new stack
-- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-xxxx-00000001", "0?initialized") in new stack
-- Executing [[email protected]:2] Set("SIP/fpbx-1-xxxx-00000001", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [[email protected]:3] Set("SIP/fpbx-1-xxxx-00000001", "NOW=1492532137") in new stack
-- Executing [[email protected]:4] Set("SIP/fpbx-1-xxxx-00000001", "__DAY=18") in new stack
-- Executing [[email protected]:5] Set("SIP/fpbx-1-xxxx-00000001", "__MONTH=04") in new stack
-- Executing [[email protected]:6] Set("SIP/fpbx-1-xxxx-00000001", "__YEAR=2017") in new stack
-- Executing [[email protected]:7] Set("SIP/fpbx-1-xxxx-00000001", "__TIMESTR=20170418-161537") in new stack
-- Executing [[email protected]:8] Set("SIP/fpbx-1-xxxx-00000001", "__FROMEXTEN=unknown") in new stack
-- Executing [[email protected]:9] Set("SIP/fpbx-1-xxxx-00000001", "__MON_FMT=wav") in new stack
-- Executing [[email protected]:10] NoOp("SIP/fpbx-1-xxxx-00000001", "Recordings initialized") in new stack
-- Executing [[email protected]:11] ExecIf("SIP/fpbx-1-xxxx-00000001", "0?Set(ARG3=dontcare)") in new stack
-- Executing [[email protected]:12] Set("SIP/fpbx-1-xxxx-00000001", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [[email protected]:13] ExecIf("SIP/fpbx-1-xxxx-00000001", "0?Set(REC_STATUS=NO)") in new stack
-- Executing [[email protected]:14] GotoIf("SIP/fpbx-1-xxxx-00000001", "2?checkaction") in new stack
-- Goto (sub-record-check,s,17)
-- Executing [[email protected]:17] GotoIf("SIP/fpbx-1-xxxx-00000001", "1?sub-record-check,in,1") in new stack
-- Goto (sub-record-check,in,1)
-- Executing [[email protected]:1] NoOp("SIP/fpbx-1-xxxx-00000001", "Inbound Recording Check to 334XXXXXXX") in new stack
-- Executing [[email protected]:2] Set("SIP/fpbx-1-xxxx-00000001", "FROMEXTEN=unknown") in new stack
-- Executing [[email protected]:3] ExecIf("SIP/fpbx-1-xxxx-00000001", "11?Set(FROMEXTEN=1920XXXXXXX)") in new stack
-- Executing [[email protected]:4] Gosub("SIP/fpbx-1-xxxx-00000001", "recordcheck,1(dontcare,in,334XXXXXXX)") in new stack
-- Executing [[email protected]:1] NoOp("SIP/fpbx-1-xxxx-00000001", "Starting recording check against dontcare") in new stack
-- Executing [[email protected]:2] Goto("SIP/fpbx-1-xxxx-00000001", "dontcare") in new stack
-- Goto (sub-record-check,recordcheck,3)
-- Executing [[email protected]:3] Return("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [[email protected]:5] Return("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [[email protected]:3] Gosub("SIP/fpbx-1-xxxx-00000001", "app-blacklist-check,s,1()") in new stack
-- Executing [[email protected]:1] GotoIf("SIP/fpbx-1-xxxx-00000001", "0?blacklisted") in new stack
-- Executing [[email protected]:2] Set("SIP/fpbx-1-xxxx-00000001", "CALLED_BLACKLIST=1") in new stack
-- Executing [[email protected]:3] Return("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [[email protected]:4] Set("SIP/fpbx-1-xxxx-00000001", "__FROM_DID=334XXXXXXX") in new stack
-- Executing [[email protected]:5] Set("SIP/fpbx-1-xxxx-00000001", "CDR(did)=334XXXXXXX") in new stack
-- Executing [[email protected]:6] ExecIf("SIP/fpbx-1-xxxx-00000001", "0 ?Set(CALLERID(name)=1920XXXXXXX)") in new stack
-- Executing [[email protected]:7] Set("SIP/fpbx-1-xxxx-00000001", "__MOHCLASS=") in new stack
-- Executing [[email protected]:8] Set("SIP/fpbx-1-xxxx-00000001", "__REVERSAL_REJECT=FALSE") in new stack
-- Executing [[email protected]:9] GotoIf("SIP/fpbx-1-xxxx-00000001", "1?post-reverse-charge") in new stack
-- Goto (from-pstn,334XXXXXXX,11)
-- Executing [[email protected]:11] NoOp("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [[email protected]:12] Set("SIP/fpbx-1-xxxx-00000001", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
-- Executing [[email protected]:13] Set("SIP/fpbx-1-xxxx-00000001", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
-- Executing [[email protected]:14] Set("SIP/fpbx-1-xxxx-00000001", "CALLERID(name-pres)=allowed_not_screened") in new stack
-- Executing [[email protected]:15] Set("SIP/fpbx-1-xxxx-00000001", "CALLERID(num-pres)=allowed_not_screened") in new stack
-- Executing [[email protected]:16] NoOp("SIP/fpbx-1-xxxx-00000001", "CallerID Entry Point") in new stack
-- Executing [[email protected]:17] Set("SIP/fpbx-1-xxxx-00000001", "__CRM_DIRECTION=INBOUND") in new stack
-- Executing [[email protected]:18] Set("SIP/fpbx-1-xxxx-00000001", "__CRM_SOURCE=1920XXXXXXX") in new stack
-- Executing [[email protected]:19] Set("SIP/fpbx-1-xxxx-00000001", "__CRM_LINKEDID=1492532137.1") in new stack
-- Executing [[email protected]:20] ExecIf("SIP/fpbx-1-xxxx-00000001", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
-- Executing [[email protected]:21] Goto("SIP/fpbx-1-xxxx-00000001", "ivr-1,s,1") in new stack
-- Goto (ivr-1,s,1)
-- Executing [[email protected]:1] Set("SIP/fpbx-1-xxxx-00000001", "TIMEOUT_LOOPCOUNT=0") in new stack
-- Executing [[email protected]:2] Set("SIP/fpbx-1-xxxx-00000001", "INVALID_LOOPCOUNT=0") in new stack
-- Executing [[email protected]:3] Set("SIP/fpbx-1-xxxx-00000001", "_IVR_CONTEXT_ivr-1=") in new stack
-- Executing [[email protected]:4] Set("SIP/fpbx-1-xxxx-00000001", "_IVR_CONTEXT=ivr-1") in new stack
-- Executing [[email protected]:5] Set("SIP/fpbx-1-xxxx-00000001", "__IVR_RETVM=") in new stack
-- Executing [[email protected]:6] GotoIf("SIP/fpbx-1-xxxx-00000001", "0?skip") in new stack
-- Executing [[email protected]:7] Answer("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [[email protected]:8] Wait("SIP/fpbx-1-xxxx-00000001", "1") in new stack
   > 0x7fc0d40113e0 -- Probation passed - setting RTP source address to 67.231.13.13:57326
-- Executing [[email protected]:9] Set("SIP/fpbx-1-xxxx-00000001", "IVR_MSG=custom/IVR") in new stack
-- Executing [[email protected]:10] Set("SIP/fpbx-1-xxxx-00000001", "TIMEOUT(digit)=3") in new stack
-- Digit timeout set to 3.000
-- Executing [[email protected]:11] ExecIf("SIP/fpbx-1-xxxx-00000001", "1?Background(custom/IVR)") in new stack
-- <SIP/fpbx-1-xxxx-00000001> Playing 'custom/IVR.slin' (language 'en')
-- Executing [[email protected]:1] Goto("SIP/fpbx-1-xxxx-00000001", "directory,1,1") in new stack
-- Goto (directory,1,1)
-- Executing [[email protected]:1] Answer("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [[email protected]:2] Wait("SIP/fpbx-1-xxxx-00000001", "1") in new stack
-- Executing [[email protected]:3] AGI("SIP/fpbx-1-xxxx-00000001", "directory.agi,dir=1,retivr=false") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/directory.agi
-- <SIP/fpbx-1-xxxx-00000001> Playing 'cdir-welcome.slin' (language 'en')
-- AGI Script Executing Application: (background) Options: (cdir-please-enter-first-three)
-- <SIP/fpbx-1-xxxx-00000001> Playing 'cdir-please-enter-first-three.slin' (language 'en')
-- <SIP/fpbx-1-xxxx-00000001> Playing 'silence/1.ulaw' (escape_digits=1234567890#) (sample_offset 0) (language 'en')
-- <SIP/fpbx-1-xxxx-00000001> Playing 'cdir-there-are.slin' (escape_digits=1234567890#) (sample_offset 0) (language 'en')
-- <SIP/fpbx-1-xxxx-00000001> Playing 'digits/2.ulaw' (language 'en')
-- <SIP/fpbx-1-xxxx-00000001> Playing 'cdir-matching-entries-or-pound.slin' (escape_digits=1234567890#) (sample_offset 0) (language 'en')
-- <SIP/fpbx-1-xxxx-00000001> Playing 'for.ulaw' (escape_digits=12) (sample_offset 0) (language 'en')

Thanks for taking the time to check, glad yours is working…any suggestions on what I need to check or change?