From 104c0b3fec793d414c4fdd6a18996fe9af4c0051 Mon Sep 17 00:00:00 2001 From: Jakub Karolczyk Date: Fri, 29 Sep 2023 08:21:15 +0000 Subject: [PATCH 1/6] [core] Fix flopping routes on ICE negotiation --- src/include/switch_rtp.h | 2 + src/switch_rtp.c | 335 +++++++++++++++++++++++++++++---------- 2 files changed, 251 insertions(+), 86 deletions(-) diff --git a/src/include/switch_rtp.h b/src/include/switch_rtp.h index dfcad5453c..7986bdb622 100644 --- a/src/include/switch_rtp.h +++ b/src/include/switch_rtp.h @@ -103,6 +103,8 @@ typedef struct icand_s { switch_port_t rport; char *generation; uint8_t ready; + uint8_t responsive; + uint8_t use_candidate; } icand_t; #define MAX_CAND 50 diff --git a/src/switch_rtp.c b/src/switch_rtp.c index 506085d86d..5ddf12ec3c 100644 --- a/src/switch_rtp.c +++ b/src/switch_rtp.c @@ -254,10 +254,11 @@ typedef struct { uint8_t sending; uint8_t ready; uint8_t rready; - uint8_t init; + uint8_t initializing; int missed_count; char last_sent_id[13]; switch_time_t last_ok; + uint8_t cand_responsive; } switch_rtp_ice_t; struct switch_rtp; @@ -401,7 +402,6 @@ struct switch_rtp { char *eff_remote_host_str; switch_time_t first_stun; switch_time_t last_stun; - uint32_t wrong_addrs; uint32_t samples_per_interval; uint32_t samples_per_second; uint32_t conf_samples_per_interval; @@ -474,7 +474,11 @@ struct switch_rtp { payload_map_t *pmap_tail; kalman_estimator_t *estimators[KALMAN_SYSTEM_MODELS]; cusum_kalman_detector_t *detectors[KALMAN_SYSTEM_MODELS]; - int ice_adj; + switch_time_t last_adj; + switch_time_t adj_window; + uint32_t elapsed_stun; + uint32_t elapsed_media; + uint32_t elapsed_adj; uint8_t has_rtp; uint8_t has_rtcp; uint8_t has_ice; @@ -540,9 +544,25 @@ static void switch_rtp_change_ice_dest(switch_rtp_t *rtp_session, switch_rtp_ice { int is_rtcp = ice == &rtp_session->rtcp_ice; const char *err = ""; + int i; + uint8_t ice_cand_found_idx = 0; + + for (i = 0; i < ice->ice_params->cand_idx[ice->proto]; i++) { + if (!strcmp(host, ice->ice_params->cands[i][ice->proto].con_addr) && port == ice->ice_params->cands[i][ice->proto].con_port) { + ice_cand_found_idx = i; + } + } + + if (!ice_cand_found_idx) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "ICE candidate [%s:%d] replaced with [%s:%d]\n", + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, host, port); + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr = switch_core_strdup(rtp_session->pool, host); + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port = port; + } else { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "ICE chosen candidate [%s:%d] set to idx [%d]\n", host, port, ice_cand_found_idx); + ice->ice_params->chosen[ice->proto] = ice_cand_found_idx; + } - ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr = switch_core_strdup(rtp_session->pool, host); - ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port = port; ice->missed_count = 0; if (is_rtcp) { @@ -796,7 +816,41 @@ static int rtp_common_write(switch_rtp_t *rtp_session, rtp_msg_t *send_msg, void *data, uint32_t datalen, switch_payload_t payload, uint32_t timestamp, switch_frame_flag_t *flags); -static switch_status_t ice_out(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice) +#define MEDIA_TOO_LONG 2000 +#define STUN_TOO_LONG 20000 +#define ADJ_TOO_LONG 1000 + +static void calc_elapsed(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice) +{ + switch_time_t ref_point; + switch_time_t now; + + now = switch_micro_time_now(); + + if (ice->last_ok && (!rtp_session->dtls || rtp_session->dtls->state == DS_READY)) { + ref_point = ice->last_ok; + } else { + ref_point = rtp_session->first_stun; + } + + if (!ref_point) ref_point = now; + + rtp_session->elapsed_stun = (unsigned int) ((now - ref_point) / 1000); + + if (rtp_session->last_media) { + rtp_session->elapsed_media = (unsigned int) ((now - rtp_session->last_media) / 1000); + } else { + rtp_session->elapsed_media = MEDIA_TOO_LONG + 1; + } + + if (rtp_session->last_adj) { + rtp_session->elapsed_adj = (unsigned int) ((now - rtp_session->last_adj) / 1000); + } else { + rtp_session->elapsed_adj = ADJ_TOO_LONG + 1; + } +} + +static switch_status_t ice_out(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, switch_bool_t force) { uint8_t buf[256] = { 0 }; switch_stun_packet_t *packet; @@ -812,7 +866,7 @@ static switch_status_t ice_out(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice) return SWITCH_STATUS_BREAK; } - if (ice->next_run && ice->next_run > now) { + if (!force && ice->next_run && ice->next_run >= now) { return SWITCH_STATUS_BREAK; } @@ -907,8 +961,19 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d int ok = 1; uint32_t *pri = NULL; int is_rtcp = ice == &rtp_session->rtcp_ice; - uint32_t elapsed; - switch_time_t ref_point; + switch_channel_t *channel; + int i; + switch_sockaddr_t *from_addr = rtp_session->from_addr; + const char *from_host = NULL; + switch_port_t from_port = 0; + char faddr_buf[80] = ""; + + if (is_rtcp) { + from_addr = rtp_session->rtcp_from_addr; + } + + from_host = switch_get_addr(faddr_buf, sizeof(faddr_buf), from_addr); + from_port = switch_sockaddr_get_port(from_addr); //if (rtp_session->flags[SWITCH_RTP_FLAG_VIDEO]) { // switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_WARNING, "WTF OK %s CALL\n", rtp_type(rtp_session)); @@ -931,6 +996,7 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d cpylen = sizeof(buf); } + channel = switch_core_session_get_channel(rtp_session->session); memcpy(buf, data, cpylen); packet = switch_stun_packet_parse(buf, (uint32_t)cpylen); @@ -946,14 +1012,7 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d rtp_session->first_stun = rtp_session->last_stun; } - if (ice->last_ok && (!rtp_session->dtls || rtp_session->dtls->state == DS_READY)) { - ref_point = ice->last_ok; - } else { - ref_point = rtp_session->first_stun; - } - - elapsed = (unsigned int) ((switch_micro_time_now() - ref_point) / 1000); - + calc_elapsed(rtp_session, ice); end_buf = buf + ((sizeof(buf) > packet->header.length) ? packet->header.length : sizeof(buf)); @@ -968,6 +1027,12 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d case SWITCH_STUN_ATTR_USE_CAND: { ice->rready = 1; + for (i = 0; i < ice->ice_params->cand_idx[ice->proto]; i++) { + if (!strcmp(ice->ice_params->cands[i][ice->proto].con_addr, from_host) && ice->ice_params->cands[i][ice->proto].con_port == from_port) { + ice->ice_params->cands[i][ice->proto].use_candidate = 1; + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG6, "Got USE-CANDIDATE on %s:%d\n", ice->ice_params->cands[i][ice->proto].con_addr, ice->ice_params->cands[i][ice->proto].con_port); + } + } } break; case SWITCH_STUN_ATTR_ERROR_CODE: @@ -1048,18 +1113,33 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d if (packet->header.type == SWITCH_STUN_BINDING_RESPONSE) { ok = 1; - if (!ice->rready) { - if (rtp_session->flags[SWITCH_RTP_FLAG_RTCP_MUX]) { - rtp_session->ice.rready = 1; - rtp_session->rtcp_ice.rready = 1; - } else { - ice->rready = 1; - } - if (rtp_session->flags[SWITCH_RTP_FLAG_VIDEO]) { - switch_core_session_video_reinit(rtp_session->session); + if (rtp_session->flags[SWITCH_RTP_FLAG_RTCP_MUX]) { + rtp_session->ice.rready = 1; + rtp_session->rtcp_ice.rready = 1; + } else { + ice->rready = 1; + } + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG6, "Received STUN Binding Response from %s\n", from_host); + + if (ice->ice_params) { + for (i = 0; i < ice->ice_params->cand_idx[ice->proto]; i++) { + if (!strcmp(ice->ice_params->cands[i][ice->proto].con_addr, from_host) && ice->ice_params->cands[i][ice->proto].con_port == from_port) { + ice->ice_params->cands[i][ice->proto].responsive = 1; + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "Marked ICE candidate %s:%d as responsive\n", ice->ice_params->cands[i][ice->proto].con_addr, ice->ice_params->cands[i][ice->proto].con_port); + if (!strcmp(ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, from_host) && ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port == from_port) { + ice->cand_responsive = 1; + ice->initializing = 0; + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "Chosen ICE candidate %s:%d is responsive\n", ice->ice_params->cands[i][ice->proto].con_addr, ice->ice_params->cands[i][ice->proto].con_port); + } + } } } + + if (rtp_session->flags[SWITCH_RTP_FLAG_VIDEO]) { + switch_core_session_video_reinit(rtp_session->session); + } } if (!ok && ice == &rtp_session->ice && rtp_session->rtcp_ice.ice_params && pri && @@ -1084,7 +1164,7 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d switch_port_t port = 0; char *host = NULL; - if (elapsed > 20000 && pri) { + if (rtp_session->elapsed_stun > STUN_TOO_LONG && pri) { int i, j; uint32_t old; //const char *tx_host; @@ -1176,6 +1256,7 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_WARNING, "missed too many: %d, looking for new ICE dest.\n", ice->missed_count); ice->rready = 0; + ice->cand_responsive = 0; ok = 1; } @@ -1185,9 +1266,8 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d //} if (ok) { - const char *host = NULL, *host2 = NULL; - switch_port_t port = 0, port2 = 0; - char buf[80] = ""; + const char *host2 = NULL; + switch_port_t port2 = 0; char buf2[80] = ""; if (packet->header.type == SWITCH_STUN_BINDING_REQUEST) { @@ -1196,16 +1276,13 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d const char *remote_ip; switch_size_t bytes; char ipbuf[50]; - switch_sockaddr_t *from_addr = rtp_session->from_addr; switch_socket_t *sock_output = rtp_session->sock_output; uint8_t do_adj = 0; switch_time_t now = switch_micro_time_now(); int cmp = 0; - int cur_idx = -1;//, is_relay = 0; - int i; - + int cur_idx = -1, is_relay = 0, is_responsive = 0, use_candidate = 0; + if (is_rtcp) { - from_addr = rtp_session->rtcp_from_addr; sock_output = rtp_session->rtcp_sock_output; } @@ -1231,58 +1308,123 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d bytes = switch_stun_packet_length(rpacket); - host = switch_get_addr(buf, sizeof(buf), from_addr); - port = switch_sockaddr_get_port(from_addr); host2 = switch_get_addr(buf2, sizeof(buf2), ice->addr); port2 = switch_sockaddr_get_port(ice->addr); cmp = switch_cmp_addr(from_addr, ice->addr, SWITCH_FALSE); - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG2, - "STUN from %s:%d %s\n", host, port, cmp ? "EXPECTED" : "IGNORED"); + for (i = 0; i < ice->ice_params->cand_idx[ice->proto]; i++) { + if (!strcmp(ice->ice_params->cands[i][ice->proto].con_addr, from_host) && ice->ice_params->cands[i][ice->proto].con_port == from_port) { + if (!strcasecmp(ice->ice_params->cands[i][ice->proto].cand_type, "relay")) { + is_relay = 1; + } - if (ice->init && !cmp && switch_cmp_addr(from_addr, ice->addr, SWITCH_TRUE)) { - do_adj++; - rtp_session->ice_adj++; - rtp_session->wrong_addrs = 0; - ice->init = 0; - } - - if (cmp) { - ice->last_ok = now; - rtp_session->wrong_addrs = 0; - } else { - switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG10, "ICE %d dt:%d i:%d i2:%d w:%d cmp:%d adj:%d\n", elapsed, (rtp_session->dtls && rtp_session->dtls->state != DS_READY), !ice->ready, !ice->rready, rtp_session->wrong_addrs, switch_cmp_addr(from_addr, ice->addr, SWITCH_TRUE), rtp_session->ice_adj); + if (ice->ice_params->cands[i][ice->proto].responsive) { + is_responsive = 1; + } - if ((rtp_session->dtls && rtp_session->dtls->state != DS_READY) || - ((!ice->ready || !ice->rready) && (rtp_session->wrong_addrs > 2 || switch_cmp_addr(from_addr, ice->addr, SWITCH_TRUE)) && - rtp_session->ice_adj < 10)) { - do_adj++; - rtp_session->ice_adj++; - rtp_session->wrong_addrs = 0; - } else if (rtp_session->wrong_addrs > 10 || elapsed >= 5000) { - do_adj++; - } - - if (!do_adj) { - rtp_session->wrong_addrs++; - } - - for (i = 0; i < ice->ice_params->cand_idx[ice->proto]; i++) { - if (!strcmp(ice->ice_params->cands[i][ice->proto].con_addr, host)) { - cur_idx = i; - //if (!strcasecmp(ice->ice_params->cands[i][ice->proto].cand_type, "relay")) { - // is_relay = 1; - //} + if (ice->ice_params->cands[i][ice->proto].use_candidate) { + use_candidate = 1; } } - - - if (ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type && - !strcasecmp(ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type, "relay")) { + } + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, + "%s %s STUN from %s:%d %s is_relay: %d is_responsive: %d use_candidate: %d ready: %d, rready: %d\n", switch_channel_get_name(channel), rtp_type(rtp_session), from_host, from_port, cmp ? "EXPECTED" : "IGNORED", + is_relay, is_responsive, use_candidate, ice->ready, ice->rready); + + if (ice->initializing && !cmp) { + if (!rtp_session->adj_window && (!ice->ready || !ice->rready || (!rtp_session->dtls || rtp_session->dtls->state != DS_READY))) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE set ADJUST window to 10 seconds on binding request from %s:%d (is_relay: %d, is_responsivie: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + rtp_session->adj_window = now + 10000000; + } + + if (rtp_session->adj_window) { + if (rtp_session->adj_window > now) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE check: %d >= 3000 or window closed and not from relay on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", rtp_session->elapsed_stun, from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + if (!is_relay && (rtp_session->elapsed_stun >= 3000 || rtp_session->adj_window == (now + 10000000))) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE ADJUST HIT 1 on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + do_adj++; + rtp_session->last_adj = now; + } + } else { + rtp_session->adj_window = 0; + } + } + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE CHECK SAME IP DIFFT PORT %d %d on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp",ice->initializing, switch_cmp_addr(from_addr, ice->addr, SWITCH_TRUE), from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + if (!do_adj && (switch_cmp_addr(from_addr, ice->addr, SWITCH_TRUE) || use_candidate)) { do_adj++; + rtp_session->last_adj = now; + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE ADJUST HIT 2 on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); } } - + + if (cmp) { + ice->last_ok = now; + } else if (!do_adj) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "ICE %d/%d dt:%d i:%d i2:%d cmp:%d\n", rtp_session->elapsed_stun, rtp_session->elapsed_media, (rtp_session->dtls && rtp_session->dtls->state != DS_READY), !ice->ready, !ice->rready, switch_cmp_addr(from_addr, ice->addr, SWITCH_TRUE)); + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE ADJUST ELAPSED vs 1000 %d on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp" ,rtp_session->elapsed_adj, from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + if (rtp_session->elapsed_adj > 1000) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE IF DTLS NOT READY or %d >= 3000 or media too long %d or stun too long %d on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", rtp_session->elapsed_stun, rtp_session->elapsed_media >= MEDIA_TOO_LONG, + rtp_session->elapsed_stun >= STUN_TOO_LONG, from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + if (!is_relay && ((rtp_session->dtls && rtp_session->dtls->state != DS_READY) || + ((!ice->ready || !ice->rready) && (rtp_session->elapsed_stun >= 3000 || switch_cmp_addr(from_addr, ice->addr, SWITCH_TRUE))))) { + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE ADJUST HIT 3 on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + do_adj++; + rtp_session->last_adj = now; + } else if (is_relay && ice->initializing && rtp_session->elapsed_stun >= 1000) { + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE ADJUST HIT 4 (FLIP TO TURN) on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + do_adj++; + rtp_session->last_adj = now; + } else if ((ice->initializing && rtp_session->elapsed_stun >= 3000) || + (rtp_session->elapsed_media >= MEDIA_TOO_LONG || rtp_session->elapsed_stun >= STUN_TOO_LONG)) { + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "%s %s %s ICE ADJUST HIT 5 on binding request from %s:%d (is_relay: %d, is_responsive: %d, use_candidate: %d) Current cand: %s:%d typ: %s\n", + switch_channel_get_name(channel), rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", from_host, from_port, is_relay, is_responsive, use_candidate, + ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_addr, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].con_port, ice->ice_params->cands[ice->ice_params->chosen[ice->proto]][ice->proto].cand_type); + + do_adj++; + rtp_session->last_adj = now; + } + + for (i = 0; i < ice->ice_params->cand_idx[ice->proto]; i++) { + if (!strcmp(ice->ice_params->cands[i][ice->proto].con_addr, from_host)) { + cur_idx = i; + } + } + } + } + if ((ice->type & ICE_VANILLA) && ice->ice_params && do_adj) { ice->missed_count = 0; ice->rready = 1; @@ -1294,15 +1436,29 @@ static void handle_ice(switch_rtp_t *rtp_session, switch_rtp_ice_t *ice, void *d switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_NOTICE, "Auto Changing %s stun/%s/dtls port from %s:%u to %s:%u idx:%d\n", rtp_type(rtp_session), is_rtcp ? "rtcp" : "rtp", host2, port2, - host, port, cur_idx); + from_host, from_port, cur_idx); + + switch_rtp_change_ice_dest(rtp_session, ice, from_host, from_port); + + ice->cand_responsive = is_responsive; + if (ice->cand_responsive) { + ice->initializing = 0; + } - switch_rtp_change_ice_dest(rtp_session, ice, host, port); ice->last_ok = now; - rtp_session->wrong_addrs = 0; } //if (cmp) { switch_socket_sendto(sock_output, from_addr, 0, (void *) rpacket, &bytes); //} + + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG6, "Send STUN Binding Response to %s:%u\n", from_host, from_port); + + if (ice->initializing && !is_responsive) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG5, "Send STUN Binding Request on ICE candidate still unresponsive to %s:%u\n", from_host, from_port); + if (ice_out(rtp_session, ice, SWITCH_TRUE) != SWITCH_STATUS_SUCCESS) { + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_WARNING, "Error sending STUN Binding Request on ICE candidate still unresponsive to %s:%u\n", from_host, from_port); + } + } } } else if (packet->header.type == SWITCH_STUN_BINDING_ERROR_RESPONSE) { @@ -2358,7 +2514,7 @@ static int check_rtcp_and_ice(switch_rtp_t *rtp_session) } if (rtp_session->ice.ice_user) { - if (ice_out(rtp_session, &rtp_session->ice) == SWITCH_STATUS_GENERR) { + if (ice_out(rtp_session, &rtp_session->ice, SWITCH_FALSE) == SWITCH_STATUS_GENERR) { ret = -1; goto end; } @@ -2366,7 +2522,7 @@ static int check_rtcp_and_ice(switch_rtp_t *rtp_session) if (!rtp_session->flags[SWITCH_RTP_FLAG_RTCP_MUX]) { if (rtp_session->rtcp_ice.ice_user) { - if (ice_out(rtp_session, &rtp_session->rtcp_ice) == SWITCH_STATUS_GENERR) { + if (ice_out(rtp_session, &rtp_session->rtcp_ice, SWITCH_FALSE) == SWITCH_STATUS_GENERR) { ret = -1; goto end; } @@ -2852,10 +3008,9 @@ SWITCH_DECLARE(void) switch_rtp_reset(switch_rtp_t *rtp_session) memset(&rtp_session->ts_norm, 0, sizeof(rtp_session->ts_norm)); rtp_session->last_stun = rtp_session->first_stun = 0; - rtp_session->wrong_addrs = 0; rtp_session->rtcp_sent_packets = 0; rtp_session->rtcp_last_sent = 0; - rtp_session->ice_adj = 0; + rtp_session->last_adj = 0; //switch_rtp_del_dtls(rtp_session, DTLS_TYPE_RTP|DTLS_TYPE_RTCP); switch_rtp_set_flag(rtp_session, SWITCH_RTP_FLAG_PAUSE); @@ -2865,6 +3020,7 @@ SWITCH_DECLARE(void) switch_rtp_reset(switch_rtp_t *rtp_session) if (rtp_session->ice.ready) { switch_rtp_reset_vb(rtp_session); rtp_session->ice.ready = rtp_session->ice.rready = 0; + rtp_session->ice.cand_responsive = 0; } } @@ -3210,13 +3366,18 @@ static int do_dtls(switch_rtp_t *rtp_session, switch_dtls_t *dtls) int r = 0, ret = 0, len; switch_size_t bytes; unsigned char buf[MAX_DTLS_MTU] = ""; - int ready = rtp_session->ice.ice_user ? (rtp_session->ice.rready && rtp_session->ice.ready) : 1; + uint8_t is_ice = rtp_session->ice.ice_user ? 1 : 0; + int ready = is_ice ? (rtp_session->ice.rready && rtp_session->ice.ready) : 1; int pending; if (!dtls->bytes && !ready) { return 0; } + if (is_ice && !rtp_session->ice.cand_responsive) { + return 0; + } + if (dtls->bytes > 0 && dtls->data) { ret = BIO_write(dtls->read_bio, dtls->data, (int)dtls->bytes); if (ret <= 0) { @@ -4764,11 +4925,13 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_activate_ice(switch_rtp_t *rtp_sessio switch_snprintf(user_ice, sizeof(user_ice), "%s:%s", rlogin, login); switch_snprintf(luser_ice, sizeof(luser_ice), "%s%s", rlogin, login); ice->ready = ice->rready = 0; + ice->cand_responsive = 0; } else { switch_snprintf(ice_user, sizeof(ice_user), "%s%s", login, rlogin); switch_snprintf(user_ice, sizeof(user_ice), "%s%s", rlogin, login); switch_snprintf(luser_ice, sizeof(luser_ice), ""); ice->ready = ice->rready = 1; + ice->cand_responsive = 0; } ice->ice_user = switch_core_strdup(rtp_session->pool, ice_user); @@ -4779,7 +4942,7 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_activate_ice(switch_rtp_t *rtp_sessio ice->pass = ""; ice->rpass = ""; ice->next_run = switch_micro_time_now(); - ice->init = 1; + ice->initializing = 1; if (password) { ice->pass = switch_core_strdup(rtp_session->pool, password); @@ -5725,7 +5888,7 @@ static switch_status_t read_rtp_packet(switch_rtp_t *rtp_session, switch_size_t /* version 2 probably rtp */ rtp_session->has_rtp = (rtp_session->recv_msg.header.version == 2); - if (rtp_session->media_timeout) { + if (rtp_session->media_timeout || rtp_session->ice.ice_user) { rtp_session->last_media = switch_micro_time_now(); } From f05b7507aa28c1a320d839d5c65a72210050dc4d Mon Sep 17 00:00:00 2001 From: Arun Raghavan Date: Thu, 12 Oct 2023 15:42:23 -0400 Subject: [PATCH 2/6] [mod_conference] Avoid a race in member->read_impl access The conference output loop accesses the member's read_impl while resampling. The output loop also spawns off the input loop thread, which is where the member->read_impl is actually initialised. This results in an uncommon race where the output loop sometimes gets an uninitialised member->read_impl and bails with logs something like this: 2023-10-12 18:19:01.436844 [DEBUG] conference_loop.c:1340 Setup timer soft success interval: 20 samples: 960 from codec L16 2023-10-12 18:19:01.436844 [DEBUG] conference_loop.c:1497 Outbound conference channel answered, setting CFLAG_ANSWERED 2023-10-12 18:19:01.436844 [NOTICE] switch_core_media.c:15852 Activating write resampler 2023-10-12 18:19:01.436844 [DEBUG] switch_core_media.c:16097 Engaging Write Buffer at 1920 bytes to accommodate 0->1920 2023-10-12 18:19:01.436844 [ERR] switch_core_media.c:16112 Write Buffer 0 bytes Failed! As a solution, we initialise the member->read_impl even before we start up the input loop, so that this race can never happen. --- src/mod/applications/mod_conference/conference_loop.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/mod/applications/mod_conference/conference_loop.c b/src/mod/applications/mod_conference/conference_loop.c index 8f112f5453..f9b7894d0e 100644 --- a/src/mod/applications/mod_conference/conference_loop.c +++ b/src/mod/applications/mod_conference/conference_loop.c @@ -1316,15 +1316,15 @@ void conference_loop_output(conference_member_t *member) uint32_t flush_len; uint32_t low_count, bytes; call_list_t *call_list, *cp; - switch_codec_implementation_t read_impl = { 0 }, real_read_impl = { 0 }; + switch_codec_implementation_t real_read_impl = { 0 }; int sanity; - switch_core_session_get_read_impl(member->session, &read_impl); + switch_core_session_get_read_impl(member->session, &member->read_impl); switch_core_session_get_real_read_impl(member->session, &real_read_impl); channel = switch_core_session_get_channel(member->session); - interval = read_impl.microseconds_per_packet / 1000; + interval = member->read_impl.microseconds_per_packet / 1000; samples = switch_samples_per_packet(member->conference->rate, interval); //csamples = samples; tsamples = real_read_impl.samples_per_packet; From f7e19e513466e2e489eeebce7a0b72d7c786cad7 Mon Sep 17 00:00:00 2001 From: Andrey Volk Date: Mon, 11 Dec 2023 22:48:00 +0300 Subject: [PATCH 3/6] [mod_sofia] BYE Reason header was limited in length. --- src/mod/endpoints/mod_sofia/mod_sofia.c | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/mod/endpoints/mod_sofia/mod_sofia.c b/src/mod/endpoints/mod_sofia/mod_sofia.c index f58bb40ac0..458be3f875 100644 --- a/src/mod/endpoints/mod_sofia/mod_sofia.c +++ b/src/mod/endpoints/mod_sofia/mod_sofia.c @@ -488,7 +488,7 @@ switch_status_t sofia_on_hangup(switch_core_session_t *session) if (sofia_test_pflag(tech_pvt->profile, PFLAG_DESTROY)) { sofia_set_flag(tech_pvt, TFLAG_BYE); } else if (tech_pvt->nh && !sofia_test_flag(tech_pvt, TFLAG_BYE)) { - char reason[128] = ""; + char *reason = switch_core_session_sprintf(session, ""); char *bye_headers = sofia_glue_get_extra_headers(channel, SOFIA_SIP_BYE_HEADER_PREFIX); const char *val = NULL; const char *max_forwards = switch_channel_get_variable(channel, SWITCH_MAX_FORWARDS_VARIABLE); @@ -499,15 +499,15 @@ switch_status_t sofia_on_hangup(switch_core_session_t *session) if (!val || switch_false(val)) { if ((val = switch_channel_get_variable(tech_pvt->channel, "sip_reason"))) { - switch_snprintf(reason, sizeof(reason), "%s", val); + reason = switch_core_session_sprintf(session, "%s", val); } else { if ((switch_channel_test_flag(channel, CF_INTERCEPT) || cause == SWITCH_CAUSE_PICKED_OFF || cause == SWITCH_CAUSE_LOSE_RACE) && !switch_true(switch_channel_get_variable(channel, "ignore_completed_elsewhere"))) { - switch_snprintf(reason, sizeof(reason), "SIP;cause=200;text=\"Call completed elsewhere\""); + reason = switch_core_session_sprintf(session, "SIP;cause=200;text=\"Call completed elsewhere\""); } else if (cause > 0 && cause < 128) { - switch_snprintf(reason, sizeof(reason), "Q.850;cause=%d;text=\"%s\"", cause, switch_channel_cause2str(cause)); + reason = switch_core_session_sprintf(session, "Q.850;cause=%d;text=\"%s\"", cause, switch_channel_cause2str(cause)); } else { - switch_snprintf(reason, sizeof(reason), "SIP;cause=%d;text=\"%s\"", cause, switch_channel_cause2str(cause)); + reason = switch_core_session_sprintf(session, "SIP;cause=%d;text=\"%s\"", cause, switch_channel_cause2str(cause)); } } } From 48608177d73c9797f9b98a322dcec153bf20b78d Mon Sep 17 00:00:00 2001 From: Jakub Karolczyk Date: Tue, 12 Dec 2023 10:03:11 +0000 Subject: [PATCH 4/6] [core] Fix missing 192 key lengths --- src/switch_rtp.c | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/src/switch_rtp.c b/src/switch_rtp.c index 5ddf12ec3c..5d58e07aad 100644 --- a/src/switch_rtp.c +++ b/src/switch_rtp.c @@ -4219,6 +4219,20 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_add_crypto_key(switch_rtp_t *rtp_sess switch_channel_set_variable(channel, "rtp_has_crypto", "AES_CM_256_HMAC_SHA1_32"); } break; + case AES_CM_192_HMAC_SHA1_80: + srtp_crypto_policy_set_aes_cm_192_hmac_sha1_80(&policy->rtp); + srtp_crypto_policy_set_aes_cm_192_hmac_sha1_80(&policy->rtcp); + if (switch_channel_direction(channel) == SWITCH_CALL_DIRECTION_OUTBOUND) { + switch_channel_set_variable(channel, "rtp_has_crypto", "AES_CM_192_HMAC_SHA1_80"); + } + break; + case AES_CM_192_HMAC_SHA1_32: + srtp_crypto_policy_set_aes_cm_192_hmac_sha1_32(&policy->rtp); + srtp_crypto_policy_set_aes_cm_192_hmac_sha1_32(&policy->rtcp); + if (switch_channel_direction(channel) == SWITCH_CALL_DIRECTION_OUTBOUND) { + switch_channel_set_variable(channel, "rtp_has_crypto", "AES_CM_192_HMAC_SHA1_32"); + } + break; case AES_CM_128_NULL_AUTH: srtp_crypto_policy_set_aes_cm_128_null_auth(&policy->rtp); srtp_crypto_policy_set_aes_cm_128_null_auth(&policy->rtcp); @@ -4228,6 +4242,7 @@ SWITCH_DECLARE(switch_status_t) switch_rtp_add_crypto_key(switch_rtp_t *rtp_sess } break; default: + switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_ERROR, "Missing crypto type!\n"); break; } From c155ea70082ea5a23e4badf757f842ecf6b6c142 Mon Sep 17 00:00:00 2001 From: Andrey Volk Date: Thu, 14 Dec 2023 13:43:33 +0300 Subject: [PATCH 5/6] [Core] Fix implicit conversion from enumeration type 'switch_odbc_status_t' to different enumeration type 'switch_status_t'. --- src/switch_core_sqldb.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/switch_core_sqldb.c b/src/switch_core_sqldb.c index 817a7a7586..165c9bd8b1 100644 --- a/src/switch_core_sqldb.c +++ b/src/switch_core_sqldb.c @@ -702,7 +702,7 @@ static switch_status_t switch_cache_db_execute_sql_real(switch_cache_db_handle_t case SCDB_TYPE_ODBC: { type = "ODBC"; - status = switch_odbc_handle_exec(dbh->native_handle.odbc_dbh, sql, NULL, &errmsg); + status = switch_odbc_handle_exec(dbh->native_handle.odbc_dbh, sql, NULL, &errmsg) == SWITCH_ODBC_SUCCESS ? SWITCH_STATUS_SUCCESS : SWITCH_STATUS_FALSE; } break; case SCDB_TYPE_CORE_DB: @@ -904,7 +904,7 @@ SWITCH_DECLARE(char *) switch_cache_db_execute_sql2str(switch_cache_db_handle_t break; case SCDB_TYPE_ODBC: { - status = switch_odbc_handle_exec_string(dbh->native_handle.odbc_dbh, sql, str, len, err); + status = switch_odbc_handle_exec_string(dbh->native_handle.odbc_dbh, sql, str, len, err) == SWITCH_ODBC_SUCCESS ? SWITCH_STATUS_SUCCESS : SWITCH_STATUS_FALSE; } break; case SCDB_TYPE_DATABASE_INTERFACE: @@ -1189,7 +1189,7 @@ SWITCH_DECLARE(switch_status_t) switch_cache_db_execute_sql_event_callback(switc break; case SCDB_TYPE_ODBC: { - status = switch_odbc_handle_callback_exec(dbh->native_handle.odbc_dbh, sql, helper_callback, &h, err); + status = switch_odbc_handle_callback_exec(dbh->native_handle.odbc_dbh, sql, helper_callback, &h, err) == SWITCH_ODBC_SUCCESS ? SWITCH_STATUS_SUCCESS : SWITCH_STATUS_FALSE; } break; case SCDB_TYPE_CORE_DB: @@ -1248,7 +1248,7 @@ SWITCH_DECLARE(switch_status_t) switch_cache_db_execute_sql_event_callback_err(s break; case SCDB_TYPE_ODBC: { - status = switch_odbc_handle_callback_exec(dbh->native_handle.odbc_dbh, sql, helper_callback, &h, err); + status = switch_odbc_handle_callback_exec(dbh->native_handle.odbc_dbh, sql, helper_callback, &h, err) == SWITCH_ODBC_SUCCESS ? SWITCH_STATUS_SUCCESS : SWITCH_STATUS_FALSE; if (err && *err) { (*err_callback)(pdata, (const char*)*err); } @@ -1305,7 +1305,7 @@ SWITCH_DECLARE(switch_status_t) switch_cache_db_execute_sql_callback(switch_cach break; case SCDB_TYPE_ODBC: { - status = switch_odbc_handle_callback_exec(dbh->native_handle.odbc_dbh, sql, callback, pdata, err); + status = switch_odbc_handle_callback_exec(dbh->native_handle.odbc_dbh, sql, callback, pdata, err) == SWITCH_ODBC_SUCCESS ? SWITCH_STATUS_SUCCESS : SWITCH_STATUS_FALSE; } break; case SCDB_TYPE_CORE_DB: @@ -1358,7 +1358,7 @@ SWITCH_DECLARE(switch_status_t) switch_cache_db_execute_sql_callback_err(switch_ break; case SCDB_TYPE_ODBC: { - status = switch_odbc_handle_callback_exec(dbh->native_handle.odbc_dbh, sql, callback, pdata, err); + status = switch_odbc_handle_callback_exec(dbh->native_handle.odbc_dbh, sql, callback, pdata, err) == SWITCH_ODBC_SUCCESS ? SWITCH_STATUS_SUCCESS : SWITCH_STATUS_FALSE; if (err && *err) { (*err_callback)(pdata, (const char*)*err); } From 2e7424169e7f39ba644f498769ca6b92c4951b4c Mon Sep 17 00:00:00 2001 From: Andrey Volk Date: Tue, 19 Dec 2023 22:42:54 +0300 Subject: [PATCH 6/6] [mod_conference] Remove static from cJSON vars in conference_jlist --- src/mod/applications/mod_conference/mod_conference.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/mod/applications/mod_conference/mod_conference.c b/src/mod/applications/mod_conference/mod_conference.c index bf03d2a5bc..aa606170d5 100644 --- a/src/mod/applications/mod_conference/mod_conference.c +++ b/src/mod/applications/mod_conference/mod_conference.c @@ -1363,7 +1363,7 @@ void conference_xlist(conference_obj_t *conference, switch_xml_t x_conference, i void conference_jlist(conference_obj_t *conference, cJSON *json_conferences) { conference_member_t *member = NULL; - static cJSON *json_conference, *json_conference_variables, *json_conference_members, *json_conference_member, *json_conference_member_flags; + cJSON *json_conference, *json_conference_variables, *json_conference_members, *json_conference_member, *json_conference_member_flags; switch_event_header_t *hp; switch_assert(conference != NULL);