diff --git a/p2p/BUILD.gn b/p2p/BUILD.gn index d911ed7127..5b008f28da 100644 --- a/p2p/BUILD.gn +++ b/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", diff --git a/p2p/DEPS b/p2p/DEPS index 94f4bcb2ad..8243179d40 100644 --- a/p2p/DEPS +++ b/p2p/DEPS @@ -1,4 +1,5 @@ include_rules = [ + "+logging", "+net", "+system_wrappers", ] diff --git a/p2p/base/p2ptransportchannel.cc b/p2p/base/p2ptransportchannel.cc index 02b943a401..0e6deeecbf 100644 --- a/p2p/base/p2ptransportchannel.cc +++ b/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(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 diff --git a/p2p/base/p2ptransportchannel.h b/p2p/base/p2ptransportchannel.h index ed0be2e111..af5625a4b4 100644 --- a/p2p/base/p2ptransportchannel.h +++ b/p2p/base/p2ptransportchannel.h @@ -27,6 +27,8 @@ #include #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 network_route_; + webrtc::IceEventLog ice_event_log_; + RTC_DISALLOW_COPY_AND_ASSIGN(P2PTransportChannel); }; diff --git a/p2p/base/port.cc b/p2p/base/port.cc index 21b817ae83..2f77aa7cc9 100644 --- a/p2p/base/port.cc +++ b/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(std::hash{}(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++; } diff --git a/p2p/base/port.h b/p2p/base/port.h index ca845e626b..8dbeccec47 100644 --- a/p2p/base/port.h +++ b/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 log_description_; + uint32_t hash_; + webrtc::IceEventLog* ice_event_log_ = nullptr; + friend class Port; friend class ConnectionRequest; }; diff --git a/pc/BUILD.gn b/pc/BUILD.gn index e44ae758ec..66f6cf1f4c 100644 --- a/pc/BUILD.gn +++ b/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", diff --git a/pc/peerconnection.cc b/pc/peerconnection.cc index 5cccd854d7..3205e8f207 100644 --- a/pc/peerconnection.cc +++ b/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(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( RTC_FROM_HERE, rtc::Bind(&cricket::PortAllocator::DiscardCandidatePool, diff --git a/pc/peerconnectionfactory.cc b/pc/peerconnectionfactory.cc index d9fcce2ae6..af8f541bd7 100644 --- a/pc/peerconnectionfactory.cc +++ b/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 diff --git a/pc/peerconnectionfactory.h b/pc/peerconnectionfactory.h index 398221ffde..652f76ad61 100644 --- a/pc/peerconnectionfactory.h +++ b/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 CreateSctpTransportInternalFactory(); diff --git a/pc/peerconnectioninterface_unittest.cc b/pc/peerconnectioninterface_unittest.cc index be042c7060..e496e4ede6 100644 --- a/pc/peerconnectioninterface_unittest.cc +++ b/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 reference_collection_; }; -// Test that no callbacks on the PeerConnectionObserver are called after the -// PeerConnection is closed. -TEST_F(PeerConnectionInterfaceTest, CloseAndTestCallbackFunctions) { - rtc::scoped_refptr 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 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. diff --git a/pc/transportcontroller.cc b/pc/transportcontroller.cc index 38200f8539..1876c3be78 100644 --- a/pc/transportcontroller.cc +++ b/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( diff --git a/pc/transportcontroller.h b/pc/transportcontroller.h index 705fc4c38f..bd2be7c765 100644 --- a/pc/transportcontroller.h +++ b/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); }; diff --git a/rtc_tools/event_log_visualizer/analyzer.cc b/rtc_tools/event_log_visualizer/analyzer.cc index 2bbb09cbc8..c32c676b38 100644 --- a/rtc_tools/event_log_visualizer/analyzer.cc +++ b/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( - candidate_pair_desc, LineStyle::kNone, PointStyle::kHighlight); + configs_by_cp_id[config.candidate_pair_id] = + 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,7 +2160,8 @@ 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( - GetCandidatePairLogDescriptionFromId(event.candidate_pair_id), + "[" + std::to_string(event.candidate_pair_id) + "]" + + GetCandidatePairLogDescriptionFromId(event.candidate_pair_id), LineStyle::kNone, PointStyle::kHighlight); } float x = ToCallTime(event.timestamp);