[Home]

Summary:ASTERISK-29018: pbx: Channel redirect might be missed if redirected channel is executing dialplan
Reporter:Patrick Wakano (pwakano)Labels:
Date Opened:2020-08-04 02:36:28Date Closed:
Priority:MinorRegression?
Status:Open/NewComponents:Core/Channels Core/PBX
Versions:16.8.0 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:When using the Channel Redirect feature (either the dialplan app ChannelRedirect or the CLI channel redirect) it has been observed that the redirection might just not work in case the channel being redirected is executing something else in the dialplan.
Take for example the dialplan below just to simulate the issue. If while the channel is looping, the channel redirect command is issued for that channel from the CLI, the redirect might simply not work and the channel keeps executing the loop.
Given the channel redirect is an explicit action to alter the channel execution, I think it should always override whatever dialplan execution the channel is doing, so it should just terminate the current priority and then immediately go to where the channel redirect determined. However there are cases where the next dialplan priority gets executed and so the redirection silently fails to happen even tough it says the redirection was successful.
The problem does not happen every time, it seems to be a 30% chance of having the issue for the example below.
{noformat}
[pstn-outgoing]
exten => 8888,1,Answer()
same => n,Set(i=0)
same => n,While($[${i} < 10000])
same => n,Set(Dummy=${PRIORITY})
same => n,Set(i=$[${i}+1])
same => n,EndWhile
same => n,NoOp(Loop end)
same => n,Hangup()
same => n(end),NoOp(Terminated)
same => n,Hangup()
{noformat}

Logs:
{noformat}
   -- Executing [8888@pstn-outgoing:4] Set("SIP/9000-0000000f", "Dummy=4") in new stack
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=69") in new stack
   -- Executing [8888@pstn-outgoing:6] EndWhile("SIP/9000-0000000f", "") in new stack
   -- Executing [8888@pstn-outgoing:3] While("SIP/9000-0000000f", "1") in new stack
   -- Executing [8888@pstn-outgoing:4] Set("SIP/9000-0000000f", "Dummy=4") in new stack
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=70") in new stack
   -- Executing [8888@pstn-outgoing:6] EndWhile("SIP/9000-0000000f", "") in new stack
   -- Executing [8888@pstn-outgoing:3] While("SIP/9000-0000000f", "1") in new stack
   -- Executing [8888@pstn-outgoing:4] Set("SIP/9000-0000000f", "Dummy=4") in new stack
pstn8*CLI> channel redirect SIP/9000-0000000f pstn-outgoing,8888,end
Channel 'SIP/9000-0000000f' successfully redirected to pstn-outgoing,8888,end
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=287") in new stack
   -- Executing [8888@pstn-outgoing:6] EndWhile("SIP/9000-0000000f", "") in new stack
   -- Executing [8888@pstn-outgoing:3] While("SIP/9000-0000000f", "1") in new stack
   -- Executing [8888@pstn-outgoing:4] Set("SIP/9000-0000000f", "Dummy=4") in new stack
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=288") in new stack
   -- Executing [8888@pstn-outgoing:6] EndWhile("SIP/9000-0000000f", "") in new stack
   -- Executing [8888@pstn-outgoing:3] While("SIP/9000-0000000f", "1") in new stack
   -- Executing [8888@pstn-outgoing:4] Set("SIP/9000-0000000f", "Dummy=4") in new stack
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=289") in new stack
.....
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=9997") in new stack
   -- Executing [8888@pstn-outgoing:6] EndWhile("SIP/9000-0000000f", "") in new stack
   -- Executing [8888@pstn-outgoing:3] While("SIP/9000-0000000f", "1") in new stack
   -- Executing [8888@pstn-outgoing:4] Set("SIP/9000-0000000f", "Dummy=4") in new stack
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=9998") in new stack
   -- Executing [8888@pstn-outgoing:6] EndWhile("SIP/9000-0000000f", "") in new stack
   -- Executing [8888@pstn-outgoing:3] While("SIP/9000-0000000f", "1") in new stack
   -- Executing [8888@pstn-outgoing:4] Set("SIP/9000-0000000f", "Dummy=4") in new stack
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=9999") in new stack
   -- Executing [8888@pstn-outgoing:6] EndWhile("SIP/9000-0000000f", "") in new stack
   -- Executing [8888@pstn-outgoing:3] While("SIP/9000-0000000f", "1") in new stack
   -- Executing [8888@pstn-outgoing:4] Set("SIP/9000-0000000f", "Dummy=4") in new stack
   -- Executing [8888@pstn-outgoing:5] Set("SIP/9000-0000000f", "i=10000") in new stack
   -- Executing [8888@pstn-outgoing:6] EndWhile("SIP/9000-0000000f", "") in new stack
   -- Executing [8888@pstn-outgoing:3] While("SIP/9000-0000000f", "0") in new stack
   -- Executing [8888@pstn-outgoing:7] NoOp("SIP/9000-0000000f", "Loop end") in new stack
   -- Executing [8888@pstn-outgoing:8] Hangup("SIP/9000-0000000f", "") in new stack
 == Spawn extension (pstn-outgoing, 8888, 8) exited non-zero on 'SIP/9000-0000000f'
