[bug]: FreePBX 17 FollowMe - GOSUB_RETVAL empty from [macro-blkvm-setifempty] #582

inferno-cc · 2024-12-09T11:26:59Z

FreePBX Version

FreePBX 17

Issue Description

When FollowMe is enabled on extension and the extension is an agent in a queue + set on DND/Busy + the queue is linked to an IVR, when calling to this extension from queue the call returns to the IVR makes it a loop.

Setup:
Inbound route > IVR > Queue

We see the call is coming to [followme-sub] and the below Gosub goes to [macro-blkvm-setifempty]:
exten => _X!,n,Gosub(macro-blkvm-setifempty,s,1())

When it returns back to [followme-sub] the variable GOSUB_RETVAL is empty so the below check on [followme-sub] fails resulting the call is looping:
exten => _X!,n,GotoIf($["${GOSUB_RETVAL}" = "TRUE"]?skipov)

If we change the GOSUB_RETVAL variable to something custom like GOSUB_RETVAL1 then it works fine.

Same setup has been tested on FreePBX 15 with no issue.

Operating Environment

FreePBX 17 + Asterisk 20.10/Asterisk 18.25

Relevant log output

No response

The text was updated successfully, but these errors were encountered:

inferno-cc · 2024-12-09T11:27:12Z

log_output.txt

Log output attached

blazestudios97 · 2024-12-09T17:03:39Z

This line:
exten => _X!,n,Gosub(macro-blkvm-setifempty,s,1())

Is executed before the Follow-Me list is dialled so that no extensions go to voicemail while dialling the list. Once the list is dialled or in this case, the list comes back with nothing to dial due to various status (or an empty list) then the following dialplan is executed:

[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@followme-sub:52] Gosub("Local/2222@from-queue-00007a28;2", "macro-blkvm-clr,s,1()") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [s@macro-blkvm-clr:1] Set("Local/2222@from-queue-00007a28;2", "SHARED(BLKVM,PJSIP/kamailio_sbc01_pjsip-0000d18a)=") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [s@macro-blkvm-clr:2] Set("Local/2222@from-queue-00007a28;2", "GOSUB_RETVAL=") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [s@macro-blkvm-clr:3] Return("Local/2222@from-queue-00007a28;2", "") in new stack

This clears the voicemail block that was set so the extension that was dialled originally can execute dialplan due to the Dial() returning with nothing answered. It then executes this dialplan to send the call back into the extensions normal routing (going to voicemail if enabled, etc).

[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@followme-sub:55] Goto("Local/2222@from-queue-00007a28;2", "ext-local,2222,dest") in new stack

It's from there because the IVR is set to return after voicemail (or in cases no voicemail is set, just return) the call is returned to the IVR

[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx_builtins.c: Goto (ext-local,2222,4)
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@ext-local:4] Set("Local/2222@from-queue-00007a28;2", "__PICKUPMARK=") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@ext-local:5] GotoIf("Local/2222@from-queue-00007a28;2", "1?ivr-31,return,1") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx_builtins.c: Goto (ivr-31,return,1)

It sounds like the IVR isn't configured the same on FreePBX v17 as it was on the FreePBX v15 systems you say this works on. I'd compare the IVR settings and make sure the IVR options don't have the return to IVR option set to Yes.

It would also be helpful to see output from the v15 system this is working on so we can compare what is happening.

inferno-cc · 2024-12-09T17:08:20Z

This line: exten => _X!,n,Gosub(macro-blkvm-setifempty,s,1())

Is executed before the Follow-Me list is dialled so that no extensions go to voicemail while dialling the list. Once the list is dialled or in this case, the list comes back with nothing to dial due to various status (or an empty list) then the following dialplan is executed:
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@followme-sub:52] Gosub("Local/2222@from-queue-00007a28;2", "macro-blkvm-clr,s,1()") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [s@macro-blkvm-clr:1] Set("Local/2222@from-queue-00007a28;2", "SHARED(BLKVM,PJSIP/kamailio_sbc01_pjsip-0000d18a)=") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [s@macro-blkvm-clr:2] Set("Local/2222@from-queue-00007a28;2", "GOSUB_RETVAL=") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [s@macro-blkvm-clr:3] Return("Local/2222@from-queue-00007a28;2", "") in new stack
This clears the voicemail block that was set so the extension that was dialled originally can execute dialplan due to the Dial() returning with nothing answered. It then executes this dialplan to send the call back into the extensions normal routing (going to voicemail if enabled, etc).

