app_unimrcp: Crashing in speech_channel_destroy

[Evan]

Hey everyone,

We've got a strange segfault issue: we can run our UniMRCP doing TTS for quite a while, but after ~2000 translations we started getting segfaults in Asterisk. It has crashed several different places, but all of them seem to be related to modifying schannel->name.

We're preloading app_unimrcp in Asterisk but not using res_speech or res_speech_unimrcp.

System is CentOS 5.8, unimrcp-deps 1.1.2, Asterisk 1.8.11.0

Here are the backtrace's for two (the first is *much* more common) kinds of segfaults we're getting:
-----------
Program terminated with signal 11, Segmentation fault.
#0  speech_channel_destroy (schannel=0xf6b5658) at app_unimrcp.c:2063
2063            schannel->name = NULL;
#0  speech_channel_destroy (schannel=0xf6b5658) at app_unimrcp.c:2063
        __PRETTY_FUNCTION__ = "speech_channel_destroy"
#1  0x00002aaaaaabd384 in app_synth_exec (chan=0x2aaac8043ee8, data=<value optimized out>) at app_unimrcp.c:4704
        dtmf_enable = 1
        f = 0xa0
        fr = {frametype = AST_FRAME_VOICE, subclass = {integer = 4, codec = 4}, datalen = 160, samples = 160, mallocd = 0,
          mallocd_hdr_len = 0, offset = 64, src = 0x2aaaaaac0887 "app_synth_exec", data = {ptr = 0x4da04080, uint32 = 1302347904,
            pad = "\200@\240M\000\000\000"}, delivery = {tv_sec = 0, tv_usec = 0}, frame_list = {next = 0x0}, flags = 0, ts = 0, len = 0,
          seqno = 0}
        next = {tv_sec = 1335506424, tv_usec = 243134}
        dobreak = 124
        ms = <value optimized out>
        len = 160
        rres = <value optimized out>
        schannel = 0xf6b5658
        profile_name = 0xa0 <Address 0xa0 out of bounds>
        speech_channel_number = 4710
        name = "TTS-4710", '\000' <repeats 191 times>
        fp = 0x0
        dtmfkey = 4
        res = 0
        args = {argc = 2, argv = 0x4da05788,
          text = 0x4da03f90 "<speak xmlns=\"http://www.w3.org/2001/10/synthesis\" version=\"1.0\" xml:lang=\"en-US\"> <voice name=\"Kate\"> <prosody rate=\"1.0\">You selected Your pouridge was too hot. Is this correct?</prosody> </voice> <"..., options = 0x4da04060 "i=any"}
        option_profile = '\000' <repeats 255 times>
        option_prate = '\000' <repeats 31 times>
        option_pvolume = '\000' <repeats 31 times>
        option_interrupt = "0123456789#*ABCD", '\000' <repeats 47 times>
        option_filename = '\000' <repeats 383 times>
        option_language = '\000' <repeats 15 times>
        option_loadlexicon = '\000' <repeats 15 times>
        option_voicename = '\000' <repeats 127 times>
        option_voicegender = '\000' <repeats 15 times>
        option_voiceage = '\000' <repeats 31 times>
        option_voicevariant = '\000' <repeats 127 times>
        owriteformat = <value optimized out>
        __PRETTY_FUNCTION__ = "app_synth_exec"
----------------

Program terminated with signal 11, Segmentation fault.
#0  audio_queue_destroy (queue=0xbd00be8) at app_unimrcp.c:873
873                queue->pool = NULL;
#0  audio_queue_destroy (queue=0xbd00be8) at app_unimrcp.c:873
        name = 0xbd00bd8 <Address 0xbd00bd8 out of bounds>
        __PRETTY_FUNCTION__ = "audio_queue_destroy"
#1  0x00002aaaaaab4d4f in speech_channel_destroy (schannel=0xba43978) at app_unimrcp.c:2038
        __PRETTY_FUNCTION__ = "speech_channel_destroy"
