From c3252467531ef565ebbe8144e3127b647d70a846 Mon Sep 17 00:00:00 2001 From: Yura Yaroshevich Date: Mon, 18 May 2020 13:26:14 +0300 Subject: [PATCH] Log content name (aka mid) in messages from channel.cc Logging of content name (mid) is valuable to debug issues in scenarios with multiple m= line sections in SDP. For example, video conferencing applications which uses SFU and Unified Plan SDPs will likely to leverage from more detailed logs when issues need to be debugged. Bug: webrtc:10139 Change-Id: Id52ba3ad54af5caa0f8c03daaa51bdb0caf9fe67 Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/175115 Commit-Queue: Tommi Reviewed-by: Tommi Cr-Commit-Position: refs/heads/master@{#31302} --- pc/channel.cc | 105 +++++++++++++++++++++++++++++++------------------- pc/channel.h | 3 ++ 2 files changed, 68 insertions(+), 40 deletions(-) diff --git a/pc/channel.cc b/pc/channel.cc index f83f5cdd9a..8a3a800210 100644 --- a/pc/channel.cc +++ b/pc/channel.cc @@ -142,7 +142,7 @@ BaseChannel::BaseChannel(rtc::Thread* worker_thread, RTC_DCHECK_RUN_ON(worker_thread_); RTC_DCHECK(ssrc_generator_); demuxer_criteria_.mid = content_name; - RTC_LOG(LS_INFO) << "Created channel for " << content_name; + RTC_LOG(LS_INFO) << "Created channel: " << ToString(); } BaseChannel::~BaseChannel() { @@ -156,12 +156,23 @@ BaseChannel::~BaseChannel() { // the media channel may try to send on the dead transport channel. NULLing // is not an effective strategy since the sends will come on another thread. media_channel_.reset(); - RTC_LOG(LS_INFO) << "Destroyed channel: " << content_name_; + RTC_LOG(LS_INFO) << "Destroyed channel: " << ToString(); +} + +std::string BaseChannel::ToString() const { + rtc::StringBuilder sb; + sb << "{mid: " << content_name_; + if (media_channel_) { + sb << ", media_type: " << MediaTypeToString(media_channel_->media_type()); + } + sb << "}"; + return sb.Release(); } bool BaseChannel::ConnectToRtpTransport() { RTC_DCHECK(rtp_transport_); if (!RegisterRtpDemuxerSink()) { + RTC_LOG(LS_ERROR) << "Failed to set up demuxing for " << ToString(); return false; } rtp_transport_->SignalReadyToSend.connect( @@ -237,7 +248,8 @@ bool BaseChannel::SetRtpTransport(webrtc::RtpTransportInternal* rtp_transport) { transport_name_ = rtp_transport_->transport_name(); if (!ConnectToRtpTransport()) { - RTC_LOG(LS_ERROR) << "Failed to connect to the new RtpTransport."; + RTC_LOG(LS_ERROR) << "Failed to connect to the new RtpTransport for " + << ToString() << "."; return false; } OnTransportReadyToSend(rtp_transport_->IsReadyToSend()); @@ -349,7 +361,7 @@ void BaseChannel::OnWritableState(bool writable) { void BaseChannel::OnNetworkRouteChanged( absl::optional network_route) { - RTC_LOG(LS_INFO) << "Network route was changed."; + RTC_LOG(LS_INFO) << "Network route for " << ToString() << " was changed."; RTC_DCHECK(network_thread_->IsCurrent()); rtc::NetworkRoute new_route; @@ -404,7 +416,7 @@ bool BaseChannel::SendPacket(bool rtcp, // Protect ourselves against crazy data. if (!IsValidRtpPacketSize(packet_type, packet->size())) { - RTC_LOG(LS_ERROR) << "Dropping outgoing " << content_name_ << " " + RTC_LOG(LS_ERROR) << "Dropping outgoing " << ToString() << " " << RtpPacketTypeToString(packet_type) << " packet: wrong size=" << packet->size(); return false; @@ -420,16 +432,16 @@ bool BaseChannel::SendPacket(bool rtcp, } // However, there shouldn't be any RTP packets sent before SRTP is set up // (and SetSend(true) is called). - RTC_LOG(LS_ERROR) - << "Can't send outgoing RTP packet when SRTP is inactive" - " and crypto is required"; + RTC_LOG(LS_ERROR) << "Can't send outgoing RTP packet for " << ToString() + << " when SRTP is inactive and crypto is required"; RTC_NOTREACHED(); return false; } std::string packet_type = rtcp ? "RTCP" : "RTP"; RTC_LOG(LS_WARNING) << "Sending an " << packet_type - << " packet without encryption."; + << " packet without encryption for " << ToString() + << "."; } // Bon voyage. @@ -463,7 +475,8 @@ void BaseChannel::OnRtpPacket(const webrtc::RtpPacketReceived& parsed_packet) { // for us to just eat packets here. This is all sidestepped if RTCP mux // is used anyway. RTC_LOG(LS_WARNING) << "Can't process incoming RTP packet when " - "SRTP is inactive and crypto is required"; + "SRTP is inactive and crypto is required " + << ToString(); return; } @@ -504,7 +517,7 @@ void BaseChannel::EnableMedia_w() { if (enabled_) return; - RTC_LOG(LS_INFO) << "Channel enabled"; + RTC_LOG(LS_INFO) << "Channel enabled: " << ToString(); enabled_ = true; UpdateMediaSendRecvState_w(); } @@ -514,7 +527,7 @@ void BaseChannel::DisableMedia_w() { if (!enabled_) return; - RTC_LOG(LS_INFO) << "Channel disabled"; + RTC_LOG(LS_INFO) << "Channel disabled: " << ToString(); enabled_ = false; UpdateMediaSendRecvState_w(); } @@ -534,7 +547,7 @@ void BaseChannel::ChannelWritable_n() { return; } - RTC_LOG(LS_INFO) << "Channel writable (" << content_name_ << ")" + RTC_LOG(LS_INFO) << "Channel writable (" << ToString() << ")" << (was_ever_writable_ ? "" : " for the first time"); was_ever_writable_ = true; @@ -547,7 +560,7 @@ void BaseChannel::ChannelNotWritable_n() { if (!writable_) return; - RTC_LOG(LS_INFO) << "Channel not writable (" << content_name_ << ")"; + RTC_LOG(LS_INFO) << "Channel not writable (" << ToString() << ")"; writable_ = false; UpdateMediaSendRecvState(); } @@ -632,7 +645,8 @@ bool BaseChannel::UpdateLocalStreams_w(const std::vector& streams, } if (media_channel()->AddSendStream(new_stream)) { - RTC_LOG(LS_INFO) << "Add send stream ssrc: " << new_stream.ssrcs[0]; + RTC_LOG(LS_INFO) << "Add send stream ssrc: " << new_stream.ssrcs[0] + << " into " << ToString(); } else { rtc::StringBuilder desc; desc << "Failed to add send stream ssrc: " << new_stream.first_ssrc(); @@ -655,11 +669,13 @@ bool BaseChannel::UpdateRemoteStreams_w( // the unsignaled stream params that are cached. if (!old_stream.has_ssrcs() && !HasStreamWithNoSsrcs(streams)) { ResetUnsignaledRecvStream_w(); - RTC_LOG(LS_INFO) << "Reset unsignaled remote stream."; + RTC_LOG(LS_INFO) << "Reset unsignaled remote stream for " << ToString() + << "."; } else if (old_stream.has_ssrcs() && !GetStreamBySsrc(streams, old_stream.first_ssrc())) { if (RemoveRecvStream_w(old_stream.first_ssrc())) { - RTC_LOG(LS_INFO) << "Remove remote ssrc: " << old_stream.first_ssrc(); + RTC_LOG(LS_INFO) << "Remove remote ssrc: " << old_stream.first_ssrc() + << " from " << ToString() << "."; } else { rtc::StringBuilder desc; desc << "Failed to remove remote stream with ssrc " @@ -681,13 +697,15 @@ bool BaseChannel::UpdateRemoteStreams_w( RTC_LOG(LS_INFO) << "Add remote ssrc: " << (new_stream.has_ssrcs() ? std::to_string(new_stream.first_ssrc()) - : "unsignaled"); + : "unsignaled") + << " to " << ToString(); } else { rtc::StringBuilder desc; desc << "Failed to add remote stream ssrc: " << (new_stream.has_ssrcs() ? std::to_string(new_stream.first_ssrc()) - : "unsignaled"); + : "unsignaled") + << " to " << ToString(); SafeSetError(desc.str(), error_desc); ret = false; } @@ -697,7 +715,9 @@ bool BaseChannel::UpdateRemoteStreams_w( new_stream.ssrcs.end()); } // Re-register the sink to update the receiving ssrcs. - RegisterRtpDemuxerSink(); + if (!RegisterRtpDemuxerSink()) { + RTC_LOG(LS_ERROR) << "Failed to set up demuxing for " << ToString(); + } remote_streams_ = streams; return ret; } @@ -813,7 +833,8 @@ void VoiceChannel::UpdateMediaSendRecvState_w() { bool send = IsReadyToSendMedia_w(); media_channel()->SetSend(send); - RTC_LOG(LS_INFO) << "Changing voice state, recv=" << recv << " send=" << send; + RTC_LOG(LS_INFO) << "Changing voice state, recv=" << recv << " send=" << send + << " for " << ToString(); } bool VoiceChannel::SetLocalContent_w(const MediaContentDescription* content, @@ -821,7 +842,7 @@ bool VoiceChannel::SetLocalContent_w(const MediaContentDescription* content, std::string* error_desc) { TRACE_EVENT0("webrtc", "VoiceChannel::SetLocalContent_w"); RTC_DCHECK_RUN_ON(worker_thread()); - RTC_LOG(LS_INFO) << "Setting local voice description"; + RTC_LOG(LS_INFO) << "Setting local voice description for " << ToString(); RTC_DCHECK(content); if (!content) { @@ -852,7 +873,7 @@ bool VoiceChannel::SetLocalContent_w(const MediaContentDescription* content, } // Need to re-register the sink to update the handled payload. if (!RegisterRtpDemuxerSink()) { - RTC_LOG(LS_ERROR) << "Failed to set up audio demuxing."; + RTC_LOG(LS_ERROR) << "Failed to set up audio demuxing for " << ToString(); return false; } } @@ -878,7 +899,7 @@ bool VoiceChannel::SetRemoteContent_w(const MediaContentDescription* content, std::string* error_desc) { TRACE_EVENT0("webrtc", "VoiceChannel::SetRemoteContent_w"); RTC_DCHECK_RUN_ON(worker_thread()); - RTC_LOG(LS_INFO) << "Setting remote voice description"; + RTC_LOG(LS_INFO) << "Setting remote voice description for " << ToString(); RTC_DCHECK(content); if (!content) { @@ -907,10 +928,11 @@ bool VoiceChannel::SetRemoteContent_w(const MediaContentDescription* content, if (!webrtc::RtpTransceiverDirectionHasSend(content->direction())) { RTC_DLOG(LS_VERBOSE) << "SetRemoteContent_w: remote side will not send - " - "disable payload type demuxing"; + "disable payload type demuxing for " + << ToString(); ClearHandledPayloadTypes(); if (!RegisterRtpDemuxerSink()) { - RTC_LOG(LS_ERROR) << "Failed to update audio demuxing."; + RTC_LOG(LS_ERROR) << "Failed to update audio demuxing for " << ToString(); return false; } } @@ -958,11 +980,12 @@ void VideoChannel::UpdateMediaSendRecvState_w() { // and we have had some form of connectivity. bool send = IsReadyToSendMedia_w(); if (!media_channel()->SetSend(send)) { - RTC_LOG(LS_ERROR) << "Failed to SetSend on video channel"; + RTC_LOG(LS_ERROR) << "Failed to SetSend on video channel: " + ToString(); // TODO(gangji): Report error back to server. } - RTC_LOG(LS_INFO) << "Changing video state, send=" << send; + RTC_LOG(LS_INFO) << "Changing video state, send=" << send << " for " + << ToString(); } void VideoChannel::FillBitrateInfo(BandwidthEstimationInfo* bwe_info) { @@ -975,7 +998,7 @@ bool VideoChannel::SetLocalContent_w(const MediaContentDescription* content, std::string* error_desc) { TRACE_EVENT0("webrtc", "VideoChannel::SetLocalContent_w"); RTC_DCHECK_RUN_ON(worker_thread()); - RTC_LOG(LS_INFO) << "Setting local video description"; + RTC_LOG(LS_INFO) << "Setting local video description for " << ToString(); RTC_DCHECK(content); if (!content) { @@ -1027,7 +1050,7 @@ bool VideoChannel::SetLocalContent_w(const MediaContentDescription* content, } // Need to re-register the sink to update the handled payload. if (!RegisterRtpDemuxerSink()) { - RTC_LOG(LS_ERROR) << "Failed to set up video demuxing."; + RTC_LOG(LS_ERROR) << "Failed to set up video demuxing for " << ToString(); return false; } } @@ -1061,7 +1084,7 @@ bool VideoChannel::SetRemoteContent_w(const MediaContentDescription* content, std::string* error_desc) { TRACE_EVENT0("webrtc", "VideoChannel::SetRemoteContent_w"); RTC_DCHECK_RUN_ON(worker_thread()); - RTC_LOG(LS_INFO) << "Setting remote video description"; + RTC_LOG(LS_INFO) << "Setting remote video description for " << ToString(); RTC_DCHECK(content); if (!content) { @@ -1120,10 +1143,11 @@ bool VideoChannel::SetRemoteContent_w(const MediaContentDescription* content, if (!webrtc::RtpTransceiverDirectionHasSend(content->direction())) { RTC_DLOG(LS_VERBOSE) << "SetRemoteContent_w: remote side will not send - " - "disable payload type demuxing"; + "disable payload type demuxing for " + << ToString(); ClearHandledPayloadTypes(); if (!RegisterRtpDemuxerSink()) { - RTC_LOG(LS_ERROR) << "Failed to update video demuxing."; + RTC_LOG(LS_ERROR) << "Failed to update video demuxing for " << ToString(); return false; } } @@ -1203,7 +1227,7 @@ bool RtpDataChannel::SetLocalContent_w(const MediaContentDescription* content, std::string* error_desc) { TRACE_EVENT0("webrtc", "RtpDataChannel::SetLocalContent_w"); RTC_DCHECK_RUN_ON(worker_thread()); - RTC_LOG(LS_INFO) << "Setting local data description"; + RTC_LOG(LS_INFO) << "Setting local data description for " << ToString(); RTC_DCHECK(content); if (!content) { @@ -1233,7 +1257,7 @@ bool RtpDataChannel::SetLocalContent_w(const MediaContentDescription* content, } // Need to re-register the sink to update the handled payload. if (!RegisterRtpDemuxerSink()) { - RTC_LOG(LS_ERROR) << "Failed to set up data demuxing."; + RTC_LOG(LS_ERROR) << "Failed to set up data demuxing for " << ToString(); return false; } @@ -1258,7 +1282,7 @@ bool RtpDataChannel::SetRemoteContent_w(const MediaContentDescription* content, std::string* error_desc) { TRACE_EVENT0("webrtc", "RtpDataChannel::SetRemoteContent_w"); RTC_DCHECK_RUN_ON(worker_thread()); - RTC_LOG(LS_INFO) << "Setting remote data description"; + RTC_LOG(LS_INFO) << "Setting remote data description for " << ToString(); RTC_DCHECK(content); if (!content) { @@ -1280,7 +1304,7 @@ bool RtpDataChannel::SetRemoteContent_w(const MediaContentDescription* content, RtpHeaderExtensions rtp_header_extensions = GetFilteredRtpHeaderExtensions(data->rtp_header_extensions()); - RTC_LOG(LS_INFO) << "Setting remote data description"; + RTC_LOG(LS_INFO) << "Setting remote data description for " << ToString(); DataSendParameters send_params = last_send_params_; RtpSendParametersFromMediaDescription( data, rtp_header_extensions, @@ -1311,20 +1335,21 @@ void RtpDataChannel::UpdateMediaSendRecvState_w() { // content. We receive data on the default channel and multiplexed streams. bool recv = IsReadyToReceiveMedia_w(); if (!media_channel()->SetReceive(recv)) { - RTC_LOG(LS_ERROR) << "Failed to SetReceive on data channel"; + RTC_LOG(LS_ERROR) << "Failed to SetReceive on data channel: " << ToString(); } // Send outgoing data if we're the active call, we have the remote content, // and we have had some form of connectivity. bool send = IsReadyToSendMedia_w(); if (!media_channel()->SetSend(send)) { - RTC_LOG(LS_ERROR) << "Failed to SetSend on data channel"; + RTC_LOG(LS_ERROR) << "Failed to SetSend on data channel: " << ToString(); } // Trigger SignalReadyToSendData asynchronously. OnDataChannelReadyToSend(send); - RTC_LOG(LS_INFO) << "Changing data state, recv=" << recv << " send=" << send; + RTC_LOG(LS_INFO) << "Changing data state, recv=" << recv << " send=" << send + << " for " << ToString(); } void RtpDataChannel::OnMessage(rtc::Message* pmsg) { diff --git a/pc/channel.h b/pc/channel.h index 238a8e20fe..9dc652236a 100644 --- a/pc/channel.h +++ b/pc/channel.h @@ -275,6 +275,9 @@ class BaseChannel : public ChannelInterface, bool RegisterRtpDemuxerSink(); + // Return description of media channel to facilitate logging + std::string ToString() const; + bool has_received_packet_ = false; private: