1 files changed, 236 insertions, 0 deletions
diff --git a/third_party/libwebrtc/rtc_tools/rtc_event_log_visualizer/alerts.cc b/third_party/libwebrtc/rtc_tools/rtc_event_log_visualizer/alerts.cc
new file mode 100644
index 0000000000..a9f50cdd5c
--- /dev/null
+++ b/third_party/libwebrtc/rtc_tools/rtc_event_log_visualizer/alerts.cc
@@ -0,0 +1,236 @@
+/*
+ *  Copyright (c) 2020 The WebRTC project authors. All Rights Reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#include "rtc_tools/rtc_event_log_visualizer/alerts.h"
+
+#include <stdio.h>
+
+#include <algorithm>
+#include <limits>
+#include <map>
+#include <string>
+
+#include "logging/rtc_event_log/rtc_event_processor.h"
+#include "rtc_base/checks.h"
+#include "rtc_base/logging.h"
+#include "rtc_base/numerics/sequence_number_unwrapper.h"
+#include "rtc_base/strings/string_builder.h"
+
+namespace webrtc {
+
+void TriageHelper::AnalyzeStreamGaps(const ParsedRtcEventLog& parsed_log,
+                                     PacketDirection direction) {
+  // With 100 packets/s (~800kbps), false positives would require 10 s without
+  // data.
+  constexpr int64_t kMaxSeqNumJump = 1000;
+  // With a 90 kHz clock, false positives would require 10 s without data.
+  constexpr int64_t kTicksPerMillisec = 90;
+  constexpr int64_t kCaptureTimeGraceMs = 10000;
+
+  std::string seq_num_explanation =
+      direction == kIncomingPacket
+          ? "Incoming RTP sequence number jumps more than 1000. Counter may "
+            "have been reset or rewritten incorrectly in a group call."
+          : "Outgoing RTP sequence number jumps more than 1000. Counter may "
+            "have been reset.";
+  std::string capture_time_explanation =
+      direction == kIncomingPacket ? "Incoming capture time jumps more than "
+                                     "10s. Clock might have been reset."
+                                   : "Outgoing capture time jumps more than "
+                                     "10s. Clock might have been reset.";
+  TriageAlertType seq_num_alert = direction == kIncomingPacket
+                                      ? TriageAlertType::kIncomingSeqNumJump
+                                      : TriageAlertType::kOutgoingSeqNumJump;
+  TriageAlertType capture_time_alert =
+      direction == kIncomingPacket ? TriageAlertType::kIncomingCaptureTimeJump
+                                   : TriageAlertType::kOutgoingCaptureTimeJump;
+
+  const int64_t segment_end_us = parsed_log.first_log_segment().stop_time_us();
+
+  // Check for gaps in sequence numbers and capture timestamps.
+  for (const auto& stream : parsed_log.rtp_packets_by_ssrc(direction)) {
+    if (IsRtxSsrc(parsed_log, direction, stream.ssrc)) {
+      continue;
+    }
+    auto packets = stream.packet_view;
+    if (packets.empty()) {
+      continue;
+    }
+    SeqNumUnwrapper<uint16_t> seq_num_unwrapper;
+    int64_t last_seq_num =
+        seq_num_unwrapper.Unwrap(packets[0].header.sequenceNumber);
+    SeqNumUnwrapper<uint32_t> capture_time_unwrapper;
+    int64_t last_capture_time =
+        capture_time_unwrapper.Unwrap(packets[0].header.timestamp);
+    int64_t last_log_time_ms = packets[0].log_time_ms();
+    for (const auto& packet : packets) {
+      if (packet.log_time_us() > segment_end_us) {
+        // Only process the first (LOG_START, LOG_END) segment.
+        break;
+      }
+
+      int64_t seq_num = seq_num_unwrapper.Unwrap(packet.header.sequenceNumber);
+      if (std::abs(seq_num - last_seq_num) > kMaxSeqNumJump) {
+        Alert(seq_num_alert, config_.GetCallTimeSec(packet.log_time()),
+              seq_num_explanation);
+      }
+      last_seq_num = seq_num;
+
+      int64_t capture_time =
+          capture_time_unwrapper.Unwrap(packet.header.timestamp);
+      if (std::abs(capture_time - last_capture_time) >
+          kTicksPerMillisec *
+              (kCaptureTimeGraceMs + packet.log_time_ms() - last_log_time_ms)) {
+        Alert(capture_time_alert, config_.GetCallTimeSec(packet.log_time()),
+              capture_time_explanation);
+      }
+      last_capture_time = capture_time;
+    }
+  }
+}
+
+void TriageHelper::AnalyzeTransmissionGaps(const ParsedRtcEventLog& parsed_log,
+                                           PacketDirection direction) {
+  constexpr int64_t kMaxRtpTransmissionGap = 500000;
+  constexpr int64_t kMaxRtcpTransmissionGap = 3000000;
+  std::string rtp_explanation =
+      direction == kIncomingPacket
+          ? "No RTP packets received for more than 500ms. This indicates a "
+            "network problem. Temporary video freezes and choppy or robotic "
+            "audio is unavoidable. Unnecessary BWE drops is a known issue."
+          : "No RTP packets sent for more than 500 ms. This might be an issue "
+            "with the pacer.";
+  std::string rtcp_explanation =
+      direction == kIncomingPacket
+          ? "No RTCP packets received for more than 3 s. Could be a longer "
+            "connection outage"
+          : "No RTCP packets sent for more than 3 s. This is most likely a "
+            "bug.";
+  TriageAlertType rtp_alert = direction == kIncomingPacket
+                                  ? TriageAlertType::kIncomingRtpGap
+                                  : TriageAlertType::kOutgoingRtpGap;
+  TriageAlertType rtcp_alert = direction == kIncomingPacket
+                                   ? TriageAlertType::kIncomingRtcpGap
+                                   : TriageAlertType::kOutgoingRtcpGap;
+
+  const int64_t segment_end_us = parsed_log.first_log_segment().stop_time_us();
+
+  // TODO(terelius): The parser could provide a list of all packets, ordered
+  // by time, for each direction.
+  std::multimap<int64_t, const LoggedRtpPacket*> rtp_in_direction;
+  for (const auto& stream : parsed_log.rtp_packets_by_ssrc(direction)) {
+    for (const LoggedRtpPacket& rtp_packet : stream.packet_view)
+      rtp_in_direction.emplace(rtp_packet.log_time_us(), &rtp_packet);
+  }
+  absl::optional<int64_t> last_rtp_time;
+  for (const auto& kv : rtp_in_direction) {
+    int64_t timestamp = kv.first;
+    if (timestamp > segment_end_us) {
+      // Only process the first (LOG_START, LOG_END) segment.
+      break;
+    }
+    int64_t duration = timestamp - last_rtp_time.value_or(0);
+    if (last_rtp_time.has_value() && duration > kMaxRtpTransmissionGap) {
+      // No packet sent/received for more than 500 ms.
+      Alert(rtp_alert, config_.GetCallTimeSec(Timestamp::Micros(timestamp)),
+            rtp_explanation);
+    }
+    last_rtp_time.emplace(timestamp);
+  }
+
+  absl::optional<int64_t> last_rtcp_time;
+  if (direction == kIncomingPacket) {
+    for (const auto& rtcp : parsed_log.incoming_rtcp_packets()) {
+      if (rtcp.log_time_us() > segment_end_us) {
+        // Only process the first (LOG_START, LOG_END) segment.
+        break;
+      }
+      int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
+      if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
+        // No feedback sent/received for more than 2000 ms.
+        Alert(rtcp_alert, config_.GetCallTimeSec(rtcp.log_time()),
+              rtcp_explanation);
+      }
+      last_rtcp_time.emplace(rtcp.log_time_us());
+    }
+  } else {
+    for (const auto& rtcp : parsed_log.outgoing_rtcp_packets()) {
+      if (rtcp.log_time_us() > segment_end_us) {
+        // Only process the first (LOG_START, LOG_END) segment.
+        break;
+      }
+      int64_t duration = rtcp.log_time_us() - last_rtcp_time.value_or(0);
+      if (last_rtcp_time.has_value() && duration > kMaxRtcpTransmissionGap) {
+        // No feedback sent/received for more than 2000 ms.
+        Alert(rtcp_alert, config_.GetCallTimeSec(rtcp.log_time()),
+              rtcp_explanation);
+      }
+      last_rtcp_time.emplace(rtcp.log_time_us());
+    }
+  }
+}
+
+// TODO(terelius): Notifications could possibly be generated by the same code
+// that produces the graphs. There is some code duplication that could be
+// avoided, but that might be solved anyway when we move functionality from the
+// analyzer to the parser.
+void TriageHelper::AnalyzeLog(const ParsedRtcEventLog& parsed_log) {
+  AnalyzeStreamGaps(parsed_log, kIncomingPacket);
+  AnalyzeStreamGaps(parsed_log, kOutgoingPacket);
+  AnalyzeTransmissionGaps(parsed_log, kIncomingPacket);
+  AnalyzeTransmissionGaps(parsed_log, kOutgoingPacket);
+
+  const int64_t segment_end_us = parsed_log.first_log_segment().stop_time_us();
+
+  Timestamp first_occurrence = parsed_log.last_timestamp();
+  constexpr double kMaxLossFraction = 0.05;
+  // Loss feedback
+  int64_t total_lost_packets = 0;
+  int64_t total_expected_packets = 0;
+  for (auto& bwe_update : parsed_log.bwe_loss_updates()) {
+    if (bwe_update.log_time_us() > segment_end_us) {
+      // Only process the first (LOG_START, LOG_END) segment.
+      break;
+    }
+    int64_t lost_packets = static_cast<double>(bwe_update.fraction_lost) / 255 *
+                           bwe_update.expected_packets;
+    total_lost_packets += lost_packets;
+    total_expected_packets += bwe_update.expected_packets;
+    if (bwe_update.fraction_lost >= 255 * kMaxLossFraction) {
+      first_occurrence = std::min(first_occurrence, bwe_update.log_time());
+    }
+  }
+  double avg_outgoing_loss =
+      static_cast<double>(total_lost_packets) / total_expected_packets;
+  if (avg_outgoing_loss > kMaxLossFraction) {
+    Alert(TriageAlertType::kOutgoingHighLoss,
+          config_.GetCallTimeSec(first_occurrence),
+          "More than 5% of outgoing packets lost.");
+  }
+}
+
+void TriageHelper::Print(FILE* file) {
+  fprintf(file, "========== TRIAGE NOTIFICATIONS ==========\n");
+  for (const auto& alert : triage_alerts_) {
+    fprintf(file, "%d %s. First occurrence at %3.3lf\n", alert.second.count,
+            alert.second.explanation.c_str(), alert.second.first_occurrence);
+  }
+  fprintf(file, "========== END TRIAGE NOTIFICATIONS ==========\n");
+}
+
+void TriageHelper::ProcessAlerts(
+    std::function<void(int, float, std::string)> f) {
+  for (const auto& alert : triage_alerts_) {
+    f(alert.second.count, alert.second.first_occurrence,
+      alert.second.explanation);
+  }
+}
+
+}  // namespace webrtc