#2  0x00002aaaaaabc384 in app_synth_exec (chan=0xbb66dc8, data=<value optimized out>) at app_unimrcp.c:4704
        dtmf_enable = 1
        f = 0xa0
        fr = {frametype = AST_FRAME_VOICE, subclass = {integer = 4, codec = 4}, datalen = 160, samples = 160, mallocd = 0,
          mallocd_hdr_len = 0, offset = 64, src = 0x2aaaaaabf887 "app_synth_exec", data = {ptr = 0x40d43080, uint32 = 1087647872,
            pad = "\200\060\324@\000\000\000"}, delivery = {tv_sec = 0, tv_usec = 0}, frame_list = {next = 0x0}, flags = 0, ts = 0, len = 0,
          seqno = 0}
        next = {tv_sec = 1335504259, tv_usec = 760639}
        dobreak = 124
        ms = <value optimized out>
        len = 160
        rres = <value optimized out>
        schannel = 0xba43978
        profile_name = 0xa0 <Address 0xa0 out of bounds>
        speech_channel_number = 1838
        name = "TTS-1838", '\000' <repeats 191 times>
        fp = 0x0
        dtmfkey = 4
        res = 0
        args = {argc = 2, argv = 0x40d44788,
          text = 0x40d42f30 "<speak xmlns=\"http://www.w3.org/2001/10/synthesis\" version=\"1.0\" xml:lang=\"en-US\"> <voice name=\"Kate\"> <prosody rate=\"1.0\">Hello Goldy Locks Press 1 for Your pouridge was too cold. Press 2 for Your po"..., options = 0x40d43052 "i=any"}
        option_profile = '\000' <repeats 255 times>
        option_prate = '\000' <repeats 31 times>
        option_pvolume = '\000' <repeats 31 times>

[Arsen Chaloyan]

Hi Evan,

As you may know, the Asterisk module app_unimrcp has been externally
developed and contributed to the project. From what I can see, many
are using this module in different projects. Even though, I'm a bit
surprised with the problem your backtraces clearly point out. And the
problem is in the usage of objects allocated from memory pools. On one
side, the following fragment of code is quite legitimate.

if (buffer->pool != NULL) {
apr_pool_destroy(buffer->pool);
buffer->pool = NULL;
}

However, if the buffer itself is allocated from the memory pool being
destroyed, setting buffer->pool to NULL thereafter can very easily
cause a segfault. I guess we all may fall into the same traps, it
happens... Anyway, I've noticed and fixed the same problem in a couple
of places in app_unimrcp.c. The patch goes below. Please give it a
try. Sorry, I haven't tried to even compile it yet.



--- app_unimrcp.c-revBASE Fri Dec 10 05:49:44 2010
+++ app_unimrcp.c Mon Apr 30 19:51:48 2012
@@ -749,15 +749,8 @@

static void audio_buffer_destroy(audio_buffer_t *buffer)
{
- if (buffer != NULL) {
- if (buffer->pool != NULL) {
- apr_pool_destroy(buffer->pool);
- buffer->pool = NULL;
- }
-
- buffer->data = NULL;
- buffer->datalen = 0;
- buffer->used = 0;
+ if (buffer != NULL && buffer->pool != NULL) {
+ apr_pool_destroy(buffer->pool);
}
}

@@ -868,17 +861,15 @@
queue->mutex = NULL;
}

- if (queue->pool != NULL) {
- apr_pool_destroy(queue->pool);
- queue->pool = NULL;
- }
-
queue->name = NULL;
queue->read_bytes = 0;
queue->waiting = 0;
queue->write_bytes = 0;

ast_log(LOG_DEBUG, "(%s) audio queue destroyed\n", name);
+ if (queue->pool != NULL) {
+ apr_pool_destroy(queue->pool);
+ }
}

return 0;
@@ -2057,9 +2048,6 @@
ast_log(LOG_WARNING, "(%s) Unable to destroy channel condition
variable\n", schannel->name);
}

