[Asterisk-code-review] debugging: Add enough to choke a mule (asterisk[17])

George Joseph asteriskteam at digium.com
Mon Sep 14 09:55:40 CDT 2020


George Joseph has submitted this change. ( https://gerrit.asterisk.org/c/asterisk/+/14891 )

Change subject: debugging:  Add enough to choke a mule
......................................................................

debugging:  Add enough to choke a mule

Added to:
 * bridges/bridge_softmix.c
 * channels/chan_pjsip.c
 * include/asterisk/res_pjsip_session.h
 * main/channel.c
 * res/res_pjsip_session.c

There NO functional changes in this commit.

Change-Id: I06af034d1ff3ea1feb56596fd7bd6d7939dfdcc3
---
M bridges/bridge_softmix.c
M channels/chan_pjsip.c
M include/asterisk/res_pjsip_session.h
M main/channel.c
M res/res_pjsip_session.c
5 files changed, 418 insertions(+), 211 deletions(-)

Approvals:
  Joshua Colp: Looks good to me, but someone else must approve
  George Joseph: Looks good to me, approved; Approved for Submit



diff --git a/bridges/bridge_softmix.c b/bridges/bridge_softmix.c
index 931cf62..8d2d67c 100644
--- a/bridges/bridge_softmix.c
+++ b/bridges/bridge_softmix.c
@@ -629,6 +629,7 @@
 
 	joiner_video = ast_stream_topology_alloc();
 	if (!joiner_video) {
+		ast_log(LOG_ERROR, "%s: Couldn't alloc topology\n", ast_channel_name(joiner->chan));
 		return;
 	}
 
@@ -642,6 +643,7 @@
 	ast_channel_unlock(joiner->chan);
 
 	if (res || !sc->topology) {
+		ast_log(LOG_ERROR, "%s: Couldn't append source streams\n", ast_channel_name(joiner->chan));
 		goto cleanup;
 	}
 
@@ -655,11 +657,17 @@
 			ast_channel_get_stream_topology(participant->chan));
 		ast_channel_unlock(participant->chan);
 		if (res) {
+			ast_log(LOG_ERROR, "%s/%s: Couldn't append source streams\n",
+				ast_channel_name(participant->chan), ast_channel_name(joiner->chan));
 			goto cleanup;
 		}
 	}
 
