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 [[email protected]: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 [[email protected]:23] Set("SIP/1100-000001c2", "STRATEGY=firstnotonphone") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:24] Set("SIP/1100-000001c2", "__RVOL=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:25] GotoIf("SIP/1100-000001c2", "0?skipsimple") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:28] Set("SIP/1100-000001c2", "RingGroupMethod=firstnotonphone") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:29] Set("SIP/1100-000001c2", "_FMGRP=1101") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:34] ExecIf("SIP/1100-000001c2", "1?Set(DOPTS=tTwWI):Set(DOPTS=m(Ring)tTwWI)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:35] GotoIf("SIP/1100-000001c2", "0?doconfirm") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:36] GotoIf("SIP/1100-000001c2", "0?ringallv21") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:37] Macro("SIP/1100-000001c2", "dial,32,tTwWI,1101-1102") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:1] NoOp("SIP/1100-000001c2", "Blind Transfer: , Attended Transfer: , User: 1100, Alert Info: Bellcore-r2") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:2] ExecIf("SIP/1100-000001c2", "0?Set(ALERT_INFO=)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:3] ExecIf("SIP/1100-000001c2", "0?Set(ALERT_INFO=)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:4] ExecIf("SIP/1100-000001c2", "0?Set(ALERT_INFO=)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:5] ExecIf("SIP/1100-000001c2", "0?Set(CHANNEL(musicclass)=)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:24] NoOp("SIP/1100-000001c2", "Returned from dialparties with 2 hunt members to dial") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:25] Set("SIP/1100-000001c2", "HuntLoop=0") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:26] ExecIf("SIP/1100-000001c2", "0?Set(HuntMembers=0)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:30] Set("SIP/1100-000001c2", "HuntMember=HuntMember0") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:32] Set("SIP/1100-000001c2", "CT_EXTEN=1101") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:33] Set("SIP/1100-000001c2", "EXTTOCALL=1101") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:34] Set("SIP/1100-000001c2", "DB(CALLTRACE/1101)=1100") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:44] NoOp("SIP/1100-000001c2", "Hunt Dial Start") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:45] ExecIf("SIP/1100-000001c2", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Bellcore-r2;volume=)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:46] ExecIf("SIP/1100-000001c2", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Bellcore-r2;volume=)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:47] Macro("SIP/1100-000001c2", "dial-hunt-predial-hook,") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:1] MacroExit("SIP/1100-000001c2", "") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:1] NoOp("SIP/1101-000001c3", "Applying SIP Headers to channel") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:2] Set("SIP/1101-000001c3", "SIPHEADERKEYS=Alert-Info") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:3] While("SIP/1101-000001c3", "1") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:4] Set("SIP/1101-000001c3", "sipheader=Bellcore-r2") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:5] SIPAddHeader("SIP/1101-000001c3", "Alert-Info: Bellcore-r2") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:6] EndWhile("SIP/1101-000001c3", "") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:3] While("SIP/1101-000001c3", "0") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:49] GotoIf("SIP/1100-000001c2", "0?ANSWER,1") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:50] Set("SIP/1100-000001c2", "HuntLoop=1") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:52] Set("SIP/1100-000001c2", "HuntMembers=1") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:53] Set("SIP/1100-000001c2", "HuntMembers=0") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:27] GotoIf("SIP/1100-000001c2", "0?a30") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:29] MacroExit("SIP/1100-000001c2", "") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:45] Set("SIP/1100-000001c2", "RingGroupMethod=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:46] GotoIf("SIP/1100-000001c2", "0?nodest") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:47] Set("SIP/1100-000001c2", "__NODEST=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:48] Set("SIP/1100-000001c2", "__PICKUPMARK=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:49] Macro("SIP/1100-000001c2", "blkvm-clr,") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:1] Set("SIP/1100-000001c2", "SHARED(BLKVM,SIP/1100-000001c2)=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:2] Set("SIP/1100-000001c2", "GOSUB_RETVAL=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:3] MacroExit("SIP/1100-000001c2", "") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:50] Set("SIP/1100-000001c2", "DIALSTATUS=NOANSWER") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:51] GotoIf("SIP/1100-000001c2", "0?dohangup") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]:3] Set("SIP/1100-000001c2", "__PICKUPMARK=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:4] Macro("SIP/1100-000001c2", "vm,1101,NOANSWER,") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:1] Macro("SIP/1100-000001c2", "user-callerid,SKIPTTL") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:1] Set("SIP/1100-000001c2", "TOUCH_MONITOR=1496948803.682") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:2] Set("SIP/1100-000001c2", "AMPUSER=1100") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]: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 [[email protected]: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 [[email protected]:27] Set("SIP/1100-000001c2", "CALLERID(number)=1100") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:28] Set("SIP/1100-000001c2", "CALLERID(name)=John Smith") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:29] GotoIf("SIP/1100-000001c2", "0?cnum") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:30] Set("SIP/1100-000001c2", "CDR(cnam)=John Smith") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:31] Set("SIP/1100-000001c2", "CDR(cnum)=1100") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:32] Set("SIP/1100-000001c2", "CHANNEL(language)=en") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:2] Set("SIP/1100-000001c2", "VMGAIN=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:3] Macro("SIP/1100-000001c2", "blkvm-check,") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:1] Set("SIP/1100-000001c2", "GOSUB_RETVAL=") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:2] ExecIf("SIP/1100-000001c2", "0?Set(GOSUB_RETVAL=TRUE)") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:3] MacroExit("SIP/1100-000001c2", "") in new stack
[Jun  8 15:06:44]     -- Executing [[email protected]:4] GotoIf("SIP/1100-000001c2", "1?vmx,1") in new stack
[Jun  8 15:06:44]     -- Goto (macro-vm,vmx,1)

(…goes to voicemail…)