Segmentation fault mrcp_start_line_init (message/src/mrcp_start_line.c:321)

We are noting unimrcpserver exiting with SIGSEGV frequently (using customised plugin for dgmrcp speechrecog - forked from https://github.com/deepgram/dgmrcp)

The underlying cause is not clear at this stage, but it appears to be memory related - potentially as a result of failed allocation by apr_palloc

Log file: segfault.log

Core dump: core.7.2805T1120 Download here

ISSUE SUMMARY

Logs:

2024-05-28 09:20:49:885070 [INFO]   Receive MRCPv2 Data 10.83.20.27:1544 <-> 10.18.4.182:38178 [286 bytes]
MRCP/2.0 286 RECOGNIZE 4
Channel-Identifier: 82ff9d541cd311ef@speechrecog
cache-control: max-age=0
cancel-if-queue: true
confidence-threshold: 0.500000
content-type: text/uri-list
fetch-timeout: 15000
save-waveform: false
start-input-timers: true
Content-length: 9

session:1
2024-05-28 09:20:49:885241 [INFO]   Process RECOGNIZE Request <82ff9d541cd311ef@speechrecog> [4]
**2024-05-28 09:20:49:885575 [INFO]   [DG::dgmrcp::channel_machine] got channel message message="ProcessRequest(Message { inner: 0x7fbfb09e6248 })"**
2024-05-28 09:20:49:885689 [INFO]   [DG::dgmrcp::channel_machine] processing request method_id="Recognize"
2024-05-28 09:20:49:885802 [INFO]   [DG::dgmrcp::channel_machine] setting noinput_timeout timeout=15000
2024-05-28 09:20:49:885887 [INFO]   [DG::dgmrcp::channel_machine] setting sensitivity sensitivity=0.5
2024-05-28 09:20:49:885968 [INFO]   [DG::dgmrcp::channel_machine] got request grammar request_grammar="session:1"
2024-05-28 09:20:49:886146 [INFO]   [DG::dgmrcp::channel_machine] got vendor headers vendor_headers="VendorHeaders { headers: {\"com.elerianai.user_id\": \"\\\"10001546591716888023\\\"\", \"swi.rec.logValue\": \"\\\"ANII=0615228705|DNIS=0219165000\\\"\"} }"
2024-05-28 09:20:49:886333 [INFO]   [DG::dgmrcp::channel_machine] adding headers to request valid_headers="[(\".user_id\", \"\\\"10001546591716888023\\\"\")]"
2024-05-28 09:20:49:886493 [NOTICE] [DG::dgmrcp::channel_machine] building request to url="ws://elerianai-ws.sanlam.co.za/stream/asr?encoding=linear16&sample_rate=8000&user_id=%2210001546591716888023%22"
2024-05-28 09:20:49:886832 [INFO]   [DG::dgmrcp::channel_machine] finished channel message
2024-05-28 09:20:49:887668 [INFO]   Process RECOGNIZE Response <82ff9d541cd311ef@speechrecog> [4]
2024-05-28 09:20:49:887710 [INFO]   State Transition IDLE -> RECOGNIZING <82ff9d541cd311ef@speechrecog>
2024-05-28 09:20:49:887782 [INFO]   Send MRCPv2 Data 10.83.20.27:1544 <-> 10.18.4.182:38178 [83 bytes]
MRCP/2.0 83 4 200 IN-PROGRESS
Channel-Identifier: 82ff9d541cd311ef@speechrecog

2024-05-28 09:20:49:892514 [INFO]   [DG::dgmrcp::channel_machine] ignoring received frame since machine is not ready yet
2024-05-28 09:20:49:897593 [INFO]   Receive MRCPv2 Data 10.83.20.27:1544 <-> 10.18.4.182:38178 [72 bytes]
MRCP/2.0 72 STOP 5
Channel-Identifier: 82ff9d541cd311ef@speechrecog

2024-05-28 09:20:49:897708 [INFO]   Process STOP Request <82ff9d541cd311ef@speechrecog> [5]
2024-05-28 09:20:49:898000 [INFO]   [DG::dgmrcp::channel_machine] got channel message message="ProcessRequest(Message { inner: 0x7fbfb09e7520 })"
2024-05-28 09:20:49:898136 [INFO]   [DG::dgmrcp::channel_machine] processing request method_id="Stop"
2024-05-28 09:20:49:898271 [INFO]   [DG::dgmrcp::channel_machine] finished channel message
2024-05-28 09:20:49:898394 [INFO]   Process STOP Response <82ff9d541cd311ef@speechrecog> [5]
2024-05-28 09:20:49:898414 [INFO]   State Transition RECOGNIZING -> IDLE <82ff9d541cd311ef@speechrecog>
2024-05-28 09:20:49:898553 [INFO]   Send MRCPv2 Data 10.83.20.27:1544 <-> 10.18.4.182:38178 [108 bytes]
MRCP/2.0 108 5 200 COMPLETE
Channel-Identifier: 82ff9d541cd311ef@speechrecog
Active-Request-Id-List: 4

2024-05-28 09:20:49:900630 [INFO]   [DG::dgmrcp::channel_machine] ignoring received frame since machine has finished the recognizing state
2024-05-28 09:20:49:900681 [INFO]   TCP/MRCPv2 Peer Disconnected 10.83.20.27:1544 <-> 10.18.4.182:38178
2024-05-28 09:20:49:900647 [INFO]   [DG::dgmrcp::channel_machine] ignoring received frame since machine is not ready yet
2024-05-28 09:20:49:901352 [INFO]   Receive SIP Event [nua_i_bye] Status 200 Session Terminated [SIP-Agent-1]
2024-05-28 09:20:49:901376 [INFO]   Receive SIP Event [nua_i_state] Status 200 Session Terminated [SIP-Agent-1]
2024-05-28 09:20:49:901385 [NOTICE] SIP Call State 0x7fbfac2c7428 [terminated]
2024-05-28 09:20:49:901402 [INFO]   Receive SIP Event [nua_i_terminated] Status 200 Session Terminated [SIP-Agent-1]
2024-05-28 09:20:49:901422 [INFO]   Deactivate Session 0x7fbfac2c7428 <82ff9d541cd311ef>
2024-05-28 09:20:49:901427 [INFO]   Terminate Session 0x7fbfac2c7428 <82ff9d541cd311ef>
2024-05-28 09:20:49:901509 [INFO]   Remove Control Channel <82ff9d541cd311ef@speechrecog> [0]
2024-05-28 09:20:49:901652 [INFO]   [DG::dgmrcp::channel_machine] got channel message message="Close"
2024-05-28 09:20:49:901711 [INFO]   [DG::dgmrcp::channel_machine] closing a stopped channel
2024-05-28 09:20:49:901744 [INFO]   [DG::dgmrcp::channel_machine] finished channel message
**2024-05-28 09:20:49:901858 [INFO]   [DG::dgmrcp::client] received ws msg msg="Ok(Ping([57, 117, 200, 208]))"
2024-05-28 09:20:49:901976 [WARN]   [DG::dgmrcp::client] unhandled WS message type message="Binary Data<length=4>"**
2024-05-28 09:20:49:909815 [INFO]   Close RTP Receiver 10.83.20.27:5362 <- 10.18.4.182:29512 [r:0 l:0 j:0 p:50 d:0 i:0]
2024-05-28 09:20:49:909922 [INFO]   Remove RTP Session 10.83.20.27:5362
2024-05-28 09:20:49:910148 [INFO]   [DG::dgmrcp::channel_machine] got channel message message="StreamClose"
2024-05-28 09:20:49:910160 [NOTICE] Destroy TCP/MRCPv2 Connection 10.83.20.27:1544 <-> 10.18.4.182:38178
2024-05-28 09:20:49:910227 [NOTICE] Remove Session <82ff9d541cd311ef>
2024-05-28 09:20:49:910233 [INFO]   [DG::dgmrcp::channel_machine] finished channel message
2024-05-28 09:20:49:910281 [INFO]   [DG::dgmrcp::channel_machine] got channel message message="Destroy"
2024-05-28 09:20:49:910322 [NOTICE] [DG::dgmrcp::ffi] closing channel
2024-05-28 09:20:49:911586 [INFO]   [DG::dgmrcp::channel_machine] ignoring received frame since machine is not ready yet
2024-05-28 09:20:49:910235 [INFO]   Session Terminated 0x7fbfac2c7428 <82ff9d541cd311ef>
2024-05-28 09:20:49:911795 [NOTICE] Destroy Session <82ff9d541cd311ef>
2024-05-28 09:20:49:916438 [INFO]   [DG::dgmrcp::client] begin writing to websocket
2024-05-28 09:20:49:916921 [INFO]   [DG::dgmrcp::client] done writing to websocket
**2024-05-28 09:20:49:917209 [WARN]   [DG::dgmrcp::channel_machine] got error from WebSocket error="ChannelClose"**

Backtrace:

Core was generated by `/usr/local/unimrcp/bin/unimrcpserver -r /usr/local/unimrcp -o 2 -w -l 6'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  mrcp_start_line_init (start_line=start_line@entry=0x0) at message/src/mrcp_start_line.c:321
[Current thread is 1 (Thread 0x7fbfbebcf700 (LWP 9))]
(gdb) bt
#0  mrcp_start_line_init (start_line=start_line@entry=0x0) 
        at message/src/mrcp_start_line.c:321
#1  0x00007fbfc0dd4bde in mrcp_message_create (pool=0x7fbfa406e008) 
        at message/src/mrcp_message.c:102
#2  0x00007fbfc0dd4d32 in mrcp_event_create (request_message=0x7fbfb09e6248, event_id=1, pool=<optimized out>) 
        at message/src/mrcp_message.c:143
#3  0x00007fbfbeff8d51 in dgmrcp::ffi::Message::create_event (self=0x7fbfbebc3690, event_id=1) 
        at src/ffi.rs:636
#4  0x00007fbfbeff8df4 in dgmrcp::ffi::Message::send_failure (self=..., channel=..., reason=...) 
        at src/ffi.rs:652
#5  0x00007fbfbef8f239 in <dgmrcp::channel_machine::OpenedState as dgmrcp::channel_machine::State>::next::{{closure}}::{{closure}}::{{closure}} ()
    at src/channel_machine.rs:531
#6  0x00007fbfbefe5515 in <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll (self=..., cx=0x7fbfbebcd930)
    at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272
#7  0x00007fbfbef8e417 in <dgmrcp::channel_machine::OpenedState as dgmrcp::channel_machine::State>::next::{{closure}}::{{closure}} () 
        at src/channel_machine.rs:534

Frame 0 (unimrcpserver):

#0  mrcp_start_line_init (start_line=start_line@entry=0x0) at message/src/mrcp_start_line.c:321
321     start_line->message_type = MRCP_MESSAGE_TYPE_UNKNOWN;

(gdb) list
316 }
317
318 /** Initialize MRCP start-line */
319 MRCP_DECLARE(void) mrcp_start_line_init(mrcp_start_line_t *start_line)
320 {
321     start_line->message_type = MRCP_MESSAGE_TYPE_UNKNOWN;
322     start_line->version = MRCP_VERSION_UNKNOWN;
323     start_line->length = 0;
324     start_line->request_id = 0;
325     apt_string_reset(&start_line->method_name);

(gdb) info locals
No locals.

(gdb) info args
start_line = **0x0**

Frame 1 (unimrcpserver):

#1  0x00007fbfc0dd4bde in mrcp_message_create (pool=0x7fbfa406e008) 
        at message/src/mrcp_message.c:102

(gdb) info locals
message = **0x0**

Frame 3 (libdgmrcp):

#3  0x00007fbfbeff8d51 in dgmrcp::ffi::Message::create_event (self=0x7fbfbebc3690, event_id=1) 
            at src/ffi.rs:636

636         let message = unsafe {

(gdb) info args
self = 0x7fbfbebc3690
event_id = 1

(gdb) x/a self
0x7fbfbebc3690: **0x7fbfb09e6248**

(gdb) x/s 0x7fbfb09e6248
0x7fbfb09e6248: **"\001"**

Frame 4 (libdgmrcp):

#4  0x00007fbfbeff8df4 in dgmrcp::ffi::Message::send_failure (self=..., channel=..., reason=...) 
            at src/ffi.rs:652

652     pub fn send_failure(self, channel: Channel, reason: &str) {

(gdb) info args
self = dgmrcp::ffi::Message {inner: 0x7fbfb09e6248}
channel = dgmrcp::ffi::Channel {inner: 0x7fbfac2c82a8}
reason = "The send channel closed"

Frame 5 (libdgmrcp):

#5  0x00007fbfbef8f239 in <dgmrcp::channel_machine::OpenedState as dgmrcp::channel_machine::State>::next::{{closure}}::{{closure}}::{{closure}} ()
            at src/channel_machine.rs:531

531                         request_thread.send_failure(channel_thread, reason);

(gdb) info locals
reason = "The send channel closed"
err = dgmrcp::client::RecognizeError::ChannelClose
result = core::result::Result<dgmrcp::client::StreamingResponse, dgmrcp::client::RecognizeError>::Err(dgmrcp::client::RecognizeError::ChannelClose)
client = dgmrcp::client::Client {rx: tokio::sync::mpsc::unbounded::UnboundedReceiver<alloc::vec::Vec<u8, alloc::alloc::Global>> {chan: tokio::sync::mpsc::chan::Rx<alloc::vec::Vec<u8, alloc::alloc::Global>, tokio::sync::mpsc::unbounded::Semaphore> {inner: alloc::sync::Arc<tokio::sync::mpsc::chan::Chan<alloc::vec::Vec<u8, alloc::alloc::Global>, tokio::sync::mpsc::unbounded::Semaphore>> {ptr: core::ptr::non_null::NonNull<alloc::sync::ArcInner<tokio::sync::mpsc::chan::Chan<alloc::vec::Vec<u8, alloc::alloc::Global>, tokio::sync::mpsc::unbounded::Semaphore>>> {pointer: 0x7fbfb8b962c0}, phantom: core::marker::PhantomData<alloc::sync::ArcInner<tokio::sync::mpsc::chan::Chan<alloc::vec::Vec<u8, alloc::alloc::Global>, tokio::sync::mpsc::unbounded::Semaphore>>>}}}}
url = url::Url {serialization: alloc::string::String {vec: alloc::vec::Vec<u8, alloc::alloc::Global> {buf: alloc::raw_vec::RawVec<u8, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<u8> {pointer: core::ptr::non_null::NonNull<u8> {pointer: 0x7fbfb127d870 " |\f\260\277\177\000"}, _marker: core::marker::PhantomData<u8>}, cap: 164, alloc: alloc::alloc::Global}, len: 111}}, scheme_end: 2, username_end: 5, host_start: 5, host_end: 30, host: <error reading variable>, port: <error reading variable>, path_start: 30, query_start: <error reading variable>, fragment_start: <error reading variable>}
config_thread = dgmrcp::engine::Config {brain_url: url::Url {serialization: alloc::string::String {vec: alloc::vec::Vec<u8, alloc::alloc::Global> {buf: alloc::raw_vec::RawVec<u8, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<u8> {pointer: core::ptr::non_null::NonNull<u8> {pointer: 0x7fbfb0393340 "ws://elerianai-ws.sanlam.co.za/stream/asr]ser_id\": \"et\000"}, _marker: core::marker::PhantomData<u8>}, cap: 41, alloc: alloc::alloc::Global}, len: 41}}, scheme_end: 2, username_end: 5, host_start: 5, host_end: 30, host: <error reading variable>, port: <error reading variable>, path_start: 30, query_start: <error reading variable>, fragment_start: <error reading variable>}, chunk_size: 4000, stream_results: false, json_response: false, is_nuance: true, json_instance: true, sensitivity_level: <error reading variable>, vendor_prefix: alloc::string::String {vec: alloc::vec::Vec<u8, alloc::alloc::Global> {buf: alloc::raw_vec::RawVec<u8, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<u8> {pointer: core::ptr::non_null::NonNull<u8> {pointer: 0x7fbfb01d4310 "com.elerianai\177\000"}, _marker: core::marker::PhantomData<u8>}, cap: 13, alloc: alloc::alloc::Global}, len: 13}}, encoding: alloc::string::String {vec: alloc::vec::Vec<u8, alloc::alloc::Global> {buf: alloc::raw_vec::RawVec<u8, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<u8> {pointer: core::ptr::non_null::NonNull<u8> {pointer: 0x7fbfb16f7c40 "linear16@\024Q\260\277\177\000"}, _marker: core::marker::PhantomData<u8>}, cap: 8, alloc: alloc::alloc::Global}, len: 8}}, sample_rate: 8000}
user_id = core::option::Option<alloc::string::String>::Some(alloc::string::String {vec: alloc::vec::Vec<u8, alloc::alloc::Global> {buf: alloc::raw_vec::RawVec<u8, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<u8> {pointer: core::ptr::non_null::NonNull<u8> {pointer: 0x7fbfb00e84c0 "\"10001546591716888023\"\000"}, _marker: core::marker::PhantomData<u8>}, cap: 22, alloc: alloc::alloc::Global}, len: 22}})
channel_thread = dgmrcp::ffi::Channel {inner: 0x7fbfac2c82a8}
request_thread = dgmrcp::ffi::Message {inner: 0x7fbfb09e6248}
request_grammar = core::option::Option<alloc::string::String>::Some(alloc::string::String {vec: alloc::vec::Vec<u8, alloc::alloc::Global> {buf: alloc::raw_vec::RawVec<u8, alloc::alloc::Global> {ptr: core::ptr::unique::Unique<u8> {pointer: core::ptr::non_null::NonNull<u8> {pointer: 0x7fbfb07f1ae0 "session:1\000"}, _marker: core::marker::PhantomData<u8>}, cap: 9, alloc: alloc::alloc::Global}, len: 9}})
_task_context = 0x7fbfbebcd930

What’s happening?

(from the logs) We receive a message:
- 2024-05-28 09:20:49:885575 [INFO] [DG::dgmrcp::channel_machine] got channel message message="ProcessRequest(Message { inner: 0x7fbfb09e6248 })"
(from coredump) We can read the memory at this address:
- 0x7fbfb09e6248: 0x200000001 (as an address)
- 0x7fbfb09e6248: "\001” (as a string)
We call mrcp_event_create
This goes up the call stack, until the top frame (mrcp_start_line_init),
- We use the value in apr_palloc to create a pointer message
  - We do not check if this call fails
  - It seems to have failed, since message is a null pointer (0x0)
- Hence, start_line->message_type exits with a Segmentation fault
You can see this in the MRCP source code here and here

unispeech / unimrcp

Segmentation fault mrcp_start_line_init (message/src/mrcp_start_line.c:321) #328

ISSUE SUMMARY

What’s happening?