[Asterisk-code-review] debugging: Add enough to choke a mule (asterisk[certified/16.8])
George Joseph
asteriskteam at digium.com
Mon Sep 14 09:29:24 CDT 2020
George Joseph has submitted this change. ( https://gerrit.asterisk.org/c/asterisk/+/14802 )
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(+), 206 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 994a39d..dd2be40 100644
--- a/bridges/bridge_softmix.c
+++ b/bridges/bridge_softmix.c
@@ -630,6 +630,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;
}
@@ -643,6 +644,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;
}
@@ -656,11 +658,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) {
@@ -669,9 +677,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:
@@ -2251,10 +2266,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
@@ -2263,19 +2281,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) {
@@ -2283,11 +2306,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 ||
@@ -2298,9 +2324,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
@@ -2308,18 +2339,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 */
@@ -2334,42 +2373,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();
}
/*!
@@ -2390,6 +2454,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:
@@ -2397,7 +2462,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;
}
@@ -2507,6 +2572,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 8ce5630..cb625cd 100644
--- a/channels/chan_pjsip.c
+++ b/channels/chan_pjsip.c
@@ -1542,32 +1542,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,
@@ -1599,6 +1612,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:
@@ -1703,9 +1725,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)) {
@@ -1795,6 +1817,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:
@@ -1814,18 +1838,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
@@ -1834,7 +1857,7 @@
}
}
- return res;
+ SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_channel_name(ast));
}
struct transfer_data {
@@ -3004,9 +3027,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 */
@@ -3022,17 +3046,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);
@@ -3045,12 +3069,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)
@@ -3148,9 +3172,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 */
@@ -3170,6 +3195,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) {
@@ -3178,6 +3204,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) {
@@ -3188,21 +3215,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 7988303..44b4568 100644
--- a/include/asterisk/res_pjsip_session.h
+++ b/include/asterisk/res_pjsip_session.h
@@ -115,6 +115,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 92b6b06..8fb0a8f 100644
--- a/main/channel.c
+++ b/main/channel.c
@@ -11024,8 +11024,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 5567573..09f07a1 100644
--- a/res/res_pjsip_session.c
+++ b/res/res_pjsip_session.c
@@ -481,12 +481,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.
@@ -494,7 +497,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");
}
}
@@ -504,6 +507,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
@@ -515,10 +519,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;
}
}
@@ -529,6 +535,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;
@@ -544,7 +551,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;
@@ -558,18 +565,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)
@@ -674,6 +686,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];
@@ -682,8 +696,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);
@@ -743,17 +761,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));
}
}
@@ -767,6 +787,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));
@@ -775,6 +796,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;
@@ -784,6 +807,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);
@@ -793,22 +818,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 */
@@ -829,19 +866,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);
@@ -849,66 +888,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,
@@ -951,13 +994,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;
}
@@ -966,15 +1009,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) {
@@ -982,8 +1025,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);
@@ -992,8 +1035,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);
}
@@ -1018,16 +1061,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;
}
}
@@ -1039,8 +1082,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;
}
@@ -1287,6 +1330,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;
};
@@ -1332,10 +1376,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) {
@@ -1347,7 +1389,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,
@@ -1356,14 +1398,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;
}
/*!
@@ -1382,6 +1425,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) {
@@ -1389,6 +1433,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) {
@@ -1407,7 +1453,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));
}
/*!
@@ -1427,6 +1473,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);
@@ -1445,6 +1492,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) {
@@ -1455,7 +1504,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));
}
/*!
@@ -1472,6 +1521,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) {
/*
@@ -1484,7 +1534,7 @@
res = invite_terminated(session);
}
- return res;
+ SCOPE_EXIT_RTN_VALUE(res, "%s\n", ast_sip_session_get_name(session));
}
/*!
@@ -1531,8 +1581,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);
@@ -1625,7 +1675,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);
@@ -2446,6 +2497,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)
{
@@ -2605,7 +2657,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) {
@@ -2863,7 +2915,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"
@@ -3180,18 +3232,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)) {
@@ -3442,8 +3495,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.
*/
@@ -3565,7 +3618,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);
}
@@ -3629,7 +3682,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);
@@ -3725,19 +3779,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)) {
@@ -3745,6 +3802,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 {
@@ -3752,8 +3814,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);
@@ -3766,8 +3828,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,
@@ -3791,6 +3853,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;
@@ -3838,7 +3905,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)
@@ -3974,9 +4041,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 */
@@ -4020,13 +4086,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;
}
@@ -4042,6 +4107,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);
}
}
@@ -4100,8 +4166,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)) {
@@ -4109,6 +4175,8 @@
}
}
}
+
+ SCOPE_EXIT("%s\n", ast_sip_session_get_name(session));
}
static void handle_session_begin(struct ast_sip_session *session)
@@ -4150,9 +4218,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)) {
@@ -4162,14 +4229,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 {
@@ -4183,13 +4249,15 @@
{
struct ast_sip_session_supplement *supplement;
struct pjsip_request_line req = tdata->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->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)
@@ -4197,21 +4265,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));
+
+ 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)
@@ -4276,6 +4347,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;
@@ -4291,9 +4365,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) {
@@ -4330,7 +4403,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:
@@ -4366,7 +4440,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;
}
@@ -4472,7 +4546,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(
@@ -4528,15 +4603,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);
}
@@ -4548,7 +4621,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)
@@ -4590,9 +4664,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) {
@@ -4601,18 +4674,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);
}
@@ -4748,14 +4819,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) {
@@ -4780,28 +4852,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 */
@@ -4815,23 +4893,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) {
@@ -4840,18 +4933,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;
@@ -4867,27 +4962,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
@@ -4899,11 +4998,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];
@@ -4913,7 +5013,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) {
@@ -4931,24 +5031,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));
}
}
@@ -4957,12 +5057,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)
@@ -5032,6 +5134,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 */
@@ -5055,7 +5159,8 @@
* 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_host(&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);
}
@@ -5072,7 +5177,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/+/14802
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings
Gerrit-Project: asterisk
Gerrit-Branch: certified/16.8
Gerrit-Change-Id: I06af034d1ff3ea1feb56596fd7bd6d7939dfdcc3
Gerrit-Change-Number: 14802
Gerrit-PatchSet: 5
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-Reviewer: Kevin Harwell <kharwell at digium.com>
Gerrit-MessageType: merged
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20200914/1c68a216/attachment-0001.html>
More information about the asterisk-code-review
mailing list