See latest HEAD and patch in FS-6006 It seems in some conditions the code around state transitions that is supposed to parse the signal data makes it past there. The new 1 line patch adds a parse_all_messages in the heart of the state machine where it is executed every time the state machine sets a new running state. I was able to lab up a bye glare scenario with sipp where I could reproduce the queued_events bug in 1 second flat with 200 simo calls. After this patch I was able to run the same test for 20000 calls without triggering any delta in the queued_events On Mon, Dec 9, 2013 at 9:26 PM, David Sanders <dsanders@pinger.com> wrote:
I've dug into this more after suggestions from Anthony and others in IRC, and reproduced against 1.2.stable.
I think there's a couple of leak cases, but I've got one large one which I'll go into further.
Our main use case is bridging audio, and most of the leaks reference leg B. After tracking down some more SIP for leaked calls, with timestamps, I can see that the leak appears to happen if events happen nearly simultaneously on leg A and leg B. One example would be both legs saying BYE (bye glare) at the same time. Another example I saw was a CANCEL coming in on leg A at the same time as a 200 OK on leg B.
My current theory is that any events in the signal data queue for leg B will get leaked, and in turn leak references to the nua_handle_t. I can't find any code which 'pumps' the signal data queue on session destroy. To prevent the leak, I think this needs to happen. The events don't need to be processed since the session is being destroyed, but they should be pumped out of the signal data queue, free'd, and their reference to the handle should be released.
Logically it makes sense that most of the leaked events I observed would be 100 BYE Trying, since simultaneous BYE is probably the most likely case for the race condition to occur in.
As per Anthony's suggestion, I added trace to where the events are queued, and to where they are processed. Grepping the logs I gathered from a 24 hour test run, I can see discrepancies between queued and processed, just by event types.
I've created the table below to illustrate the difference in events queued vs processed that I'm seeing. I'm only using one SIP profile, and I can see in memory that 'queued_events' on the struct = 87. The table adds up to -85, so there's likely one event type I didn't notice in my trace.
+------------------+--------+----------+-----------+------+ | event | status | in count | out count | diff | +------------------+--------+----------+-----------+------+ | nua_i_active | 200 | 86717 | 86711 | -6 | | nua_i_invite | 100 | 77054 | 77054 | -1 | | nua_i_terminated | 200 | 32588 | 32588 | 0 | | nua_i_terminated | 487 | 29156 | 29155 | -1 | | nua_i_state | 0 | 45443 | 45443 | 0 | | nua_i_state | 180 | 73921 | 73917 | -4 | | nua_i_state | 200 | 206908 | 206898 | -10 | | nua_i_state | 487 | 29156 | 29155 | -1 | | nua_r_invite | 180 | 2411 | 2411 | 0 | | nua_r_invite | 183 | 36423 | 36418 | -5 | | nua_r_invite | 200 | 32075 | 32071 | -4 | | nua_r_invite | 408 | 1543 | 1543 | 0 | | nua_r_invite | 486 | 2479 | 2479 | 0 | | nua_r_cancel | 200 | 9099 | 9099 | 0 | | nua_r_bye | 200 | 32491 | 32491 | 0 | | nua_i_bye | 100 | 52363 | 52310 | -53| +------------------+--------+----------+-----------+------+
- David
On 12/6/13 12:20 PM, David Sanders wrote:
I've been trying to track down and kill a memory leak which is occurring in mod_sofia/Sofia-SIP. The leak was first spotted under 1.2.0 and confirmed to still exist in 1.2.14 (latest when it was tested about a month ago).
Two JIRA bugs were submitted as part of this hunt, FS-6005 and FS-6006. The issue improved on 1.2.0 after the patches for those two bugs, but showed no difference on 1.2.14.
The leak only seems to occur under heavy load (i.e. production traffic), but will produce several leaks within 24 hours of a FS restart. Gory details follow.
Things known about the leak: * The leaked memory is a nua_handle_t struct, and the associated structs which are free'd properly if the nua_handle_t doesn't leak * The box running FS is a CentOS 6.3 machine, Linux kernel version 2.6.32-279 * Leak can be analyzed on an idle FS server using GDB + a modified version of gdb-heap (an extension for GDB for viewing the heap) * Once leaked memory is identified, it can be printed with GDB as the nua_handle_t struct and data can be gleaned from it
After the patches mentioned above, 1.2.0 has several handles leaked, all with a sofia_dispatch_event_t struct in their memory pool, indicating a 100 BYE Trying event. Since this event was never processed (and free'd) it never decremented the ref count on the handle. The handle is marked as destroyed, so the ref count is the only thing keeping it around.
On 1.2.14, it acted the same prior to FS-6006's patch. After that patch was applied, the leak mutated. The idle box lists no calls and no channels, but the leaked handles are not marked as destroyed, have nh_active_call=1, and have a ref count of 3.
Prior to FS-6006 it was clear with ref trace enabled for mod_sofia that the missing unref was due to the 100 BYE Trying never being processed. I'll have to re-enable the ref trace to see why there are now 3 references left after FS-6006.
Here's a Valgrind entry for the leaked memory (this is from a 1.2.14 instance):
==28083== 22,980 (1,120 direct, 21,860 indirect) bytes in 4 blocks are definitely lost in loss record 448 of 453 ==28083== at 0x4C2677B: calloc (vg_replace_malloc.c:593) ==28083== by 0xBA60CC1: su_home_new (su_alloc.c:559) ==28083== by 0xBA0D8F5: nh_create_handle (nua_common.c:113) ==28083== by 0xBA2AA2A: nua_handle (nua.c:315) ==28083== by 0xB9AAD38: sofia_glue_do_invite (sofia_glue.c:2357) ==28083== by 0xB9729CC: sofia_on_init (mod_sofia.c:108) ==28083== by 0x5138702: switch_core_session_run (switch_core_state_machine.c:424) ==28083== by 0x5134D8D: switch_core_session_thread (switch_core_session.c:1417) ==28083== by 0x596C850: start_thread (in /lib64/libpthread-2.12.so) ==28083== by 0x6AEB11C: clone (in /lib64/libc-2.12.so)
I've exhausted my ability to debug the issue, and could use some help from the FS maintainers/community in killing the issue. The leaked memory, while small, appears to cause rather large performance problems for the FS instance if allowed to accumulate.
- David
P.S. I'll be on the freeswitch-dev IRC channel if anyone would like to discuss more details of the leak.
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
-- Anthony Minessale II ☞ http://www.freeswitch.org/ ☞ http://www.cluecon.com/ ☞ http://twitter.com/FreeSWITCH ☞ irc.freenode.net #freeswitch ClueCon Weekly Development Call ☎ sip:888@conference.freeswitch.org ☎ +19193869900