From 695f26cbb759f8ecc18c6b1d6cf84b3105b2f007 Mon Sep 17 00:00:00 2001 From: "David M. Lee" Date: Fri, 4 Sep 2015 16:33:39 -0500 Subject: res_rtp_asterisk: Add more ICE debugging In working through a recent ICE negotiation bug, I found the debug logging in res_rtp_asterisk to be lacking. This patch adds a number of debug and warning statements that were helpful. Change-Id: I950c6d8f13a41f14b3d6334b4cafe7d4e997be80 --- res/res_rtp_asterisk.c | 50 +++++++++++++++++++++++++++++++++++++++++--------- 1 file changed, 41 insertions(+), 9 deletions(-) (limited to 'res/res_rtp_asterisk.c') diff --git a/res/res_rtp_asterisk.c b/res/res_rtp_asterisk.c index adbec8297..371c01df4 100644 --- a/res/res_rtp_asterisk.c +++ b/res/res_rtp_asterisk.c @@ -590,12 +590,16 @@ static int ice_reset_session(struct ast_rtp_instance *instance) pj_ice_sess_role role = rtp->ice->role; int res; + ast_debug(3, "Resetting ICE for RTP instance '%p'\n", instance); if (!rtp->ice->is_nominating && !rtp->ice->is_complete) { + ast_debug(3, "Nevermind. ICE isn't ready for a reset\n"); return 0; } + ast_debug(3, "Stopping ICE for RTP instance '%p'\n", instance); ast_rtp_ice_stop(instance); + ast_debug(3, "Recreating ICE session %s (%d) for RTP instance '%p'\n", ast_sockaddr_stringify(&rtp->ice_original_rtp_addr), rtp->ice_port, instance); res = ice_create(instance, &rtp->ice_original_rtp_addr, rtp->ice_port, 1); if (!res) { /* Preserve the role that the old ICE session used */ @@ -648,6 +652,7 @@ static void ast_rtp_ice_start(struct ast_rtp_instance *instance) /* Check for equivalence in the lists */ if (rtp->ice_active_remote_candidates && !ice_candidates_compare(rtp->ice_proposed_remote_candidates, rtp->ice_active_remote_candidates)) { + ast_debug(3, "Proposed == active candidates for RTP instance '%p'\n", instance); ao2_cleanup(rtp->ice_proposed_remote_candidates); rtp->ice_proposed_remote_candidates = NULL; return; @@ -694,8 +699,10 @@ static void ast_rtp_ice_start(struct ast_rtp_instance *instance) } if (candidate->id == AST_RTP_ICE_COMPONENT_RTP && rtp->turn_rtp) { + ast_debug(3, "RTP candidate %s (%p)\n", ast_sockaddr_stringify(&candidate->address), instance); pj_turn_sock_set_perm(rtp->turn_rtp, 1, &candidates[cand_cnt].addr, 1); } else if (candidate->id == AST_RTP_ICE_COMPONENT_RTCP && rtp->turn_rtcp) { + ast_debug(3, "RTCP candidate %s (%p)\n", ast_sockaddr_stringify(&candidate->address), instance); pj_turn_sock_set_perm(rtp->turn_rtcp, 1, &candidates[cand_cnt].addr, 1); } @@ -705,20 +712,40 @@ static void ast_rtp_ice_start(struct ast_rtp_instance *instance) ao2_iterator_destroy(&i); - if (has_rtp && has_rtcp && - pj_ice_sess_create_check_list(rtp->ice, &ufrag, &passwd, cand_cnt, &candidates[0]) == PJ_SUCCESS) { - ast_test_suite_event_notify("ICECHECKLISTCREATE", "Result: SUCCESS"); - pj_ice_sess_start_check(rtp->ice); - pj_timer_heap_poll(timer_heap, NULL); - rtp->strict_rtp_state = STRICT_RTP_OPEN; - return; + if (cand_cnt < ao2_container_count(rtp->ice_active_remote_candidates)) { + ast_log(LOG_WARNING, "Lost %d ICE candidates. Consider increasing PJ_ICE_MAX_CAND in PJSIP (%p)\n", + ao2_container_count(rtp->ice_active_remote_candidates) - cand_cnt, instance); + } + + if (!has_rtp) { + ast_log(LOG_WARNING, "No RTP candidates; skipping ICE checklist (%p)\n", instance); + } + + if (!has_rtcp) { + ast_log(LOG_WARNING, "No RTCP candidates; skipping ICE checklist (%p)\n", instance); + } + + if (has_rtp && has_rtcp) { + pj_status_t res = pj_ice_sess_create_check_list(rtp->ice, &ufrag, &passwd, cand_cnt, &candidates[0]); + char reason[80]; + + if (res == PJ_SUCCESS) { + ast_debug(3, "Successfully created ICE checklist (%p)\n", instance); + ast_test_suite_event_notify("ICECHECKLISTCREATE", "Result: SUCCESS"); + pj_ice_sess_start_check(rtp->ice); + pj_timer_heap_poll(timer_heap, NULL); + rtp->strict_rtp_state = STRICT_RTP_OPEN; + return; + } + + pj_strerror(res, reason, sizeof(reason)); + ast_log(LOG_WARNING, "Failed to create ICE session check list: %s (%p)\n", reason, instance); } ast_test_suite_event_notify("ICECHECKLISTCREATE", "Result: FAILURE"); /* even though create check list failed don't stop ice as it might still work */ - ast_debug(1, "Failed to create ICE session check list\n"); /* however we do need to reset remote candidates since this function may be re-entered */ ao2_ref(rtp->ice_active_remote_candidates, -1); @@ -768,7 +795,11 @@ static void ast_rtp_ice_set_role(struct ast_rtp_instance *instance, enum ast_rtp { struct ast_rtp *rtp = ast_rtp_instance_get_data(instance); + ast_debug(3, "Set role to %s (%p)\n", + role == AST_RTP_ICE_ROLE_CONTROLLED ? "CONTROLLED" : "CONTROLLING", instance); + if (!rtp->ice) { + ast_log(LOG_WARNING, "Set role failed; no ice instance (%p)\n", instance); return; } @@ -2484,7 +2515,7 @@ static int ast_rtp_new(struct ast_rtp_instance *instance, create_new_socket("RTP", ast_sockaddr_is_ipv4(addr) ? AF_INET : ast_sockaddr_is_ipv6(addr) ? AF_INET6 : -1)) < 0) { - ast_debug(1, "Failed to create a new socket for RTP instance '%p'\n", instance); + ast_log(LOG_WARNING, "Failed to create a new socket for RTP instance '%p'\n", instance); ast_free(rtp); return -1; } @@ -2525,6 +2556,7 @@ static int ast_rtp_new(struct ast_rtp_instance *instance, #ifdef HAVE_PJPROJECT /* Create an ICE session for ICE negotiation */ if (icesupport) { + ast_debug(3, "Creating ICE session %s (%d) for RTP instance '%p'\n", ast_sockaddr_stringify(addr), x, instance); if (ice_create(instance, addr, x, 0)) { ast_log(LOG_NOTICE, "Failed to start ICE session\n"); } else { -- cgit v1.2.3