- if (schannel->pool != NULL)
- apr_pool_destroy(schannel->pool);
-
schannel->name = NULL;
schannel->profile = NULL;
schannel->application = NULL;
@@ -2075,6 +2063,10 @@
schannel->params = NULL;
schannel->data = NULL;
schannel->chan = NULL;
+
+ if (schannel->pool != NULL)
+ apr_pool_destroy(schannel->pool);
+
} else {
ast_log(LOG_ERROR, "Speech channel structure pointer is NULL\n");
return -1;

> --
> You received this message because you are subscribed to the Google Groups
> "UniMRCP" group.
> To view this discussion on the web visit
> https://groups.google.com/d/msg/unimrcp/-/0RL968682CAJ.
> To post to this group, send email to uni...@googlegroups.com.
> To unsubscribe from this group, send email to
> unimrcp+u...@googlegroups.com.
> For more options, visit this group at
> http://groups.google.com/group/unimrcp?hl=en.



--
Arsen Chaloyan
Author of UniMRCP
http://www.unimrcp.org

[Evan]

Arsen,

That makes complete sense. As a bonus, not only did the patch compile, it worked perfectly. We've now run a large series of test runs against it and come up with nothing but happiness. Thank you!

I'd suggest this for inclusion in the svn of app-unimrcp, just to make sure no one else falls into the same trap.

Thanks once again.

Cheers,
Evan

> unimrcp+unsubscribe@googlegroups.com.

[Arsen Chaloyan]

Evan,

I'm really glad the patch has helped, and thank you for coming back
with the results. Given that positive feedback, I've committed the
changes to the repository (r1844) to make the fix available to other
users too.

http://code.google.com/p/unimrcp/source/detail?r=1844

Cheers,

>> > unimrcp+u...@googlegroups.com.

>> > For more options, visit this group at
>> > http://groups.google.com/group/unimrcp?hl=en.
>>
>>
>>
>> --
>> Arsen Chaloyan
>> Author of UniMRCP
>> http://www.unimrcp.org
>

> --
> You received this message because you are subscribed to the Google Groups
> "UniMRCP" group.
> To view this discussion on the web visit

> https://groups.google.com/d/msg/unimrcp/-/eamrBNmI8R8J.

>
> To post to this group, send email to uni...@googlegroups.com.
> To unsubscribe from this group, send email to

> unimrcp+u...@googlegroups.com.

[Rodolfo Rodrigues]

Arsen and Evan,

It really helped, thanks.

Arsen, in the line 2058:
2058 schannel->pool = NULL;

And then,
2067 if (schannel->pool != NULL)
2068 apr_pool_destroy(schannel->pool);

It's ok?

Regards,

Rodolfo Rodrigues de Araujo


2012/5/3 Arsen Chaloyan <acha...@gmail.com>:

[Arsen Chaloyan]

Rodolfo,

Sorry, just got a couple of minutes to look into this. Your are right.
That was just an oversight introduced with the last change. Fixed in
r1845.

http://code.google.com/p/unimrcp/source/detail?r=1845

All the users of MRCPSynth application are encouraged to upgrade.

Thanks,

[Stephen George]

Excellent, thank you to both Rodolfo and Arsen!

Evan and I may have very well been suffering from this memory pool issue..

Based on load tests we've been running over the past couple of weeks on an Asterisk 1.8 instance w/ UniMRCP loaded,  definitely observed higher accumulation of memory usage when calls utilized MRCPSynth than when they did not.

We'll let you know how the new patch works out for us.

Thanks!

Stephen

[Stephen George]

Hey all,

Unfortunately, we are still experiencing memory leakage on Asterisk 1.8 even with the latest patch in r1845.  I've been generating calls at rate of 1 call every 4 seconds... and after 4 hours of this the virtual memory footprint has steadily grown from 701MB to 1586MB.

I should note that as a "control group", I performed a similar experiment with the same rate of call generation... but playing wav files instead of invoking MRCPSynth().  That test ran for an entire 48 hours with only a minor increase in memory footprint (64 MB).

What's the most helpful diagnostic info I can share to help troubleshoot this?  Would some output from valgrind help?

Thanks very much for your help once again,

Stephen

[Rodolfo Rodrigues]

Stephen,

How do you do your tests? Do you generate ".call" files?

Here, we are facing a problem with audio stuttering. When we use
asterisk or when we don't.

Are you using mrcp v1 or v2?
Valgrind logs would be helpful.

Thanks,

Rodolfo Rodrigues de Araujo


2012/5/14 Stephen George <sfge...@gmail.com>:

> --
> You received this message because you are subscribed to the Google Groups
> "UniMRCP" group.
> To view this discussion on the web visit

> https://groups.google.com/d/msg/unimrcp/-/mJjQ1ffjvNUJ.

[Stephen George]

Thanks Rodolfo,

I'm actually using an Adhearsion app, ahn-loadbot, to generate the calls.

When I run Asterisk normally and I dial-in to listen to TTS audio during a high-load test, I fortunately do not notice any audio stuttering; I only notice stuttering when I'm running valgrind... which I guess is to be expected.

We are using MRCP 1.0.

I should have some valgrind logs available in the next 12-24 hours.

Thanks again!

Stephen

[Stephen George]

Hello again,

The attached valgrind.output.bz2 is a valgrind log during a leaky synth test.  Please let me know if more information would be helpful.  You guys rock!

Thanks again,

Stephen

[Rodolfo Rodrigues]

Stephen,

I read the valgrind output and there are a lot of messages telling
about leak in "ast_log (logger.c:1241)".
I don't know if it's a leak in fact. Because, asterisk can use a logger thread.
I think that valgrind wasn't able to identify that it wasn't a leak,
in the logger thread the memory will be freed.

Valgrind identify a leak in the channels memory pool,
"speech_channel_create (app_unimrcp.c:1785)". Are you using the last
revision? In the last revision, the pool will be freed in
speech_channel_destroy(app_unimrcp.c:2069).

I checked if speech_channel_destroy wasn't used in app_synth_exec.
And, it will be called always if the speech_channel was created.

Sorry if I can't help more...

Rodolfo Rodrigues de Araujo


2012/5/14 Stephen George <sfge...@gmail.com>:

> --
> You received this message because you are subscribed to the Google Groups
> "UniMRCP" group.
> To view this discussion on the web visit

> https://groups.google.com/d/msg/unimrcp/-/QkEE5VHVY0gJ.

[Arsen Chaloyan]

Hi Stephen,

I think valgrind is the right tool for debugging this sort of
problems. Though, it's not always very obvious how to differentiate so
called false positives from real leaks.

Rodolfo is right there are at least two very strange reports in the
provided output. The first one is related to ast_log(). Valgrind shows
a huge number of memory blocks possibly lost in the logger. If it is
not a false positive, then the problem is definitely in Asterisk. BTW,
which version of Asterisk 1.8 are you using in particular? I've tried
to run a similar test against the version I have installed such as
1.8.2.3 and haven't encountered any problem.

Another and probably more ridiculous reports are related to memory
blocks possibly lost in speech_channel_create(). I've noticed that the
reported line numbers of functions in app_unimrcp.cpp don't match the
latest source. There is a shift in 2,3 lines. You may have added some
additional log statements in your local copy. If so, that's probably
OK. But please make sure those changes have indeed been made over the
last revision.

For now, I'd ask you to reproduce the problem once again by following
these steps:

1) Set compiler options

