External forwarding problem with RCF numbers

While awaiting a number port, we have some numbers RCF’d to native TNs. I have a native with an inbound route to a custom extension that calls an external number.

When we call the native it goes through to the external cell as expected. When we call the number that is RCF’d to the native the calls comes in but is then dropped.

The same thing happens if the RCF’d number rings to an on-prem handset that is forwarded to an external number.

Would be great if we can find a fix for this. There is only one trunk and it’s a Comcast PRI running through a Digium G100.

Appreciate any insight/help.

Not without the information from /var/log/asterisk/full. That will elucidate precisely what is happening on the drop.

Thank you. I apologize for not knowing exactly what to look for in here; trying to learn. All of these have the same timestamp, and I think there is a failed forward in there. First portion (32000 character limit in posts):

[2018-01-29 21:25:30] VERBOSE[11000][C-00000034] netsock2.c: Using SIP RTP TOS bits 184
[2018-01-29 21:25:30] VERBOSE[11000][C-00000034] netsock2.c: Using SIP RTP CoS mark 5
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:1] Set(“SIP/DigiumG100-00000088”, “__DIRECTION=INBOUND”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:2] Gosub(“SIP/DigiumG100-00000088”, “sub-record-check,s,1(in,2067172710,never)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/DigiumG100-00000088”, “0?initialized”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/DigiumG100-00000088”, “__REC_STATUS=INITIALIZED”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/DigiumG100-00000088”, “NOW=1517261130”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/DigiumG100-00000088”, “__DAY=29”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/DigiumG100-00000088”, “__MONTH=01”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/DigiumG100-00000088”, “__YEAR=2018”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/DigiumG100-00000088”, “__TIMESTR=20180129-212530”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/DigiumG100-00000088”, “__FROMEXTEN=unknown”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/DigiumG100-00000088”, “__MON_FMT=wav”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/DigiumG100-00000088”, “Recordings initialized”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(ARG3=dontcare)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/DigiumG100-00000088”, “REC_POLICY_MODE_SAVE=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(REC_STATUS=NO)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/DigiumG100-00000088”, “2?checkaction”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/DigiumG100-00000088”, “1?sub-record-check,in,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,in,1)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [in@sub-record-check:1] NoOp(“SIP/DigiumG100-00000088”, “Inbound Recording Check to 2067172710”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [in@sub-record-check:2] Set(“SIP/DigiumG100-00000088”, “FROMEXTEN=unknown”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [in@sub-record-check:3] ExecIf(“SIP/DigiumG100-00000088”, “10?Set(FROMEXTEN=4257659999)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [in@sub-record-check:4] Gosub(“SIP/DigiumG100-00000088”, “recordcheck,1(never,in,2067172710)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/DigiumG100-00000088”, “Starting recording check against never”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/DigiumG100-00000088”, “never”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,recordcheck,14)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:14] Set(“SIP/DigiumG100-00000088”, “__REC_POLICY_MODE=NEVER”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:15] Goto(“SIP/DigiumG100-00000088”, “stoprec”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,recordcheck,25)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:25] NoOp(“SIP/DigiumG100-00000088”, “Stopping recording: in, 2067172710”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:26] Set(“SIP/DigiumG100-00000088”, “__REC_STATUS=STOPPED”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:27] System(“SIP/DigiumG100-00000088”, "/var/lib/asterisk/bin/stoprecording.php “SIP/DigiumG100-00000088"”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:28] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [in@sub-record-check:5] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:3] Gosub(“SIP/DigiumG100-00000088”, “app-blacklist-check,s,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“SIP/DigiumG100-00000088”, “0?blacklisted”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@app-blacklist-check:2] Set(“SIP/DigiumG100-00000088”, “CALLED_BLACKLIST=1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@app-blacklist-check:3] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:4] Set(“SIP/DigiumG100-00000088”, “__FROM_DID=2067172710”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:5] Set(“SIP/DigiumG100-00000088”, “CDR(did)=2067172710”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:6] ExecIf(“SIP/DigiumG100-00000088”, “0 ?Set(CALLERID(name)=4257659999)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:7] Set(“SIP/DigiumG100-00000088”, “__MOHCLASS=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:8] Set(“SIP/DigiumG100-00000088”, “__REVERSAL_REJECT=FALSE”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:9] GotoIf(“SIP/DigiumG100-00000088”, “1?post-reverse-charge”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (from-trunk,2067172710,11)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:11] NoOp(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:12] Set(“SIP/DigiumG100-00000088”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:13] Set(“SIP/DigiumG100-00000088”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:14] Set(“SIP/DigiumG100-00000088”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:15] Set(“SIP/DigiumG100-00000088”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:16] NoOp(“SIP/DigiumG100-00000088”, “CallerID Entry Point”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:17] Set(“SIP/DigiumG100-00000088”, “__CRM_DIRECTION=INBOUND”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:18] Set(“SIP/DigiumG100-00000088”, “__CRM_SOURCE=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:19] Set(“SIP/DigiumG100-00000088”, “__CRM_LINKEDID=1517261130.1043”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:20] ExecIf(“SIP/DigiumG100-00000088”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [2067172710@from-trunk:21] Goto(“SIP/DigiumG100-00000088”, “from-did-direct,6040,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (from-did-direct,6040,1)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [6040@from-did-direct:1] GotoIf(“SIP/DigiumG100-00000088”, “1?ext-local,6040,1:followme-check,6040,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (ext-local,6040,1)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [6040@ext-local:1] Set(“SIP/DigiumG100-00000088”, “__RINGTIMER=15”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [6040@ext-local:2] Macro(“SIP/DigiumG100-00000088”, “exten-vm,novm,6040,0,0,0”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:1] Macro(“SIP/DigiumG100-00000088”, “user-callerid,”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:1] Set(“SIP/DigiumG100-00000088”, “TOUCH_MONITOR=1517261130.1043”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:2] Set(“SIP/DigiumG100-00000088”, “AMPUSER=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“SIP/DigiumG100-00000088”, “0?report”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“SIP/DigiumG100-00000088”, “1?Set(REALCALLERIDNUM=4257659999)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:5] Set(“SIP/DigiumG100-00000088”, “AMPUSER=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:6] GotoIf(“SIP/DigiumG100-00000088”, “0?limit”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:7] Set(“SIP/DigiumG100-00000088”, “AMPUSERCIDNAME=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:8] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:9] GotoIf(“SIP/DigiumG100-00000088”, “1?report”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-user-callerid,s,16)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:16] NoOp(“SIP/DigiumG100-00000088”, “Macro Depth is 2”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:17] GotoIf(“SIP/DigiumG100-00000088”, “1?report2:macroerror”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-user-callerid,s,19)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:19] GotoIf(“SIP/DigiumG100-00000088”, “0?continue”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:20] Set(“SIP/DigiumG100-00000088”, “__TTL=64”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:21] GotoIf(“SIP/DigiumG100-00000088”, “1?continue”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:37] Set(“SIP/DigiumG100-00000088”, “CALLERID(number)=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:38] Set(“SIP/DigiumG100-00000088”, “CALLERID(name)=CAMPBELL,LOREN”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:39] GotoIf(“SIP/DigiumG100-00000088”, “0?cnum”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:40] Set(“SIP/DigiumG100-00000088”, “CDR(cnam)=CAMPBELL,LOREN”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:41] Set(“SIP/DigiumG100-00000088”, “CDR(cnum)=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-user-callerid:42] Set(“SIP/DigiumG100-00000088”, “CHANNEL(language)=en”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:2] Set(“SIP/DigiumG100-00000088”, “RingGroupMethod=none”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:3] Set(“SIP/DigiumG100-00000088”, “__EXTTOCALL=6040”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:4] Set(“SIP/DigiumG100-00000088”, “__PICKUPMARK=6040”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:5] Set(“SIP/DigiumG100-00000088”, “RT=”) in new stack
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:6] ExecIf(“SIP/DigiumG100-00000088”, “0?Macro(vm,novm,DIRECTDIAL,)”) in new stack
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:7] ExecIf(“SIP/DigiumG100-00000088”, “0?MacroExit()”) in new stack
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:8] ExecIf(“SIP/DigiumG100-00000088”, “0?Gosub(ext-intercom,*806040,1())”) in new stack
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:9] ExecIf(“SIP/DigiumG100-00000088”, “0?MacroExit()”) in new stack
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:10] ExecIf(“SIP/DigiumG100-00000088”, “0?ChanSpy(LOCAL/14257368888@outbound-allroutes,q)”) in new stack
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:11] ExecIf(“SIP/DigiumG100-00000088”, “0?MacroExit()”) in new stack
[2018-01-29 21:25:30] ERROR[27618][C-00000034] res_pjsip_header_funcs.c: This function requires a PJSIP channel.
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:12] Gosub(“SIP/DigiumG100-00000088”, “sub-record-check,s,1(exten,6040,dontcare)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/DigiumG100-00000088”, “10?initialized”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,s,10)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/DigiumG100-00000088”, “Recordings initialized”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(ARG3=dontcare)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/DigiumG100-00000088”, “REC_POLICY_MODE_SAVE=NEVER”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(REC_STATUS=NO)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/DigiumG100-00000088”, “5?checkaction”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/DigiumG100-00000088”, “1?sub-record-check,exten,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [exten@sub-record-check:1] NoOp(“SIP/DigiumG100-00000088”, “Exten Recording Check between 4257659999 and 6040”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [exten@sub-record-check:2] Set(“SIP/DigiumG100-00000088”, “CALLTYPE=external”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [exten@sub-record-check:3] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(CALLTYPE=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [exten@sub-record-check:4] Set(“SIP/DigiumG100-00000088”, “CALLEE=force”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [exten@sub-record-check:5] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(CALLEE=dontcare)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [exten@sub-record-check:6] GotoIf(“SIP/DigiumG100-00000088”, “1?callee”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,exten,11)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [exten@sub-record-check:11] Gosub(“SIP/DigiumG100-00000088”, “recordcheck,1(force,external,6040)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/DigiumG100-00000088”, “Starting recording check against force”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/DigiumG100-00000088”, “force”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,recordcheck,5)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:5] Set(“SIP/DigiumG100-00000088”, “__REC_POLICY_MODE=FORCE”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:6] GotoIf(“SIP/DigiumG100-00000088”, “1?startrec”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp(“SIP/DigiumG100-00000088”, “Starting recording: external, 6040”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:17] Set(“SIP/DigiumG100-00000088”, “AUDIOHOOK_INHERIT(MixMonitor)=yes”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:18] Set(“SIP/DigiumG100-00000088”, “__CALLFILENAME=external-6040-4257659999-20180129-212530-1517261130.1043”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:19] MixMonitor(“SIP/DigiumG100-00000088”, “2018/01/29/external-6040-4257659999-20180129-212530-1517261130.1043.wav,abi(LOCAL_MIXMON_ID),”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:20] Set(“SIP/DigiumG100-00000088”, “__MIXMON_ID=0x7febf88a6670”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:21] Set(“SIP/DigiumG100-00000088”, “__RECORD_ID=SIP/DigiumG100-00000088”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:22] Set(“SIP/DigiumG100-00000088”, “__REC_STATUS=RECORDING”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:23] Set(“SIP/DigiumG100-00000088”, “CDR(recordingfile)=external-6040-4257659999-20180129-212530-1517261130.1043.wav”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:24] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [exten@sub-record-check:12] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:13] GotoIf(“SIP/DigiumG100-00000088”, “1?macrodial”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-exten-vm,s,19)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:19] GosubIf(“SIP/DigiumG100-00000088”, “0?clrheader,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:20] Macro(“SIP/DigiumG100-00000088”, “dial-one,HhTtr,6040”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:1] Set(“SIP/DigiumG100-00000088”, “DEXTEN=6040”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:2] Set(“SIP/DigiumG100-00000088”, “__CRM_SOURCE=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:3] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(EXTTOCALL=6040)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:4] Set(“SIP/DigiumG100-00000088”, “DIALSTATUS_CW=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:5] GosubIf(“SIP/DigiumG100-00000088”, “0?screen,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:6] GosubIf(“SIP/DigiumG100-00000088”, “0?cf,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:7] GotoIf(“SIP/DigiumG100-00000088”, “1?skip1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-dial-one,s,10)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:10] GotoIf(“SIP/DigiumG100-00000088”, “0?nodial”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:11] GotoIf(“SIP/DigiumG100-00000088”, “0?continue”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:12] Set(“SIP/DigiumG100-00000088”, “EXTHASCW=ENABLED”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:13] GotoIf(“SIP/DigiumG100-00000088”, “0?next1:cwinusebusy”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-dial-one,s,25)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:25] GotoIf(“SIP/DigiumG100-00000088”, “0?next3:continue”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-dial-one,s,27)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:27] GotoIf(“SIP/DigiumG100-00000088”, “0?nodial”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:28] GosubIf(“SIP/DigiumG100-00000088”, “1?dstring,1():dlocal,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:1] Set(“SIP/DigiumG100-00000088”, “DSTRING=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:2] Set(“SIP/DigiumG100-00000088”, “DEVICES=6040”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf(“SIP/DigiumG100-00000088”, “0?Return()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(DEVICES=040)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:5] Set(“SIP/DigiumG100-00000088”, “LOOPCNT=1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:6] Set(“SIP/DigiumG100-00000088”, “ITER=1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:7] Set(“SIP/DigiumG100-00000088”, “THISDIAL=LOCAL/14257368888@outbound-allroutes”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf(“SIP/DigiumG100-00000088”, “1?zap2dahdi,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/DigiumG100-00000088”, “0?Return()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/DigiumG100-00000088”, “NEWDIAL=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/DigiumG100-00000088”, “LOOPCNT2=1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/DigiumG100-00000088”, “ITER2=1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/DigiumG100-00000088”, “THISPART2=LOCAL/14257368888@outbound-allroutes”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(THISPART2=DAHDIAL/14257368888@outbound-allroutes)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/DigiumG100-00000088”, “NEWDIAL=LOCAL/14257368888@outbound-allroutes&”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/DigiumG100-00000088”, “ITER2=2”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/DigiumG100-00000088”, “0?begin2”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/DigiumG100-00000088”, “THISDIAL=LOCAL/14257368888@outbound-allroutes”) in new stack

Second portion:

[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf(“SIP/DigiumG100-00000088”, “1?docheck”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-dial-one,dstring,14)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:14] GotoIf(“SIP/DigiumG100-00000088”, “0?skipset”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:15] Set(“SIP/DigiumG100-00000088”, “DSTRING=LOCAL/14257368888@outbound-allroutes&”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:16] Set(“SIP/DigiumG100-00000088”, “ITER=2”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:17] GotoIf(“SIP/DigiumG100-00000088”, “0?begin”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:18] ExecIf(“SIP/DigiumG100-00000088”, “0?Return()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:19] Set(“SIP/DigiumG100-00000088”, “DSTRING=LOCAL/14257368888@outbound-allroutes”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [dstring@macro-dial-one:20] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:29] GotoIf(“SIP/DigiumG100-00000088”, “0?nodial”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:30] GotoIf(“SIP/DigiumG100-00000088”, “0?skiptrace”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:31] GosubIf(“SIP/DigiumG100-00000088”, “1?ctset,1():ctclear,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [ctset@macro-dial-one:1] Set(“SIP/DigiumG100-00000088”, “DB(CALLTRACE/6040)=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [ctset@macro-dial-one:2] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:32] Set(“SIP/DigiumG100-00000088”, “D_OPTIONS=HhTtr”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:33] NoOp(“SIP/DigiumG100-00000088”, "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:34] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(ALERT_INFO=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:35] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(ALERT_INFO=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:36] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(ALERT_INFO=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:37] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(ALERT_INFO=Normal;volume=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:38] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(ALERT_INFO=Normal;volume=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:39] GosubIf(“SIP/DigiumG100-00000088”, “0?func-set-sipheader,s,1(Alert-Info,)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:40] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(CHANNEL(musicclass)=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:41] GosubIf(“SIP/DigiumG100-00000088”, “0?qwait,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:42] Set(“SIP/DigiumG100-00000088”, “__CWIGNORE=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:43] Set(“SIP/DigiumG100-00000088”, “__KEEPCID=TRUE”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:44] GotoIf(“SIP/DigiumG100-00000088”, “0?usegoto,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:45] GotoIf(“SIP/DigiumG100-00000088”, “1?godial”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-dial-one,s,50)
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:50] Macro(“SIP/DigiumG100-00000088”, “dialout-one-predial-hook,”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:51] ExecIf(“SIP/DigiumG100-00000088”, “1?Set(D_OPTIONS=HhtrI)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:52] NoOp(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:53] Dial(“SIP/DigiumG100-00000088”, “LOCAL/14257368888@outbound-allroutes,HhtrIb(func-apply-sipheaders^s^1)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27628][C-00000034] app_mixmonitor.c: Begin MixMonitor Recording SIP/DigiumG100-00000088
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] app_stack.c: Local/14257368888@outbound-allroutes-00000017;1 Internal Gosub(func-apply-sipheaders,s,1) start
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf(“Local/14257368888@outbound-allroutes-00000017;1”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp(“Local/14257368888@outbound-allroutes-00000017;1”, “Applying SIP Headers to channel”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@func-apply-sipheaders:3] Set(“Local/14257368888@outbound-allroutes-00000017;1”, “SIPHEADERKEYS=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@func-apply-sipheaders:4] While(“Local/14257368888@outbound-allroutes-00000017;1”, “0”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] app_while.c: Jumping to priority 8
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] pbx.c: Executing [s@func-apply-sipheaders:9] Return(“Local/14257368888@outbound-allroutes-00000017;1”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] app_stack.c: Spawn extension (outbound-allroutes, 6040, 1) exited non-zero on ‘Local/14257368888@outbound-allroutes-00000017;1’
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] app_stack.c: Local/14257368888@outbound-allroutes-00000017;1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] app_dial.c: Called LOCAL/14257368888@outbound-allroutes
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [14257368888@outbound-allroutes:1] Macro(“Local/14257368888@outbound-allroutes-00000017;2”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:1] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “TOUCH_MONITOR=1517261130.1045”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:2] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “AMPUSER=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?report”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?Set(REALCALLERIDNUM=4257659999)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:5] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “AMPUSER=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:6] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?limit”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:7] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “AMPUSERCIDNAME=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:8] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:9] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?report”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-user-callerid,s,16)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:16] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “Macro Depth is 1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:17] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?report2:macroerror”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-user-callerid,s,19)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:19] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?continue”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:37] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “CALLERID(number)=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:38] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “CALLERID(name)=CAMPBELL,LOREN”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:39] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?cnum”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:40] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “CDR(cnam)=CAMPBELL,LOREN”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:41] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “CDR(cnum)=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-user-callerid:42] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “CHANNEL(language)=en”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [14257368888@outbound-allroutes:2] Gosub(“Local/14257368888@outbound-allroutes-00000017;2”, “sub-record-check,s,1(out,14257368888,dontcare)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:1] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?initialized”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:2] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “__REC_STATUS=INITIALIZED”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:3] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “NOW=1517261130”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:4] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “__DAY=29”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:5] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “__MONTH=01”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:6] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “__YEAR=2018”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:7] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “__TIMESTR=20180129-212530”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:8] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “__FROMEXTEN=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:9] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “__MON_FMT=wav”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:10] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “Recordings initialized”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:11] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(ARG3=dontcare)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:12] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “REC_POLICY_MODE_SAVE=FORCE”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:13] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(REC_STATUS=NO)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:14] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “3?checkaction”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@sub-record-check:17] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?sub-record-check,out,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (sub-record-check,out,1)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [out@sub-record-check:1] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “Outbound Recording Check from 4257659999 to 14257368888”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [out@sub-record-check:2] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “RECMODE=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [out@sub-record-check:3] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?Goto(routewins)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (sub-record-check,out,7)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [out@sub-record-check:7] Gosub(“Local/14257368888@outbound-allroutes-00000017;2”, “recordcheck,1(dontcare,out,14257368888)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “Starting recording check against dontcare”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“Local/14257368888@outbound-allroutes-00000017;2”, “dontcare”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“Local/14257368888@outbound-allroutes-00000017;2”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [out@sub-record-check:8] Return(“Local/14257368888@outbound-allroutes-00000017;2”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [14257368888@outbound-allroutes:3] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0 ?Set(CDR(accountcode)=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [14257368888@outbound-allroutes:4] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “MOHCLASS=default”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [14257368888@outbound-allroutes:5] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “_NODEST=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [14257368888@outbound-allroutes:6] Macro(“Local/14257368888@outbound-allroutes-00000017;2”, “dialout-trunk,1,14257368888,off”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:1] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “DIAL_TRUNK=1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:2] GosubIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?sub-pincheck,s,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:3] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(CALLERID(num)=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:4] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?disabletrunk,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:5] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “DIAL_NUMBER=14257368888”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:6] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “DIAL_TRUNK_OPTIONS=HhTtr”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:7] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:8] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “DIAL_TRUNK_OPTIONS=T”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:9] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?nomax”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?chanfull”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:11] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?skipoutcid”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:12] Macro(“Local/14257368888@outbound-allroutes-00000017;2”, “outbound-callerid,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “TRUE”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “off”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?Set(CALLERPRES(name-pres)=allowed_not_screened)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?Set(CALLERPRES(num-pres)=allowed_not_screened)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:6] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(REALCALLERIDNUM=4257659999)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:7] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?normcid”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:8] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “USEROUTCID=4257659999”) in new stack

