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 [s@macro-dial: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 [s@macro-dial:23] Set("SIP/1007-00000126", "HuntLoop=0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [s@macro-dial:46] Set("SIP/1007-00000126", "HuntMembers=0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial:47] Set("SIP/1007-00000126", "HuntMembers=-1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [1900@from-internal:1] Macro("SIP/1007-00000126", "user-callerid,") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("SIP/1007-00000126", "AMPUSER=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/1007-00000126", "0?report") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:5] Set("SIP/1007-00000126", "AMPUSER=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/1007-00000126", "0?limit") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/1007-00000126", "AMPUSERCIDNAME=Phil Ozlin") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/1007-00000126", "0?report") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/1007-00000126", "AMPUSERCID=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/1007-00000126", "__DIAL_OPTIONS=Ttr") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:12] GotoIf("SIP/1007-00000126", "0?limit") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:15] GotoIf("SIP/1007-00000126", "0?continue") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:17] Set("SIP/1007-00000126", "__TTL=64") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:29] Set("SIP/1007-00000126", "CALLERID(number)=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:31] Set("SIP/1007-00000126", "CDR(cnum)=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:33] Set("SIP/1007-00000126", "CHANNEL(language)=en") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal:2] Macro("SIP/1007-00000126", "blkvm-setifempty,") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-blkvm-setifempty: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 [s@macro-blkvm-setifempty: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 [s@macro-blkvm-setifempty: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 [s@macro-blkvm-setifempty:6] Set("SIP/1007-00000126", "GOSUB_RETVAL=TRUE") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal: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 [1900@from-internal:6] Set("SIP/1007-00000126", "RRNODEST=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal:7] Set("SIP/1007-00000126", "__NODEST=1900") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal: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 [1900@from-internal: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 [s@sub-record-check:1] GotoIf("SIP/1007-00000126", "0?initialized") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:2] Set("SIP/1007-00000126", "__REC_STATUS=INITIALIZED") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:3] Set("SIP/1007-00000126", "NOW=1471964001") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:4] Set("SIP/1007-00000126", "__DAY=23") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:5] Set("SIP/1007-00000126", "__MONTH=08") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:6] Set("SIP/1007-00000126", "__YEAR=2016") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:7] Set("SIP/1007-00000126", "__TIMESTR=20160823-145321") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:8] Set("SIP/1007-00000126", "__FROMEXTEN=1007") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:9] Set("SIP/1007-00000126", "__MON_FMT=wav") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/1007-00000126", "Recordings initialized") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check:3] Return("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@sub-record-check:20] Return("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal:10] Set("SIP/1007-00000126", "RingGroupMethod=firstavailable") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal: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 [s@macro-dial: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 [s@macro-dial: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 [s@macro-dial: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 [s@macro-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 [s@macro-dial: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 [s@macro-dial: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 [s@macro-dial: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 [s@macro-dial:23] Set("SIP/1007-00000126", "HuntLoop=0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [s@macro-dial: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 [s@macro-dial:28] Set("SIP/1007-00000126", "HuntMember=HuntMember0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [s@macro-dial:30] Set("SIP/1007-00000126", "CT_EXTEN=1000") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [s@macro-dial: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 [s@macro-dial:40] NoOp("SIP/1007-00000126", "Hunt Dial Start") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [s@macro-dial-hunt-predial-hook:1] MacroExit("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders:2] Set("SIP/1000-00000127", "SIPHEADERKEYS=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@macro-dial:43] GotoIf("SIP/1007-00000126", "0?ANSWER,1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial:44] Set("SIP/1007-00000126", "HuntLoop=1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial:45] GotoIf("SIP/1007-00000126", "0?a46") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial:46] Set("SIP/1007-00000126", "HuntMembers=0") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial:47] Set("SIP/1007-00000126", "HuntMembers=-1") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [s@macro-dial:25] GotoIf("SIP/1007-00000126", "0?a30") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-dial: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 [s@macro-dial:27] MacroExit("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal: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 [s@sub-record-cancel:1] Return("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal:13] Set("SIP/1007-00000126", "RingGroupMethod=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal:14] GotoIf("SIP/1007-00000126", "0?nodest") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal:15] Set("SIP/1007-00000126", "__NODEST=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal:16] Macro("SIP/1007-00000126", "blkvm-clr,") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-blkvm-clr: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 [s@macro-blkvm-clr:2] Set("SIP/1007-00000126", "GOSUB_RETVAL=") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("SIP/1007-00000126", "") in new stack
[2016-08-23 14:53:21] VERBOSE[16692][C-0000008c] pbx.c: Executing [1900@from-internal: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?