[asterisk-dev] AMI Disconnect/Sudden "Asterisk Call Manager/1.3" received

[Tony Mountifield]

In article <5368ED8B.4080103 at szeto.ca>,
Daniel McFarlane <daniel at szeto.ca> wrote:
> Hi All,
> 
> I've been working with Asterisk for 2.5 years now but I am new to the 
> mailing list.  Hoping to get some answers here..
> 
> I've written a piece of software to control Asterisk via AMI.  I'm able 
> to login, making outbound calls, receive/record calls, handle digits, 
> put people into conferences, etc.  Everything seems to work well, at a 
> low to medium call volume.

It would be worthwhile mentioning which version of Asterisk you are using.

> I've been stress testing the system and found what seems to be a memory 
> issue within Asterisk.  However, after over a day of searching I can't 
> even find any bug reports or anything to bring me closer to a 
> solution..but still hoping to find a solution or that someone can help 
> me find one..
> 
> I connect to the AMI successfully.  In my test I am making an outbound 
> call through a sip "device" I configured within sip.conf. This sip 
> "device" basically connects back into the same Asterisk I am using to 
> generate the calls.
> 
> If I generate outbound calls (i.e.: Via Action: Originate) using a low 
> call volume everything seems to be fine.  e.g.: I can generate 10 calls 
> and they all go through and complete successfully (with a total of 20 
> calls bring processed by the same Asterisk, due to both outbound and 
> inbound calls).
> 
> The problem arises If I bombard (i.e.: Write all the Originate requests 
> within about 7 seconds) the AMI to generate 97 outbound calls (for a 
> total of 194 channels).  The first Originate commands seem to get 
> processed,  but then all of a sudden (after Asterisk seems to have 
> started processing a good amount of my Originate requests already) 
> Asterisk seems to reset the AMI interface! Without even having a dropped 
> connection I receive a new "Asterisk Call Manager/1.3" string and then 
> previous commands that I issued start coming back with Response: Error 
> and Message: Permission denied.
> 
> I've enabled debugging and here's the security log output when I connect:
> 
> [Apr  1 12:43:25] SECURITY[9877] res_security_log.c: 
> SecurityEvent="SuccessfulAuth",EventTV="1396370605-551714",Severity="Informational",Service="AMI",EventVersion="1",AccountID="username",SessionID="0x7f0c540d96b8",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/192.168.1.62/52139",UsingPassword="0",SessionTV="1396370605-551710"
> 
> (This is the time when I am issuing commands, it is accepting and 
> processing them)
> 
> Then all of a sudden (when I receive a new "Asterisk Call Manager/1.3" 
> string and commands are rejected with "Permission denied") here is what 
> the log shows:
> 
> [Apr  1 12:44:36] SECURITY[9877] res_security_log.c: 
> SecurityEvent="RequestNotAllowed",EventTV="1396370676-876795",Severity="Error",Service="AMI",EventVersion="1",AccountID="",SessionID="0x7f0c54072968",LocalAddress="IPV4/TCP/0.0.0.0/5038",RemoteAddress="IPV4/TCP/192.168.1.62/52144",RequestType="Action: 
> Originate",SessionTV="0-0"
> 
> (Note: How the AccountID is now empty)
> 
> At this same time the CLI shows:
> 
>    == Manager '*****' logged off from 192.168.1.**

Why ***-out the username and part of the IP address when you've included
them both in the log messages above?

> ..yet it wasn't my application that disconnected and/or issued an 
> Action: logoff to Asterisk (my application doesn't even detect a 
> connection drop, so it seems like Asterisk just logs the manager user out!).
> 
> Why did Asterisk all of a sudden reset itself and/or lose reference to 
> the user I am authenticating with?

Just to be certain what is happening on the connection, set up a tcpdump
on the Asterisk box to capture the traffic into a file, then look at it
in wireshark. I find it easiest to create a suitable script:

root# cat capture-ami.sh
#!/bin/sh

DATE=`date '+%Y%m%d-%H%M%S'`
FILE=ami-`hostname -s`-$DATE.pkt

cd /var/tmp

tcpdump -C 8 -i any -n -p -s 0 -w $FILE tcp port 5038 </dev/null >/dev/null 2>&1 &
root# ./capture-ami.sh

Then when you have reproduced the problem, kill the tcpdump and copy the file
to a machine that has wireshark. You can then see exactly what is happening
at the time of the problem - whether it is initiated by your client program
doing something strange or by Asterisk.

Cheers
Tony

-- 
Tony Mountifield
Work: tony at softins.co.uk - http://www.softins.co.uk
Play: tony at mountifield.org - http://tony.mountifield.org