[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@followme-sub:55] Goto("Local/2222@from-queue-00007a28;2", "ext-local,2222,dest") in new stack

It's from there because the IVR is set to return after voicemail (or in cases no voicemail is set, just return) the call is returned to the IVR
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx_builtins.c: Goto (ext-local,2222,4)
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@ext-local:4] Set("Local/2222@from-queue-00007a28;2", "__PICKUPMARK=") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@ext-local:5] GotoIf("Local/2222@from-queue-00007a28;2", "1?ivr-31,return,1") in new stack
[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx_builtins.c: Goto (ivr-31,return,1)
It sounds like the IVR isn't configured the same on FreePBX v17 as it was on the FreePBX v15 systems you say this works on. I'd compare the IVR settings and make sure the IVR options don't have the return to IVR option set to Yes.

It would also be helpful to see output from the v15 system this is working on so we can compare what is happening.

I can try to send the output from v15.. but why it's working fine when we change the var from GOSUB_RETVAL to GOSUB_RETVAL1 is a big question for me?

Return on voicemail on the IVR is set to No.

blazestudios97 · 2024-12-09T18:12:28Z

We will need to see what 15 is doing because in v15 here's what an extension's dialplan looks like when no voicemail is set on the extension.

exten => 219,1,Set(__RINGTIMER=${IF($["${DB(AMPUSER/219/ringtimer)}" > "0"]?${DB(AMPUSER/219/ringtimer)}:${RINGTIMER_DEFAULT})})
exten => 219,n,ExecIf($["${REGEX("from-queue" ${CHANNEL})}"="1" && "${CONTEXT}"="from-internal-xfer"]?Set(__CWIGNORE=))
exten => 219,n,Macro(exten-vm,novm,219,0,0,0)
exten => 219,n(dest),Set(__PICKUPMARK=)
exten => 219,n,GotoIf($["${IVR_CONTEXT}" != ""]?${IVR_CONTEXT},return,1)
exten => 219,hint,SIP/219&Custom:DND219,CustomPresence:219

Here's what it looks like in v17:

exten => 101,1,Set(__RINGTIMER=${IF($["${DB(AMPUSER/101/ringtimer)}" > "0"]?${DB(AMPUSER/101/ringtimer)}:${RINGTIMER_DEFAULT})})
exten => 101,n,ExecIf($["${REGEX("from-queue" ${CHANNEL})}"="1" && "${CONTEXT}"="from-internal-xfer"]?Set(__CWIGNORE=))
exten => 101,n,Gosub(macro-exten-vm,s,1(novm,101,0,0,0))
exten => 101,n(dest),Set(__PICKUPMARK=)
exten => 101,n,GotoIf($["${IVR_CONTEXT}" != ""]?${IVR_CONTEXT},return,1)
exten => 101,hint,PJSIP/101&Custom:DND101,CustomPresence:101

They are virtually the same. This is your issue GotoIf($["${IVR_CONTEXT}" != ""]?${IVR_CONTEXT},return,1) because IVR_CONTEXT is set in the IVR, it exists.

Again, we'll need to see something from v15 that is working as you say. Because they both would end up hitting the same exact dialplan which begs the question, why does it work differently between the systems?

inferno-cc · 2024-12-09T19:18:57Z

Further investigation brings us to the below.
In v15 they are using built-in variable GOSUB_RETVAL, its value is overwritten by Return() call in the second case. In the first call (which is ok) they use Macro:
[2024-12-09 09:38:02] VERBOSE[25882][C-00003120] pbx.c: Executing [480@followme-sub:10] Macro("Local/480@from-queue-00003155;2", "blkvm-setifempty,")
in new stack which does not have Return() - (because it is a macro), in the second call (which is not ok) they use
Gosub:
[2024-12-09 09:19:34] VERBOSE[3788609][C-00003bbd] pbx.c: Executing [2222@followme-sub:10] Gosub("Local/2222@from-queue-0000769f;2", "macro-blkvm-setifempty,s,1()")
in new stack which upon completion resets GOSUB_RETVAL with Return()
We were right as well by adding a variable with a different name, or in macro-blkvm-setifempty return should be replaced with: Return(${GOSUB_RETVAL})

So the built-in variable GOSUB_RETVAL is being reset with Return().

@kguptasangoma the macro-blkvm-setifempty (extensions_additional.conf) from the core module should be adjusted by replacing the Return() with Return(${GOSUB_RETVAL}). Pull request: FreePBX/core#140

blazestudios97 · 2024-12-09T19:32:51Z

None of this has to do with the voicemail block or clearing. The extension doesn't have voicemail enabled on it so it doesn't matter if voicemail is blocked or not. The issue you are having is the line I highlighted in my previous comment, I will provide it again:

GotoIf($["${IVR_CONTEXT}" != ""]?${IVR_CONTEXT},return,1). << when this is executed because ${IVR_CONTEXT} was set in the IVR dialplan, it will return to the IVR. This behavior exists in v15 and v17 with no changes. So again, we need to see a call from the v15 system you say works as you expect/want. We need to see if there is something different happening in the dialplan.

To reiterate, the voicemail Gosub's or Macro's have no bearing on the call being returned to the IVR.

inferno-cc · 2024-12-09T19:39:56Z

So why [macro-blkvm-check] has a different Return than the others? :)

