Help understanding where a call went to

Hi,
I have built a simple dialplan to be able to do some ring back features with short and long BLF presses. It’s working for most people but there seems there are a small number of calls where, during the BLF transfer, the inbound call goes somewhere and sits on hold for minutes and my client can’t get the callback. I don’t think it’s my dial plan, but it is my first real dial plan so I am sure it could be enhanced to help these types of things happening in future. I am finding it difficult to find out what’s happening by the logs.

Can anyone confirm my notes below or help me understand where the call might be going, and how, perhaps, the same users are having the same issues.

Background - 150 user PBXact in the cloud with 7 sites (about 20 phones (S500’s and S505’s) per site)
More than one site is having the issue, but its only on very few calls. Could it be a user issue, a faulty phone, a broadband issue at the time of the BLF transfer?

BLF buttons are setup to do Attended Transfer
Short Press BLF injects SP before the BLF Value
My dial plan looks for calls with SP in the first two characters, then sends the call to the Extension (minus the first 2 characters) with a ring back time that is less than the extension voicemail timeout. I also inject some additional text so the Ring back shows the user name of who was unavailable.

First my dial plan
[from-internal-custom]
exten => _SPX.,1,Set(origext=${CALLERID(num)})
same => n,Set(origextname=${DB(AMPUSER/${EXTEN:2}/cidname)})
same => n,Set(timeoutd=20) ; set timeout in seconds
same => n,Dial(Local/${EXTEN:2}@from-internal,${timeoutd},m)
same => n,Set(CALLERID(name)=RB:${origextname}-${CALLERID(name)})
same => n,Dial(Local/${EXTEN:2}@from-internal&Local/${origext}@from-internal,90,m); this calls both phones back but finishes at voicemail of destination
same => n,Hangup()`

Here is a list of the logs showing an inbound call yesterday - the full logs will be uploaded after this first post.
Call in to this number 021111111111
[2019-10-09 12:00:29] VERBOSE[11278][C-00002df2] pbx.c: Executing [02111111111@from-trunk:1] Set("IAX2/sbc3-3141", "__DIRECTION=INBOUND") in new stack

from this number 02020202020
[2019-10-09 12:00:29] VERBOSE[11278][C-00002df2] pbx.c: Executing [in@sub-record-check:3] ExecIf("IAX2/sbc3-3141", "11?Set(FROMEXTEN=02020202020)") in new stack

picked up by extension 805 after 5 seconds
[2019-10-09 12:00:34] VERBOSE[11324][C-00002df2] app_dial.c: SIP/805-00009163 answered Local/805@from-queue-00038a83;2

The recorded audio of this call reveals that they speak for about 20 seconds and then 805 puts the call on hold and the call sits listening to hold music for about 5 minutes before they hang up.

It looks like 805 presses the transfer button which puts the call on hold.
[2019-10-09 12:00:57] VERBOSE[11324][C-00002df2] res_musiconhold.c: Started music on hold, class ‘clientname’, on channel ‘Local/805@from-queue-00038a83;2’
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User

Then 805 presses the BLF of 812 a second later (this is where my dial plan code comes in - Short Press)
(I know they don’t need to press the Transfer button first but I am unsure if it makes a difference? or could this be the cause here? We have tested the code and pressing the transfer button before the short press option doesn’t make a difference - please correct me if I am wrong)
(one thing I can see might be an issue below is [SP812@from-internal:1]… should I try to get my code to also remove SP in it so it would look like [812@from-internal:1])

[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [SP812@from-internal:1] Set("SIP/805-00009166", "origext=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [SP812@from-internal:2] Set("SIP/805-00009166", "origextname=812 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [SP812@from-internal:3] Set("SIP/805-00009166", "timeoutd=20") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [SP812@from-internal:4] Dial("SIP/805-00009166", "Local/812@from-internal,20,m") in new stack

by the looks of the code - and this is where I need help…
It looks like 812 answered the call from 805 a few seconds later
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] app_dial.c: SIP/812-00009167 answered Local/812@from-internal-00038a8e;2
[2019-10-09 12:01:00] VERBOSE[11611][C-00002df4] app_dial.c: Local/812@from-internal-00038a8e;1 answered SIP/805-00009166
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User

For some reason 812 didn’t get connected to the call, the call didn’t follow the ring back code and sat on hold until they hung up.

I can see 10 seconds later these logs showing 812 and 805 going idle and hangup. This is where I am stuck, I cant work out where the call sent to, and finally is there anything i can enhance my dialplan code with to stop this happening?

[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 811 
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] bridge_channel.c: Channel SIP/805-00009166 left 'simple_bridge' basic-bridge <a9d6a425-6ab7-481c-8ba3-5486ec1b0510>
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 831 
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 830 
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Spawn extension (from-internal, SP812, 4) exited non-zero on 'SIP/805-00009166'
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Executing [h@from-internal:1] Macro("SIP/805-00009166", "hangupcall") in new stack

I shall paste the full call log in the next few minutes.
Thanks

Yeah, we’re going to need to see the full thing. Right now this looks like the Local channel is going to hit the ext-local context (included in from-internal) which will end up doing a Dial(SIP/812). So you have a SIP channel executing a Local channel that in turn executes a SIP channel. The Dial() from the Local channel to SIP/812 is what will be bridged up when 812 answers.

But yeah, need to see the whole verbose call to see how these channels bridge up to each other.

The full log is too big, here is the first section from when 805 starts to transfer the call

[2019-10-09 12:00:57] VERBOSE[11324][C-00002df2] res_musiconhold.c: Started music on hold, class 'clientname', on channel 'Local/805@from-queue-00038a83;2'
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 831 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 830 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 810 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 821 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 812 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 800 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 820 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 813 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 801 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 815 
[2019-10-09 12:00:57] VERBOSE[12601] chan_sip.c: Extension Changed 805[ext-local] new state Hold for Notify User 811 
[2019-10-09 12:00:58] VERBOSE[12669][C-00002df4] netsock2.c: Using SIP RTP TOS bits 184
[2019-10-09 12:00:58] VERBOSE[12669][C-00002df4] netsock2.c: Using SIP RTP CoS mark 5
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [SP812@from-internal:1] Set("SIP/805-00009166", "origext=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [SP812@from-internal:2] Set("SIP/805-00009166", "origextname=812 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [SP812@from-internal:3] Set("SIP/805-00009166", "timeoutd=20") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [SP812@from-internal:4] Dial("SIP/805-00009166", "Local/812@from-internal,20,m") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] app_dial.c: Called Local/812@from-internal
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/805-00009166'
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [812@from-internal:1] GotoIf("Local/812@from-internal-00038a8e;2", "1?ext-local,812,1:followme-check,812,1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (ext-local,812,1)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [812@ext-local:1] Set("Local/812@from-internal-00038a8e;2", "__RINGTIMER=30") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [812@ext-local:2] Macro("Local/812@from-internal-00038a8e;2", "exten-vm,812,812,0,0,0") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:1] Macro("Local/812@from-internal-00038a8e;2", "user-callerid,") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:1] Set("Local/812@from-internal-00038a8e;2", "TOUCH_MONITOR=1570618858.520172") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:2] Set("Local/812@from-internal-00038a8e;2", "AMPUSER=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("Local/812@from-internal-00038a8e;2", "0?report") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("Local/812@from-internal-00038a8e;2", "1?Set(REALCALLERIDNUM=805)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:5] Set("Local/812@from-internal-00038a8e;2", "AMPUSER=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("Local/812@from-internal-00038a8e;2", "0?limit") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:7] Set("Local/812@from-internal-00038a8e;2", "AMPUSERCIDNAME=805 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("Local/812@from-internal-00038a8e;2", "0?report") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:10] Set("Local/812@from-internal-00038a8e;2", "AMPUSERCID=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:11] Set("Local/812@from-internal-00038a8e;2", "__DIAL_OPTIONS=HhTtr") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:12] Set("Local/812@from-internal-00038a8e;2", "CALLERID(all)="805 User Name - Dept" <805>") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("Local/812@from-internal-00038a8e;2", "0?limit") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(GROUP(concurrency_limit)=805)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(CHANNEL(language)=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:16] NoOp("Local/812@from-internal-00038a8e;2", "Macro Depth is 2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("Local/812@from-internal-00038a8e;2", "1?report2:macroerror") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("Local/812@from-internal-00038a8e;2", "0?continue") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("Local/812@from-internal-00038a8e;2", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:20] Set("Local/812@from-internal-00038a8e;2", "__TTL=64") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:21] GotoIf("Local/812@from-internal-00038a8e;2", "1?continue") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:37] Set("Local/812@from-internal-00038a8e;2", "CALLERID(number)=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:38] Set("Local/812@from-internal-00038a8e;2", "CALLERID(name)=805 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("Local/812@from-internal-00038a8e;2", "0?cnum") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:40] Set("Local/812@from-internal-00038a8e;2", "CDR(cnam)=805 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:41] Set("Local/812@from-internal-00038a8e;2", "CDR(cnum)=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:42] Set("Local/812@from-internal-00038a8e;2", "CHANNEL(language)=en_GB") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-user-callerid:43] GosubIf("Local/812@from-internal-00038a8e;2", "0?app-check-classofservce,s,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:2] Set("Local/812@from-internal-00038a8e;2", "RingGroupMethod=none") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:3] Set("Local/812@from-internal-00038a8e;2", "__EXTTOCALL=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:4] Set("Local/812@from-internal-00038a8e;2", "__PICKUPMARK=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:5] Set("Local/812@from-internal-00038a8e;2", "RT=30") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:6] Gosub("Local/812@from-internal-00038a8e;2", "sub-record-check,s,1(exten,812,dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:1] GotoIf("Local/812@from-internal-00038a8e;2", "0?initialized") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:2] Set("Local/812@from-internal-00038a8e;2", "__REC_STATUS=INITIALIZED") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:3] Set("Local/812@from-internal-00038a8e;2", "NOW=1570618858") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:4] Set("Local/812@from-internal-00038a8e;2", "__DAY=09") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:5] Set("Local/812@from-internal-00038a8e;2", "__MONTH=10") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:6] Set("Local/812@from-internal-00038a8e;2", "__YEAR=2019") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:7] Set("Local/812@from-internal-00038a8e;2", "__TIMESTR=20191009-120058") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:8] Set("Local/812@from-internal-00038a8e;2", "__FROMEXTEN=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:9] Set("Local/812@from-internal-00038a8e;2", "__MON_FMT=wav") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:10] NoOp("Local/812@from-internal-00038a8e;2", "Recordings initialized") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:11] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(ARG3=dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:12] Set("Local/812@from-internal-00038a8e;2", "REC_POLICY_MODE_SAVE=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:13] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(REC_STATUS=NO)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:14] GotoIf("Local/812@from-internal-00038a8e;2", "5?checkaction") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-record-check:17] GotoIf("Local/812@from-internal-00038a8e;2", "1?sub-record-check,exten,1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:1] NoOp("Local/812@from-internal-00038a8e;2", "Exten Recording Check between 805 and 812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:2] Set("Local/812@from-internal-00038a8e;2", "CALLTYPE=internal") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:3] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(CALLTYPE=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:4] Set("Local/812@from-internal-00038a8e;2", "CALLEE=dontcare") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:5] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(CALLEE=dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:6] GotoIf("Local/812@from-internal-00038a8e;2", "0?callee") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:7] GotoIf("Local/812@from-internal-00038a8e;2", "1?caller") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:13] Set("Local/812@from-internal-00038a8e;2", "RECMODE=dontcare") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:14] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(RECMODE=dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:15] ExecIf("Local/812@from-internal-00038a8e;2", "1?Set(RECMODE=dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:16] Gosub("Local/812@from-internal-00038a8e;2", "recordcheck,1(dontcare,internal,812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("Local/812@from-internal-00038a8e;2", "Starting recording check against dontcare") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("Local/812@from-internal-00038a8e;2", "dontcare") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [recordcheck@sub-record-check:3] Return("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [exten@sub-record-check:17] Return("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:7] GotoIf("Local/812@from-internal-00038a8e;2", "1?macrodial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-exten-vm,s,13)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:13] GosubIf("Local/812@from-internal-00038a8e;2", "0?clrheader,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-exten-vm:14] Macro("Local/812@from-internal-00038a8e;2", "dial-one,30,HhTtr,812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:1] Set("Local/812@from-internal-00038a8e;2", "DEXTEN=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:2] Set("Local/812@from-internal-00038a8e;2", "__CRM_SOURCE=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:3] UserEvent("Local/812@from-internal-00038a8e;2", "zulu-inbound-call,type:macro-dial-one,from:805,to:812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:4] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(__EXTTOCALL=812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:5] Set("Local/812@from-internal-00038a8e;2", "DIALSTATUS_CW=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:6] GosubIf("Local/812@from-internal-00038a8e;2", "0?screen,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:7] GosubIf("Local/812@from-internal-00038a8e;2", "0?cf,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:8] GotoIf("Local/812@from-internal-00038a8e;2", "1?skip1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-dial-one,s,11)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:11] GotoIf("Local/812@from-internal-00038a8e;2", "0?nodial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:12] GotoIf("Local/812@from-internal-00038a8e;2", "0?continue") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:13] Set("Local/812@from-internal-00038a8e;2", "EXTHASCW=ENABLED") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:14] GotoIf("Local/812@from-internal-00038a8e;2", "0?next1:cwinusebusy") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-dial-one,s,26)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:26] GotoIf("Local/812@from-internal-00038a8e;2", "0?next3:continue") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-dial-one,s,28)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:28] GotoIf("Local/812@from-internal-00038a8e;2", "0?nodial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:29] GosubIf("Local/812@from-internal-00038a8e;2", "1?dstring,1():dlocal,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:1] Set("Local/812@from-internal-00038a8e;2", "DSTRING=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:2] Set("Local/812@from-internal-00038a8e;2", "DEVICES=812&90812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("Local/812@from-internal-00038a8e;2", "0?Return()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(DEVICES=12&90812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:5] Set("Local/812@from-internal-00038a8e;2", "LOOPCNT=2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:6] Set("Local/812@from-internal-00038a8e;2", "ITER=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:7] Set("Local/812@from-internal-00038a8e;2", "THISDIAL=SIP/812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("Local/812@from-internal-00038a8e;2", "1?zap2dahdi,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("Local/812@from-internal-00038a8e;2", "0?Return()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("Local/812@from-internal-00038a8e;2", "NEWDIAL=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("Local/812@from-internal-00038a8e;2", "LOOPCNT2=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("Local/812@from-internal-00038a8e;2", "ITER2=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("Local/812@from-internal-00038a8e;2", "THISPART2=SIP/812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(THISPART2=DAHDI/812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("Local/812@from-internal-00038a8e;2", "NEWDIAL=SIP/812&") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("Local/812@from-internal-00038a8e;2", "ITER2=2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("Local/812@from-internal-00038a8e;2", "0?begin2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("Local/812@from-internal-00038a8e;2", "THISDIAL=SIP/812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("Local/812@from-internal-00038a8e;2", "1?docheck") in new stack

The next set of code showing 812 ringing

[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-dial-one,dstring,15)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:15] GotoIf("Local/812@from-internal-00038a8e;2", "0?skipset") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:16] Set("Local/812@from-internal-00038a8e;2", "DSTRING=SIP/812&") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:17] Set("Local/812@from-internal-00038a8e;2", "ITER=2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:18] GotoIf("Local/812@from-internal-00038a8e;2", "1?begin") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-dial-one,dstring,7)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:7] Set("Local/812@from-internal-00038a8e;2", "THISDIAL=Local/90812@zulu-call") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("Local/812@from-internal-00038a8e;2", "1?zap2dahdi,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("Local/812@from-internal-00038a8e;2", "0?Return()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("Local/812@from-internal-00038a8e;2", "NEWDIAL=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("Local/812@from-internal-00038a8e;2", "LOOPCNT2=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("Local/812@from-internal-00038a8e;2", "ITER2=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("Local/812@from-internal-00038a8e;2", "THISPART2=Local/90812@zulu-call") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(THISPART2=DAHDIal/90812@zulu-call)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("Local/812@from-internal-00038a8e;2", "NEWDIAL=Local/90812@zulu-call&") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("Local/812@from-internal-00038a8e;2", "ITER2=2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("Local/812@from-internal-00038a8e;2", "0?begin2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("Local/812@from-internal-00038a8e;2", "THISDIAL=Local/90812@zulu-call") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("Local/812@from-internal-00038a8e;2", "1?docheck") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-dial-one,dstring,15)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:15] GotoIf("Local/812@from-internal-00038a8e;2", "0?skipset") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:16] Set("Local/812@from-internal-00038a8e;2", "DSTRING=SIP/812&Local/90812@zulu-call&") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:17] Set("Local/812@from-internal-00038a8e;2", "ITER=3") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:18] GotoIf("Local/812@from-internal-00038a8e;2", "0?begin") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:19] ExecIf("Local/812@from-internal-00038a8e;2", "0?Return()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:20] Set("Local/812@from-internal-00038a8e;2", "DSTRING=SIP/812&Local/90812@zulu-call") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [dstring@macro-dial-one:21] Return("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:30] GotoIf("Local/812@from-internal-00038a8e;2", "0?nodial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:31] GotoIf("Local/812@from-internal-00038a8e;2", "0?skiptrace") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:32] GosubIf("Local/812@from-internal-00038a8e;2", "1?ctset,1():ctclear,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [ctset@macro-dial-one:1] Set("Local/812@from-internal-00038a8e;2", "DB(CALLTRACE/812)=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [ctset@macro-dial-one:2] Return("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:33] Set("Local/812@from-internal-00038a8e;2", "D_OPTIONS=HhTtr") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:34] GosubIf("Local/812@from-internal-00038a8e;2", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:35] NoOp("Local/812@from-internal-00038a8e;2", "Blind Transfer: , Attended Transfer: , User: 805, Alert Info: ") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:36] ExecIf("Local/812@from-internal-00038a8e;2", "1?Set(ALERT_INFO=ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:37] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(ALERT_INFO=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:38] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(ALERT_INFO=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:39] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(ALERT_INFO=ring5;volume=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:40] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(ALERT_INFO=ring5;volume=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:41] GosubIf("Local/812@from-internal-00038a8e;2", "1?func-set-sipheader,s,1(Alert-Info,ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-set-sipheader:1] NoOp("Local/812@from-internal-00038a8e;2", "Sip Add Header function called. Adding Alert-Info = ring5") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-set-sipheader:2] Set("Local/812@from-internal-00038a8e;2", "HASH(__SIPHEADERS,Alert-Info)=ring5") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-set-sipheader:3] Return("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:42] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(CHANNEL(musicclass)=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:43] GosubIf("Local/812@from-internal-00038a8e;2", "0?qwait,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:44] Set("Local/812@from-internal-00038a8e;2", "__CWIGNORE=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:45] Set("Local/812@from-internal-00038a8e;2", "__KEEPCID=TRUE") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:46] GotoIf("Local/812@from-internal-00038a8e;2", "0?usegoto,1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:47] GotoIf("Local/812@from-internal-00038a8e;2", "0?godial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:48] Gosub("Local/812@from-internal-00038a8e;2", "sub-presencestate-display,s,1(812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@sub-presencestate-display:1] Goto("Local/812@from-internal-00038a8e;2", "state-not_set,1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (sub-presencestate-display,state-not_set,1)
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [state-not_set@sub-presencestate-display:1] Set("Local/812@from-internal-00038a8e;2", "PRESENCESTATE_DISPLAY=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [state-not_set@sub-presencestate-display:2] Return("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:49] Set("Local/812@from-internal-00038a8e;2", "CONNECTEDLINE(name,i)=812 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:50] Set("Local/812@from-internal-00038a8e;2", "CONNECTEDLINE(num)=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:51] Set("Local/812@from-internal-00038a8e;2", "D_OPTIONS=HhTtrI") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:52] Macro("Local/812@from-internal-00038a8e;2", "dialout-one-predial-hook,") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:53] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(D_OPTIONS=HhtrII)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:54] Set("Local/812@from-internal-00038a8e;2", "__ZULU_TIMEOUT=30") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:55] Set("Local/812@from-internal-00038a8e;2", "__ZULU_FROMEXTEN=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:56] Set("Local/812@from-internal-00038a8e;2", "__ZULU_DIALOPTS=HhTtr") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:57] NoOp("Local/812@from-internal-00038a8e;2", "Finished") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:58] NoOp("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:59] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(D_OPTIONS=HhTtrIg)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-dial-one:60] Dial("Local/812@from-internal-00038a8e;2", "SIP/812&Local/90812@zulu-call,30,HhTtrIb(func-apply-sipheaders^s^1)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] netsock2.c: Using SIP RTP TOS bits 184
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] netsock2.c: Using SIP RTP CoS mark 5
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_stack.c: SIP/812-00009167 Internal Gosub(func-apply-sipheaders,s,1) start
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("SIP/812-00009167", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("SIP/812-00009167", "Applying SIP Headers to channel SIP/812-00009167") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:3] Set("SIP/812-00009167", "TECH=SIP") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:4] Set("SIP/812-00009167", "SIPHEADERKEYS=Alert-Info") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:5] While("SIP/812-00009167", "1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:6] Set("SIP/812-00009167", "sipheader=ring5") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("SIP/812-00009167", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("SIP/812-00009167", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("SIP/812-00009167", "1?Set(sipheader=<http://127.0.0.1>;info=ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("SIP/812-00009167", "1?SIPAddHeader(Alert-Info:<http://127.0.0.1>;info=ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("SIP/812-00009167", "0?Set(PJSIP_HEADER(add,Alert-Info)=<http://127.0.0.1>;info=ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:12] EndWhile("SIP/812-00009167", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:5] While("SIP/812-00009167", "0") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:13] Return("SIP/812-00009167", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_stack.c: Spawn extension (from-internal, 812, 1) exited non-zero on 'SIP/812-00009167'
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_stack.c: SIP/812-00009167 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_stack.c: Local/90812@zulu-call-00038a8f;1 Internal Gosub(func-apply-sipheaders,s,1) start
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("Local/90812@zulu-call-00038a8f;1", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("Local/90812@zulu-call-00038a8f;1", "Applying SIP Headers to channel Local/90812@zulu-call-00038a8f;1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:3] Set("Local/90812@zulu-call-00038a8f;1", "TECH=Local") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:4] Set("Local/90812@zulu-call-00038a8f;1", "SIPHEADERKEYS=Alert-Info") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:5] While("Local/90812@zulu-call-00038a8f;1", "1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:6] Set("Local/90812@zulu-call-00038a8f;1", "sipheader=ring5") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("Local/90812@zulu-call-00038a8f;1", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("Local/90812@zulu-call-00038a8f;1", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("Local/90812@zulu-call-00038a8f;1", "1?Set(sipheader=<http://127.0.0.1>;info=ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("Local/90812@zulu-call-00038a8f;1", "0?SIPAddHeader(Alert-Info:<http://127.0.0.1>;info=ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("Local/90812@zulu-call-00038a8f;1", "0?Set(PJSIP_HEADER(add,Alert-Info)=<http://127.0.0.1>;info=ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:12] EndWhile("Local/90812@zulu-call-00038a8f;1", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:5] While("Local/90812@zulu-call-00038a8f;1", "0") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@func-apply-sipheaders:13] Return("Local/90812@zulu-call-00038a8f;1", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_stack.c: Spawn extension (zulu-call, 812, 1) exited non-zero on 'Local/90812@zulu-call-00038a8f;1'
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_stack.c: Local/90812@zulu-call-00038a8f;1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_dial.c: Called SIP/812
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_dial.c: Called Local/90812@zulu-call
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_dial.c: Connected line update to Local/812@from-internal-00038a8e;2 prevented.
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] app_dial.c: Local/812@from-internal-00038a8e;1 is ringing
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [90812@zulu-call:1] NoOp("Local/90812@zulu-call-00038a8f;2", "Dialing Zulu 90812") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [90812@zulu-call:2] Set("Local/90812@zulu-call-00038a8f;2", "ZULU_EXTTOCALL=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [90812@zulu-call:3] Gosub("Local/90812@zulu-call-00038a8f;2", "zulu-user-settings-map,s,1(812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [s@zulu-user-settings-map:1] GotoIf("Local/90812@zulu-call-00038a8f;2", "0?812,1") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [s@zulu-user-settings-map:2] Return("Local/90812@zulu-call-00038a8f;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [90812@zulu-call:4] Gosub("Local/90812@zulu-call-00038a8f;2", "zulu-send-event,s,1(812,805)") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [s@zulu-send-event:1] GotoIf("Local/90812@zulu-call-00038a8f;2", "1?skippopup") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx_builtins.c: Goto (zulu-send-event,s,4)
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [s@zulu-send-event:4] NoOp("Local/90812@zulu-call-00038a8f;2", "No Call Pop") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [s@zulu-send-event:5] UserEvent("Local/90812@zulu-call-00038a8f;2", "zulu-call,eventtype:calling,extension:812,type:,url:,cnam:QmV2ZXJsZXkgUHJlc3RvbiAtIEFjY291bnRz,cnum:805,lid:1570618858.520170,from:805,to:812}") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [s@zulu-send-event:6] Return("Local/90812@zulu-call-00038a8f;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [90812@zulu-call:5] Dial("Local/90812@zulu-call-00038a8f;2", "Local/90812@zulu-mobile-phone-wait&Local/90812@zulu-mobile-phone-registered&Local/90812@zulu-desktop-phone&Local/90812@zulu-mobile-phone-push,30,HhTtr,") in new stack
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 811 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 831 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 830 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 801 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 800 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 805 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 820 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 813 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 810 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 812 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 821 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 815 
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] app_dial.c: Called Local/90812@zulu-mobile-phone-wait
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] app_dial.c: Called Local/90812@zulu-mobile-phone-registered
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] app_dial.c: Called Local/90812@zulu-desktop-phone
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] app_dial.c: Called Local/90812@zulu-mobile-phone-push
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_dial.c: Local/90812@zulu-call-00038a8f;1 is ringing
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] app_dial.c: Local/812@from-internal-00038a8e;1 is ringing
[2019-10-09 12:00:58] VERBOSE[11614][C-00002df4] pbx.c: Executing [90812@zulu-mobile-phone-wait:1] Stasis("Local/90812@zulu-mobile-phone-wait-00038a90;2", "zulu-mobile-call-wait-processing,30,90,") in new stack
[2019-10-09 12:00:58] VERBOSE[11616][C-00002df4] pbx.c: Executing [90812@zulu-desktop-phone:1] Stasis("Local/90812@zulu-desktop-phone-00038a92;2", "zulu-desktop-call-processing,30,90,") in new stack
[2019-10-09 12:00:58] VERBOSE[11615][C-00002df4] pbx.c: Executing [90812@zulu-mobile-phone-registered:1] Stasis("Local/90812@zulu-mobile-phone-registered-00038a91;2", "zulu-mobile-call-registered-processing,30,90,") in new stack
[2019-10-09 12:00:58] VERBOSE[11617][C-00002df4] pbx.c: Executing [90812@zulu-mobile-phone-push:1] Stasis("Local/90812@zulu-mobile-phone-push-00038a93;2", "zulu-mobile-call-push-processing,1570618858,90,") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_dial.c: SIP/812-00009167 is ringing
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 811 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 831 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 830 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 801 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 800 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 805 (queued)
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 820 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 813 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 810 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 812 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 821 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Ringing for Notify User 815 
[2019-10-09 12:00:58] VERBOSE[11616][C-00002df4] pbx.c: Executing [90812@zulu-desktop-phone:2] GotoIf("Local/90812@zulu-desktop-phone-00038a92;2", "0?connected") in new stack
[2019-10-09 12:00:58] VERBOSE[11616][C-00002df4] pbx.c: Executing [90812@zulu-desktop-phone:3] Hangup("Local/90812@zulu-desktop-phone-00038a92;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11616][C-00002df4] pbx.c: Spawn extension (zulu-desktop-phone, 90812, 3) exited non-zero on 'Local/90812@zulu-desktop-phone-00038a92;2'
[2019-10-09 12:00:58] VERBOSE[11615][C-00002df4] pbx.c: Executing [90812@zulu-mobile-phone-registered:2] GotoIf("Local/90812@zulu-mobile-phone-registered-00038a91;2", "0?connected") in new stack
[2019-10-09 12:00:58] VERBOSE[11615][C-00002df4] pbx.c: Executing [90812@zulu-mobile-phone-registered:3] Hangup("Local/90812@zulu-mobile-phone-registered-00038a91;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11615][C-00002df4] pbx.c: Spawn extension (zulu-mobile-phone-registered, 90812, 3) exited non-zero on 'Local/90812@zulu-mobile-phone-registered-00038a91;2'
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] bridge_channel.c: Channel SIP/813-00009150 left 'simple_bridge' basic-bridge <7a2932de-d2ad-44b1-a6b7-b37fbdcc6c3b>
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] app_macro.c: Spawn extension (macro-dialout-trunk, s, 31) exited non-zero on 'SIP/813-00009150' in macro 'dialout-trunk'
[2019-10-09 12:00:58] VERBOSE[9046][C-00002dea] bridge_channel.c: Channel IAX2/clientname_sbc3-6572 left 'simple_bridge' basic-bridge <7a2932de-d2ad-44b1-a6b7-b37fbdcc6c3b>
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Spawn extension (restrictedroute-98c6f2c2287f4c73cea3d40ae7ec3ff2, 38332238, 6) exited non-zero on 'SIP/813-00009150'
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [h@restrictedroute-98c6f2c2287f4c73cea3d40ae7ec3ff2:1] Hangup("SIP/813-00009150", "") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Spawn extension (restrictedroute-98c6f2c2287f4c73cea3d40ae7ec3ff2, h, 1) exited non-zero on 'SIP/813-00009150'
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] app_stack.c: SIP/813-00009150 Internal Gosub(crm-hangup,s,1) start
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [s@crm-hangup:1] NoOp("SIP/813-00009150", "Sending Hangup to CRM") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [s@crm-hangup:2] NoOp("SIP/813-00009150", "HANGUP CAUSE: 16") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [s@crm-hangup:3] ExecIf("SIP/813-00009150", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2019-10-09 12:00:58] VERBOSE[9046][C-00002dea] chan_iax2.c: Hungup 'IAX2/clientname_sbc3-6572'
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [s@crm-hangup:4] NoOp("SIP/813-00009150", "MASTER CHANNEL: 1570618462.519901 = 1570618462.519901") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [s@crm-hangup:5] GotoIf("SIP/813-00009150", "0?return") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [s@crm-hangup:6] Set("SIP/813-00009150", "__CRM_HANGUP=1") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [s@crm-hangup:7] AGI("SIP/813-00009150", "sangomacrm.agi") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2019-10-09 12:00:58] VERBOSE[11614][C-00002df4] pbx.c: Executing [90812@zulu-mobile-phone-wait:2] GotoIf("Local/90812@zulu-mobile-phone-wait-00038a90;2", "0?connected") in new stack
[2019-10-09 12:00:58] VERBOSE[11614][C-00002df4] pbx.c: Executing [90812@zulu-mobile-phone-wait:3] Hangup("Local/90812@zulu-mobile-phone-wait-00038a90;2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11614][C-00002df4] pbx.c: Spawn extension (zulu-mobile-phone-wait, 90812, 3) exited non-zero on 'Local/90812@zulu-mobile-phone-wait-00038a90;2'

The next bit of code showing 812 answering the call, which never gets connected.
If you need more code let me know.
Thanks

[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: sangomacrm.agi: LINKEDID: 1570618462.519901
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: sangomacrm.agi: SOURCE: 813
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: sangomacrm.agi: DESTINATION: 38383838883
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: sangomacrm.agi: DIRECTION: OUTBOUND
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: sangomacrm.agi: EXTTOCALL: 
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: sangomacrm.agi: START
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: sangomacrm.agi: SCRIPT: php /var/www/html/admin/modules/sangomacrm/importOne.php 'eyJ1dWlkIjoiMTU3MDYxODQ2Mi41MTk5MDEiLCJzb3VyY2UiOiI4MTMiLCJkZXN0aW5hdGlvbiI6IjAyODM4MzMyMjM4IiwiZGlyZWN0aW9uIjoiT1VUQk9VTkQiLCJ0eXBlIjoiRU5EIiwienVsdV9yYXdfdHlwZSI6IiIsInp1bHVfdHlwZSI6IiIsInp1bHVfdXJsIjoiIiwiZXh0dG9jYWxsIjoiIiwiY251bSI6IjAyODM3NTIyOTEyIiwiY25hbSI6IiIsImNhbGxwb3AiOmZhbHNlLCJ2b2ljZW1haWwiOiIifQ==' > /dev/null 2>&1 &
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] res_agi.c: <SIP/813-00009150>AGI Script sangomacrm.agi completed, returning 0
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [s@crm-hangup:8] Return("SIP/813-00009150", "") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] app_stack.c: Spawn extension (restrictedroute-98c6f2c2287f4c73cea3d40ae7ec3ff2, h, 1) exited non-zero on 'SIP/813-00009150'
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] app_stack.c: SIP/813-00009150 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2019-10-09 12:00:58] VERBOSE[8835][C-00002dea] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2019-10-09 12:00:58] VERBOSE[8835][C-00002dea] app_mixmonitor.c: End MixMonitor Recording SIP/813-00009150
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 831 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 830 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 811 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 800 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 815 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 813 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 805 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 821 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 812 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 801 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 820 
[2019-10-09 12:00:58] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state Idle for Notify User 810 
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] app_dial.c: Connected line update to Local/812@from-internal-00038a8e;2 prevented.
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] app_dial.c: SIP/812-00009167 answered Local/812@from-internal-00038a8e;2
[2019-10-09 12:01:00] VERBOSE[11611][C-00002df4] app_dial.c: Local/812@from-internal-00038a8e;1 answered SIP/805-00009166
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 811 
[2019-10-09 12:01:00] VERBOSE[11611][C-00002df4] res_musiconhold.c: Stopped music on hold on SIP/805-00009166
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 831 
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 830 
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 801 
[2019-10-09 12:01:00] VERBOSE[11613][C-00002df4] pbx.c: Spawn extension (zulu-call, 90812, 5) exited non-zero on 'Local/90812@zulu-call-00038a8f;2'
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 800 
[2019-10-09 12:01:00] VERBOSE[11746][C-00002df4] bridge_channel.c: Channel SIP/812-00009167 joined 'simple_bridge' basic-bridge <9d4e1db2-017b-42a4-b20d-c9c02523094e>
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 805 
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] bridge_channel.c: Channel Local/812@from-internal-00038a8e;2 joined 'simple_bridge' basic-bridge <9d4e1db2-017b-42a4-b20d-c9c02523094e>
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 820 
[2019-10-09 12:01:00] VERBOSE[11747][C-00002df4] bridge_channel.c: Channel Local/812@from-internal-00038a8e;1 joined 'simple_bridge' basic-bridge <a9d6a425-6ab7-481c-8ba3-5486ec1b0510>
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 813 
[2019-10-09 12:01:00] VERBOSE[11611][C-00002df4] bridge_channel.c: Channel SIP/805-00009166 joined 'simple_bridge' basic-bridge <a9d6a425-6ab7-481c-8ba3-5486ec1b0510>
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 810 
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 812 
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 821 
[2019-10-09 12:01:00] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state InUse for Notify User 815 
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] bridge_channel.c: Channel SIP/812-00009167 left 'simple_bridge' basic-bridge <9d4e1db2-017b-42a4-b20d-c9c02523094e>
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] bridge_channel.c: Channel Local/812@from-internal-00038a8e;1 left 'simple_bridge' basic-bridge <a9d6a425-6ab7-481c-8ba3-5486ec1b0510>
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] bridge_channel.c: Channel SIP/812-00009167 swapped with Local/812@from-internal-00038a8e;1 into 'simple_bridge' basic-bridge <a9d6a425-6ab7-481c-8ba3-5486ec1b0510>
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] bridge_channel.c: Channel Local/812@from-internal-00038a8e;2 left 'simple_bridge' basic-bridge <9d4e1db2-017b-42a4-b20d-c9c02523094e>
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] app_macro.c: Spawn extension (macro-dial-one, s, 60) exited non-zero on 'Local/812@from-internal-00038a8e;2' in macro 'dial-one'
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] app_macro.c: Spawn extension (macro-exten-vm, s, 14) exited non-zero on 'Local/812@from-internal-00038a8e;2' in macro 'exten-vm'
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Spawn extension (ext-local, 812, 2) exited non-zero on 'Local/812@from-internal-00038a8e;2'
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [h@ext-local:1] Macro("Local/812@from-internal-00038a8e;2", "hangupcall,") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("Local/812@from-internal-00038a8e;2", "1?theend") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("Local/812@from-internal-00038a8e;2", "0?Set(CDR(recordingfile)=)") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-hangupcall:4] NoOp("Local/812@from-internal-00038a8e;2", "Local/90812@zulu-call-00038a8f;1 montior file= ") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-hangupcall:5] GotoIf("Local/812@from-internal-00038a8e;2", "1?skipagi") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx_builtins.c: Goto (macro-hangupcall,s,7)
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [s@macro-hangupcall:7] Hangup("Local/812@from-internal-00038a8e;2", "") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'Local/812@from-internal-00038a8e;2' in macro 'hangupcall'
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'Local/812@from-internal-00038a8e;2'
[2019-10-09 12:01:02] NOTICE[28621] res_pjsip_exten_state.c: Endpoint '921' state subscription failed: Extension '913' does not exist in context 'from-internal' or has no associated hint
[2019-10-09 12:01:10] VERBOSE[11746][C-00002df4] bridge_channel.c: Channel SIP/812-00009167 left 'simple_bridge' basic-bridge <a9d6a425-6ab7-481c-8ba3-5486ec1b0510>
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 811 
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] bridge_channel.c: Channel SIP/805-00009166 left 'simple_bridge' basic-bridge <a9d6a425-6ab7-481c-8ba3-5486ec1b0510>
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 831 
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 830 
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Spawn extension (from-internal, SP812, 4) exited non-zero on 'SIP/805-00009166'
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Executing [h@from-internal:1] Macro("SIP/805-00009166", "hangupcall") in new stack
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 801 
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 800 
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 805 
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/805-00009166", "1?theend") in new stack
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 820 
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/805-00009166", "0?Set(CDR(recordingfile)=)") in new stack
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 813 
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 810 
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 812 
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 821 
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Executing [s@macro-hangupcall:4] NoOp("SIP/805-00009166", "SIP/812-00009167 montior file= ") in new stack
[2019-10-09 12:01:10] VERBOSE[12601] chan_sip.c: Extension Changed 812[ext-local] new state Idle for Notify User 815 
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Executing [s@macro-hangupcall:5] GotoIf("SIP/805-00009166", "1?skipagi") in new stack
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx_builtins.c: Goto (macro-hangupcall,s,7)
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Executing [s@macro-hangupcall:7] Hangup("SIP/805-00009166", "") in new stack
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'SIP/805-00009166' in macro 'hangupcall'
[2019-10-09 12:01:10] VERBOSE[11611][C-00002df4] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/805-00009166'
[2019-10-09 12:01:30] VERBOSE[12669][C-00002df5] netsock2.c: Using SIP RTP TOS bits 184
[2019-10-09 12:01:30] VERBOSE[12669][C-00002df5] netsock2.c: Using SIP RTP CoS mark 5
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [38633521@from-internal:1] Macro("SIP/813-00009168", "user-callerid,LIMIT") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/813-00009168", "TOUCH_MONITOR=1570618890.520184") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/813-00009168", "AMPUSER=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/813-00009168", "0?report") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/813-00009168", "1?Set(REALCALLERIDNUM=813)") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/813-00009168", "AMPUSER=813") in new stack
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 831 
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/813-00009168", "0?limit") in new stack
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 830 
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 811 
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/813-00009168", "AMPUSERCIDNAME=User Name - Dept") in new stack
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 800 
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 815 
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/813-00009168", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 813 
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 805 
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 821 
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 812 
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 801 
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 820 
[2019-10-09 12:01:30] VERBOSE[12601] chan_sip.c: Extension Changed 813[ext-local] new state InUse for Notify User 810 
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/813-00009168", "0?report") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/813-00009168", "AMPUSERCID=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/813-00009168", "__DIAL_OPTIONS=HhTtr") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:12] Set("SIP/813-00009168", "CALLERID(all)="User Name - Dept" <813>") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("SIP/813-00009168", "0?limit") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("SIP/813-00009168", "1?Set(GROUP(concurrency_limit)=813)") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("SIP/813-00009168", "0?Set(CHANNEL(language)=)") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:16] NoOp("SIP/813-00009168", "Macro Depth is 1") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("SIP/813-00009168", "1?report2:macroerror") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/813-00009168", "1?continue") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/813-00009168", "CALLERID(number)=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:38] Set("SIP/813-00009168", "CALLERID(name)=User Name - Dept") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("SIP/813-00009168", "0?cnum") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/813-00009168", "CDR(cnam)=User Name - Dept") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/813-00009168", "CDR(cnum)=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:42] Set("SIP/813-00009168", "CHANNEL(language)=en_GB") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@macro-user-callerid:43] GosubIf("SIP/813-00009168", "0?app-check-classofservce,s,1()") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [38633521@from-internal:2] Set("SIP/813-00009168", "ROUTEUSER=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [38633521@from-internal:3] Set("SIP/813-00009168", "ROUTEUSER=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [38633521@from-internal:4] GotoIf("SIP/813-00009168", "1?notblind") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx_builtins.c: Goto (from-internal,38633521,7)
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [38633521@from-internal:7] GotoIf("SIP/813-00009168", "1?restrictedroute-98c6f2c2287f4c73cea3d40ae7ec3ff2,38633521,2:outbound-allroutes,38633521,2") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx_builtins.c: Goto (restrictedroute-98c6f2c2287f4c73cea3d40ae7ec3ff2,38633521,2)
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [38633521@restrictedroute-98c6f2c2287f4c73cea3d40ae7ec3ff2:2] Gosub("SIP/813-00009168", "sub-record-check,s,1(out,38633521,force)") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/813-00009168", "0?initialized") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:2] Set("SIP/813-00009168", "__REC_STATUS=INITIALIZED") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:3] Set("SIP/813-00009168", "NOW=1570618890") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:4] Set("SIP/813-00009168", "__DAY=09") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:5] Set("SIP/813-00009168", "__MONTH=10") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:6] Set("SIP/813-00009168", "__YEAR=2019") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:7] Set("SIP/813-00009168", "__TIMESTR=20191009-120130") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:8] Set("SIP/813-00009168", "__FROMEXTEN=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:9] Set("SIP/813-00009168", "__MON_FMT=wav") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/813-00009168", "Recordings initialized") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/813-00009168", "0?Set(ARG3=dontcare)") in new stack

Hi Tom,
Thanks for you reply, sounds like I have only dipped my toe in the asterisk dial plan ocean. Hopefully the logs below can help figure out the problem.

D

Hi Tom,
by your comments, do you think I should dial using SIP/ instead of Local/
The /Local was originally in another posts RingBack code which I just copied.
Thanks
David

By hitting the transfer button, then a BLF button (which acts as a speed dial), 805 initiated an attended transfer. During the time 805 and 812 were connected, did they talk to each other? This is the part of the attended transfer where 805 tells 812 “I have a call for you” and then presses the transfer button again to finish it.

If that didn’t happen, the caller remained on hold. I think this is what happened and it doesn’t really have anything to do with your custom dial plan. If I understand you right, you’re wanting to do a blind transfer to 812 via the “short press” SP dialplan. Probably hitting the BLF directly while talking to the caller, or going through the attended transfer routine (transfer - BLF - transfer softkey) would work.

Just taking a stab at it, as it’s hard to follow without seeing it in action.

Hi,
The client requested no blind transfers, they only want attended transfers, but sometimes rather than extension 1 waiting for extension 2 to answer, they just hang up their side to send the call directly extension 2.
If extension 2 doesnt pick up the call with a time out of 20 seconds, it needs to RingBack to Extension 2 and Extension 1 at the same time for 90 seconds, and if still unanswered end up and extension 2 unavailable mailbox.

For some reason this process is working great by my dial plan for 99% of calls, the client has a few calls each day similar to this call log, where a call doesnt transfer, but disappears somewhere and the caller sits listening to moh for 5 minutes before hanging up.

I am trying to figure out what the users are doing to make to call disappear, and then put something in the system to help stop this from happening.

Thanks for helping

Recommend you figure out how to reproduce it on a system under your control, and when the call ends up in this on-hold/stuck state, you can see on the console what happened more clearly. You can also examine the state by looking at active channels, etc.

Thanks, will do,
upon further investigation it looks like the extensions must have spoken to each other

[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] app_dial.c: SIP/812-00009167 answered Local/812@from-internal-00038a8e;2
[2019-10-09 12:01:00] VERBOSE[11611][C-00002df4] app_dial.c: Local/812@from-internal-00038a8e;1 answered SIP/805-00009166

I shall try to reproduce the scenario and see what the system says, thanks for the help,
D

We suspect extension 805 is putting the call on hold before pressing the BLF 812 button.
Then leaving the phone thinking it has been transferred.
We are turning on Hold Tone in EPM to see if that flags up to the end user if they leave a call on hold.
edit - first tests of Hold Tone doesnt seem to do anything. Will look further into it next week.
D

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.