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

biztech · April 18, 2017, 3:38am

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?

jfinstrom · April 18, 2017, 4:47am

Can you supply a call trace

biztech · April 18, 2017, 3:41pm

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 [7777@from-pstn:3] Set("PJSIP/200-00000048", "__FROM_DID=7777") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [7777@from-pstn: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 [s@ext-did:1] Set("PJSIP/200-00000048", "__DIRECTION=INBOUND") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did: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 [s@sub-record-check:1] GotoIf("PJSIP/200-00000048", "0?initialized") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/200-00000048", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/200-00000048", "NOW=1492196479") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/200-00000048", "__DAY=14") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/200-00000048", "__MONTH=04") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/200-00000048", "__YEAR=2017") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/200-00000048", "__TIMESTR=20170414-140119") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/200-00000048", "__FROMEXTEN=200") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/200-00000048", "__MON_FMT=wav") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/200-00000048", "Recordings initialized") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [in@sub-record-check: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 [in@sub-record-check:2] Set("PJSIP/200-00000048", "FROMEXTEN=unknown") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [in@sub-record-check: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 [in@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check:3] Return("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [in@sub-record-check:5] Return("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did: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 [s@app-blacklist-check:1] GotoIf("PJSIP/200-00000048", "0?blacklisted") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@app-blacklist-check:2] Set("PJSIP/200-00000048", "CALLED_BLACKLIST=1") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@app-blacklist-check:3] Return("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did: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 [s@ext-did:5] Set("PJSIP/200-00000048", "CDR(did)=7777") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did: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 [s@ext-did:7] Set("PJSIP/200-00000048", "__MOHCLASS=") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did:8] Set("PJSIP/200-00000048", "__REVERSAL_REJECT=FALSE") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did: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 [s@ext-did:11] NoOp("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did: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 [s@ext-did: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 [s@ext-did: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 [s@ext-did: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 [s@ext-did:16] NoOp("PJSIP/200-00000048", "CallerID Entry Point") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did: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 [s@ext-did:18] Set("PJSIP/200-00000048", "FAXOPT(faxdetect)=yes") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did:19] Answer("PJSIP/200-00000048", "") in new stack
[2017-04-14 14:01:19] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did:20] Wait("PJSIP/200-00000048", "4") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ext-did: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 [0@app-daynight: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 [4@timeconditions: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 [4@timeconditions: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 [4@timeconditions: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 [4@timeconditions:12] GotoIf("PJSIP/200-00000048", "0?falsegoto") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [4@timeconditions: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 [4@timeconditions: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 [4@timeconditions: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 [4@timeconditions: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 [s@ivr-1:1] Set("PJSIP/200-00000048", "TIMEOUT_LOOPCOUNT=0") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ivr-1:2] Set("PJSIP/200-00000048", "INVALID_LOOPCOUNT=0") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ivr-1: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 [s@ivr-1: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 [s@ivr-1:5] Set("PJSIP/200-00000048", "__IVR_RETVM=RETURN") in new stack
[2017-04-14 14:01:23] VERBOSE[1583][C-00001c27] pbx.c: Executing [s@ivr-1: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 [s@ivr-1: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 [s@ivr-1: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 [s@ivr-1: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 [i@ivr-1:1] Set("PJSIP/200-00000048", "INVALID_LOOPCOUNT=1") in new stack
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Executing [i@ivr-1:2] GotoIf("PJSIP/200-00000048", "0?final") in new stack
[2017-04-14 14:01:29] VERBOSE[1583][C-00001c27] pbx.c: Executing [i@ivr-1: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 [i@ivr-1: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 [s@ivr-1: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 [s@ivr-1: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 [h@ivr-1:1] Hangup("PJSIP/200-00000048", "") in new stack

biztech · April 18, 2017, 3:47pm

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!

biztech · April 18, 2017, 4:00pm

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 [7777@from-internal:1] Macro("PJSIP/200-00000049", "user-callerid,") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("PJSIP/200-00000049", "AMPUSER=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/200-00000049", "0?report") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("PJSIP/200-00000049", "AMPUSER=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("PJSIP/200-00000049", "0?limit") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/200-00000049", "AMPUSERCIDNAME=Brian") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("PJSIP/200-00000049", "0?report") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:9] Set("PJSIP/200-00000049", "AMPUSERCID=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/200-00000049", "__DIAL_OPTIONS=Ttr") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:12] GotoIf("PJSIP/200-00000049", "0?limit") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:14] GotoIf("PJSIP/200-00000049", "0?continue") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:16] Set("PJSIP/200-00000049", "__TTL=64") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:28] Set("PJSIP/200-00000049", "CALLERID(number)=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:29] Set("PJSIP/200-00000049", "CALLERID(name)=Brian") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:30] GotoIf("PJSIP/200-00000049", "0?cnum") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:31] Set("PJSIP/200-00000049", "CDR(cnam)=Brian") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:32] Set("PJSIP/200-00000049", "CDR(cnum)=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:33] Set("PJSIP/200-00000049", "CHANNEL(language)=en") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [7777@from-internal: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 [7777@from-pstn: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 [7777@from-pstn: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 [7777@from-pstn:3] Set("PJSIP/200-00000049", "__FROM_DID=7777") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [7777@from-pstn: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 [s@ext-did:1] Set("PJSIP/200-00000049", "__DIRECTION=INBOUND") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [s@sub-record-check:1] GotoIf("PJSIP/200-00000049", "0?initialized") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/200-00000049", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/200-00000049", "NOW=1492196782") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/200-00000049", "__DAY=14") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/200-00000049", "__MONTH=04") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/200-00000049", "__YEAR=2017") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/200-00000049", "__TIMESTR=20170414-140622") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/200-00000049", "__FROMEXTEN=200") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/200-00000049", "__MON_FMT=wav") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/200-00000049", "Recordings initialized") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [in@sub-record-check: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 [in@sub-record-check:2] Set("PJSIP/200-00000049", "FROMEXTEN=unknown") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [in@sub-record-check: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 [in@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check:3] Return("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [in@sub-record-check:5] Return("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [s@app-blacklist-check:1] GotoIf("PJSIP/200-00000049", "0?blacklisted") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@app-blacklist-check:2] Set("PJSIP/200-00000049", "CALLED_BLACKLIST=1") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@app-blacklist-check:3] Return("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [s@ext-did:5] Set("PJSIP/200-00000049", "CDR(did)=7777") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [s@ext-did:7] Set("PJSIP/200-00000049", "__MOHCLASS=") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did:8] Set("PJSIP/200-00000049", "__REVERSAL_REJECT=FALSE") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [s@ext-did:11] NoOp("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [s@ext-did: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 [s@ext-did: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 [s@ext-did: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 [s@ext-did:16] NoOp("PJSIP/200-00000049", "CallerID Entry Point") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [s@ext-did:18] Set("PJSIP/200-00000049", "FAXOPT(faxdetect)=yes") in new stack
[2017-04-14 14:06:22] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [s@ext-did:20] Wait("PJSIP/200-00000049", "4") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ext-did: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 [0@app-daynight: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 [4@timeconditions: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 [4@timeconditions: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 [4@timeconditions: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 [4@timeconditions:12] GotoIf("PJSIP/200-00000049", "0?falsegoto") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [4@timeconditions: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 [4@timeconditions: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 [4@timeconditions: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 [4@timeconditions: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 [s@ivr-1:1] Set("PJSIP/200-00000049", "TIMEOUT_LOOPCOUNT=0") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ivr-1:2] Set("PJSIP/200-00000049", "INVALID_LOOPCOUNT=0") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ivr-1: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 [s@ivr-1: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 [s@ivr-1:5] Set("PJSIP/200-00000049", "__IVR_RETVM=RETURN") in new stack
[2017-04-14 14:06:26] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@ivr-1: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 [s@ivr-1: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 [s@ivr-1: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 [s@ivr-1: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 [2@ivr-1: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 [vmb200@ext-local: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 [s@macro-vm:1] Macro("PJSIP/200-00000049", "user-callerid,SKIPTTL") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("PJSIP/200-00000049", "AMPUSER=200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:28] Set("PJSIP/200-00000049", "CALLERID(number)=200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:29] Set("PJSIP/200-00000049", "CALLERID(name)=Brian") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:30] GotoIf("PJSIP/200-00000049", "0?cnum") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:31] Set("PJSIP/200-00000049", "CDR(cnam)=Brian") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:32] Set("PJSIP/200-00000049", "CDR(cnum)=200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-user-callerid:33] Set("PJSIP/200-00000049", "CHANNEL(language)=en") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-vm:2] Set("PJSIP/200-00000049", "VMGAIN=g(12)") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-vm:3] Macro("PJSIP/200-00000049", "blkvm-check,") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-blkvm-check:1] Set("PJSIP/200-00000049", "GOSUB_RETVAL=") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-blkvm-check: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 [s@macro-blkvm-check:3] MacroExit("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-vm: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 [vmx@macro-vm:1] Set("PJSIP/200-00000049", "MEXTEN=200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:2] Set("PJSIP/200-00000049", "MMODE=BUSY") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:3] Set("PJSIP/200-00000049", "RETVM=RETURN") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:4] Set("PJSIP/200-00000049", "MODE=busy") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:5] Macro("PJSIP/200-00000049", "get-vmcontext,200") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-get-vmcontext:1] Set("PJSIP/200-00000049", "VMCONTEXT=default") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-get-vmcontext: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 [s@macro-get-vmcontext:300] NoOp("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:6] Set("PJSIP/200-00000049", "MODE=busy") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:7] NoOp("PJSIP/200-00000049", "MODE IS: busy") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:8] GotoIf("PJSIP/200-00000049", "0?chknomsg") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:9] Set("PJSIP/200-00000049", "VM_OPTS=s") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm: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 [vmx@macro-vm:15] GotoIf("PJSIP/200-00000049", "0?tmpgreet") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:16] GotoIf("PJSIP/200-00000049", "0?nofile") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:17] Set("PJSIP/200-00000049", "VMX_TIMEOUT=2") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:18] Set("PJSIP/200-00000049", "VMX_REPEAT=1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:19] Set("PJSIP/200-00000049", "VMX_LOOPS=1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:20] Set("PJSIP/200-00000049", "LOOPCOUNT=0") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:21] Set("PJSIP/200-00000049", "VMX_REPEAT=1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:22] Set("PJSIP/200-00000049", "VMX_TIMEOUT=2") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:23] Set("PJSIP/200-00000049", "VMX_LOOPS=1") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm:24] Answer("PJSIP/200-00000049", "") in new stack
[2017-04-14 14:06:33] VERBOSE[1779][C-00001c34] pbx.c: Executing [vmx@macro-vm: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 [h@ext-local:1] Macro("PJSIP/200-00000049", "hangupcall,") in new stack
[2017-04-14 14:06:38] VERBOSE[1779][C-00001c34] pbx.c: Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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'

jfinstrom · April 18, 2017, 4:19pm

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

-- Executing [334XXXXXXX@from-pstn:1] Set("SIP/fpbx-1-xxxx-00000001", "__DIRECTION=INBOUND") in new stack
-- Executing [334XXXXXXX@from-pstn:2] Gosub("SIP/fpbx-1-xxxx-00000001", "sub-record-check,s,1(in,334XXXXXXX,dontcare)") in new stack
-- Executing [s@sub-record-check:1] GotoIf("SIP/fpbx-1-xxxx-00000001", "0?initialized") in new stack
-- Executing [s@sub-record-check:2] Set("SIP/fpbx-1-xxxx-00000001", "__REC_STATUS=INITIALIZED") in new stack
-- Executing [s@sub-record-check:3] Set("SIP/fpbx-1-xxxx-00000001", "NOW=1492532137") in new stack
-- Executing [s@sub-record-check:4] Set("SIP/fpbx-1-xxxx-00000001", "__DAY=18") in new stack
-- Executing [s@sub-record-check:5] Set("SIP/fpbx-1-xxxx-00000001", "__MONTH=04") in new stack
-- Executing [s@sub-record-check:6] Set("SIP/fpbx-1-xxxx-00000001", "__YEAR=2017") in new stack
-- Executing [s@sub-record-check:7] Set("SIP/fpbx-1-xxxx-00000001", "__TIMESTR=20170418-161537") in new stack
-- Executing [s@sub-record-check:8] Set("SIP/fpbx-1-xxxx-00000001", "__FROMEXTEN=unknown") in new stack
-- Executing [s@sub-record-check:9] Set("SIP/fpbx-1-xxxx-00000001", "__MON_FMT=wav") in new stack
-- Executing [s@sub-record-check:10] NoOp("SIP/fpbx-1-xxxx-00000001", "Recordings initialized") in new stack
-- Executing [s@sub-record-check:11] ExecIf("SIP/fpbx-1-xxxx-00000001", "0?Set(ARG3=dontcare)") in new stack
-- Executing [s@sub-record-check:12] Set("SIP/fpbx-1-xxxx-00000001", "REC_POLICY_MODE_SAVE=") in new stack
-- Executing [s@sub-record-check:13] ExecIf("SIP/fpbx-1-xxxx-00000001", "0?Set(REC_STATUS=NO)") in new stack
-- Executing [s@sub-record-check:14] GotoIf("SIP/fpbx-1-xxxx-00000001", "2?checkaction") in new stack
-- Goto (sub-record-check,s,17)
-- Executing [s@sub-record-check:17] GotoIf("SIP/fpbx-1-xxxx-00000001", "1?sub-record-check,in,1") in new stack
-- Goto (sub-record-check,in,1)
-- Executing [in@sub-record-check:1] NoOp("SIP/fpbx-1-xxxx-00000001", "Inbound Recording Check to 334XXXXXXX") in new stack
-- Executing [in@sub-record-check:2] Set("SIP/fpbx-1-xxxx-00000001", "FROMEXTEN=unknown") in new stack
-- Executing [in@sub-record-check:3] ExecIf("SIP/fpbx-1-xxxx-00000001", "11?Set(FROMEXTEN=1920XXXXXXX)") in new stack
-- Executing [in@sub-record-check:4] Gosub("SIP/fpbx-1-xxxx-00000001", "recordcheck,1(dontcare,in,334XXXXXXX)") in new stack
-- Executing [recordcheck@sub-record-check:1] NoOp("SIP/fpbx-1-xxxx-00000001", "Starting recording check against dontcare") in new stack
-- Executing [recordcheck@sub-record-check:2] Goto("SIP/fpbx-1-xxxx-00000001", "dontcare") in new stack
-- Goto (sub-record-check,recordcheck,3)
-- Executing [recordcheck@sub-record-check:3] Return("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [in@sub-record-check:5] Return("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [334XXXXXXX@from-pstn:3] Gosub("SIP/fpbx-1-xxxx-00000001", "app-blacklist-check,s,1()") in new stack
-- Executing [s@app-blacklist-check:1] GotoIf("SIP/fpbx-1-xxxx-00000001", "0?blacklisted") in new stack
-- Executing [s@app-blacklist-check:2] Set("SIP/fpbx-1-xxxx-00000001", "CALLED_BLACKLIST=1") in new stack
-- Executing [s@app-blacklist-check:3] Return("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [334XXXXXXX@from-pstn:4] Set("SIP/fpbx-1-xxxx-00000001", "__FROM_DID=334XXXXXXX") in new stack
-- Executing [334XXXXXXX@from-pstn:5] Set("SIP/fpbx-1-xxxx-00000001", "CDR(did)=334XXXXXXX") in new stack
-- Executing [334XXXXXXX@from-pstn:6] ExecIf("SIP/fpbx-1-xxxx-00000001", "0 ?Set(CALLERID(name)=1920XXXXXXX)") in new stack
-- Executing [334XXXXXXX@from-pstn:7] Set("SIP/fpbx-1-xxxx-00000001", "__MOHCLASS=") in new stack
-- Executing [334XXXXXXX@from-pstn:8] Set("SIP/fpbx-1-xxxx-00000001", "__REVERSAL_REJECT=FALSE") in new stack
-- Executing [334XXXXXXX@from-pstn:9] GotoIf("SIP/fpbx-1-xxxx-00000001", "1?post-reverse-charge") in new stack
-- Goto (from-pstn,334XXXXXXX,11)
-- Executing [334XXXXXXX@from-pstn:11] NoOp("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [334XXXXXXX@from-pstn:12] Set("SIP/fpbx-1-xxxx-00000001", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
-- Executing [334XXXXXXX@from-pstn:13] Set("SIP/fpbx-1-xxxx-00000001", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
-- Executing [334XXXXXXX@from-pstn:14] Set("SIP/fpbx-1-xxxx-00000001", "CALLERID(name-pres)=allowed_not_screened") in new stack
-- Executing [334XXXXXXX@from-pstn:15] Set("SIP/fpbx-1-xxxx-00000001", "CALLERID(num-pres)=allowed_not_screened") in new stack
-- Executing [334XXXXXXX@from-pstn:16] NoOp("SIP/fpbx-1-xxxx-00000001", "CallerID Entry Point") in new stack
-- Executing [334XXXXXXX@from-pstn:17] Set("SIP/fpbx-1-xxxx-00000001", "__CRM_DIRECTION=INBOUND") in new stack
-- Executing [334XXXXXXX@from-pstn:18] Set("SIP/fpbx-1-xxxx-00000001", "__CRM_SOURCE=1920XXXXXXX") in new stack
-- Executing [334XXXXXXX@from-pstn:19] Set("SIP/fpbx-1-xxxx-00000001", "__CRM_LINKEDID=1492532137.1") in new stack
-- Executing [334XXXXXXX@from-pstn:20] ExecIf("SIP/fpbx-1-xxxx-00000001", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
-- Executing [334XXXXXXX@from-pstn:21] Goto("SIP/fpbx-1-xxxx-00000001", "ivr-1,s,1") in new stack
-- Goto (ivr-1,s,1)
-- Executing [s@ivr-1:1] Set("SIP/fpbx-1-xxxx-00000001", "TIMEOUT_LOOPCOUNT=0") in new stack
-- Executing [s@ivr-1:2] Set("SIP/fpbx-1-xxxx-00000001", "INVALID_LOOPCOUNT=0") in new stack
-- Executing [s@ivr-1:3] Set("SIP/fpbx-1-xxxx-00000001", "_IVR_CONTEXT_ivr-1=") in new stack
-- Executing [s@ivr-1:4] Set("SIP/fpbx-1-xxxx-00000001", "_IVR_CONTEXT=ivr-1") in new stack
-- Executing [s@ivr-1:5] Set("SIP/fpbx-1-xxxx-00000001", "__IVR_RETVM=") in new stack
-- Executing [s@ivr-1:6] GotoIf("SIP/fpbx-1-xxxx-00000001", "0?skip") in new stack
-- Executing [s@ivr-1:7] Answer("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [s@ivr-1: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 [s@ivr-1:9] Set("SIP/fpbx-1-xxxx-00000001", "IVR_MSG=custom/IVR") in new stack
-- Executing [s@ivr-1:10] Set("SIP/fpbx-1-xxxx-00000001", "TIMEOUT(digit)=3") in new stack
-- Digit timeout set to 3.000
-- Executing [s@ivr-1: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 [9@ivr-1:1] Goto("SIP/fpbx-1-xxxx-00000001", "directory,1,1") in new stack
-- Goto (directory,1,1)
-- Executing [1@directory:1] Answer("SIP/fpbx-1-xxxx-00000001", "") in new stack
-- Executing [1@directory:2] Wait("SIP/fpbx-1-xxxx-00000001", "1") in new stack
-- Executing [1@directory: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')

biztech · April 18, 2017, 4:38pm

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