Last portion. External TNs have been changed for privacy.

[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:9] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?normcid”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:10] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?bypass”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-outbound-callerid,s,12)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:12] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “EMERGENCYCID=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:13] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “TRUNKOUTCID=4257326000”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:14] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?trunkcid”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-outbound-callerid,s,19)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:19] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?Set(CALLERID(all)=4257326000)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:20] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?Set(CALLERID(all)=4257659999)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(CALLERID(all)=)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(CALLERPRES(name-pres)=prohib_passed_screen)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(CALLERPRES(num-pres)=prohib_passed_screen)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:24] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “CDR(outbound_cnum)=4257659999”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-outbound-callerid:25] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “CDR(outbound_cnam)=”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:13] GosubIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?sub-flp-1,s,1()”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:14] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “OUTNUM=14257368888”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:15] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “custom=SIP/DigiumG100”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:16] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:18] Macro(“Local/14257368888@outbound-allroutes-00000017;2”, “dialout-trunk-predial-hook,”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“Local/14257368888@outbound-allroutes-00000017;2”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:19] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “1?skipcrm”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-dialout-trunk,s,25)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:25] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “CRM Finished”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:26] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?bypass,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:27] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(CONNECTEDLINE(num,i)=14257368888)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:28] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(CONNECTEDLINE(name,i)=CID:4257659999)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:29] ExecIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)4257659999)”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:30] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?customtrunk”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:31] Dial(“Local/14257368888@outbound-allroutes-00000017;2”, “SIP/DigiumG100/14257368888,300,T”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] netsock2.c: Using SIP RTP TOS bits 184
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] netsock2.c: Using SIP RTP CoS mark 5
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] app_dial.c: Called SIP/DigiumG100/14257368888
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:32] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:33] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?continue,1:s-CHANUNAVAIL,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set(“Local/14257368888@outbound-allroutes-00000017;2”, “RC=1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto(“Local/14257368888@outbound-allroutes-00000017;2”, “1,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-dialout-trunk,1,1)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [1@macro-dialout-trunk:1] Goto(“Local/14257368888@outbound-allroutes-00000017;2”, “s-INVALIDNMBR,1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx_builtins.c: Goto (macro-dialout-trunk,s-INVALIDNMBR,1)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s-INVALIDNMBR@macro-dialout-trunk:1] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “Dial failed due to trunk reporting Address Incomplete - giving up”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s-INVALIDNMBR@macro-dialout-trunk:2] Progress(“Local/14257368888@outbound-allroutes-00000017;2”, “”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s-INVALIDNMBR@macro-dialout-trunk:3] Playback(“Local/14257368888@outbound-allroutes-00000017;2”, “ss-noservice,noanswer”) in new stack
[2018-01-29 21:25:30] VERBOSE[27618][C-00000034] app_dial.c: Local/14257368888@outbound-allroutes-00000017;1 is making progress passing it to SIP/DigiumG100-00000088
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] file.c: <Local/14257368888@outbound-allroutes-00000017;2> Playing ‘ss-noservice.ulaw’ (language ‘en’)
[2018-01-29 21:25:35] VERBOSE[27629][C-00000034] pbx.c: Executing [s-INVALIDNMBR@macro-dialout-trunk:4] Busy(“Local/14257368888@outbound-allroutes-00000017;2”, “20”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] app_dial.c: Local/14257368888@outbound-allroutes-00000017;1 is busy
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] app_stack.c: Local/14257368888@outbound-allroutes-00000017;1 Internal Gosub(crm-hangup,s,1) start
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:1] NoOp(“Local/14257368888@outbound-allroutes-00000017;1”, “Sending Hangup to CRM”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:2] NoOp(“Local/14257368888@outbound-allroutes-00000017;1”, “HANGUP CAUSE: 0”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:3] ExecIf(“Local/14257368888@outbound-allroutes-00000017;1”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:4] NoOp(“Local/14257368888@outbound-allroutes-00000017;1”, “MASTER CHANNEL: 1517261130.1044 = 1517261130.1043”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:5] GotoIf(“Local/14257368888@outbound-allroutes-00000017;1”, “1?return”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (crm-hangup,s,8)
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:8] Return(“Local/14257368888@outbound-allroutes-00000017;1”, “”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] app_stack.c: Spawn extension (outbound-allroutes, 6040, 1) exited non-zero on ‘Local/14257368888@outbound-allroutes-00000017;1’
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] app_stack.c: Local/14257368888@outbound-allroutes-00000017;1 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] app_dial.c: Everyone is busy/congested at this time (1:1/0/0)
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:54] ExecIf(“SIP/DigiumG100-00000088”, “0?MacroExit()”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:55] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(DIALSTATUS=)”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:56] GosubIf(“SIP/DigiumG100-00000088”, “0?s-BUSY,1()”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-dial-one:57] MacroExit(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:21] Set(“SIP/DigiumG100-00000088”, “SV_DIALSTATUS=BUSY”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:22] GosubIf(“SIP/DigiumG100-00000088”, “0?docfu,1()”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:23] GosubIf(“SIP/DigiumG100-00000088”, “0?docfb,1()”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:24] Set(“SIP/DigiumG100-00000088”, “DIALSTATUS=BUSY”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:25] ExecIf(“SIP/DigiumG100-00000088”, “0?MacroExit()”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-exten-vm:26] GotoIf(“SIP/DigiumG100-00000088”, “1?s-BUSY,1”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-exten-vm,s-BUSY,1)
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s-BUSY@macro-exten-vm:1] GotoIf(“SIP/DigiumG100-00000088”, “0?exit,1”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s-BUSY@macro-exten-vm:2] PlayTones(“SIP/DigiumG100-00000088”, “busy”) in new stack
[2018-01-29 21:25:35] VERBOSE[27629][C-00000034] app_macro.c: Spawn extension (macro-dialout-trunk, s-INVALIDNMBR, 4) exited non-zero on ‘Local/14257368888@outbound-allroutes-00000017;2’ in macro ‘dialout-trunk’
[2018-01-29 21:25:35] VERBOSE[27629][C-00000034] pbx.c: Spawn extension (outbound-allroutes, 14257368888, 6) exited non-zero on ‘Local/14257368888@outbound-allroutes-00000017;2’
[2018-01-29 21:25:35] WARNING[27618][C-00000034] translate.c: no samples for ulawtolin
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s-BUSY@macro-exten-vm:3] Busy(“SIP/DigiumG100-00000088”, “20”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] app_macro.c: Spawn extension (macro-exten-vm, s-BUSY, 3) exited non-zero on ‘SIP/DigiumG100-00000088’ in macro ‘exten-vm’
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Spawn extension (ext-local, 6040, 2) exited non-zero on ‘SIP/DigiumG100-00000088’
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [h@ext-local:1] Macro(“SIP/DigiumG100-00000088”, “hangupcall,”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“SIP/DigiumG100-00000088”, “1?theend”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(CDR(recordingfile)=)”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“SIP/DigiumG100-00000088”, " monior file= /var/spool/asterisk/monitor/2018/01/29/external-6040-4257659999-20180129-212530-1517261130.1043.wav") in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-hangupcall:5] AGI(“SIP/DigiumG100-00000088”, “attendedtransfer-rec-restart.php,/var/spool/asterisk/monitor/2018/01/29/external-6040-4257659999-20180129-212530-1517261130.1043.wav”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] res_agi.c: <SIP/DigiumG100-00000088>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@macro-hangupcall:6] Hangup(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on ‘SIP/DigiumG100-00000088’ in macro ‘hangupcall’
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on ‘SIP/DigiumG100-00000088’
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] app_stack.c: SIP/DigiumG100-00000088 Internal Gosub(crm-hangup,s,1) start
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/DigiumG100-00000088”, “Sending Hangup to CRM”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/DigiumG100-00000088”, “HANGUP CAUSE: 17”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/DigiumG100-00000088”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/DigiumG100-00000088”, “MASTER CHANNEL: 1517261130.1043 = 1517261130.1043”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/DigiumG100-00000088”, “0?return”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/DigiumG100-00000088”, “__CRM_HANGUP=1”) in new stack
[2018-01-29 21:25:35] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/DigiumG100-00000088”, “sangomacrm.agi”) in new stack
[2018-01-29 21:25:36] VERBOSE[27618][C-00000034] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-01-29 21:25:36] VERBOSE[27618][C-00000034] res_agi.c: <SIP/DigiumG100-00000088>AGI Script sangomacrm.agi completed, returning 0
[2018-01-29 21:25:36] VERBOSE[27618][C-00000034] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/DigiumG100-00000088”, “”) in new stack
[2018-01-29 21:25:36] VERBOSE[27618][C-00000034] app_stack.c: Spawn extension (ext-local, h, 1) exited non-zero on ‘SIP/DigiumG100-00000088’
[2018-01-29 21:25:36] VERBOSE[27618][C-00000034] app_stack.c: SIP/DigiumG100-00000088 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-01-29 21:25:36] VERBOSE[27628][C-00000034] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2018-01-29 21:25:36] VERBOSE[27628][C-00000034] app_mixmonitor.c: End MixMonitor Recording SIP/DigiumG100-00000088

