Segmentation fault when a channel is added to a session for recognition

[J.W.F. Thirion]

Dear Arsen,

I'm trying to get my application to do speech recognition. I do an
mrcp_application_session_create,
mrcp_application_source_termination_create,
mrcp_application_channel_create and finally a
mrcp_application_channel_add. On the mrcp_application_channel_add, the
application crashes.

Below is my log. It seems like it crashes inside the
mpf_bridge_process when trying to read a frame. My test application
borrows the speech_channel_open function from the freeswitch project..

I'm really stuck and can't see what I'm doing wrong here.

Any help would be appreciated!

(PS: I'm using unimrcp-0.8.0 with Nuance Speech Server 5.1.0).

Kind regards,
Derik Thirion


Application log:
-----------------------
speech_channel_open: Checking that channel is closed
speech_channel_open: Creating MRCP session
unimrcp_log: Create MRCP Handle 0x8776ec0 [viterbi-nuance5-mrcp2]
speech_channel_open: Create RTP endpoint
speech_channel_open: Setting up codec
speech_channel_open: (TTS-0) requesting codec L16/96/8000
speech_channel_open: Create channel
unimrcp_log: Create Channel 0x8776ec0 <new>
speech_channel_open: Add channel to session
unimrcp_log: Signal Application Task Message
unimrcp_log: Receive Application Task Message [0]
unimrcp_log: Receive App Request 0x8776ec0 <new> [2]
unimrcp_log: Add MRCP Handle 0x8776ec0
unimrcp_log: Dispatch Application Request 0x8776ec0 <new> [2]
unimrcp_log: Add Control Channel 0x8776ec0 <new@speechrecog>
unimrcp_log: Add RTP Termination 0x8776ec0 <new>
unimrcp_log: Process Control Message
unimrcp_log: Signal Connection Task Message
unimrcp_log: Receive Connection Task Message [0]
unimrcp_log: On Control Channel Add 0x8776ec0 <new>
unimrcp_log: Process MPF Message
unimrcp_log: Add Context
unimrcp_log: Add Termination
unimrcp_log: Add Termination
unimrcp_log: Receive Media Task Message
unimrcp_log: On Termination Add 0x8776ec0 <new>
unimrcp_log: On Termination Add 0x8776ec0 <new>
unimrcp_log: Send Offer 0x8776ec0 <new> [c:1 a:1 v:0]
unimrcp_log: Local SDP 0x8776ec0 <new>
v=0
o=Test 0 0 IN IP4 192.168.1.2
s=-
c=IN IP4 192.168.1.2
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4000 RTP/AVP 0 8 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=sendonly
a=ptime:20
a=mid:1

unimrcp_log: Receive SIP Event [nua_i_state] Status 0 INVITE sent
unimrcp_log: SIP Call State 0x8776ec0 [calling]
unimrcp_log: Receive SIP Event [nua_r_invite] Status 200 OK
unimrcp_log: Receive SIP Event [nua_i_state] Status 200 OK
unimrcp_log: SIP Call State 0x8776ec0 [ready]
unimrcp_log: Remote SDP 0x8776ec0 <new>
v=0
o=- 1258457930 1258457930 IN IP4 192.168.1.3
s=MRCP session
c=IN IP4 192.168.1.3
t=0 0
m=application 6075 TCP/MRCPv2 1
a=channel:140@speechrecog
a=cmid:1
a=connection:new
a=setup:passive
m=audio 7892 RTP/AVP 0 8 96 100
a=rtpmap:0 pcmu/8000
a=rtpmap:8 pcma/8000
a=rtpmap:96 l16/8000
a=rtpmap:100 telephone-event/8000
a=fmtp:100 0-15
a=recvonly
a=mid:1

unimrcp_log: Signal Signaling Task Message
unimrcp_log: Receive SIP Event [nua_i_active] Status 200 Call active
unimrcp_log: Receive Signaling Task Message [0]
unimrcp_log: Receive Answer 0x8776ec0 <new> [c:1 a:1 v:0]
unimrcp_log: Modify Control Channel 0x8776ec0 <140>
unimrcp_log: Modify Termination 0x8776ec0 <140>
unimrcp_log: Process Control Message
unimrcp_log: Established TCP/MRCPv2 Connection 192.168.1.2:52946 <->
192.168.1.3:6075
unimrcp_log: Add Control Channel <140@speechrecog> 192.168.1.2:52946 <-
> 192.168.1.3:6075 [1]
unimrcp_log: Signal Connection Task Message
unimrcp_log: Receive Connection Task Message [1]
unimrcp_log: On Control Channel Modify 0x8776ec0 <140>
Segmentation fault (core dumped)


GDB backtrace:
------------------------
#0 0x00000000 in ?? ()
#1 0x0046cc47 in mpf_bridge_process (object=0x8777b08) at src/
mpf_bridge.c:43
#2 0x0046e7cd in mpf_context_process (context=0x8777200) at src/
mpf_context.c:434
#3 0x0046e818 in mpf_context_factory_process (factory=0x86e8940) at
src/mpf_context.c:103
#4 0x0046fb0f in mpf_engine_main (timer=0x86fa7a8, data=0x86e8868) at
src/mpf_engine.c:395
#5 0x00470ed8 in timer_thread_proc (thread=0x86fa7c0, data=0x86fa7a8)
at src/mpf_timer.c:138
#6 0x002f5376 in dummy_worker (opaque=0x86fa7c0) at threadproc/unix/
thread.c:142
#7 0x0063a5ab in start_thread () from /lib/libpthread.so.0
#8 0x00590cfe in clone () from /lib/libc.so.6
(gdb) frame 1
#1 0x0046cc47 in mpf_bridge_process (object=0x8777b08) at src/
mpf_bridge.c:43
43 bridge->source->vtable->read_frame(bridge-
>source,&bridge->frame);
(gdb) frame 2
#2 0x0046e7cd in mpf_context_process (context=0x8777200) at src/
mpf_context.c:434
434 object->process(object);
(gdb) frame 3
#3 0x0046e818 in mpf_context_factory_process (factory=0x86e8940) at
src/mpf_context.c:103
103 mpf_context_process(context);
(gdb) frame 4
#4 0x0046fb0f in mpf_engine_main (timer=0x86fa7a8, data=0x86e8868) at
src/mpf_engine.c:395
395 mpf_context_factory_process(engine->context_factory);
(gdb) frame 5
#5 0x00470ed8 in timer_thread_proc (thread=0x86fa7c0, data=0x86fa7a8)
at src/mpf_timer.c:138
138 timer->timer_proc(timer,timer->obj);
(gdb) frame 6
#6 0x002f5376 in dummy_worker (opaque=0x86fa7c0) at threadproc/unix/
thread.c:142
142 return thread->func(thread, thread->data);
(gdb) frame 7
#7 0x0063a5ab in start_thread () from /lib/libpthread.so.0
(gdb) frame 8
#8 0x00590cfe in clone () from /lib/libc.so.6

(gdb) frame 1
#1 0x0046cc47 in mpf_bridge_process (object=0x8777b08) at src/
mpf_bridge.c:43
43 bridge->source->vtable->read_frame(bridge-
>source,&bridge->frame);
(gdb) inspect vtable
$1 = {destroy = 0x471ab0 <mpf_rtp_stream_destroy>, open_rx = 0x472130
<mpf_rtp_rx_stream_open>, close_rx = 0x472070
<mpf_rtp_rx_stream_close>,
read_frame = 0x472930 <mpf_rtp_stream_receive>, open_tx = 0x471b80
<mpf_rtp_tx_stream_open>, close_tx = 0x471b00
<mpf_rtp_tx_stream_close>,
write_frame = 0x4727a0 <mpf_rtp_stream_transmit>, trace = 0}


Source extract where dump occurs:
-----------------------------------------------------
static int speech_channel_open(speech_channel_t *schannel, profile_t
*profile)
{
int status = 0;
mpf_termination_t *termination = NULL;
mpf_codec_descriptor_t *codec = NULL;
mrcp_resource_type_e resource_type;

apr_thread_mutex_lock(schannel->mutex);
log(LOG_DEBUG, "Checking that channel is closed\n");
if (schannel->state != SPEECH_CHANNEL_CLOSED) {
apr_thread_mutex_unlock(schannel->mutex);
return -1;
}
schannel->profile = profile;
log(LOG_DEBUG, "Creating MRCP session\n");
/* Create MRCP session. */
if ((schannel->unimrcp_session = mrcp_application_session_create
(schannel->application->app, profile->name, schannel)) == NULL) {
/* Profile doesn't exist? */
log(LOG_ERROR, "(%s) Unable to create session with %s\n",
schannel->name, profile->name);
apr_thread_mutex_unlock(schannel->mutex);
return 2;
}
log(LOG_DEBUG, "Create RTP endpoint\n");
/* Create RTP endpoint and link to session channel. */
if ((codec = (mpf_codec_descriptor_t *)apr_palloc(schannel-
>unimrcp_session->pool, sizeof(mpf_codec_descriptor_t))) == NULL) {
log(LOG_ERROR, "(%s) Unable to create codec with %s\n",
schannel->name, profile->name);
if (!mrcp_application_session_destroy(schannel-
>unimrcp_session))
log(LOG_WARNING, "(%s) Unable to destroy application
session for %s\n", schannel->name, profile->name);
apr_thread_mutex_unlock(schannel->mutex);
return -1;
}

log(LOG_DEBUG, "Setting up codec\n");
mpf_codec_descriptor_init(codec);
codec->channel_count = 1;
codec->payload_type = 96;
codec->sampling_rate = schannel->rate;

/* "LPCM" is UniMRCP's name for L16 host byte ordered */
if (strcasecmp(schannel->codec, "L16") == 0)
apt_string_set(&codec->name, "LPCM");
else
apt_string_set(&codec->name, schannel->codec);

/* See RFC 1890 for payload types. */
if ((strcasecmp(schannel->codec, "PCMU") == 0) && (schannel->rate
== 8000))
codec->payload_type = 0;
else if ((strcasecmp(schannel->codec, "PCMA") == 0) && (schannel-
>rate == 8000))
codec->payload_type = 8;

log(LOG_DEBUG, "(%s) requesting codec %s/%d/%d\n", schannel->name,
schannel->codec, codec->payload_type, codec->sampling_rate);

if (schannel->type == SPEECH_CHANNEL_SYNTHESIZER)
termination = mrcp_application_sink_termination_create
(schannel->unimrcp_session, &schannel->application-
>audio_stream_vtable, codec, schannel);
else
termination = mrcp_application_source_termination_create
(schannel->unimrcp_session, &schannel->application-
>audio_stream_vtable, codec, schannel);

if (termination == NULL) {
log(LOG_ERROR, "(%s) Unable to create termination with %s\n",
schannel->name, profile->name);

if (!mrcp_application_session_destroy(schannel-
>unimrcp_session))
log(LOG_WARNING, "(%s) Unable to destroy application
session for %s\n", schannel->name, profile->name);

apr_thread_mutex_unlock(schannel->mutex);

return -1;
}

if (schannel->type == SPEECH_CHANNEL_SYNTHESIZER)
resource_type = MRCP_SYNTHESIZER_RESOURCE;
else
resource_type = MRCP_RECOGNIZER_RESOURCE;

log(LOG_DEBUG, "Create channel\n");

if ((schannel->unimrcp_channel = mrcp_application_channel_create
(schannel->unimrcp_session, resource_type, termination, NULL,
schannel)) == NULL) {
log(LOG_ERROR, "(%s) Unable to create channel with %s\n",
schannel->name, profile->name);

if (!mrcp_application_session_destroy(schannel-
>unimrcp_session))
log(LOG_WARNING, "(%s) Unable to destroy application
session for %s\n", schannel->name, profile->name);

apr_thread_mutex_unlock(schannel->mutex);

return -1;
}

log(LOG_DEBUG, "Add channel to session\n");

/* Add channel to session. This establishes the connection to the
MRCP server. */
if (mrcp_application_channel_add(schannel->unimrcp_session,
schannel->unimrcp_channel) != TRUE) {
log(LOG_ERROR, "(%s) Unable to add channel to session with %s
\n", schannel->name, profile->name);

if (!mrcp_application_session_destroy(schannel-
>unimrcp_session))
log(LOG_WARNING, "(%s) Unable to destroy application
session for %s\n", schannel->name, profile->name);

apr_thread_mutex_unlock(schannel->mutex);

return -1;
}

log(LOG_DEBUG, "Waiting for channel to be ready\n");

/* Wait for channel to be ready. */
if (schannel->cond != NULL)
apr_thread_cond_timedwait(schannel->cond, schannel->mutex,
SPEECH_CHANNEL_TIMEOUT_USEC);
if (schannel->state == SPEECH_CHANNEL_READY) {
log(LOG_DEBUG, "(%s) channel is ready\n", schannel->name);
} else if (schannel->state == SPEECH_CHANNEL_CLOSED) {
log(LOG_ERROR, "(%s) Timed out waiting for channel to be ready
\n", schannel->name);
/* Can't retry. */
status = -1;
} else if (schannel->state == SPEECH_CHANNEL_ERROR) {
/* Wait for session to be cleaned up. */
if (schannel->cond != NULL)
apr_thread_cond_timedwait(schannel->cond, schannel->mutex,
SPEECH_CHANNEL_TIMEOUT_USEC);

if (schannel->state != SPEECH_CHANNEL_CLOSED) {
/* Major issue. Can't retry. */
status = -1;
} else {
/* Failed to open profile, retry is allowed. */
status = 2;
}
}

apr_thread_mutex_unlock(schannel->mutex);
return status;
}

[J.W.F. Thirion]

My appologies everyone.

I made a stupid mistake in that I created the channel and associated
it to my synthesis application instead of the recognizer application.
The audio_stream_vtable for the synth app of course did not have an
audio_stream_vtable.read_frame callback specified, which caused the
segmentation fault. After creating the session with the recognizer
application, everything work.

Wish gdb could have given me a bit more useful output here... :-)

Kind regards,
Derik

[Arsen Chaloyan]

Hi Derik,

You're definitely faster than me.
Everything is right with gdb, it's me should be more careful while
processing wild pointers passed from user space.

I've just fixed it to simply return an error.
http://code.google.com/p/unimrcp/source/detail?r=1288

Thanks for the catch.

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

[J.W.F. Thirion]

Hi Arsen,

Wow! Thanks for the great support!

I must say, this is certainly one of the better open source projects
out there.

Kind regards,
Derik