-	ast_channel_request_stream_topology_change(joiner->chan, sc->topology, NULL);
+	res = ast_channel_request_stream_topology_change(joiner->chan, sc->topology, NULL);
+	if (res) {
+		ast_debug(3, "%s: Couldn't request topology change\n", ast_channel_name(joiner->chan));
+		goto cleanup;
+	}
 
 	AST_LIST_TRAVERSE(participants, participant, entry) {
 		if (participant == joiner) {
@@ -668,9 +676,16 @@
 
 		sc = participant->tech_pvt;
 		if (append_all_streams(sc->topology, joiner_video)) {
+			ast_log(LOG_ERROR, "%s/%s: Couldn't apopend streams\n",
+				ast_channel_name(participant->chan), ast_channel_name(joiner->chan));
 			goto cleanup;
 		}
-		ast_channel_request_stream_topology_change(participant->chan, sc->topology, NULL);
+		res = ast_channel_request_stream_topology_change(participant->chan, sc->topology, NULL);
+		if (res) {
+			ast_debug(3, "%s/%s: Couldn't request topology change\n",
+				ast_channel_name(participant->chan), ast_channel_name(joiner->chan));
+			goto cleanup;
+		}
 	}
 
 cleanup:
@@ -2250,10 +2265,13 @@
 	struct ast_stream_topology *added_streams;
 	struct ast_bridge_channels_list *participants = &bridge->channels;
 	struct ast_bridge_channel *participant;
+	SCOPE_ENTER(3, "%s: OT: %s NT: %s\n", ast_channel_name(bridge_channel->chan),
+		ast_str_tmp(256, ast_stream_topology_to_str(old_topology, &STR_TMP)),
+		ast_str_tmp(256, ast_stream_topology_to_str(new_topology, &STR_TMP)));
 
 	added_streams = ast_stream_topology_alloc();
 	if (!added_streams) {
-		return;
+		SCOPE_EXIT_LOG(LOG_ERROR, "%s: Couldn't alloc topology\n", ast_channel_name(bridge_channel->chan));
 	}
 
 	/* We go through the old topology comparing it to the new topology to determine what streams
@@ -2262,19 +2280,24 @@
 	 * Added streams are copied into a topology and added to each other participant while for
 	 * removed streams we merely store their position and mark them as removed later.
 	 */
+	ast_trace(-1, "%s: Checking for state changes\n", ast_channel_name(bridge_channel->chan));
 	for (index = 0; index < ast_stream_topology_get_count(sc->topology) && index < ast_stream_topology_get_count(new_topology); ++index) {
 		struct ast_stream *old_stream = ast_stream_topology_get_stream(sc->topology, index);
 		struct ast_stream *new_stream = ast_stream_topology_get_stream(new_topology, index);
+		SCOPE_ENTER(4, "%s:   Slot: %d  Old stream: %s  New stream: %s\n",  ast_channel_name(bridge_channel->chan),
+			index, ast_str_tmp(256, ast_stream_to_str(old_stream, &STR_TMP)),
+			ast_str_tmp(256, ast_stream_to_str(new_stream, &STR_TMP)));
 
 		/* Ignore all streams that don't carry video and streams that are strictly outgoing destination streams */
 		if ((ast_stream_get_type(old_stream) != AST_MEDIA_TYPE_VIDEO && ast_stream_get_type(new_stream) != AST_MEDIA_TYPE_VIDEO) ||
 			!strncmp(ast_stream_get_name(new_stream), SOFTBRIDGE_VIDEO_DEST_PREFIX,
 				SOFTBRIDGE_VIDEO_DEST_LEN)) {
-			continue;
+			SCOPE_EXIT_EXPR(continue, "%s: Stream %d ignored\n",  ast_channel_name(bridge_channel->chan), index);
 		}
 
 		if (ast_stream_get_type(old_stream) == AST_MEDIA_TYPE_VIDEO && ast_stream_get_type(new_stream) != AST_MEDIA_TYPE_VIDEO) {
 			/* If a stream renegotiates from video to non-video then we need to remove it as a source */
+			ast_trace(-1, "%s: Stream %d added to remove list\n",  ast_channel_name(bridge_channel->chan), index);
 			removed_streams[removed_streams_count++] = index;
 		} else if (ast_stream_get_type(old_stream) != AST_MEDIA_TYPE_VIDEO && ast_stream_get_type(new_stream) == AST_MEDIA_TYPE_VIDEO) {
 			if (ast_stream_get_state(new_stream) != AST_STREAM_STATE_REMOVED) {
@@ -2282,11 +2305,14 @@
 				if (append_source_stream(added_streams, ast_channel_name(bridge_channel->chan),
 							bridge->softmix.send_sdp_label ? ast_channel_uniqueid(bridge_channel->chan) : NULL,
 							new_stream, index)) {
-					goto cleanup;
+					SCOPE_EXIT_EXPR(goto cleanup, "%s: Couldn't append source stream %d:%s\n",  ast_channel_name(bridge_channel->chan),
+						index, ast_stream_get_name(new_stream));
 				}
+				ast_trace(-1, "%s: Stream %d changed from non-video to video\n",  ast_channel_name(bridge_channel->chan), index);
 			}
 		} else if (ast_stream_get_state(old_stream) != AST_STREAM_STATE_REMOVED &&
 				ast_stream_get_state(new_stream) != AST_STREAM_STATE_SENDRECV && ast_stream_get_state(new_stream) != AST_STREAM_STATE_RECVONLY) {
+			ast_trace(-1, "%s: Stream %d added to remove list\n",  ast_channel_name(bridge_channel->chan), index);
 			/* If a stream renegotiates and is removed then we remove it */
 			removed_streams[removed_streams_count++] = index;
 		} else if ((ast_stream_get_state(old_stream) == AST_STREAM_STATE_REMOVED || ast_stream_get_state(old_stream) == AST_STREAM_STATE_INACTIVE ||
@@ -2297,9 +2323,14 @@
 			if (append_source_stream(added_streams, ast_channel_name(bridge_channel->chan),
 						bridge->softmix.send_sdp_label ? ast_channel_uniqueid(bridge_channel->chan) : NULL,
 						new_stream, index)) {
-				goto cleanup;
+				SCOPE_EXIT_EXPR(goto cleanup, "%s: Couldn't append source stream %d:%s\n",  ast_channel_name(bridge_channel->chan),
+					index, ast_stream_get_name(new_stream));
 			}
+			ast_trace(-1, "%s: Stream %d:%s changed state from %s to %s\n",  ast_channel_name(bridge_channel->chan),
+				index, ast_stream_get_name(old_stream), ast_stream_state2str(ast_stream_get_state(old_stream)),
+				ast_stream_state2str(ast_stream_get_state(new_stream)));
 		}
+		SCOPE_EXIT();
 	}
 
 	/* Any newly added streams that did not take the position of a removed stream
@@ -2307,18 +2338,26 @@
 	 * removed from the topology but merely marked as removed we can pick up where we
 	 * left off when comparing the old and new topologies.
 	 */
+	ast_trace(-1, "%s: Checking for newly added streams\n", ast_channel_name(bridge_channel->chan));
+
 	for (; index < ast_stream_topology_get_count(new_topology); ++index) {
 		struct ast_stream *stream = ast_stream_topology_get_stream(new_topology, index);
+		SCOPE_ENTER(4, "%s: Checking stream %d:%s\n",  ast_channel_name(bridge_channel->chan), index,
+			ast_stream_get_name(stream));
 
 		if (!is_video_source(stream)) {
-			continue;
+			SCOPE_EXIT_EXPR(continue, "%s: Stream %d:%s is not video source\n",  ast_channel_name(bridge_channel->chan),
+				index, ast_stream_get_name(stream));
 		}
 
 		if (append_source_stream(added_streams, ast_channel_name(bridge_channel->chan),
 					bridge->softmix.send_sdp_label ? ast_channel_uniqueid(bridge_channel->chan) : NULL,
 					stream, index)) {
-			goto cleanup;
+			SCOPE_EXIT_EXPR(goto cleanup, "%s: Couldn't append stream %d:%s\n",  ast_channel_name(bridge_channel->chan),
+				index, ast_stream_get_name(stream));
 		}
+		SCOPE_EXIT("%s:   Added new stream %s\n", ast_channel_name(bridge_channel->chan),
+			ast_str_tmp(256, ast_stream_to_str(stream, &STR_TMP)));
 	}
 
 	/*  We always update the stored topology if we can to reflect what is currently negotiated */
@@ -2333,42 +2372,67 @@
 	 * other participants.
 	 */
 	if (!removed_streams_count && !ast_stream_topology_get_count(added_streams)) {
+		ast_trace(-1, "%s: Nothing added or removed\n", ast_channel_name(bridge_channel->chan));
 		goto cleanup;
 	}
 
+	ast_trace(-1, "%s: Processing adds and removes\n", ast_channel_name(bridge_channel->chan));
 	/* Go through each participant adding in the new streams and removing the old ones */
-	AST_LIST_TRAVERSE(participants, participant, entry) {
-		if (participant == bridge_channel) {
-			continue;
-		}
+	AST_LIST_TRAVERSE(participants, participant, entry)
+	{
+		struct softmix_channel *participant_sc = participant->tech_pvt;
+		SCOPE_ENTER(4, "%s/%s: Old participant topology %s\n",
+			ast_channel_name(bridge_channel->chan),
+			ast_channel_name(participant->chan),
+			ast_str_tmp(256, ast_stream_topology_to_str(participant_sc->topology, &STR_TMP)));
 
-		sc = participant->tech_pvt;
+		if (participant == bridge_channel) {
+			SCOPE_EXIT_EXPR(continue, "%s/%s: Same channel.  Skipping\n",
+				ast_channel_name(bridge_channel->chan),
+				ast_channel_name(participant->chan));
+		}
 
 		/* We add in all the new streams first so that they do not take the place
 		 * of any of our removed streams, allowing the remote side to reset the state
 		 * for each removed stream. */
-                if (append_all_streams(sc->topology, added_streams)) {
-                        goto cleanup;
-                }
+		if (append_all_streams(participant_sc->topology, added_streams)) {
+			SCOPE_EXIT_EXPR(goto cleanup, "%s/%s: Couldn't append streams\n",  ast_channel_name(bridge_channel->chan),
+				ast_channel_name(participant->chan));
+		}
+		ast_trace(-1, "%s/%s:   Adding streams %s\n", ast_channel_name(bridge_channel->chan),
+			ast_channel_name(participant->chan),
+			ast_str_tmp(256, ast_stream_topology_to_str(added_streams, &STR_TMP)));
 
 		/* Then we go through and remove any ones that were removed */
-		for (index = 0; removed_streams_count && index < ast_stream_topology_get_count(sc->topology); ++index) {
+		for (index = 0;
+			removed_streams_count && index < ast_stream_topology_get_count(sc->topology); ++index) {
 			struct ast_stream *stream = ast_stream_topology_get_stream(sc->topology, index);
 			int removed_stream;
 
 			for (removed_stream = 0; removed_stream < removed_streams_count; ++removed_stream) {
-				if (is_video_dest(stream, ast_channel_name(bridge_channel->chan), removed_streams[removed_stream])) {
+				if (is_video_dest(stream, ast_channel_name(bridge_channel->chan),
+					removed_streams[removed_stream])) {
+					ast_trace(-1, "%s/%s:    Removing stream %s\n",
+						ast_channel_name(bridge_channel->chan),
+						ast_channel_name(participant->chan),
+						ast_str_tmp(256, ast_stream_to_str(stream, &STR_TMP)));
 					ast_stream_set_state(stream, AST_STREAM_STATE_REMOVED);
 				}
 			}
 		}
+		ast_channel_request_stream_topology_change(participant->chan, participant_sc->topology, NULL);
+		SCOPE_EXIT("%s/%s:   New participant topology %s\n",
+			ast_channel_name(bridge_channel->chan),
+			ast_channel_name(participant->chan),
+			ast_str_tmp(256, ast_stream_topology_to_str(participant_sc->topology, &STR_TMP)));
+	}
 
-                ast_channel_request_stream_topology_change(participant->chan, sc->topology, NULL);
-        }
-
+	ast_trace(-1, "%s: New topology %s\n", ast_channel_name(bridge_channel->chan),
+		ast_str_tmp(256, ast_stream_topology_to_str(sc->topology, &STR_TMP)));
 
 cleanup:
 	ast_stream_topology_free(added_streams);
+	SCOPE_EXIT();
 }
 
 /*!
@@ -2389,6 +2453,7 @@
 	struct ast_vector_int media_types;
 	int nths[AST_MEDIA_TYPE_END] = {0};
 	int idx;
+	SCOPE_ENTER(3, "%s: \n", ast_channel_name(bridge_channel->chan));
 
 	switch (bridge->softmix.video_mode.mode) {
 	case AST_BRIDGE_VIDEO_MODE_NONE:
@@ -2396,7 +2461,7 @@
 	case AST_BRIDGE_VIDEO_MODE_TALKER_SRC:
 	default:
 		ast_bridge_channel_stream_map(bridge_channel);
-		return;
+		SCOPE_EXIT_RTN("%s: Not in SFU mode\n", ast_channel_name(bridge_channel->chan));
 	case AST_BRIDGE_VIDEO_MODE_SFU:
 		break;
 	}
@@ -2506,6 +2571,7 @@
 	}
 
 	AST_VECTOR_FREE(&media_types);
+	SCOPE_EXIT_RTN("%s\n", ast_channel_name(bridge_channel->chan));
 }
 
 static struct ast_bridge_technology softmix_bridge = {
diff --git a/channels/chan_pjsip.c b/channels/chan_pjsip.c
index afaecdf..6654905 100644
--- a/channels/chan_pjsip.c
+++ b/channels/chan_pjsip.c
@@ -1564,32 +1564,45 @@
 
 static int on_topology_change_response(struct ast_sip_session *session, pjsip_rx_data *rdata)
 {
+	SCOPE_ENTER(3, "%s: Received response code %d.  PT: %s  AT: %s\n", ast_sip_session_get_name(session),
+		rdata->msg_info.msg->line.status.code,
+		ast_str_tmp(256, ast_stream_topology_to_str(session->pending_media_state->topology, &STR_TMP)),
+		ast_str_tmp(256, ast_stream_topology_to_str(session->active_media_state->topology, &STR_TMP)));
+
+
 	if (PJSIP_IS_STATUS_IN_CLASS(rdata->msg_info.msg->line.status.code, 200)) {
 		/* The topology was changed to something new so give notice to what requested
 		 * it so it queries the channel and updates accordingly.
 		 */
 		if (session->channel) {
 			ast_queue_control(session->channel, AST_CONTROL_STREAM_TOPOLOGY_CHANGED);
+			SCOPE_EXIT_RTN_VALUE(0, "%s: Queued topology change frame\n", ast_sip_session_get_name(session));
 		}
+		SCOPE_EXIT_RTN_VALUE(0, "%s: No channel?  Can't queue topology change frame\n", ast_sip_session_get_name(session));
 	} else if (300 <= rdata->msg_info.msg->line.status.code) {
 		/* The topology change failed, so drop the current pending media state */
 		ast_sip_session_media_state_reset(session->pending_media_state);
+		SCOPE_EXIT_RTN_VALUE(0, "%s: response code > 300.  Resetting pending media state\n", ast_sip_session_get_name(session));
 	}
 
-	return 0;
+	SCOPE_EXIT_RTN_VALUE(0, "%s: Nothing to do\n", ast_sip_session_get_name(session));
 }
 
 static int send_topology_change_refresh(void *data)
 {
 	struct topology_change_refresh_data *refresh_data = data;
+	struct ast_sip_session *session = refresh_data->session;
 	int ret;
+	SCOPE_ENTER(3, "%s: %s\n", ast_sip_session_get_name(session),
+		ast_str_tmp(256, ast_stream_topology_to_str(refresh_data->media_state->topology, &STR_TMP)));
 
-	ret = ast_sip_session_refresh(refresh_data->session, NULL, NULL, on_topology_change_response,
+
+	ret = ast_sip_session_refresh(session, NULL, NULL, on_topology_change_response,
 		AST_SIP_SESSION_REFRESH_METHOD_INVITE, 1, refresh_data->media_state);
 	refresh_data->media_state = NULL;
 	topology_change_refresh_data_free(refresh_data);
 
-	return ret;
+	SCOPE_EXIT_RTN_VALUE(ret, "%s\n", ast_sip_session_get_name(session));
 }
 
 static int handle_topology_request_change(struct ast_sip_session *session,
@@ -1621,6 +1634,15 @@
 	size_t device_buf_size;
 	int i;
 	const struct ast_stream_topology *topology;
+	struct ast_frame f = {
+		.frametype = AST_FRAME_CONTROL,
+		.subclass = {
+			.integer = condition
+		}
+	};
+	char condition_name[256];
+	SCOPE_ENTER(3, "%s: Indicated %s\n", ast_channel_name(ast),
+		ast_frame_subclass2str(&f, condition_name, sizeof(condition_name), NULL, 0));
 
 	switch (condition) {
 	case AST_CONTROL_RINGING:
@@ -1725,9 +1747,9 @@
 		ao2_ref(channel->session, +1);
 #ifdef HAVE_PJSIP_INV_SESSION_REF
 		if (pjsip_inv_add_ref(channel->session->inv_session) != PJ_SUCCESS) {
-			ast_log(LOG_ERROR, "Can't increase the session reference counter\n");
 			ao2_cleanup(channel->session);
-			return -1;
+			SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't increase the session reference counter\n",
+				ast_channel_name(ast));
 		}
 #endif
 		if (ast_sip_push_task(channel->session->serializer, update_connected_line_information, channel->session)) {
@@ -1817,6 +1839,8 @@
 		break;
 	case AST_CONTROL_STREAM_TOPOLOGY_REQUEST_CHANGE:
 		topology = data;
+		ast_trace(-1, "%s: New topology: %s\n", ast_channel_name(ast),
+			ast_str_tmp(256, ast_stream_topology_to_str(topology, &STR_TMP)));
 		res = handle_topology_request_change(channel->session, topology);
 		break;
 	case AST_CONTROL_STREAM_TOPOLOGY_CHANGED:
@@ -1836,18 +1860,17 @@
 		struct indicate_data *ind_data = indicate_data_alloc(channel->session, condition, response_code, data, datalen);
 
 		if (!ind_data) {
-			return -1;
+			SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't alloc indicate data\n", ast_channel_name(ast));
 		}
 #ifdef HAVE_PJSIP_INV_SESSION_REF
 		if (pjsip_inv_add_ref(ind_data->session->inv_session) != PJ_SUCCESS) {
-			ast_log(LOG_ERROR, "Can't increase the session reference counter\n");
 			ao2_cleanup(ind_data);
-			return -1;
+			SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't increase the session reference counter\n", ast_channel_name(ast));
 		}
 #endif
 		if (ast_sip_push_task(channel->session->serializer, indicate, ind_data)) {
-			ast_log(LOG_NOTICE, "Cannot send response code %d to endpoint %s. Could not queue task properly\n",
-					response_code, ast_sorcery_object_get_id(channel->session->endpoint));
+			ast_log(LOG_ERROR, "%s: Cannot send response code %d to endpoint %s. Could not queue task properly\n",
+					ast_channel_name(ast), response_code, ast_sorcery_object_get_id(channel->session->endpoint));
 #ifdef HAVE_PJSIP_INV_SESSION_REF
 			pjsip_inv_dec_ref(ind_data->session->inv_session);
 #endif
@@ -1856,7 +1879,7 @@
 		}
 	}
 
-	return res;
+	SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_channel_name(ast));
 }
 
 struct transfer_data {
@@ -3029,9 +3052,10 @@
 	RAII_VAR(struct ast_datastore *, datastore, NULL, ao2_cleanup);
 	struct transport_info_data *transport_data;
 	pjsip_tx_data *packet = NULL;
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));
 
 	if (session->channel) {
-		return 0;
+		SCOPE_EXIT_RTN_VALUE(0, "%s: No channel\n", ast_sip_session_get_name(session));
 	}
 
 	/* Check for a to-tag to determine if this is a reinvite */