Did you see that one?

I was still parsing through. Excuse my ignorance, but even though you’ve pointed it out, I cannot see why it’s failing; there is a valid TN in there…and if we dial the native TN that triggers this forward, it works. It’s only failing when the non-native TN RCF’d to the functioning native is called.

Also seeing this:

[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] app_dial.c: Called SIP/DigiumG100/14257368888
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:32] NoOp(“Local/14257368888@outbound-allroutes-00000017;2”, “Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 1”) in new stack
[2018-01-29 21:25:30] VERBOSE[27629][C-00000034] pbx.c: Executing [s@macro-dialout-trunk:33] GotoIf(“Local/14257368888@outbound-allroutes-00000017;2”, “0?continue,1:s-CHANUNAVAIL,1”) in new stack

Still doesn’t make sense to me; architecture is PRI to Digium G100 to FreePBX via SIP trunk. Sorry if I’m missing something obvious here, I just can’t get my head around why it errors only when the RCF’d number is called.

Is it possible that you only paid for one RCF path but are trying to use it twice?

Asterisk has a problem with forwarding forwarded calls - it’s hard coded in such a way to make that a problem. While this doesn’t sound like that’s the case, it’s certainly something to look at. Since your RCF is outside of Asterisk, the call forward loop detection shouldn’t be getting invoked, but you never know.

