Unable to confirm calls when -> ring group -> follow me -> external number

Hi,

We're running Sangoma FreePBX Distro v7 comprising of Asterisk 16.13.0 and FreePBX core 15.0.12.26. All packages (yum update) and FreePBX modules are up to date.

We have an inbound route for 0220 landing in ring group 520 which only has member '1904#'. This allows the ring group to send calls to the extension's off-system follow me number, which in this example is 0116661904. All of this works perfectly until we enable 'confirm call'.

Thereafter each member is offered the call, listens to the options and presses 1 to accept the call. The agent then hears a message that the call is no longer available.

Things also work when we convert the ring groups to queues, this specifically affects:

Inbound DID -> ring group -> follow me -> external call -> confirm call 

I've uploaded logging as 'RG-FM-CC_call_no_longer_available.txt'

[2020-09-13 09:38:09] VERBOSE[5045][C-00000011] app_dial.c: Called IAX2/Teams/0116661904
{{ [2020-09-13 09:38:09] VERBOSE[29502][C-00000011] chan_iax2.c: Call accepted by 192.168.20.7:4569 (format g722)}}
{{ [2020-09-13 09:38:09] VERBOSE[29502][C-00000011] chan_iax2.c: Format for call is (g722)}}
{{ [2020-09-13 09:38:10] VERBOSE[5045][C-00000011] app_dial.c: IAX2/Teams-32054 is ringing}}
{{ [2020-09-13 09:38:10] VERBOSE[4992][C-00000011] app_dial.c: Local/0116661904@from-internal-00000013;1 is ringing}}
{{ [2020-09-13 09:38:10] VERBOSE[4987][C-00000011] app_dial.c: Local/FMGL-0116661904#@from-internal-00000012;1 is ringing}}
[2020-09-13 09:38:14] VERBOSE[5045][C-00000011] app_dial.c: IAX2/Teams-32054 answered Local/0116661904@from-internal-00000013;2
[2020-09-13 09:38:14] VERBOSE[5045][C-00000011] app_stack.c: IAX2/Teams-32054 Internal Gosub(sub-send-obroute-email,s,1(0116661904,0116661904,5,,+27823335555,0823335555)) start
<snip>
[2020-09-13 09:38:14] VERBOSE[5052][C-00000011] bridge_channel.c: Channel Local/FMGL-0116661904#@from-internal-00000012;1 joined 'simple_bridge' basic-bridge <8b6438cb-3db0-4dff-866a-db14f4cb2d94>
[2020-09-13 09:38:14] VERBOSE[4987][C-00000011] bridge_channel.c: Channel Local/1904@from-internal-00000010;2 joined 'simple_bridge' basic-bridge <8b6438cb-3db0-4dff-866a-db14f4cb2d94>
[2020-09-13 09:38:14] VERBOSE[4984][C-00000011] file.c: <Local/1904@from-internal-00000010;1> Playing 'incoming-call-1-accept-2-decline.alaw' (language 'en_GB')
[2020-09-13 09:38:14] VERBOSE[5052][C-00000011] bridge.c: Move-swap optimizing Local/FMGL-0116661904#@from-internal-00000012;2 <-- Local/1904@from-internal-00000010;2.
[2020-09-13 09:38:14] VERBOSE[5052][C-00000011] bridge_channel.c: Channel Local/1904@from-internal-00000010;2 left 'simple_bridge' basic-bridge <8b6438cb-3db0-4dff-866a-db14f4cb2d94>
[2020-09-13 09:38:14] VERBOSE[5052][C-00000011] bridge_channel.c: Channel Local/FMGL-0116661904#@from-internal-00000012;2 left 'simple_bridge' basic-bridge <04575d03-60ee-4276-8ef3-7698189d96cb>
[2020-09-13 09:38:14] VERBOSE[5052][C-00000011] bridge_channel.c: Channel Local/1904@from-internal-00000010;2 swapped with Local/FMGL-0116661904#@from-internal-00000012;2 into 'simple_bridge' basic-bridge <04575d03-60ee-4276-8ef3-7698189d96cb>
[2020-09-13 09:38:14] VERBOSE[5052][C-00000011] bridge_channel.c: Channel Local/FMGL-0116661904#@from-internal-00000012;1 left 'simple_bridge' basic-bridge <8b6438cb-3db0-4dff-866a-db14f4cb2d94>
[2020-09-13 09:38:14] VERBOSE[4992][C-00000011] app_macro.c: Spawn extension (macro-dial, s, 24) exited non-zero on 'Local/FMGL-0116661904#@from-internal-00000012;2' in macro 'dial'
[2020-09-13 09:38:14] VERBOSE[4992][C-00000011] pbx.c: Spawn extension (from-internal, FMGL-0116661904#, 8) exited non-zero on 'Local/FMGL-0116661904#@from-internal-00000012;2'
[2020-09-13 09:38:14] VERBOSE[4992][C-00000011] pbx.c: Executing [h@from-internal:1] Macro("Local/FMGL-0116661904#@from-internal-00000012;2", "hangupcall") in new stack
[2020-09-13 09:38:14] VERBOSE[4992][C-00000011] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("Local/FMGL-0116661904#@from-internal-00000012;2", "1?theend") in new stack
[2020-09-13 09:38:14] VERBOSE[4992][C-00000011] pbx_builtins.c: Goto (macro-hangupcall,s,3)

Doesn't appear to wait for DTMF and hangs up 'Local/1904'. DTMF comes through from the agent and the dialplan then matches 'toolate':

[2020-09-13 09:38:18] DTMF[4984][C-00000011] channel.c: DTMF end '1' received on Local/1904@from-internal-00000010;1, duration 180 ms
[2020-09-13 09:38:18] DTMF[4984][C-00000011] channel.c: DTMF end '1' received on Local/1904@from-internal-00000010;1, duration 180 ms
[2020-09-13 09:38:18] DTMF[4984][C-00000011] channel.c: DTMF end passthrough '1' on Local/1904@from-internal-00000010;1
[2020-09-13 09:38:18] DTMF[4984][C-00000011] channel.c: DTMF end passthrough '1' on Local/1904@from-internal-00000010;1
[2020-09-13 09:38:18] VERBOSE[4984][C-00000011] pbx.c: Executing [1@macro-confirm:1] GotoIf("Local/1904@from-internal-00000010;1", "0?toolate,1") in new stack
[2020-09-13 09:38:18] VERBOSE[4984][C-00000011] pbx.c: Executing [1@macro-confirm:2] GotoIf("Local/1904@from-internal-00000010;1", "0?toolate,1") in new stack
[2020-09-13 09:38:18] VERBOSE[4984][C-00000011] pbx.c: Executing [1@macro-confirm:3] Set("Local/1904@from-internal-00000010;1", "cfchannel=IAX2/PSTN-615") in new stack
[2020-09-13 09:38:18] VERBOSE[4984][C-00000011] pbx.c: Executing [1@macro-confirm:4] GotoIf("Local/1904@from-internal-00000010;1", "1?toolate,1") in new stack
[2020-09-13 09:38:18] VERBOSE[4984][C-00000011] pbx_builtins.c: Goto (macro-confirm,toolate,1)
[2020-09-13 09:38:18] VERBOSE[4984][C-00000011] pbx.c: Executing [toolate@macro-confirm:1] Set("Local/1904@from-internal-00000010;1", "MSG2="incoming-call-no-longer-avail"") in new stack
[2020-09-13 09:38:18] VERBOSE[4984][C-00000011] pbx.c: Executing [toolate@macro-confirm:2] Playback("Local/1904@from-internal-00000010;1", ""incoming-call-no-longer-avail"") in new stack
[2020-09-13 09:38:18] VERBOSE[4984][C-00000011] file.c: <Local/1904@from-internal-00000010;1> Playing 'incoming-call-no-longer-avail.alaw' (language 'en_GB')

Regards
David Herselman