app_dial.c: Moved channel lock to prevent deadlock

It's reproducible with pbx_lua, not regular dialplan.

deadlock description:
1. asterisk locks a channel
2. calls function onedigit_goto
3. calls ast_goto_if_exists funciton
4. checks ast_exists_extension -> pbx_extension_helper
5. pbx_extension_helper calls pbx_find_extension
6. Then asterisk starts autoservice in a new thread
7. autoservice run tries to lock the channel again

Because our channel is locked already, autoservice can't lock.
Autoservice can't lock -> autoservice stop is waiting forever.
onedigit_goto waits for autoservice stop.

Resolves: https://github.com/asterisk/asterisk/issues/1335

apps/app_dial.c

@@ -1808,7 +1808,10 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
 				if (ast_test_flag64(peerflags, OPT_DTMF_EXIT)) {
 					const char *context;
 					ast_channel_lock(in);
-					context = pbx_builtin_getvar_helper(in, "EXITCONTEXT");
+					if ((context = pbx_builtin_getvar_helper(in, "EXITCONTEXT"))) {
+						context = ast_strdupa(context);
+					}
+					ast_channel_unlock(in);
 					if (onedigit_goto(in, context, (char) f->subclass.integer, 1)) {
 						ast_verb(3, "User hit %c to disconnect call.\n", f->subclass.integer);
 						*to_answer = 0;
@@ -1817,14 +1820,12 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
 						pa->canceled = 1;
 						publish_dial_end_event(in, out_chans, NULL, pa->status);
 						ast_frfree(f);
-						ast_channel_unlock(in);
 						if (is_cc_recall) {
 							ast_cc_completed(in, "CC completed, but the caller used DTMF to exit");
 						}
 						SCOPE_EXIT_RTN_VALUE(NULL, "%s: Caller pressed %c to end call\n",
 							ast_channel_name(in), f->subclass.integer);
 					}
-					ast_channel_unlock(in);
 				}
 
 				if (ast_test_flag64(peerflags, OPT_CALLER_HANGUP) &&

configs/samples/cel.conf.sample

@@ -59,6 +59,12 @@ apps=dial,park
 ;  USER_DEFINED     -- Triggered from the dialplan, and has a name given by the
 ;                      user
 ;  LOCAL_OPTIMIZE   -- A local channel pair is optimizing away.
+;  STREAM_BEGIN     -- A stream started playing: it can be a standalone sound file
+;                      playing back, or a music-on-hold class started
+;  STREAM_END       -- A playing stream ended
+;  DTMF             -- A DTMF digit was processed: these events are dispatched at the
+;                      end, when the button is released and the duration is present in
+;                      the extra field
 ;
 ; Default value: none
 ;                (Track no events)

include/asterisk/cel.h

@@ -77,6 +77,12 @@ enum ast_cel_event_type {
 	AST_CEL_LOCAL_OPTIMIZE = 17,
 	/*! \brief A local channel optimization has begun */
 	AST_CEL_LOCAL_OPTIMIZE_BEGIN = 18,
+	/*! \brief A stream started */
+	AST_CEL_STREAM_BEGIN = 19,
+	/*! \brief A stream ended */
+	AST_CEL_STREAM_END = 20,
+	/*! \brief A DTMF digit was processed */
+	AST_CEL_DTMF = 21,
 };
 
 /*!

main/cel.c

@@ -118,6 +118,9 @@
 						<enum name="LINKEDID_END"/>
 						<enum name="LOCAL_OPTIMIZE"/>
 						<enum name="LOCAL_OPTIMIZE_BEGIN"/>
+						<enum name="STREAM_BEGIN"/>
+						<enum name="STREAM_END"/>
+						<enum name="DTMF"/>
 					</enumlist>
 					</description>
 				</configOption>
@@ -338,6 +341,9 @@ static const char * const cel_event_types[CEL_MAX_EVENT_IDS] = {
 	[AST_CEL_LINKEDID_END]     = "LINKEDID_END",
 	[AST_CEL_LOCAL_OPTIMIZE]   = "LOCAL_OPTIMIZE",
 	[AST_CEL_LOCAL_OPTIMIZE_BEGIN]   = "LOCAL_OPTIMIZE_BEGIN",
+	[AST_CEL_STREAM_BEGIN]     = "STREAM_BEGIN",
+	[AST_CEL_STREAM_END]       = "STREAM_END",
+	[AST_CEL_DTMF]             = "DTMF",
 };
 
 struct cel_backend {
@@ -849,12 +855,8 @@ int ast_cel_fill_record(const struct ast_event *e, struct ast_cel_event_record *
 	r->event_time.tv_usec = ast_event_get_ie_uint(e, AST_EVENT_IE_CEL_EVENT_TIME_USEC);
 
 	r->event_name = ast_cel_get_type_name(r->event_type);
-	if (r->event_type == AST_CEL_USER_DEFINED) {
-		r->user_defined_name = ast_event_get_ie_str(e, AST_EVENT_IE_CEL_USEREVENT_NAME);
-	} else {
-		r->user_defined_name = "";
-	}
 
+	r->user_defined_name= S_OR(ast_event_get_ie_str(e, AST_EVENT_IE_CEL_USEREVENT_NAME), "");
 	r->caller_id_name   = S_OR(ast_event_get_ie_str(e, AST_EVENT_IE_CEL_CIDNAME), "");
 	r->caller_id_num    = S_OR(ast_event_get_ie_str(e, AST_EVENT_IE_CEL_CIDNUM), "");
 	r->caller_id_ani    = S_OR(ast_event_get_ie_str(e, AST_EVENT_IE_CEL_CIDANI), "");
@@ -1282,6 +1284,8 @@ static void cel_generic_cb(
 
 	switch (event_type) {
 	case AST_CEL_USER_DEFINED:
+	case AST_CEL_DTMF:
+	case AST_CEL_STREAM_BEGIN:
 		{
 			const char *event = ast_json_string_get(ast_json_object_get(event_details, "event"));
 			struct ast_json *extra = ast_json_object_get(event_details, "extra");
@@ -1289,6 +1293,13 @@ static void cel_generic_cb(
 				event, extra, NULL);
 			break;
 		}
+	case AST_CEL_STREAM_END:
+		{
+			const char *event = ast_json_string_get(ast_json_object_get(event_details, "event"));
+			cel_report_event(obj->snapshot, event_type, stasis_message_timestamp(message),
+				event, NULL, NULL);
+			break;
+		}
 	default:
 		ast_log(LOG_ERROR, "Unhandled %s event blob\n", ast_cel_get_type_name(event_type));
 		break;

main/channel.c

@@ -42,6 +42,7 @@
 #include "asterisk/mod_format.h"
 #include "asterisk/sched.h"
 #include "asterisk/channel.h"
+#include "asterisk/cel.h"
 #include "asterisk/musiconhold.h"
 #include "asterisk/say.h"
 #include "asterisk/file.h"
@@ -3336,34 +3337,45 @@ static const char *dtmf_direction_to_string(enum DtmfDirection direction)
 static void send_dtmf_begin_event(struct ast_channel *chan,
 	enum DtmfDirection direction, const char digit)
 {
-	RAII_VAR(struct ast_json *, blob, NULL, ast_json_unref);
+	RAII_VAR(struct ast_json *, channel_blob, NULL, ast_json_unref);
 	char digit_str[] = { digit, '\0' };
 
-	blob = ast_json_pack("{ s: s, s: s }",
+	channel_blob = ast_json_pack("{ s: s, s: s }",
 		"digit", digit_str,
 		"direction", dtmf_direction_to_string(direction));
-	if (!blob) {
-		return;
-	}
 
-	ast_channel_publish_blob(chan, ast_channel_dtmf_begin_type(), blob);
+	if (channel_blob) {
+		ast_channel_publish_blob(chan, ast_channel_dtmf_begin_type(), channel_blob);
+	}
 }
 
 static void send_dtmf_end_event(struct ast_channel *chan,
 	enum DtmfDirection direction, const char digit, long duration_ms)
 {
-	RAII_VAR(struct ast_json *, blob, NULL, ast_json_unref);
+	RAII_VAR(struct ast_json *, channel_blob, NULL, ast_json_unref);
+	RAII_VAR(struct ast_json *, cel_blob, NULL, ast_json_unref);
 	char digit_str[] = { digit, '\0' };
 
-	blob = ast_json_pack("{ s: s, s: s, s: I }",
+	channel_blob = ast_json_pack("{ s: s, s: s, s: I }",
 		"digit", digit_str,
 		"direction", dtmf_direction_to_string(direction),
 		"duration_ms", (ast_json_int_t)duration_ms);
-	if (!blob) {
-		return;
+
+	if (channel_blob) {
+		ast_channel_publish_blob(chan, ast_channel_dtmf_end_type(), channel_blob);
 	}
 
-	ast_channel_publish_blob(chan, ast_channel_dtmf_end_type(), blob);
+	cel_blob = ast_json_pack("{ s: s, s: { s: s, s: I }}",
+		"event", dtmf_direction_to_string(direction),
+		"extra",
+			"digit", digit_str,
+			"duration_ms", (ast_json_int_t)duration_ms);
+
+	if (cel_blob) {
+		ast_cel_publish_event(chan, AST_CEL_DTMF, cel_blob);
+	} else {
+		ast_log(LOG_WARNING, "Unable to build extradata for DTMF CEL event on channel %s", ast_channel_name(chan));
+	}
 }
 
 static void send_flash_event(struct ast_channel *chan)

main/file.c

@@ -39,6 +39,7 @@
 #include "asterisk/mod_format.h"
 #include "asterisk/cli.h"
 #include "asterisk/channel.h"
+#include "asterisk/cel.h"
 #include "asterisk/sched.h"
 #include "asterisk/translate.h"
 #include "asterisk/utils.h"
@@ -221,15 +222,25 @@ int ast_file_fdtemp(const char *path, char **filename, const char *template_name
 
 int ast_stopstream(struct ast_channel *tmp)
 {
+	struct ast_json * cel_event = NULL;
+
 	ast_channel_lock(tmp);
 
 	/* Stop a running stream if there is one */
 	if (ast_channel_stream(tmp)) {
 		ast_closestream(ast_channel_stream(tmp));
 		ast_channel_stream_set(tmp, NULL);
+
+		cel_event = ast_json_pack("{ s: s }", "event", "FILE_STREAM_END");
+		if (cel_event) {
+			ast_cel_publish_event(tmp, AST_CEL_STREAM_END, cel_event);
+		}
+
 		if (ast_channel_oldwriteformat(tmp) && ast_set_write_format(tmp, ast_channel_oldwriteformat(tmp)))
 			ast_log(LOG_WARNING, "Unable to restore format back to %s\n", ast_format_get_name(ast_channel_oldwriteformat(tmp)));
 	}
+	ast_json_unref(cel_event);
+
 	/* Stop the video stream too */
 	if (ast_channel_vstream(tmp) != NULL) {
 		ast_closestream(ast_channel_vstream(tmp));
@@ -1301,6 +1312,7 @@ int ast_file_read_dirs(const char *dir_name, ast_file_on_file on_file, void *obj
 int ast_streamfile(struct ast_channel *chan, const char *filename,
 	const char *preflang)
 {
+	struct ast_json * cel_event = NULL;
 	struct ast_filestream *fs = NULL;
 	struct ast_filestream *vfs = NULL;
 	off_t pos;
@@ -1315,7 +1327,7 @@ int ast_streamfile(struct ast_channel *chan, const char *filename,
 	if (ast_opt_sounds_search_custom && !is_absolute_path(filename)) {
 		memset(custom_filename, 0, sizeof(custom_filename));
 		snprintf(custom_filename, sizeof(custom_filename), "custom/%s", filename);
-		fs = openstream_internal(chan, filename, preflang, 0, 1); /* open stream, do not warn for missing files */
+		fs = openstream_internal(chan, custom_filename, preflang, 0, 1); /* open stream, do not warn for missing files */
 		if (fs) {
 			tmp_filename = custom_filename;
 			ast_debug(3, "Found file %s in custom directory\n", filename);
@@ -1367,6 +1379,20 @@ int ast_streamfile(struct ast_channel *chan, const char *filename,
 	if (!res && vfs)
 		res = ast_playstream(vfs);
 
+	cel_event = ast_json_pack("{ s: s, s: {s: s, s: s, s: s}}",
+		"event", "FILE_STREAM_BEGIN",
+		"extra",
+			"sound", tmp_filename,
+			"format", ast_format_get_name(ast_channel_writeformat(chan)),
+			"language", preflang ? preflang : "default"
+	);
+	if (cel_event) {
+		ast_cel_publish_event(chan, AST_CEL_STREAM_BEGIN, cel_event);
+	} else {
+		ast_log(LOG_WARNING, "Unable to build extradata for sound file STREAM_BEGIN event on channel %s", ast_channel_name(chan));
+	}
+	ast_json_unref(cel_event);
+
 	if (VERBOSITY_ATLEAST(3)) {
 		ast_channel_lock(chan);
 		ast_verb(3, "<%s> Playing '%s.%s' (language '%s')\n", ast_channel_name(chan), tmp_filename, ast_format_get_name(ast_channel_writeformat(chan)), preflang ? preflang : "default");

res/res_musiconhold.c

@@ -54,6 +54,7 @@
 #include "asterisk/lock.h"
 #include "asterisk/file.h"
 #include "asterisk/channel.h"
+#include "asterisk/cel.h"
 #include "asterisk/pbx.h"
 #include "asterisk/app.h"
 #include "asterisk/module.h"
@@ -253,10 +254,23 @@ static void moh_post_start(struct ast_channel *chan, const char *moh_class_name)
 {
 	struct stasis_message *message;
 	struct ast_json *json_object;
+	struct ast_json *cel_event;
 
 	ast_verb(3, "Started music on hold, class '%s', on channel '%s'\n",
 		moh_class_name, ast_channel_name(chan));
 
+	cel_event = ast_json_pack("{ s: s, s: {s: s }}",
+		"event", "MOH_STREAM_BEGIN",
+		"extra",
+			"class", moh_class_name
+	);
+	if (cel_event) {
+		ast_cel_publish_event(chan, AST_CEL_STREAM_BEGIN, cel_event);
+	} else {
+		ast_log(LOG_WARNING, "Unable to build extradata for music on hold STREAM_BEGIN event on channel %s", ast_channel_name(chan));
+	}
+	ast_json_unref(cel_event);
+
 	json_object = ast_json_pack("{s: s}", "class", moh_class_name);
 	if (!json_object) {
 		return;
@@ -277,9 +291,16 @@ static void moh_post_start(struct ast_channel *chan, const char *moh_class_name)
 static void moh_post_stop(struct ast_channel *chan)
 {
 	struct stasis_message *message;
+	struct ast_json *cel_event;
 
 	ast_verb(3, "Stopped music on hold on %s\n", ast_channel_name(chan));
 
+	cel_event = ast_json_pack("{ s: s }", "event", "MOH_STREAM_END");
+	if (cel_event) {
+		ast_cel_publish_event(chan, AST_CEL_STREAM_END, cel_event);
+	}
+	ast_json_unref(cel_event);
+
 	message = ast_channel_blob_create_from_cache(ast_channel_uniqueid(chan),
 		ast_channel_moh_stop_type(), NULL);
 	if (message) {

res/res_pjsip_diversion.c

@@ -39,6 +39,14 @@ static const pj_str_t diversion_name = { "Diversion", 9 };
 static const pj_str_t history_info_name = { "History-Info", 12 };
 static pj_str_t HISTINFO_SUPPORTED_NAME = { "histinfo", 8 };
 
+/*
+ * Should we queue a frame with the updated redirecting information.
+ */
+typedef enum  {
+	PJSIP_DIVERSION_NOSEND_UPDATE = 0,
+	PJSIP_DIVERSION_SEND_UPDATE = 1,
+} pjsip_diversion_send_update;
+
 /*!
  * \internal
  * \brief Determine if the given string is a SIP token.
@@ -385,7 +393,8 @@ static void set_redirecting_reason(pjsip_fromto_hdr *from_info, pjsip_name_addr
 
 static void set_redirecting(struct ast_sip_session *session,
 			    pjsip_fromto_hdr *from_info,
-			    pjsip_name_addr *to_info)
+			    pjsip_name_addr *to_info,
+			    pjsip_diversion_send_update send_update)
 {
 	struct ast_party_redirecting data;
 	struct ast_set_party_redirecting update;
@@ -417,8 +426,8 @@ static void set_redirecting(struct ast_sip_session *session,
 	++data.count;
 
 	ast_channel_set_redirecting(session->channel, &data, &update);
-	/* Only queue an indication if it was due to a response */
-	if (session->inv_session->role == PJSIP_ROLE_UAC) {
+	/* Only queue an indication if it was due to a response received pre media*/
+	if (session->inv_session->role == PJSIP_ROLE_UAC && send_update) {
 		ast_channel_queue_redirecting_update(session->channel, &data, &update);
 	}
 	ast_party_redirecting_free(&data);
@@ -430,7 +439,7 @@ static int diversion_incoming_request(struct ast_sip_session *session, pjsip_rx_
 
 	if (hdr) {
 		set_redirecting(session, hdr, (pjsip_name_addr*)
-				PJSIP_MSG_TO_HDR(rdata->msg_info.msg)->uri);
+				PJSIP_MSG_TO_HDR(rdata->msg_info.msg)->uri, PJSIP_DIVERSION_SEND_UPDATE);
 	} else {
 		pjsip_fromto_hdr *history_info_to;
 		pjsip_fromto_hdr *history_info_from;
@@ -440,14 +449,14 @@ static int diversion_incoming_request(struct ast_sip_session *session, pjsip_rx_
 			/* If History-Info is present, then it will also include the original
 			   redirected-from in addition to the redirected-to */
 			history_info_from = get_history_info_header(rdata, 1);
-			set_redirecting(session, history_info_from, (pjsip_name_addr*)history_info_to->uri);
+			set_redirecting(session, history_info_from, (pjsip_name_addr*)history_info_to->uri, PJSIP_DIVERSION_SEND_UPDATE);
 		}
 	}
 
 	return 0;
 }
 
-static void diversion_incoming_response(struct ast_sip_session *session, pjsip_rx_data *rdata)
+static void diversion_incoming_response(struct ast_sip_session *session, pjsip_rx_data *rdata, pjsip_diversion_send_update send_update)
 {
 	static const pj_str_t contact_name = { "Contact", 7 };
 	static const pj_str_t contact_name_s = { "m", 1 };
@@ -472,7 +481,7 @@ static void diversion_incoming_response(struct ast_sip_session *session, pjsip_r
 			/* If History-Info is present, then it will also include the original
 			   redirected-from in addition to the redirected-to */
 			history_info_from = get_history_info_header(rdata, 1);
-			set_redirecting(session, history_info_from, (pjsip_name_addr*)history_info_to->uri);
+			set_redirecting(session, history_info_from, (pjsip_name_addr*)history_info_to->uri, send_update);
 			return;
 		}
 		if (!div_hdr && !session->id.number.valid) {
@@ -484,16 +493,30 @@ static void diversion_incoming_response(struct ast_sip_session *session, pjsip_r
 	if (status.code == 302) {
 		/* With 302, Contact indicates the final destination and possibly Diversion indicates the hop before */
 		contact_hdr = pjsip_msg_find_hdr_by_names(rdata->msg_info.msg, &contact_name, &contact_name_s, NULL);
-
 		set_redirecting(session, div_hdr, contact_hdr ?	(pjsip_name_addr*)contact_hdr->uri :
-				(pjsip_name_addr*)PJSIP_MSG_FROM_HDR(rdata->msg_info.msg)->uri);
+				(pjsip_name_addr*)PJSIP_MSG_FROM_HDR(rdata->msg_info.msg)->uri, send_update);
 	} else {
 		/* With 181, Diversion is non-standard, but if present indicates the new final destination, and To indicating the original */
 		set_redirecting(session, PJSIP_MSG_TO_HDR(rdata->msg_info.msg),
-				div_hdr ? (pjsip_name_addr*)div_hdr->uri : NULL);
+				div_hdr ? (pjsip_name_addr*)div_hdr->uri : NULL, send_update);
 	}
 }
 
+static void diversion_incoming_response_media(struct ast_sip_session *session, pjsip_rx_data *rdata)
+{
+	/* Trigger an update if the event is triggered by the PJSIP AST_SIP_SESSION_BEFORE_MEDIA callback */
+	diversion_incoming_response(session, rdata, PJSIP_DIVERSION_SEND_UPDATE);
+	return;
+}
+
+static void diversion_incoming_response_redirecting(struct ast_sip_session *session, pjsip_rx_data *rdata)
+{
+	/* Don't trigger an update if the event is triggered by the PJSIP AST_SIP_SESSION_REDIRECTING callback
+	   otherwise, we will send a duplicate 181 to the UAC */
+	diversion_incoming_response(session, rdata, PJSIP_DIVERSION_NOSEND_UPDATE);
+	return;
+}
+
 /*!
  * \internal
  * \brief Adds diversion header information to an outbound SIP message
@@ -688,20 +711,29 @@ static void diversion_outgoing_response(struct ast_sip_session *session, pjsip_t
 
 	/* add to 302 and 181 */
 	if (PJSIP_IS_STATUS_IN_CLASS(status.code, 300) || (status.code == 181)) {
-		get_redirecting_add_diversion(session, tdata);
-	}
+        get_redirecting_add_diversion(session, tdata);
+    }
 }
 
-static struct ast_sip_session_supplement diversion_supplement = {
+static struct ast_sip_session_supplement diversion_supplement_media = {
+	.method = "INVITE",
+	/* this supplement needs to be called after caller id
+           and after the channel has been created */
+	.priority = AST_SIP_SUPPLEMENT_PRIORITY_CHANNEL + 100,
+	.incoming_response = diversion_incoming_response_media,
+	.response_priority = AST_SIP_SESSION_BEFORE_MEDIA,
+};
+
+static struct ast_sip_session_supplement diversion_supplement_redirecting = {
 	.method = "INVITE",
 	/* this supplement needs to be called after caller id
            and after the channel has been created */
 	.priority = AST_SIP_SUPPLEMENT_PRIORITY_CHANNEL + 100,
 	.incoming_request = diversion_incoming_request,
-	.incoming_response = diversion_incoming_response,
+	.incoming_response = diversion_incoming_response_redirecting,
 	.outgoing_request = diversion_outgoing_request,
 	.outgoing_response = diversion_outgoing_response,
-	.response_priority = AST_SIP_SESSION_BEFORE_MEDIA,
+	.response_priority = AST_SIP_SESSION_BEFORE_REDIRECTING,
 };
 
 static int load_module(void)
@@ -709,13 +741,15 @@ static int load_module(void)
 	/* Because we are passing static memory to pjsip, we need to make sure it
 	 * stays valid while we potentially have active sessions */
 	ast_module_shutdown_ref(ast_module_info->self);
-	ast_sip_session_register_supplement(&diversion_supplement);
+	ast_sip_session_register_supplement(&diversion_supplement_media);
+	ast_sip_session_register_supplement(&diversion_supplement_redirecting);
 	return AST_MODULE_LOAD_SUCCESS;
 }
 
 static int unload_module(void)
 {
-	ast_sip_session_unregister_supplement(&diversion_supplement);
+	ast_sip_session_unregister_supplement(&diversion_supplement_media);
+	ast_sip_session_unregister_supplement(&diversion_supplement_redirecting);
 	return 0;
 }