The error message from your provider says that the Dial failed due to trunk reporting Address Incomplete and that your provider is giving up on the call. This error can be used when people are using foreign Caller IDs. Does your provider care about your outbound caller ID settings?

I don’t think so; the outbound calls should not be on the RCF path; the losing provider is simply remote forwarding the calls to new native numbers (pending port), and the outbound/forwarded calls should just go out directly on the PRI.

At least that’s what I think. The custom dial string on the extension that should ring the external number is: LOCAL/14257368888@outbound-allroutes

Maybe it needs to be modified to use just the SIP trunk that lands on the PRI? I just don’t see how FreePBX would know to do anything else; it only has one outbound route.

“Does your provider care about your outbound caller ID settings?”

No, they do not. They accept what we send. That said, I can try setting the outbound CallerID on the custom extension to a native TN and see what happens. Can’t get my head around how that would be different than a call to the native routed to that extension/external number, which works.

Same result: Call rings once, then plays a busy signal.

From your logs

so calling 14257368888 on DigiumG100 is returning a “1” which means that number is unallocated on outbound-allroutes, so check your dialpatterns against your preferred outbound trunk routing perhaps you need to strip the initial 1 ? or you might need to add a route that can handle it after the PRI fails

Thanks. I understand what you are saying, but don’t see how it explains why the route works if the native TN that routes to the custom extension is dialed.

