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 [[email protected]: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 [[email protected]: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/[email protected];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/[email protected];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 [[email protected]:1]… should I try to get my code to also remove SP in it so it would look like [[email protected]:1])

[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [[email protected]:1] Set("SIP/805-00009166", "origext=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [[email protected]: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 [[email protected]:3] Set("SIP/805-00009166", "timeoutd=20") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [[email protected]:4] Dial("SIP/805-00009166", "Local/[email protected],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/[email protected];2
[2019-10-09 12:01:00] VERBOSE[11611][C-00002df4] app_dial.c: Local/[email protected];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 [[email protected]: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/[email protected];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 [[email protected]:1] Set("SIP/805-00009166", "origext=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [[email protected]: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 [[email protected]:3] Set("SIP/805-00009166", "timeoutd=20") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] pbx.c: Executing [[email protected]:4] Dial("SIP/805-00009166", "Local/[email protected],20,m") in new stack
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] app_dial.c: Called Local/[email protected]
[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 [[email protected]:1] GotoIf("Local/[email protected];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 [[email protected]:1] Set("Local/[email protected];2", "__RINGTIMER=30") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Macro("Local/[email protected];2", "exten-vm,812,812,0,0,0") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] Macro("Local/[email protected];2", "user-callerid,") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] Set("Local/[email protected];2", "TOUCH_MONITOR=1570618858.520172") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "AMPUSER=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] GotoIf("Local/[email protected];2", "0?report") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] ExecIf("Local/[email protected];2", "1?Set(REALCALLERIDNUM=805)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] Set("Local/[email protected];2", "AMPUSER=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] GotoIf("Local/[email protected];2", "0?limit") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] Set("Local/[email protected];2", "AMPUSERCIDNAME=805 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:8] ExecIf("Local/[email protected];2", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?report") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:10] Set("Local/[email protected];2", "AMPUSERCID=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:11] Set("Local/[email protected];2", "__DIAL_OPTIONS=HhTtr") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:12] Set("Local/[email protected];2", "CALLERID(all)="805 User Name - Dept" <805>") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:13] GotoIf("Local/[email protected];2", "0?limit") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:14] ExecIf("Local/[email protected];2", "0?Set(GROUP(concurrency_limit)=805)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:15] ExecIf("Local/[email protected];2", "0?Set(CHANNEL(language)=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:16] NoOp("Local/[email protected];2", "Macro Depth is 2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:17] GotoIf("Local/[email protected];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 [[email protected]:18] GotoIf("Local/[email protected];2", "0?continue") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:19] ExecIf("Local/[email protected];2", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:20] Set("Local/[email protected];2", "__TTL=64") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:21] GotoIf("Local/[email protected];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 [[email protected]:37] Set("Local/[email protected];2", "CALLERID(number)=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:38] Set("Local/[email protected];2", "CALLERID(name)=805 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:39] GotoIf("Local/[email protected];2", "0?cnum") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:40] Set("Local/[email protected];2", "CDR(cnam)=805 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:41] Set("Local/[email protected];2", "CDR(cnum)=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:42] Set("Local/[email protected];2", "CHANNEL(language)=en_GB") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:43] GosubIf("Local/[email protected];2", "0?app-check-classofservce,s,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "RingGroupMethod=none") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] Set("Local/[email protected];2", "__EXTTOCALL=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] Set("Local/[email protected];2", "__PICKUPMARK=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] Set("Local/[email protected];2", "RT=30") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] Gosub("Local/[email protected];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 [[email protected]:1] GotoIf("Local/[email protected];2", "0?initialized") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "__REC_STATUS=INITIALIZED") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] Set("Local/[email protected]nternal-00038a8e;2", "NOW=1570618858") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] Set("Local/[email protected];2", "__DAY=09") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] Set("Local/[email protected];2", "__MONTH=10") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] Set("Local/[email protected];2", "__YEAR=2019") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] Set("Local/[email protected];2", "__TIMESTR=20191009-120058") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:8] Set("Local/[email protected];2", "__FROMEXTEN=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:9] Set("Local/[email protected];2", "__MON_FMT=wav") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:10] NoOp("Local/[email protected];2", "Recordings initialized") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:11] ExecIf("Local/[email protected];2", "0?Set(ARG3=dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:12] Set("Local/[email protected];2", "REC_POLICY_MODE_SAVE=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:13] ExecIf("Local/[email protected];2", "0?Set(REC_STATUS=NO)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:14] GotoIf("Local/[email protected];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 [[email protected]:17] GotoIf("Local/[email protected];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 [[email protected]:1] NoOp("Local/[email protected];2", "Exten Recording Check between 805 and 812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "CALLTYPE=internal") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] ExecIf("Local/[email protected];2", "0?Set(CALLTYPE=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] Set("Local/[email protected];2", "CALLEE=dontcare") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] ExecIf("Local/[email protected];2", "0?Set(CALLEE=dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] GotoIf("Local/[email protected];2", "0?callee") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] GotoIf("Local/[email protected];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 [[email protected]:13] Set("Local/[email protected];2", "RECMODE=dontcare") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:14] ExecIf("Local/[email protected];2", "0?Set(RECMODE=dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:15] ExecIf("Local/[email protected];2", "1?Set(RECMODE=dontcare)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:16] Gosub("Local/[email protected];2", "recordcheck,1(dontcare,internal,812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] NoOp("Local/[email protected];2", "Starting recording check against dontcare") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Goto("Local/[email protected];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 [[email protected]:3] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:17] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] GotoIf("Local/[email protected];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 [[email protected]:13] GosubIf("Local/[email protected];2", "0?clrheader,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:14] Macro("Local/[email protected];2", "dial-one,30,HhTtr,812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] Set("Local/[email protected];2", "DEXTEN=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "__CRM_SOURCE=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] UserEvent("Local/[email protected];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 [[email protected]:4] ExecIf("Local/[email protected];2", "0?Set(__EXTTOCALL=812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] Set("Local/[email protected];2", "DIALSTATUS_CW=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] GosubIf("Local/[email protected];2", "0?screen,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] GosubIf("Local/[email protected];2", "0?cf,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:8] GotoIf("Local/[email protected];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 [[email protected]:11] GotoIf("Local/[email protected];2", "0?nodial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:12] GotoIf("Local/[email protected];2", "0?continue") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:13] Set("Local/[email protected];2", "EXTHASCW=ENABLED") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:14] GotoIf("Local/[email protected];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 [[email protected]:26] GotoIf("Local/[email protected];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 [[email protected]:28] GotoIf("Local/[email protected];2", "0?nodial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:29] GosubIf("Local/[email protected];2", "1?dstring,1():dlocal,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] Set("Local/[email protected];2", "DSTRING=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "DEVICES=812&90812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] ExecIf("Local/[email protected];2", "0?Return()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] ExecIf("Local/[email protected];2", "0?Set(DEVICES=12&90812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] Set("Local/[email protected];2", "LOOPCNT=2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] Set("Local/[email protected];2", "ITER=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] Set("Local/[email protected];2", "THISDIAL=SIP/812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:8] GosubIf("Local/[email protected];2", "1?zap2dahdi,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] ExecIf("Local/[email protected];2", "0?Return()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "NEWDIAL=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] Set("Local/[email protected];2", "LOOPCNT2=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] Set("Local/[email protected];2", "ITER2=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] Set("Local/[email protected];2", "THISPART2=SIP/812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] ExecIf("Local/[email protected];2", "0?Set(THISPART2=DAHDI/812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] Set("Local/[email protected];2", "NEWDIAL=SIP/812&") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:8] Set("Local/[email protected];2", "ITER2=2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?begin2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:10] Set("Local/[email protected];2", "THISDIAL=SIP/812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:11] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:9] GotoIf("Local/[email protected];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 [[email protected]:15] GotoIf("Local/[email protected];2", "0?skipset") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:16] Set("Local/[email protected];2", "DSTRING=SIP/812&") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:17] Set("Local/[email protected];2", "ITER=2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:18] GotoIf("Local/[email protected];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 [[email protected]:7] Set("Local/[email protected];2", "THISDIAL=Local/[email protected]") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:8] GosubIf("Local/[email protected];2", "1?zap2dahdi,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] ExecIf("Local/[email protected];2", "0?Return()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "NEWDIAL=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] Set("Local/[email protected];2", "LOOPCNT2=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] Set("Local/[email protected];2", "ITER2=1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] Set("Local/[email protected];2", "THISPART2=Local/[email protected]") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] ExecIf("Local/[email protected];2", "0?Set(THISPART2=DAHDIal/[email protected])") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] Set("Local/[email protected];2", "NEWDIAL=Local/[email protected]&") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:8] Set("Local/[email protected];2", "ITER2=2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:9] GotoIf("Local/[email protected];2", "0?begin2") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:10] Set("Local/[email protected];2", "THISDIAL=Local/[email protected]") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:11] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:9] GotoIf("Local/[email protected];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 [[email protected]:15] GotoIf("Local/[email protected];2", "0?skipset") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:16] Set("Local/[email protected];2", "DSTRING=SIP/812&Local/[email protected]&") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:17] Set("Local/[email protected];2", "ITER=3") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:18] GotoIf("Local/[email protected];2", "0?begin") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:19] ExecIf("Local/[email protected];2", "0?Return()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:20] Set("Local/[email protected];2", "DSTRING=SIP/812&Local/[email protected]") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:21] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:30] GotoIf("Local/[email protected];2", "0?nodial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:31] GotoIf("Local/[email protected];2", "0?skiptrace") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:32] GosubIf("Local/[email protected];2", "1?ctset,1():ctclear,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] Set("Local/[email protected];2", "DB(CALLTRACE/812)=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:33] Set("Local/[email protected];2", "D_OPTIONS=HhTtr") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:34] GosubIf("Local/[email protected];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 [[email protected]:35] NoOp("Local/[email protected];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 [[email protected]:36] ExecIf("Local/[email protected];2", "1?Set(ALERT_INFO=ring5)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:37] ExecIf("Local/[email protected];2", "0?Set(ALERT_INFO=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:38] ExecIf("Local/[email protected];2", "0?Set(ALERT_INFO=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:39] ExecIf("Local/[email protected]-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 [[email protected]:40] ExecIf("Local/[email protected];2", "0?Set(ALERT_INFO=ring5;volume=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:41] GosubIf("Local/[email protected];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 [[email protected]:1] NoOp("Local/[email protected];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 [[email protected]:2] Set("Local/[email protected];2", "HASH(__SIPHEADERS,Alert-Info)=ring5") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:42] ExecIf("Local/[email protected];2", "0?Set(CHANNEL(musicclass)=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:43] GosubIf("Local/[email protected];2", "0?qwait,1()") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:44] Set("Local/[email protected];2", "__CWIGNORE=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:45] Set("Local/[email protected];2", "__KEEPCID=TRUE") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:46] GotoIf("Local/[email protected];2", "0?usegoto,1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:47] GotoIf("Local/[email protected];2", "0?godial") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:48] Gosub("Local/[email protected];2", "sub-presencestate-display,s,1(812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] Goto("Local/[email protected];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 [[email protected]:1] Set("Local/[email protected];2", "PRESENCESTATE_DISPLAY=") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:2] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:49] Set("Local/[email protected];2", "CONNECTEDLINE(name,i)=812 User Name - Dept") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:50] Set("Local/[email protected];2", "CONNECTEDLINE(num)=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:51] Set("Local/[email protected];2", "D_OPTIONS=HhTtrI") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:52] Macro("Local/[email protected];2", "dialout-one-predial-hook,") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] MacroExit("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:53] ExecIf("Local/[email protected];2", "0?Set(D_OPTIONS=HhtrII)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:54] Set("Local/[email protected];2", "__ZULU_TIMEOUT=30") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:55] Set("Local/[email protected];2", "__ZULU_FROMEXTEN=805") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:56] Set("Local/[email protected];2", "__ZULU_DIALOPTS=HhTtr") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:57] NoOp("Local/[email protected];2", "Finished") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:58] NoOp("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:59] ExecIf("Local/[email protected];2", "0?Set(D_OPTIONS=HhTtrIg)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:60] Dial("Local/[email protected];2", "SIP/812&Local/[email protected],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 [[email protected]: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 [[email protected]: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 [[email protected]:3] Set("SIP/812-00009167", "TECH=SIP") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] Set("SIP/812-00009167", "SIPHEADERKEYS=Alert-Info") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] While("SIP/812-00009167", "1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] Set("SIP/812-00009167", "sipheader=ring5") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:12] EndWhile("SIP/812-00009167", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] While("SIP/812-00009167", "0") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]: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/[email protected];1 Internal Gosub(func-apply-sipheaders,s,1) start
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] ExecIf("Local/[email protected];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 [[email protected]:2] NoOp("Local/[email protected];1", "Applying SIP Headers to channel Local/[email protected];1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:3] Set("Local/[email protected];1", "TECH=Local") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] Set("Local/[email protected];1", "SIPHEADERKEYS=Alert-Info") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] While("Local/[email protected];1", "1") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:6] Set("Local/[email protected];1", "sipheader=ring5") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:7] ExecIf("Local/[email protected];1", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:8] ExecIf("Local/[email protected];1", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:9] ExecIf("Local/[email protected];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 [[email protected]:10] ExecIf("Local/[email protected];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 [[email protected]:11] ExecIf("Local/[email protected];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 [[email protected]:12] EndWhile("Local/[email protected];1", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] While("Local/[email protected];1", "0") in new stack
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:13] Return("Local/[email protected];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/[email protected];1'
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_stack.c: Local/[email protected];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/[email protected]
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_dial.c: Connected line update to Local/[email protected];2 prevented.
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] app_dial.c: Local/[email protected];1 is ringing
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:1] NoOp("Local/[email protected];2", "Dialing Zulu 90812") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:2] Set("Local/[email protected];2", "ZULU_EXTTOCALL=812") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:3] Gosub("Local/[email protected];2", "zulu-user-settings-map,s,1(812)") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:1] GotoIf("Local/[email protected];2", "0?812,1") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:2] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:4] Gosub("Local/9[email protected];2", "zulu-send-event,s,1(812,805)") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:1] GotoIf("Local/[email protected];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 [[email protected]:4] NoOp("Local/[email protected];2", "No Call Pop") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:5] UserEvent("Local/[email protected];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 [[email protected]:6] Return("Local/[email protected];2", "") in new stack
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] pbx.c: Executing [[email protected]:5] Dial("Local/[email protected];2", "Local/[email protected]&Local/[email protected]&Local/[email protected]&Local/[email protected],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/[email protected]
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] app_dial.c: Called Local/[email protected]
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] app_dial.c: Called Local/[email protected]
[2019-10-09 12:00:58] VERBOSE[11613][C-00002df4] app_dial.c: Called Local/[email protected]
[2019-10-09 12:00:58] VERBOSE[11612][C-00002df4] app_dial.c: Local/[email protected];1 is ringing
[2019-10-09 12:00:58] VERBOSE[11611][C-00002df4] app_dial.c: Local/[email protected];1 is ringing
[2019-10-09 12:00:58] VERBOSE[11614][C-00002df4] pbx.c: Executing [[email protected]:1] Stasis("Local/[email protected];2", "zulu-mobile-call-wait-processing,30,90,") in new stack
[2019-10-09 12:00:58] VERBOSE[11616][C-00002df4] pbx.c: Executing [[email protected]:1] Stasis("Local/[email protected];2", "zulu-desktop-call-processing,30,90,") in new stack
[2019-10-09 12:00:58] VERBOSE[11615][C-00002df4] pbx.c: Executing [[email protected]:1] Stasis("Local/[email protected];2", "zulu-mobile-call-registered-processing,30,90,") in new stack
[2019-10-09 12:00:58] VERBOSE[11617][C-00002df4] pbx.c: Executing [[email protected]:1] Stasis("Local/[email protected];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 [[email protected]:2] GotoIf("Local/[email protected];2", "0?connected") in new stack
[2019-10-09 12:00:58] VERBOSE[11616][C-00002df4] pbx.c: Executing [[email protected]:3] Hangup("Local/[email protected];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/[email protected];2'
[2019-10-09 12:00:58] VERBOSE[11615][C-00002df4] pbx.c: Executing [[email protected]:2] GotoIf("Local/[email protected];2", "0?connected") in new stack
[2019-10-09 12:00:58] VERBOSE[11615][C-00002df4] pbx.c: Executing [[email protected]:3] Hangup("Local/[email protected];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/[email protected];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 [[email protected]: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 [[email protected]: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 [[email protected]:2] NoOp("SIP/813-00009150", "HANGUP CAUSE: 16") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:5] GotoIf("SIP/813-00009150", "0?return") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [[email protected]:6] Set("SIP/813-00009150", "__CRM_HANGUP=1") in new stack
[2019-10-09 12:00:58] VERBOSE[8827][C-00002dea] pbx.c: Executing [[email protected]: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 [[email protected]:2] GotoIf("Local/[email protected];2", "0?connected") in new stack
[2019-10-09 12:00:58] VERBOSE[11614][C-00002df4] pbx.c: Executing [[email protected]:3] Hangup("Local/[email protected];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/[email protected];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 [[email protected]: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/[email protected];2 prevented.
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] app_dial.c: SIP/812-00009167 answered Local/[email protected];2
[2019-10-09 12:01:00] VERBOSE[11611][C-00002df4] app_dial.c: Local/[email protected];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/[email protected];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/[email protected];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/[email protected];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/[email protected];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/[email protected];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/[email protected];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/[email protected];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/[email protected];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/[email protected];2'
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] Macro("Local/[email protected];2", "hangupcall,") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:1] GotoIf("Local/[email protected];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 [[email protected]:3] ExecIf("Local/[email protected];2", "0?Set(CDR(recordingfile)=)") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:4] NoOp("Local/[email protected];2", "Local/[email protected];1 montior file= ") in new stack
[2019-10-09 12:01:00] VERBOSE[11612][C-00002df4] pbx.c: Executing [[email protected]:5] GotoIf("Local/[email protected];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 [[email protected]:7] Hangup("Local/[email protected];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/[email protected];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/[email protected];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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:1] Macro("SIP/813-00009168", "user-callerid,LIMIT") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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 [[email protected]:2] Set("SIP/813-00009168", "AMPUSER=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:3] GotoIf("SIP/813-00009168", "0?report") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:9] GotoIf("SIP/813-00009168", "0?report") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:10] Set("SIP/813-00009168", "AMPUSERCID=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:11] Set("SIP/813-00009168", "__DIAL_OPTIONS=HhTtr") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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 [[email protected]:13] GotoIf("SIP/813-00009168", "0?limit") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:37] Set("SIP/813-00009168", "CALLERID(number)=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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 [[email protected]:39] GotoIf("SIP/813-00009168", "0?cnum") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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 [[email protected]:41] Set("SIP/813-00009168", "CDR(cnum)=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]:2] Set("SIP/813-00009168", "ROUTEUSER=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:3] Set("SIP/813-00009168", "ROUTEUSER=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:1] GotoIf("SIP/813-00009168", "0?initialized") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:2] Set("SIP/813-00009168", "__REC_STATUS=INITIALIZED") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:3] Set("SIP/813-00009168", "NOW=1570618890") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:4] Set("SIP/813-00009168", "__DAY=09") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:5] Set("SIP/813-00009168", "__MONTH=10") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:6] Set("SIP/813-00009168", "__YEAR=2019") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:7] Set("SIP/813-00009168", "__TIMESTR=20191009-120130") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:8] Set("SIP/813-00009168", "__FROMEXTEN=813") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:9] Set("SIP/813-00009168", "__MON_FMT=wav") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]:10] NoOp("SIP/813-00009168", "Recordings initialized") in new stack
[2019-10-09 12:01:30] VERBOSE[11941][C-00002df5] pbx.c: Executing [[email protected]: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/[email protected];2
[2019-10-09 12:01:00] VERBOSE[11611][C-00002df4] app_dial.c: Local/[email protected];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.