Could someone please explain why this follow-me won't work?

I’m running Asterisk 13.16.0 & FreePBX 14.0.1rc1.17. This worked on an older version of FreePBX and Asterisk.

Calling from extension 1100 to 1101. 1101 is on another call. Expected behavior is it should roll over to 1102.

1101 has an enabled follow-me with these settings:

Calendar matching disabled
Initial Ring Time 0
Ring Strategy firstnotonphone
Follow-Me Ring Time 32
Follow-Me List:
1101
1102
Remaining settings are defaults.

Here is what I believe to be the pertinent portion of the CLI output. You can see that it knows it’s supposed to try 1102 after 1101, but it doesn’t. But I don’t understand exactly what is preventing it from doing that. If I call 1102 directly it works fine. If I set the follow-me to go to 1102 only, then it will ring only 1102, so it’s not that it can’t get to 1102. And it must know that 1101 is busy because it display this:

Got SIP response 486 “Busy Here” back from 192.168.10.68:5083

Which is the address of the the VoIP adapter used by 1101 but not 1102.

Is FreePBX maybe not recognizing response 486 as an indication it should move on and try the next extension in the follow-me, or is it maybe something completely different? If someone could look at this and tell me how it is failing I would much appreciate it.

[Jun  8 15:06:44]     -- Executing [1101@followme-sub:20] GotoIf("SIP/1100-000001c2", "1?skipdring") in new stack
[Jun  8 15:06:44]     -- Goto (followme-sub,1101,23)
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:23] Set("SIP/1100-000001c2", "STRATEGY=firstnotonphone") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:24] Set("SIP/1100-000001c2", "__RVOL=") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:25] GotoIf("SIP/1100-000001c2", "0?skipsimple") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:26] GotoIf("SIP/1100-000001c2", "1 ?skipsimple") in new stack
[Jun  8 15:06:44]     -- Goto (followme-sub,1101,28)
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:28] Set("SIP/1100-000001c2", "RingGroupMethod=firstnotonphone") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:29] Set("SIP/1100-000001c2", "_FMGRP=1101") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:30] GotoIf("SIP/1100-000001c2", "1?DIALGRP") in new stack
[Jun  8 15:06:44]     -- Goto (followme-sub,1101,34)
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:34] ExecIf("SIP/1100-000001c2", "1?Set(DOPTS=tTwWI):Set(DOPTS=m(Ring)tTwWI)") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:35] GotoIf("SIP/1100-000001c2", "0?doconfirm") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:36] GotoIf("SIP/1100-000001c2", "0?ringallv21") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:37] Macro("SIP/1100-000001c2", "dial,32,tTwWI,1101-1102") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:1] NoOp("SIP/1100-000001c2", "Blind Transfer: , Attended Transfer: , User: 1100, Alert Info: Bellcore-r2") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:2] ExecIf("SIP/1100-000001c2", "0?Set(ALERT_INFO=)") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:3] ExecIf("SIP/1100-000001c2", "0?Set(ALERT_INFO=)") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:4] ExecIf("SIP/1100-000001c2", "0?Set(ALERT_INFO=)") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:5] ExecIf("SIP/1100-000001c2", "0?Set(CHANNEL(musicclass)=)") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:6] AGI("SIP/1100-000001c2", "dialparties.agi") in new stack
[Jun  8 15:06:44]     -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jun  8 15:06:44]  dialparties.agi: Starting New Dialparties.agi
[Jun  8 15:06:44]  dialparties.agi: Caller ID name is 'John Smith' number is '1100'
[Jun  8 15:06:44]  dialparties.agi: CW Ignore is:
[Jun  8 15:06:44]  dialparties.agi: CF Ignore is:
[Jun  8 15:06:44]  dialparties.agi: CW IN_USE/BUSY is: 1
[Jun  8 15:06:44]        > dialparties.agi: Setting Alert-Info:  Bellcore-r2
[Jun  8 15:06:44]     -- AGI Script Executing Application: (SIPAddHeader) Options: (Alert-Info:Bellcore-r2)
[Jun  8 15:06:44]        > dialparties.agi: Setting sipheader Alert-Info: Bellcore-r2
[Jun  8 15:06:44]        > dialparties.agi: USE_CONFIRMATION:  'FALSE'
[Jun  8 15:06:44]        > dialparties.agi: RINGGROUP_INDEX:   ''
[Jun  8 15:06:44]  dialparties.agi: Methodology of ring is  'firstnotonphone'
[Jun  8 15:06:44]     -- dialparties.agi: Added extension 1101 to extension map
[Jun  8 15:06:44]     -- dialparties.agi: Added extension 1102 to extension map
[Jun  8 15:06:44]     -- dialparties.agi: Extension 1101 cf is disabled
[Jun  8 15:06:44]     -- dialparties.agi: Extension 1102 cf is disabled
[Jun  8 15:06:44]     -- dialparties.agi: Extension 1101 do not disturb is disabled
[Jun  8 15:06:44]     -- dialparties.agi: Extension 1102 do not disturb is disabled
[Jun  8 15:06:44]        > dialparties.agi: extnum 1101 has:  cw: 0; hascfb: 0 [] hascfu: 0 []
[Jun  8 15:06:44]  dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[Jun  8 15:06:44]  dialparties.agi: Extension 1101 has ExtensionState: 0
[Jun  8 15:06:44]     -- dialparties.agi: Checking CW and CFB status for extension 1101
[Jun  8 15:06:44]        > dialparties.agi: extnum 1102 has:  cw: 0; hascfb: 0 [] hascfu: 0 []
[Jun  8 15:06:44]  dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[Jun  8 15:06:44]  dialparties.agi: Extension 1102 has ExtensionState: 0
[Jun  8 15:06:44]     -- dialparties.agi: Checking CW and CFB status for extension 1102
[Jun  8 15:06:44]     -- dialparties.agi: Filtered ARG3: 1101-1102
[Jun  8 15:06:44]        > dialparties.agi: NODEST: 1101 adding M(auto-blkvm) to dialopts: tTwWIM(auto-blkvm)
[Jun  8 15:06:44]        > dialparties.agi: NODEST: 1101 blkvm enabled macro already in dialopts: tTwWIM(auto-blkvm)
[Jun  8 15:06:44]  dialparties.agi: RVOL_MODE ''
[Jun  8 15:06:44]  dialparties.agi: RVOL is:
[Jun  8 15:06:44]  dialparties.agi: RVOLPARENT is:
[Jun  8 15:06:44]     -- <SIP/1100-000001c2>AGI Script dialparties.agi completed, returning 0
[Jun  8 15:06:44]     -- Executing [s@macro-dial:24] NoOp("SIP/1100-000001c2", "Returned from dialparties with 2 hunt members to dial") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:25] Set("SIP/1100-000001c2", "HuntLoop=0") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:26] ExecIf("SIP/1100-000001c2", "0?Set(HuntMembers=0)") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:27] GotoIf("SIP/1100-000001c2", "1?a30") in new stack
[Jun  8 15:06:44]     -- Goto (macro-dial,s,30)
[Jun  8 15:06:44]     -- Executing [s@macro-dial:30] Set("SIP/1100-000001c2", "HuntMember=HuntMember0") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:31] GotoIf("SIP/1100-000001c2", "1?a32:a35") in new stack
[Jun  8 15:06:44]     -- Goto (macro-dial,s,32)
[Jun  8 15:06:44]     -- Executing [s@macro-dial:32] Set("SIP/1100-000001c2", "CT_EXTEN=1101") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:33] Set("SIP/1100-000001c2", "EXTTOCALL=1101") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:34] Set("SIP/1100-000001c2", "DB(CALLTRACE/1101)=1100") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:35] Goto("SIP/1100-000001c2", "s,huntstart") in new stack
[Jun  8 15:06:44]     -- Goto (macro-dial,s,44)
[Jun  8 15:06:44]     -- Executing [s@macro-dial:44] NoOp("SIP/1100-000001c2", "Hunt Dial Start") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:45] ExecIf("SIP/1100-000001c2", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Bellcore-r2;volume=)") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:46] ExecIf("SIP/1100-000001c2", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Bellcore-r2;volume=)") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:47] Macro("SIP/1100-000001c2", "dial-hunt-predial-hook,") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial-hunt-predial-hook:1] MacroExit("SIP/1100-000001c2", "") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:48] Dial("SIP/1100-000001c2", "SIP/1101,32,tTwWIM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[Jun  8 15:06:44]   == Using SIP RTP TOS bits 184
[Jun  8 15:06:44]   == Using SIP RTP CoS mark 5
[Jun  8 15:06:44]     -- SIP/1101-000001c3 Internal Gosub(func-apply-sipheaders,s,1) start
[Jun  8 15:06:44]     -- Executing [s@func-apply-sipheaders:1] NoOp("SIP/1101-000001c3", "Applying SIP Headers to channel") in new stack
[Jun  8 15:06:44]     -- Executing [s@func-apply-sipheaders:2] Set("SIP/1101-000001c3", "SIPHEADERKEYS=Alert-Info") in new stack
[Jun  8 15:06:44]     -- Executing [s@func-apply-sipheaders:3] While("SIP/1101-000001c3", "1") in new stack
[Jun  8 15:06:44]     -- Executing [s@func-apply-sipheaders:4] Set("SIP/1101-000001c3", "sipheader=Bellcore-r2") in new stack
[Jun  8 15:06:44]     -- Executing [s@func-apply-sipheaders:5] SIPAddHeader("SIP/1101-000001c3", "Alert-Info: Bellcore-r2") in new stack
[Jun  8 15:06:44]     -- Executing [s@func-apply-sipheaders:6] EndWhile("SIP/1101-000001c3", "") in new stack
[Jun  8 15:06:44]     -- Executing [s@func-apply-sipheaders:3] While("SIP/1101-000001c3", "0") in new stack
[Jun  8 15:06:44]     -- Executing [s@func-apply-sipheaders:7] Return("SIP/1101-000001c3", "") in new stack
[Jun  8 15:06:44]   == Spawn extension (from-internal, 1101, 1) exited non-zero on 'SIP/1101-000001c3'
[Jun  8 15:06:44]     -- SIP/1101-000001c3 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[Jun  8 15:06:44]     -- Called SIP/1101
[Jun  8 15:06:44]     -- Connected line update to SIP/1100-000001c2 prevented.
[Jun  8 15:06:44]     -- Got SIP response 486 "Busy Here" back from 192.168.10.68:5083
[Jun  8 15:06:44]     -- SIP/1101-000001c3 is busy
[Jun  8 15:06:44]   == Everyone is busy/congested at this time (1:1/0/0)
[Jun  8 15:06:44]     -- Executing [s@macro-dial:49] GotoIf("SIP/1100-000001c2", "0?ANSWER,1") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:50] Set("SIP/1100-000001c2", "HuntLoop=1") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:51] GotoIf("SIP/1100-000001c2", "1 & 1?huntreset:a46") in new stack
[Jun  8 15:06:44]     -- Goto (macro-dial,s,52)
[Jun  8 15:06:44]     -- Executing [s@macro-dial:52] Set("SIP/1100-000001c2", "HuntMembers=1") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:53] Set("SIP/1100-000001c2", "HuntMembers=0") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:54] Goto("SIP/1100-000001c2", "s,a22") in new stack
[Jun  8 15:06:44]     -- Goto (macro-dial,s,27)
[Jun  8 15:06:44]     -- Executing [s@macro-dial:27] GotoIf("SIP/1100-000001c2", "0?a30") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:28] NoOp("SIP/1100-000001c2", "Returning as there are no members left in the hunt group to ring") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-dial:29] MacroExit("SIP/1100-000001c2", "") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:38] Goto("SIP/1100-000001c2", "nextstep") in new stack
[Jun  8 15:06:44]     -- Goto (followme-sub,1101,45)
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:45] Set("SIP/1100-000001c2", "RingGroupMethod=") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:46] GotoIf("SIP/1100-000001c2", "0?nodest") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:47] Set("SIP/1100-000001c2", "__NODEST=") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:48] Set("SIP/1100-000001c2", "__PICKUPMARK=") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:49] Macro("SIP/1100-000001c2", "blkvm-clr,") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-blkvm-clr:1] Set("SIP/1100-000001c2", "SHARED(BLKVM,SIP/1100-000001c2)=") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-blkvm-clr:2] Set("SIP/1100-000001c2", "GOSUB_RETVAL=") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-blkvm-clr:3] MacroExit("SIP/1100-000001c2", "") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:50] Set("SIP/1100-000001c2", "DIALSTATUS=NOANSWER") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:51] GotoIf("SIP/1100-000001c2", "0?dohangup") in new stack
[Jun  8 15:06:44]     -- Executing [1101@followme-sub:52] Goto("SIP/1100-000001c2", "ext-local,1101,dest") in new stack
[Jun  8 15:06:44]     -- Goto (ext-local,1101,3)
[Jun  8 15:06:44]     -- Executing [1101@ext-local:3] Set("SIP/1100-000001c2", "__PICKUPMARK=") in new stack
[Jun  8 15:06:44]     -- Executing [1101@ext-local:4] Macro("SIP/1100-000001c2", "vm,1101,NOANSWER,") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-vm:1] Macro("SIP/1100-000001c2", "user-callerid,SKIPTTL") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:1] Set("SIP/1100-000001c2", "TOUCH_MONITOR=1496948803.682") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:2] Set("SIP/1100-000001c2", "AMPUSER=1100") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:3] GotoIf("SIP/1100-000001c2", "11?report") in new stack
[Jun  8 15:06:44]     -- Goto (macro-user-callerid,s,14)
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:14] GotoIf("SIP/1100-000001c2", "1?continue") in new stack
[Jun  8 15:06:44]     -- Goto (macro-user-callerid,s,27)
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:27] Set("SIP/1100-000001c2", "CALLERID(number)=1100") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:28] Set("SIP/1100-000001c2", "CALLERID(name)=John Smith") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:29] GotoIf("SIP/1100-000001c2", "0?cnum") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:30] Set("SIP/1100-000001c2", "CDR(cnam)=John Smith") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:31] Set("SIP/1100-000001c2", "CDR(cnum)=1100") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-user-callerid:32] Set("SIP/1100-000001c2", "CHANNEL(language)=en") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-vm:2] Set("SIP/1100-000001c2", "VMGAIN=") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-vm:3] Macro("SIP/1100-000001c2", "blkvm-check,") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-blkvm-check:1] Set("SIP/1100-000001c2", "GOSUB_RETVAL=") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-blkvm-check:2] ExecIf("SIP/1100-000001c2", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-blkvm-check:3] MacroExit("SIP/1100-000001c2", "") in new stack
[Jun  8 15:06:44]     -- Executing [s@macro-vm:4] GotoIf("SIP/1100-000001c2", "1?vmx,1") in new stack
[Jun  8 15:06:44]     -- Goto (macro-vm,vmx,1)

(…goes to voicemail…)