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

[Olle E. Johansson]

On 06 May 2014, at 16:11, 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.
> 
> 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.**
> 
> ..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?
> 
> Note: My maxcalls setting within asterisk.conf was set to default. I even tried upping it to 200 and that didn't help.  My maxload setting was untouched/commented out and therefore set to default (no threshold).  I still tried upping it to 6.0, 8.0 and 10.0 to no avail.  I even uncommented minmemfree and set it to 256 (although calling free -m from a terminal showed their to always be plenty of memory on my system).
> 
> Does anyone have an idea how to fix/correct this?

One thing you have to be aware of is that Action:s are atomic. You have to wait for the response of one action before you send the next one. Otherwise they will all end up in the TCP buffer. That's propably what you see - a lot of queued up messages being red after the tcp connection is reset. 

That doesn't explain why something resets and send you a new connect message and possibly requires a new login. That seems like a bug that needs to be reported. Can you easily repeat this?

Just my 5 öre. Anyone else with good comments on this?
/O