FS-8547 #resolve [Add error log into stats to log when quality impacting events begin...

diff --git a/src/include/switch_types.h b/src/include/switch_types.h
index f9479cec80261260048a7e00a1b7d7f010b1947f..2d574a2be41d0c0053f2bf2a5aad642182e18569 100644 (file)
--- a/src/include/switch_types.h
+++ b/src/include/switch_types.h
@@ -595,6 +595,14 @@ typedef enum {
 } switch_vad_flag_enum_t;
 typedef uint32_t switch_vad_flag_t;
 
+
+typedef struct error_period {
+       int64_t start;
+       int64_t stop;
+       struct error_period *next;
+} switch_error_period_t;
+
+
 typedef struct {
        switch_size_t raw_bytes;
        switch_size_t media_bytes;
@@ -630,6 +638,7 @@ typedef struct {
        switch_size_t last_flaw;
        double R;
        double mos;
+       struct error_period *error_log;
 } switch_rtp_numbers_t;
 
 typedef struct {

diff --git a/src/switch_ivr.c b/src/switch_ivr.c
index 6b601e80f91c5b3bae159d17401da6adc75ba968..e05848e2ddd3e1ea4228ba4bf3cf9c4a9a139f36 100644 (file)
--- a/src/switch_ivr.c
+++ b/src/switch_ivr.c
@@ -2261,6 +2261,105 @@ SWITCH_DECLARE(int) switch_ivr_set_xml_profile_data(switch_xml_t xml, switch_cal
        return off;
 }
 
+
+#define add_stat(_x, _i, _s)                                                                                   \
+       switch_snprintf(var_val, sizeof(var_val), "%" SWITCH_SIZE_T_FMT, _i); \
+       x_tmp = switch_xml_add_child_d(_x, _s, loff++);                                         \
+       switch_xml_set_txt_d(x_tmp, var_val)
+
+#define add_stat_double(_x, _i, _s)                                                                            \
+       switch_snprintf(var_val, sizeof(var_val), "%0.2f", _i);                         \
+       x_tmp = switch_xml_add_child_d(_x, _s, loff++);                                         \
+       switch_xml_set_txt_d(x_tmp, var_val)
+
+SWITCH_DECLARE(int) switch_ivr_set_xml_call_stats(switch_xml_t xml, switch_core_session_t *session, int off, switch_media_type_t type)
+{
+       const char *name = (type == SWITCH_MEDIA_TYPE_VIDEO) ? "video" : "audio";
+       switch_xml_t x_stat, x_in, x_out, x_tmp = NULL;
+       int loff = 0;
+       switch_rtp_stats_t *stats = switch_core_media_get_stats(session, type, NULL);
+       char var_val[35] = "";
+
+       if (!stats) return off;
+
+       if (!(x_stat = switch_xml_add_child_d(xml, name, off++))) {
+               abort();
+       }
+
+       if (!(x_in = switch_xml_add_child_d(x_stat, "inbound", off++))) {
+               abort();
+       }
+
+       if (!(x_out = switch_xml_add_child_d(x_stat, "outbound", off++))) {
+               abort();
+       }
+
+       stats->inbound.std_deviation = sqrt(stats->inbound.variance);
+
+       add_stat(x_in, stats->inbound.raw_bytes, "raw_bytes");
+       add_stat(x_in, stats->inbound.media_bytes, "media_bytes");
+       add_stat(x_in, stats->inbound.packet_count, "packet_count");
+       add_stat(x_in, stats->inbound.media_packet_count, "media_packet_count");
+       add_stat(x_in, stats->inbound.skip_packet_count, "skip_packet_count");
+       add_stat(x_in, stats->inbound.jb_packet_count, "jitter_packet_count");
+       add_stat(x_in, stats->inbound.dtmf_packet_count, "dtmf_packet_count");
+       add_stat(x_in, stats->inbound.cng_packet_count, "cng_packet_count");
+       add_stat(x_in, stats->inbound.flush_packet_count, "flush_packet_count");
+       add_stat(x_in, stats->inbound.largest_jb_size, "largest_jb_size");
+       add_stat_double(x_in, stats->inbound.min_variance, "jitter_min_variance");
+       add_stat_double(x_in, stats->inbound.max_variance, "jitter_max_variance");
+       add_stat_double(x_in, stats->inbound.lossrate, "jitter_loss_rate");
+       add_stat_double(x_in, stats->inbound.burstrate, "jitter_burst_rate");
+       add_stat_double(x_in, stats->inbound.mean_interval, "mean_interval");
+       add_stat(x_in, stats->inbound.flaws, "flaw_total");
+       add_stat_double(x_in, stats->inbound.R, "quality_percentage");
+       add_stat_double(x_in, stats->inbound.mos, "mos");
+       
+
+       if (stats->inbound.error_log) {
+               switch_xml_t x_err_log, x_err;
+               switch_error_period_t *ep;
+               int eoff = 0;
+
+               if (!(x_err_log = switch_xml_add_child_d(x_stat, "error-log", off++))) {
+                       abort();
+               }
+               
+               for(ep = stats->inbound.error_log; ep; ep = ep->next) {
+
+                       if (!(ep->start && ep->stop)) continue;
+
+                       if (!(x_err = switch_xml_add_child_d(x_err_log, "error-period", eoff++))) {
+                               abort();
+                       }
+
+                       switch_snprintf(var_val, sizeof(var_val), "%" SWITCH_TIME_T_FMT, ep->start);
+                       x_tmp = switch_xml_add_child_d(x_err, "start", 0);
+                       switch_xml_set_txt_d(x_tmp, var_val);
+
+                       switch_snprintf(var_val, sizeof(var_val), "%" SWITCH_TIME_T_FMT, ep->stop);
+                       x_tmp = switch_xml_add_child_d(x_err, "stop", 1);
+                       switch_xml_set_txt_d(x_tmp, var_val);
+
+                       switch_snprintf(var_val, sizeof(var_val), "%" SWITCH_TIME_T_FMT, (ep->stop - ep->start) / 1000);
+                       x_tmp = switch_xml_add_child_d(x_err, "duration-msec", 2);
+                       switch_xml_set_txt_d(x_tmp, var_val);
+               }
+       }
+
+       add_stat(x_out, stats->outbound.raw_bytes, "raw_bytes");
+       add_stat(x_out, stats->outbound.media_bytes, "media_bytes");
+       add_stat(x_out, stats->outbound.packet_count, "packet_count");
+       add_stat(x_out, stats->outbound.media_packet_count, "media_packet_count");
+       add_stat(x_out, stats->outbound.skip_packet_count, "skip_packet_count");
+       add_stat(x_out, stats->outbound.dtmf_packet_count, "dtmf_packet_count");
+       add_stat(x_out, stats->outbound.cng_packet_count, "cng_packet_count");
+       add_stat(x_out, stats->rtcp.packet_count, "rtcp_packet_count");
+       add_stat(x_out, stats->rtcp.octet_count, "rtcp_octet_count");
+       
+       return off;
+}
+
 static int switch_ivr_set_xml_chan_var(switch_xml_t xml, const char *var, const char *val, int off)
 {
        char *data;
@@ -2355,6 +2454,13 @@ SWITCH_DECLARE(switch_status_t) switch_ivr_generate_xml_cdr(switch_core_session_
                free(f);
        }
 
+       if (!(variables = switch_xml_add_child_d(cdr, "call-stats", cdr_off++))) {
+               goto error;
+       }
+
+       switch_ivr_set_xml_call_stats(variables, session, v_off, SWITCH_MEDIA_TYPE_AUDIO);
+       switch_ivr_set_xml_call_stats(variables, session, v_off, SWITCH_MEDIA_TYPE_VIDEO);
+
 
        if (!(variables = switch_xml_add_child_d(cdr, "variables", cdr_off++))) {
                goto error;
@@ -2659,6 +2765,80 @@ static void switch_ivr_set_json_profile_data(cJSON *json, switch_caller_profile_
        cJSON_AddItemToObject(json, "chan_name", cJSON_CreateString(caller_profile->chan_name));
 }
 
+#define add_jstat(_j, _i, _s)                                                                                  \
+       switch_snprintf(var_val, sizeof(var_val), "%" SWITCH_SIZE_T_FMT, _i); \
+       cJSON_AddItemToObject(_j, _s, cJSON_CreateNumber(_i))                           
+
+SWITCH_DECLARE(void) switch_ivr_set_json_call_stats(cJSON *json, switch_core_session_t *session, switch_media_type_t type)
+{
+       const char *name = (type == SWITCH_MEDIA_TYPE_VIDEO) ? "video" : "audio";
+       cJSON *j_stat, *j_in, *j_out;
+       switch_rtp_stats_t *stats = switch_core_media_get_stats(session, type, NULL);
+       char var_val[35] = "";
+
+       if (!stats) return;
+
+       j_stat = cJSON_CreateObject();
+       j_in = cJSON_CreateObject();
+       j_out = cJSON_CreateObject();
+
+       cJSON_AddItemToObject(json, name, j_stat);
+       cJSON_AddItemToObject(j_stat, "inbound", j_in);
+       cJSON_AddItemToObject(j_stat, "outbound", j_out);
+
+       stats->inbound.std_deviation = sqrt(stats->inbound.variance);
+
+       add_jstat(j_in, stats->inbound.raw_bytes, "raw_bytes");
+       add_jstat(j_in, stats->inbound.media_bytes, "media_bytes");
+       add_jstat(j_in, stats->inbound.packet_count, "packet_count");
+       add_jstat(j_in, stats->inbound.media_packet_count, "media_packet_count");
+       add_jstat(j_in, stats->inbound.skip_packet_count, "skip_packet_count");
+       add_jstat(j_in, stats->inbound.jb_packet_count, "jitter_packet_count");
+       add_jstat(j_in, stats->inbound.dtmf_packet_count, "dtmf_packet_count");
+       add_jstat(j_in, stats->inbound.cng_packet_count, "cng_packet_count");
+       add_jstat(j_in, stats->inbound.flush_packet_count, "flush_packet_count");
+       add_jstat(j_in, stats->inbound.largest_jb_size, "largest_jb_size");
+       add_jstat(j_in, stats->inbound.min_variance, "jitter_min_variance");
+       add_jstat(j_in, stats->inbound.max_variance, "jitter_max_variance");
+       add_jstat(j_in, stats->inbound.lossrate, "jitter_loss_rate");
+       add_jstat(j_in, stats->inbound.burstrate, "jitter_burst_rate");
+       add_jstat(j_in, stats->inbound.mean_interval, "mean_interval");
+       add_jstat(j_in, stats->inbound.flaws, "flaw_total");
+       add_jstat(j_in, stats->inbound.R, "quality_percentage");
+       add_jstat(j_in, stats->inbound.mos, "mos");
+       
+
+       if (stats->inbound.error_log) {
+               cJSON *j_err_log, *j_err;
+               switch_error_period_t *ep;
+
+               j_err_log = cJSON_CreateArray();
+               cJSON_AddItemToObject(j_in, "errorLog", j_err_log);
+
+               for(ep = stats->inbound.error_log; ep; ep = ep->next) {
+
+                       if (!(ep->start && ep->stop)) continue;
+
+                       j_err = cJSON_CreateObject();
+
+                       cJSON_AddItemToObject(j_err, "start", cJSON_CreateNumber(ep->start));
+                       cJSON_AddItemToObject(j_err, "stop", cJSON_CreateNumber(ep->stop));
+                       cJSON_AddItemToObject(j_err, "durationMS", cJSON_CreateNumber((ep->stop - ep->start) / 1000));
+                       cJSON_AddItemToArray(j_err_log, j_err);
+               }
+       }
+
+       add_jstat(j_out, stats->outbound.raw_bytes, "raw_bytes");
+       add_jstat(j_out, stats->outbound.media_bytes, "media_bytes");
+       add_jstat(j_out, stats->outbound.packet_count, "packet_count");
+       add_jstat(j_out, stats->outbound.media_packet_count, "media_packet_count");
+       add_jstat(j_out, stats->outbound.skip_packet_count, "skip_packet_count");
+       add_jstat(j_out, stats->outbound.dtmf_packet_count, "dtmf_packet_count");
+       add_jstat(j_out, stats->outbound.cng_packet_count, "cng_packet_count");
+       add_jstat(j_out, stats->rtcp.packet_count, "rtcp_packet_count");
+       add_jstat(j_out, stats->rtcp.octet_count, "rtcp_octet_count");
+}
+
 static void switch_ivr_set_json_chan_vars(cJSON *json, switch_channel_t *channel, switch_bool_t urlencode)
 {
        switch_event_header_t *hi = switch_channel_variable_first(channel);
@@ -2696,7 +2876,7 @@ SWITCH_DECLARE(switch_status_t) switch_ivr_generate_json_cdr(switch_core_session
        switch_channel_t *channel = switch_core_session_get_channel(session);
        switch_caller_profile_t *caller_profile;
        cJSON *variables, *j_main_cp, *j_caller_profile, *j_caller_extension, *j_caller_extension_apps, *j_times, *j_application,
-               *j_callflow, *j_profile, *j_inner_extension, *j_app_log, *j_apps, *j_o, *j_o_profiles, *j_channel_data;
+               *j_callflow, *j_profile, *j_inner_extension, *j_app_log, *j_apps, *j_o, *j_o_profiles, *j_channel_data, *callStats;
        switch_app_log_t *app_log;
        char tmp[512], *f;
 
@@ -2722,9 +2902,13 @@ SWITCH_DECLARE(switch_status_t) switch_ivr_generate_json_cdr(switch_core_session
                free(f);
        }
 
+       callStats = cJSON_CreateObject();
+       cJSON_AddItemToObject(cdr, "callStats", callStats);
+       switch_ivr_set_json_call_stats(callStats, session, SWITCH_MEDIA_TYPE_AUDIO);
+       switch_ivr_set_json_call_stats(callStats, session, SWITCH_MEDIA_TYPE_VIDEO);
+
        variables = cJSON_CreateObject();
        cJSON_AddItemToObject(cdr, "variables", variables);
-
        switch_ivr_set_json_chan_vars(variables, channel, urlencode);
 
 

diff --git a/src/switch_rtp.c b/src/switch_rtp.c
index dc7c77cbebd2d45ef3cfee2b09bff94ee360b822..677bd00c537e7ab6492082f51a4dcaa26dfcbc12 100644 (file)
--- a/src/switch_rtp.c
+++ b/src/switch_rtp.c
@@ -397,6 +397,10 @@ struct switch_rtp {
        uint32_t cng_count;
        switch_rtp_bug_flag_t rtp_bugs;
        switch_rtp_stats_t stats;
+       uint32_t clean_stream;
+       uint32_t bad_stream;
+       uint32_t recovering_stream;
+
        uint32_t hot_hits;
        uint32_t sync_packets;
        int rtcp_interval;
@@ -1659,7 +1663,7 @@ static void do_mos(switch_rtp_t *rtp_session, int force) {
                        switch_log_printf(SWITCH_CHANNEL_SESSION_LOG(rtp_session->session), SWITCH_LOG_DEBUG1, "%s %s %d consecutive flaws, adding %d flaw penalty\n", 
                                                          rtp_session_name(rtp_session), rtp_type(rtp_session), 
                                                          rtp_session->consecutive_flaws, penalty);
-
+                       rtp_session->bad_stream++;
                        rtp_session->stats.inbound.flaws += penalty;
                }
 
@@ -1758,12 +1762,12 @@ static void check_jitter(switch_rtp_t *rtp_session)
                        rtp_session->stats.inbound.loss[rtp_session->stats.inbound.last_loss] += lost;
                }
 
+               rtp_session->bad_stream++;
                rtp_session->stats.inbound.flaws += lost;
-               
        } else {
                rtp_session->stats.inbound.last_loss = 0;
        }
-           
+       
        rtp_session->stats.inbound.last_processed_seq = seq;
 
        /* Burst and Packet Loss */
@@ -1776,7 +1780,32 @@ static void check_jitter(switch_rtp_t *rtp_session)
        } else {
                do_mos(rtp_session, SWITCH_FALSE);
        }
-               
+       
+       if (rtp_session->stats.inbound.last_loss || rtp_session->bad_stream) {
+               if (rtp_session->session && (!rtp_session->stats.inbound.error_log || rtp_session->stats.inbound.error_log->stop)) {
+                       struct error_period *error = switch_core_session_alloc(rtp_session->session, sizeof(*error));
+                       error->start = switch_micro_time_now();
+                       error->next = rtp_session->stats.inbound.error_log;
+                       rtp_session->stats.inbound.error_log = error;
+               }
+
+               if (!rtp_session->stats.inbound.last_loss) {
+                       if (++rtp_session->recovering_stream > (rtp_session->one_second * 3)) {
+                               if (rtp_session->session && rtp_session->stats.inbound.error_log) {
+                                       rtp_session->stats.inbound.error_log->stop = switch_micro_time_now();
+                               }
+
+                               rtp_session->bad_stream = 0;
+                       }
+               } else {
+                       rtp_session->recovering_stream = 0;
+                       rtp_session->bad_stream++;
+               }
+       } else {
+               rtp_session->recovering_stream = 0;
+               rtp_session->clean_stream++;
+       }
+       
 
        if ( diff_time < 0 ) {
                diff_time = -diff_time;
@@ -4170,6 +4199,10 @@ SWITCH_DECLARE(void) switch_rtp_destroy(switch_rtp_t **rtp_session)
 
        do_mos(*rtp_session, SWITCH_TRUE);
 
+       if ((*rtp_session)->stats.inbound.error_log && !(*rtp_session)->stats.inbound.error_log->stop) {
+               (*rtp_session)->stats.inbound.error_log->stop = switch_micro_time_now();
+       }
+
        switch_mutex_lock((*rtp_session)->flag_mutex);
 
        switch_rtp_kill_socket(*rtp_session);
@@ -5479,6 +5512,7 @@ static int rtp_common_read(switch_rtp_t *rtp_session, switch_payload_t *payload_
                                                                                 rtp_session_name(rtp_session),
                                                                                  rtp_session->sync_packets, rtp_type(rtp_session));
 
+                                               rtp_session->bad_stream++;
                                                rtp_session->stats.inbound.flaws += rtp_session->sync_packets;
                                        }