[Home]

Summary:ASTERISK-00527: iax2 channel is sometimes not freed.
Reporter:zoa (zoa)Labels:
Date Opened:2003-11-14 07:46:15.000-0600Date Closed:2004-09-25 02:49:15
Priority:BlockerRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) ls.txt
Description:I use SIP to connect 200 users to an asterisk server with iLBC, (xlite clients).
That servers forwards (stays  iLBC) all calls to another asterisk server for termination.

Normally the first server has a load of 0,0 after a lot of simultaneous calls and an hour of time, suddenly the load goes to 37 and asterisk seems to hang.
(reload not doing a thing)


chan_iax2.so         Inter Asterisk eXchange (Ver 2)          14



****** ADDITIONAL INFORMATION ******

When doing a show modules, chan_iax2.so usage seems to increase over time,

chan_iax2.so         Inter Asterisk eXchange (Ver 2)          14

--> i only had 2 simultaneous calls at that time.

It sometimes does decrease, but i dont think it gets freed every time.

There are no special extensions used, just dial(IAX2).
Comments:By: Brian West (bkw918) 2003-11-14 10:02:33.000-0600

Yes I have noticed this behavior also.  I didn't think twice because it doesn't cause iax2 to be impaired in functionality... granted its still a problem and needs to be fixed.  So I can confirm this bug.

bkw
By: zoa (zoa) 2003-11-14 10:06:00.000-0600

it is causing asterisk to stop once you go over the 1024 limit i think, when piping errors and open file limits occur.
By: Mark Spencer (markster) 2003-11-14 10:08:06.000-0600

Does iax2 show channels still show channels?  What about "show channels"?  can you confirm with ls /proc/<pid of asterisk>/fd | wc -l that the number of open fd's is actually increasing?
By: zoa (zoa) 2003-11-14 10:17:00.000-0600

iax2 does not show that amount of channels, only the ones that are in uses.

i didnt try /proc/ thingie, will be back tomorrow.

i never experienced the problem on the server that is receiving the iax2 calls, only on the server that is sending them.

running on a dual xeon 2.4 raid 5 15krpm disks & intel mb.

lsof | wc -l also seems to show a lot of open files, i cannot ask a lot of people to call with it atm, but will do so tomorrow.

I sometimes see this in /var/log/asterisk/messages, maybe its related.

Nov 12 18:47:45 WARNING[10251]: File rtp.c, Line 683 (ast_rtcp_new): Unable to allocate socket: Too many open files
Nov 12 18:47:46 WARNING[10251]: File rtp.c, Line 683 (ast_rtcp_new): Unable to allocate socket: Too many open files
Nov 12 18:47:46 WARNING[10251]: File rtp.c, Line 683 (ast_rtcp_new): Unable to allocate socket: Too many open files
By: zoa (zoa) 2003-11-14 10:17:38.000-0600

i am not using any agi scripts on that server, and its a dedicated asterisk machine.
By: zoa (zoa) 2003-11-14 10:18:41.000-0600

running todays cvs, also tried it with cvs of some days ago, never tried it with that many people before, so cant tell if the bug also existed in previous cvs versions.
By: Mark Spencer (markster) 2003-11-14 10:29:46.000-0600

If you do ls -l /proc/<pid of asterisk>/fd, what are most of the fd's?
By: Mark Spencer (markster) 2003-11-14 10:36:47.000-0600

I mean on his box with the leaking.  yours looks fine.
By: zoa (zoa) 2003-11-15 06:40:48.000-0600

scxgk3:~# ls -l /proc/9592/fd | wc -l
    52
scxgk3:~# ls -l /proc/9593/fd | wc -l
    42
scxgk3:~# ls -l /proc/9594/fd | wc -l
    42
scxgk3:~# ls -l /proc/9595/fd | wc -l
    42
scxgk3:~# ls -l /proc/9596/fd | wc -l
    42
scxgk3:~# ls -l /proc/9597/fd | wc -l
    34
scxgk3:~# ls -l /proc/9598/fd | wc -l
    34
