asterisk users - Jul 2013 - AMI timeouts

Hi,

We're using Asterisk 1.8.0 to run a call centre.  There is a Java
process which talks to Asterisk through AMI, which is part of the
software stack that presents a user interface to the call centre agents.

We're seeing a strange issue with AMI.  Most of the time, it doesn't
cause problems, because the Java code is written to cope with it, but
occasionally it does, and, in rare cases, may even result in calls being
dropped.

The main problem with the issue is that we haven't been able to
reproduce it in a test environment, and that it's not that easy to
describe.

The fact that we can't reproduce it in test leads me to think that it's
somehow related to the load on our production system.

I'm hoping that someone else on the list may have seen something similar
before, or that an Asterisk developer might read this and think "ah,
it's this bit of code that's doing it!". :-)

Anyway, let me try to describe what's happening.

The Java process has an AMI connection to Asterisk which it keeps open
continuously.  When sending an AMI request, the process will wait a
certain amount of time for a response (I think the timeout is 5 seconds)
and if it hasn't received it, will retry the request up to 5 times.

Occasionally, the Java process logs show AMI requests timing out (after
5 tries).  What I see in packet captures of the AMI traffic is:

  1. Java process sends a request (e.g., add member to queue)
  2. Retries 5 seconds later
  3. Retries again 5 seconds later
  4. Retries again 5 seconds later
  5. Retries again 5 seconds later
  6. Logs a timeout
  7. After a few more seconds, Asterisk replies to all five requests
     in one go (in a single packet; so, e.g., for "add member to
queue"
     it would reply "success", then four failures because the member
is
     already added); however at this stage, the Java process has given
     up

It feels like Asterisk queues up the AMI responses and then
periodically sends out all the responses in the queue in one go.  Is
something like this going on?  Does the frequency at which Asterisk
flushes the queue depend on load?  Are there any tunable in the config
for this?

If anyone has seen this before, or understands what's happening here, I
would be very grateful for any info!

If you need more details, please do ask and I'll do my best.


Thanks in advance,

Alex

Are you using raw AMI or AMI via HTTP?

Are you using a 3rd party java library such as asterisk-java
(https://github.com/srt/asterisk-java), or are you doing your own Java
AMI connector?  I use asterisk-java and it has been working great.


Jacob

On Jul 11, 2013, at 2:40 AM, Alexander Frolkin <avf at eldamar.org.uk>
wrote:
> The Java process has an AMI connection to Asterisk which it keeps open
> continuously.  When sending an AMI request, the process will wait a
> certain amount of time for a response (I think the timeout is 5 seconds)
> and if it hasn't received it, will retry the request up to 5 times.
Timeout based retries on AMI is probably going to be a problem.

AMI uses TCP, which has its own retry/retransmission logic. While the
TCP connection is alive, you can safely assume that the message is
either on its way to Asterisk, Asterisk is processing the message, or
the response is heading back to you.

Now if the TCP connection fails after you've sent a request, but
before you receive a response, then you really have no way of knowing
if the request was received/processed/rejected/etc. At that point, the
best you can do is reestablish the AMI connection and retry the
action.
> Occasionally, the Java process logs show AMI requests timing out (after
> 5 tries).  What I see in packet captures of the AMI traffic is:
> 
>  1. Java process sends a request (e.g., add member to queue)
Do you see the TCP ACK coming back from Asterisk?
>  2. Retries 5 seconds later
>  3. Retries again 5 seconds later
>  4. Retries again 5 seconds later
>  5. Retries again 5 seconds later
>  6. Logs a timeout
>  7. After a few more seconds, Asterisk replies to all five requests
>     in one go (in a single packet; so, e.g., for "add member to
queue"
>     it would reply "success", then four failures because the
member is
>     already added); however at this stage, the Java process has given
>     up
During the quiet period while you're waiting for the response, do you
receive events over that AMI connection? Are there other actions that
you're attempting to execute? Is there any consistency as to which
commands are getting delayed?
> It feels like Asterisk queues up the AMI responses and then
> periodically sends out all the responses in the queue in one go.  Is
> something like this going on?  Does the frequency at which Asterisk
> flushes the queue depend on load?  Are there any tunable in the config
> for this?
No, there's no response queue in Asterisk. For the action's I've
looked at, it pretty much immediately processes the request and sends
the response.

There are any number of reasons why the response would be delayed, but
the >25 seconds delay you're seeing is excessive for any of the
reasons I can think of. The resource you're using AMI to access may be
busy doing something else. Or the request is simply taking that long
to process. Packet loss could cause delays in getting responses, but
usually not for the lengths of times you're talking about.

I know it's not a lot of info, but hopefully you can turn up some
logging or packet captures to narrow down what's going on.
> Thanks in advance,
> 
> Alex
-- 
David M. Lee
Digium, Inc. | Software Developer
445 Jan Davis Drive NW - Huntsville, AL 35806 - USA
Check us out at:  www.digium.com  & www.asterisk.org