rtc_tools/rtc_event_log_visualizer/alerts.cc

/*
 *  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_util.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