From 9bd1d686a120db5233acb2d6f90c31d4f52464a0 Mon Sep 17 00:00:00 2001 From: George Joseph Date: Mon, 6 Jul 2020 13:23:24 -0600 Subject: [PATCH] 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 --- apps/app_dial.c | 3 + channels/chan_pjsip.c | 197 +++++++++++------ include/asterisk/res_pjsip_session.h | 9 + main/bridge.c | 3 + main/channel.c | 3 + main/channel_internal_api.c | 12 +- main/features.c | 2 + res/res_pjsip_sdp_rtp.c | 80 ++++--- res/res_pjsip_session.c | 310 ++++++++++++++++++++------- 9 files changed, 439 insertions(+), 180 deletions(-) diff --git a/apps/app_dial.c b/apps/app_dial.c index 2744868201..95f36d7ab2 100644 --- a/apps/app_dial.c +++ b/apps/app_dial.c @@ -1223,6 +1223,7 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in, 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 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in, 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 @@ static int dial_exec_full(struct ast_channel *chan, const char *data, struct ast */ 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 2fc98b4c32..e99ec314f3 100644 --- a/channels/chan_pjsip.c +++ b/channels/chan_pjsip.c @@ -241,7 +241,10 @@ static enum ast_rtp_glue_result chan_pjsip_get_vrtp_peer(struct ast_channel *cha /*! \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 @@ static int chan_pjsip_set_rtp_peer(struct ast_channel *chan, 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 @@ static int chan_pjsip_set_rtp_peer(struct ast_channel *chan, 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 @@ static int compatible_formats_exist(struct ast_stream_topology *top, struct ast_ { 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 @@ static struct ast_channel *chan_pjsip_new(struct ast_sip_session *session, int s 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 @@ static struct ast_channel *chan_pjsip_new(struct ast_sip_session *session, int s 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 @@ static struct ast_channel *chan_pjsip_new(struct ast_sip_session *session, int s 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 @@ static struct ast_channel *chan_pjsip_new(struct ast_sip_session *session, int s 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 @@ static struct ast_channel *chan_pjsip_new(struct ast_sip_session *session, int s 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 @@ static struct ast_channel *chan_pjsip_new(struct ast_sip_session *session, int s 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 @@ static int answer(void *data) #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 @@ static int answer(void *data) * 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 @@ static int chan_pjsip_answer(struct ast_channel *ast) { 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 @@ static int chan_pjsip_answer(struct ast_channel *ast) #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 @@ static int chan_pjsip_answer(struct ast_channel *ast) 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 @@ static int chan_pjsip_answer(struct ast_channel *ast) } 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 struct topology_change_refresh_data *topology_change_refresh_data_alloc( 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 @@ static int on_topology_change_response(struct ast_sip_session *session, pjsip_rx 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 @@ static int handle_topology_request_change(struct ast_sip_session *session, { 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 @@ static int chan_pjsip_indicate(struct ast_channel *ast, int condition, const voi 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 @@ static int chan_pjsip_indicate(struct ast_channel *ast, int condition, const voi 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 @@ static int chan_pjsip_indicate(struct ast_channel *ast, int condition, const voi 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 @@ static int chan_pjsip_indicate(struct ast_channel *ast, int condition, const voi } } - return res; + SCOPE_EXIT_RTN_VALUE(res, "RC: %d\n", res); } struct transfer_data { @@ -2397,8 +2427,14 @@ static int call(void *data) 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 @@ static int call(void *data) 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 @@ static int hangup(void *data) 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 @@ static int hangup(void *data) 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 @@ static int chan_pjsip_hangup(struct ast_channel *ast) 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 @@ static int chan_pjsip_hangup(struct ast_channel *ast) 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 @@ failure: 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 @@ static int request(void *obj) 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 @@ static int request(void *obj) 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@domain) */ @@ -2634,7 +2676,7 @@ static int request(void *obj) 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 @@ static int request(void *obj) 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 @@ static int request(void *obj) ast_log(LOG_ERROR, "Unable to create PJSIP channel with empty endpoint name: %s@\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 @@ static int request(void *obj) 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 @@ static int request(void *obj) 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 @@ static struct ast_channel *chan_pjsip_request_with_stream_topology(const char *t { 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 @@ static struct ast_channel *chan_pjsip_request_with_stream_topology(const char *t 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 int hangup_sip2cause(int cause) 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 @@ static void chan_pjsip_session_end(struct ast_sip_session *session) } else { ast_queue_hangup(session->channel); } + + SCOPE_EXIT_RTN(); } /*! \brief Function called when a request is received on the session */ @@ -3029,9 +3079,10 @@ static int chan_pjsip_incoming_request(struct ast_sip_session *session, struct p 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 @@ static int chan_pjsip_incoming_request(struct ast_sip_session *session, struct p */ 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 @@ static int chan_pjsip_incoming_request(struct ast_sip_session *session, struct p } 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 struct ast_sip_session_supplement call_pickup_supplement = { 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 @@ static int pbx_start_incoming_request(struct ast_sip_session *session, pjsip_rx_ 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 @@ static void chan_pjsip_incoming_response(struct ast_sip_session *session, struct 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 @@ static void chan_pjsip_incoming_response(struct ast_sip_session *session, struct 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 @@ static void chan_pjsip_incoming_response(struct ast_sip_session *session, struct 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 fd49a7ba5e..9db68a8922 100644 --- a/include/asterisk/res_pjsip_session.h +++ b/include/asterisk/res_pjsip_session.h @@ -926,4 +926,13 @@ int ast_sip_session_media_set_write_callback(struct ast_sip_session *session, st */ 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 fb7012df33..7a7b6f6cb5 100644 --- a/main/bridge.c +++ b/main/bridge.c @@ -1673,6 +1673,7 @@ int ast_bridge_join(struct ast_bridge *bridge, { 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 @@ int ast_bridge_impart(struct ast_bridge *bridge, .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 @@ int ast_bridge_depart(struct ast_channel *chan) { 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 2f3aad1b50..8dd008dd15 100644 --- a/main/channel.c +++ b/main/channel.c @@ -2622,6 +2622,7 @@ static void set_channel_answer_time(struct ast_channel *chan) 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 __ast_answer(struct ast_channel *chan, unsigned int delay) { 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, unsigned int delay) 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 be8fd7c024..fb62da5a95 100644 --- a/main/channel_internal_api.c +++ b/main/channel_internal_api.c @@ -677,6 +677,10 @@ void *ast_channel_get_stream_topology_change_source(struct ast_channel *chan) 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), ""), + 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 @@ void ast_channel_nativeformats_set(struct ast_channel *chan, * 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 @@ void ast_channel_nativeformats_set(struct ast_channel *chan, 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 *ast_channel_set_stream_topology(struct ast_channel * 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 @@ struct ast_stream_topology *ast_channel_set_stream_topology(struct ast_channel * 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 ab03bef69b..51cc3ed98d 100644 --- a/main/features.c +++ b/main/features.c @@ -536,6 +536,7 @@ static int pre_bridge_setup(struct ast_channel *chan, struct ast_channel *peer, 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 @@ int ast_bridge_call_with_flags(struct ast_channel *chan, struct ast_channel *pee 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 1bcb661661..eacae22dd6 100644 --- a/res/res_pjsip_sdp_rtp.c +++ b/res/res_pjsip_sdp_rtp.c @@ -324,6 +324,7 @@ static void get_codecs(struct ast_sip_session *session, const struct pjmedia_sdp 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 @@ static void get_codecs(struct ast_sip_session *session, const struct pjmedia_sdp 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 @@ static struct ast_format_cap *set_incoming_call_offer_cap( 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 @@ static struct ast_format_cap *set_incoming_call_offer_cap( 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 @@ static struct ast_format_cap *set_incoming_call_offer_cap( 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 @@ static int set_caps(struct ast_sip_session *session, 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 @@ static int set_caps(struct ast_sip_session *session, 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 @@ static int set_caps(struct ast_sip_session *session, } 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 @@ static int negotiate_incoming_sdp_stream(struct ast_sip_session *session, 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 @@ static int negotiate_incoming_sdp_stream(struct ast_sip_session *session, 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 @@ static int negotiate_incoming_sdp_stream(struct ast_sip_session *session, /* 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 @@ static int negotiate_incoming_sdp_stream(struct ast_sip_session *session, * 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 @@ static int negotiate_incoming_sdp_stream(struct ast_sip_session *session, 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as * 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as /* 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 @@ static int create_outgoing_sdp_stream(struct ast_sip_session *session, struct as /* 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 @@ static int apply_negotiated_sdp_stream(struct ast_sip_session *session, 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 @@ static int apply_negotiated_sdp_stream(struct ast_sip_session *session, /* 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 @@ static int apply_negotiated_sdp_stream(struct ast_sip_session *session, /* 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 @@ static int apply_negotiated_sdp_stream(struct ast_sip_session *session, } 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 @@ static int apply_negotiated_sdp_stream(struct ast_sip_session *session, && (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 @@ static int apply_negotiated_sdp_stream(struct ast_sip_session *session, 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 450c401c13..0cf0c8a0a6 100644 --- a/res/res_pjsip_session.c +++ b/res/res_pjsip_session.c @@ -111,6 +111,20 @@ static int sdp_handler_list_hash(const void *obj, int flags) 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 @@ static int handle_incoming_sdp(struct ast_sip_session *session, const pjmedia_sd 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 @@ static int handle_incoming_sdp(struct ast_sip_session *session, const pjmedia_sd 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 @@ static int handle_incoming_sdp(struct ast_sip_session *session, const pjmedia_sd 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 @@ static int handle_incoming_sdp(struct ast_sip_session *session, const pjmedia_sd 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 @@ static int handle_incoming_sdp(struct ast_sip_session *session, const pjmedia_sd } } 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 @@ static int handle_negotiated_sdp_session_media(struct ast_sip_session_media *ses 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 @@ static int handle_negotiated_sdp_session_media(struct ast_sip_session_media *ses 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 @@ static int handle_negotiated_sdp_session_media(struct ast_sip_session_media *ses 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 @@ static int handle_negotiated_sdp_session_media(struct ast_sip_session_media *ses 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 @@ static int handle_negotiated_sdp(struct ast_sip_session *session, const pjmedia_ 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 @@ static int handle_negotiated_sdp(struct ast_sip_session *session, const pjmedia_ 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 @@ static int handle_negotiated_sdp(struct ast_sip_session *session, const pjmedia_ } 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 @@ static int handle_negotiated_sdp(struct ast_sip_session *session, const pjmedia_ 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 @@ static int handle_negotiated_sdp(struct ast_sip_session *session, const pjmedia_ } 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 @@ static int handle_negotiated_sdp(struct ast_sip_session *session, const pjmedia_ ast_queue_frame(session->channel, &ast_null_frame); } - return 0; + SCOPE_EXIT_RTN_VALUE(0); } #define DATASTORE_BUCKETS 53 @@ -1499,6 +1530,7 @@ static pjmedia_sdp_session *generate_session_refresh_sdp(struct ast_sip_session { 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 @@ static pjmedia_sdp_session *generate_session_refresh_sdp(struct ast_sip_session 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 @@ int ast_sip_session_regenerate_answer(struct ast_sip_session *session, 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 @@ int ast_sip_session_regenerate_answer(struct ast_sip_session *session, 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 @@ void ast_sip_session_send_response(struct ast_sip_session *session, pjsip_tx_dat } 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 @@ void ast_sip_session_send_request(struct ast_sip_session *session, pjsip_tx_data 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 @@ int ast_sip_session_create_invite(struct ast_sip_session *session, pjsip_tx_data 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 ast_sip_session *ast_sip_session_create_outgoing(struct ast_sip_endpoint 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 @@ struct ast_sip_session *ast_sip_session_create_outgoing(struct ast_sip_endpoint 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 @@ struct ast_sip_session *ast_sip_session_create_outgoing(struct ast_sip_endpoint 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 @@ struct ast_sip_session *ast_sip_session_create_outgoing(struct ast_sip_endpoint 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 @@ struct ast_sip_session *ast_sip_session_create_outgoing(struct ast_sip_endpoint * 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 @@ void ast_sip_session_terminate(struct ast_sip_session *session, int response) { 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 @@ void ast_sip_session_terminate(struct ast_sip_session *session, int response) } break; } + SCOPE_EXIT_RTN(); } static int session_termination_task(void *data) @@ -3175,6 +3217,7 @@ static int new_invite(struct new_invite *invite) 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 @@ static int new_invite(struct new_invite *invite) #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 @@ end: #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 @@ static void handle_new_invite_request(pjsip_rx_data *rdata) 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 @@ static void handle_new_invite_request(pjsip_rx_data *rdata) pjsip_inv_send_msg(inv_session, tdata); } } - return; + SCOPE_EXIT_RTN("Couldn't add invite session reference\n"); } #endif @@ -3341,7 +3390,7 @@ static void handle_new_invite_request(pjsip_rx_data *rdata) #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 @@ static void handle_new_invite_request(pjsip_rx_data *rdata) 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 @@ static pj_bool_t has_supplement(const struct ast_sip_session *session, const pjs } 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 has_supplement(const struct ast_sip_session *session, const pjs 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; - - switch (rdata->msg_info.msg->line.req.method.id) { + 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 (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 @@ static pj_bool_t session_on_rx_request(pjsip_rx_data *rdata) 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 @@ static void handle_incoming_request(struct ast_sip_session *session, pjsip_rx_da { 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 @@ static void handle_incoming_request(struct ast_sip_session *session, pjsip_rx_da } } } + + SCOPE_EXIT_RTN(); } static void handle_session_begin(struct ast_sip_session *session) @@ -3591,6 +3693,10 @@ static void handle_incoming_response(struct ast_sip_session *session, pjsip_rx_d { 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 @@ static void handle_incoming_response(struct ast_sip_session *session, pjsip_rx_d 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 @@ static int handle_incoming(struct ast_sip_session *session, pjsip_rx_data *rdata 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 @@ static void handle_outgoing_request(struct ast_sip_session *session, pjsip_tx_da 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 @@ static void handle_outgoing_response(struct ast_sip_session *session, pjsip_tx_d 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 @@ static void handle_outgoing_response(struct ast_sip_session *session, pjsip_tx_d supplement->outgoing_response(session, tdata); } } + + SCOPE_EXIT_RTN(); } static int session_end(void *vsession) @@ -3722,6 +3842,7 @@ static void handle_incoming_before_media(pjsip_inv_session *inv, 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 @@ static void handle_incoming_before_media(pjsip_inv_session *inv, 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 @@ static void session_inv_on_state_changed(pjsip_inv_session *inv, pjsip_event *e) session = inv->mod_data[session_module.id]; if (!session) { - return; + SCOPE_EXIT_RTN("No session\n"); } switch(type) { @@ -3814,7 +3939,7 @@ static void session_inv_on_state_changed(pjsip_inv_session *inv, pjsip_event *e) 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 @@ static void session_inv_on_state_changed(pjsip_inv_session *inv, pjsip_event *e) session_end(session); } } + + SCOPE_EXIT_RTN(); } static void session_inv_on_new_session(pjsip_inv_session *inv, pjsip_event *e) @@ -3863,11 +3990,13 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans { 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans * 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans /* 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans * 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans 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 @@ static void session_inv_on_tsx_state_changed(pjsip_inv_session *inv, pjsip_trans 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 @@ static int add_sdp_streams(struct ast_sip_session_media *session_media, { 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 @@ static int add_sdp_streams(struct ast_sip_session_media *session_media, 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 @@ static struct pjmedia_sdp_session *create_local_sdp(pjsip_inv_session *inv, stru 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 @@ static struct pjmedia_sdp_session *create_local_sdp(pjsip_inv_session *inv, stru 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 @@ static struct pjmedia_sdp_session *create_local_sdp(pjsip_inv_session *inv, stru 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 @@ static struct pjmedia_sdp_session *create_local_sdp(pjsip_inv_session *inv, stru /* 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 @@ static struct pjmedia_sdp_session *create_local_sdp(pjsip_inv_session *inv, stru 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_create_offer(pjsip_inv_session *inv, pjmedia_sdp_sess 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 @@ static void session_inv_on_media_update(pjsip_inv_session *inv, pj_status_t stat * don't care about media updates. * Just ignore */ - return; + SCOPE_EXIT_RTN("No session or channel\n"); } if (session->endpoint) { @@ -4408,7 +4550,7 @@ static void session_inv_on_media_update(pjsip_inv_session *inv, pj_status_t stat } #endif if (bail) { - return; + SCOPE_EXIT_RTN("Bail\n"); } } @@ -4417,12 +4559,14 @@ static void session_inv_on_media_update(pjsip_inv_session *inv, pj_status_t stat 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) -- 2.47.2