@@ -3047,17 +3071,17 @@
 		 */
 		session->defer_terminate = 0;
 		ast_sip_session_terminate(session, 400);
-		return -1;
+		SCOPE_EXIT_RTN_VALUE(-1, "%s: We have a To tag but no channel.  Terminating session\n", ast_sip_session_get_name(session));
 	}
 
 	datastore = ast_sip_session_alloc_datastore(&transport_info, "transport_info");
 	if (!datastore) {
-		return -1;
+		SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't alloc transport_info datastore\n", ast_sip_session_get_name(session));
 	}
 
 	transport_data = ast_calloc(1, sizeof(*transport_data));
 	if (!transport_data) {
-		return -1;
+		SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't alloc transport_info\n", ast_sip_session_get_name(session));
 	}
 	pj_sockaddr_cp(&transport_data->local_addr, &rdata->tp_info.transport->local_addr);
 	pj_sockaddr_cp(&transport_data->remote_addr, &rdata->pkt_info.src_addr);
@@ -3070,12 +3094,12 @@
 			ast_sip_session_send_response(session, packet);
 		}
 
-		ast_log(LOG_ERROR, "Failed to allocate new PJSIP channel on incoming SIP INVITE\n");
-		return -1;
+		SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Failed to allocate new PJSIP channel on incoming SIP INVITE\n",
+			 ast_sip_session_get_name(session));
 	}
 	/* channel gets created on incoming request, but we wait to call start
            so other supplements have a chance to run */
-	return 0;
+	SCOPE_EXIT_RTN_VALUE(0, "%s\n", ast_sip_session_get_name(session));
 }
 
 static int call_pickup_incoming_request(struct ast_sip_session *session, pjsip_rx_data *rdata)
@@ -3173,9 +3197,10 @@
 	struct pjsip_status_line status = rdata->msg_info.msg->line.status;
 	struct ast_control_pvt_cause_code *cause_code;
 	int data_size = sizeof(*cause_code);
+	SCOPE_ENTER(3, "%s: Status: %d\n", ast_sip_session_get_name(session), status.code);
 
 	if (!session->channel) {
-		return;
+		SCOPE_EXIT_RTN("%s: No channel\n", ast_sip_session_get_name(session));
 	}
 
 	/* Build and send the tech-specific cause information */
@@ -3195,6 +3220,7 @@
 
 	switch (status.code) {
 	case 180:
+		ast_trace(-1, "%s: Queueing RINGING\n", ast_sip_session_get_name(session));
 		ast_queue_control(session->channel, AST_CONTROL_RINGING);
 		ast_channel_lock(session->channel);
 		if (ast_channel_state(session->channel) != AST_STATE_UP) {
@@ -3203,6 +3229,7 @@
 		ast_channel_unlock(session->channel);
 		break;
 	case 183:
+		ast_trace(-1, "%s: Queueing PROGRESS\n", ast_sip_session_get_name(session));
 		if (session->endpoint->ignore_183_without_sdp) {
 			pjsip_rdata_sdp_info *sdp = pjsip_rdata_get_sdp_info(rdata);
 			if (sdp && sdp->body.ptr) {
@@ -3213,21 +3240,28 @@
 		}
 		break;
 	case 200:
+		ast_trace(-1, "%s: Queueing ANSWER\n", ast_sip_session_get_name(session));
 		ast_queue_control(session->channel, AST_CONTROL_ANSWER);
 		break;
 	default:
+		ast_trace(-1, "%s: Not queueing anything\n", ast_sip_session_get_name(session));
 		break;
 	}
+
+	SCOPE_EXIT_RTN("%s\n", ast_sip_session_get_name(session));
 }
 
 static int chan_pjsip_incoming_ack(struct ast_sip_session *session, struct pjsip_rx_data *rdata)
 {
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));
+
 	if (rdata->msg_info.msg->line.req.method.id == PJSIP_ACK_METHOD) {
 		if (session->endpoint->media.direct_media.enabled && session->channel) {
+			ast_trace(-1, "%s: Queueing SRCCHANGE\n", ast_sip_session_get_name(session));
 			ast_queue_control(session->channel, AST_CONTROL_SRCCHANGE);
 		}
 	}
-	return 0;
+	SCOPE_EXIT_RTN_VALUE(0, "%s\n", ast_sip_session_get_name(session));
 }
 
 static int update_devstate(void *obj, void *arg, int flags)
diff --git a/include/asterisk/res_pjsip_session.h b/include/asterisk/res_pjsip_session.h
index d8b215e..180c868 100644
--- a/include/asterisk/res_pjsip_session.h
+++ b/include/asterisk/res_pjsip_session.h
@@ -117,6 +117,10 @@
 	unsigned int changed;
 	/*! \brief Remote media stream label */
 	char *remote_mslabel;
+	/*! \brief Remote stream label */
+	char *remote_label;
+	/*! \brief Stream name */
+	char *stream_name;
 };
 
 /*!
diff --git a/main/channel.c b/main/channel.c
index 339f004..0470ddc 100644
--- a/main/channel.c
+++ b/main/channel.c
@@ -11006,8 +11006,10 @@
 	}
 
 	if (ast_stream_topology_equal(ast_channel_get_stream_topology(chan), topology)) {
-		ast_debug(3, "Topology of %s already matches what is requested so ignoring topology change request\n",
-				ast_channel_name(chan));
+		ast_debug(2, "%s: Topologies already match. Current: %s  Requested: %s\n",
+				ast_channel_name(chan),
+				ast_str_tmp(256, ast_stream_topology_to_str(ast_channel_get_stream_topology(chan), &STR_TMP)),
+				ast_str_tmp(256, ast_stream_topology_to_str(topology, &STR_TMP)));
 		ast_channel_unlock(chan);
 		return 0;
 	}
diff --git a/res/res_pjsip_session.c b/res/res_pjsip_session.c
index 0896212..a344eb5 100644
--- a/res/res_pjsip_session.c
+++ b/res/res_pjsip_session.c
@@ -482,12 +482,15 @@
 
 	ast_free(session_media->mid);
 	ast_free(session_media->remote_mslabel);
+	ast_free(session_media->remote_label);
+	ast_free(session_media->stream_name);
 }
 
 struct ast_sip_session_media *ast_sip_session_media_state_add(struct ast_sip_session *session,
 	struct ast_sip_session_media_state *media_state, enum ast_media_type type, int position)
 {
 	struct ast_sip_session_media *session_media = NULL;
+	SCOPE_ENTER(1, "%s Adding position %d\n", ast_sip_session_get_name(session), position);
 
 	/* It is possible for this media state to already contain a session for the stream. If this
 	 * is the case we simply return it.
@@ -495,7 +498,7 @@
 	if (position < AST_VECTOR_SIZE(&media_state->sessions)) {
 		session_media = AST_VECTOR_GET(&media_state->sessions, position);
 		if (session_media) {
-			return session_media;
+			SCOPE_EXIT_RTN_VALUE(session_media, "Using existing media_session\n");
 		}
 	}
 
@@ -505,6 +508,7 @@
 		/* A stream can never exist without an accompanying media session */
 		if (session_media->type == type) {
 			ao2_ref(session_media, +1);
+			ast_trace(1, "Reusing existing media session\n");
 			/*
 			 * If this session_media was previously removed, its bundle group was probably reset
 			 * to -1 so if bundling is enabled on the endpoint, we need to reset it to 0, set
@@ -516,10 +520,12 @@
 				ast_free(session_media->mid);
 				if (ast_asprintf(&session_media->mid, "%s-%d", ast_codec_media_type2str(type), position) < 0) {
 					ao2_ref(session_media, -1);
-					return NULL;
+					SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't alloc mid\n");
 				}
 			}
 		} else {
+			ast_trace(1, "Can't reuse existing media session because the types are different. %s <> %s\n",
+				ast_codec_media_type2str(type), ast_codec_media_type2str(session_media->type));
 			session_media = NULL;
 		}
 	}
@@ -530,6 +536,7 @@
 		if (!session_media) {
 			return NULL;
 		}
+		ast_trace(1, "Creating new media session\n");
 
 		session_media->encryption = session->endpoint->media.rtp.encryption;
 		session_media->remote_ice = session->endpoint->media.rtp.ice_support;
@@ -545,7 +552,7 @@
 			 */
 			if (ast_asprintf(&session_media->mid, "%s-%d", ast_codec_media_type2str(type), position) < 0) {
 				ao2_ref(session_media, -1);
-				return NULL;
+				SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't alloc mid\n");
 			}
 			session_media->bundle_group = 0;
 
@@ -559,18 +566,23 @@
 		}
 	}
 
+	ast_free(session_media->stream_name);
+	session_media->stream_name = ast_strdup(ast_stream_get_name(ast_stream_topology_get_stream(media_state->topology, position)));
+
 	if (AST_VECTOR_REPLACE(&media_state->sessions, position, session_media)) {
 		ao2_ref(session_media, -1);
 
-		return NULL;
+		SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't replace media_session\n");
 	}
 
 	/* If this stream will be active in some way and it is the first of this type then consider this the default media session to match */
 	if (!media_state->default_session[type] && ast_stream_get_state(ast_stream_topology_get_stream(media_state->topology, position)) != AST_STREAM_STATE_REMOVED) {
+		ast_trace(1, "Setting media session as default for %s\n", ast_codec_media_type2str(session_media->type));
+
 		media_state->default_session[type] = session_media;
 	}
 
-	return session_media;
+	SCOPE_EXIT_RTN_VALUE(session_media, "Done\n");
 }
 
 static int is_stream_limitation_reached(enum ast_media_type type, const struct ast_sip_endpoint *endpoint, int *type_streams)
@@ -675,6 +687,8 @@
 
 	ast_free(session_media->remote_mslabel);
 	session_media->remote_mslabel = NULL;