scxgk3:~# ls -l /proc/9599/fd | wc -l
     6
scxgk3:~# ls -l /proc/9600/fd | wc -l
    52
scxgk3:~# ls -l /proc/9604/fd | wc -l
    34
scxgk3:~# ls -l /proc/9608/fd | wc -l
    34
scxgk3:~# ls -l /proc/9609/fd | wc -l
    42
scxgk3:~# ls -l /proc/9613/fd | wc -l
    50
scxgk3:~# ls -l /proc/9614/fd | wc -l
    50
scxgk3:~# ls -l /proc/9615/fd | wc -l
    50
scxgk3:~# ls -l /proc/9616/fd | wc -l
    50
scxgk3:~# ls -l /proc/9617/fd | wc -l
    50
scxgk3:~# ls -l /proc/9618/fd | wc -l
    42
scxgk3:~# ls -l /proc/9619/fd | wc -l
    42
scxgk3:~# ls -l /proc/9620/fd | wc -l
    34
scxgk3:~# ls -l /proc/9671/fd | wc -l
    52
scxgk3:~# ls -l /proc/10554/fd | wc -l
    42

I took the box out of production, only very few calls are being made on the box atm (max two at the same time), but its still increasing :)

chan_iax2.so         Inter Asterisk eXchange (Ver 2)          114

ls -l /proc/9671/fd


total 0
lr-x------    1 root     root           64 Nov 15 16:32 0 -> /dev/tty9
l-wx------    1 root     root           64 Nov 15 16:32 1 -> /dev/tty9
lr-x------    1 root     root           64 Nov 15 16:32 10 -> /dev/zap/pseudo
lr-x------    1 root     root           64 Nov 15 16:32 11 -> pipe:[46513799]
lr-x------    1 root     root           64 Nov 15 16:32 12 -> pipe:[46513800]
lr-x------    1 root     root           64 Nov 15 16:32 13 -> /dev/zap/pseudo
lr-x------    1 root     root           64 Nov 15 16:32 14 -> pipe:[46513798]
lr-x------    1 root     root           64 Nov 15 16:32 15 -> pipe:[46513801]
lr-x------    1 root     root           64 Nov 15 16:32 16 -> /dev/zap/pseudo
lrwx------    1 root     root           64 Nov 15 16:32 17 -> socket:[46584905]
lrwx------    1 root     root           64 Nov 15 16:32 18 -> socket:[46513811]
lrwx------    1 root     root           64 Nov 15 16:32 19 -> /var/lib/asterisk/astdb
l-wx------    1 root     root           64 Nov 15 16:32 2 -> /dev/tty9
lrwx------    1 root     root           64 Nov 15 16:32 20 -> socket:[46513812]
lrwx------    1 root     root           64 Nov 15 16:32 21 -> socket:[46513848]
lrwx------    1 root     root           64 Nov 15 16:32 22 -> /dev/zap/timer
lrwx------    1 root     root           64 Nov 15 16:32 23 -> /dev/zap/channel
lrwx------    1 root     root           64 Nov 15 16:32 24 -> socket:[46584906]
lr-x------    1 root     root           64 Nov 15 16:32 25 -> pipe:[46584907]
l-wx------    1 root     root           64 Nov 15 16:32 26 -> pipe:[46584907]
lrwx------    1 root     root           64 Nov 15 16:32 27 -> /dev/zap/timer
lr-x------    1 root     root           64 Nov 15 16:32 28 -> pipe:[46584908]
l-wx------    1 root     root           64 Nov 15 16:32 29 -> pipe:[46584908]
lrwx------    1 root     root           64 Nov 15 16:32 3 -> socket:[46513795]
lrwx------    1 root     root           64 Nov 15 16:32 30 -> /dev/zap/timer
lrwx------    1 root     root           64 Nov 15 16:32 31 -> socket:[46584931]
lrwx------    1 root     root           64 Nov 15 16:32 32 -> socket:[46584932]
lr-x------    1 root     root           64 Nov 15 16:32 33 -> pipe:[46584933]
lrwx------    1 root     root           64 Nov 15 16:32 34 -> socket:[46522410]
lrwx------    1 root     root           64 Nov 15 16:32 35 -> socket:[46522411]
lrwx------    1 root     root           64 Nov 15 16:32 36 -> socket:[46522412]
l-wx------    1 root     root           64 Nov 15 16:32 37 -> pipe:[46584933]
lrwx------    1 root     root           64 Nov 15 16:32 38 -> /dev/zap/timer
lr-x------    1 root     root           64 Nov 15 16:32 39 -> pipe:[46584934]
lr-x------    1 root     root           64 Nov 15 16:32 4 -> pipe:[46513797]
l-wx------    1 root     root           64 Nov 15 16:32 40 -> pipe:[46584934]
lrwx------    1 root     root           64 Nov 15 16:32 41 -> /dev/zap/timer
lrwx------    1 root     root           64 Nov 15 16:32 42 -> socket:[46514659]
lrwx------    1 root     root           64 Nov 15 16:32 43 -> socket:[46514660]
lrwx------    1 root     root           64 Nov 15 16:32 44 -> socket:[46514661]
lrwx------    1 root     root           64 Nov 15 16:32 47 -> socket:[46513849]
lr-x------    1 root     root           64 Nov 15 16:32 48 -> /var/run/autodial.ctl
lr-x------    1 root     root           64 Nov 15 16:32 49 -> pipe:[46513841]
l-wx------    1 root     root           64 Nov 15 16:32 5 -> pipe:[46513797]
l-wx------    1 root     root           64 Nov 15 16:32 50 -> pipe:[46513841]
l-wx------    1 root     root           64 Nov 15 16:32 6 -> /var/log/asterisk/event_log
l-wx------    1 root     root           64 Nov 15 16:32 7 -> /var/log/asterisk/debug
l-wx------    1 root     root           64 Nov 15 16:32 8 -> /var/log/asterisk/messages
lr-x------    1 root     root           64 Nov 15 16:32 9 -> /dev/zap/pseudo
By: Mark Spencer (markster) 2003-11-17 11:24:24.000-0600