pstn8*CLI>
{noformat}
Comments:By: Asterisk Team (asteriskteam) 2020-08-04 02:36:31.198-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution. Please note that log messages and other files should not be sent to the Sangoma Asterisk Team unless explicitly asked for. All files should be placed on this issue in a sanitized fashion as needed.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: Joshua C. Colp (jcolp) 2020-08-04 05:43:08.082-0500

Do you have realistic scenarios where this occurs so that if this issue is looked into it can be verified to be resolved there as well?
By: Patrick Wakano (pwakano) 2020-08-04 20:24:02.683-0500

The example was created just to force the problem and simulate it in my local asterisk but it was based on my production scenario. So my real world case is just a very complex version of the example. The loop is there to simulate a long dialplan. The CLI command is simulating a separate application that triggers the channel redirect from the ChannelRedirect application running in another context.
To summarize, you can think of it as this pseudo-code:
[callwait-context]
exten => s,1,NoOp(Income calls land here and some dialplan logic happens)
same => n,AGI(A RabbitMQ msg is sent)
same => n,NoOp(Long dialplan logic happens here which includes playbacks, setting variables, GoSub and AGI calls with DB queries)
same => n,BridgeWait

[redirect-context]
exten => s,1,NoOp(Only few lines in here)
same => n,ChannelRedirect(${WAIT_CHAN},somewhereelse,s,1)

So the idea is that the channel should execute the callwait-context and reach the BridgeWait from where it will be bridged or redirected somewhere else. In my case the RabbitMQ msg is treated by another application. As a result that application will at some point decide to send an Originate command via AMI which will run the redirect-context in a Local channel that executes the ChannelRedirect for the waiting channel. However, occasionally, the Originate command is sent before the channel being able to reach the BridgeWait. In this case, the ChannelRedirect happens to happen during that long dialplan logic, and we've seen some few cases where the ChannelRedirect just doesn't work, and because the redirection is missed the channel reaches and stays in the BridgeWait until it times out (an error situation not expected to happen).
From observation, I could not find a pattern for the problem. From the cases I've seen there is no common step in the dialplan causing the issue. It seems that, regardless of the command, for every priority, there is a small window where the dialplan and the redirect can both modify the next step for the channel, and if unlucky the dialplan overrides what the redirect has just done. Sometimes it even happens to have the context and priority mixed from both commands, eg. the context is the one set by the redirect, but the priority is the one from the dialplan...

By: Kevin Harwell (kharwell) 2020-08-07 16:35:34.974-0500

Steps I used to replicate.

Dialplan (I altered the given example to be an infinite loop):
{noformat}
exten => echo,1,NoOp()
same => n,Answer()
same => n,Echo()
same => n,Hangup()

exten => caladan,1,Answer()
same => n,Set(i=0)
same => n,While($[${i} < 10000])
same => n,Set(Dummy=${PRIORITY})
;same => n,Set(i=$[${i}+1])
same => n,EndWhile
same => n,NoOp(Loop end)
same => n,Hangup()
same => n(end),NoOp(Terminated)
same => n,Hangup()

exten => arrakis,1,NoOp()
same => n,Verbose(0, he who controls the spice)
same => n,Hangup()
{noformat}
Asterisk CLI:
{noformat}
*CLI> channel originate Local/echo extension caladan
*CLI> channel redirect Local/echo@default-00000000;1 arrakis,1
Channel 'Local/echo@default-00000000;1' successfully redirected to arrakis,1
*CLI> core show channels
Channel              Location             State   Application(Data)            
Local/echo@default-0 caladan@default:3    Up      While(1)                      
Local/echo@default-0 echo@default:3       Up      Echo()                        
2 active channels
2 active calls
2 calls processed
{noformat}
As mentioned it may take a few times to replicate, but it'll state it successfully redirected but doesn't actually redirect.
By: Patrick Wakano (pwakano) 2020-12-03 16:53:49.907-0600

Hello there, just checking if there was any progress on this problem and if there anything else I can help with?
By: Joshua C. Colp (jcolp) 2020-12-03 17:18:43.154-0600

If there are any updates then they will be posted here. As there have been no updates, there are none.
By: Mark Ferris (Mark_Ferris) 2023-02-20 22:45:31.496-0600

Hi Joshua, Could I please request that this issue is reviewed again as it has been 2.5 years and still occurs? If this is not intended to be fixed by the Asterisk team then that would be good to have that clarity. Thanks in advance!
By: Joshua C. Colp (jcolp) 2023-02-21 03:55:33.572-0600

The issue has been accepted, it is in queue, there is no timeframe on if/when it would be looked into by the Asterisk team at Sangoma. Anyone else is free to fix it if they wish, same as any other issue.
By: Mark Ferris (Mark_Ferris) 2023-02-21 16:14:12.590-0600

Thanks Joshua, I appreciate your speedy reply! Forgive me as I am not familiar with your processes. You mentioned anyone else is free to fix this, as I am unable to do this myself, what is the best forum for me to approach someone about doing this on my behalf?
By: Joshua C. Colp (jcolp) 2023-02-21 16:17:37.760-0600

There is a bug bounty process[1]. There is also a Jobs category on the Asterisk community forum.

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Bug+Bounties