The code is expecting GOSUB_RETVAL to be returned from macro-blkvm-setifempty but it does not because it's being reset (or even not set in the return) by Return().

blazestudios97 · 2024-12-09T19:46:31Z

You are not understanding the logic of the dialplan. The voicemail gosubs are there to block/clear/reset the calls ability to leave voicemail for the extension. The extension in question does not have voicemail enabled so when followme finishes and sends to the post destination of ext-local,2222,dest (priority 4) it clears the PICKUPMARK variable and checks to see if ${IVR_CONTEXT} is set, which it is. If ${IVR_CONTEXT} is set, it returns to the ivr set in ${IVR_CONTEXT}

Again, you need to provide the requested verbose call log from the v15 system that you claim works right.

inferno-cc · 2024-12-09T20:09:25Z

As you wish :D
log_output_V15.txt

blkvm-setifempty is being executed from followme-sub:10 :
exten => _X!,n,Macro(blkvm-setifempty,)

[2024-12-09 20:53:21] VERBOSE[11164][C-000036a4] pbx.c: Executing [2222@followme-sub:10] Macro("Local/2222@from-queue-00003402;2", "blkvm-setifempty,") in new stack

GOSUB_RETVAL is set from blkvm-setifempty and returned by MacroExit():

[macro-blkvm-setifempty]
include => macro-blkvm-setifempty-custom
exten => s,1,GotoIf($[!${EXISTS(${BLKVM_CHANNEL})}]?init)
exten => s,n,Set(GOSUB_RETVAL=${SHARED(BLKVM,${BLKVM_CHANNEL})})
exten => s,n,MacroExit()
exten => s,n(init),Set(__BLKVM_CHANNEL=${CHANNEL})
exten => s,n,Set(SHARED(BLKVM,${BLKVM_CHANNEL})=TRUE)
exten => s,n,Set(GOSUB_RETVAL=TRUE)
exten => s,n,MacroExit()

[2024-12-09 20:53:21] VERBOSE[11164][C-000036a4] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("Local/2222@from-queue-00003402;2", "0?init") in new stack
[2024-12-09 20:53:21] VERBOSE[11164][C-000036a4] pbx.c: Executing [s@macro-blkvm-setifempty:2] Set("Local/2222@from-queue-00003402;2", "GOSUB_RETVAL=TRUE") in new stack
[2024-12-09 20:53:21] VERBOSE[11164][C-000036a4] pbx.c: Executing [s@macro-blkvm-setifempty:3] MacroExit("Local/2222@from-queue-00003402;2", "") in new stack

GotoIf is 1:

[2024-12-09 20:53:21] VERBOSE[11164][C-000036a4] pbx.c: Executing [2222@followme-sub:11] GotoIf("Local/2222@from-queue-00003402;2", "1?skipov") in new stack

