Log DTLS writable changes to RtcEventLog

Bug: webrtc:9972
Change-Id: I8d29dcbc200bd0aad7f4c2600459c4d344c61bbb
Reviewed-on: https://webrtc-review.googlesource.com/c/111453
Reviewed-by: Qingsi Wang <qingsi@webrtc.org>
Reviewed-by: Elad Alon <eladalon@webrtc.org>
Reviewed-by: Björn Terelius <terelius@webrtc.org>
Commit-Queue: Zach Stein <zstein@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#25866}

logging/BUILD.gn

@@ -402,6 +402,8 @@ rtc_source_set("ice_log") {
   sources = [
     "rtc_event_log/events/rtc_event_dtls_transport_state.cc",
     "rtc_event_log/events/rtc_event_dtls_transport_state.h",
+    "rtc_event_log/events/rtc_event_dtls_writable_state.cc",
+    "rtc_event_log/events/rtc_event_dtls_writable_state.h",
     "rtc_event_log/events/rtc_event_ice_candidate_pair.cc",
     "rtc_event_log/events/rtc_event_ice_candidate_pair.h",
     "rtc_event_log/events/rtc_event_ice_candidate_pair_config.cc",

logging/rtc_event_log/encoder/rtc_event_log_encoder_legacy.cc

@@ -301,6 +301,10 @@ std::string RtcEventLogEncoderLegacy::Encode(const RtcEvent& event) {
       return "";
     }
 
+    case RtcEvent::Type::DtlsWritableState: {
+      return "";
+    }
+
     case RtcEvent::Type::IceCandidatePairConfig: {
       auto& rtc_event =
           static_cast<const RtcEventIceCandidatePairConfig&>(event);

logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc

@@ -23,6 +23,7 @@
 #include "logging/rtc_event_log/events/rtc_event_bwe_update_delay_based.h"
 #include "logging/rtc_event_log/events/rtc_event_bwe_update_loss_based.h"
 #include "logging/rtc_event_log/events/rtc_event_dtls_transport_state.h"
+#include "logging/rtc_event_log/events/rtc_event_dtls_writable_state.h"
 #include "logging/rtc_event_log/events/rtc_event_ice_candidate_pair.h"
 #include "logging/rtc_event_log/events/rtc_event_ice_candidate_pair_config.h"
 #include "logging/rtc_event_log/events/rtc_event_probe_cluster_created.h"
@@ -670,6 +671,7 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch(
     std::vector<const RtcEventBweUpdateDelayBased*> bwe_delay_based_updates;
     std::vector<const RtcEventBweUpdateLossBased*> bwe_loss_based_updates;
     std::vector<const RtcEventDtlsTransportState*> dtls_transport_states;
+    std::vector<const RtcEventDtlsWritableState*> dtls_writable_states;
     std::vector<const RtcEventProbeClusterCreated*>
         probe_cluster_created_events;
     std::vector<const RtcEventProbeResultFailure*> probe_result_failure_events;
@@ -739,6 +741,12 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch(
           dtls_transport_states.push_back(rtc_event);
           break;
         }
+        case RtcEvent::Type::DtlsWritableState: {
+          auto* rtc_event =
+              static_cast<const RtcEventDtlsWritableState* const>(it->get());
+          dtls_writable_states.push_back(rtc_event);
+          break;
+        }
         case RtcEvent::Type::ProbeClusterCreated: {
           auto* rtc_event =
               static_cast<const RtcEventProbeClusterCreated* const>(it->get());
@@ -822,6 +830,7 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch(
     EncodeBweUpdateDelayBased(bwe_delay_based_updates, &event_stream);
     EncodeBweUpdateLossBased(bwe_loss_based_updates, &event_stream);
     EncodeDtlsTransportState(dtls_transport_states, &event_stream);
+    EncodeDtlsWritableState(dtls_writable_states, &event_stream);
     EncodeProbeClusterCreated(probe_cluster_created_events, &event_stream);
     EncodeProbeResultFailure(probe_result_failure_events, &event_stream);
     EncodeProbeResultSuccess(probe_result_success_events, &event_stream);
@@ -1213,6 +1222,17 @@ void RtcEventLogEncoderNewFormat::EncodeDtlsTransportState(
   }
 }
 
+void RtcEventLogEncoderNewFormat::EncodeDtlsWritableState(
+    rtc::ArrayView<const RtcEventDtlsWritableState*> batch,
+    rtclog2::EventStream* event_stream) {
+  for (const RtcEventDtlsWritableState* base_event : batch) {
+    rtclog2::DtlsWritableState* proto_batch =
+        event_stream->add_dtls_writable_states();
+    proto_batch->set_timestamp_ms(base_event->timestamp_ms());
+    proto_batch->set_writable(base_event->writable());
+  }
+}
+
 void RtcEventLogEncoderNewFormat::EncodeProbeClusterCreated(
     rtc::ArrayView<const RtcEventProbeClusterCreated*> batch,
     rtclog2::EventStream* event_stream) {

logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.h

@@ -34,6 +34,7 @@ class RtcEventAudioSendStreamConfig;
 class RtcEventBweUpdateDelayBased;
 class RtcEventBweUpdateLossBased;
 class RtcEventDtlsTransportState;
+class RtcEventDtlsWritableState;
 class RtcEventLoggingStarted;
 class RtcEventLoggingStopped;
 class RtcEventProbeClusterCreated;
@@ -85,6 +86,9 @@ class RtcEventLogEncoderNewFormat final : public RtcEventLogEncoder {
   void EncodeDtlsTransportState(
       rtc::ArrayView<const RtcEventDtlsTransportState*> batch,
       rtclog2::EventStream* event_stream);
+  void EncodeDtlsWritableState(
+      rtc::ArrayView<const RtcEventDtlsWritableState*> batch,
+      rtclog2::EventStream* event_stream);
   void EncodeLoggingStarted(rtc::ArrayView<const RtcEventLoggingStarted*> batch,
                             rtclog2::EventStream* event_stream);
   void EncodeLoggingStopped(rtc::ArrayView<const RtcEventLoggingStopped*> batch,

logging/rtc_event_log/encoder/rtc_event_log_encoder_unittest.cc

@@ -490,6 +490,33 @@ TEST_P(RtcEventLogEncoderTest, RtcEventDtlsTransportState) {
   }
 }
 
+TEST_P(RtcEventLogEncoderTest, RtcEventDtlsWritableState) {
+  std::vector<std::unique_ptr<RtcEventDtlsWritableState>> events(event_count_);
+  for (size_t i = 0; i < event_count_; ++i) {
+    events[i] = (i == 0 || !force_repeated_fields_)
+                    ? gen_.NewDtlsWritableState()
+                    : events[0]->Copy();
+    history_.push_back(events[i]->Copy());
+  }
+
+  const std::string encoded =
+      encoder_->EncodeBatch(history_.begin(), history_.end());
+  ASSERT_TRUE(parsed_log_.ParseString(encoded));
+
+  const auto& dtls_writable_states = parsed_log_.dtls_writable_states();
+  if (!new_encoding_) {
+    ASSERT_EQ(dtls_writable_states.size(), 0u);
+    return;
+  }
+
+  ASSERT_EQ(dtls_writable_states.size(), event_count_);
+
+  for (size_t i = 0; i < event_count_; ++i) {
+    verifier_.VerifyLoggedDtlsWritableState(*events[i],
+                                            dtls_writable_states[i]);
+  }
+}
+
 // TODO(eladalon/terelius): Test with multiple events in the batch.
 TEST_P(RtcEventLogEncoderTest, RtcEventIceCandidatePairConfig) {
   std::unique_ptr<RtcEventIceCandidatePairConfig> event =

logging/rtc_event_log/events/rtc_event.h

@@ -38,6 +38,7 @@ class RtcEvent {
     BweUpdateDelayBased,
     BweUpdateLossBased,
     DtlsTransportState,
+    DtlsWritableState,
     IceCandidatePairConfig,
     IceCandidatePairEvent,
     ProbeClusterCreated,

logging/rtc_event_log/events/rtc_event_dtls_writable_state.cc

@@ -0,0 +1,40 @@
+/*
+ *  Copyright (c) 2018 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 "logging/rtc_event_log/events/rtc_event_dtls_writable_state.h"
+
+#include "absl/memory/memory.h"
+
+namespace webrtc {
+
+RtcEventDtlsWritableState::RtcEventDtlsWritableState(bool writable)
+    : writable_(writable) {}
+
+RtcEventDtlsWritableState::RtcEventDtlsWritableState(
+    const RtcEventDtlsWritableState& other)
+    : writable_(other.writable_) {}
+
+RtcEventDtlsWritableState::~RtcEventDtlsWritableState() = default;
+
+RtcEvent::Type RtcEventDtlsWritableState::GetType() const {
+  return RtcEvent::Type::DtlsWritableState;
+}
+
+bool RtcEventDtlsWritableState::IsConfigEvent() const {
+  return false;
+}
+
+std::unique_ptr<RtcEventDtlsWritableState> RtcEventDtlsWritableState::Copy()
+    const {
+  return absl::WrapUnique<RtcEventDtlsWritableState>(
+      new RtcEventDtlsWritableState(*this));
+}
+
+}  // namespace webrtc

logging/rtc_event_log/events/rtc_event_dtls_writable_state.h

@@ -0,0 +1,40 @@
+/*
+ *  Copyright (c) 2018 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.
+ */
+
+#ifndef LOGGING_RTC_EVENT_LOG_EVENTS_RTC_EVENT_DTLS_WRITABLE_STATE_H_
+#define LOGGING_RTC_EVENT_LOG_EVENTS_RTC_EVENT_DTLS_WRITABLE_STATE_H_
+
+#include <memory>
+
+#include "logging/rtc_event_log/events/rtc_event.h"
+
+namespace webrtc {
+
+class RtcEventDtlsWritableState : public RtcEvent {
+ public:
+  explicit RtcEventDtlsWritableState(bool writable);
+  ~RtcEventDtlsWritableState() override;
+
+  Type GetType() const override;
+  bool IsConfigEvent() const override;
+
+  std::unique_ptr<RtcEventDtlsWritableState> Copy() const;
+
+  bool writable() const { return writable_; }
+
+ private:
+  RtcEventDtlsWritableState(const RtcEventDtlsWritableState& other);
+
+  const bool writable_;
+};
+
+}  // namespace webrtc
+
+#endif  // LOGGING_RTC_EVENT_LOG_EVENTS_RTC_EVENT_DTLS_WRITABLE_STATE_H_

logging/rtc_event_log/rtc_event_log2.proto

@@ -33,6 +33,7 @@ message EventStream {
   repeated IceCandidatePairConfig ice_candidate_configs = 25;
   repeated IceCandidatePairEvent ice_candidate_events = 26;
   repeated DtlsTransportStateEvent dtls_transport_state_events = 27;
+  repeated DtlsWritableState dtls_writable_states = 28;
 
   repeated AudioRecvStreamConfig audio_recv_stream_configs = 101;
   repeated AudioSendStreamConfig audio_send_stream_configs = 102;
@@ -589,3 +590,11 @@ message DtlsTransportStateEvent {
   // required
   optional DtlsTransportState dtls_transport_state = 2;
 }
+
+message DtlsWritableState {
+  // required
+  optional int64 timestamp_ms = 1;
+
+  // required
+  optional bool writable = 2;
+}

logging/rtc_event_log/rtc_event_log_parser_new.cc

@@ -861,6 +861,7 @@ void ParsedRtcEventLogNew::Clear() {
   bwe_delay_updates_.clear();
   bwe_loss_updates_.clear();
   dtls_transport_states_.clear();
+  dtls_writable_states_.clear();
   alr_state_events_.clear();
   ice_candidate_pair_configs_.clear();
   ice_candidate_pair_events_.clear();
@@ -1840,6 +1841,7 @@ void ParsedRtcEventLogNew::StoreParsedNewFormatEvent(
           stream.end_log_events_size() + stream.loss_based_bwe_updates_size() +
           stream.delay_based_bwe_updates_size() +
           stream.dtls_transport_state_events_size() +
+          stream.dtls_writable_states_size() +
           stream.audio_network_adaptations_size() +
           stream.probe_clusters_size() + stream.probe_success_size() +
           stream.probe_failure_size() + stream.alr_states_size() +
@@ -1871,6 +1873,8 @@ void ParsedRtcEventLogNew::StoreParsedNewFormatEvent(
     StoreBweDelayBasedUpdate(stream.delay_based_bwe_updates(0));
   } else if (stream.dtls_transport_state_events_size() == 1) {
     StoreDtlsTransportState(stream.dtls_transport_state_events(0));
+  } else if (stream.dtls_writable_states_size() == 1) {
+    StoreDtlsWritableState(stream.dtls_writable_states(0));
   } else if (stream.audio_network_adaptations_size() == 1) {
     StoreAudioNetworkAdaptationEvent(stream.audio_network_adaptations(0));
   } else if (stream.probe_clusters_size() == 1) {
@@ -2332,6 +2336,17 @@ void ParsedRtcEventLogNew::StoreDtlsTransportState(
   dtls_transport_states_.push_back(dtls_state);
 }
 
+void ParsedRtcEventLogNew::StoreDtlsWritableState(
+    const rtclog2::DtlsWritableState& proto) {
+  LoggedDtlsWritableState dtls_writable_state;
+  RTC_CHECK(proto.has_timestamp_ms());
+  dtls_writable_state.timestamp_us = proto.timestamp_ms() * 1000;
+  RTC_CHECK(proto.has_writable());
+  dtls_writable_state.writable = proto.writable();
+
+  dtls_writable_states_.push_back(dtls_writable_state);
+}
+
 void ParsedRtcEventLogNew::StoreIceCandidatePairConfig(
     const rtclog2::IceCandidatePairConfig& proto) {
   LoggedIceCandidatePairConfig ice_config;

logging/rtc_event_log/rtc_event_log_parser_new.h

@@ -139,6 +139,17 @@ struct LoggedDtlsTransportState {
   DtlsTransportState dtls_transport_state;
 };
 
+struct LoggedDtlsWritableState {
+  LoggedDtlsWritableState() = default;
+  explicit LoggedDtlsWritableState(bool writable) : writable(writable) {}
+
+  int64_t log_time_us() const { return timestamp_us; }
+  int64_t log_time_ms() const { return timestamp_us / 1000; }
+
+  int64_t timestamp_us;
+  bool writable;
+};
+
 struct LoggedBweProbeClusterCreatedEvent {
   LoggedBweProbeClusterCreatedEvent() = default;
   LoggedBweProbeClusterCreatedEvent(int64_t timestamp_us,
@@ -769,6 +780,10 @@ class ParsedRtcEventLogNew {
     return bwe_loss_updates_;
   }
 
+  const std::vector<LoggedDtlsWritableState>& dtls_writable_states() const {
+    return dtls_writable_states_;
+  }
+
   const std::vector<LoggedAlrStateEvent>& alr_state_events() const {
     return alr_state_events_;
   }
@@ -941,6 +956,7 @@ class ParsedRtcEventLogNew {
   void StoreStopEvent(const rtclog2::EndLogEvent& proto);
   void StoreBweLossBasedUpdate(const rtclog2::LossBasedBweUpdates& proto);
   void StoreBweDelayBasedUpdate(const rtclog2::DelayBasedBweUpdates& proto);
+  void StoreDtlsWritableState(const rtclog2::DtlsWritableState& proto);
   void StoreAudioNetworkAdaptationEvent(
       const rtclog2::AudioNetworkAdaptations& proto);
   void StoreBweProbeClusterCreated(const rtclog2::BweProbeCluster& proto);
@@ -1043,6 +1059,7 @@ class ParsedRtcEventLogNew {
   std::vector<LoggedBweLossBasedUpdate> bwe_loss_updates_;
 
   std::vector<LoggedDtlsTransportState> dtls_transport_states_;
+  std::vector<LoggedDtlsWritableState> dtls_writable_states_;
 
   std::vector<LoggedAlrStateEvent> alr_state_events_;
 

logging/rtc_event_log/rtc_event_log_unittest.cc

@@ -24,6 +24,7 @@
 #include "logging/rtc_event_log/events/rtc_event_bwe_update_delay_based.h"
 #include "logging/rtc_event_log/events/rtc_event_bwe_update_loss_based.h"
 #include "logging/rtc_event_log/events/rtc_event_dtls_transport_state.h"
+#include "logging/rtc_event_log/events/rtc_event_dtls_writable_state.h"
 #include "logging/rtc_event_log/events/rtc_event_probe_cluster_created.h"
 #include "logging/rtc_event_log/events/rtc_event_probe_result_failure.h"
 #include "logging/rtc_event_log/events/rtc_event_probe_result_success.h"
@@ -75,6 +76,7 @@ struct EventCounts {
   size_t bwe_loss_events = 0;
   size_t bwe_delay_events = 0;
   size_t dtls_transport_states = 0;
+  size_t dtls_writable_states = 0;
   size_t probe_creations = 0;
   size_t probe_successes = 0;
   size_t probe_failures = 0;
@@ -87,10 +89,10 @@ struct EventCounts {
 
   size_t total_nonconfig_events() const {
     return alr_states + audio_playouts + ana_configs + bwe_loss_events +
-           bwe_delay_events + dtls_transport_states + probe_creations +
+           bwe_delay_events + dtls_transport_states + dtls_writable_states +
-           probe_successes + probe_failures + ice_configs + ice_events +
+           probe_creations + probe_successes + probe_failures + ice_configs +
-           incoming_rtp_packets + outgoing_rtp_packets + incoming_rtcp_packets +
+           ice_events + incoming_rtp_packets + outgoing_rtp_packets +
-           outgoing_rtcp_packets;
+           incoming_rtcp_packets + outgoing_rtcp_packets;
   }
 
   size_t total_config_events() const {
@@ -160,6 +162,8 @@ class RtcEventLogSession
   std::vector<std::unique_ptr<RtcEventBweUpdateDelayBased>> bwe_delay_list_;
   std::vector<std::unique_ptr<RtcEventDtlsTransportState>>
       dtls_transport_state_list_;
+  std::vector<std::unique_ptr<RtcEventDtlsWritableState>>
+      dtls_writable_state_list_;
   std::vector<std::unique_ptr<RtcEventProbeClusterCreated>>
       probe_creation_list_;
   std::vector<std::unique_ptr<RtcEventProbeResultSuccess>> probe_success_list_;
@@ -406,6 +410,15 @@ void RtcEventLogSession::WriteLog(EventCounts count,
     }
     selection -= count.dtls_transport_states;
 
+    if (selection < count.dtls_writable_states) {
+      auto event = gen_.NewDtlsWritableState();
+      event_log->Log(event->Copy());
+      dtls_writable_state_list_.push_back(std::move(event));
+      count.dtls_writable_states--;
+      continue;
+    }
+    selection -= count.dtls_writable_states;
+
     if (selection < count.ice_configs) {
       auto event = gen_.NewIceCandidatePairConfig();
       event_log->Log(event->Copy());
@@ -661,6 +674,7 @@ TEST_P(RtcEventLogSession, StartLoggingFromBeginning) {
   count.bwe_loss_events = 20;
   count.bwe_delay_events = 20;
   count.dtls_transport_states = 4;
+  count.dtls_writable_states = 2;
   count.probe_creations = 4;
   count.probe_successes = 2;
   count.probe_failures = 2;
@@ -687,6 +701,7 @@ TEST_P(RtcEventLogSession, StartLoggingInTheMiddle) {
   count.bwe_loss_events = 50;
   count.bwe_delay_events = 50;
   count.dtls_transport_states = 4;
+  count.dtls_writable_states = 5;
   count.probe_creations = 10;
   count.probe_successes = 5;
   count.probe_failures = 5;

logging/rtc_event_log/rtc_event_log_unittest_helper.cc

@@ -138,6 +138,12 @@ EventGenerator::NewDtlsTransportState() {
   return absl::make_unique<RtcEventDtlsTransportState>(state);
 }
 
+std::unique_ptr<RtcEventDtlsWritableState>
+EventGenerator::NewDtlsWritableState() {
+  bool writable = prng_.Rand<bool>();
+  return absl::make_unique<RtcEventDtlsWritableState>(writable);
+}
+
 std::unique_ptr<RtcEventProbeClusterCreated>
 EventGenerator::NewProbeClusterCreated() {
   constexpr int kMaxBweBps = 20000000;
@@ -610,6 +616,13 @@ void EventVerifier::VerifyLoggedDtlsTransportState(
             logged_event.dtls_transport_state);
 }
 
+void EventVerifier::VerifyLoggedDtlsWritableState(
+    const RtcEventDtlsWritableState& original_event,
+    const LoggedDtlsWritableState& logged_event) const {
+  EXPECT_EQ(original_event.timestamp_ms(), logged_event.log_time_ms());
+  EXPECT_EQ(original_event.writable(), logged_event.writable);
+}
+
 void EventVerifier::VerifyLoggedIceCandidatePairConfig(
     const RtcEventIceCandidatePairConfig& original_event,
     const LoggedIceCandidatePairConfig& logged_event) const {

logging/rtc_event_log/rtc_event_log_unittest_helper.h

@@ -23,6 +23,7 @@
 #include "logging/rtc_event_log/events/rtc_event_bwe_update_delay_based.h"
 #include "logging/rtc_event_log/events/rtc_event_bwe_update_loss_based.h"
 #include "logging/rtc_event_log/events/rtc_event_dtls_transport_state.h"
+#include "logging/rtc_event_log/events/rtc_event_dtls_writable_state.h"
 #include "logging/rtc_event_log/events/rtc_event_ice_candidate_pair.h"
 #include "logging/rtc_event_log/events/rtc_event_ice_candidate_pair_config.h"
 #include "logging/rtc_event_log/events/rtc_event_probe_cluster_created.h"
@@ -63,6 +64,8 @@ class EventGenerator {
 
   std::unique_ptr<RtcEventDtlsTransportState> NewDtlsTransportState();
 
+  std::unique_ptr<RtcEventDtlsWritableState> NewDtlsWritableState();
+
   std::unique_ptr<RtcEventProbeClusterCreated> NewProbeClusterCreated();
 
   std::unique_ptr<RtcEventProbeResultFailure> NewProbeResultFailure();
@@ -168,6 +171,10 @@ class EventVerifier {
       const RtcEventDtlsTransportState& original_event,
       const LoggedDtlsTransportState& logged_event) const;
 
+  void VerifyLoggedDtlsWritableState(
+      const RtcEventDtlsWritableState& original_event,
+      const LoggedDtlsWritableState& logged_event) const;
+
   void VerifyLoggedIceCandidatePairConfig(
       const RtcEventIceCandidatePairConfig& original_event,
       const LoggedIceCandidatePairConfig& logged_event) const;

p2p/base/dtlstransport.cc

@@ -16,6 +16,7 @@
 
 #include "absl/memory/memory.h"
 #include "logging/rtc_event_log/events/rtc_event_dtls_transport_state.h"
+#include "logging/rtc_event_log/events/rtc_event_dtls_writable_state.h"
 #include "logging/rtc_event_log/rtc_event_log.h"
 #include "p2p/base/packettransportinternal.h"
 #include "rtc_base/buffer.h"
@@ -751,6 +752,10 @@ void DtlsTransport::set_writable(bool writable) {
   if (writable_ == writable) {
     return;
   }
+  if (event_log_) {
+    event_log_->Log(
+        absl::make_unique<webrtc::RtcEventDtlsWritableState>(writable));
+  }
   RTC_LOG(LS_VERBOSE) << ToString() << ": set_writable to: " << writable;
   writable_ = writable;
   if (writable_) {