Adds logging of configuration information for VideoReceiveStream

webrtc/video/rtc_event_log.cc

+/*
+ *  Copyright (c) 2015 The WebRTC project authors. All Rights Reserved.
+ *
+ *  Use of this source code is governed by a BSD-style license
+ *  that can be found in the LICENSE file in the root of the source
+ *  tree. An additional intellectual property rights grant can be found
+ *  in the file PATENTS.  All contributing project authors may
+ *  be found in the AUTHORS file in the root of the source tree.
+ */
+
+#include "webrtc/video/rtc_event_log.h"
+
+#include <deque>
+
+#include "webrtc/base/checks.h"
+#include "webrtc/base/thread_annotations.h"
+#include "webrtc/call.h"  // For MediaType definition

[pbos-webrtc, 2015/07/22 11:05:27]

Remove comment

[terelius, 2015/07/23 15:54:00]

Done.

+#include "webrtc/system_wrappers/interface/clock.h"
+#include "webrtc/system_wrappers/interface/critical_section_wrapper.h"
+#include "webrtc/system_wrappers/interface/file_wrapper.h"
+
+#ifdef ENABLE_RTC_EVENT_LOG
+// Files generated at build-time by the protobuf compiler.
+#ifdef WEBRTC_ANDROID_PLATFORM_BUILD
+#include "external/webrtc/webrtc/video/rtc_event_log.pb.h"
+#else
+#include "webrtc/video/rtc_event_log.pb.h"
+#endif
+#endif
+
+namespace webrtc {
+
+// Noop implementation if flag is not set.

[pbos-webrtc, 2015/07/22 11:05:26]

No-op

[terelius, 2015/07/23 15:54:00]

Done.

+#ifndef ENABLE_RTC_EVENT_LOG
+class RtcEventLogImpl final : public RtcEventLog {
+ public:
+  void StartLogging(const std::string& file_name, int duration_ms) override {};
+  void LogVideoReceiveStreamConfig(
+      const webrtc::VideoReceiveStream::Config& config) override{};
+  void LogVideoSendStreamConfig(
+      const webrtc::VideoSendStream::Config& config) override{};
+  void LogRtpHeader(bool incoming,
+                    MediaType media_type,
+                    const uint8_t* header,
+                    size_t header_length,
+                    size_t total_length) override{};
+  void LogRtcpPacket(bool incoming,
+                     MediaType media_type,
+                     const uint8_t* packet,
+                     size_t length) override{};
+  void LogDebugEvent(DebugEvent event_type,
+                     const std::string& event_message) override{};
+  void LogDebugEvent(DebugEvent event_type) override{};
+};
+#else
+
+class RtcEventLogImpl final : public RtcEventLog {
+ public:
+  RtcEventLogImpl();
+
+  void StartLogging(const std::string& file_name, int duration_ms) override;
+  void LogVideoReceiveStreamConfig(
+      const webrtc::VideoReceiveStream::Config& config) override;
+  void LogVideoSendStreamConfig(
+      const webrtc::VideoSendStream::Config& config) override;
+  void LogRtpHeader(bool incoming,
+                    MediaType media_type,
+                    const uint8_t* header,
+                    size_t header_length,
+                    size_t total_length) override;
+  void LogRtcpPacket(bool incoming,
+                     MediaType media_type,
+                     const uint8_t* packet,
+                     size_t length) override;
+  void LogDebugEvent(DebugEvent event_type,
+                     const std::string& event_message) override;
+  void LogDebugEvent(DebugEvent event_type) override;
+
+ private:
+  // This function is identical to LogDebugEvent, but requires holding the lock.
+  void LogDebugEventLocked(DebugEvent event_type,
+                           const std::string& event_message)
+      EXCLUSIVE_LOCKS_REQUIRED(crit_);
+  // Stops logging and clears the stored data and buffers.
+  void Clear() EXCLUSIVE_LOCKS_REQUIRED(crit_);
+  // Adds a new event to the logfile if logging is active, or adds it to the
+  // list of recent log events otherwise.
+  void HandleEvent(RelEvent* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
+  // Writes the event to the file. Note that this will destroy the state of the
+  // input argument.
+  void StoreToFile(RelEvent* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
+  // Adds the event to the list of recent events, and removes any events that
+  // are too old and no longer fall in the time window.
+  void AddRecentEvent(const RelEvent& event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
+
+  // Amount of time in microseconds to record log events, before starting the
+  // actual log.
+  const int recent_log_duration_us = 10000000;
+
+  rtc::scoped_ptr<webrtc::CriticalSectionWrapper> crit_;
+  rtc::scoped_ptr<webrtc::FileWrapper> file_ GUARDED_BY(crit_);
+  rtc::scoped_ptr<RelEventStream> stream_ GUARDED_BY(crit_);
+  std::deque<RelEvent> recent_log_events_ GUARDED_BY(crit_);
+  bool currently_logging_ GUARDED_BY(crit_);
+  int64_t start_time_us_ GUARDED_BY(crit_);
+  int64_t duration_us_ GUARDED_BY(crit_);
+  const webrtc::Clock* const clock_;
+};
+
+namespace {
+// The functions in this namespace convert enums from the runtime format
+// that the rest of the WebRtc project can use, to the corresponding
+// serialized enum which is defined by the protobuf.
+
+// Do not add default return values to the conversion functions in this
+// unnamed namespace. The intention is to make the compiler warn if anyone
+// adds unhandled new events/modes/etc.
+
+RelDebugEvent_EventType ConvertDebugEvent(RtcEventLog::DebugEvent event_type) {
+  switch (event_type) {
+    case RtcEventLog::DebugEvent::kLogStart:
+      return RelDebugEvent::LOG_START;
+    case RtcEventLog::DebugEvent::kLogEnd:
+      return RelDebugEvent::LOG_END;
+    case RtcEventLog::DebugEvent::kAudioPlayout:
+      return RelDebugEvent::AUDIO_PLAYOUT;
+  }
+  RTC_NOTREACHED();  // Return something only to avoid certain compiler warnings

[pbos-webrtc, 2015/07/22 11:05:27]

Remove comment, it's very obvious (conveyed by RTC_NOTREACHED();). Here and
below.

[terelius, 2015/07/23 15:54:01]

Done.

+  return RelDebugEvent::UNKNOWN_EVENT;
+}
+
+RelVideoReceiveConfig_RtcpMode ConvertRtcpMode(newapi::RtcpMode rtcp_mode) {
+  switch (rtcp_mode) {
+    case newapi::kRtcpCompound:
+      return RelVideoReceiveConfig::RTCP_COMPOUND;
+    case newapi::kRtcpReducedSize:
+      return RelVideoReceiveConfig::RTCP_REDUCEDSIZE;
+  }
+  RTC_NOTREACHED();  // Return something only to avoid certain compiler warnings
+  return RelVideoReceiveConfig::RTCP_COMPOUND;
+}
+
+
+RelRtpPacket_PayloadType ConvertRtpPayloadType(MediaType media_type) {

[pbos-webrtc, 2015/07/22 11:05:26]

This is not a payload type. RTP payload types have a special meaning, 101 can be
VP8, since this is not the 7-bit payload type, rename it. Why not call it
RelRtpPacket_MediaType?

[terelius, 2015/07/23 15:54:01]

This is not really related to my CL, and since I wanted to keep it as small and
focused as possible, I figured it would be better to just put a comment in the
protobuf file that our current usage does not match the fields (or indeed name)
very well.

I'll change this to MediaType though.

+  switch (media_type) {
+    case  MediaType::VIDEO:
+      return RelRtpPacket::VIDEO;
+    case MediaType::AUDIO:
+      return RelRtpPacket::AUDIO;
+    case MediaType::DATA:  // Fall through
+    case MediaType::ANY:
+      return RelRtpPacket::UNKNOWN_TYPE;

[pbos-webrtc, 2015/07/22 11:05:27]

Should any "ANY" or "DATA" stamped packets enter here? If not, put a
RTC_NOTREACHED().

[terelius, 2015/07/23 15:54:00]

It was unclear what UNKNOWN_TYPE was for, but presumably it would be used for
everything that wasn't audio or video. I've now removed the UNKNOWN_TYPE field
and added fields for ANY and DATA instead.

[ivoc, 2015/07/24 08:06:04]

The reason for UNKNOWN_TYPE is that when you add a field in the future to the
enum in the protobuf, all old code will read those new types as UNKNOWN_TYPE
(basically whatever happens to be element 0 of the enum). If element 0 is an
actual meaningful type (like now), it will cause problems in the old code.
Therefore I suggest adding back UNKNOWN_TYPE, and not using it. 

[pbos-webrtc, 2015/07/24 11:43:40]

Don't understand this one, are you expecting to parse new protobufs with old
code?

[terelius, 2015/07/24 11:58:41]

By reading the generated protobuf code I've found that when one
attempts to parse a new (ie unknown) enum value, the code will not
write anything to the enum. A default constructed enum will thus
be left in it's 0 state which would correspond to the UNKNOWN_TYPE.
However, the has_bits will also remain zero, so we can detect
that no (valid) enum type has been found by checking has_type()
before accessing type(). This is the approach the current code is
taking.

[ivoc, 2015/07/24 12:07:27]

Well, not planning on it, but it might happen. It is listed as a best practice
on go/protodosdonts to do this. 
Anyway, after some discussion with terelius@, I changed my mind and agree that
in this case it's not particularly useful, mostly due to the mismatch with
existing WebRTC data structures when parsing.

+  }
+  RTC_NOTREACHED();  // Return something only to avoid certain compiler warnings
+  return RelRtpPacket::UNKNOWN_TYPE;
+}
+
+
+RelRtcpPacket_PayloadType ConvertRtcpPayloadType(MediaType media_type) {

[pbos-webrtc, 2015/07/22 11:05:26]

Same here, payload type is "kind-of reserved".

[terelius, 2015/07/23 15:54:00]

Done.

+  switch (media_type) {
+    case MediaType::VIDEO:
+      return RelRtcpPacket::VIDEO;
+    case MediaType::AUDIO:
+      return RelRtcpPacket::AUDIO;
+    case MediaType::DATA:  // Fall through
+    case MediaType::ANY:
+      return RelRtcpPacket::UNKNOWN_TYPE;
+  }
+  RTC_NOTREACHED();  // Return something only to avoid certain compiler warnings
+  return RelRtcpPacket::UNKNOWN_TYPE;
+}
+
+}  // Anonymous namespace.
+
+// RtcEventLogImpl member functions.
+RtcEventLogImpl::RtcEventLogImpl()
+    : crit_(webrtc::CriticalSectionWrapper::CreateCriticalSection()),

[pbos-webrtc, 2015/07/22 11:05:27]

Use a rtc::CriticalSection (this doesn't require additional heap allocation).
We're trying to move off webrtc::CriticalSectionWrapper.

[terelius, 2015/07/23 15:54:00]

Done. Please review the locking changes extra carefully as I am unfamiliar with
both the existing code and webrtc's locks.

[pbos-webrtc, 2015/07/24 11:43:40]

The GUARDED_BY macros above are your friend (they make sure you hold the lock
while accessing the members).

+      file_(webrtc::FileWrapper::Create()),
+      stream_(new webrtc::RelEventStream()),
+      currently_logging_(false),
+      start_time_us_(0),
+      duration_us_(0),
+      clock_(webrtc::Clock::GetRealTimeClock()) {
+}
+
+void RtcEventLogImpl::StartLogging(const std::string& file_name,
+                                   int duration_ms) {
+  CriticalSectionScoped lock(crit_.get());
+  Clear();
+  if (file_->OpenFile(file_name.c_str(), false) != 0) {
+    return;
+  }
+
+  // Add LOG_START event to the recent event list. This call will also remove
+  // any events that are too old from the recent event list.
+  LogDebugEventLocked(DebugEvent::kLogStart, "");
+  currently_logging_ = true;
+  start_time_us_ = clock_->TimeInMicroseconds();
+  duration_us_ = static_cast<int64_t>(duration_ms) * 1000;
+  // Write all the recent events to the log file.
+  for (auto& event : recent_log_events_) {

[pbos-webrtc, 2015/07/22 11:05:26]

Remove {}s

[terelius, 2015/07/23 15:54:00]

All other loops and if-statements use braces, even if the body is only a single
line. I'd like to keep the braces for consistency.

+    StoreToFile(&event);
+  }
+  recent_log_events_.clear();
+}
+
+void RtcEventLogImpl::LogVideoReceiveStreamConfig(
+    const webrtc::VideoReceiveStream::Config& config) {

[pbos-webrtc, 2015/07/22 11:05:26]

Remove all webrtc::, you're under the webrtc namespace.

[terelius, 2015/07/23 15:54:00]

Done.

+  CriticalSectionScoped lock(crit_.get());
+
+  RelEvent event;
+  const int64_t timestamp = clock_->TimeInMicroseconds();
+  event.set_timestamp_us(timestamp);
+  event.set_type(webrtc::RelEvent::RECEIVER_CONFIG_EVENT);
+
+  RelVideoReceiveConfig* receiver_config = event.mutable_receiver_config();
+  receiver_config->set_remote_ssrc(config.rtp.remote_ssrc);
+  receiver_config->set_local_ssrc(config.rtp.local_ssrc);
+
+  receiver_config->set_rtcp_mode(ConvertRtcpMode(config.rtp.rtcp_mode));
+
+  receiver_config->set_receiver_reference_time_report(
+      config.rtp.rtcp_xr.receiver_reference_time_report);
+  receiver_config->set_remb(config.rtp.remb);
+
+  for (const auto& config_rtx : config.rtp.rtx) {

[pbos-webrtc, 2015/07/22 11:05:27]

s/config_rtx/kv, I think. We do this in a bunch of places for maps.

[terelius, 2015/07/23 15:54:00]

Done.

+    RtxMap* rtx = receiver_config->add_rtx_map();
+    rtx->set_payload_type(config_rtx.first);
+    rtx->mutable_config()->set_rtx_ssrc(config_rtx.second.ssrc);
+    rtx->mutable_config()->set_rtx_payload_type(config_rtx.second.payload_type);
+  }
+
+  for (const auto& config_extension : config.rtp.extensions) {

[pbos-webrtc, 2015/07/22 11:05:26]

extension

[terelius, 2015/07/23 15:54:00]

extension is already used. I'll rename the loop variable to e.

+    RtpHeaderExtension* extension = receiver_config->add_header_extensions();
+    extension->set_name(config_extension.name);
+    extension->set_id(config_extension.id);
+  }
+
+  for (const auto& config_decoder : config.decoders) {

[pbos-webrtc, 2015/07/22 11:05:26]

decoder, and switch below DecoderConfig to decoder_config

[terelius, 2015/07/23 15:54:01]

decoder is already used. I'll rename the loop variable to d.

+    DecoderConfig* decoder = receiver_config->add_decoders();
+    decoder->set_name(config_decoder.payload_name);
+    decoder->set_payload_type(config_decoder.payload_type);
+  }
+  // TODO(terelius): We should use a separate event queue for config events.
+  // The current approach of storing the configuration together with the
+  // RTP events causes the configuration information to be removed 10s
+  // after the ReceiveStream is created.
+  HandleEvent(&event);
+}
+
+void RtcEventLogImpl::LogVideoSendStreamConfig(
+    const webrtc::VideoSendStream::Config& config) {
+  CriticalSectionScoped lock(crit_.get());
+
+  RelEvent event;

[pbos-webrtc, 2015/07/22 11:05:26]

What's the "Rel" in "RelEvent" supposed to mean? Does "LogEvent" or "RtcEvent"
make more sense here?

[terelius, 2015/07/23 15:54:00]

It originated as an abbreviation of RtcEventLog. Names like
RtcEventLogEventStream and RtcEventLogVideoReceiverConfig were cumbersome both
to read and to write.

We'll see how the code looks after placing the protobuf types in a separate
namespace and dropping the Rel prefix.

+  const int64_t timestamp = clock_->TimeInMicroseconds();
+  event.set_timestamp_us(timestamp);
+  event.set_type(webrtc::RelEvent::SENDER_CONFIG_EVENT);
+
+  RelVideoSendConfig* sender_config = event.mutable_sender_config();
+
+  for (const auto& ssrc : config.rtp.ssrcs) {

[pbos-webrtc, 2015/07/22 11:05:26]

Remove {}s

[terelius, 2015/07/23 15:54:00]

All other loops and if-statements use braces, even if the body is only a single
line. I'd like to keep the braces for consistency.

+    sender_config->add_ssrcs(ssrc);
+  }
+
+  for (const auto& config_extension : config.rtp.extensions) {
+    RtpHeaderExtension* extension = sender_config->add_header_extensions();
+    extension->set_name(config_extension.name);
+    extension->set_id(config_extension.id);
+  }
+
+  for (const auto& rtx_ssrc : config.rtp.rtx.ssrcs) {
+    sender_config->add_rtx_ssrcs(rtx_ssrc);
+  }
+  sender_config->set_rtx_payload_type(config.rtp.rtx.payload_type);
+
+  sender_config->set_c_name(config.rtp.c_name);
+
+  EncoderConfig* encoder = sender_config->mutable_encoder();
+  encoder->set_name(config.encoder_settings.payload_name);
+  encoder->set_payload_type(config.encoder_settings.payload_type);
+
+  // TODO(terelius): We should use a separate event queue for config events.
+  // The current approach of storing the configuration together with the
+  // RTP events causes the configuration information to be removed 10s
+  // after the ReceiveStream is created.
+  HandleEvent(&event);
+}
+
+void RtcEventLogImpl::LogRtpHeader(bool incoming,
+                                   MediaType media_type,
+                                   const uint8_t* header,
+                                   size_t header_length,
+                                   size_t total_length) {
+  CriticalSectionScoped lock(crit_.get());
+  RelEvent rtp_event;
+  const int64_t timestamp = clock_->TimeInMicroseconds();
+  rtp_event.set_timestamp_us(timestamp);
+  rtp_event.set_type(webrtc::RelEvent::RTP_EVENT);
+  rtp_event.mutable_rtp_packet()->set_direction(
+      incoming ? RelRtpPacket::INCOMING : RelRtpPacket::OUTGOING);

[pbos-webrtc, 2015/07/22 11:05:26]

Do we need separate direction types for RTP and RTCP? Also, Rel?
PacketDirection::INCOMING/OUTGOING?

[terelius, 2015/07/23 15:54:00]

I changed to use a bool instead. I have a hard time imagining a situation where
we dont know which direction the packets are travelling...

+  rtp_event.mutable_rtp_packet()->set_type(ConvertRtpPayloadType(media_type));

[pbos-webrtc, 2015/07/22 11:05:26]

Not PayloadType

[terelius, 2015/07/23 15:54:01]

Changed to ConvertMediaType

+  rtp_event.mutable_rtp_packet()->set_packet_length(total_length);
+  rtp_event.mutable_rtp_packet()->set_header(header, header_length);
+  HandleEvent(&rtp_event);
+}
+
+void RtcEventLogImpl::LogRtcpPacket(bool incoming,
+                                    MediaType media_type,
+                                    const uint8_t* packet,
+                                    size_t length) {
+  CriticalSectionScoped lock(crit_.get());
+  RelEvent rtcp_event;
+  const int64_t timestamp = clock_->TimeInMicroseconds();
+  rtcp_event.set_timestamp_us(timestamp);
+  rtcp_event.set_type(webrtc::RelEvent::RTCP_EVENT);
+  rtcp_event.mutable_rtcp_packet()->set_direction(
+      incoming ? RelRtcpPacket::INCOMING : RelRtcpPacket::OUTGOING);
+  rtcp_event.mutable_rtcp_packet()->set_type(
+      ConvertRtcpPayloadType(media_type));
+  rtcp_event.mutable_rtcp_packet()->set_data(packet, length);
+  HandleEvent(&rtcp_event);
+}
+
+void RtcEventLogImpl::LogDebugEvent(DebugEvent event_type,
+                                    const std::string& event_message) {
+  CriticalSectionScoped lock(crit_.get());
+  LogDebugEventLocked(event_type, event_message);
+}
+
+void RtcEventLogImpl::LogDebugEvent(DebugEvent event_type) {
+  CriticalSectionScoped lock(crit_.get());
+  LogDebugEventLocked(event_type, "");
+}
+
+void RtcEventLogImpl::LogDebugEventLocked(DebugEvent event_type,
+                                          const std::string& event_message) {
+  RelEvent event;
+  int64_t timestamp = clock_->TimeInMicroseconds();
+  event.set_timestamp_us(timestamp);
+  event.set_type(webrtc::RelEvent::DEBUG_EVENT);
+  auto debug_event = event.mutable_debug_event();
+  debug_event->set_type(ConvertDebugEvent(event_type));
+  debug_event->set_message(event_message);
+  HandleEvent(&event);
+}
+
+void RtcEventLogImpl::Clear() {
+  if (file_->Open()) {
+    file_->CloseFile();
+  }
+  currently_logging_ = false;
+  stream_->Clear();
+}
+
+void RtcEventLogImpl::HandleEvent(RelEvent* event) {
+  if (currently_logging_) {
+    if (clock_->TimeInMicroseconds() < start_time_us_ + duration_us_) {
+      StoreToFile(event);
+    } else {
+      LogDebugEventLocked(DebugEvent::kLogEnd, "");
+      Clear();
+      AddRecentEvent(*event);
+    }
+  } else {
+    AddRecentEvent(*event);
+  }
+}
+
+void RtcEventLogImpl::StoreToFile(RelEvent* event) {
+  // Reuse the same object at every log event.
+  if (stream_->stream_size() < 1) {
+    stream_->add_stream();
+  }
+  DCHECK_EQ(stream_->stream_size(), 1);
+  stream_->mutable_stream(0)->Swap(event);
+
+  std::string dump_buffer;
+  stream_->SerializeToString(&dump_buffer);
+  file_->Write(dump_buffer.data(), dump_buffer.size());
+}
+
+void RtcEventLogImpl::AddRecentEvent(const RelEvent& event) {
+  recent_log_events_.push_back(event);
+  while (recent_log_events_.front().timestamp_us() <
+         event.timestamp_us() - recent_log_duration_us) {
+    recent_log_events_.pop_front();
+  }
+}
+
+bool RtcEventLog::ParseRtcEventLog(const std::string& file_name,
+                                   RelEventStream* result) {
+  char tmp_buffer[1024];
+  int bytes_read = 0;
+  rtc::scoped_ptr<FileWrapper> dump_file(FileWrapper::Create());
+  if (dump_file->OpenFile(file_name.c_str(), true) != 0) {
+    return false;
+  }
+  std::string dump_buffer;
+  while ((bytes_read = dump_file->Read(tmp_buffer, sizeof(tmp_buffer))) > 0) {
+    dump_buffer.append(tmp_buffer, bytes_read);
+  }
+  dump_file->CloseFile();
+  return result->ParseFromString(dump_buffer);
+}
+
+#endif  // ENABLE_RTC_EVENT_LOG
+
+// RtcEventLog member functions.
+rtc::scoped_ptr<RtcEventLog> RtcEventLog::Create() {
+  return rtc::scoped_ptr<RtcEventLog>(new RtcEventLogImpl());
+}
+}  // namespace webrtc