Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
laurencehardman opened this issue Jun 11, 2024 · 0 comments
Open

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

laurencehardman opened this issue Jun 11, 2024 · 0 comments

Comments

@laurencehardman
Copy link

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
Screenshot_2024-05-28_at_15 39 07 Screenshot_2024-05-29_at_12 28 36
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@laurencehardman