Bind the structured ICE logging with P2PTransportChannel.

This change list passes the instance of RtcEventLog from Peerconnection
down to P2PTransportChannel, and binds the structured ICE logging with
ICE layer objects. Logs of ICE connectivity checks are injected for
candidate pairs.

TBR=terelius@webrtc.org

Bug: None
Change-Id: Ia979dbbac6d31dcf0f8988da1065bdfc3e461821
Reviewed-on: https://webrtc-review.googlesource.com/34660
Commit-Queue: Qingsi Wang <qingsi@google.com>
Reviewed-by: Peter Thatcher <pthatcher@webrtc.org>
Reviewed-by: Taylor Brandstetter <deadbeef@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#21884}

p2p/BUILD.gn

@@ -89,6 +89,7 @@ rtc_static_library("rtc_p2p") {
     "../api:libjingle_peerconnection_api",
     "../api:optional",
     "../api:ortc_api",
+    "../logging:ice_log",
     "../rtc_base:checks",
     "../rtc_base:rtc_base",
     "../rtc_base:stringutils",

p2p/DEPS

@@ -1,4 +1,5 @@
 include_rules = [
+  "+logging",
   "+net",
   "+system_wrappers",
 ]

p2p/base/p2ptransportchannel.cc

@@ -17,6 +17,7 @@
 
 #include "api/candidate.h"
 #include "api/umametrics.h"
+#include "logging/rtc_event_log/icelogger.h"
 #include "p2p/base/candidatepairinterface.h"
 #include "p2p/base/common.h"
 #include "p2p/base/relayport.h"  // For RELAY_PORT_TYPE.
@@ -140,7 +141,8 @@ bool IceCredentialsChanged(const std::string& old_ufrag,
 
 P2PTransportChannel::P2PTransportChannel(const std::string& transport_name,
                                          int component,
-                                         PortAllocator* allocator)
+                                         PortAllocator* allocator,
+                                         webrtc::RtcEventLog* event_log)
     : transport_name_(transport_name),
       component_(component),
       allocator_(allocator),
@@ -169,6 +171,7 @@ P2PTransportChannel::P2PTransportChannel(const std::string& transport_name,
   if (weak_ping_interval) {
     weak_ping_interval_ = static_cast<int>(weak_ping_interval);
   }
+  ice_event_log_.set_event_log(event_log);
 }
 
 P2PTransportChannel::~P2PTransportChannel() {
@@ -215,7 +218,11 @@ void P2PTransportChannel::AddConnection(Connection* connection) {
   connection->SignalDestroyed.connect(
       this, &P2PTransportChannel::OnConnectionDestroyed);
   connection->SignalNominated.connect(this, &P2PTransportChannel::OnNominated);
+
   had_connection_ = true;
+
+  connection->set_ice_event_log(&ice_event_log_);
+  LogCandidatePairEvent(connection, webrtc::IceCandidatePairEventType::kAdded);
 }
 
 // Determines whether we should switch the selected connection to
@@ -383,6 +390,7 @@ IceTransportState P2PTransportChannel::ComputeState() const {
     }
   }
 
+  ice_event_log_.DumpCandidatePairDescriptionToMemoryAsConfigEvents();
   return IceTransportState::STATE_COMPLETED;
 }
 