+	ast_free(session_media->remote_label);
+	session_media->remote_label = NULL;
 
 	for (index = 0; index < stream->attr_count; ++index) {
 		pjmedia_sdp_attr *attr = stream->attr[index];
@@ -683,8 +697,12 @@
 		char *msid, *tmp = attr_value;
 		static const pj_str_t STR_msid = { "msid", 4 };
 		static const pj_str_t STR_ssrc = { "ssrc", 4 };
+		static const pj_str_t STR_label = { "label", 5 };
 
-		if (!pj_strcmp(&attr->name, &STR_msid)) {
+		if (!pj_strcmp(&attr->name, &STR_label)) {
+			ast_copy_pj_str(attr_value, &attr->value, sizeof(attr_value));
+			session_media->remote_label = ast_strdup(attr_value);
+		} else if (!pj_strcmp(&attr->name, &STR_msid)) {
 			ast_copy_pj_str(attr_value, &attr->value, sizeof(attr_value));
 			msid = strsep(&tmp, " ");
 			session_media->remote_mslabel = ast_strdup(msid);
@@ -744,17 +762,19 @@
 	int i;
 	int handled = 0;
 	int type_streams[AST_MEDIA_TYPE_END] = {0};
+	SCOPE_ENTER(3, "%s: Media count: %d\n", ast_sip_session_get_name(session), sdp->media_count);
 
 	if (session->inv_session && session->inv_session->state == PJSIP_INV_STATE_DISCONNECTED) {
-		ast_log(LOG_ERROR, "Failed to handle incoming SDP. Session has been already disconnected\n");
-		return -1;
+		SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Failed to handle incoming SDP. Session has been already disconnected\n",
+			ast_sip_session_get_name(session));
 	}
 
 	/* It is possible for SDP deferral to have already created a pending topology */
 	if (!session->pending_media_state->topology) {
 		session->pending_media_state->topology = ast_stream_topology_alloc();
 		if (!session->pending_media_state->topology) {
-			return -1;
+			SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_ERROR, "%s: Couldn't alloc pending topology\n",
+				ast_sip_session_get_name(session));
 		}
 	}
 
@@ -768,6 +788,7 @@
 		enum ast_media_type type;
 		struct ast_stream *stream = NULL;
 		pjmedia_sdp_media *remote_stream = sdp->media[i];
+		SCOPE_ENTER(4, "%s: Processing stream %d\n", ast_sip_session_get_name(session), i);
 
 		/* We need a null-terminated version of the media string */
 		ast_copy_pj_str(media, &sdp->media[i]->desc.media, sizeof(media));
@@ -776,6 +797,8 @@
 		/* See if we have an already existing stream, which can occur from SDP deferral checking */
 		if (i < ast_stream_topology_get_count(session->pending_media_state->topology)) {
 			stream = ast_stream_topology_get_stream(session->pending_media_state->topology, i);
+			ast_trace(-1, "%s: Using existing pending stream %s\n", ast_sip_session_get_name(session),
+				ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 		}
 		if (!stream) {
 			struct ast_stream *existing_stream = NULL;
@@ -785,6 +808,8 @@
 			if (session->active_media_state->topology &&
 				(i < ast_stream_topology_get_count(session->active_media_state->topology))) {
 				existing_stream = ast_stream_topology_get_stream(session->active_media_state->topology, i);
+				ast_trace(-1, "%s: Found existing active stream %s\n", ast_sip_session_get_name(session),
+					ast_str_tmp(128, ast_stream_to_str(existing_stream, &STR_TMP)));
 
 				if (ast_stream_get_state(existing_stream) != AST_STREAM_STATE_REMOVED) {
 					stream_name = (char *)ast_stream_get_name(existing_stream);
@@ -794,22 +819,34 @@
 
 			if (ast_strlen_zero(stream_name)) {
 				if (ast_asprintf(&stream_name, "%s-%d", ast_codec_media_type2str(type), i) < 0) {
-					return -1;
+					handled = 0;
+					SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't alloc stream name\n",
+						 ast_sip_session_get_name(session));
+
 				}
+				ast_trace(-1, "%s: Using %s for new stream name\n", ast_sip_session_get_name(session),
+					stream_name);
 			}
 
 			stream = ast_stream_alloc(stream_name, type);
 			if (!stream) {
-				return -1;
+				handled = 0;
+				SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't alloc stream\n",
+					 ast_sip_session_get_name(session));
 			}
 
 			if (!ast_strlen_zero(stream_label)) {
 				ast_stream_set_metadata(stream, "SDP:LABEL", stream_label);
+				ast_trace(-1, "%s: Using %s for new stream label\n", ast_sip_session_get_name(session),
+					stream_label);
+
 			}
 
 			if (ast_stream_topology_set_stream(session->pending_media_state->topology, i, stream)) {
 				ast_stream_free(stream);
-				return -1;
+				handled = 0;
+				SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't set stream in topology\n",
+					 ast_sip_session_get_name(session));
 			}
 
 			/* For backwards compatibility with the core the default audio stream is always sendrecv */
@@ -830,19 +867,21 @@
 			} else {
 				ast_stream_set_state(stream, AST_STREAM_STATE_SENDRECV);
 			}
+			ast_trace(-1, "%s: Using new stream %s\n", ast_sip_session_get_name(session),
+				ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 		}
 
 		session_media = ast_sip_session_media_state_add(session, session->pending_media_state, ast_media_type_from_str(media), i);
 		if (!session_media) {
-			return -1;
+			SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't alloc session media\n",
+				 ast_sip_session_get_name(session));
 		}
 
 		/* If this stream is already declined mark it as such, or mark it as such if we've reached the limit */
 		if (!remote_stream->desc.port || is_stream_limitation_reached(type, session->endpoint, type_streams)) {
-			ast_debug(1, "Declining incoming SDP media stream '%s' at position '%d'\n",
-				ast_codec_media_type2str(type), i);
 			remove_stream_from_bundle(session_media, stream);
-			continue;
+			SCOPE_EXIT_EXPR(continue, "%s: Declining incoming SDP media stream %s'\n",
+				ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 		}
 
 		set_mid_and_bundle_group(session, session_media, sdp, remote_stream);
@@ -850,66 +889,70 @@
 
 		if (session_media->handler) {
 			handler = session_media->handler;
-			ast_debug(1, "Negotiating incoming SDP media stream '%s' using %s SDP handler\n",
-				ast_codec_media_type2str(session_media->type),
+			ast_trace(-1, "%s: Negotiating incoming SDP media stream %s using %s SDP handler\n",
+				ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),
 				session_media->handler->id);
 			res = handler->negotiate_incoming_sdp_stream(session, session_media, sdp, i, stream);
 			if (res < 0) {
 				/* Catastrophic failure. Abort! */
-				return -1;
+				SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't negotiate stream %s\n",
+					 ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 			} else if (res == 0) {
-				ast_debug(1, "Declining incoming SDP media stream '%s' at position '%d'\n",
-					ast_codec_media_type2str(type), i);
 				remove_stream_from_bundle(session_media, stream);
-				continue;
+				SCOPE_EXIT_EXPR(continue, "%s: Declining incoming SDP media stream %s\n",
+					ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 			} else if (res > 0) {
-				ast_debug(1, "Media stream '%s' handled by %s\n",
-					ast_codec_media_type2str(session_media->type),
-					session_media->handler->id);
-				/* Handled by this handler. Move to the next stream */
 				handled = 1;
 				++type_streams[type];
-				continue;
+				/* Handled by this handler. Move to the next stream */
+				SCOPE_EXIT_EXPR(continue, "%s: Media stream %s handled by %s\n",
+					ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),
+					session_media->handler->id);
 			}
 		}
 
 		handler_list = ao2_find(sdp_handlers, media, OBJ_KEY);
 		if (!handler_list) {
-			ast_debug(1, "No registered SDP handlers for media type '%s'\n", media);
-			continue;
+			SCOPE_EXIT_EXPR(continue, "%s: Media stream %s has no registered handlers\n",
+				ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 		}
 		AST_LIST_TRAVERSE(&handler_list->list, handler, next) {
 			if (handler == session_media->handler) {
 				continue;
 			}
-			ast_debug(1, "Negotiating incoming SDP media stream '%s' using %s SDP handler\n",
-				ast_codec_media_type2str(session_media->type),
+			ast_trace(-1, "%s: Negotiating incoming SDP media stream %s using %s SDP handler\n",
+				ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),
 				handler->id);
+
 			res = handler->negotiate_incoming_sdp_stream(session, session_media, sdp, i, stream);
 			if (res < 0) {
 				/* Catastrophic failure. Abort! */
-				return -1;
+				handled = 0;
+				SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't negotiate stream %s\n",
+					 ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 			} else if (res == 0) {
-				ast_debug(1, "Declining incoming SDP media stream '%s' at position '%d'\n",
-					ast_codec_media_type2str(type), i);
 				remove_stream_from_bundle(session_media, stream);
+				ast_trace(-1, "%s: Declining incoming SDP media stream %s\n",
+					ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 				continue;
 			} else if (res > 0) {
-				ast_debug(1, "Media stream '%s' handled by %s\n",
-					ast_codec_media_type2str(session_media->type),
-					handler->id);
-				/* Handled by this handler. Move to the next stream */
 				session_media_set_handler(session_media, handler);
 				handled = 1;
 				++type_streams[type];
+				ast_trace(-1, "%s: Media stream %s handled by %s\n",
+					ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),
+					session_media->handler->id);
 				break;
 			}
 		}
+
+		SCOPE_EXIT("%s: Done with stream %s\n", ast_sip_session_get_name(session),
+			ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 	}
-	if (!handled) {
-		return -1;
-	}
-	return 0;
+
+end:
+	SCOPE_EXIT_RTN_VALUE(handled ? 0 : -1, "%s: Handled? %s\n", ast_sip_session_get_name(session),
+		handled ? "yes" : "no");
 }
 
 static int handle_negotiated_sdp_session_media(struct ast_sip_session_media *session_media,
@@ -952,13 +995,13 @@
 
 	handler = session_media->handler;
 	if (handler) {
-		ast_debug(1, "Applying negotiated SDP media stream '%s' using %s SDP handler\n",
-			ast_codec_media_type2str(session_media->type),
+		ast_debug(4, "%s: Applying negotiated SDP media stream '%s' using %s SDP handler\n",
+			ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),
 			handler->id);
 		res = handler->apply_negotiated_sdp_stream(session, session_media, local, remote, index, asterisk_stream);
 		if (res >= 0) {
-			ast_debug(1, "Applied negotiated SDP media stream '%s' using %s SDP handler\n",
-				ast_codec_media_type2str(session_media->type),
+			ast_debug(4, "%s: Applied negotiated SDP media stream '%s' using %s SDP handler\n",
+				ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),
 				handler->id);
 			return 0;
 		}
@@ -967,15 +1010,15 @@
 
 	handler_list = ao2_find(sdp_handlers, media, OBJ_KEY);
 	if (!handler_list) {
-		ast_debug(1, "No registered SDP handlers for media type '%s'\n", media);
+		ast_debug(4, "%s: No registered SDP handlers for media type '%s'\n", ast_sip_session_get_name(session), media);
 		return -1;
 	}
 	AST_LIST_TRAVERSE(&handler_list->list, handler, next) {
 		if (handler == session_media->handler) {
 			continue;
 		}
-		ast_debug(1, "Applying negotiated SDP media stream '%s' using %s SDP handler\n",
-			ast_codec_media_type2str(session_media->type),
+		ast_debug(4, "%s: Applying negotiated SDP media stream '%s' using %s SDP handler\n",
+			ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),
 			handler->id);
 		res = handler->apply_negotiated_sdp_stream(session, session_media, local, remote, index, asterisk_stream);
 		if (res < 0) {
@@ -983,8 +1026,8 @@
 			return -1;
 		}
 		if (res > 0) {
-			ast_debug(1, "Applied negotiated SDP media stream '%s' using %s SDP handler\n",
-				ast_codec_media_type2str(session_media->type),
+			ast_debug(4, "%s: Applied negotiated SDP media stream '%s' using %s SDP handler\n",
+				ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),
 				handler->id);
 			/* Handled by this handler. Move to the next stream */
 			session_media_set_handler(session_media, handler);
@@ -993,8 +1036,8 @@
 	}
 
 	if (session_media->handler && session_media->handler->stream_stop) {
-		ast_debug(1, "Stopping SDP media stream '%s' as it is not currently negotiated\n",
-			ast_codec_media_type2str(session_media->type));
+		ast_debug(4, "%s: Stopping SDP media stream '%s' as it is not currently negotiated\n",
+			ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type));
 		session_media->handler->stream_stop(session_media);
 	}
 
@@ -1019,16 +1062,16 @@
 			active_media_state_clone =
 				ast_sip_session_media_state_clone(session->active_media_state);
 			if (!active_media_state_clone) {
-				ast_log(LOG_WARNING, "Unable to clone active media state for channel '%s'\n",
-					session->channel ? ast_channel_name(session->channel) : "unknown");
+				ast_log(LOG_WARNING, "%s: Unable to clone active media state\n",
+					ast_sip_session_get_name(session));
 				return -1;
 			}
 
 			ast_sip_session_media_state_free(session->pending_media_state);
 			session->pending_media_state = active_media_state_clone;
 		} else {
-			ast_log(LOG_WARNING, "No pending or active media state for channel '%s'\n",
-				session->channel ? ast_channel_name(session->channel) : "unknown");
+			ast_log(LOG_WARNING, "%s: No pending or active media state\n",
+				ast_sip_session_get_name(session));
 			return -1;
 		}
 	}
@@ -1040,8 +1083,8 @@
 	 */
 	if (ast_stream_topology_get_count(session->pending_media_state->topology) != local->media_count
 		|| AST_VECTOR_SIZE(&session->pending_media_state->sessions) != local->media_count) {
-		ast_log(LOG_WARNING, "Local SDP for channel '%s' contains %d media streams while we expected it to contain %u\n",
-			session->channel ? ast_channel_name(session->channel) : "unknown",
+		ast_log(LOG_WARNING, "%s: Local SDP contains %d media streams while we expected it to contain %u\n",
+			ast_sip_session_get_name(session),
 			ast_stream_topology_get_count(session->pending_media_state->topology), local->media_count);
 		return -1;
 	}
@@ -1288,6 +1331,7 @@
 	struct ast_sip_session_media_state *pending_media_state;
 	/*! Active media state at the time of the original request */
 	struct ast_sip_session_media_state *active_media_state;
+
 	AST_LIST_ENTRY(ast_sip_session_delayed_request) next;
 };
 
@@ -1333,10 +1377,8 @@
 static int send_delayed_request(struct ast_sip_session *session, struct ast_sip_session_delayed_request *delay)
 {
 	int res;
-
-	ast_debug(3, "Endpoint '%s(%s)' sending delayed %s request.\n",
-		ast_sorcery_object_get_id(session->endpoint),
-		session->channel ? ast_channel_name(session->channel) : "",
+	SCOPE_ENTER(3, "%s: sending delayed %s request\n",
+		ast_sip_session_get_name(session),
 		delayed_method2str(delay->method));
 
 	switch (delay->method) {
@@ -1348,7 +1390,7 @@
 		/* Ownership of media state transitions to ast_sip_session_refresh */
 		delay->pending_media_state = NULL;
 		delay->active_media_state = NULL;
-		return res;
+		SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));
 	case DELAYED_METHOD_UPDATE:
 		res = sip_session_refresh(session, delay->on_request_creation,
 			delay->on_sdp_creation, delay->on_response,
@@ -1357,14 +1399,15 @@
 		/* Ownership of media state transitions to ast_sip_session_refresh */
 		delay->pending_media_state = NULL;
 		delay->active_media_state = NULL;
-		return res;
+		SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));
 	case DELAYED_METHOD_BYE:
 		ast_sip_session_terminate(session, 0);
-		return 0;
+		SCOPE_EXIT_RTN_VALUE(0, "%s: Terminating session on delayed BYE\n", ast_sip_session_get_name(session));
 	}
-	ast_log(LOG_WARNING, "Don't know how to send delayed %s(%d) request.\n",
+
+	SCOPE_EXIT_LOG_RTN_VALUE(-1, LOG_WARNING, "%s: Don't know how to send delayed %s(%d) request.\n",
+		ast_sip_session_get_name(session),
 		delayed_method2str(delay->method), delay->method);
-	return -1;
 }
 
 /*!
@@ -1383,6 +1426,7 @@
 	struct ast_sip_session_delayed_request *delay;
 	int found = 0;
 	int res = 0;
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));
 
 	AST_LIST_TRAVERSE_SAFE_BEGIN(&session->delayed_requests, delay, next) {
 		switch (delay->method) {
@@ -1390,6 +1434,8 @@
 			break;
 		case DELAYED_METHOD_UPDATE:
 			AST_LIST_REMOVE_CURRENT(next);
+			ast_trace(-1, "%s: Sending delayed %s request\n", ast_sip_session_get_name(session),
+				delayed_method2str(delay->method));
 			res = send_delayed_request(session, delay);
 			delayed_request_free(delay);
 			if (!res) {
@@ -1408,7 +1454,7 @@
 	AST_LIST_TRAVERSE_SAFE_END;
 
 	ao2_ref(session, -1);
-	return res;
+	SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));
 }
 
 /*!
@@ -1428,6 +1474,7 @@
 	int found = 0;
 	int res = 0;
 	int timer_running;
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));
 
 	/* re-INVITE collision timer running? */
 	timer_running = pj_timer_entry_running(&session->rescheduled_reinvite);
@@ -1446,6 +1493,8 @@
 		}
 		if (found) {
 			AST_LIST_REMOVE_CURRENT(next);
+			ast_trace(-1, "%s: Sending delayed %s request\n", ast_sip_session_get_name(session),
+				delayed_method2str(delay->method));
 			res = send_delayed_request(session, delay);
 			delayed_request_free(delay);
 			if (!res) {
@@ -1456,7 +1505,7 @@
 	AST_LIST_TRAVERSE_SAFE_END;
 
 	ao2_ref(session, -1);
-	return res;
+	SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));
 }
 
 /*!
@@ -1473,6 +1522,7 @@
 {
 	struct ast_sip_session *session = vsession;
 	int res;
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));
 
 	if (session->inv_session->invite_tsx) {
 		/*
@@ -1485,7 +1535,7 @@
 		res = invite_terminated(session);
 	}
 
-	return res;
+	SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));
 }
 
 /*!
@@ -1532,8 +1582,8 @@
 	int queue_head)
 {
 	struct ast_sip_session_delayed_request *delay = delayed_request_alloc(method,
-		on_request, on_sdp_creation, on_response, generate_new_sdp, pending_media_state,
-		active_media_state);
+			on_request, on_sdp_creation, on_response, generate_new_sdp, pending_media_state,
+			active_media_state);
 
 	if (!delay) {
 		ast_sip_session_media_state_free(pending_media_state);
@@ -1626,7 +1676,8 @@
 	ast_channel_lock(session->channel);
 	pjsip_from_domain = pbx_builtin_getvar_helper(session->channel, "SIPFROMDOMAIN");
 	if (!ast_strlen_zero(pjsip_from_domain)) {
-		ast_debug(3, "From header domain reset by channel variable SIPFROMDOMAIN (%s)\n", pjsip_from_domain);
+		ast_debug(3, "%s: From header domain reset by channel variable SIPFROMDOMAIN (%s)\n",
+			ast_sip_session_get_name(session), pjsip_from_domain);
 		pj_strdup2(dlg_pool, &dlg_info_uri->host, pjsip_from_domain);
 	}
 	ast_channel_unlock(session->channel);
@@ -2450,6 +2501,7 @@
 	return sip_session_refresh(session, on_request_creation, on_sdp_creation,
 		on_response, method, generate_new_sdp, media_state, NULL, 0);
 }
+
 int ast_sip_session_regenerate_answer(struct ast_sip_session *session,
 		ast_sip_session_sdp_creation_cb on_sdp_creation)
 {
@@ -2609,7 +2661,7 @@
 
 		handler_list = ao2_find(sdp_handlers, media, OBJ_KEY);
 		if (!handler_list) {
-			ast_debug(1, "No registered SDP handlers for media type '%s'\n", media);
+			ast_debug(3, "%s: No registered SDP handlers for media type '%s'\n", ast_sip_session_get_name(session), media);
 			continue;
 		}
 		AST_LIST_TRAVERSE(&handler_list->list, handler, next) {
@@ -2869,7 +2921,7 @@
 	const char *endpoint_name = session->endpoint ?
 		ast_strdupa(ast_sorcery_object_get_id(session->endpoint)) : "<none>";
 
-	ast_debug(3, "Destroying SIP session with endpoint %s\n", endpoint_name);
+	ast_debug(3, "%s: Destroying SIP session\n", ast_sip_session_get_name(session));
 
 	ast_test_suite_event_notify("SESSION_DESTROYING",
 		"Endpoint: %s\r\n"
@@ -3186,18 +3238,19 @@
 	}
 
 	inv = pjsip_dlg_get_inv_session(dlg);
+	session = inv->mod_data[session_module.id];
+
 	if (PJSIP_INV_STATE_CONFIRMED <= inv->state) {
 		/*
 		 * We cannot handle reINVITE authentication at this
 		 * time because the reINVITE transaction is still in
 		 * progress.
 		 */
-		ast_debug(1, "A reINVITE is being challenged.\n");
+		ast_debug(3, "%s: A reINVITE is being challenged\n", ast_sip_session_get_name(session));
 		return PJ_FALSE;
 	}
-	ast_debug(1, "Initial INVITE is being challenged.\n");
+	ast_debug(3, "%s: Initial INVITE is being challenged.\n", ast_sip_session_get_name(session));
 
