[CRASH]OpenSIPS 3.5.6 Crash on SIPREC Session Termination with RTP Relay Context Release #3740
Description
OpenSIPS Version:
version: opensips 3.5.6 (x86_64/linux)
Problem Description:
OpenSIPS crashes (SIGABRT) during call termination when the SIPREC module is engaged with RTP relay (rtpproxy). Crash occurs during RTP relay context release and dialog destruction leading to a shutdown timeout abort.
Crash Core Dump:
[New LWP 237155]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by /usr/local/sbin/opensips -F /usr/local/etc/opensips/opensips.cfg -D.
Program terminated with signal SIGABRT, Aborted.
#0 __pthread_kill_implementation (threadid=, signo=6, no_tid=0) at ./nptl/pthread_kill.c:44
#1 0x00007fba58783f4f in __pthread_kill_internal (signo=6, threadid=) at ./nptl/pthread_kill.c:78
#2 0x00007fba58734fb2 in __GI_raise (sig=6) at ../sysdeps/posix/raise.c:26
#3 0x00007fba5871f472 in __GI_abort () at ./stdlib/abort.c:79
#4 0x000055a7c8995cce in sig_alarm_abort (signo=6) at shutdown.c:141
#7 0x00007fba554ce6d5 in get_lock (lock=0x7fba55b269a0) at ../../fastlock.h:231
#8 rtp_relay_ctx_release (param=0x7fba55b26928) at rtp_relay_ctx.c:300
#9 context_destroy (ctxtype=CONTEXT_DIALOG, ctx=0x7fba55b22788) at context.c:111
#10 free_dlg_dlg (dlg=0x7fba55b22658) at dlg_hash.c:174
#11 destroy_dlg_table () at dlg_hash.c:297
#12 mod_destroy () at dialog.c:980
#13 destroy_module (m=0x7fba57703350, skip_others=) at sr_module.c:600
#14 destroy_module (skip_others=0, m=0x7fba57703fa0) at sr_module.c:589
Steps to Reproduce:
Start OpenSIPS.
Make a SIP call where RTP flows are active.
When one side ends the call, observe the OpenSIPS shutdown process.
Crash occurs during RTP relay cleanup (rtp_relay_delete called) and session/dialog destruction.
Logs:
Oct 14 11:31:41 [237545] DBG:core:parse_msg_opt: SIP Request:
Oct 14 11:31:41 [237545] DBG:core:parse_msg_opt: method:
Oct 14 11:31:41 [237545] DBG:core:parse_msg_opt: uri: sip:[email protected]:51348;transport=TCP
Oct 14 11:31:41 [237545] DBG:core:parse_msg_opt: version: <SIP/2.0>
Oct 14 11:31:41 [237545] DBG:core:parse_headers_aux: flags=ffffffffffffffff
Oct 14 11:31:41 [237545] DBG:core:parse_via_param: found param type 235, = <n/a>; state=6
Oct 14 11:31:41 [237545] DBG:core:parse_via_param: found param type 232, = ; state=6
Oct 14 11:31:41 [237545] DBG:core:parse_via_param: found param type 237, = <n/a>; state=16
Oct 14 11:31:41 [237545] DBG:core:parse_via: end of header reached, state=5
Oct 14 11:31:41 [237545] DBG:core:parse_headers_aux: via found, flags=ffffffffffffffff
Oct 14 11:31:41 [237545] DBG:core:parse_headers_aux: this is the first via
Oct 14 11:31:41 [237545] DBG:core:parse_to_param: tag=5658b202
Oct 14 11:31:41 [237545] DBG:core:parse_to_param: end of header reached, state=13
Oct 14 11:31:41 [237545] DBG:core:_parse_to: end of header reached, state=29
Oct 14 11:31:41 [237545] DBG:core:_parse_to: display={}, ruri={sip:[email protected]}
Oct 14 11:31:41 [237545] DBG:core:get_hdr_field_aux: [36]; uri=[sip:[email protected]]
Oct 14 11:31:41 [237545] DBG:core:get_hdr_field_aux: to body [sip:[email protected]]
Oct 14 11:31:41 [237545] DBG:core:get_hdr_field_aux: cseq : <19961>
Oct 14 11:31:41 [237545] DBG:core:get_hdr_field_aux: content_length=0
Oct 14 11:31:41 [237545] DBG:core:get_hdr_field_aux: found end of header
Oct 14 11:31:41 [237545] DBG:core:receive_msg: After parse_msg...
Oct 14 11:31:41 [237545] DBG:core:tcpconn_add_alias: refusing to add alias (alias_mode: 0, via 'alias': 1)
Oct 14 11:31:41 [237545] DBG:core:receive_msg: preparing to run routing scripts...
Oct 14 11:31:41 [237545] DBG:core:parse_headers_aux: flags=ffffffffffffffff
Oct 14 11:31:41 [237545] DBG:b2b_entities:b2b_prescript_f: start - method = BYE
Oct 14 11:31:41 [237545] DBG:b2b_entities:b2b_prescript_f: Found route headers
Oct 14 11:31:41 [237545] DBG:core:grep_sock_info_ext: checking if host==us: 10==10 && [x.x.x.x] == [x.x.x.x]
Oct 14 11:31:41 [237545] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Oct 14 11:31:41 [237545] DBG:b2b_entities:b2b_prescript_f: host:port [x.x.x.x][51348]
Oct 14 11:31:41 [237545] DBG:core:grep_sock_info_ext: checking if host==us: 14==10 && [x.x.x.x] == [x.x.x.x]
Oct 14 11:31:41 [237545] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 51348
Oct 14 11:31:41 [237545] DBG:core:check_self: host != me
Oct 14 11:31:41 [237545] DBG:b2b_entities:b2b_prescript_f: RURI does not point to me
Oct 14 11:31:41 [237545] DBG:maxfwd:is_maxfwd_present: value = 70
Oct 14 11:31:41 [237545] DBG:sipmsgops:has_totag: totag found
Oct 14 11:31:41 [237545] INFO:Report: method=BYE, from=10.212.134.200:51347 to sip:[email protected]:51348;transport=TCP
Oct 14 11:31:41 [237545] DBG:core:parse_headers_aux: flags=200
Oct 14 11:31:41 [237545] DBG:rr:is_preloaded: No
Oct 14 11:31:41 [237545] DBG:core:grep_sock_info_ext: checking if host==us: 14==10 && [x.x.x.x] == [x.x.x.x]
Oct 14 11:31:41 [237545] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 51348
Oct 14 11:31:41 [237545] DBG:core:check_self: host != me
Oct 14 11:31:41 [237545] DBG:core:grep_sock_info_ext: checking if host==us: 10==10 && [x.x.x.x] == [x.x.x.x]
Oct 14 11:31:41 [237545] DBG:core:grep_sock_info_ext: checking if port 5060 matches port 5060
Oct 14 11:31:41 [237545] DBG:rr:after_loose: Topmost route URI: 'sip:10.16.7.92;transport=tcp;lr;did=b3c.684d3cf1' is me
Oct 14 11:31:41 [237545] DBG:core:parse_headers_aux: flags=200
Oct 14 11:31:41 [237545] DBG:core:get_hdr_field_aux: found end of header
Oct 14 11:31:41 [237545] DBG:rr:find_next_route: No next Route HF found
Oct 14 11:31:41 [237545] DBG:rr:after_loose: No next URI found!
Oct 14 11:31:41 [237545] DBG:rr:run_rr_callbacks: callback id 1 entered with <transport=tcp;lr;did=b3c.684d3cf1>
Oct 14 11:31:41 [237545] DBG:dialog:dlg_onroute: route param is 'b3c.684d3cf1' (len=12)
Oct 14 11:31:41 [237545] DBG:dialog:lookup_dlg: dialog id=532927622 found on entry 3131
Oct 14 11:31:41 [237545] DBG:core:parse_headers_aux: flags=58
Oct 14 11:31:41 [237545] DBG:core:parse_to_param: tag=645eae46e10f4253bce4b140bf980c8c
Oct 14 11:31:41 [237545] DBG:core:parse_to_param: end of header reached, state=11
Oct 14 11:31:41 [237545] DBG:core:_parse_to: end of header reached, state=29
Oct 14 11:31:41 [237545] DBG:core:_parse_to: display={"1000"}, ruri={sip:[email protected]}
Oct 14 11:31:41 [237545] DBG:dialog:dlg_onroute: match_dialog => dst_leg=[1]
Oct 14 11:31:41 [237545] DBG:dialog:next_state_dlg: dialog 0x7fe596aff600 changed from state 4 to state 5, due event 7
Oct 14 11:31:41 [237545] DBG:dialog:init_dlg_term_reason: Setting DLG term reason to [Downstream BYE]
Oct 14 11:31:41 [237545] DBG:dialog:dlg_onroute: BYE successfully processed - dst_leg = 1
Oct 14 11:31:41 [237545] DBG:dialog:run_dlg_callbacks: dialog=0x7fe596aff600, type=32
Oct 14 11:31:41 [237545] DBG:core:parse_headers_aux: flags=10
Oct 14 11:31:41 [237545] DBG:rtp_relay:rtp_relay_delete: callid=[f4d7ec576909421399e08a203c060a44] ftag=[] ttag=[5658b202] ctx-flags=[] delete-flags=[]
Oct 14 11:31:41 [237545] CRITICAL:core:sig_usr: segfault in process pid: 237545, id: 7
Oct 14 11:31:41 [237545] DBG:core:restore_segv_handler: restoring SIGSEGV handler...
Oct 14 11:31:41 [237545] DBG:core:restore_segv_handler: successfully restored system SIGSEGV handler
Oct 14 11:31:42 [237536] DBG:core:handle_sigs: OpenSIPS exit status = 139
Oct 14 11:31:42 [237536] INFO:core:handle_sigs: child process 237545 exited by a signal 11
Oct 14 11:31:42 [237536] INFO:core:handle_sigs: core was generated
Oct 14 11:31:42 [237536] INFO:core:handle_sigs: terminating due to SIGCHLD
Oct 14 11:31:42 [237536] DBG:core:shutdown_opensips: Asking process 3 [SIP receiver udp:x.x.x.x:5060] to terminate
Oct 14 11:31:42 [237540] INFO:core:sig_usr: signal 15 received
Oct 14 11:31:42 [237541] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Oct 14 11:31:42 [237541] DBG:core:rpc_process_terminate: Process 3 exiting with code 0...
Oct 14 11:31:42 [237536] DBG:core:shutdown_opensips: Asking process 4 [SIP receiver udp:x.x.x.x:5060] to terminate
Oct 14 11:31:42 [237536] DBG:core:shutdown_opensips: Asking process 5 [SIP receiver udp:x.x.x.x:5060] to terminate
Oct 14 11:31:42 [237539] INFO:core:sig_usr: signal 15 received
Oct 14 11:31:42 [237536] DBG:core:shutdown_opensips: Asking process 6 [SIP receiver udp:x.x.x.x:5060] to terminate
Oct 14 11:31:42 [237542] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Oct 14 11:31:42 [237536] DBG:core:shutdown_opensips: Asking process 8 [TCP receiver] to terminate
Oct 14 11:31:42 [237536] DBG:core:shutdown_opensips: Asking process 9 [Timer handler] to terminate
Oct 14 11:31:42 [237542] DBG:core:rpc_process_terminate: Process 4 exiting with code 0...
Oct 14 11:31:42 [237536] DBG:core:shutdown_opensips: Asking process 10 [TCP main] to terminate
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 2(237540) [timer] terminated, still waiting for 8 more
Oct 14 11:31:42 [237543] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Oct 14 11:31:42 [237548] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Oct 14 11:31:42 [237543] DBG:core:rpc_process_terminate: Process 5 exiting with code 0...
Oct 14 11:31:42 [237548] DBG:core:rpc_process_terminate: Process 10 exiting with code 0...
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 4(237542) [SIP receiver udp:x.x.x.x:5060] terminated, still waiting for 7 more
Oct 14 11:31:42 [237544] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Oct 14 11:31:42 [237544] DBG:core:rpc_process_terminate: Process 6 exiting with code 0...
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 5(237543) [SIP receiver udp:x.x.x.x:5060] terminated, still waiting for 6 more
Oct 14 11:31:42 [237547] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Oct 14 11:31:42 [237547] DBG:core:rpc_process_terminate: Process 9 exiting with code 0...
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 10(237548) [TCP main] terminated, still waiting for 5 more
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 6(237544) [SIP receiver udp:x.x.x.x:5060] terminated, still waiting for 4 more
Oct 14 11:31:42 [237546] DBG:core:ipc_handle_job: received job type 0[RPC] from process 0
Oct 14 11:31:42 [237546] DBG:core:rpc_process_terminate: Process 8 exiting with code 0...
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 9(237547) [Timer handler] terminated, still waiting for 3 more
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 1(237539) [time_keeper] terminated, still waiting for 2 more
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 3(237541) [SIP receiver udp:x.x.x.x:5060] terminated, still waiting for 1 more
Oct 14 11:31:42 [237536] INFO:core:shutdown_opensips: process 8(237546) [TCP receiver] terminated, still waiting for 0 more
Oct 14 11:31:42 [237536] INFO:core:cleanup: cleanup
Oct 14 11:31:42 [237536] DBG:tm:tm_shutdown: tm_shutdown : start
Oct 14 11:31:42 [237536] DBG:tm:unlink_timer_lists: emptying DELETE list for set 0
Oct 14 11:31:42 [237536] DBG:tm:tm_shutdown: emptying hash table
Oct 14 11:31:42 [237536] DBG:tm:tm_shutdown: releasing timers
Oct 14 11:31:42 [237536] DBG:tm:tm_shutdown: removing semaphores
Oct 14 11:31:42 [237536] DBG:tm:tm_shutdown: destroying callback lists
Oct 14 11:31:42 [237536] DBG:tm:tm_shutdown: tm_shutdown : done
Oct 14 11:32:38 [237536] CRITICAL:core:sig_alarm_abort: BUG - shutdown timeout triggered, dying...
Aborted (core dumped)
OS/environment information
Linux fs-node-2 6.1.0-20-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.85-1 (2024-04-11) x86_64 GNU/Linux
opensips.cfg
OpenSIPS residential configuration script
by OpenSIPS Solutions [email protected]
This script was generated via "make menuconfig", from
the "Residential" scenario.
You can enable / disable more features / functionalities by
re-generating the scenario with different options.#
Please refer to the Core CookBook at:
https://opensips.org/Resources/DocsCookbooks
for a explanation of possible statements, functions and parameters.
####### Global Parameters #########
/* uncomment the following lines to enable debugging */
debug_mode=yes
log_level=3
xlog_level=3
stderror_enabled=no
syslog_enabled=yes
syslog_facility=LOG_LOCAL0
udp_workers=4
/* uncomment the next line to enable the auto temporary blacklisting of
not available destinations (default disabled) */
#disable_dns_blacklist=no
/* uncomment the next line to enable IPv6 lookup after IPv4 dns
lookup failures (default disabled) */
#dns_try_ipv6=yes
socket=udp:10.x.x.x:5060 # CUSTOMIZE ME
socket=tcp:10.x.x.x:5060
####### Modules Section ########
#set module path
mpath="/usr/local/lib64/opensips/modules/"
SIGNALING module
loadmodule "signaling.so"
StateLess module
loadmodule "sl.so"
Transaction Module
loadmodule "tm.so"
modparam("tm", "fr_timeout", 5)
modparam("tm", "fr_inv_timeout", 30)
modparam("tm", "restart_fr_on_each_reply", 0)
modparam("tm", "onreply_avp_mode", 1)
Record Route Module
loadmodule "rr.so"
/* do not append from tag to the RR (no need for this script) */
modparam("rr", "append_fromtag", 0)
MAX ForWarD module
loadmodule "maxfwd.so"
SIP MSG OPerationS module
loadmodule "sipmsgops.so"
FIFO Management Interface
#loadmodule "mi_fifo.so"
#modparam("mi_fifo", "fifo_name", "/run/opensips/opensips_fifo")
#modparam("mi_fifo", "fifo_mode", 0666)
USeR LOCation module
loadmodule "usrloc.so"
modparam("usrloc", "nat_bflag", "NAT")
modparam("usrloc", "working_mode_preset", "single-instance-no-db")
REGISTRAR module
loadmodule "registrar.so"
modparam("registrar", "tcp_persistent_flag", "TCP_PERSISTENT")
/* uncomment the next line not to allow more than 10 contacts per AOR */
#modparam("registrar", "max_contacts", 10)
ACCounting module
loadmodule "acc.so"
/* what special events should be accounted ? /
modparam("acc", "early_media", 0)
modparam("acc", "report_cancels", 0)
/ by default we do not adjust the direct of the sequential requests.
if you enable this parameter, be sure to enable "append_fromtag"
in "rr" module */
modparam("acc", "detect_direction", 0)
DIALOG module
loadmodule "dialog.so"
modparam("dialog", "dlg_match_mode", 1)
modparam("dialog", "default_timeout", 21600) # 6 hours timeout
#modparam("dialog", "db_mode", 2)
loadmodule "proto_udp.so"
loadmodule "proto_tcp.so"
loadmodule "rtpproxy.so"
#modparam("rtpproxy", "default_set", 1)
modparam("rtpproxy", "rtpproxy_sock", "udp:10.x.x.x:7722")
loadmodule "rtp_relay.so"
siprec module
loadmodule "siprec.so"
###b2b
loadmodule "b2b_entities.so"
####### Routing Logic ########
main request routing logic
route{
if (!mf_process_maxfwd_header(10)) {
send_reply(483,"Too Many Hops");
exit;
}
if (has_totag()) {
# handle hop-by-hop ACK (no routing required)
if ( is_method("ACK") && t_check_trans() ) {
t_relay();
exit;
}
# sequential request within a dialog should
# take the path determined by record-routing
if ( !loose_route() ) {
# we do record-routing for all our traffic, so we should not
# receive any sequential requests without Route hdr.
send_reply(404,"Not here");
exit;
}
if (is_method("BYE")) {
# do accounting even if the transaction fails
do_accounting("log","failed");
}
# route it out to whatever destination was set by loose_route()
# in $du (destination URI).
route(relay);
exit;
}
# CANCEL processing
if (is_method("CANCEL")) {
if (t_check_trans())
t_relay();
exit;
}
# absorb retransmissions, but do not create transaction
t_check_trans();
if ( !(is_method("REGISTER") ) ) {
if (is_myself("$fd")) {
} else {
# if caller is not local, then called number must be local
if (!is_myself("$rd")) {
send_reply(403,"Relay Forbidden");
exit;
}
}
}
# preloaded route checking
if (loose_route()) {
xlog("L_ERR",
"Attempt to route with preloaded Route's [$fu/$tu/$ru/$ci]");
if (!is_method("ACK"))
send_reply(403,"Preload Route denied");
exit;
}
# record routing
if (!is_method("REGISTER|MESSAGE"))
record_route();
# account only INVITEs
if (is_method("INVITE") && !has_totag()) {
create_dialog();
rtp_relay_engage("rtpproxy");
do_accounting("log");
}
if (!is_myself("$rd")) {
append_hf("P-hint: outbound\r\n");
route(relay);
}
# requests for my domain
if (is_method("PUBLISH|SUBSCRIBE")) {
send_reply(503, "Service Unavailable");
exit;
}
if (is_method("REGISTER")) {
# store the registration and generate a SIP reply
if (!save("location"))
xlog("failed to register AoR $tu\n");
exit;
}
if ($rU==NULL) {
# request with no Username in RURI
send_reply(484,"Address Incomplete");
exit;
}
# do lookup with method filtering
if (!lookup("location","method-filtering")) {
t_reply(404, "Not Found");
exit;
}
# when routing via usrloc, log the missed calls also
do_accounting("log","missed");
route(relay);
}
route[relay] {
# for INVITEs enable some additional helper routes
if (is_method("INVITE")) {
t_on_branch("per_branch_ops");
t_on_reply("handle_nat");
t_on_failure("missed_call");
}
if (!t_relay()) {
send_reply(500,"Internal Error");
}
exit;
}
branch_route[per_branch_ops] {
xlog("new branch at $ru\n");
}
onreply_route[handle_nat] {
xlog("incoming reply\n");
xlog("reply_route for siprec\n");
if (is_method("INVITE") && (t_check_status("2[0-9][0-9]"))) {
$siprec(media) = "10.x.x.x";
if (!siprec_start_recording("sip:10.x.x.x:5062")) {
xlog("L_ERR", "Failed to start SIPREC recording for $ci\n");
}
xlog("L_INFO", "SIPREC started:$rm\n");
}
}
failure_route[missed_call] {
if (t_was_cancelled()) {
exit;
}
# uncomment the following lines if you want to block client
# redirect based on 3xx replies.
##if (t_check_status("3[0-9][0-9]")) {
##t_reply(404,"Not found");
## exit;
##}
}
Notes:
The same issue occurs on OpenSIPS 3.6.1.
SIPREC is used in combination with rtp_relay_engage for media relay.
Crash occurs during call termination in rtp_relay_delete.