ASTERISK-21012: Memory Leak on res

[Home]

Summary: ASTERISK-21012: Memory Leak on res_calendar (icalendar)

Reporter: Joel Vandal (joel_vandal) Labels:

Date Opened: 2013-01-29 19:57:38.000-0600 Date Closed: 2013-01-30 08:18:58.000-0600

Priority: Major Regression?

Status: Closed/Complete Components: Resources/res_calendar_icalendar

Versions: 1.8.20.1 Frequency of
Occurrence Constant

Related
Issues:

Environment: Asterisk 1.8.20.1 running on CentOS 5.8 (x86_64) Attachments: ( 0) ASTERISK-21012.diff
( 1) valgrind.txt

Description: Have a server where Asterisk memory usage grow to ~8gb per 24 hours.

I start Asterisk and after few minutes, I start to see memory changes.

After some debugging, I've pinpoint the issue to Calendar modules and if I remove all res_calendar_* files then memory usage is normal.

I've rebuild Asterisk with MALLOC_DEBUG and DONT_OPTIMIZE ..

Here a partial log of valgrind started with :

valgrind -v --track-origins=yes --leak-check=full --show-reachable=yes --suppressions=/root/valgrind.supp --log-fd=9 asterisk -vvvvcg 9> valgrind.txt

==27030== 2,835,600 bytes in 70,890 blocks are indirectly lost in loss record 3,827 of 3,844
==27030== at 0x4A0610C: malloc (vg_replace_malloc.c:195)
==27030== by 0x1278D34D: pvl_newlist (pvl.c:72)
==27030== by 0x1277F1F3: icalproperty_new_impl (icalproperty.c:111)
==27030== by 0x1277D5EA: icalparser_add_line (icalparser.c:830)
==27030== by 0x1277DECC: icalparser_parse (icalparser.c:621)
==27030== by 0x1277E010: icalparser_parse_string (icalparser.c:1285)
==27030== by 0x1BA45359: fetch_icalendar (res_calendar_icalendar.c:156)
==27030== by 0x1BA46CD8: ical_load_calendar (res_calendar_icalendar.c:471)
==27030== by 0x5202DC: dummy_start (in /usr/sbin/asterisk18)
==27030== by 0x37DB60683C: start_thread (in /lib64/libpthread-2.5.so)
==27030== by 0x37DA6D503C: clone (in /lib64/libc-2.5.so)

...

==27030== 16,816,205 (280 direct, 16,815,925 indirect) bytes in 5 blocks are definitely lost in loss record 3,844 of 3,844
==27030== at 0x4A0610C: malloc (vg_replace_malloc.c:195)
==27030== by 0x1277F1D9: icalproperty_new_impl (icalproperty.c:103)
==27030== by 0x1277D5EA: icalparser_add_line (icalparser.c:830)
==27030== by 0x1277DECC: icalparser_parse (icalparser.c:621)
==27030== by 0x1277E010: icalparser_parse_string (icalparser.c:1285)
==27030== by 0x1BA45359: fetch_icalendar (res_calendar_icalendar.c:156)
==27030== by 0x1BA46CD8: ical_load_calendar (res_calendar_icalendar.c:471)
==27030== by 0x5202DC: dummy_start (in /usr/sbin/asterisk18)
==27030== by 0x37DB60683C: start_thread (in /lib64/libpthread-2.5.so)
==27030== by 0x37DA6D503C: clone (in /lib64/libc-2.5.so)
==27030==
==27030== LEAK SUMMARY:
==27030== definitely lost: 1,926 bytes in 79 blocks
==27030== indirectly lost: 28,121,308 bytes in 419,674 blocks
==27030== possibly lost: 117,010,929 bytes in 1,463,484 blocks
==27030== still reachable: 11,224,116 bytes in 158,313 blocks
==27030== suppressed: 0 bytes in 0 blocks
==27030==
==27030== ERROR SUMMARY: 127637 errors from 1718 contexts (suppressed: 748 from 7)
==27030==

Comments: By: Joel Vandal (joel_vandal) 2013-01-29 20:02:09.082-0600

Also, I only have 2 calendar defined :

cat /etc/asterisk/calendar.conf
;
; DESCRIPTION: Configuration for Asterisk
; GENERATOR: ScopServ-VoIP v2.0
; TIMESTAMP: 2013-01-29 17:11:32
;

[calendar_scopserv_302]
type = ical
url = https://www.google.com/calendar/ical/*****/basic.ics
user = sysadmin@****.net
secret =
refresh = 15
timeframe = 60
channel = SIP/302
context = scopserv
extension = 302

[calendar_scopserv_301]
type = ical
url = https://www.google.com/calendar/ical/************/basic.ics
user = ******@gmail.com
secret =
refresh = 1
timeframe = 60
channel = Local/301@scopserv-local-devices
context = scopserv
extension = 301

By: Matt Jordan (mjordan) 2013-01-29 20:28:12.471-0600

Thanks for running this under valgrind. That makes it a *lot* easier to find the problem.

Try the attached patch (ASTERISK-21012.patch) - it looks like we weren't properly disposing of the calendar data before fetching it from the server.

By: Joel Vandal (joel_vandal) 2013-01-29 20:33:00.687-0600

Testing right now ! Pretty fast fix :)
By: Matt Jordan (mjordan) 2013-01-29 20:47:27.980-0600

Valgrind traces help a lot :-)
By: Joel Vandal (joel_vandal) 2013-01-29 20:53:19.523-0600

Still have memory leak. Here the complete valgrind file.
By: Joel Vandal (joel_vandal) 2013-01-29 21:01:55.895-0600

Maybe I'm wrong and I misread the valgrind output... memory usage for asterisk process is low for now, will check tomorrow after a ~8 hours run time.

11117 scopserv 15 0 877m 68m 12m S 0.0 0.9 0:04.97 /usr/sbin/asterisk -f -vvvg -c

By: Matt Jordan (mjordan) 2013-01-29 21:10:01.827-0600

Nope, it's definitely still leaking. I think there's something a bit larger at work, as it isn't just the icalendar data leaking - the ne_session is also leaking. That implies that the whole calendar pvt is lurking around.

Are you causing the memory leak by issues a module reload?
By: Joel Vandal (joel_vandal) 2013-01-30 07:38:15.655-0600

IMHO the problem is fixed, memory increase in ~10 hours is very small (less than 5mb). Without the patch, asterisk process used about 4GB or memory.

Yesterday : 11117 scopserv 15 0 877m 68m 12m S 0.0 0.9 0:04.97 /usr/sbin/asterisk -f -vvvg -c

This morning: 11117 scopserv 15 0 883m 75m 12m S 0.0 1.0 2:49.67 /usr/sbin/asterisk -f -vvvg -c

So 5mb vs 4gb of memory for same period and server usage made me thinking that your patch is fully working and that can be commited.
By: Matt Jordan (mjordan) 2013-01-30 07:52:00.978-0600

Hm. I'm still a bit concerned about the rest, but okay. With MALLOC_DEBUG enabled, you should get a dump of offending memory allocations when you exit Asterisk, so if the 5 mb is actually being leaked, that should tell us.

I'll go ahead and commit/close the issue, but if the problem persists or gets worse, let me know and I'll reopen.