-	session = inv->mod_data[session_module.id];
 
 	if (ast_sip_create_request_with_auth(&session->endpoint->outbound_auths, rdata,
 		tsx->last_tx, &tdata)) {
@@ -3448,8 +3501,8 @@
 		break;
 	case PJSIP_INV_STATE_CONFIRMED:
 		if (session->inv_session->invite_tsx) {
-			ast_debug(3, "Delay sending BYE to %s because of outstanding transaction...\n",
-					ast_sorcery_object_get_id(session->endpoint));
+			ast_debug(3, "%s: Delay sending BYE because of outstanding transaction...\n",
+				ast_sip_session_get_name(session));
 			/* If this is delayed the only thing that will happen is a BYE request so we don't
 			 * actually need to store the response code for when it happens.
 			 */
@@ -3571,7 +3624,7 @@
 
 	if (session->ended_while_deferred) {
 		/* Complete the session end started by the remote hangup. */
-		ast_debug(3, "Ending session (%p) after being deferred\n", session);
+		ast_debug(3, "%s: Ending session after being deferred\n", ast_sip_session_get_name(session));
 		session->ended_while_deferred = 0;
 		session_end(session);
 	}
@@ -3635,7 +3688,8 @@
 
 	pickup_cfg = ast_get_chan_features_pickup_config(session->channel);
 	if (!pickup_cfg) {
-		ast_log(LOG_ERROR, "Unable to retrieve pickup configuration options. Unable to detect call pickup extension\n");
+		ast_log(LOG_ERROR, "%s: Unable to retrieve pickup configuration options. Unable to detect call pickup extension\n",
+			ast_sip_session_get_name(session));
 		pickupexten = "";
 	} else {
 		pickupexten = ast_strdupa(pickup_cfg->pickupexten);
@@ -3787,19 +3841,22 @@
 	pjsip_rdata_sdp_info *sdp_info;
 	pjmedia_sdp_session *local = NULL;
 	char buffer[AST_SOCKADDR_BUFLEN];
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(invite->session));
+
 
 	/* From this point on, any calls to pjsip_inv_terminate have the last argument as PJ_TRUE
 	 * so that we will be notified so we can destroy the session properly
 	 */
 
 	if (invite->session->inv_session->state == PJSIP_INV_STATE_DISCONNECTED) {
-		ast_log(LOG_ERROR, "Session already DISCONNECTED [reason=%d (%s)]\n",
+		ast_trace_log(-1, LOG_ERROR, "%s: Session already DISCONNECTED [reason=%d (%s)]\n",
+			ast_sip_session_get_name(invite->session),
 			invite->session->inv_session->cause,
 			pjsip_get_status_text(invite->session->inv_session->cause)->ptr);
 #ifdef HAVE_PJSIP_INV_SESSION_REF
 		pjsip_inv_dec_ref(invite->session->inv_session);
 #endif
-		return -1;
+		SCOPE_EXIT_RTN_VALUE(-1);
 	}
 
 	switch (get_destination(invite->session, invite->rdata)) {
@@ -3807,6 +3864,11 @@
 		/* Things worked. Keep going */
 		break;
 	case SIP_GET_DEST_UNSUPPORTED_URI:
+		ast_trace(-1, "%s: Call (%s:%s) to extension '%s' - unsupported uri\n",
+			ast_sip_session_get_name(invite->session),
+			invite->rdata->tp_info.transport->type_name,
+			pj_sockaddr_print(&invite->rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),
+			invite->session->exten);
 		if (pjsip_inv_initial_answer(invite->session->inv_session, invite->rdata, 416, NULL, NULL, &tdata) == PJ_SUCCESS) {
 			ast_sip_session_send_response(invite->session, tdata);
 		} else  {
@@ -3814,8 +3876,8 @@
 		}
 		goto end;
 	case SIP_GET_DEST_EXTEN_PARTIAL:
-		ast_debug(1, "Call from '%s' (%s:%s) to extension '%s' - partial match\n",
-			ast_sorcery_object_get_id(invite->session->endpoint),
+		ast_trace(-1, "%s: Call (%s:%s) to extension '%s' - partial match\n",
+			ast_sip_session_get_name(invite->session),
 			invite->rdata->tp_info.transport->type_name,
 			pj_sockaddr_print(&invite->rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),
 			invite->session->exten);
@@ -3828,8 +3890,8 @@
 		goto end;
 	case SIP_GET_DEST_EXTEN_NOT_FOUND:
 	default:
-		ast_log(LOG_NOTICE, "Call from '%s' (%s:%s) to extension '%s' rejected because extension not found in context '%s'.\n",
-			ast_sorcery_object_get_id(invite->session->endpoint),
+		ast_trace_log(-1, LOG_NOTICE, "%s: Call (%s:%s) to extension '%s' rejected because extension not found in context '%s'.\n",
+			ast_sip_session_get_name(invite->session),
 			invite->rdata->tp_info.transport->type_name,
 			pj_sockaddr_print(&invite->rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),
 			invite->session->exten,
@@ -3862,6 +3924,11 @@
 	 * so let's go ahead and send a 100 Trying out to stop any
 	 * retransmissions.
 	 */
+	ast_trace(-1, "%s: Call (%s:%s) to extension '%s' sending 100 Trying\n",
+		ast_sip_session_get_name(invite->session),
+		invite->rdata->tp_info.transport->type_name,
+		pj_sockaddr_print(&invite->rdata->pkt_info.src_addr, buffer, sizeof(buffer), 3),
+		invite->session->exten);
 	if (pjsip_inv_initial_answer(invite->session->inv_session, invite->rdata, 100, NULL, NULL, &tdata) != PJ_SUCCESS) {
 		pjsip_inv_terminate(invite->session->inv_session, 500, PJ_TRUE);
 		goto end;
@@ -3909,7 +3976,7 @@
 #ifdef HAVE_PJSIP_INV_SESSION_REF
 	pjsip_inv_dec_ref(invite->session->inv_session);
 #endif
-	return 0;
+	SCOPE_EXIT_RTN_VALUE(0, "%s\n", ast_sip_session_get_name(invite->session));
 }
 
 static void handle_new_invite_request(pjsip_rx_data *rdata)
@@ -4045,9 +4112,8 @@
 {
 	struct ast_sip_session *session = entry->user_data;
 
-	ast_debug(3, "Endpoint '%s(%s)' re-INVITE collision timer expired.\n",
-		ast_sorcery_object_get_id(session->endpoint),
-		session->channel ? ast_channel_name(session->channel) : "");
+	ast_debug(3, "%s: re-INVITE collision timer expired.\n",
+		ast_sip_session_get_name(session));
 
 	if (AST_LIST_EMPTY(&session->delayed_requests)) {
 		/* No delayed request pending, so just return */
@@ -4091,13 +4157,12 @@
 		ast_sip_session_media_state_free(pending_media_state);
 		ast_sip_session_media_state_free(active_media_state);
 		ast_log(LOG_ERROR, "%s: Failed to add delayed request\n", session_name);
+		return;
 	}
 
 	if (pj_timer_entry_running(&session->rescheduled_reinvite)) {
 		/* Timer already running.  Something weird is going on. */
-		ast_debug(1, "Endpoint '%s(%s)' re-INVITE collision while timer running!!!\n",
-			ast_sorcery_object_get_id(session->endpoint),
-			session->channel ? ast_channel_name(session->channel) : "");
+		ast_log(LOG_ERROR, "%s: re-INVITE collision while timer running!!!\n", session_name);
 		return;
 	}
 
@@ -4113,6 +4178,7 @@
 	if (pjsip_endpt_schedule_timer(ast_sip_get_pjsip_endpoint(),
 		&session->rescheduled_reinvite, &tv) != PJ_SUCCESS) {
 		ao2_ref(session, -1);
+		ast_log(LOG_ERROR, "%s: Couldn't schedule timer\n", session_name);
 	}
 }
 
@@ -4171,8 +4237,8 @@
 {
 	struct ast_sip_session_supplement *supplement;
 	struct pjsip_request_line req = rdata->msg_info.msg->line.req;
+	SCOPE_ENTER(3, "%s: Method is %.*s\n", ast_sip_session_get_name(session), (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));
 
-	ast_debug(3, "Method is %.*s\n", (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));
 	AST_LIST_TRAVERSE(&session->supplements, supplement, next) {
 		if (supplement->incoming_request && does_method_match(&req.method.name, supplement->method)) {
 			if (supplement->incoming_request(session, rdata)) {
@@ -4180,6 +4246,8 @@
 			}
 		}
 	}
+
+	SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));
 }
 
 static void handle_session_begin(struct ast_sip_session *session)
@@ -4221,9 +4289,8 @@
 {
 	struct ast_sip_session_supplement *supplement;
 	struct pjsip_status_line status = rdata->msg_info.msg->line.status;
-
-	ast_debug(3, "Response is %d %.*s\n", status.code, (int) pj_strlen(&status.reason),
-			pj_strbuf(&status.reason));
+	SCOPE_ENTER(3, "%s: Response is %d %.*s\n", ast_sip_session_get_name(session),
+		status.code, (int) pj_strlen(&status.reason), pj_strbuf(&status.reason));
 
 	AST_LIST_TRAVERSE(&session->supplements, supplement, next) {
 		if (!(supplement->response_priority & response_priority)) {
@@ -4233,14 +4300,13 @@
 			supplement->incoming_response(session, rdata);
 		}
 	}
+
+	SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));
 }
 
 static int handle_incoming(struct ast_sip_session *session, pjsip_rx_data *rdata,
 		enum ast_sip_session_response_priority response_priority)
 {
-	ast_debug(3, "Received %s\n", rdata->msg_info.msg->type == PJSIP_REQUEST_MSG ?
-			"request" : "response");
-
 	if (rdata->msg_info.msg->type == PJSIP_REQUEST_MSG) {
 		handle_incoming_request(session, rdata);
 	} else {
@@ -4254,16 +4320,15 @@
 {
 	struct ast_sip_session_supplement *supplement;
 	struct pjsip_request_line req = tdata->msg->line.req;
-
-	ast_debug(3, "Method is %.*s\n", (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));
-
-	ast_sip_message_apply_transport(session->endpoint->transport, tdata);
+	SCOPE_ENTER(3, "%s: Method is %.*s\n", ast_sip_session_get_name(session),
+		(int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name));
 
 	AST_LIST_TRAVERSE(&session->supplements, supplement, next) {
 		if (supplement->outgoing_request && does_method_match(&req.method.name, supplement->method)) {
 			supplement->outgoing_request(session, tdata);
 		}
 	}
+	SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));
 }
 
 static void handle_outgoing_response(struct ast_sip_session *session, pjsip_tx_data *tdata)
@@ -4271,23 +4336,24 @@
 	struct ast_sip_session_supplement *supplement;
 	struct pjsip_status_line status = tdata->msg->line.status;
 	pjsip_cseq_hdr *cseq = pjsip_msg_find_hdr(tdata->msg, PJSIP_H_CSEQ, NULL);
-
-	if (!cseq) {
-		ast_log(LOG_ERROR, "Cannot send response due to missing sequence header");
-		return;
-	}
-
-	ast_debug(3, "Method is %.*s, Response is %d %.*s\n", (int) pj_strlen(&cseq->method.name),
+	SCOPE_ENTER(3, "%s: Method is %.*s, Response is %d %.*s\n", ast_sip_session_get_name(session),
+		(int) pj_strlen(&cseq->method.name),
 		pj_strbuf(&cseq->method.name), status.code, (int) pj_strlen(&status.reason),
 		pj_strbuf(&status.reason));
 
-	ast_sip_message_apply_transport(session->endpoint->transport, tdata);
+
+	if (!cseq) {
+		SCOPE_EXIT_LOG_RTN(LOG_ERROR, "%s: Cannot send response due to missing sequence header",
+			ast_sip_session_get_name(session));
+	}
 
 	AST_LIST_TRAVERSE(&session->supplements, supplement, next) {
 		if (supplement->outgoing_response && does_method_match(&cseq->method.name, supplement->method)) {
 			supplement->outgoing_response(session, tdata);
 		}
 	}
+
+	SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));
 }
 
 static int session_end(void *vsession)
@@ -4352,6 +4418,9 @@
 	struct ast_sip_session *session, pjsip_rx_data *rdata)
 {
 	pjsip_msg *msg;
+	ast_debug(3, "%s: Received %s\n", ast_sip_session_get_name(session), rdata->msg_info.msg->type == PJSIP_REQUEST_MSG ?
+			"request" : "response");
+
 
 	handle_incoming(session, rdata, AST_SIP_SESSION_BEFORE_MEDIA);
 	msg = rdata->msg_info.msg;
@@ -4367,9 +4436,8 @@
 		 * SDP answer.
 		 */
 		ast_debug(1,
-			"Endpoint '%s(%s)': Ending session due to incomplete SDP negotiation.  %s\n",
-			ast_sorcery_object_get_id(session->endpoint),
-			session->channel ? ast_channel_name(session->channel) : "",
+			"%s: Ending session due to incomplete SDP negotiation.  %s\n",
+			ast_sip_session_get_name(session),
 			pjsip_rx_data_get_info(rdata));
 		if (pjsip_inv_end_session(inv, 400, NULL, &tdata) == PJ_SUCCESS
 			&& tdata) {
@@ -4406,7 +4474,8 @@
 		handle_incoming_before_media(inv, session, e->body.rx_msg.rdata);
 		break;
 	case PJSIP_EVENT_TSX_STATE:
-		ast_debug(3, "Source of transaction state change is %s\n", pjsip_event_str(e->body.tsx_state.type));
+		ast_debug(3, "%s: Source of transaction state change is %s\n", ast_sip_session_get_name(session),
+			pjsip_event_str(e->body.tsx_state.type));
 		/* Transaction state changes are prompted by some other underlying event. */
 		switch(e->body.tsx_state.type) {
 		case PJSIP_EVENT_TX_MSG:
@@ -4442,7 +4511,7 @@
 
 	if (inv->state == PJSIP_INV_STATE_DISCONNECTED) {
 		if (session->defer_end) {
-			ast_debug(3, "Deferring session (%p) end\n", session);
+			ast_debug(3, "%s: Deferring session end\n", ast_sip_session_get_name(session));
 			session->ended_while_deferred = 1;
 			return;
 		}
@@ -4548,7 +4617,8 @@
 						return;
 					}
 					if (inv->state == PJSIP_INV_STATE_CONFIRMED) {
-						ast_debug(1, "reINVITE received final response code %d\n",
+						ast_debug(1, "%s: reINVITE received final response code %d\n",
+							ast_sip_session_get_name(session),
 							tsx->status_code);
 						if ((tsx->status_code == 401 || tsx->status_code == 407)
 							&& !ast_sip_create_request_with_auth(
@@ -4621,15 +4691,13 @@
 							pjsip_rx_data_get_info(e->body.tsx_state.src.rdata),
 							sdp_negotiation_done ? "complete" : "incomplete");
 						if (!sdp_negotiation_done) {
-							ast_debug(1, "Endpoint '%s(%s)': Incomplete SDP negotiation cancelled session.  %s\n",
-								ast_sorcery_object_get_id(session->endpoint),
-								session->channel ? ast_channel_name(session->channel) : "",
+							ast_debug(1, "%s: Incomplete SDP negotiation cancelled session.  %s\n",
+								ast_sip_session_get_name(session),
 								pjsip_rx_data_get_info(e->body.tsx_state.src.rdata));
 						} else if (pjsip_inv_end_session(inv, 500, NULL, &tdata) == PJ_SUCCESS
 							&& tdata) {
-							ast_debug(1, "Endpoint '%s(%s)': Ending session due to RFC5407 race condition.  %s\n",
-								ast_sorcery_object_get_id(session->endpoint),
-								session->channel ? ast_channel_name(session->channel) : "",
+							ast_debug(1, "%s: Ending session due to RFC5407 race condition.  %s\n",
+								ast_sip_session_get_name(session),
 								pjsip_rx_data_get_info(e->body.tsx_state.src.rdata));
 							ast_sip_session_send_request(session, tdata);
 						}
@@ -4641,7 +4709,8 @@
 			if (tsx->role == PJSIP_ROLE_UAC) {
 				if (tsx->state == PJSIP_TSX_STATE_COMPLETED) {
 					/* This means we got a final response to our outgoing method */
-					ast_debug(1, "%.*s received final response code %d\n",
+					ast_debug(1, "%s: %.*s received final response code %d\n",
+						ast_sip_session_get_name(session),
 						(int) pj_strlen(&tsx->method.name), pj_strbuf(&tsx->method.name),
 						tsx->status_code);
 					if ((tsx->status_code == 401 || tsx->status_code == 407)
@@ -4683,9 +4752,8 @@
 
 	if (tsx->method.id == PJSIP_INVITE_METHOD) {
 		if (tsx->state == PJSIP_TSX_STATE_PROCEEDING) {
-			ast_debug(3, "Endpoint '%s(%s)' INVITE delay check. tsx-state:%s\n",
-				ast_sorcery_object_get_id(session->endpoint),
-				session->channel ? ast_channel_name(session->channel) : "",
+			ast_debug(3, "%s: INVITE delay check. tsx-state:%s\n",
+				ast_sip_session_get_name(session),
 				pjsip_tsx_state_str(tsx->state));
 			check_delayed_requests(session, invite_proceeding);
 		} else if (tsx->state == PJSIP_TSX_STATE_TERMINATED) {
@@ -4694,18 +4762,16 @@
 			 * queuing delayed requests, no matter what event caused
 			 * the transaction to terminate.
 			 */
-			ast_debug(3, "Endpoint '%s(%s)' INVITE delay check. tsx-state:%s\n",
-				ast_sorcery_object_get_id(session->endpoint),
-				session->channel ? ast_channel_name(session->channel) : "",
+			ast_debug(3, "%s: INVITE delay check. tsx-state:%s\n",
+				ast_sip_session_get_name(session),
 				pjsip_tsx_state_str(tsx->state));
 			check_delayed_requests(session, invite_terminated);
 		}
 	} else if (tsx->role == PJSIP_ROLE_UAC
 		&& tsx->state == PJSIP_TSX_STATE_COMPLETED
 		&& !pj_strcmp2(&tsx->method.name, "UPDATE")) {
-		ast_debug(3, "Endpoint '%s(%s)' UPDATE delay check. tsx-state:%s\n",
-			ast_sorcery_object_get_id(session->endpoint),
-			session->channel ? ast_channel_name(session->channel) : "",
+		ast_debug(3, "%s: UPDATE delay check. tsx-state:%s\n",
+			ast_sip_session_get_name(session),
 			pjsip_tsx_state_str(tsx->state));
 		check_delayed_requests(session, update_completed);
 	}
@@ -4841,14 +4907,15 @@
 	pjmedia_sdp_session *local;
 	int i;
 	int stream;
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));
 
 	if (inv->state == PJSIP_INV_STATE_DISCONNECTED) {
-		ast_log(LOG_ERROR, "Failed to create session SDP. Session has been already disconnected\n");
-		return NULL;
+		SCOPE_EXIT_LOG_RTN_VALUE(NULL, LOG_ERROR, "%s: Failed to create session SDP. Session has been already disconnected\n",
+			ast_sip_session_get_name(session));
 	}
 
 	if (!inv->pool_prov || !(local = PJ_POOL_ZALLOC_T(inv->pool_prov, pjmedia_sdp_session))) {
-		return NULL;
+		SCOPE_EXIT_LOG_RTN_VALUE(NULL, LOG_ERROR, "%s: Pool allocation failure\n", ast_sip_session_get_name(session));
 	}
 
 	if (!offer) {
@@ -4873,28 +4940,34 @@
 			session->pending_media_state->topology = ast_stream_topology_clone(session->endpoint->media.topology);
 		}
 		if (!session->pending_media_state->topology) {
-			return NULL;
+			SCOPE_EXIT_LOG_RTN_VALUE(NULL, LOG_ERROR, "%s: No pending media state topology\n", ast_sip_session_get_name(session));
 		}
 	}
 
+	ast_trace(-1, "%s: Processing streams\n", ast_sip_session_get_name(session));
+
 	for (i = 0; i < ast_stream_topology_get_count(session->pending_media_state->topology); ++i) {
 		struct ast_sip_session_media *session_media;
-		struct ast_stream *stream;
+		struct ast_stream *stream = ast_stream_topology_get_stream(session->pending_media_state->topology, i);
 		unsigned int streams = local->media_count;
+		SCOPE_ENTER(4, "%s: Processing stream %s\n", ast_sip_session_get_name(session),
+			ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 
 		/* This code does not enforce any maximum stream count limitations as that is done on either
 		 * the handling of an incoming SDP offer or on the handling of a session refresh.
 		 */
 
-		stream = ast_stream_topology_get_stream(session->pending_media_state->topology, i);
-
 		session_media = ast_sip_session_media_state_add(session, session->pending_media_state, ast_stream_get_type(stream), i);
 		if (!session_media) {
-			return NULL;
+			local = NULL;
+			SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't alloc/add session media for stream %s\n",
+				ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 		}
 
 		if (add_sdp_streams(session_media, session, local, offer, stream)) {
-			return NULL;
+			local = NULL;
+			SCOPE_EXIT_LOG_EXPR(goto end, LOG_ERROR, "%s: Couldn't add sdp streams for stream %s\n",
+				ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
 		}
 
 		/* If a stream was actually added then add any additional details */
@@ -4908,23 +4981,38 @@
 				attr = pjmedia_sdp_attr_create(inv->pool_prov, "mid", pj_cstr(&stmp, session_media->mid));
 				pjmedia_sdp_attr_add(&media->attr_count, media->attr, attr);
 			}
+
+			ast_trace(-1, "%s: Stream %s added%s%s\n", ast_sip_session_get_name(session),
+				ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),
+				S_COR(!ast_strlen_zero(session_media->mid), " with mid ", ""), S_OR(session_media->mid, ""));
+
 		}
 
 		/* Ensure that we never exceed the maximum number of streams PJMEDIA will allow. */
 		if (local->media_count == PJMEDIA_MAX_SDP_MEDIA) {
-			break;
+			SCOPE_EXIT_EXPR(break, "%s: Stream %s exceeded max pjmedia count of %d\n",
+				ast_sip_session_get_name(session), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)),
+				PJMEDIA_MAX_SDP_MEDIA);
 		}
+
+		SCOPE_EXIT("%s: Done with %s\n", ast_sip_session_get_name(session),
+			ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
+
 	}
 
 	/* Add any bundle groups that are present on the media state */
+	ast_trace(-1, "%s: Adding bundle groups (if available)\n", ast_sip_session_get_name(session));
 	if (add_bundle_groups(session, inv->pool_prov, local)) {
-		return NULL;
+		SCOPE_EXIT_LOG_RTN_VALUE(NULL, LOG_ERROR, "%s: Couldn't add bundle groups\n", ast_sip_session_get_name(session));
 	}
 
 	/* Use the connection details of an available media if possible for SDP level */
+	ast_trace(-1, "%s: Copying connection details\n", ast_sip_session_get_name(session));
+
 	for (stream = 0; stream < local->media_count; stream++) {
+		SCOPE_ENTER(4, "%s: Processing media %d\n", ast_sip_session_get_name(session), stream);
 		if (!local->media[stream]->conn) {
-			continue;
+			SCOPE_EXIT_EXPR(continue, "%s: Media %d has no connection info\n", ast_sip_session_get_name(session), stream);
 		}
 
 		if (local->conn) {
@@ -4933,18 +5021,20 @@
 				!pj_strcmp(&local->conn->addr, &local->media[stream]->conn->addr)) {
 				local->media[stream]->conn = NULL;
 			}
-			continue;
+			SCOPE_EXIT_EXPR(continue, "%s: Media %d has good existing connection info\n", ast_sip_session_get_name(session), stream);
 		}
 
 		/* This stream's connection info will serve as the connection details for SDP level */
 		local->conn = local->media[stream]->conn;
 		local->media[stream]->conn = NULL;
 
-		continue;
+		SCOPE_EXIT_EXPR(continue, "%s: Media %d reset\n", ast_sip_session_get_name(session), stream);
 	}
 
 	/* If no SDP level connection details are present then create some */
 	if (!local->conn) {
+		ast_trace(-1, "%s: Creating connection details\n", ast_sip_session_get_name(session));
+
 		local->conn = pj_pool_zalloc(inv->pool_prov, sizeof(struct pjmedia_sdp_conn));
 		local->conn->net_type = STR_IN;
 		local->conn->addr_type = session->endpoint->media.rtp.ipv6 ? STR_IP6 : STR_IP4;
@@ -4960,27 +5050,31 @@
 	pj_strassign(&local->origin.addr_type, &local->conn->addr_type);
 	pj_strassign(&local->origin.addr, &local->conn->addr);
 
-	return local;
+end:
+	SCOPE_EXIT_RTN_VALUE(local, "%s\n", ast_sip_session_get_name(session));
 }
 
 static void session_inv_on_rx_offer(pjsip_inv_session *inv, const pjmedia_sdp_session *offer)
 {
-	struct ast_sip_session *session;
+	struct ast_sip_session *session = inv->mod_data[session_module.id];
 	pjmedia_sdp_session *answer;
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));
 
 	if (ast_shutdown_final()) {
-		return;
+		SCOPE_EXIT_RTN("%s: Shutdown in progress\n", ast_sip_session_get_name(session));
 	}
 
 	session = inv->mod_data[session_module.id];
 	if (handle_incoming_sdp(session, offer)) {
 		ast_sip_session_media_state_reset(session->pending_media_state);
-		return;
+		SCOPE_EXIT_RTN("%s: handle_incoming_sdp failed\n", ast_sip_session_get_name(session));
 	}
 
 	if ((answer = create_local_sdp(inv, session, offer))) {
 		pjsip_inv_set_sdp_answer(inv, answer);
+		SCOPE_EXIT_RTN("%s: Set SDP answer\n", ast_sip_session_get_name(session));
 	}
+	SCOPE_EXIT_RTN("%s: create_local_sdp failed\n", ast_sip_session_get_name(session));
 }
 
 #if 0
@@ -4992,11 +5086,12 @@
 
 static void session_inv_on_media_update(pjsip_inv_session *inv, pj_status_t status)
 {
-	struct ast_sip_session *session;
+	struct ast_sip_session *session = inv->mod_data[session_module.id];
 	const pjmedia_sdp_session *local, *remote;
+	SCOPE_ENTER(3, "%s\n", ast_sip_session_get_name(session));
 
 	if (ast_shutdown_final()) {
-		return;
+		SCOPE_EXIT_RTN("%s: Shutdown in progress\n", ast_sip_session_get_name(session));
 	}
 
 	session = inv->mod_data[session_module.id];
@@ -5006,7 +5101,7 @@
 		 * don't care about media updates.
 		 * Just ignore
 		 */
-		return;
+		SCOPE_EXIT_RTN("%s: No channel or session\n", ast_sip_session_get_name(session));
 	}
 
 	if (session->endpoint) {
@@ -5024,24 +5119,24 @@
 
 		if (inv->following_fork) {
 			if (session->endpoint->media.rtp.follow_early_media_fork) {
-				ast_debug(3, "Following early media fork with different To tags\n");
+				ast_trace(-1, "%s: Following early media fork with different To tags\n", ast_sip_session_get_name(session));
 			} else {
-				ast_debug(3, "Not following early media fork with different To tags\n");
+				ast_trace(-1, "%s: Not following early media fork with different To tags\n", ast_sip_session_get_name(session));
 				bail = 1;
 			}
 		}
 #ifdef HAVE_PJSIP_INV_ACCEPT_MULTIPLE_SDP_ANSWERS
 		else if (inv->updated_sdp_answer) {
 			if (session->endpoint->media.rtp.accept_multiple_sdp_answers) {
-				ast_debug(3, "Accepting updated SDP with same To tag\n");
+				ast_trace(-1, "%s: Accepting updated SDP with same To tag\n", ast_sip_session_get_name(session));
 			} else {
-				ast_debug(3, "Ignoring updated SDP answer with same To tag\n");
+				ast_trace(-1, "%s: Ignoring updated SDP answer with same To tag\n", ast_sip_session_get_name(session));
 				bail = 1;
 			}
 		}
 #endif
 		if (bail) {
-			return;
+			SCOPE_EXIT_RTN("%s: Bailing\n", ast_sip_session_get_name(session));
 		}
 	}
 
@@ -5050,12 +5145,14 @@
 		ast_channel_hangupcause_set(session->channel, AST_CAUSE_BEARERCAPABILITY_NOTAVAIL);
 		ast_set_hangupsource(session->channel, ast_channel_name(session->channel), 0);
 		ast_queue_hangup(session->channel);
-		return;
+		SCOPE_EXIT_RTN("%s: Couldn't get active or local or remote negotiator.  Hanging up\n", ast_sip_session_get_name(session));
 	}
 
 	if (handle_negotiated_sdp(session, local, remote)) {
 		ast_sip_session_media_state_reset(session->pending_media_state);
+		SCOPE_EXIT_RTN("%s: handle_negotiated_sdp failed.  Resetting pending media state\n", ast_sip_session_get_name(session));
 	}
+	SCOPE_EXIT_RTN("%s\n", ast_sip_session_get_name(session));
 }
 
 static pjsip_redirect_op session_inv_on_redirected(pjsip_inv_session *inv, const pjsip_uri *target, const pjsip_event *e)
@@ -5125,6 +5222,8 @@
 	struct ast_sip_nat_hook *hook = ast_sip_mod_data_get(
 		tdata->mod_data, session_module.id, MOD_DATA_NAT_HOOK);
 	struct pjmedia_sdp_session *sdp;
+	pjsip_dialog *dlg = pjsip_tdata_get_dlg(tdata);
+	struct ast_sip_session *session = dlg ? ast_sip_dialog_get_session(dlg) : NULL;
 	int stream;
 
 	/* SDP produced by us directly will never be multipart */
@@ -5148,8 +5247,9 @@
 		 * outgoing session IP is local. If it is, we'll do
 		 * rewriting. No localnet configured? Always rewrite. */
 		if (ast_sip_transport_is_local(transport_state, &our_sdp_addr) || !transport_state->localnet) {
-			ast_debug(5, "Setting external media address to %s\n", ast_sockaddr_stringify_addr_remote(&transport_state->external_media_address));
-			pj_strdup2(tdata->pool, &sdp->conn->addr, ast_sockaddr_stringify_addr_remote(&transport_state->external_media_address));
+			ast_debug(5, "%s: Setting external media address to %s\n", ast_sip_session_get_name(session),
+				ast_sockaddr_stringify_host(&transport_state->external_media_address));
+			pj_strdup2(tdata->pool, &sdp->conn->addr, ast_sockaddr_stringify_host(&transport_state->external_media_address));
 			pj_strassign(&sdp->origin.addr, &sdp->conn->addr);
 		}
 	}
@@ -5165,7 +5265,8 @@
 
 		handler_list = ao2_find(sdp_handlers, media, OBJ_KEY);
 		if (!handler_list) {
-			ast_debug(1, "No registered SDP handlers for media type '%s'\n", media);
+			ast_debug(4, "%s: No registered SDP handlers for media type '%s'\n",  ast_sip_session_get_name(session),
+				media);
 			continue;
 		}
 		AST_LIST_TRAVERSE(&handler_list->list, handler, next) {

-- 
To view, visit https://gerrit.asterisk.org/c/asterisk/+/14891
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings

Gerrit-Project: asterisk
Gerrit-Branch: 17
Gerrit-Change-Id: I06af034d1ff3ea1feb56596fd7bd6d7939dfdcc3
Gerrit-Change-Number: 14891
Gerrit-PatchSet: 2
Gerrit-Owner: George Joseph <gjoseph at digium.com>
Gerrit-Reviewer: Friendly Automation
Gerrit-Reviewer: George Joseph <gjoseph at digium.com>
Gerrit-Reviewer: Joshua Colp <jcolp at sangoma.com>
Gerrit-MessageType: merged
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20200914/a8126194/attachment-0001.html>


More information about the asterisk-code-review mailing list