as from:
exten => _X!,n,GotoIf($["${GOSUB_RETVAL}" = "TRUE"]?skipov)

In the v17 we got false for the same condition:

[2024-12-09 11:53:56] VERBOSE[3816018][C-00003d46] pbx.c: Executing [2222@followme-sub:12] GotoIf("Local/2222@from-queue-00007a28;2", "0?skipov") in new stack

If we put Noop of var ${GOSUB_RETVAL} just before:
exten => _X!,n,GotoIf($["${GOSUB_RETVAL}" = "TRUE"]?skipov)

we will see it's empty. So that means it's not being set/returned by Return() function.

inferno-cc · 2024-12-09T20:18:11Z

btw I'm not 100% sure why the call is returning to the IVR but I'm pretty sure if we set ${GOSUB_RETVAL} to TRUE from macro-blkvm-setifempty and then we check the same variable in followme-sub if it's TRUE it should work but it cannot work because Return() resets/does not return this variable and this should be Return(${GOSUB_RETVAL}) instead, as it's done for example in macro-blkvm-check.

blazestudios97 · 2024-12-09T20:32:57Z

I believe I have found the problem and it is a configuration issue.

v15:
Follow-me is set to the strategy of ringallv2 with Call Confirm enabled.

v17:
Follow-me is set to strategy of ringallv2-prim with Call Confirm disabled.

The issue is the ring strategy because ringallv2 will ring the extension then continue to ring the extension with the follow-me list. However, with ringallv2-prim it will attempt to ring the extension and if the extension returns BUSY (inuse or DND) it will not continue to the follow-me list. Which is exactly what is happening on the v17 system.

Update your ring strategy in Follow-Me to ringallv2 instead of ringallv2-prim and that should allow the external number to be tried instead of ending the call as it is now and returning back to the IVR.

inferno-cc · 2024-12-09T20:45:28Z

I made a short test without the -prim and it indeed does something else.

ringallv2-prim seems to not ring the Busy extension's fm list yes, but it returns the call to the IVR, is this not strange? This should be routed to the final destination at least

anyway, my conclusion about macro-blkvm-setifempty remains the same, it the variable ${GOSUB_RETVAL} is being set there to TRUE and is being accessed from somewhere else (followme-sub in this case) it's should exist but without Return(${GOSUB_RETVAL}) it's empty...

blazestudios97 · 2024-12-09T20:53:26Z

This has nothing to do with the macro-blkvm-setifempty Gosub. It's already being set as a variable and doesn't need to be in the Return().

ringallv2-prim seems to not ring the Busy extension's fm list yes, but it returns the call to the IVR, is this not strange? This should be routed to the final destination at least

It is not strange, I've explained it a few times. The call was ringing extension 2222, it returned BUSY and wasn't using follow-me list, so it issued a Goto(ext-local,2222,dest) which would execute the following:

exten => 2222,n(dest),Set(__PICKUPMARK=)
exten => 2222,n,GotoIf($["${IVR_CONTEXT}" != ""]?${IVR_CONTEXT},return,1)

${IVR_CONTEXT} is set to ivr-31 due to this executing earlier in the dialplan:
[2024-12-09 11:53:54] VERBOSE[3816005][C-00003d46] pbx.c: Executing [s@ivr-31:4] Set("PJSIP/kamailio_sbc01_pjsip-0000d18a", "_IVR_CONTEXT=ivr-31") in new stack

Everything that is happening is happening as it should. The issue was with your ring strategy in follow-me which was not allowing the follow-me list to execute because the extension is in a BUSY status. That's it.

inferno-cc · 2024-12-09T20:57:36Z

As I already told:

If we put Noop of var ${GOSUB_RETVAL} just before:
exten => _X!,n,GotoIf($["${GOSUB_RETVAL}" = "TRUE"]?skipov)

we will see it's empty. So that means it's not being set/returned by Return() function.

If I follow you, why the call is returning to the IVR if Return to IVR after VM is set to No?

inferno-cc · 2024-12-09T21:04:55Z

additionally the main questions are

