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 <tommi@webrtc.org>
Reviewed-by: Tommi <tommi@webrtc.org>
Cr-Commit-Position: refs/heads/master@{#31302}
This commit is contained in:
Yura Yaroshevich 2020-05-18 13:26:14 +03:00 committed by Commit Bot
parent 8ce078de5d
commit c325246753
2 changed files with 68 additions and 40 deletions

View File

@ -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<rtc::NetworkRoute> 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<StreamParams>& 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<DataCodec>(
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) {

View File

@ -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: