[asterisk-bugs] [JIRA] (ASTERISK-27987) AGI() call causes RTP to briefly freeze under certain circumstances

[xrobau (JIRA)]

    [ https://issues.asterisk.org/jira/browse/ASTERISK-27987?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=244287#comment-244287 ] 

xrobau commented on ASTERISK-27987:
-----------------------------------

After chatting on IRC, another test was proposed in that a seperate Asterisk process is run on the same machine, which runs timing tests at the same time as the live machine.  This showed that the timing issue was only in the Asterisk that was suffering from the problem:

{code}
Active It has been 1000 milliseconds, and we got 50 timer ticks
Idle It has been 1000 milliseconds, and we got 50 timer ticks
Active It has been 1000 milliseconds, and we got 50 timer ticks
Idle It has been 1000 milliseconds, and we got 50 timer ticks
Active It has been 1011 milliseconds, and we got 46 timer ticks
Idle It has been 1000 milliseconds, and we got 50 timer ticks
Active It has been 1000 milliseconds, and we got 49 timer ticks
Idle It has been 1000 milliseconds, and we got 50 timer ticks
Active It has been 1000 milliseconds, and we got 50 timer ticks
Idle It has been 1000 milliseconds, and we got 50 timer ticks
{code}

You'll see that the 'Active' machine slipped twice.  This, actually, confirms what I posted earlier - running a large number of AGI's causes timing to slip:

{code}
uc-85436011*CLI> timing test
Attempting to test a timer with 50 ticks per second.
Using the 'timerfd' timing module for this test.
It has been 1005 milliseconds, and we got 50 timer ticks
{code}

Looking at the code of timing test: https://github.com/asterisk/asterisk/blob/master/main/timing.c#L252

That loop is based on time, so being that it ran *long*, it feels to me that ast_poll is delaying internally for some reason.

So, this now appears that this IS something that is better described as "ast_poll can suffer delays when AGI calls are spawned" - and that IS replicable!
  


> AGI() call causes RTP to briefly freeze under certain circumstances
> -------------------------------------------------------------------
>
>                 Key: ASTERISK-27987
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-27987
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Core/Bridging
>    Affects Versions: 15.5.0
>            Reporter: xrobau
>            Assignee: Unassigned
>              Labels: pjsip
>         Attachments: debug-server.txt, fdlist.txt, pcap1.png, pcap2.png, timer_list.txt
>
>
> "Something" causes Asterisk to get into a state where launching an AGI causes the entire process to freeze briefly.
> The symptoms are identical to ASTERISK-26257, but that is inaccurate as to the number of services that are impacted.
> Currently I am unable to create an artificial reproduction of the CAUSE, but the symptoms are extremely obvious.
> When Asterisk gets into this state (however it may occur) anything that is reading audio from the filesystem (MoH, Playback()/Background(), or Voicemail) OR confbridge conferences (not meetme) will briefly pause while an AGI is launched.
> We have numerous wireshark captures that show this happening (which we can attach if required), and the timestamps as generated by Asterisk are correct for when the packet WAS sent, not for when it SHOULD have been sent.
> This is triggered by AGI calls in dialplan.  Our test dialplan to determine if Asterisk is in this state is as follows:
> {code}
> exten => 998,1,Answer
>  same => n,Dial(Local/999 at from-internal-custom/n,300,gm(default))
>  same => n,Playback(beep)
>  same => n,Goto(1)
> exten => 999,1,Set(COUNT=0)
>  same => n(loop),GotoIf($[ ${COUNT} > 1000 ]?toomany)
>  same => n,Gosub(testtrigger)
>  same => n,Set(COUNT=$[ ${COUNT} + 1 ])
>  same => n,Goto(loop)
>  same => n(toomany),Hangup
>  same => n(testtrigger),AGI(/bin/true)
>  same => n,Return
> {code}
> If Asterisk is in this broken state, the MoH will be extremely choppy.  After a restart of Asterisk, the MoH is not interrupted.
> We've also noticed that the loop runs MUCH slower when Asterisk is in this state. 
> My random, and probably incorrect, hypothesis is that there's a core lock somewhere that is being grabbed by res_agi which is appending to a gradually growing list, or SOMETHING, that takes a longer and longer time, until it's locking up for longer than 20msec and blocking things that are reading from files (and whatever confbridge is doing)
> I ran that dialplan on a test machine, and was unable to get Asterisk into that state after 250,000 AGI calls. However, our (Sangoma)'s main PBX does randomly and sporadically experience this problem, and we've just got into the habit of restarting asterisk whenever we notice it, which has never been below 30,000 calls (calls as reported by 'core show calls'), and is almost certain to be in that state over 50,000 calls.
> The only common factor that is visible, so far, is that this only happens on Hardware, not in VMs (which may be a red herring), and that all the machines have a lot of listeners to AMI Events.
> Unfortunately, without any way to reproduce this, I'm aware that it's hard to proceed further. However, if there's any more information I can provide when a machine IS in this state, as to what may be causing it, please feel free to ask. 
> Fixing it, as above, is as simple as 'core restart now'. The AGI loops runs fast, and the audio glitch vanishes.



--
This message was sent by Atlassian JIRA
(v6.2#6252)