Testing an IVR before implementation

Hi there. We’re migrating to FreePBX from an old bare-metal Asterisk version. Since we’re currently running Asterisk through our firewall to our SIP provider, I don’t think it’s a good idea to actually set up another SIP trunk for testing our inbound routes. Historically, this has broken NAT and prevents incoming calls to our live PBX.

So here’s where we are at this stage:

  • Our FreePBX server is up and running, several Yealink phones are connected and can call each other with no issue.
  • I’ve set up an inbound route for our phone number, which is supposed to go to our IVR.
  • I’ve set up our IVR, but I still need to test it before we go live with the new PBX.
  • I’ve tried to set up an internal extension that forwards to that inbound route, but I just get a busy signal. Asterisk seems to be going around in circles for a few seconds before giving up.

Here’s the Asterisk console logs I see when I test the inbound number:

[2018-01-12 10:08:55] VERBOSE[16396][C-00000001] pbx.c: Executing [s@macro-dial-one:50] Macro("Local/6045551234@default-00000025;2", "dialout-one-predial-hook,") in new stack
[2018-01-12 10:08:55] VERBOSE[16396][C-00000001] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("Local/6045551234@default-00000025;2", "") in new stack
[2018-01-12 10:08:55] VERBOSE[16396][C-00000001] pbx.c: Executing [s@macro-dial-one:51] ExecIf("Local/6045551234@default-00000025;2", "0?Set(D_OPTIONS=HhtrII)") in new stack
[2018-01-12 10:08:55] VERBOSE[16396][C-00000001] pbx.c: Executing [s@macro-dial-one:52] NoOp("Local/6045551234@default-00000025;2", "") in new stack
[2018-01-12 10:08:55] VERBOSE[16396][C-00000001] pbx.c: Executing [s@macro-dial-one:53] Dial("Local/6045551234@default-00000025;2", "LOCAL/6045551234@default,,HhTtrIb(func-apply-sipheaders^s^1)") in new stack
[2018-01-12 10:08:55] VERBOSE[16395][C-00000001] app_dial.c: Connected line update to Local/6045551234@default-00000024;2 prevented.
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] app_stack.c: Local/6045551234@default-00000026;1 Internal Gosub(func-apply-sipheaders,s,1) start
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("Local/6045551234@default-00000026;1", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("Local/6045551234@default-00000026;1", "Applying SIP Headers to channel") in new stack
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:3] Set("Local/6045551234@default-00000026;1", "SIPHEADERKEYS=") in new stack
[2018-01-12 10:08:56] WARNING[16396][C-00000001] taskprocessor.c: The 'subm:ast_channel_topic_all-cached-00000041' task processor queue reached 500 scheduled tasks again.
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:4] While("Local/6045551234@default-00000026;1", "0") in new stack
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] app_while.c: Jumping to priority 7
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] pbx.c: Executing [s@func-apply-sipheaders:8] Return("Local/6045551234@default-00000026;1", "") in new stack
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] app_stack.c: Spawn extension (default, 6045551234, 1) exited non-zero on 'Local/6045551234@default-00000026;1'
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] app_stack.c: Local/6045551234@default-00000026;1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-01-12 10:08:56] VERBOSE[16396][C-00000001] app_dial.c: Called LOCAL/6045551234@default
[2018-01-12 10:08:56] VERBOSE[16395][C-00000001] app_dial.c: Local/6045551234@default-00000025;1 is ringing
[2018-01-12 10:08:56] VERBOSE[16394][C-00000001] app_dial.c: Local/6045551234@default-00000024;1 is ringing
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [6045551234@default:1] Set("Local/6045551234@default-00000026;2", "__RINGTIMER=15") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [6045551234@default:2] Macro("Local/6045551234@default-00000026;2", "exten-vm,novm,6045551234,0,0,0") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:1] Macro("Local/6045551234@default-00000026;2", "user-callerid,") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:1] Set("Local/6045551234@default-00000026;2", "TOUCH_MONITOR=1515780536.79") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:2] Set("Local/6045551234@default-00000026;2", "AMPUSER=1002") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("Local/6045551234@default-00000026;2", "0?report") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("Local/6045551234@default-00000026;2", "1?Set(REALCALLERIDNUM=1002)") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:5] Set("Local/6045551234@default-00000026;2", "AMPUSER=1002") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("Local/6045551234@default-00000026;2", "0?limit") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:7] Set("Local/6045551234@default-00000026;2", "AMPUSERCIDNAME=Ernie Dunbar") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("Local/6045551234@default-00000026;2", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("Local/6045551234@default-00000026;2", "0?report") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:10] Set("Local/6045551234@default-00000026;2", "AMPUSERCID=1002") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:11] Set("Local/6045551234@default-00000026;2", "__DIAL_OPTIONS=HhTtr") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:12] Set("Local/6045551234@default-00000026;2", "CALLERID(all)="Ernie Dunbar" <1002>") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("Local/6045551234@default-00000026;2", "0?limit") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("Local/6045551234@default-00000026;2", "0?Set(GROUP(concurrency_limit)=1002)") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("Local/6045551234@default-00000026;2", "0?Set(CHANNEL(language)=)") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:16] NoOp("Local/6045551234@default-00000026;2", "Macro Depth is 2") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("Local/6045551234@default-00000026;2", "1?report2:macroerror") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx_builtins.c: Goto (macro-user-callerid,s,19)
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("Local/6045551234@default-00000026;2", "0?continue") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:20] Set("Local/6045551234@default-00000026;2", "__TTL=45") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:21] GotoIf("Local/6045551234@default-00000026;2", "1?continue") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:37] Set("Local/6045551234@default-00000026;2", "CALLERID(number)=1002") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:38] Set("Local/6045551234@default-00000026;2", "CALLERID(name)=Ernie Dunbar") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("Local/6045551234@default-00000026;2", "0?cnum") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:40] Set("Local/6045551234@default-00000026;2", "CDR(cnam)=Ernie Dunbar") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:41] Set("Local/6045551234@default-00000026;2", "CDR(cnum)=1002") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-user-callerid:42] Set("Local/6045551234@default-00000026;2", "CHANNEL(language)=en") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:2] Set("Local/6045551234@default-00000026;2", "RingGroupMethod=none") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:3] Set("Local/6045551234@default-00000026;2", "__EXTTOCALL=6045551234") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:4] Set("Local/6045551234@default-00000026;2", "__PICKUPMARK=6045551234") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:5] Set("Local/6045551234@default-00000026;2", "RT=") in new stack
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("Local/6045551234@default-00000026;2", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("Local/6045551234@default-00000026;2", "0?MacroExit()") in new stack
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:8] ExecIf("Local/6045551234@default-00000026;2", "0?Gosub(ext-intercom,*806045551234,1())") in new stack
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:9] ExecIf("Local/6045551234@default-00000026;2", "0?MacroExit()") in new stack
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:10] ExecIf("Local/6045551234@default-00000026;2", "0?ChanSpy(LOCAL/6045551234@default,q)") in new stack
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:11] ExecIf("Local/6045551234@default-00000026;2", "0?MacroExit()") in new stack
[2018-01-12 10:08:56] WARNING[16397][C-00000001] chan_sip.c: This function can only be used on SIP channels.
[2018-01-12 10:08:56] ERROR[16397][C-00000001] pbx_functions.c: Function PJSIP_HEADER not registered
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@macro-exten-vm:12] Gosub("Local/6045551234@default-00000026;2", "sub-record-check,s,1(exten,6045551234,dontcare)") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx.c: Executing [s@sub-record-check:1] GotoIf("Local/6045551234@default-00000026;2", "4?initialized") in new stack
[2018-01-12 10:08:56] VERBOSE[16397][C-00000001] pbx_builtins.c: Goto (sub-record-check,s,10)