In the source dir of Asterisk, run 'make menuselect' and in the
Compiler Options, enable MALLOC_DEBUG and DONT_OPTIMIZE.

2) Rebuild and install Asterisk and then asterisk-unimrcp.

3) Run Asterisk under valgrind by suppressing known false positives as follows

valgrind --leak-check=full --track-origins=yes
--suppressions=/path-to-asterisk-source-dir/contrib/valgrind.supp
--log-fd=9 asterisk -vvvvcg 9 > valgrind.txt

4) Reproduce the issue.

A few test calls should be enough.

5) Stop Asterisk gracefully

> core stop gracefully

6) Provide the output

And don't worry we will narrow down the problem in a few attempts.

[Stephen George]

Hi guys,

Sorry for the false alarm - you are correct, I was mistaken when I thought I was running the updated module from revision 1845.

I have since successfully updated, and I am not seeing any more leaks!

Nevertheless, for completeness I'm attaching some new valgrind logs if they are of any interest.  The "big" test ran through 200 calls, while the "small" one ran through just 4.

Thanks very much you guys, this was a huge help.

Stephen

[Arsen Chaloyan]

Hi Stephen,

Nice the mystery is gone. And thanks for providing the new valgrind
reports. Looking through them, I've found a minor issue below

==17784== Uninitialised value was created by a stack allocation
==17784== at 0x6A6E670: mpf_rtp_rx_stream_open (mpf_rtp_stream.c:456)

