Asterisk Crash - Cannot Allocate Memory

Distro Discussion & Help
1

Hi,

I am using FreePBX Distro (1.87.29.55-2) and last night I experienced an asterisk crash. I will try to provide as much as information I can.

Server: Dell R510
Memory: 4GM

Asterisk has around 130 extensions registered. The part that asterisk crashed is

[2011-12-20 20:32:00] VERBOSE[31296] pbx.c: == Spawn extension (tc-maint, s, 4) exited non-zero on 'Local/s@tc-maint-fad3;2' [2011-12-20 20:32:00] NOTICE[31295] pbx_spool.c: Call failed to go through, reason (1) Hangup [2011-12-20 20:32:00] NOTICE[31295] pbx_spool.c: Queued call to Local/s@tc-maint expired without completion after 0 attempts [2011-12-20 20:33:00] WARNING[5558] pbx_spool.c: Unable to create thread :( (returned error: 12) [2011-12-20 20:35:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:36:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:38:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:39:51] WARNING[5221] pbx.c: Failed to create new channel thread [2011-12-20 20:39:51] WARNING[5221] sig_pri.c: Unable to start PBX on channel 0/15, span 3 [2011-12-20 20:39:51] DEBUG[5221] sig_pri.c: sig_pri_hangup 77 [2011-12-20 20:39:51] DEBUG[5221] sig_pri.c: Not yet hungup... Calling hangup once with icause, and clearing call [2011-12-20 20:39:51] VERBOSE[5221] chan_dahdi.c: -- Hungup 'DAHDI/i3/6944382533-1630' [2011-12-20 20:40:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:41:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:43:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:45:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:46:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:48:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:50:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:51:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:53:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:55:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:55:02] WARNING[4823] tcptls.c: Unable to launch helper thread: Cannot allocate memory [2011-12-20 20:56:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 20:58:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:00:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:01:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:02:01] WARNING[4823] tcptls.c: Unable to launch helper thread: Cannot allocate memory [2011-12-20 21:03:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:05:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:06:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:08:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:10:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:11:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:13:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:15:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:16:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:18:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:20:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:21:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:23:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:25:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:26:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:28:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:30:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:31:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:32:57] WARNING[5221] pbx.c: Failed to create new channel thread [2011-12-20 21:32:57] WARNING[5221] sig_pri.c: Unable to start PBX on channel 0/17, span 3 [2011-12-20 21:32:57] DEBUG[5221] sig_pri.c: sig_pri_hangup 79 [2011-12-20 21:32:57] DEBUG[5221] sig_pri.c: Not yet hungup... Calling hangup once with icause, and clearing call [2011-12-20 21:32:57] VERBOSE[5221] chan_dahdi.c: -- Hungup 'DAHDI/i3/2108971557-1631' [2011-12-20 21:33:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call' [2011-12-20 21:35:00] DEBUG[5558] pbx_spool.c: Delaying retry since we're currently running '/var/spool/asterisk/outgoing/schedtc.0.call'

And after this the log messages just repeat.

Why did this happen? Any help would be appreciated.

Thanks in advance

2

You have a memory issue. What does free -m show from the linux CLI

3

I need to make a correction. The Server has 8GB RAM but due to CentOS being 32bit it uses only 3GB.

free -m total used free shared buffers cached Mem: 3278 3128 149 0 212 2290 -/+ buffers/cache: 626 2652 Swap: 760 0 760

Also, this crash came after around 6days of usage.

4

There is your issue. Only 149 free. What is using all your ram. We run 400 extensions on 2Gb of ram no issues. You must have something running with a memory leak

5

I’ll recheck but from what I remember its the default installation of FreePBX Distro with Wanpipe and iSymphony (installed with yum).

Thank you

6

Just to update this after some research I found a possible problem,a memory leak at chan_iax2. The PBX has some IAX2 trunks and extensions and that might be the problem. I will make some changes I found on another forum at the IAX extensions and report back if the problem is solved.

Thanks,

7

Just an update on this subject. As it seems there are 2 open tickets at asterisk Jira

https://issues.asterisk.org/jira/browse/ASTERISK-17339
https://issues.asterisk.org/jira/browse/ASTERISK-17825

referring to a iax2 memory leak. So, the problem still remains. A temporary solution was to restart the whole server every 3 days.

8

Hello,

I am experiencing a similar issue, but on a different version of Asterisk and I don’t use IAX2 trunks.

Below are the relevant Asterisk packages:

asterisk18-addons.i386 1.8.8.0-1_centos5 installed
asterisk18-addons-bluetooth.i386 1.8.8.0-1_centos5 installed
asterisk18-addons-core.i386 1.8.8.0-1_centos5 installed
asterisk18-addons-mysql.i386 1.8.8.0-1_centos5 installed
asterisk18-addons-ooh323.i386 1.8.8.0-1_centos5 installed
asterisk18-core.i386 1.8.8.0-1_centos5 installed
asterisk18-curl.i386 1.8.8.0-1_centos5 installed
asterisk18-dahdi.i386 1.8.8.0-1_centos5 installed
asterisk18-doc.i386 1.8.8.0-1_centos5 installed
asterisk18-voicemail-imapstorage.i386 1.8.8.0-1_centos5 installed

And we are using the FreePBX distro CD for version 1.8.8 of Asterisk - 1.8.9 and newer, as of a couple weeks ago - contains a broken IMAP package, and we use a hosted IMAP service in the sky for UC on cell phones, Outlook, etc, so 1.8.8 is our best option. We had a similar issue this morning where our Asterisk server quit responding and it was restarted before I could look at it. Again, we do not use IAX2 trunks. We have 10 extensions and use time groups with time conditions to route phones to their business hours or after hours IVR, depending on what time it is. I haven’t noticed any memory issues, and everything has seemed to be fine thus far. However, I have the same errors in the log as what was posted previously. Below is a section of this log file:

[2012-05-01 07:23:56] VERBOSE[4106] pbx.c: – Executing [SIP_103@park-dial:1] Dial(“SIP/ICE-0000075d”, “SIP/103,30,t”) in new stack
[2012-05-01 07:23:56] VERBOSE[4106] netsock2.c: == Using SIP RTP TOS bits 184
[2012-05-01 07:23:56] VERBOSE[4106] netsock2.c: == Using SIP RTP CoS mark 5
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 106
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 105
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 103
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 100
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 101
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 102
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 107
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 104
[2012-05-01 07:23:56] VERBOSE[3960] chan_sip.c: == Extension Changed 71[park-hints] new state Idle for Notify User 1001
[2012-05-01 07:25:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:26:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:28:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:30:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:31:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:33:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:35:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:36:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:38:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:40:00] DEBUG[4963] pbx_spool.c: Delaying retry since we’re currently running ‘/var/spool/asterisk/outgoing/schedtc.1.call’
[2012-05-01 07:40:44] VERBOSE[3789] asterisk.c: Executing last minute cleanups
[2012-05-01 07:40:44] VERBOSE[3789] res_musiconhold.c: == Destroying musiconhold processes
[2012-05-01 07:40:44] VERBOSE[3789] asterisk.c: Asterisk uncleanly ending (0).
[2012-05-01 07:42:34] VERBOSE[3668] config.c: == Parsing ‘/etc/asterisk/asterisk.conf’: [2012-05-01 07:42:34] VERBOSE[3668] config.c: == Found
[2012-05-01 07:42:35] VERBOSE[3668] manager.c: == Manager registered action DataGet
[2012-05-01 07:42:35] VERBOSE[3668] loader.c: Asterisk Dynamic Loader Starting:

As you can see at 2012-05-01 07:25:00, Asterisk quit responding. The server was then restarted to free up the issue.

Also, here is the output of ‘free -m’ if that is of any importance:

         total       used       free     shared    buffers     cached

Mem: 2017 614 1402 0 31 248
-/+ buffers/cache: 335 1681
Swap: 760 0 760

9

I have two recently installed production systems that are crashing. I am going to open them up to any FreePBX developer who would like to test them. Or just give me some directions and I’ll post the results.