(from here, it just goes into a loop for another 600 lines of console output or so)

There should also probably be a procedure for how to set up IVR testing in the “First Steps After Installation” chapter in the manual. Especially for when you’re in my situation.

7777 simulates an inbound call

When configuring PBXact I used a custom destination to test my IVR’s. Can set a dialed number to go right to the IVR.

Actually, I tried that first. It’s never worked, so I gave this a shot instead.

This is what happens when I dial 7777:

[2018-01-12 14:32:42] VERBOSE[3929][C-00000003] netsock2.c: Using SIP RTP TOS bits 184
[2018-01-12 14:32:42] VERBOSE[3929][C-00000003] netsock2.c: Using SIP RTP CoS mark 5
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [7777@from-internal:1] Macro("SIP/1002-00000003", "user-callerid,") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/1002-00000003", "TOUCH_MONITOR=1515796362.83") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/1002-00000003", "AMPUSER=1002") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/1002-00000003", "0?report") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/1002-00000003", "1?Set(REALCALLERIDNUM=1002)") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/1002-00000003", "AMPUSER=1002") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/1002-00000003", "0?limit") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/1002-00000003", "AMPUSERCIDNAME=Ernie Dunbar") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/1002-00000003", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/1002-00000003", "0?report") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/1002-00000003", "AMPUSERCID=1002") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/1002-00000003", "__DIAL_OPTIONS=HhTtr") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:12] Set("SIP/1002-00000003", "CALLERID(all)="Ernie Dunbar" <1002>") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("SIP/1002-00000003", "0?limit") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("SIP/1002-00000003", "0?Set(GROUP(concurrency_limit)=1002)") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("SIP/1002-00000003", "0?Set(CHANNEL(language)=)") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:16] NoOp("SIP/1002-00000003", "Macro Depth is 1") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("SIP/1002-00000003", "1?report2:macroerror") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx_builtins.c: Goto (macro-user-callerid,s,19)
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("SIP/1002-00000003", "0?continue") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:20] Set("SIP/1002-00000003", "__TTL=64") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:21] GotoIf("SIP/1002-00000003", "1?continue") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/1002-00000003", "CALLERID(number)=1002") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:38] Set("SIP/1002-00000003", "CALLERID(name)=Ernie Dunbar") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("SIP/1002-00000003", "0?cnum") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/1002-00000003", "CDR(cnam)=Ernie Dunbar") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/1002-00000003", "CDR(cnum)=1002") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-user-callerid:42] Set("SIP/1002-00000003", "CHANNEL(language)=en") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [7777@from-internal:2] Goto("SIP/1002-00000003", "from-pstn,7777,1") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx_builtins.c: Goto (from-pstn,7777,1)
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [7777@from-pstn:1] Set("SIP/1002-00000003", "__FROM_DID=7777") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [7777@from-pstn:2] NoOp("SIP/1002-00000003", "Received an unknown call with DID set to 7777") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [7777@from-pstn:3] Goto("SIP/1002-00000003", "s,a2") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx_builtins.c: Goto (from-pstn,s,2)
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@from-pstn:2] Answer("SIP/1002-00000003", "") in new stack
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@from-pstn:3] Log("SIP/1002-00000003", "WARNING,Friendly Scanner from 192.168.0.90") in new stack
[2018-01-12 14:32:42] WARNING[17684][C-00000003] Ext. s: Friendly Scanner from 192.168.0.90
[2018-01-12 14:32:42] VERBOSE[17684][C-00000003] pbx.c: Executing [s@from-pstn:4] Wait("SIP/1002-00000003", "2") in new stack
[2018-01-12 14:32:44] VERBOSE[17684][C-00000003] pbx.c: Executing [s@from-pstn:5] Playback("SIP/1002-00000003", "ss-noservice") in new stack
[2018-01-12 14:32:44] VERBOSE[17684][C-00000003] file.c: <SIP/1002-00000003> Playing 'ss-noservice.ulaw' (language 'en')
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] pbx.c: Executing [h@from-pstn:1] Macro("SIP/1002-00000003", "hangupcall,") in new stack
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/1002-00000003", "1?theend") in new stack
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/1002-00000003", "0?Set(CDR(recordingfile)=)") in new stack
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-hangupcall:4] NoOp("SIP/1002-00000003", " monior file= ") in new stack
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-hangupcall:5] AGI("SIP/1002-00000003", "attendedtransfer-rec-restart.php,,") in new stack
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] res_agi.c: <SIP/1002-00000003>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] pbx.c: Executing [s@macro-hangupcall:6] Hangup("SIP/1002-00000003", "") in new stack
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'SIP/1002-00000003' in macro 'hangupcall'
[2018-01-12 14:32:47] VERBOSE[17684][C-00000003] pbx.c: Spawn extension (from-pstn, h, 1) exited non-zero on 'SIP/1002-00000003'

Bump!

Did you submit a ticket to go along with the bug report?