The problem came from the use of inappropriate printf format to log
the playout delay. Nothing serious, but still glad to have this fixed
in r1846.

A few more observations mostly for your information.

I still see many memory blocks reported as possibly lost in ast_log()
calls. While it's almost certain they are false positives which can be
safely ignored, it's interesting why I don't get them on my end.
Perhaps the difference comes from the version of valgrind. I use
3.6.1, while yours is 3.5.0.

Another interesting report I also encountered a year or so ago is

==17784== Invalid read of size 4
==17784== at 0x782F30B: url_xtra (url.c:1042)
==17784== by 0x783279A: url_hdup (url.c:1214)
==17784== by 0x7799E6B: nta_agent_add_tport (nta.c:2161)
==17784== by 0x77CECF4: nua_stack_init_transport (nua_register.c:1198)
==17784== by 0x77BD685: nua_stack_init (nua_stack.c:192)
==17784== by 0x7810DA7: su_pthread_port_clone_main (su_pthread_port.c:321)
==17784== by 0x4C1E77C: start_thread (in /lib64/libpthread-2.5.so)
==17784== by 0x3C5F8D325C: clone (in /lib64/libc-2.5.so)

This seemed to point out to an invalid operation in the Sofia-SIP
stack. However, it is not true either. Even the latest valgrind still
has problems with inline/optimized version of strlen(). If you build
Sofia-SIP with -fno-builtin-strlen option, this report will disappear.
Perhaps it's better not to do that and live with yet another false
positive.

Hope this helps.

> --
> You received this message because you are subscribed to the Google Groups
> "UniMRCP" group.
> To view this discussion on the web visit

> https://groups.google.com/d/msg/unimrcp/-/oONLFvtAuIIJ.

[Stephen George]

Hi Arsen!

Thanks for the follow-up.  Sorry for the delay in responding here.

We've upgraded to valgrind 3.7.0 (I hope that's not a problem), updated to revision 1846, and re-ran our tests.

The "Uninitialised value was created by a stack allocation" warning is definitely gone, thank you!

Attached are some grind logs.

In addition, here's a full list of operands I used. Let me know if any of this is incorrect:

  LD_LIBRARY_PATH=/path/to/unimrcp-trunk/lib /path/to/valgrind --leak-check=full \

  --track-origins=yes --suppressions=/path/to/asterisk-1.8.11.0/contrib/valgrind.supp \

  --log-fd=9 --log-file=/path/to/valgrind-3.7.0-2012-05-31-asterisk-unimrcp-r1846-big.txt \

  /path/to/asterisk18/sbin/asterisk

Thanks yet again!

Stephen

> unimrcp+unsubscribe@googlegroups.com.

[Arsen Chaloyan]

Hi Stephen,

Glad to notice those false ast_log reports are also gone. So indeed,
the valgrind output is getting better and cleaner.

You seem to run Asterisk under valgrind correctly. The only question
is how did you stop Asterisk. I still see numerous possibly/definitely
lost blocks occurred as a result of load_module() calls. And I guess
these blocks are considered lost as the respective unload_module()
calls were missing. If you stopped Asterisk gracefully ("core stop
gracefully"), this shouldn't have happened. Anyway, it's still not a
problem, but just a matter of having a nicer valgrind output.

>> > unimrcp+u...@googlegroups.com.

>> > For more options, visit this group at
>> > http://groups.google.com/group/unimrcp?hl=en.
>>
>>
>>
>> --
>> Arsen Chaloyan
>> Author of UniMRCP
>> http://www.unimrcp.org
>

> --
> You received this message because you are subscribed to the Google Groups
> "UniMRCP" group.
> To view this discussion on the web visit

> https://groups.google.com/d/msg/unimrcp/-/LRAkP-PvDHUJ.

>
> To post to this group, send email to uni...@googlegroups.com.
> To unsubscribe from this group, send email to

> unimrcp+u...@googlegroups.com.