Dial strategies firstavailable, firstnotonphone not working correctly in FreePBX13

I have a fresh installation of FreePBX 13 (Distro version 10.x) in which the firstavailable and firstnotonphone are not working correctly for Ring Groups. The system builds a list of the correct extensions in the group, but only tests the very first one. If that line is busy, the whole dial strategy falls through to the next Ring Group. My understanding, and the way that it worked on my old FreePBX installation (Distro version 5.x), is that it should test each line in order, and ring the first that is available/not on the phone, and only fall through if EVERY line reports busy. At the bottom of my post is the full result of ‘asterisk -vvvvvr’ when trying to dial the group (and hanging up after letting it ring once, because it is ringing all the extensions after falling through to the next ring group). The parts that seem relevant are as follows:

The system appears to recognize the ring methodology:

[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Methodology of ring is 'firstavailable'

It pulls the right list of extensions:

[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Filtered ARG3: 1000-1028-1034-1047-1011-1015

But then when it starts to loop through them, it pulls the wrong count for the extensions:

[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:22] NoOp("SIP/1007-00000126", "Returned from dialparties with hunt groups to dial") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:23] Set("SIP/1007-00000126", "HuntLoop=0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:24] ExecIf("SIP/1007-00000126", "0?Set(HuntMembers=0)") in new stack

… at which point it tests the first line and then falls through the loop.

[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:46] Set("SIP/1007-00000126", "HuntMembers=0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:47] Set("SIP/1007-00000126", "HuntMembers=-1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:48] Goto("SIP/1007-00000126", "s,a22") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (macro-dial,s,25)

Is this a bug or a configuration issue I can fix somehow?

Full Output:

[2016-08-23 14:53:18] VERBOSE[4929] asterisk.c: Remote UNIX connection
[2016-08-23 14:53:21] VERBOSE[4998][C-0000008c] netsock2.c: Using SIP RTP CoS mark 5
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] Macro("SIP/1007-00000126", "user-callerid,") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] Set("SIP/1007-00000126", "TOUCH_MONITOR=1471964001.532") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:2] Set("SIP/1007-00000126", "AMPUSER=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:3] GotoIf("SIP/1007-00000126", "0?report") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:4] ExecIf("SIP/1007-00000126", "1?Set(REALCALLERIDNUM=1007)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:5] Set("SIP/1007-00000126", "AMPUSER=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:6] GotoIf("SIP/1007-00000126", "0?limit") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:7] Set("SIP/1007-00000126", "AMPUSERCIDNAME=Phil Ozlin") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:8] GotoIf("SIP/1007-00000126", "0?report") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:9] Set("SIP/1007-00000126", "AMPUSERCID=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:10] Set("SIP/1007-00000126", "__DIAL_OPTIONS=Ttr") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:11] Set("SIP/1007-00000126", "CALLERID(all)="Phil Ozlin" <1007>") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:12] GotoIf("SIP/1007-00000126", "0?limit") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:13] ExecIf("SIP/1007-00000126", "0?Set(GROUP(concurrency_limit)=1007)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:14] ExecIf("SIP/1007-00000126", "0?Set(CHANNEL(language)=)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:15] GotoIf("SIP/1007-00000126", "0?continue") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:16] ExecIf("SIP/1007-00000126", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:17] Set("SIP/1007-00000126", "__TTL=64") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:18] GotoIf("SIP/1007-00000126", "1?continue") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:29] Set("SIP/1007-00000126", "CALLERID(number)=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:30] Set("SIP/1007-00000126", "CALLERID(name)=Phil Ozlin") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:31] Set("SIP/1007-00000126", "CDR(cnum)=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:32] Set("SIP/1007-00000126", "CDR(cnam)=Phil Ozlin") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:33] Set("SIP/1007-00000126", "CHANNEL(language)=en") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:2] Macro("SIP/1007-00000126", "blkvm-setifempty,") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] GotoIf("SIP/1007-00000126", "1?init") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (macro-blkvm-setifempty,s,4)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:4] Set("SIP/1007-00000126", "__BLKVM_CHANNEL=SIP/1007-00000126") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:5] Set("SIP/1007-00000126", "SHARED(BLKVM,SIP/1007-00000126)=TRUE") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:6] Set("SIP/1007-00000126", "GOSUB_RETVAL=TRUE") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:7] MacroExit("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:3] GotoIf("SIP/1007-00000126", "1?skipov") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (from-internal,1900,6)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:6] Set("SIP/1007-00000126", "RRNODEST=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:7] Set("SIP/1007-00000126", "__NODEST=1900") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:8] GosubIf("SIP/1007-00000126", "0?sub-rgsetcid,s,1()") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:9] Gosub("SIP/1007-00000126", "sub-record-check,s,1(rg,1900,dontcare)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] GotoIf("SIP/1007-00000126", "0?initialized") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:2] Set("SIP/1007-00000126", "__REC_STATUS=INITIALIZED") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:3] Set("SIP/1007-00000126", "NOW=1471964001") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:4] Set("SIP/1007-00000126", "__DAY=23") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:5] Set("SIP/1007-00000126", "__MONTH=08") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:6] Set("SIP/1007-00000126", "__YEAR=2016") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:7] Set("SIP/1007-00000126", "__TIMESTR=20160823-145321") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:8] Set("SIP/1007-00000126", "__FROMEXTEN=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:9] Set("SIP/1007-00000126", "__MON_FMT=wav") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:10] NoOp("SIP/1007-00000126", "Recordings initialized") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:11] ExecIf("SIP/1007-00000126", "0?Set(ARG3=dontcare)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:12] Set("SIP/1007-00000126", "REC_POLICY_MODE_SAVE=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:13] ExecIf("SIP/1007-00000126", "0?Set(REC_STATUS=NO)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:14] GotoIf("SIP/1007-00000126", "2?checkaction") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (sub-record-check,s,17)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:17] GotoIf("SIP/1007-00000126", "0?sub-record-check,rg,1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:18] NoOp("SIP/1007-00000126", "Generic rg Recording Check - 1007 1900") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:19] Gosub("SIP/1007-00000126", "recordcheck,1(dontcare,rg,1900)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] NoOp("SIP/1007-00000126", "Starting recording check against dontcare") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:2] Goto("SIP/1007-00000126", "dontcare") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:3] Return("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:20] Return("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:10] Set("SIP/1007-00000126", "RingGroupMethod=firstavailable") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:11] Macro("SIP/1007-00000126", "dial,20,Ttr,1000-1028-1034-1047-1011-1015") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] NoOp("SIP/1007-00000126", "Blind Transfer: , Attended Transfer: , User: 1007, Alert Info: ") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:2] ExecIf("SIP/1007-00000126", "1?Set(ALERT_INFO=)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:3] ExecIf("SIP/1007-00000126", "0?Set(ALERT_INFO=)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]dial:4] ExecIf("SIP/1007-00000126", "0?Set(ALERT_INFO=)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:5] ExecIf("SIP/1007-00000126", "0?Set(CHANNEL(musicclass)=)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:6] AGI("SIP/1007-00000126", "dialparties.agi") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Caller ID name is 'Phil Ozlin' number is '1007'
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Methodology of ring is 'firstavailable'
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Added extension 1000 to extension map
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Added extension 1028 to extension map
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Added extension 1034 to extension map
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Added extension 1047 to extension map
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Added extension 1011 to extension map
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Added extension 1015 to extension map
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1000 cf is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1028 cf is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1034 cf is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1047 cf is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1011 cf is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1015 cf is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1000 do not disturb is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1028 do not disturb is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1034 do not disturb is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1047 do not disturb is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1011 do not disturb is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1015 do not disturb is disabled
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1000 has ExtensionState: 0
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1028 has ExtensionState: 0
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1034 has ExtensionState: 0
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1047 has ExtensionState: 0
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1011 has ExtensionState: 0
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Extension 1015 has ExtensionState: 0
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: dialparties.agi: Filtered ARG3: 1000-1028-1034-1047-1011-1015
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] res_agi.c: <SIP/1007-00000126>AGI Script dialparties.agi completed, returning 0
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:22] NoOp("SIP/1007-00000126", "Returned from dialparties with hunt groups to dial") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:23] Set("SIP/1007-00000126", "HuntLoop=0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:24] ExecIf("SIP/1007-00000126", "0?Set(HuntMembers=0)") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:25] GotoIf("SIP/1007-00000126", "1?a30") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (macro-dial,s,28)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:28] Set("SIP/1007-00000126", "HuntMember=HuntMember0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:29] GotoIf("SIP/1007-00000126", "1?a32:a35") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (macro-dial,s,30)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:30] Set("SIP/1007-00000126", "CT_EXTEN=1000") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:31] Set("SIP/1007-00000126", "DB(CALLTRACE/1000)=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:32] Goto("SIP/1007-00000126", "s,huntstart") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (macro-dial,s,40)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:40] NoOp("SIP/1007-00000126", "Hunt Dial Start") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:41] Macro("SIP/1007-00000126", "dial-hunt-predial-hook,") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] MacroExit("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:42] Dial("SIP/1007-00000126", "SIP/1000,20,TtrM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] netsock2.c: Using SIP RTP CoS mark 5
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] app_stack.c: SIP/1000-00000127 Internal Gosub(func-apply-sipheaders,s,1) start
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] NoOp("SIP/1000-00000127", "Applying SIP Headers to channel") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:2] Set("SIP/1000-00000127", "SIPHEADERKEYS=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:3] While("SIP/1000-00000127", "0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] app_while.c: Jumping to priority 7
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:8] Return("SIP/1000-00000127", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] app_stack.c: Spawn extension (from-internal, 1900, 1) exited non-zero on 'SIP/1000-00000127'
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] app_stack.c: SIP/1000-00000127 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] app_dial.c: Called SIP/1000
[2016-08-23 14:53:21] VERBOSE[4998][C-0000008c] chan_sip.c: Got SIP response 486 "Busy Here" back from 10.11.5.2:5060
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] app_dial.c: SIP/1000-00000127 is busy
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] app_dial.c: Everyone is busy/congested at this time (1:1/0/0)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:43] GotoIf("SIP/1007-00000126", "0?ANSWER,1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:44] Set("SIP/1007-00000126", "HuntLoop=1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:45] GotoIf("SIP/1007-00000126", "0?a46") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:46] Set("SIP/1007-00000126", "HuntMembers=0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:47] Set("SIP/1007-00000126", "HuntMembers=-1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:48] Goto("SIP/1007-00000126", "s,a22") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (macro-dial,s,25)
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:25] GotoIf("SIP/1007-00000126", "0?a30") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:26] NoOp("SIP/1007-00000126", "Returning as there are no members left in the hunt group to ring") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:27] MacroExit("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:12] Gosub("SIP/1007-00000126", "sub-record-cancel,s,1()") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] Return("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:13] Set("SIP/1007-00000126", "RingGroupMethod=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:14] GotoIf("SIP/1007-00000126", "0?nodest") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:15] Set("SIP/1007-00000126", "__NODEST=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:16] Macro("SIP/1007-00000126", "blkvm-clr,") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:1] Set("SIP/1007-00000126", "SHARED(BLKVM,SIP/1007-00000126)=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:2] Set("SIP/1007-00000126", "GOSUB_RETVAL=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:3] MacroExit("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [[email protected]:17] Goto("SIP/1007-00000126", "ext-group,1901,1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx_builtins.c: Goto (ext-group,1901,1)

Please wrap this in code indents.

Modified as requested.

Any thoughts now that the description of the issue is more human readable?