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: