Keep config events in RtcEventLog even if they are old.

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.
  */
 
@@ skipping 17 matching lines @@
 #endif
 #endif
 
 namespace webrtc {
 
 #ifndef ENABLE_RTC_EVENT_LOG
 
 // No-op implementation if flag is not set.
 class RtcEventLogImpl final : public RtcEventLog {
  public:
+  void SetBufferDuration(int64_t recent_log_duration_us) override {}
   void StartLogging(const std::string& file_name, int duration_ms) override {}
   void StopLogging(void) override {}
   void LogVideoReceiveStreamConfig(
       const VideoReceiveStream::Config& config) override {}
   void LogVideoSendStreamConfig(
       const 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) override {}
 };
 
 #else  // ENABLE_RTC_EVENT_LOG is defined
 
 class RtcEventLogImpl final : public RtcEventLog {
  public:
   RtcEventLogImpl();
 
+  void SetBufferDuration(int64_t recent_log_duration_us) override;
   void StartLogging(const std::string& file_name, int duration_ms) override;
   void StopLogging() override;
   void LogVideoReceiveStreamConfig(
       const VideoReceiveStream::Config& config) override;
   void LogVideoSendStreamConfig(const VideoSendStream::Config& config) override;
   void LogRtpHeader(bool incoming,
                     MediaType media_type,
                     const uint8_t* header,
                     size_t header_length,
                     size_t total_length) override;
@@ skipping 10 matching lines @@
   // list of recent log events otherwise.
   void HandleEvent(rtclog::Event* event) EXCLUSIVE_LOCKS_REQUIRED(crit_);
   // Writes the event to the file. Note that this will destroy the state of the
   // input argument.
   void StoreToFile(rtclog::Event* 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 rtclog::Event& 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::CriticalSection crit_;
   rtc::scoped_ptr<FileWrapper> file_ GUARDED_BY(crit_);
   rtclog::EventStream stream_ GUARDED_BY(crit_);
   std::deque<rtclog::Event> recent_log_events_ GUARDED_BY(crit_);
+  std::vector<rtclog::Event> config_events_ GUARDED_BY(crit_);
+
+  // Microseconds to record log events, before starting the actual log.
+  int64_t recent_log_duration_us_ 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 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.
@@ skipping 42 matching lines @@
   RTC_NOTREACHED();
   return rtclog::ANY;
 }
 
 }  // namespace
 
 // RtcEventLogImpl member functions.
 RtcEventLogImpl::RtcEventLogImpl()
     : file_(FileWrapper::Create()),
       stream_(),
+      recent_log_duration_us_(10000000),
       currently_logging_(false),
       start_time_us_(0),
       duration_us_(0),
       clock_(Clock::GetRealTimeClock()) {
 }
 
+void RtcEventLogImpl::SetBufferDuration(int64_t recent_log_duration_us) {
+  rtc::CritScope lock(&crit_);
+  recent_log_duration_us_ = recent_log_duration_us;

[ivoc, 2015/08/25 08:03:21]

Shouldn't there be some sort of purging of the buffer in case the new value is
lower than the old value? (i.e. discard events that are too old due to the
buffer change)

[terelius, 2015/08/25 16:41:44]

The old events are purged whenever we add a new event to the queue or when we
call StartLogging.

[ivoc, 2015/08/26 08:15:28]

Acknowledged.

+}
+
 void RtcEventLogImpl::StartLogging(const std::string& file_name,
                                    int duration_ms) {
   rtc::CritScope lock(&crit_);
   if (currently_logging_) {
     StopLoggingLocked();
   }
   if (file_->OpenFile(file_name.c_str(), false) != 0) {
     return;
   }
   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, ignoring any old events.
+  // Write all old configuration events to the log file.
+  for (auto& event : config_events_) {
+    StoreToFile(&event);
+  }
+  // Write all recent configuration events to the log file, and
+  // write all other recent events to the log file, ignoring any old events.
   for (auto& event : recent_log_events_) {
-    if (event.timestamp_us() >= start_time_us_ - recent_log_duration_us) {
+    if (event.type() == rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT ||
+        event.type() == rtclog::Event::VIDEO_SENDER_CONFIG_EVENT ||
+        event.type() == rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT ||
+        event.type() == rtclog::Event::AUDIO_SENDER_CONFIG_EVENT) {
+      StoreToFile(&event);
+      config_events_.push_back(event);
+    } else if (event.timestamp_us() >=
+               start_time_us_ - recent_log_duration_us_) {
       StoreToFile(&event);
     }
   }
   recent_log_events_.clear();
   // Write a LOG_START event to the file.
   rtclog::Event start_event;
   start_event.set_timestamp_us(start_time_us_);
   start_event.set_type(rtclog::Event::DEBUG_EVENT);
   auto debug_event = start_event.mutable_debug_event();
   debug_event->set_type(ConvertDebugEvent(DebugEvent::kLogStart));
@@ skipping 37 matching lines @@
         receiver_config->add_header_extensions();
     extension->set_name(e.name);
     extension->set_id(e.id);
   }
 
   for (const auto& d : config.decoders) {
     rtclog::DecoderConfig* decoder = receiver_config->add_decoders();
     decoder->set_name(d.payload_name);
     decoder->set_payload_type(d.payload_type);
   }
   // TODO(terelius): We should use a separate event queue for config events.

[ivoc, 2015/08/25 08:03:21]

I guess this TODO can be removed in this CL.

[terelius, 2015/08/25 16:41:44]

Yeah, that was kind of the point of the CL. :)

   // 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 VideoSendStream::Config& config) {
   rtc::CritScope lock(&crit_);
 
@@ skipping 19 matching lines @@
     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);
 
   rtclog::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.