Works:
Native TN -> custom extension -> external number

Fails:
RCF number ->. native TN -> custom extension -> external number

Same native TN and extension. Can also pick up a handset and dial the external number as its entered in the custom extension and the call goes through.

you would have to post that call process, obviously you can’t call 14257368888 on your programmed outbound routes, perhaps your “custom extension” context can, we have no knowledge of what that is from you yet, please post it.

Note: Uploading file with a TGZ extension, as txt isn’t accepted. It’s a text file. It’s over 160,000 characters and the post limit is 32,000.
RCF Issue.tgz (164.5 KB)

Three calls in here. All from 4257659999.
First call is to the non-native RCF’d to 2067177777. Call fails, one ring then busy.
Second call is to the native TN, 2067177777 with an inbound route to the custom ext. Call goes to custom extension and then out to 2062628888, successful
Third call is to another native TN, 2067176666, with an inbound route to the custom ext. Call goes to custom extension and then out to 2062628888, successful.

More info: If I remove the leading 1 from the custom dial setting for the extension, calls to the RCF’d number go through. So there is something about the leading 1 that somehow only affects externally routed RCF’d calls.

LOCAL/12062628888@outbound-allroutes
Call to RCF number fails.
Call to native number works.

LOCAL/2062628888@outbound-allroutes
Call to RCF’d number works.
Call to native number works.

that would be a QED, no? don’t do that. . to verify, post a call that did go through.

There is an example of a successful call in the log I posted.

I’m starting to think this is an arcane bug.