@@ -1538,6 +1546,7 @@ void P2PTransportChannel::SwitchSelectedConnection(Connection* conn) {
   // destroyed, so don't use it.
   Connection* old_selected_connection = selected_connection_;
   selected_connection_ = conn;
+  LogCandidatePairEvent(conn, webrtc::IceCandidatePairEventType::kSelected);
   network_route_.reset();
   if (selected_connection_) {
     ++nomination_;
@@ -2251,4 +2260,15 @@ int P2PTransportChannel::SampleRegatherAllNetworksInterval() {
   return rand_.Rand(interval->min(), interval->max());
 }
 
+void P2PTransportChannel::LogCandidatePairEvent(
+    Connection* conn,
+    webrtc::IceCandidatePairEventType type) {
+  if (conn == nullptr) {
+    return;
+  }
+  auto candidate_pair_id = conn->hash();
+  ice_event_log_.LogCandidatePairEvent(type, candidate_pair_id,
+                                       conn->ToLogDescription());
+}
+
 }  // namespace cricket

p2p/base/p2ptransportchannel.h

@@ -27,6 +27,8 @@
 #include <vector>
 
 #include "api/candidate.h"
+#include "logging/rtc_event_log/events/rtc_event_ice_candidate_pair_config.h"
+#include "logging/rtc_event_log/icelogger.h"
 #include "p2p/base/candidatepairinterface.h"
 #include "p2p/base/icetransportinternal.h"
 #include "p2p/base/portallocator.h"
@@ -36,6 +38,10 @@
 #include "rtc_base/random.h"
 #include "rtc_base/sigslot.h"
 
+namespace webrtc {
+class RtcEventLog;
+}  // namespace webrtc
+
 namespace cricket {
 
 // Enum for UMA metrics, used to record whether the channel is
@@ -72,7 +78,8 @@ class P2PTransportChannel : public IceTransportInternal,
  public:
   P2PTransportChannel(const std::string& transport_name,
                       int component,
-                      PortAllocator* allocator);
+                      PortAllocator* allocator,
+                      webrtc::RtcEventLog* event_log = nullptr);
   ~P2PTransportChannel() override;
 
   // From TransportChannelImpl:
@@ -293,6 +300,9 @@ class P2PTransportChannel : public IceTransportInternal,
   void OnRegatherOnFailedNetworks();
   void OnRegatherOnAllNetworks();
 
+  void LogCandidatePairEvent(Connection* conn,
+                             webrtc::IceCandidatePairEventType type);
+
   uint32_t GetNominationAttr(Connection* conn) const;
   bool GetUseCandidateAttr(Connection* conn, NominationMode mode) const;
 
@@ -414,6 +424,8 @@ class P2PTransportChannel : public IceTransportInternal,
 
   rtc::Optional<rtc::NetworkRoute> network_route_;
 
+  webrtc::IceEventLog ice_event_log_;
+
   RTC_DISALLOW_COPY_AND_ASSIGN(P2PTransportChannel);
 };
 

p2p/base/port.cc

@@ -62,6 +62,60 @@ inline bool TooLongWithoutResponse(
   return now > (first.sent_time + maximum_time);
 }
 
+// Helper methods for converting string values of log description fields to
+// enum.
+webrtc::IceCandidateType GetCandidateTypeByString(const std::string& type) {
+  if (type == cricket::LOCAL_PORT_TYPE) {
+    return webrtc::IceCandidateType::kLocal;
+  } else if (type == cricket::STUN_PORT_TYPE) {
+    return webrtc::IceCandidateType::kStun;
+  } else if (type == cricket::PRFLX_PORT_TYPE) {
+    return webrtc::IceCandidateType::kPrflx;
+  } else if (type == cricket::RELAY_PORT_TYPE) {
+    return webrtc::IceCandidateType::kRelay;
+  }
+  return webrtc::IceCandidateType::kUnknown;
+}
+
+webrtc::IceCandidatePairProtocol GetProtocolByString(
+    const std::string& protocol) {
+  if (protocol == cricket::UDP_PROTOCOL_NAME) {
+    return webrtc::IceCandidatePairProtocol::kUdp;
+  } else if (protocol == cricket::TCP_PROTOCOL_NAME) {
+    return webrtc::IceCandidatePairProtocol::kTcp;
+  } else if (protocol == cricket::SSLTCP_PROTOCOL_NAME) {
+    return webrtc::IceCandidatePairProtocol::kSsltcp;
+  } else if (protocol == cricket::TLS_PROTOCOL_NAME) {
+    return webrtc::IceCandidatePairProtocol::kTls;
+  }
+  return webrtc::IceCandidatePairProtocol::kUnknown;
+}
+
+webrtc::IceCandidatePairAddressFamily GetAddressFamilyByInt(
+    int address_family) {
+  if (address_family == AF_INET) {
+    return webrtc::IceCandidatePairAddressFamily::kIpv4;
+  } else if (address_family == AF_INET6) {
+    return webrtc::IceCandidatePairAddressFamily::kIpv6;
+  }
+  return webrtc::IceCandidatePairAddressFamily::kUnknown;
+}
+
+webrtc::IceCandidateNetworkType ConvertNetworkType(rtc::AdapterType type) {
+  if (type == rtc::ADAPTER_TYPE_ETHERNET) {
+    return webrtc::IceCandidateNetworkType::kEthernet;
+  } else if (type == rtc::ADAPTER_TYPE_LOOPBACK) {
+    return webrtc::IceCandidateNetworkType::kLoopback;
+  } else if (type == rtc::ADAPTER_TYPE_WIFI) {
+    return webrtc::IceCandidateNetworkType::kWifi;
+  } else if (type == rtc::ADAPTER_TYPE_VPN) {
+    return webrtc::IceCandidateNetworkType::kVpn;
+  } else if (type == rtc::ADAPTER_TYPE_CELLULAR) {
+    return webrtc::IceCandidateNetworkType::kCellular;
+  }
+  return webrtc::IceCandidateNetworkType::kUnknown;
+}
+
 // We will restrict RTT estimates (when used for determining state) to be
 // within a reasonable range.
 const int MINIMUM_RTT = 100;   // 0.1 seconds