you know, your ast_rtcp_new() issue suggests this could be related to SIP channels. Are you sure this is iax2 and not sip?

what does:

iax2 show channels
and

sip show channels

say when it gets bad?
By: zoa (zoa) 2003-11-17 13:57:14.000-0600

to be honest, i dont really know.
That was my idea too in the beginning as i heard JerJer has no issues using a lot of iax2 calls.

however, im unable to check any show channels when cpu load goes up to 37 as asterisk stops responding. (just shows CLI> again whatever command i type in the cli)

the show modules never shows a lot of sip modules in use, only iax2 channels.
all sip users use the same username and pw, dont know it this could cause such a behaviour ?
By: zoa (zoa) 2003-11-17 14:11:18.000-0600

chan_iax2.so         Inter Asterisk eXchange (Ver 2)          6857
chan_agent.so        Agent Proxy Channel                      0
chan_modem_i4l.so    ISDN4Linux Emulated Modem Driver         0
chan_modem_bestdata.so BestData (Conexant V.90 Chipset) VoiceMo 0
chan_oss.so          OSS Console Channel Driver               0
chan_sip.so          Session Initiation Protocol (SIP)        0
chan_iax.so          Inter Asterisk eXchange                  29

so its not blocking after 6857 anyway, maybe i should give you axx to the box and let 60 people call concurrently ?
By: Mark Spencer (markster) 2003-11-17 14:19:35.000-0600

