[Asterisk-code-review] ACN: Add tracing to existing code (asterisk[master])
George Joseph
asteriskteam at digium.com
Wed Jul 8 15:32:01 CDT 2020
George Joseph has submitted this change. ( https://gerrit.asterisk.org/c/asterisk/+/14631 )
Change subject: ACN: Add tracing to existing code
......................................................................
ACN: Add tracing to existing code
Prior to making any modifications to the pjsip infrastructure
for ACN, I've added the tracing functions to the existing code.
This should make the final commit easier to review, but we can also
now run a "before and after" trace.
No functional changes were made with this commit.
Change-Id: Ia83a1a2687ccb96f2bc8a2a3928a5214c4be775c
---
M apps/app_dial.c
M channels/chan_pjsip.c
M include/asterisk/res_pjsip_session.h
M main/bridge.c
M main/channel.c
M main/channel_internal_api.c
M main/features.c
M res/res_pjsip_sdp_rtp.c
M res/res_pjsip_session.c
9 files changed, 438 insertions(+), 179 deletions(-)
Approvals:
Kevin Harwell: Looks good to me, but someone else must approve
George Joseph: Looks good to me, approved; Approved for Submit
diff --git a/apps/app_dial.c b/apps/app_dial.c
index 2744868..95f36d7 100644
--- a/apps/app_dial.c
+++ b/apps/app_dial.c
@@ -1223,6 +1223,7 @@
int sent_ring = 0;
int sent_progress = 0;
struct timeval start = ast_tvnow();
+ SCOPE_TRACE(1, "%s\n", ast_channel_name(in));
if (single) {
/* Turn off hold music, etc */
@@ -1389,6 +1390,7 @@
case AST_CONTROL_ANSWER:
/* This is our guy if someone answered. */
if (!peer) {
+ ast_trace(1, "%s answered %s\n", ast_channel_name(c), ast_channel_name(in));
ast_verb(3, "%s answered %s\n", ast_channel_name(c), ast_channel_name(in));
if (o->orig_chan_name
&& strcmp(o->orig_chan_name, ast_channel_name(c))) {
@@ -2269,6 +2271,7 @@
*/
struct ast_party_caller caller;
int max_forwards;
+ SCOPE_TRACE(1, "%s Data: %s\n", ast_channel_name(chan), data);
/* Reset all DIAL variables back to blank, to prevent confusion (in case we don't reset all of them). */
ast_channel_lock(chan);
diff --git a/channels/chan_pjsip.c b/channels/chan_pjsip.c
index 2fc98b4..e99ec31 100644
--- a/channels/chan_pjsip.c
+++ b/channels/chan_pjsip.c
@@ -241,7 +241,10 @@
/*! \brief Function called by RTP engine to get peer capabilities */
static void chan_pjsip_get_codec(struct ast_channel *chan, struct ast_format_cap *result)
{
+ SCOPE_ENTER(1, "%s Native formats %s\n", ast_channel_name(chan),
+ ast_str_tmp(AST_FORMAT_CAP_NAMES_LEN, ast_format_cap_get_names(ast_channel_nativeformats(chan), &STR_TMP)));
ast_format_cap_append_from_cap(result, ast_channel_nativeformats(chan), AST_MEDIA_TYPE_UNKNOWN);
+ SCOPE_EXIT_RTN();
}
/*! \brief Destructor function for \ref transport_info_data */
@@ -450,21 +453,23 @@
struct ast_sip_channel_pvt *channel = ast_channel_tech_pvt(chan);
struct ast_sip_session *session = channel->session;
struct rtp_direct_media_data *cdata;
+ SCOPE_ENTER(1, "%s %s\n", ast_channel_name(chan),
+ ast_str_tmp(AST_FORMAT_CAP_NAMES_LEN, ast_format_cap_get_names(cap, &STR_TMP)));
/* Don't try to do any direct media shenanigans on early bridges */
if ((rtp || vrtp || tpeer) && !ast_channel_is_bridged(chan)) {
ast_debug(4, "Disregarding setting RTP on %s: channel is not bridged\n", ast_channel_name(chan));
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Channel not bridged\n");
}
if (nat_active && session->endpoint->media.direct_media.disable_on_nat) {
ast_debug(4, "Disregarding setting RTP on %s: NAT is active\n", ast_channel_name(chan));
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "NAT is active\n");
}
cdata = rtp_direct_media_data_create(chan, rtp, vrtp, cap, session);
if (!cdata) {
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
if (ast_sip_push_task(session->serializer, send_direct_media_request, cdata)) {
@@ -472,7 +477,7 @@
ao2_ref(cdata, -1);
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
/*! \brief Local glue for interacting with the RTP engine core */
@@ -520,17 +525,20 @@
{
struct ast_format_cap *cap_from_top;
int res;
+ SCOPE_ENTER(1, "Topology: %s Formats: %s\n",
+ ast_str_tmp(AST_FORMAT_CAP_NAMES_LEN, ast_stream_topology_to_str(top, &STR_TMP)),
+ ast_str_tmp(AST_FORMAT_CAP_NAMES_LEN, ast_format_cap_get_names(cap, &STR_TMP)));
cap_from_top = ast_stream_topology_get_formats(top);
if (!cap_from_top) {
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Topology had no formats\n");
}
res = ast_format_cap_iscompatible(cap_from_top, cap);
ao2_ref(cap_from_top, -1);
- return res;
+ SCOPE_EXIT_RTN_VALUE(res, "Compatible? %s\n", res ? "yes" : "no");
}
/*! \brief Function called to create a new PJSIP Asterisk channel */
@@ -542,9 +550,10 @@
struct ast_sip_channel_pvt *channel;
struct ast_variable *var;
struct ast_stream_topology *topology;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
if (!(pvt = ao2_alloc_options(sizeof(*pvt), chan_pjsip_pvt_dtor, AO2_ALLOC_OPT_LOCK_NOLOCK))) {
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't create pvt\n");
}
chan = ast_channel_alloc_with_endpoint(1, state,
@@ -557,7 +566,7 @@
ast_sorcery_object_get_id(session->endpoint),
(unsigned) ast_atomic_fetchadd_int((int *) &chan_idx, +1));
if (!chan) {
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't create channel\n");
}
ast_channel_tech_set(chan, &chan_pjsip_tech);
@@ -565,7 +574,7 @@
if (!(channel = ast_sip_channel_pvt_alloc(pvt, session))) {
ast_channel_unlock(chan);
ast_hangup(chan);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't create pvt channel\n");
}
ast_channel_tech_pvt_set(chan, channel);
@@ -576,7 +585,7 @@
if (!caps) {
ast_channel_unlock(chan);
ast_hangup(chan);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't create caps\n");
}
ast_format_cap_append_from_cap(caps, session->endpoint->media.codecs, AST_MEDIA_TYPE_UNKNOWN);
topology = ast_stream_topology_clone(session->endpoint->media.topology);
@@ -590,7 +599,7 @@
ast_stream_topology_free(topology);
ast_channel_unlock(chan);
ast_hangup(chan);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't get caps or clone topology\n");
}
ast_channel_stage_snapshot(chan);
@@ -660,14 +669,21 @@
set_channel_on_rtp_instance(session, ast_channel_uniqueid(chan));
- return chan;
+ SCOPE_EXIT_RTN_VALUE(chan);
}
+struct answer_data {
+ struct ast_sip_session *session;
+ unsigned long indent;
+};
+
static int answer(void *data)
{
+ struct answer_data *ans_data = data;
pj_status_t status = PJ_SUCCESS;
pjsip_tx_data *packet = NULL;
- struct ast_sip_session *session = data;
+ struct ast_sip_session *session = ans_data->session;
+ SCOPE_ENTER_TASK(1, ans_data->indent, "%s\n", ast_sip_session_get_name(session));
if (session->inv_session->state == PJSIP_INV_STATE_DISCONNECTED) {
ast_log(LOG_ERROR, "Session already DISCONNECTED [reason=%d (%s)]\n",
@@ -676,7 +692,7 @@
#ifdef HAVE_PJSIP_INV_SESSION_REF
pjsip_inv_dec_ref(session->inv_session);
#endif
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Disconnected\n");
}
pjsip_dlg_inc_lock(session->inv_session->dlg);
@@ -706,9 +722,9 @@
* Return this value so we can distinguish between this
* failure and the threadpool synchronous push failing.
*/
- return -2;
+ SCOPE_EXIT_RTN_VALUE(-2, "pjproject failure\n");
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
/*! \brief Function called by core when we should answer a PJSIP session */
@@ -716,9 +732,12 @@
{
struct ast_sip_channel_pvt *channel = ast_channel_tech_pvt(ast);
struct ast_sip_session *session;
+ struct answer_data ans_data = { 0, };
int res;
+ SCOPE_ENTER(1, "%s\n", ast_channel_name(ast));
if (ast_channel_state(ast) == AST_STATE_UP) {
+ SCOPE_EXIT_RTN_VALUE(0, "Already up\n");
return 0;
}
@@ -727,9 +746,9 @@
#ifdef HAVE_PJSIP_INV_SESSION_REF
if (pjsip_inv_add_ref(session->inv_session) != PJ_SUCCESS) {
- ast_log(LOG_ERROR, "Can't increase the session reference counter\n");
+ ast_log(LOG_ERROR, "Couldn't increase the session reference counter\n");
ao2_ref(session, -1);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't increase the session reference counter\n");
}
#endif
@@ -737,7 +756,9 @@
can occur between this thread and bridging (specifically when native bridging
attempts to do direct media) */
ast_channel_unlock(ast);
- res = ast_sip_push_task_wait_serializer(session->serializer, answer, session);
+ ans_data.session = session;
+ ans_data.indent = ast_trace_get_indent();
+ res = ast_sip_push_task_wait_serializer(session->serializer, answer, &ans_data);
if (res) {
if (res == -1) {
ast_log(LOG_ERROR,"Cannot answer '%s': Unable to push answer task to the threadpool.\n",
@@ -748,12 +769,12 @@
}
ao2_ref(session, -1);
ast_channel_lock(ast);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't push task\n");
}
ao2_ref(session, -1);
ast_channel_lock(ast);
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
/*! \brief Internal helper function called when CNG tone is detected */
@@ -1564,6 +1585,9 @@
static int on_topology_change_response(struct ast_sip_session *session, pjsip_rx_data *rdata)
{
+ SCOPE_ENTER(1, "%s Status code: %d\n", ast_sip_session_get_name(session),
+ rdata->msg_info.msg->line.status.code);
+
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.
@@ -1576,20 +1600,21 @@
ast_sip_session_media_state_reset(session->pending_media_state);
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
static int send_topology_change_refresh(void *data)
{
struct topology_change_refresh_data *refresh_data = data;
int ret;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(refresh_data->session));
ret = ast_sip_session_refresh(refresh_data->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, "RC: %d\n", ret);
}
static int handle_topology_request_change(struct ast_sip_session *session,
@@ -1597,17 +1622,18 @@
{
struct topology_change_refresh_data *refresh_data;
int res;
+ SCOPE_ENTER(1);
refresh_data = topology_change_refresh_data_alloc(session, proposed);
if (!refresh_data) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create refresh_data\n");
}
res = ast_sip_push_task(session->serializer, send_topology_change_refresh, refresh_data);
if (res) {
topology_change_refresh_data_free(refresh_data);
}
- return res;
+ SCOPE_EXIT_RTN_VALUE(res, "RC: %d\n", res);
}
/*! \brief Function called by core to ask the channel to indicate some sort of condition */
@@ -1621,6 +1647,10 @@
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 subclass[40] = "";
+ SCOPE_ENTER(1, "%s Handling %s\n", ast_channel_name(ast),
+ ast_frame_subclass2str(&f, subclass, sizeof(subclass), NULL, 0));
switch (condition) {
case AST_CONTROL_RINGING:
@@ -1727,7 +1757,7 @@
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_RTN_VALUE(-1, "Couldn't increase the session reference counter\n");
}
#endif
if (ast_sip_push_task(channel->session->serializer, update_connected_line_information, channel->session)) {
@@ -1836,13 +1866,13 @@
struct indicate_data *ind_data = indicate_data_alloc(channel->session, condition, response_code, data, datalen);
if (!ind_data) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create indicate data\n");
}
#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_RTN_VALUE(-1, "Couldn't increase the session reference counter\n");
}
#endif
if (ast_sip_push_task(channel->session->serializer, indicate, ind_data)) {
@@ -1856,7 +1886,7 @@
}
}
- return res;
+ SCOPE_EXIT_RTN_VALUE(res, "RC: %d\n", res);
}
struct transfer_data {
@@ -2397,8 +2427,14 @@
struct ast_sip_channel_pvt *channel = data;
struct ast_sip_session *session = channel->session;
pjsip_tx_data *tdata;
+ int res = 0;
+ SCOPE_ENTER(1, "%s Topology: %s\n",
+ ast_sip_session_get_name(session),
+ ast_str_tmp(256, ast_stream_topology_to_str(channel->session->pending_media_state->topology, &STR_TMP))
+ );
- int res = ast_sip_session_create_invite(session, &tdata);
+
+ res = ast_sip_session_create_invite(session, &tdata);
if (res) {
ast_set_hangupsource(session->channel, ast_channel_name(session->channel), 0);
@@ -2409,22 +2445,24 @@
ast_sip_session_send_request(session, tdata);
}
ao2_ref(channel, -1);
- return res;
+ SCOPE_EXIT_RTN_VALUE(res, "RC: %d\n", res);
}
/*! \brief Function called by core to actually start calling a remote party */
static int chan_pjsip_call(struct ast_channel *ast, const char *dest, int timeout)
{
struct ast_sip_channel_pvt *channel = ast_channel_tech_pvt(ast);
+ SCOPE_ENTER(1, "%s Topology: %s\n", ast_sip_session_get_name(channel->session),
+ ast_str_tmp(256, ast_stream_topology_to_str(channel->session->pending_media_state->topology, &STR_TMP)));
ao2_ref(channel, +1);
if (ast_sip_push_task(channel->session->serializer, call, channel)) {
ast_log(LOG_WARNING, "Error attempting to place outbound call to '%s'\n", dest);
ao2_cleanup(channel);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't push task\n");
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "'call' task pushed\n");
}
/*! \brief Internal function which translates from Asterisk cause codes to SIP response codes */
@@ -2514,6 +2552,8 @@
struct hangup_data *h_data = data;
struct ast_channel *ast = h_data->chan;
struct ast_sip_channel_pvt *channel = ast_channel_tech_pvt(ast);
+ SCOPE_ENTER(1, "%s\n", ast_channel_name(ast));
+
/*
* Before cleaning we have to ensure that channel or its session is not NULL
* we have seen rare case when taskprocessor calls hangup but channel is NULL
@@ -2536,7 +2576,7 @@
ao2_cleanup(channel);
}
ao2_cleanup(h_data);
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
/*! \brief Function called by core to hang up a PJSIP session */
@@ -2545,9 +2585,10 @@
struct ast_sip_channel_pvt *channel = ast_channel_tech_pvt(ast);
int cause;
struct hangup_data *h_data;
+ SCOPE_ENTER(1, "%s\n", ast_channel_name(ast));
if (!channel || !channel->session) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "No channel or session\n");
}
cause = hangup_cause2sip(ast_channel_hangupcause(channel->session->channel));
@@ -2562,7 +2603,7 @@
goto failure;
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Cause: %d\n", cause);
failure:
/* Go ahead and do our cleanup of the session and channel even if we're not going
@@ -2572,7 +2613,7 @@
ao2_cleanup(channel);
ao2_cleanup(h_data);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Cause: %d\n", cause);
}
struct request_data {
@@ -2593,11 +2634,12 @@
AST_APP_ARG(endpoint);
AST_APP_ARG(aor);
);
+ SCOPE_ENTER(1, "%s\n",tmp);
if (ast_strlen_zero(tmp)) {
ast_log(LOG_ERROR, "Unable to create PJSIP channel with empty destination\n");
req_data->cause = AST_CAUSE_CHANNEL_UNACCEPTABLE;
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Empty destination\n");
}
AST_NONSTANDARD_APP_ARGS(args, tmp, '/');
@@ -2619,14 +2661,14 @@
ast_log(LOG_ERROR, "Unable to create PJSIP channel with empty endpoint name\n");
}
req_data->cause = AST_CAUSE_CHANNEL_UNACCEPTABLE;
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Empty endpoint name\n");
}
endpoint = ast_sorcery_retrieve_by_id(ast_sip_get_sorcery(), "endpoint",
endpoint_name);
if (!endpoint) {
ast_log(LOG_ERROR, "Unable to create PJSIP channel - endpoint '%s' was not found\n", endpoint_name);
req_data->cause = AST_CAUSE_NO_ROUTE_DESTINATION;
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Endpoint not found\n");
}
} else {
/* First try to find an exact endpoint match, for single (user) or multi-domain (user at domain) */
@@ -2634,7 +2676,7 @@
if (ast_strlen_zero(endpoint_name)) {
ast_log(LOG_ERROR, "Unable to create PJSIP channel with empty endpoint name\n");
req_data->cause = AST_CAUSE_CHANNEL_UNACCEPTABLE;
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Empty endpoint name\n");
}
endpoint = ast_sorcery_retrieve_by_id(ast_sip_get_sorcery(), "endpoint",
endpoint_name);
@@ -2652,7 +2694,7 @@
ast_log(LOG_ERROR, "Unable to create PJSIP channel - endpoint '%s' was not found\n",
args.endpoint);
req_data->cause = AST_CAUSE_NO_ROUTE_DESTINATION;
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Endpoint not found\n");
}
request_user = args.endpoint;
*endpoint_name++ = '\0';
@@ -2661,7 +2703,7 @@
ast_log(LOG_ERROR, "Unable to create PJSIP channel with empty endpoint name: %s@<endpoint-name>\n",
request_user);
req_data->cause = AST_CAUSE_CHANNEL_UNACCEPTABLE;
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Empty endpoint name\n");
}
endpoint = ast_sorcery_retrieve_by_id(ast_sip_get_sorcery(), "endpoint",
@@ -2669,7 +2711,7 @@
if (!endpoint) {
ast_log(LOG_ERROR, "Unable to create PJSIP channel - endpoint '%s' was not found\n", endpoint_name);
req_data->cause = AST_CAUSE_NO_ROUTE_DESTINATION;
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Endpoint not found\n");
}
}
}
@@ -2680,12 +2722,12 @@
if (!session) {
ast_log(LOG_ERROR, "Failed to create outgoing session to endpoint '%s'\n", endpoint_name);
req_data->cause = AST_CAUSE_NO_ROUTE_DESTINATION;
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create session\n");
}
req_data->session = session;
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
/*! \brief Function called by core to create a new outgoing PJSIP session */
@@ -2693,6 +2735,8 @@
{
struct request_data req_data;
RAII_VAR(struct ast_sip_session *, session, NULL, ao2_cleanup);
+ SCOPE_ENTER(1, "%s Topology: %s\n", data,
+ ast_str_tmp(256, ast_stream_topology_to_str(topology, &STR_TMP)));
req_data.topology = topology;
req_data.dest = data;
@@ -2701,17 +2745,17 @@
if (ast_sip_push_task_wait_servant(NULL, request, &req_data)) {
*cause = req_data.cause;
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't push task\n");
}
session = req_data.session;
if (!(session->channel = chan_pjsip_new(session, AST_STATE_DOWN, NULL, NULL, assignedids, requestor, NULL))) {
/* Session needs to be terminated prematurely */
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't create channel\n");
}
- return session->channel;
+ SCOPE_EXIT_RTN_VALUE(session->channel, "Channel: %s\n", ast_channel_name(session->channel));
}
static struct ast_channel *chan_pjsip_request(const char *type, struct ast_format_cap *cap, const struct ast_assigned_ids *assignedids, const struct ast_channel *requestor, const char *data, int *cause)
@@ -2988,27 +3032,31 @@
static void chan_pjsip_session_begin(struct ast_sip_session *session)
{
RAII_VAR(struct ast_datastore *, datastore, NULL, ao2_cleanup);
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
if (session->endpoint->media.direct_media.glare_mitigation ==
AST_SIP_DIRECT_MEDIA_GLARE_MITIGATION_NONE) {
- return;
+ SCOPE_EXIT_RTN("Direct media no glare mitigation\n");
}
datastore = ast_sip_session_alloc_datastore(&direct_media_mitigation_info,
"direct_media_glare_mitigation");
if (!datastore) {
- return;
+ SCOPE_EXIT_RTN("Couldn't create datastore\n");
}
ast_sip_session_add_datastore(session, datastore);
+ SCOPE_EXIT_RTN();
}
/*! \brief Function called when the session ends */
static void chan_pjsip_session_end(struct ast_sip_session *session)
{
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
+
if (!session->channel) {
- return;
+ SCOPE_EXIT_RTN("No channel\n");
}
chan_pjsip_remove_hold(ast_channel_uniqueid(session->channel));
@@ -3021,6 +3069,8 @@
} else {
ast_queue_hangup(session->channel);
}
+
+ SCOPE_EXIT_RTN();
}
/*! \brief Function called when a request is received on the session */
@@ -3029,9 +3079,10 @@
RAII_VAR(struct ast_datastore *, datastore, NULL, ao2_cleanup);
struct transport_info_data *transport_data;
pjsip_tx_data *packet = NULL;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
if (session->channel) {
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Already have channel\n");
}
/* Check for a to-tag to determine if this is a reinvite */
@@ -3047,17 +3098,17 @@
*/
session->defer_terminate = 0;
ast_sip_session_terminate(session, 400);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Reinvite without channel\n");
}
datastore = ast_sip_session_alloc_datastore(&transport_info, "transport_info");
if (!datastore) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create datastore\n");
}
transport_data = ast_calloc(1, sizeof(*transport_data));
if (!transport_data) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create transport_data\n");
}
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);
@@ -3071,11 +3122,11 @@
}
ast_log(LOG_ERROR, "Failed to allocate new PJSIP channel on incoming SIP INVITE\n");
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create channel\n");
}
/* 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);
}
static int call_pickup_incoming_request(struct ast_sip_session *session, pjsip_rx_data *rdata)
@@ -3131,11 +3182,12 @@
static int pbx_start_incoming_request(struct ast_sip_session *session, pjsip_rx_data *rdata)
{
int res;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
/* Check for a to-tag to determine if this is a reinvite */
if (rdata->msg_info.to->tag.slen) {
/* We don't care about reinvites */
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Reinvite\n");
}
res = ast_pbx_start(session->channel);
@@ -3158,7 +3210,7 @@
ast_debug(3, "Started PBX on new PJSIP channel %s\n", ast_channel_name(session->channel));
- return (res == AST_PBX_SUCCESS) ? 0 : -1;
+ SCOPE_EXIT_RTN_VALUE((res == AST_PBX_SUCCESS) ? 0 : -1, "RC: %d\n", res);
}
static struct ast_sip_session_supplement pbx_start_supplement = {
@@ -3173,9 +3225,11 @@
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(1, "%s Method: %.*s Status: %d\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);
if (!session->channel) {
- return;
+ SCOPE_EXIT_RTN("No channel\n");
}
/* Build and send the tech-specific cause information */
@@ -3195,6 +3249,8 @@
switch (status.code) {
case 180:
+ ast_trace(1, "%s Method: %.*s Status: %d Queueing RINGING\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);
ast_queue_control(session->channel, AST_CONTROL_RINGING);
ast_channel_lock(session->channel);
if (ast_channel_state(session->channel) != AST_STATE_UP) {
@@ -3206,28 +3262,45 @@
if (session->endpoint->ignore_183_without_sdp) {
pjsip_rdata_sdp_info *sdp = pjsip_rdata_get_sdp_info(rdata);
if (sdp && sdp->body.ptr) {
+ ast_trace(1, "%s Method: %.*s Status: %d Queueing PROGRESS with SDP\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);
ast_queue_control(session->channel, AST_CONTROL_PROGRESS);
}
} else {
+ ast_trace(1, "%s Method: %.*s Status: %d Queueing PROGRESS without SDP\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);
ast_queue_control(session->channel, AST_CONTROL_PROGRESS);
}
break;
case 200:
+ ast_trace(1, "%s Method: %.*s Status: %d Queueing ANSWER\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);
+
ast_queue_control(session->channel, AST_CONTROL_ANSWER);
break;
default:
+ ast_trace(1, "%s Method: %.*s Status: %d Ignored\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);
break;
}
+
+ SCOPE_EXIT_RTN();
}
static int chan_pjsip_incoming_ack(struct ast_sip_session *session, struct pjsip_rx_data *rdata)
{
+ SCOPE_ENTER(1, "%s Method: %.*s Status: %d After Media\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr,
+ rdata->msg_info.msg->line.status.code);
+
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 Method: %.*s Queueing SRCCHANGE\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr);
ast_queue_control(session->channel, AST_CONTROL_SRCCHANGE);
}
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
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 fd49a7b..9db68a8 100644
--- a/include/asterisk/res_pjsip_session.h
+++ b/include/asterisk/res_pjsip_session.h
@@ -926,4 +926,13 @@
*/
struct ast_sip_session_media *ast_sip_session_media_get_transport(struct ast_sip_session *session, struct ast_sip_session_media *session_media);
+/*!
+ * \brief Get the channel or endpoint name associated with the session
+ * \since 18.0.0
+ *
+ * \param session
+ * \retval Channel name or endpoint name or "unknown"
+ */
+const char *ast_sip_session_get_name(const struct ast_sip_session *session);
+
#endif /* _RES_PJSIP_SESSION_H */
diff --git a/main/bridge.c b/main/bridge.c
index fb7012d..7a7b6f6 100644
--- a/main/bridge.c
+++ b/main/bridge.c
@@ -1673,6 +1673,7 @@
{
struct ast_bridge_channel *bridge_channel;
int res = 0;
+ SCOPE_TRACE(1, "%s Bridge: %s\n", ast_channel_name(chan), bridge->uniqueid);
bridge_channel = bridge_channel_internal_alloc(bridge);
if (flags & AST_BRIDGE_JOIN_PASS_REFERENCE) {
@@ -1921,6 +1922,7 @@
.done = 0,
};
int res;
+ SCOPE_TRACE(1, "%s Bridge: %s\n", ast_channel_name(chan), bridge->uniqueid);
ast_mutex_init(&cond.lock);
ast_cond_init(&cond.cond, NULL);
@@ -1942,6 +1944,7 @@
{
struct ast_bridge_channel *bridge_channel;
int departable;
+ SCOPE_TRACE(1, "%s\n", ast_channel_name(chan));
ast_channel_lock(chan);
bridge_channel = ast_channel_internal_bridge_channel(chan);
diff --git a/main/channel.c b/main/channel.c
index 2f3aad1..8dd008d 100644
--- a/main/channel.c
+++ b/main/channel.c
@@ -2622,6 +2622,7 @@
int ast_raw_answer(struct ast_channel *chan)
{
int res = 0;
+ SCOPE_TRACE(1, "%s\n", ast_channel_name(chan));
ast_channel_lock(chan);
@@ -2670,6 +2671,7 @@
{
int res = 0;
enum ast_channel_state old_state;
+ SCOPE_TRACE(1, "%s\n", ast_channel_name(chan));
old_state = ast_channel_state(chan);
if ((res = ast_raw_answer(chan))) {
@@ -2777,6 +2779,7 @@
int ast_answer(struct ast_channel *chan)
{
+ SCOPE_TRACE(1, "%s\n", ast_channel_name(chan));
return __ast_answer(chan, 0);
}
diff --git a/main/channel_internal_api.c b/main/channel_internal_api.c
index be8fd7c..fb62da5 100644
--- a/main/channel_internal_api.c
+++ b/main/channel_internal_api.c
@@ -677,6 +677,10 @@
void ast_channel_nativeformats_set(struct ast_channel *chan,
struct ast_format_cap *value)
{
+ SCOPE_ENTER(2, "%s: %sFormats: %s\n", S_OR(ast_channel_name(chan), "<initializing>"),
+ S_COR(ast_channel_is_multistream(chan), "Multistream", ""),
+ ast_str_tmp(128, ast_format_cap_get_names(value, &STR_TMP)));
+
ast_assert(chan != NULL);
ao2_replace(chan->nativeformats, value);
@@ -685,7 +689,7 @@
* and topology is destroyed.
*/
if (!chan->stream_topology) {
- return;
+ SCOPE_EXIT_RTN("Channel is being initialized or destroyed\n");
}
if (!ast_channel_is_multistream(chan) || !value) {
@@ -693,7 +697,9 @@
new_topology = ast_stream_topology_create_from_format_cap(value);
ast_channel_internal_set_stream_topology(chan, new_topology);
+ SCOPE_EXIT_RTN("New %stopology set\n", value ? "" : "empty ");
}
+ SCOPE_EXIT_RTN("Set native formats but not topology\n");
}
struct ast_framehook_list *ast_channel_framehooks(const struct ast_channel *chan)
@@ -1586,6 +1592,8 @@
struct ast_stream_topology *topology)
{
struct ast_stream_topology *new_topology;
+ SCOPE_ENTER(1, "%s: %s\n", ast_channel_name(chan),
+ ast_str_tmp(256, ast_stream_topology_to_str(topology, &STR_TMP)));
ast_assert(chan != NULL);
@@ -1605,7 +1613,7 @@
ast_channel_internal_set_stream_topology(chan, new_topology);
}
- return new_topology;
+ SCOPE_EXIT_RTN_VALUE(new_topology, "Used %s topology\n", topology ? "provided" : "empty");
}
struct ast_stream *ast_channel_get_default_stream(struct ast_channel *chan,
diff --git a/main/features.c b/main/features.c
index ab03bef..51cc3ed 100644
--- a/main/features.c
+++ b/main/features.c
@@ -536,6 +536,7 @@
struct ast_bridge_features *chan_features, struct ast_bridge_features *peer_features)
{
int res;
+ SCOPE_TRACE(1, "%s Peer: %s\n", ast_channel_name(chan), ast_channel_name(peer));
set_bridge_features_on_config(config, pbx_builtin_getvar_helper(chan, "BRIDGE_FEATURES"));
add_features_datastores(chan, peer, config);
@@ -629,6 +630,7 @@
struct ast_bridge *bridge;
struct ast_bridge_features chan_features;
struct ast_bridge_features *peer_features;
+ SCOPE_TRACE(1, "%s Peer: %s\n", ast_channel_name(chan), ast_channel_name(peer));
/* Setup features. */
res = ast_bridge_features_init(&chan_features);
diff --git a/res/res_pjsip_sdp_rtp.c b/res/res_pjsip_sdp_rtp.c
index 1bcb661..eacae22 100644
--- a/res/res_pjsip_sdp_rtp.c
+++ b/res/res_pjsip_sdp_rtp.c
@@ -324,6 +324,7 @@
char fmt_param[256];
enum ast_rtp_options options = session->endpoint->media.g726_non_standard ?
AST_RTP_OPT_G726_NONSTANDARD : 0;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
ast_rtp_codecs_payloads_initialize(codecs);
@@ -395,6 +396,8 @@
ast_rtp_codecs_set_framing(codecs, framing);
}
}
+
+ SCOPE_EXIT_RTN();
}
static int apply_cap_to_bundled(struct ast_sip_session_media *session_media,
@@ -436,12 +439,14 @@
struct ast_format_cap *remote;
struct ast_rtp_codecs codecs = AST_RTP_CODECS_NULL_INIT;
int fmts = 0;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
+
remote = ast_format_cap_alloc(AST_FORMAT_CAP_FLAG_DEFAULT);
if (!remote) {
ast_log(LOG_ERROR, "Failed to allocate %s incoming remote capabilities\n",
ast_codec_media_type2str(session_media->type));
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't allocate caps\n");
}
/* Get the peer's capabilities*/
@@ -456,7 +461,7 @@
if (!incoming_call_offer_cap || ast_format_cap_empty(incoming_call_offer_cap)) {
ao2_cleanup(incoming_call_offer_cap);
ast_rtp_codecs_payloads_destroy(&codecs);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "No incoming call offer caps\n");
}
/*
@@ -470,7 +475,7 @@
ast_rtp_codecs_payloads_destroy(&codecs);
- return incoming_call_offer_cap;
+ SCOPE_EXIT_RTN_VALUE(incoming_call_offer_cap);
}
static int set_caps(struct ast_sip_session *session,
@@ -488,13 +493,15 @@
int direct_media_enabled = !ast_sockaddr_isnull(&session_media->direct_media_addr) &&
ast_format_cap_count(session->direct_media_cap);
int dsp_features = 0;
+ SCOPE_ENTER(1, "%s %s\n", ast_sip_session_get_name(session), is_offer ? "OFFER" : "ANSWER");
if (!(caps = ast_format_cap_alloc(AST_FORMAT_CAP_FLAG_DEFAULT)) ||
!(peer = ast_format_cap_alloc(AST_FORMAT_CAP_FLAG_DEFAULT)) ||
!(joint = ast_format_cap_alloc(AST_FORMAT_CAP_FLAG_DEFAULT))) {
ast_log(LOG_ERROR, "Failed to allocate %s capabilities\n",
ast_codec_media_type2str(session_media->type));
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create %s capabilities\n",
+ ast_codec_media_type2str(session_media->type));
}
/* get the endpoint capabilities */
@@ -519,7 +526,10 @@
ast_codec_media_type2str(session_media->type),
ast_format_cap_get_names(caps, &usbuf),
ast_format_cap_get_names(peer, &thembuf));
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "No joint capabilities for '%s' media stream between our configuration(%s) and incoming SDP(%s)\n",
+ ast_codec_media_type2str(session_media->type),
+ ast_format_cap_get_names(caps, &usbuf),
+ ast_format_cap_get_names(peer, &thembuf));
}
if (is_offer) {
@@ -594,7 +604,7 @@
}
ast_rtp_codecs_payloads_destroy(&codecs);
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
static pjmedia_sdp_attr* generate_rtpmap_attr(struct ast_sip_session *session, pjmedia_sdp_media *media, pj_pool_t *pool,
@@ -1416,12 +1426,13 @@
enum ast_sip_session_media_encryption encryption = AST_SIP_MEDIA_ENCRYPT_NONE;
struct ast_format_cap *joint;
int res;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
/* If no type formats have been configured reject this stream */
if (!ast_format_cap_has_type(session->endpoint->media.codecs, media_type)) {
ast_debug(3, "Endpoint has no codecs for media type '%s', declining stream\n",
ast_codec_media_type2str(session_media->type));
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Endpoint has no codecs\n");
}
/* Ensure incoming transport is compatible with the endpoint's configuration */
@@ -1429,7 +1440,7 @@
encryption = check_endpoint_media_transport(session->endpoint, stream);
if (encryption == AST_SIP_MEDIA_TRANSPORT_INVALID) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Incompatible transport\n");
}
}
@@ -1438,12 +1449,12 @@
/* Ensure that the address provided is valid */
if (ast_sockaddr_resolve(&addrs, host, PARSE_PORT_FORBID, AST_AF_UNSPEC) <= 0) {
/* The provided host was actually invalid so we error out this negotiation */
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Invalid host\n");
}
/* Using the connection information create an appropriate RTP instance */
if (!session_media->rtp && create_rtp(session, session_media, sdp)) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create rtp\n");
}
process_ssrc_attributes(session, session_media, stream);
@@ -1465,7 +1476,7 @@
* but was not this session must fail. This must also fail if crypto was
* required in the offer but could not be set up.
*/
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Incompatible crypto\n");
}
/* There is no encryption, sad. */
session_media->encryption = AST_SIP_MEDIA_ENCRYPT_NONE;
@@ -1510,10 +1521,10 @@
res = apply_cap_to_bundled(session_media, session_media_transport, asterisk_stream, joint);
ao2_cleanup(joint);
if (res != 0) {
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Something failed\n");
}
- return 1;
+ SCOPE_EXIT_RTN_VALUE(1);
}
static int add_crypto_to_stream(struct ast_sip_session *session,
@@ -1666,13 +1677,14 @@
enum ast_media_type media_type = session_media->type;
struct ast_sip_session_media *session_media_transport;
pj_sockaddr ip;
-
int direct_media_enabled = !ast_sockaddr_isnull(&session_media->direct_media_addr) &&
ast_format_cap_count(session->direct_media_cap);
+ SCOPE_ENTER(1, "%s Type: %s %s\n", ast_sip_session_get_name(session),
+ ast_codec_media_type2str(media_type), ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
media = pj_pool_zalloc(pool, sizeof(struct pjmedia_sdp_media));
if (!media) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Pool alloc failure\n");
}
pj_strdup2(pool, &media->desc.media, ast_codec_media_type2str(session_media->type));
@@ -1702,11 +1714,11 @@
sdp->media[sdp->media_count++] = media;
ast_stream_set_state(stream, AST_STREAM_STATE_REMOVED);
- return 1;
+ SCOPE_EXIT_RTN_VALUE(1, "Stream removed or no formats\n");
}
if (!session_media->rtp && create_rtp(session, session_media, sdp)) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create rtp\n");
}
/* If this stream has not been bundled already it is new and we need to ensure there is no SSRC conflict */
@@ -1738,7 +1750,7 @@
* set up according to the configuration. This ends up changing the media transport.
*/
if (add_crypto_to_stream(session, session_media, pool, media)) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't add crypto\n");
}
if (pj_strlen(&session_media->transport)) {
@@ -1755,7 +1767,7 @@
media->conn = pj_pool_zalloc(pool, sizeof(struct pjmedia_sdp_conn));
if (!media->conn) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Pool alloc failure\n");
}
/* Add connection level details */
@@ -1770,7 +1782,7 @@
if (ast_strlen_zero(hostip)) {
ast_log(LOG_ERROR, "No local host IP available for stream %s\n",
ast_codec_media_type2str(session_media->type));
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "No local host ip\n");
}
media->conn->net_type = STR_IN;
@@ -1798,7 +1810,7 @@
media->desc.port = bundle_group_stream->desc.port;
if (add_crypto_to_stream(session, session_media_transport, pool, media)) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't add crypto\n");
}
add_ice_to_stream(session, session_media_transport, pool, media, 0);
@@ -1809,7 +1821,7 @@
if (!(caps = ast_format_cap_alloc(AST_FORMAT_CAP_FLAG_DEFAULT))) {
ast_log(LOG_ERROR, "Failed to allocate %s capabilities\n",
ast_codec_media_type2str(session_media->type));
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create caps\n");
}
if (direct_media_enabled) {
@@ -1896,7 +1908,7 @@
/* If no formats were actually added to the media stream don't add it to the SDP */
if (!media->desc.fmt_count) {
- return 1;
+ SCOPE_EXIT_RTN_VALUE(1, "No formats added to stream\n");
}
/* If ptime is set add it as an attribute */
@@ -1952,7 +1964,7 @@
/* Add the media stream to the SDP */
sdp->media[sdp->media_count++] = media;
- return 1;
+ SCOPE_EXIT_RTN_VALUE(1, "RC: 1\n");
}
static struct ast_frame *media_session_rtp_read_callback(struct ast_sip_session *session, struct ast_sip_session_media *session_media)
@@ -2010,20 +2022,22 @@
char host[NI_MAXHOST];
int res;
struct ast_sip_session_media *session_media_transport;
+ SCOPE_ENTER(1, "%s Stream: %s\n", ast_sip_session_get_name(session),
+ ast_str_tmp(128, ast_stream_to_str(asterisk_stream, &STR_TMP)));
if (!session->channel) {
- return 1;
+ SCOPE_EXIT_RTN_VALUE(1, "No channel\n");
}
/* Ensure incoming transport is compatible with the endpoint's configuration */
if (!session->endpoint->media.rtp.use_received_transport &&
check_endpoint_media_transport(session->endpoint, remote_stream) == AST_SIP_MEDIA_TRANSPORT_INVALID) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Incompatible transport\n");
}
/* Create an RTP instance if need be */
if (!session_media->rtp && create_rtp(session, session_media, local)) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create rtp\n");
}
process_ssrc_attributes(session, session_media, remote_stream);
@@ -2042,11 +2056,11 @@
/* If optimistic encryption is disabled and crypto should have been enabled but was not
* this session must fail.
*/
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Incompatible crypto\n");
}
if (!remote_stream->conn && !remote->conn) {
- return 1;
+ SCOPE_EXIT_RTN_VALUE(1, "No connection info\n");
}
ast_copy_pj_str(host, remote_stream->conn ? &remote_stream->conn->addr : &remote->conn->addr, sizeof(host));
@@ -2054,7 +2068,7 @@
/* Ensure that the address provided is valid */
if (ast_sockaddr_resolve(&addrs, host, PARSE_PORT_FORBID, AST_AF_UNSPEC) <= 0) {
/* The provided host was actually invalid so we error out this negotiation */
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Host invalid\n");
}
/* Apply connection information to the RTP instance */
@@ -2079,7 +2093,7 @@
}
if (set_caps(session, session_media, session_media_transport, remote_stream, 0, asterisk_stream)) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "set_caps failed\n");
}
/* Set the channel uniqueid on the RTP instance now that it is becoming active */
@@ -2097,7 +2111,7 @@
&& (session->inv_session->state == PJSIP_INV_STATE_CONFIRMED)) {
ast_queue_control(session->channel, AST_CONTROL_UPDATE_RTP_PEER);
}
- return 1;
+ SCOPE_EXIT_RTN_VALUE(1, "moh\n");
}
if (session_media->remotely_held_changed) {
@@ -2155,7 +2169,7 @@
session_media, 1);
}
- return 1;
+ SCOPE_EXIT_RTN_VALUE(1, "Handled\n");
}
/*! \brief Function which updates the media stream with external media address, if applicable */
diff --git a/res/res_pjsip_session.c b/res/res_pjsip_session.c
index 450c401..0cf0c8a 100644
--- a/res/res_pjsip_session.c
+++ b/res/res_pjsip_session.c
@@ -111,6 +111,20 @@
return ast_str_hash(stream_type);
}
+const char *ast_sip_session_get_name(const struct ast_sip_session *session)
+{
+ if (!session) {
+ return "(null session)";
+ }
+ if (session->channel) {
+ return ast_channel_name(session->channel);
+ } else if (session->endpoint) {
+ return ast_sorcery_object_get_id(session->endpoint);
+ } else {
+ return "unknown";
+ }
+}
+
static int sdp_handler_list_cmp(void *obj, void *arg, int flags)
{
struct sdp_handler_list *handler_list1 = obj;
@@ -713,17 +727,18 @@
int i;
int handled = 0;
int type_streams[AST_MEDIA_TYPE_END] = {0};
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
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_RTN_VALUE(-1, "Already disconnected\n");
}
/* 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_RTN_VALUE(-1, "No topology\n");
}
}
@@ -756,11 +771,11 @@
stream = ast_stream_alloc(existing_stream ? ast_stream_get_name(existing_stream) : ast_codec_media_type2str(type), type);
if (!stream) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create stream\n");
}
if (ast_stream_topology_set_stream(session->pending_media_state->topology, i, stream)) {
ast_stream_free(stream);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't set stream\n");
}
if (existing_stream) {
const char *stream_label = ast_stream_get_metadata(existing_stream, "SDP:LABEL");
@@ -792,7 +807,7 @@
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_RTN_VALUE(-1, "Couldn't add session media\n");
}
/* If this stream is already declined mark it as such, or mark it as such if we've reached the limit */
@@ -814,7 +829,7 @@
res = handler->negotiate_incoming_sdp_stream(session, session_media, sdp, i, stream);
if (res < 0) {
/* Catastrophic failure. Abort! */
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't negotiate incoming sdp stream\n");
} else if (res == 0) {
ast_debug(1, "Declining incoming SDP media stream '%s' at position '%d'\n",
ast_codec_media_type2str(type), i);
@@ -865,9 +880,12 @@
}
}
if (!handled) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Not handled\n");
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Handled. Active: %s Pending: %s\n",
+ ast_str_tmp(256, ast_stream_topology_to_str(session->active_media_state->topology, &STR_TMP)),
+ ast_str_tmp(256, ast_stream_topology_to_str(session->pending_media_state->topology, &STR_TMP))
+ );
}
static int handle_negotiated_sdp_session_media(struct ast_sip_session_media *session_media,
@@ -880,6 +898,7 @@
struct ast_sip_session_sdp_handler *handler;
RAII_VAR(struct sdp_handler_list *, handler_list, NULL, ao2_cleanup);
int res;
+ SCOPE_ENTER(1, "%s\n", session ? ast_sip_session_get_name(session) : "unknown");
/* We need a null-terminated version of the media string */
ast_copy_pj_str(media, &local->media[index]->desc.media, sizeof(media));
@@ -918,15 +937,20 @@
ast_debug(1, "Applied negotiated SDP media stream '%s' using %s SDP handler\n",
ast_codec_media_type2str(session_media->type),
handler->id);
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "%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 -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "%s: Failed to apply 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);
}
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);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "%s: No registered SDP handlers for media type '%s'\n",
+ ast_sip_session_get_name(session), media);
}
AST_LIST_TRAVERSE(&handler_list->list, handler, next) {
if (handler == session_media->handler) {
@@ -938,7 +962,8 @@
res = handler->apply_negotiated_sdp_stream(session, session_media, local, remote, index, asterisk_stream);
if (res < 0) {
/* Catastrophic failure. Abort! */
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "%s: Handler '%s' returned %d\n",
+ ast_sip_session_get_name(session), handler->id, res);
}
if (res > 0) {
ast_debug(1, "Applied negotiated SDP media stream '%s' using %s SDP handler\n",
@@ -946,17 +971,22 @@
handler->id);
/* Handled by this handler. Move to the next stream */
session_media_set_handler(session_media, handler);
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "%s: Handler '%s' handled this sdp stream\n",
+ ast_sip_session_get_name(session), handler->id);
}
}
+ res = 0;
if (session_media->handler && session_media->handler->stream_stop) {
+ res = 1;
ast_debug(1, "Stopping SDP media stream '%s' as it is not currently negotiated\n",
ast_codec_media_type2str(session_media->type));
session_media->handler->stream_stop(session_media);
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "%s: Media type '%s' %s\n",
+ ast_sip_session_get_name(session), ast_codec_media_type2str(session_media->type),
+ res ? "not negotiated. Stopped" : "handled");
}
static int handle_negotiated_sdp(struct ast_sip_session *session, const pjmedia_sdp_session *local, const pjmedia_sdp_session *remote)
@@ -964,6 +994,7 @@
int i;
struct ast_stream_topology *topology;
unsigned int changed = 0; /* 0 = unchanged, 1 = new source, 2 = new topology */
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
if (!session->pending_media_state->topology) {
if (session->active_media_state->topology) {
@@ -979,7 +1010,7 @@
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");
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Unable to clone active media state\n");
}
ast_sip_session_media_state_free(session->pending_media_state);
@@ -987,7 +1018,7 @@
} else {
ast_log(LOG_WARNING, "No pending or active media state for channel '%s'\n",
session->channel ? ast_channel_name(session->channel) : "unknown");
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "No media state\n");
}
}
@@ -1001,7 +1032,7 @@
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_stream_topology_get_count(session->pending_media_state->topology), local->media_count);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Media stream count mismatch\n");
}
for (i = 0; i < local->media_count; ++i) {
@@ -1038,7 +1069,7 @@
}
if (handle_negotiated_sdp_session_media(session_media, session, local, remote, i, stream)) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Unable to handle negotiated session media\n");
}
changed |= session_media->changed;
@@ -1118,7 +1149,7 @@
ast_queue_frame(session->channel, &ast_null_frame);
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
#define DATASTORE_BUCKETS 53
@@ -1499,6 +1530,7 @@
{
pjsip_inv_session *inv_session = session->inv_session;
const pjmedia_sdp_session *previous_sdp = NULL;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
if (inv_session->neg) {
if (pjmedia_sdp_neg_was_answer_remote(inv_session->neg)) {
@@ -1507,7 +1539,7 @@
pjmedia_sdp_neg_get_active_local(inv_session->neg, &previous_sdp);
}
}
- return create_local_sdp(inv_session, session, previous_sdp);
+ SCOPE_EXIT_RTN_VALUE(create_local_sdp(inv_session, session, previous_sdp));
}
static void set_from_header(struct ast_sip_session *session)
@@ -1878,13 +1910,14 @@
pjsip_inv_session *inv_session = session->inv_session;
pjmedia_sdp_session *new_answer = NULL;
const pjmedia_sdp_session *previous_offer = NULL;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
/* The SDP answer can only be regenerated if it is still pending to be sent */
if (!inv_session->neg || (pjmedia_sdp_neg_get_state(inv_session->neg) != PJMEDIA_SDP_NEG_STATE_REMOTE_OFFER &&
pjmedia_sdp_neg_get_state(inv_session->neg) != PJMEDIA_SDP_NEG_STATE_WAIT_NEGO)) {
ast_log(LOG_WARNING, "Requested to regenerate local SDP answer for channel '%s' but negotiation in state '%s'\n",
ast_channel_name(session->channel), pjmedia_sdp_neg_state_str(pjmedia_sdp_neg_get_state(inv_session->neg)));
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Bad negotiation state\n");
}
pjmedia_sdp_neg_get_neg_remote(inv_session->neg, &previous_offer);
@@ -1898,18 +1931,18 @@
if (!new_answer) {
ast_log(LOG_WARNING, "Could not create a new local SDP answer for channel '%s'\n",
ast_channel_name(session->channel));
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create new SDP\n");
}
if (on_sdp_creation) {
if (on_sdp_creation(session, new_answer)) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Callback failed\n");
}
}
pjsip_inv_set_sdp_answer(inv_session, new_answer);
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
void ast_sip_session_send_response(struct ast_sip_session *session, pjsip_tx_data *tdata)
@@ -1920,11 +1953,15 @@
}
static pj_bool_t session_on_rx_request(pjsip_rx_data *rdata);
+static pj_bool_t session_on_rx_response(pjsip_rx_data *rdata);
+static void session_on_tsx_state(pjsip_transaction *tsx, pjsip_event *e);
static pjsip_module session_module = {
.name = {"Session Module", 14},
.priority = PJSIP_MOD_PRIORITY_APPLICATION,
.on_rx_request = session_on_rx_request,
+ .on_rx_response = session_on_rx_response,
+ .on_tsx_state = session_on_tsx_state,
};
/*! \brief Determine whether the SDP provided requires deferral of negotiating or not
@@ -2226,10 +2263,11 @@
int ast_sip_session_create_invite(struct ast_sip_session *session, pjsip_tx_data **tdata)
{
pjmedia_sdp_session *offer;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
if (!(offer = create_local_sdp(session->inv_session, session, NULL))) {
pjsip_inv_terminate(session->inv_session, 500, PJ_FALSE);
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Couldn't create offer\n");
}
pjsip_inv_set_local_sdp(session->inv_session, offer);
@@ -2247,10 +2285,10 @@
set_from_header(session);
if (pjsip_inv_invite(session->inv_session, tdata) != PJ_SUCCESS) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "pjsip_inv_invite failed\n");
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
static int datastore_hash(const void *obj, int flags)
@@ -2668,6 +2706,8 @@
struct pjsip_inv_session *inv_session;
RAII_VAR(struct ast_sip_session *, session, NULL, ao2_cleanup);
struct ast_sip_session *ret_session;
+ SCOPE_ENTER(1, "%s %s Topology: %s\n", ast_sorcery_object_get_id(endpoint), request_user,
+ ast_str_tmp(256, ast_stream_topology_to_str(req_topology, &STR_TMP)));
/* If no location has been provided use the AOR list from the endpoint itself */
if (location || !contact) {
@@ -2688,21 +2728,21 @@
if (ast_strlen_zero(uri)) {
ast_log(LOG_ERROR, "Endpoint '%s': No URI available. Is endpoint registered?\n",
ast_sorcery_object_get_id(endpoint));
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "No URI\n");
}
if (!(dlg = ast_sip_create_dialog_uac(endpoint, uri, request_user))) {
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't create dialog\n");
}
if (setup_outbound_invite_auth(dlg)) {
pjsip_dlg_terminate(dlg);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't setup auth\n");
}
if (pjsip_inv_create_uac(dlg, NULL, endpoint->extensions.flags, &inv_session) != PJ_SUCCESS) {
pjsip_dlg_terminate(dlg);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't create uac\n");
}
#if defined(HAVE_PJSIP_REPLACE_MEDIA_STREAM) || defined(PJMEDIA_SDP_NEG_ALLOW_MEDIA_CHANGE)
inv_session->sdp_neg_flags = PJMEDIA_SDP_NEG_ALLOW_MEDIA_CHANGE;
@@ -2749,7 +2789,7 @@
if (!session->pending_media_state->topology) {
pjsip_inv_terminate(inv_session, 500, PJ_FALSE);
ao2_ref(session, -1);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't create topology\n");
}
}
@@ -2766,7 +2806,7 @@
if (!session->pending_media_state->topology) {
pjsip_inv_terminate(inv_session, 500, PJ_FALSE);
ao2_ref(session, -1);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't clone topology\n");
}
}
@@ -2776,13 +2816,13 @@
* we need to manually drop its reference to session
*/
ao2_ref(session, -1);
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't add usage\n");
}
/* Avoid unnecessary ref manipulation to return a session */
ret_session = session;
session = NULL;
- return ret_session;
+ SCOPE_EXIT_RTN_VALUE(ret_session);
}
static int session_end(void *vsession);
@@ -2792,10 +2832,11 @@
{
pj_status_t status;
pjsip_tx_data *packet = NULL;
+ SCOPE_ENTER(1, "%s Response %d\n", ast_sip_session_get_name(session), response);
if (session->defer_terminate) {
session->terminate_while_deferred = 1;
- return;
+ SCOPE_EXIT_RTN("Deferred\n");
}
if (!response) {
@@ -2863,6 +2904,7 @@
}
break;
}
+ SCOPE_EXIT_RTN();
}
static int session_termination_task(void *data)
@@ -3175,6 +3217,7 @@
pjsip_rdata_sdp_info *sdp_info;
pjmedia_sdp_session *local = NULL;
char buffer[AST_SOCKADDR_BUFLEN];
+ SCOPE_ENTER(1, "%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
@@ -3187,7 +3230,7 @@
#ifdef HAVE_PJSIP_INV_SESSION_REF
pjsip_inv_dec_ref(invite->session->inv_session);
#endif
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Already disconnected\n");
}
switch (get_destination(invite->session, invite->rdata)) {
@@ -3297,7 +3340,10 @@
#ifdef HAVE_PJSIP_INV_SESSION_REF
pjsip_inv_dec_ref(invite->session->inv_session);
#endif
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Handled. Active: %s Pending: %s\n",
+ ast_str_tmp(256, ast_stream_topology_to_str(invite->session->active_media_state->topology, &STR_TMP)),
+ ast_str_tmp(256, ast_stream_topology_to_str(invite->session->pending_media_state->topology, &STR_TMP))
+ );
}
static void handle_new_invite_request(pjsip_rx_data *rdata)
@@ -3308,13 +3354,16 @@
pjsip_inv_session *inv_session = NULL;
struct ast_sip_session *session;
struct new_invite invite;
+ char *req_uri = TRACE_ATLEAST(1) ? ast_alloca(256) : "";
+ int res = TRACE_ATLEAST(1) ? pjsip_uri_print(PJSIP_URI_IN_REQ_URI, rdata->msg_info.msg->line.req.uri, req_uri, 256) : 0;
+ SCOPE_ENTER(1, "Request: %s\n", res ? req_uri : "");
ast_assert(endpoint != NULL);
inv_session = pre_session_setup(rdata, endpoint);
if (!inv_session) {
/* pre_session_setup() returns a response on failure */
- return;
+ SCOPE_EXIT_RTN("Failure in pre session setup\n");
}
#ifdef HAVE_PJSIP_INV_SESSION_REF
@@ -3327,7 +3376,7 @@
pjsip_inv_send_msg(inv_session, tdata);
}
}
- return;
+ SCOPE_EXIT_RTN("Couldn't add invite session reference\n");
}
#endif
@@ -3341,7 +3390,7 @@
#ifdef HAVE_PJSIP_INV_SESSION_REF
pjsip_inv_dec_ref(inv_session);
#endif
- return;
+ SCOPE_EXIT_RTN("Couldn't create session\n");
}
session->call_direction = AST_SIP_SESSION_INCOMING_CALL;
@@ -3356,6 +3405,7 @@
invite.rdata = rdata;
new_invite(&invite);
+ SCOPE_EXIT("Request: %s Session: %s\n", req_uri, ast_sip_session_get_name(session));
ao2_ref(session, -1);
}
@@ -3388,6 +3438,46 @@
}
return PJ_FALSE;
}
+
+/*!
+ * \internal
+ * Added for debugging purposes
+ */
+static void session_on_tsx_state(pjsip_transaction *tsx, pjsip_event *e)
+{
+
+ pjsip_dialog *dlg = pjsip_tsx_get_dlg(tsx);
+ pjsip_inv_session *inv_session = (dlg ? pjsip_dlg_get_inv_session(dlg) : NULL);
+ struct ast_sip_session *session = (inv_session ? inv_session->mod_data[session_module.id] : NULL);
+ SCOPE_ENTER(1, "%s TSX State: %s Inv State: %s\n", ast_sip_session_get_name(session),
+ pjsip_tsx_state_str(tsx->state), inv_session ? pjsip_inv_state_name(inv_session->state) : "unknown");
+
+ if (session) {
+ ast_trace(2, "Topology: Pending: %s Active: %s\n",
+ 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)));
+ }
+
+ SCOPE_EXIT_RTN();
+}
+
+/*!
+ * \internal
+ * Added for debugging purposes
+ */
+static pj_bool_t session_on_rx_response(pjsip_rx_data *rdata)
+{
+
+ struct pjsip_status_line status = rdata->msg_info.msg->line.status;
+ pjsip_dialog *dlg = pjsip_rdata_get_dlg(rdata);
+ pjsip_inv_session *inv_session = pjsip_dlg_get_inv_session(dlg);
+ struct ast_sip_session *session = (inv_session ? inv_session->mod_data[session_module.id] : NULL);
+ SCOPE_ENTER(1, "%s Method: %.*s Status: %d\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code);
+
+ SCOPE_EXIT_RTN_VALUE(PJ_FALSE);
+}
+
/*!
* \brief Called when a new SIP request comes into PJSIP
*
@@ -3408,10 +3498,16 @@
static pj_bool_t session_on_rx_request(pjsip_rx_data *rdata)
{
pj_status_t handled = PJ_FALSE;
+ struct pjsip_request_line req = rdata->msg_info.msg->line.req;
pjsip_dialog *dlg = pjsip_rdata_get_dlg(rdata);
- pjsip_inv_session *inv_session;
+ pjsip_inv_session *inv_session = (dlg ? pjsip_dlg_get_inv_session(dlg) : NULL);
+ struct ast_sip_session *session = (inv_session ? inv_session->mod_data[session_module.id] : NULL);
+ char *req_uri = TRACE_ATLEAST(1) ? ast_alloca(256) : "";
+ int res = TRACE_ATLEAST(1) ? pjsip_uri_print(PJSIP_URI_IN_REQ_URI, rdata->msg_info.msg->line.req.uri, req_uri, 256) : 0;
+ SCOPE_ENTER(1, "%s Request: %.*s %s\n", ast_sip_session_get_name(session),
+ (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name), res ? req_uri : "");
- switch (rdata->msg_info.msg->line.req.method.id) {
+ switch (req.method.id) {
case PJSIP_INVITE_METHOD:
if (dlg) {
ast_log(LOG_WARNING, "on_rx_request called for INVITE in mid-dialog?\n");
@@ -3427,7 +3523,9 @@
break;
}
- return handled;
+ SCOPE_EXIT_RTN_VALUE(handled, "%s Handled request %.*s %s ? %s\n", ast_sip_session_get_name(session),
+ (int) pj_strlen(&req.method.name), pj_strbuf(&req.method.name), req_uri,
+ handled == PJ_TRUE ? "yes" : "no");
}
static void resend_reinvite(pj_timer_heap_t *timer, pj_timer_entry *entry)
@@ -3541,6 +3639,8 @@
{
struct ast_sip_session_supplement *supplement;
struct pjsip_request_line req = rdata->msg_info.msg->line.req;
+ SCOPE_ENTER(1, "%s Method: %.*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) {
@@ -3550,6 +3650,8 @@
}
}
}
+
+ SCOPE_EXIT_RTN();
}
static void handle_session_begin(struct ast_sip_session *session)
@@ -3591,6 +3693,10 @@
{
struct ast_sip_session_supplement *supplement;
struct pjsip_status_line status = rdata->msg_info.msg->line.status;
+ SCOPE_ENTER(1, "%s Method: %.*s Status: %d Priority %s\n", ast_sip_session_get_name(session),
+ (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr,
+ rdata->msg_info.msg->line.status.code,
+ response_priority == AST_SIP_SESSION_AFTER_MEDIA ? "after" : "before");
ast_debug(3, "Response is %d %.*s\n", status.code, (int) pj_strlen(&status.reason),
pj_strbuf(&status.reason));
@@ -3603,11 +3709,14 @@
supplement->incoming_response(session, rdata);
}
}
+
+ SCOPE_EXIT_RTN();
}
static int handle_incoming(struct ast_sip_session *session, pjsip_rx_data *rdata,
enum ast_sip_session_response_priority response_priority)
{
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
ast_debug(3, "Received %s\n", rdata->msg_info.msg->type == PJSIP_REQUEST_MSG ?
"request" : "response");
@@ -3617,13 +3726,16 @@
handle_incoming_response(session, rdata, response_priority);
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0);
}
static void handle_outgoing_request(struct ast_sip_session *session, pjsip_tx_data *tdata)
{
struct ast_sip_session_supplement *supplement;
struct pjsip_request_line req = tdata->msg->line.req;
+ SCOPE_ENTER(1, "%s Method: %.*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));
@@ -3634,6 +3746,8 @@
supplement->outgoing_request(session, tdata);
}
}
+
+ SCOPE_EXIT_RTN();
}
static void handle_outgoing_response(struct ast_sip_session *session, pjsip_tx_data *tdata)
@@ -3641,10 +3755,14 @@
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);
+ SCOPE_ENTER(1, "%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) {
ast_log(LOG_ERROR, "Cannot send response due to missing sequence header");
- return;
+ SCOPE_EXIT_RTN("Missing cseq\n");
}
ast_debug(3, "Method is %.*s, Response is %d %.*s\n", (int) pj_strlen(&cseq->method.name),
@@ -3658,6 +3776,8 @@
supplement->outgoing_response(session, tdata);
}
}
+
+ SCOPE_EXIT_RTN();
}
static int session_end(void *vsession)
@@ -3722,6 +3842,7 @@
struct ast_sip_session *session, pjsip_rx_data *rdata)
{
pjsip_msg *msg;
+ SCOPE_ENTER(1, "%s\n", ast_sip_session_get_name(session));
handle_incoming(session, rdata, AST_SIP_SESSION_BEFORE_MEDIA);
msg = rdata->msg_info.msg;
@@ -3746,15 +3867,19 @@
ast_sip_session_send_request(session, tdata);
}
}
+
+ SCOPE_EXIT_RTN();
}
static void session_inv_on_state_changed(pjsip_inv_session *inv, pjsip_event *e)
{
- struct ast_sip_session *session;
pjsip_event_id_e type;
+ struct ast_sip_session *session = inv->mod_data[session_module.id];
+ SCOPE_ENTER(1, "%s Event: %s Inv State: %s\n", ast_sip_session_get_name(session),
+ pjsip_event_str(e->type), pjsip_inv_state_name(inv->state));
if (ast_shutdown_final()) {
- return;
+ SCOPE_EXIT_RTN("Shutting down\n");
}
if (e) {
@@ -3766,7 +3891,7 @@
session = inv->mod_data[session_module.id];
if (!session) {
- return;
+ SCOPE_EXIT_RTN("No session\n");
}
switch(type) {
@@ -3814,7 +3939,7 @@
if (session->defer_end) {
ast_debug(3, "Deferring session (%p) end\n", session);
session->ended_while_deferred = 1;
- return;
+ SCOPE_EXIT_RTN("Deferring\n");
}
if (ast_sip_push_task(session->serializer, session_end, session)) {
@@ -3822,6 +3947,8 @@
session_end(session);
}
}
+
+ SCOPE_EXIT_RTN();
}
static void session_inv_on_new_session(pjsip_inv_session *inv, pjsip_event *e)
@@ -3863,11 +3990,13 @@
{
ast_sip_session_response_cb cb;
int id = session_module.id;
- struct ast_sip_session *session;
pjsip_tx_data *tdata;
+ struct ast_sip_session *session = inv->mod_data[session_module.id];
+ SCOPE_ENTER(1, "%s TSX State: %s Inv State: %s\n", ast_sip_session_get_name(session),
+ pjsip_tsx_state_str(tsx->state), pjsip_inv_state_name(inv->state));
if (ast_shutdown_final()) {
- return;
+ SCOPE_EXIT_RTN("Shutting down\n");
}
session = inv->mod_data[id];
@@ -3875,7 +4004,7 @@
print_debug_details(inv, tsx, e);
if (!session) {
/* The session has ended. Ignore the transaction change. */
- return;
+ SCOPE_EXIT_RTN("Session ended\n");
}
/*
@@ -3885,7 +4014,7 @@
* state but the BYE request transaction has not yet completed.
*/
if (tsx->method.id != PJSIP_BYE_METHOD && session_end_if_disconnected(id, inv)) {
- return;
+ SCOPE_EXIT_RTN("Disconnected\n");
}
switch (e->body.tsx_state.type) {
@@ -3915,7 +4044,7 @@
/* This means we got a non 2XX final response to our outgoing INVITE */
if (tsx->status_code == PJSIP_SC_REQUEST_PENDING) {
reschedule_reinvite(session, cb);
- return;
+ SCOPE_EXIT_RTN("Non 2XX final response\n");
}
if (inv->state == PJSIP_INV_STATE_CONFIRMED) {
ast_debug(1, "reINVITE received final response code %d\n",
@@ -3926,7 +4055,7 @@
e->body.tsx_state.src.rdata, tsx->last_tx, &tdata)) {
/* Send authed reINVITE */
ast_sip_session_send_request_with_cb(session, tdata, cb);
- return;
+ SCOPE_EXIT_RTN("Sending authed reinvite\n");
}
if (tsx->status_code != 488 && tsx->status_code != 500) {
/* Other reinvite failures (except 488 and 500) result in destroying the session. */
@@ -3956,7 +4085,7 @@
session->channel ? ast_channel_name(session->channel) : "",
pjsip_rx_data_get_info(e->body.tsx_state.src.rdata));
pjsip_inv_end_session(session->inv_session, 503, NULL, &tdata);
- return;
+ SCOPE_EXIT_RTN("Incomplete SDP negotiation\n");
}
if (inv->cancelling && tsx->status_code == PJSIP_SC_OK) {
@@ -4017,7 +4146,8 @@
e->body.tsx_state.src.rdata, tsx->last_tx, &tdata)) {
/* Send authed version of the method */
ast_sip_session_send_request_with_cb(session, tdata, cb);
- return;
+ SCOPE_EXIT_RTN("Sending authed %.*s\n",
+ (int) pj_strlen(&tsx->method.name), pj_strbuf(&tsx->method.name));
}
}
}
@@ -4033,7 +4163,7 @@
* by the session serializer.
*/
if (session_end_if_disconnected(id, inv)) {
- return;
+ SCOPE_EXIT_RTN("Disconnected\n");
}
break;
case PJSIP_EVENT_USER:
@@ -4045,7 +4175,7 @@
if (AST_LIST_EMPTY(&session->delayed_requests)) {
/* No delayed request pending, so just return */
- return;
+ SCOPE_EXIT_RTN("Nothing delayed\n");
}
if (tsx->method.id == PJSIP_INVITE_METHOD) {
@@ -4076,6 +4206,8 @@
pjsip_tsx_state_str(tsx->state));
check_delayed_requests(session, update_completed);
}
+
+ SCOPE_EXIT_RTN();
}
static int add_sdp_streams(struct ast_sip_session_media *session_media,
@@ -4085,20 +4217,22 @@
{
struct ast_sip_session_sdp_handler *handler = session_media->handler;
RAII_VAR(struct sdp_handler_list *, handler_list, NULL, ao2_cleanup);
- int res;
+ int res = 0;
+ SCOPE_ENTER(1, "%s Stream: %s\n", ast_sip_session_get_name(session),
+ ast_str_tmp(128, ast_stream_to_str(stream, &STR_TMP)));
if (handler) {
/* if an already assigned handler reports a catastrophic error, fail */
res = handler->create_outgoing_sdp_stream(session, session_media, answer, remote, stream);
if (res < 0) {
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Coudn't create sdp stream\n");
}
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Had handler\n");
}
handler_list = ao2_find(sdp_handlers, ast_codec_media_type2str(session_media->type), OBJ_KEY);
if (!handler_list) {
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "No handlers\n");
}
/* no handler for this stream type and we have a list to search */
@@ -4109,17 +4243,17 @@
res = handler->create_outgoing_sdp_stream(session, session_media, answer, remote, stream);
if (res < 0) {
/* catastrophic error */
- return -1;
+ SCOPE_EXIT_RTN_VALUE(-1, "Coudn't create sdp stream\n");
}
if (res > 0) {
/* Handled by this handler. Move to the next stream */
session_media_set_handler(session_media, handler);
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Handled\n");
}
}
/* streams that weren't handled won't be included in generated outbound SDP */
- return 0;
+ SCOPE_EXIT_RTN_VALUE(0, "Not handled\n");
}
/*! \brief Bundle group building structure */
@@ -4208,14 +4342,16 @@
pjmedia_sdp_session *local;
int i;
int stream;
+ SCOPE_ENTER(1, "%s Topology: %s\n", ast_sip_session_get_name(session),
+ ast_str_tmp(256, ast_stream_topology_to_str(session->pending_media_state->topology, &STR_TMP)));
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_RTN_VALUE(NULL, "Disconnected\n");
}
if (!inv->pool_prov || !(local = PJ_POOL_ZALLOC_T(inv->pool_prov, pjmedia_sdp_session))) {
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Pool alloc failure\n");
}
if (!offer) {
@@ -4240,7 +4376,7 @@
session->pending_media_state->topology = ast_stream_topology_clone(session->endpoint->media.topology);
}
if (!session->pending_media_state->topology) {
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "No pending topology\n");
}
}
@@ -4257,11 +4393,11 @@
session_media = ast_sip_session_media_state_add(session, session->pending_media_state, ast_stream_get_type(stream), i);
if (!session_media) {
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't add state\n");
}
if (add_sdp_streams(session_media, session, local, offer, stream)) {
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't add stream\n");
}
/* If a stream was actually added then add any additional details */
@@ -4285,7 +4421,7 @@
/* Add any bundle groups that are present on the media state */
if (add_bundle_groups(session, inv->pool_prov, local)) {
- return NULL;
+ SCOPE_EXIT_RTN_VALUE(NULL, "Couldn't add bundled\n");
}
/* Use the connection details of an available media if possible for SDP level */
@@ -4327,27 +4463,31 @@
pj_strassign(&local->origin.addr_type, &local->conn->addr_type);
pj_strassign(&local->origin.addr, &local->conn->addr);
- return local;
+ SCOPE_EXIT_RTN_VALUE(local);
}
static void session_inv_on_rx_offer(pjsip_inv_session *inv, const pjmedia_sdp_session *offer)
{
- struct ast_sip_session *session;
pjmedia_sdp_session *answer;
+ struct ast_sip_session *session = inv->mod_data[session_module.id];
+ SCOPE_ENTER(1, "%s Inv State: %s\n", ast_sip_session_get_name(session),
+ pjsip_inv_state_name(inv->state));
if (ast_shutdown_final()) {
- return;
+ SCOPE_EXIT_RTN("Shutting down\n");
}
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("Couldn't handle sdp\n");
}
if ((answer = create_local_sdp(inv, session, offer))) {
pjsip_inv_set_sdp_answer(inv, answer);
}
+
+ SCOPE_EXIT_RTN();
}
#if 0
@@ -4359,11 +4499,13 @@
static void session_inv_on_media_update(pjsip_inv_session *inv, pj_status_t status)
{
- struct ast_sip_session *session;
const pjmedia_sdp_session *local, *remote;
+ struct ast_sip_session *session = inv->mod_data[session_module.id];
+ SCOPE_ENTER(1, "%s Inv State: %s\n", ast_sip_session_get_name(session),
+ pjsip_inv_state_name(inv->state));
if (ast_shutdown_final()) {
- return;
+ SCOPE_EXIT_RTN("Shutting down\n");
}
session = inv->mod_data[session_module.id];
@@ -4373,7 +4515,7 @@
* don't care about media updates.
* Just ignore
*/
- return;
+ SCOPE_EXIT_RTN("No session or channel\n");
}
if (session->endpoint) {
@@ -4408,7 +4550,7 @@
}
#endif
if (bail) {
- return;
+ SCOPE_EXIT_RTN("Bail\n");
}
}
@@ -4417,12 +4559,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("Couldn't get active local\n");return;
}
if (handle_negotiated_sdp(session, local, remote)) {
ast_sip_session_media_state_reset(session->pending_media_state);
}
+
+ SCOPE_EXIT_RTN();
}
static pjsip_redirect_op session_inv_on_redirected(pjsip_inv_session *inv, const pjsip_uri *target, const pjsip_event *e)
--
To view, visit https://gerrit.asterisk.org/c/asterisk/+/14631
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings
Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-Change-Id: Ia83a1a2687ccb96f2bc8a2a3928a5214c4be775c
Gerrit-Change-Number: 14631
Gerrit-PatchSet: 3
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/20200708/77cb9f2a/attachment-0001.html>
More information about the asterisk-code-review
mailing list