@@ -713,6 +767,8 @@ void Port::SendBindingResponse(StunMessage* request,
         << ", id=" << rtc::hex_encode(response.transaction_id());
 
     conn->stats_.sent_ping_responses++;
+    conn->LogCandidatePairEvent(
+        webrtc::IceCandidatePairEventType::kCheckResponseSent);
   }
 }
 
@@ -976,6 +1032,7 @@ Connection::Connection(Port* port,
   // TODO(mallinath) - Start connections from STATE_FROZEN.
   // Wire up to send stun packets
   requests_.SignalSendPacket.connect(this, &Connection::OnSendStunPacket);
+  hash_ = static_cast<uint32_t>(std::hash<std::string>{}(ToString()));
   LOG_J(LS_INFO, this) << "Connection created";
 }
 
@@ -1160,6 +1217,7 @@ void Connection::HandleBindingRequest(IceMessage* msg) {
   }
 
   stats_.recv_ping_requests++;
+  LogCandidatePairEvent(webrtc::IceCandidatePairEventType::kCheckReceived);
 
   // This is a validated stun request from remote peer.
   port_->SendBindingResponse(msg, remote_addr);
@@ -1229,6 +1287,7 @@ void Connection::Destroy() {
   // AutoSocketServerThread::~AutoSocketServerThread.
   LOG_J(LS_VERBOSE, this) << "Connection destroyed";
   port_->thread()->Post(RTC_FROM_HERE, this, MSG_DELETE);
+  LogCandidatePairEvent(webrtc::IceCandidatePairEventType::kDestroyed);
 }
 
 void Connection::FailAndDestroy() {
@@ -1467,6 +1526,37 @@ std::string Connection::ToSensitiveString() const {
   return ToString();
 }
 
+const webrtc::IceCandidatePairDescription& Connection::ToLogDescription() {
+  if (log_description_.has_value()) {
+    return log_description_.value();
+  }
+  const Candidate& local = local_candidate();
+  const Candidate& remote = remote_candidate();
+  const rtc::Network* network = port()->Network();
+  log_description_ = webrtc::IceCandidatePairDescription();
+  log_description_->local_candidate_type =
+      GetCandidateTypeByString(local.type());
+  log_description_->local_relay_protocol =
+      GetProtocolByString(local.relay_protocol());
+  log_description_->local_network_type = ConvertNetworkType(network->type());
+  log_description_->local_address_family =
+      GetAddressFamilyByInt(local.address().family());
+  log_description_->remote_candidate_type =
+      GetCandidateTypeByString(remote.type());
+  log_description_->remote_address_family =
+      GetAddressFamilyByInt(remote.address().family());
+  log_description_->candidate_pair_protocol =
+      GetProtocolByString(local.protocol());
+  return log_description_.value();
+}
+
+void Connection::LogCandidatePairEvent(webrtc::IceCandidatePairEventType type) {
+  if (ice_event_log_ == nullptr) {
+    return;
+  }
+  ice_event_log_->LogCandidatePairEvent(type, hash(), ToLogDescription());
+}
+
 void Connection::OnConnectionRequestResponse(ConnectionRequest* request,
                                              StunMessage* response) {
   // Log at LS_INFO if we receive a ping response on an unwritable
@@ -1490,6 +1580,8 @@ void Connection::OnConnectionRequestResponse(ConnectionRequest* request,
   packet_loss_estimator_.ReceivedResponse(request->id(), time_received);
 
   stats_.recv_ping_responses++;
+  LogCandidatePairEvent(
+      webrtc::IceCandidatePairEventType::kCheckResponseReceived);
 
   MaybeUpdateLocalCandidate(request, response);
 }
@@ -1534,6 +1626,7 @@ void Connection::OnConnectionRequestSent(ConnectionRequest* request) {
                     << ", use_candidate=" << use_candidate_attr()
                     << ", nomination=" << nomination();
   stats_.sent_ping_requests_total++;
+  LogCandidatePairEvent(webrtc::IceCandidatePairEventType::kCheckSent);
   if (stats_.recv_ping_responses == 0) {
     stats_.sent_ping_requests_before_first_response++;
   }

p2p/base/port.h

@@ -19,6 +19,9 @@
 
 #include "api/candidate.h"
 #include "api/optional.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/icelogger.h"
 #include "p2p/base/candidatepairinterface.h"
 #include "p2p/base/packetlossestimator.h"
 #include "p2p/base/packetsocketfactory.h"
@@ -639,6 +642,13 @@ class Connection : public CandidatePairInterface,
   std::string ToDebugId() const;
   std::string ToString() const;
   std::string ToSensitiveString() const;
+  // Structured description of this candidate pair.
+  const webrtc::IceCandidatePairDescription& ToLogDescription();
+  // Integer typed hash value of this candidate pair.
+  uint32_t hash() { return hash_; }
+  void set_ice_event_log(webrtc::IceEventLog* ice_event_log) {
+    ice_event_log_ = ice_event_log;
+  }
   // Prints pings_since_last_response_ into a string.
   void PrintPingsSinceLastResponse(std::string* pings, size_t max);
 
@@ -728,6 +738,8 @@ class Connection : public CandidatePairInterface,
   void MaybeUpdateLocalCandidate(ConnectionRequest* request,
                                  StunMessage* response);
 
+  void LogCandidatePairEvent(webrtc::IceCandidatePairEventType type);
+
   WriteState write_state_;
   bool receiving_;
   bool connected_;
@@ -775,6 +787,10 @@ class Connection : public CandidatePairInterface,
   int64_t time_created_ms_;
   int num_pings_sent_ = 0;
 
+  rtc::Optional<webrtc::IceCandidatePairDescription> log_description_;
+  uint32_t hash_;
+  webrtc::IceEventLog* ice_event_log_ = nullptr;
+
   friend class Port;
   friend class ConnectionRequest;
 };

pc/BUILD.gn

@@ -187,6 +187,7 @@ rtc_static_library("peerconnection") {
     "../api/video_codecs:video_codecs_api",
     "../call:call_interfaces",
     "../common_video:common_video",
+    "../logging:ice_log",
     "../logging:rtc_event_log_api",
     "../logging:rtc_event_log_impl_output",
     "../media:rtc_data",

pc/peerconnection.cc

@@ -22,6 +22,7 @@
 #include "api/mediastreamproxy.h"
 #include "api/mediastreamtrackproxy.h"
 #include "call/call.h"
+#include "logging/rtc_event_log/icelogger.h"
 #include "logging/rtc_event_log/output/rtc_event_log_output_file.h"
 #include "logging/rtc_event_log/rtc_event_log.h"
 #include "media/sctp/sctptransport.h"
@@ -762,6 +763,7 @@ PeerConnection::~PeerConnection() {
   // call_ and event_log_ must be destroyed on the worker thread.
   worker_thread()->Invoke<void>(RTC_FROM_HERE, [this] {
     call_.reset();
+    // The event log must outlive call (and any other object that uses it).
     event_log_.reset();
   });
 }
@@ -825,7 +827,8 @@ bool PeerConnection::Initialize(
   // LLONG_MAX.
   session_id_ = rtc::ToString(rtc::CreateRandomId64() & LLONG_MAX);
   transport_controller_.reset(factory_->CreateTransportController(
-      port_allocator_.get(), configuration.redetermine_role_on_ice_restart));
+      port_allocator_.get(), configuration.redetermine_role_on_ice_restart,
+      event_log_.get()));
   transport_controller_->SetIceRole(cricket::ICEROLE_CONTROLLED);
   transport_controller_->SignalConnectionState.connect(
       this, &PeerConnection::OnTransportControllerConnectionState);
@@ -2857,6 +2860,14 @@ void PeerConnection::Close() {
   }
   DestroyAllChannels();
 
+  // The event log is used in the transport controller, which must be outlived
+  // by the former. CreateOffer by the peer connection is implemented
+  // asynchronously and if the peer connection is closed without resetting the
+  // WebRTC session description factory, the session description factory would
+  // call the transport controller.
+  webrtc_session_desc_factory_.reset();
+  transport_controller_.reset();
+
   network_thread()->Invoke<void>(
       RTC_FROM_HERE,
       rtc::Bind(&cricket::PortAllocator::DiscardCandidatePool,

pc/peerconnectionfactory.cc

@@ -295,11 +295,12 @@ PeerConnectionFactory::CreateAudioTrack(const std::string& id,
 
 cricket::TransportController* PeerConnectionFactory::CreateTransportController(
     cricket::PortAllocator* port_allocator,
-    bool redetermine_role_on_ice_restart) {
+    bool redetermine_role_on_ice_restart,
+    RtcEventLog* event_log) {
   RTC_DCHECK(signaling_thread_->IsCurrent());
   return new cricket::TransportController(
       signaling_thread_, network_thread_, port_allocator,
-      redetermine_role_on_ice_restart, options_.crypto_options);
+      redetermine_role_on_ice_restart, options_.crypto_options, event_log);
 }
 
 std::unique_ptr<cricket::SctpTransportInternalFactory>

pc/peerconnectionfactory.h

@@ -89,7 +89,8 @@ class PeerConnectionFactory : public PeerConnectionFactoryInterface {
 
   virtual cricket::TransportController* CreateTransportController(
       cricket::PortAllocator* port_allocator,
-      bool redetermine_role_on_ice_restart);
+      bool redetermine_role_on_ice_restart,
+      RtcEventLog* event_log = nullptr);
 
   virtual std::unique_ptr<cricket::SctpTransportInternalFactory>
   CreateSctpTransportInternalFactory();

pc/peerconnectioninterface_unittest.cc

@@ -581,10 +581,11 @@ class PeerConnectionFactoryForTest : public webrtc::PeerConnectionFactory {
 
   cricket::TransportController* CreateTransportController(
       cricket::PortAllocator* port_allocator,
-      bool redetermine_role_on_ice_restart) override {
+      bool redetermine_role_on_ice_restart,
+      webrtc::RtcEventLog* event_log = nullptr) override {
     transport_controller = new cricket::TransportController(
         rtc::Thread::Current(), rtc::Thread::Current(), port_allocator,
-        redetermine_role_on_ice_restart, rtc::CryptoOptions());
+        redetermine_role_on_ice_restart, rtc::CryptoOptions(), event_log);
     return transport_controller;
   }
 
@@ -1138,31 +1139,6 @@ class PeerConnectionInterfaceTest : public testing::Test {
   rtc::scoped_refptr<StreamCollection> reference_collection_;
 };
 
-// Test that no callbacks on the PeerConnectionObserver are called after the
-// PeerConnection is closed.
-TEST_F(PeerConnectionInterfaceTest, CloseAndTestCallbackFunctions) {
-  rtc::scoped_refptr<PeerConnectionInterface> pc(
-      pc_factory_for_test_->CreatePeerConnection(
-          PeerConnectionInterface::RTCConfiguration(), nullptr, nullptr,
-          nullptr, &observer_));
-  observer_.SetPeerConnectionInterface(pc.get());
-  pc->Close();
-
-  // No callbacks is expected to be called.
-  observer_.callback_triggered_ = false;
-  std::vector<cricket::Candidate> candidates;
-  pc_factory_for_test_->transport_controller->SignalGatheringState(
-      cricket::IceGatheringState{});
-  pc_factory_for_test_->transport_controller->SignalCandidatesGathered(
-      "", candidates);
-  pc_factory_for_test_->transport_controller->SignalConnectionState(
-      cricket::IceConnectionState{});
-  pc_factory_for_test_->transport_controller->SignalCandidatesRemoved(
-      candidates);
-  pc_factory_for_test_->transport_controller->SignalReceiving(false);
-  EXPECT_FALSE(observer_.callback_triggered_);
-}
-
 // Generate different CNAMEs when PeerConnections are created.
 // The CNAMEs are expected to be generated randomly. It is possible
 // that the test fails, though the possibility is very low.

pc/transportcontroller.cc

@@ -115,12 +115,14 @@ TransportController::TransportController(
     rtc::Thread* network_thread,
     PortAllocator* port_allocator,
     bool redetermine_role_on_ice_restart,
-    const rtc::CryptoOptions& crypto_options)
+    const rtc::CryptoOptions& crypto_options,
+    webrtc::RtcEventLog* event_log)
     : signaling_thread_(signaling_thread),
       network_thread_(network_thread),
       port_allocator_(port_allocator),
       redetermine_role_on_ice_restart_(redetermine_role_on_ice_restart),
-      crypto_options_(crypto_options) {}
+      crypto_options_(crypto_options),
+      event_log_(event_log) {}
 
 TransportController::~TransportController() {
   // Channel destructors may try to send packets, so this needs to happen on
@@ -541,7 +543,8 @@ DtlsTransportInternal* TransportController::get_channel_for_testing(
 IceTransportInternal* TransportController::CreateIceTransportChannel_n(
     const std::string& transport_name,
     int component) {
-  return new P2PTransportChannel(transport_name, component, port_allocator_);
+  return new P2PTransportChannel(transport_name, component, port_allocator_,
+                                 event_log_);
 }
 
 DtlsTransportInternal* TransportController::CreateDtlsTransportChannel_n(

pc/transportcontroller.h

@@ -36,6 +36,7 @@ class PacketTransportInternal;
 
 namespace webrtc {
 class MetricsObserverInterface;
+class RtcEventLog;
 }  // namespace webrtc
 
 namespace cricket {
@@ -53,7 +54,8 @@ class TransportController : public sigslot::has_slots<>,
                       rtc::Thread* network_thread,
                       PortAllocator* port_allocator,
                       bool redetermine_role_on_ice_restart,
-                      const rtc::CryptoOptions& crypto_options);
+                      const rtc::CryptoOptions& crypto_options,
+                      webrtc::RtcEventLog* event_log = nullptr);
 
   virtual ~TransportController();
 
@@ -307,6 +309,8 @@ class TransportController : public sigslot::has_slots<>,
 
   webrtc::MetricsObserverInterface* metrics_observer_ = nullptr;
 
+  webrtc::RtcEventLog* event_log_;
+
   RTC_DISALLOW_COPY_AND_ASSIGN(TransportController);
 };
 

rtc_tools/event_log_visualizer/analyzer.cc

@@ -2109,8 +2109,10 @@ void EventLogAnalyzer::CreateIceCandidatePairConfigGraph(Plot* plot) {
         configs_by_cp_id.end()) {
       const std::string candidate_pair_desc =
           GetCandidatePairLogDescriptionAsString(config);
-      configs_by_cp_id[config.candidate_pair_id] = TimeSeries(
+      configs_by_cp_id[config.candidate_pair_id] =
-          candidate_pair_desc, LineStyle::kNone, PointStyle::kHighlight);
+          TimeSeries("[" + std::to_string(config.candidate_pair_id) + "]" +
+                         candidate_pair_desc,
+                     LineStyle::kNone, PointStyle::kHighlight);
       candidate_pair_desc_by_id_[config.candidate_pair_id] =
           candidate_pair_desc;
     }
@@ -2158,6 +2160,7 @@ void EventLogAnalyzer::CreateIceConnectivityCheckGraph(Plot* plot) {
     if (checks_by_cp_id.find(event.candidate_pair_id) ==
         checks_by_cp_id.end()) {
       checks_by_cp_id[event.candidate_pair_id] = TimeSeries(
+          "[" + std::to_string(event.candidate_pair_id) + "]" +
               GetCandidatePairLogDescriptionFromId(event.candidate_pair_id),
           LineStyle::kNone, PointStyle::kHighlight);
     }