The usage numbers are meaningless in this case.  *please* try the commands I suggested (iax2 show channels, sip show channels, and the ls -l in /proc/<pid of *>/fd.  You may attach the LS as an attachment if you prefer.
By: zoa (zoa) 2003-11-18 11:10:58.000-0600

i just uploaded the thing you asked.

sip show channels & show iax2 channels shows nothing, the cli is no longer responding.

except for a lot of messages like the following, nothing weird shows up in /var/log/asterisk/messages:

Nov 18 19:04:28 WARNING[11276]: File chan_iax2.c, Line 3998 (socket_read): Received trunked frame before first full voice frame
Nov 18 19:04:28 WARNING[11276]: File chan_iax2.c, Line 3998 (socket_read): Received trunked frame before first full voice frame
Nov 18 19:04:29 WARNING[11276]: File chan_iax2.c, Line 3998 (socket_read): Received trunked frame before first full voice frame
Nov 18 19:04:29 WARNING[11276]: File chan_iax2.c, Line 3998 (socket_read): Received trunked frame before first full voice frame
Nov 18 19:04:29 WARNING[11276]: File chan_iax2.c, Line 3998 (socket_read): Received trunked frame before first full voice frame
Nov 18 19:04:29 WARNING[11276]: File chan_iax2.c, Line 3998 (socket_read): Received trunked frame before first full voice frame
Nov 18 19:04:29 WARNING[11276]: File chan_iax2.c, Line 3998 (socket_read): Received trunked frame before first full voice frame
By: zoa (zoa) 2003-11-18 12:48:48.000-0600

scxgk3:/var/log/asterisk# lsof | wc -l
119986
By: zoa (zoa) 2003-11-18 13:05:00.000-0600

gdb output:

<snip>

Loaded symbols for /usr/lib/asterisk/modules/app_hasnewvoicemail.so
Reading symbols from /usr/lib/asterisk/modules/app_sayunixtime.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_sayunixtime.so
Reading symbols from /usr/lib/asterisk/modules/app_cut.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_cut.so
Reading symbols from /usr/lib/asterisk/modules/app_read.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_read.so
Reading symbols from /usr/lib/asterisk/modules/app_zapras.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_zapras.so
Reading symbols from /usr/lib/asterisk/modules/app_meetme.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_meetme.so
Reading symbols from /usr/lib/asterisk/modules/app_flash.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_flash.so
Reading symbols from /usr/lib/asterisk/modules/app_zapbarge.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_zapbarge.so
0x08051ad3 in ast_sched_add (con=0x4023a1a8, when=0,
   callback=0x4056b500 <send_ping>, data=0x4) at sched.c:167
167                     if (SOONER(s->when, current->when))
(gdb)


scxgk3:/var/log/asterisk# lsof | cut -c67-|egrep -v "^/|pipe" | wc
81492   37868  238409


147 asterisk threads currently running.
By: zoa (zoa) 2003-11-18 13:13:29.000-0600

Loaded symbols for /usr/lib/asterisk/modules/app_meetme.so
Reading symbols from /usr/lib/asterisk/modules/app_flash.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_flash.so
Reading symbols from /usr/lib/asterisk/modules/app_zapbarge.so...done.
Loaded symbols for /usr/lib/asterisk/modules/app_zapbarge.so
ast_sched_del (con=0x4023a1a8, id=1987566) at sched.c:271
271      

when gdb -p asterisk_thread_id

strace not showing anything....
By: zoa (zoa) 2003-11-25 14:36:53.000-0600

Markster had a look at the server and added some locking in ast_sched_add & ast_sched_del.

I tried it for 3 hours with a constant load of 20 to 30 simultaneous calls.
Server kept running.

Bug seems fixed, although show modules still has weird behaviour. (probably not related to the deadlock problem).

Bugfix is already in cvs, bugnote can be closed.

Thnx Markster !
By: zoa (zoa) 2003-11-25 14:37:02.000-0600

Markster had a look at the server and added some locking in ast_sched_add & ast_sched_del.

I tried it for 3 hours with a constant load of 20 to 30 simultaneous calls.
Server kept running.

Bug seems fixed, although show modules still has weird behaviour. (probably not related to the deadlock problem).

Bugfix is already in cvs, bugnote can be closed.

Thnx Markster !
By: Brian West (bkw918) 2003-11-25 14:45:19.000-0600

Fixed in CVS