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; + 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 @@ 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)