Why is this working on FreePBX V15?
Why the variable GOSUB_RETVAL is not being returned from macro-blkvm-setifempty? ==> for this I made a small change in the macro-blkvm-setifempty

Here is also the output from V15 with the same followme settings as on v17 (ringallv2-prim). The call is not looping to the IVR, it ends instead in the final destination of the queue (= terminate call: busy).
log_output_V15_ringallv2_prim.txt

blazestudios97 · 2024-12-09T21:21:13Z

Can I see output from v17 that isn't from modified dialplan?

inferno-cc · 2024-12-09T21:27:25Z

It's on my second message (:
log_output.txt

blazestudios97 · 2024-12-09T21:39:55Z

OK so I've done so testing with things and I was incorrect, the voicemail check is a factor for the returning to the queue...and the issue you have found isn't just for the voicemail gosub's but any old Macro that was setting GOSUB_RETVAL as a way to work with other GoSub calls. Each GoSub that needs to return a value needs to have it set in the Return() as you have pointed out. Otherwise it sets to the an empty value.

So this isn't just a follow-me issue, it's an issue with quite a few things using these checks and GOSUB_RETVAL being returned as empty all the time.

Sorry about that but there were some config differences....you use call confirm on v15 which also handles the call differently. But in the v17 because the GOSUB_RETVAL was empty, it didn't set the needed settings to make the call return to the queue and no follow the extensions normal routing.

inferno-cc · 2024-12-09T21:43:19Z

Yes indeed.
So far I only found below 2 dialplans where it has to be changed for sure:
macro-blkvm-setifempty & macro-blkvm-set

Not sure if there are more..

inferno-cc · 2024-12-09T21:46:08Z

Yes indeed. So far I only found below 2 dialplans where it has to be changed for sure: macro-blkvm-setifempty & macro-blkvm-set

Not sure if there are more..

so for these I made a pull request :)

blazestudios97 · 2024-12-12T01:57:59Z

See my review. It needs a fix applied.

inferno-cc · 2024-12-13T14:02:09Z

See my review. It needs a fix applied.

Thanks!
Changed as well.

jissphilip · 2024-12-17T09:38:31Z

framework version 17.0.19.22

inferno-cc added bug Something isn't working triage Triage labels Dec 9, 2024

inferno-cc mentioned this issue Dec 9, 2024

Bugfix #582 - FollowMe - GOSUB_RETVAL returns empty from [macro-blkvm-setifempty] FreePBX/core#140

Open

inferno-cc mentioned this issue Dec 16, 2024

Bugfix #582 FreePBX/framework#177

Merged

jissphilip closed this as completed Dec 17, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[bug]: FreePBX 17 FollowMe - GOSUB_RETVAL empty from [macro-blkvm-setifempty] #582

[bug]: FreePBX 17 FollowMe - GOSUB_RETVAL empty from [macro-blkvm-setifempty] #582

inferno-cc commented Dec 9, 2024 •

edited

Loading

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024 •

edited

Loading

inferno-cc commented Dec 9, 2024

inferno-cc commented Dec 9, 2024 •

edited

Loading

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024 •

edited

Loading

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 12, 2024

inferno-cc commented Dec 13, 2024

jissphilip commented Dec 17, 2024

[bug]: FreePBX 17 FollowMe - GOSUB_RETVAL empty from [macro-blkvm-setifempty] #582

[bug]: FreePBX 17 FollowMe - GOSUB_RETVAL empty from [macro-blkvm-setifempty] #582

Comments

inferno-cc commented Dec 9, 2024 • edited Loading

FreePBX Version

Issue Description

Operating Environment

Relevant log output

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024 • edited Loading

inferno-cc commented Dec 9, 2024

inferno-cc commented Dec 9, 2024 • edited Loading

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024 • edited Loading

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

inferno-cc commented Dec 9, 2024

blazestudios97 commented Dec 12, 2024

inferno-cc commented Dec 13, 2024

jissphilip commented Dec 17, 2024

inferno-cc commented Dec 9, 2024 •

edited

Loading

blazestudios97 commented Dec 9, 2024 •

edited

Loading

inferno-cc commented Dec 9, 2024 •

edited

Loading

inferno-cc commented Dec 9, 2024 •

edited

Loading