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/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.
+#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;
+  }
+  return RelDebugEvent::UNKNOWN_EVENT;

[ivoc, 2015/07/17 12:14:29]

Can you add the RTC_NOTREACHED() macro here as well?

[terelius, 2015/07/17 15:17:40]

Done.

+}
+
+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 RelVideoReceiveConfig::RTCP_COMPOUND;  // Silence stupid compilers

[ivoc, 2015/07/17 12:14:29]

Although I agree with your sentiment, maybe we can rephrase it to something a
little more neutral like "Avoid warning on less clever compilers" or something
similar.

[terelius, 2015/07/17 15:17:40]

Done.

+}
+
+
+RelRtpPacket_PayloadType ConvertRtpPayloadType(MediaType media_type) {
+  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;
+  }
+  RTC_NOTREACHED();
+  return RelRtpPacket::UNKNOWN_TYPE;  // Silence stupid compilers

[ivoc, 2015/07/17 12:14:28]

Same here

[terelius, 2015/07/17 15:17:40]

Done.

+}
+
+
+RelRtcpPacket_PayloadType ConvertRtcpPayloadType(MediaType media_type) {
+  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 RelRtcpPacket::UNKNOWN_TYPE;  // Silence stupid compilers

[ivoc, 2015/07/17 12:14:28]

And here.

[terelius, 2015/07/17 15:17:40]

Done.

+}
+
+}  // Anonymous namespace.
+
+// RtcEventLogImpl member functions.
+RtcEventLogImpl::RtcEventLogImpl()
+    : crit_(webrtc::CriticalSectionWrapper::CreateCriticalSection()),
+      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_) {
+    StoreToFile(&event);
+  }
+  recent_log_events_.clear();
+}
+
+void RtcEventLogImpl::LogVideoReceiveStreamConfig(
+    const webrtc::VideoReceiveStream::Config& config) {
+  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) {
+    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) {
+    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) {
+    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;
+  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) {
+    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);
+  rtp_event.mutable_rtp_packet()->set_type(ConvertRtpPayloadType(media_type));
+  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