[ivoc, 2015/08/25 08:03:21]

This one as well.

[terelius, 2015/08/25 16:41:44]

Done.

   // 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);
 }
 
 // TODO(terelius): It is more convenient and less error prone to parse the
 // header length from the packet instead of relying on the caller to provide it.
 void RtcEventLogImpl::LogRtpHeader(bool incoming,
                                    MediaType media_type,
@@ skipping 78 matching lines @@
   // TODO(terelius): Doesn't this create a new EventStream per event?
   // Is this guaranteed to work e.g. in future versions of protobuf?
   std::string dump_buffer;
   stream_.SerializeToString(&dump_buffer);
   file_->Write(dump_buffer.data(), dump_buffer.size());
 }
 
 void RtcEventLogImpl::AddRecentEvent(const rtclog::Event& event) {
   recent_log_events_.push_back(event);
   while (recent_log_events_.front().timestamp_us() <
-         event.timestamp_us() - recent_log_duration_us) {
+         event.timestamp_us() - recent_log_duration_us_) {
+    rtclog::Event_EventType event_type = recent_log_events_.front().type();
+    if (event_type == rtclog::Event::VIDEO_RECEIVER_CONFIG_EVENT ||
+        event_type == rtclog::Event::VIDEO_SENDER_CONFIG_EVENT ||
+        event_type == rtclog::Event::AUDIO_RECEIVER_CONFIG_EVENT ||
+        event_type == rtclog::Event::AUDIO_SENDER_CONFIG_EVENT) {
+      config_events_.push_back(recent_log_events_.front());

[ivoc, 2015/08/25 08:03:21]

I wonder if we should be checking if any of the config events that are already
stored in config_events_ might become obsolete due to a newer config event. Is
that something that could happen?

[terelius, 2015/08/25 16:41:44]

This is a good point.

I don't think it is possible to reconfigure (video) streams during runtime.
However, it is possible to delete the stream and create a new one with the same
SSRC which would result in two config events for the "same" stream.

It is not clear whether we should resolve those ambiguities while writing the
log or when we read it. Doing the check here would not completely solve the
issue since we could potentially have multiple config events in the
recent_log_events queue.

[ivoc, 2015/08/26 08:15:28]

I think a check here would solve this problem. Even if the recent_events_ queue
contains another config event that will succeed one of the ones from the
config_events_ list, the one that is stored in config_events_ is still valid for
any older packets that are in the recent_events_ queue, and is therefore still
needed. Once the succeeding config event is too old for the recent_events_
queue, it can replace the old one in config_events_ since it is no longer
useful.

I'm not sure if it's better to solve this while writing or reading. I guess it
also depends on how likely it is that this happens. If it happens frequently, it
is not nice if the RtcEventLog starts collecting a whole list of config events
that are no longer valid. If it is rare, then it's probably acceptable to leave
it in. I don't know how often this happens in practice, maybe one of the other
reviewers can comment? If we decide to solve it while reading, I think it would
be good to document this behavior somewhere (maybe in the protobuf, or with the
parsing functions?).

[ivoc, 2015/09/25 15:30:23]

Could you respond to this? I still think it would be better to purge old configs
that are not needed to interpret any packets that appear in the log or in the
recentEvents_queue, and I don't think it would be that complicated to add that
feature (unless I'm missing something). 

[terelius, 2015/10/15 13:28:21]

So what you are proposing is checking whether there exists an older config in
config_events before adding a new config for the same SSRC?

The reason why I am hesitant is that we would add code for a rare event that
wont be tested exhaustively, yet we would not solve the problem completely. (We
could still have unused configurations for streams that are configured but never
receive or send any packets. We could also have two configurations for the
"same" stream if there are packets sent before the reconfiguration. Finally, if
the reconfiguration is done while we are logging then everything would be
written to file directly so there is no way to detect whether we have
unnecessary configurations.)

It is also slightly complicated to solve due to the fact that VideoSendConfig
doesn't have a single SSRC, but a whole vector of them. Handling configurations
with overlapping but nonidentical ssrc vectors will probably be ugly.

[ivoc, 2015/10/15 15:52:06]

Okay, let's stick to the simple solution for now. We can analyze later if there
actually is a problem in practice or if it's a complete non-issue (probably the
latter).

+    }
     recent_log_events_.pop_front();
   }
 }
 
 bool RtcEventLog::ParseRtcEventLog(const std::string& file_name,
                                    rtclog::EventStream* 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