RtcEventLogImpl: Add mocked time test.

This change adds mocked time unit tests to RtcEventLogImpl. In
order to simplify test implementation, the Impl ctor was changed
to accept an already created event log encoder. The previous
factory was made public in the Impl interface and relevant
code sites were updated.

Bug: chromium:1288710
Change-Id: Ifbfd899c5a06a3350c7e5fbc3bb7280f67124f2b
Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/290382
Reviewed-by: Henrik Andreassson <henrika@webrtc.org>
Commit-Queue: Markus Handell <handellm@webrtc.org>
Reviewed-by: Björn Terelius <terelius@webrtc.org>
Cr-Commit-Position: refs/heads/main@{#38987}

api/rtc_event_log/rtc_event.h

@@ -55,7 +55,8 @@ class RtcEvent {
     GenericAckReceived,
     FrameDecoded,
     BeginV3Log = 0x2501580,
-    EndV3Log = 0x2501581
+    EndV3Log = 0x2501581,
+    FakeEvent,  // For unit testing.
   };
 
   RtcEvent();

api/rtc_event_log/rtc_event_log_factory.cc

@@ -33,7 +33,8 @@ std::unique_ptr<RtcEventLog> RtcEventLogFactory::Create(
   if (field_trial::IsEnabled("WebRTC-RtcEventLogKillSwitch")) {
     return std::make_unique<RtcEventLogNull>();
   }
-  return std::make_unique<RtcEventLogImpl>(encoding_type, task_queue_factory_);
+  return std::make_unique<RtcEventLogImpl>(
+      RtcEventLogImpl::CreateEncoder(encoding_type), task_queue_factory_);
 #else
   return std::make_unique<RtcEventLogNull>();
 #endif

logging/BUILD.gn

@@ -354,7 +354,10 @@ rtc_source_set("rtc_event_log_impl_output") {
 
 if (rtc_enable_protobuf) {
   rtc_library("rtc_event_log_impl") {
-    visibility = [ "../api/rtc_event_log:rtc_event_log_factory" ]
+    visibility = [
+      ":rtc_event_log_tests",
+      "../api/rtc_event_log:rtc_event_log_factory",
+    ]
     sources = [
       "rtc_event_log/rtc_event_log_impl.cc",
       "rtc_event_log/rtc_event_log_impl.h",
@@ -481,6 +484,7 @@ if (rtc_enable_protobuf) {
         "rtc_event_log/encoder/rtc_event_log_encoder_unittest.cc",
         "rtc_event_log/events/rtc_event_field_encoding_unittest.cc",
         "rtc_event_log/events/rtc_event_field_extraction_unittest.cc",
+        "rtc_event_log/rtc_event_log_impl_unittest.cc",
         "rtc_event_log/rtc_event_log_unittest.cc",
         "rtc_event_log/rtc_event_log_unittest_helper.cc",
         "rtc_event_log/rtc_event_log_unittest_helper.h",
@@ -494,6 +498,7 @@ if (rtc_enable_protobuf) {
         ":rtc_event_frame_events",
         ":rtc_event_generic_packet_events",
         ":rtc_event_log2_proto",
+        ":rtc_event_log_impl",
         ":rtc_event_log_impl_encoder",
         ":rtc_event_log_parser",
         ":rtc_event_log_proto",
@@ -526,6 +531,7 @@ if (rtc_enable_protobuf) {
         "../test:fileutils",
         "../test:test_support",
         "../test/logging:log_writer",
+        "../test/time_controller",
         "//testing/gtest",
       ]
       absl_deps = [

logging/rtc_event_log/encoder/rtc_event_log_encoder_legacy.cc

@@ -374,6 +374,10 @@ std::string RtcEventLogEncoderLegacy::Encode(const RtcEvent& event) {
       // and stopping the log, and only as part of version 3 of the format.
       RTC_DCHECK_NOTREACHED();
       break;
+    case RtcEvent::Type::FakeEvent:
+      // Fake event used for unit test.
+      RTC_DCHECK_NOTREACHED();
+      break;
     case RtcEvent::Type::RouteChangeEvent:
     case RtcEvent::Type::GenericPacketReceived:
     case RtcEvent::Type::GenericPacketSent:

logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc

@@ -883,6 +883,10 @@ std::string RtcEventLogEncoderNewFormat::EncodeBatch(
           // and stopping the log, and only as part of version 3 of the format.
           RTC_DCHECK_NOTREACHED();
           break;
+        case RtcEvent::Type::FakeEvent:
+          // Fake event used for unit test.
+          RTC_DCHECK_NOTREACHED();
+          break;
       }
     }
 

logging/rtc_event_log/rtc_event_log_impl.cc

@@ -30,13 +30,8 @@
 #include "rtc_base/time_utils.h"
 
 namespace webrtc {
-namespace {
-constexpr size_t kMaxEventsInHistory = 10000;
-// The config-history is supposed to be unbounded, but needs to have some bound
-// to prevent an attack via unreasonable memory use.
-constexpr size_t kMaxEventsInConfigHistory = 1000;
 
-std::unique_ptr<RtcEventLogEncoder> CreateEncoder(
+std::unique_ptr<RtcEventLogEncoder> RtcEventLogImpl::CreateEncoder(
     RtcEventLog::EncodingType type) {
   switch (type) {
     case RtcEventLog::EncodingType::Legacy:
@@ -52,11 +47,14 @@ std::unique_ptr<RtcEventLogEncoder> CreateEncoder(
       return std::unique_ptr<RtcEventLogEncoder>(nullptr);
   }
 }
-}  // namespace
 
-RtcEventLogImpl::RtcEventLogImpl(RtcEventLog::EncodingType encoding_type,
-                                 TaskQueueFactory* task_queue_factory)
-    : event_encoder_(CreateEncoder(encoding_type)),
+RtcEventLogImpl::RtcEventLogImpl(std::unique_ptr<RtcEventLogEncoder> encoder,
+                                 TaskQueueFactory* task_queue_factory,
+                                 size_t max_events_in_history,
+                                 size_t max_config_events_in_history)
+    : max_events_in_history_(max_events_in_history),
+      max_config_events_in_history_(max_config_events_in_history),
+      event_encoder_(std::move(encoder)),
       num_config_events_written_(0),
       last_output_ms_(rtc::TimeMillis()),
       output_scheduled_(false),
@@ -152,7 +150,7 @@ void RtcEventLogImpl::Log(std::unique_ptr<RtcEvent> event) {
 
 void RtcEventLogImpl::ScheduleOutput() {
   RTC_DCHECK(event_output_ && event_output_->IsActive());
-  if (history_.size() >= kMaxEventsInHistory) {
+  if (history_.size() >= max_events_in_history_) {
     // We have to emergency drain the buffer. We can't wait for the scheduled
     // output task because there might be other event incoming before that.
     LogEventsFromMemoryToOutput();
@@ -190,8 +188,9 @@ void RtcEventLogImpl::ScheduleOutput() {
 void RtcEventLogImpl::LogToMemory(std::unique_ptr<RtcEvent> event) {
   std::deque<std::unique_ptr<RtcEvent>>& container =
       event->IsConfigEvent() ? config_history_ : history_;
-  const size_t container_max_size =
-      event->IsConfigEvent() ? kMaxEventsInConfigHistory : kMaxEventsInHistory;
+  const size_t container_max_size = event->IsConfigEvent()
+                                        ? max_config_events_in_history_
+                                        : max_events_in_history_;
 
   if (container.size() >= container_max_size) {
     RTC_DCHECK(!event_output_);  // Shouldn't lose events if we have an output.

logging/rtc_event_log/rtc_event_log_impl.h

@@ -33,13 +33,26 @@ namespace webrtc {
 
 class RtcEventLogImpl final : public RtcEventLog {
  public:
-  RtcEventLogImpl(EncodingType encoding_type,
-                  TaskQueueFactory* task_queue_factory);
+  // The max number of events that the history can store.
+  static constexpr size_t kMaxEventsInHistory = 10000;
+  // The max number of events that the config history can store.
+  // The config-history is supposed to be unbounded, but needs to have some
+  // bound to prevent an attack via unreasonable memory use.
+  static constexpr size_t kMaxEventsInConfigHistory = 1000;
+
+  RtcEventLogImpl(
+      std::unique_ptr<RtcEventLogEncoder> encoder,
+      TaskQueueFactory* task_queue_factory,
+      size_t max_events_in_history = kMaxEventsInHistory,
+      size_t max_config_events_in_history = kMaxEventsInConfigHistory);
   RtcEventLogImpl(const RtcEventLogImpl&) = delete;
   RtcEventLogImpl& operator=(const RtcEventLogImpl&) = delete;
 
   ~RtcEventLogImpl() override;
 
+  static std::unique_ptr<RtcEventLogEncoder> CreateEncoder(
+      EncodingType encoding_type);
+
   // TODO(eladalon): We should change these name to reflect that what we're
   // actually starting/stopping is the output of the log, not the log itself.
   bool StartLogging(std::unique_ptr<RtcEventLogOutput> output,
@@ -64,6 +77,12 @@ class RtcEventLogImpl final : public RtcEventLog {
 
   void ScheduleOutput() RTC_RUN_ON(task_queue_);
 
+  // Max size of event history.
+  const size_t max_events_in_history_;
+
+  // Max size of config event history.
+  const size_t max_config_events_in_history_;
+
   // History containing all past configuration events.
   std::deque<std::unique_ptr<RtcEvent>> config_history_
       RTC_GUARDED_BY(*task_queue_);

logging/rtc_event_log/rtc_event_log_impl_unittest.cc

@@ -0,0 +1,188 @@
+/*
+ *  Copyright (c) 2023 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 "logging/rtc_event_log/rtc_event_log_impl.h"
+
+#include <utility>
+#include <vector>
+
+#include "test/gmock.h"
+#include "test/gtest.h"
+#include "test/time_controller/simulated_time_controller.h"
+
+namespace webrtc {
+namespace {
+
+using ::testing::InSequence;
+using ::testing::Mock;
+using ::testing::Property;
+using ::testing::Ref;
+using ::testing::Return;
+using ::testing::StrEq;
+
+class MockEventEncoder : public RtcEventLogEncoder {
+ public:
+  MOCK_METHOD(std::string,
+              EncodeLogStart,
+              (int64_t /*timestamp_us*/, int64_t /*utc_time_us*/),
+              (override));
+  MOCK_METHOD(std::string,
+              EncodeLogEnd,
+              (int64_t /*timestamp_us*/),
+              (override));
+  MOCK_METHOD(std::string, OnEncode, (const RtcEvent&), ());
+  std::string EncodeBatch(
+      std::deque<std::unique_ptr<RtcEvent>>::const_iterator a,
+      std::deque<std::unique_ptr<RtcEvent>>::const_iterator b) override {
+    std::string result;
+    while (a != b) {
+      result += OnEncode(**a);
+      ++a;
+    }
+    return result;
+  }
+};
+
+class FakeOutput : public RtcEventLogOutput {
+ public:
+  explicit FakeOutput(std::string& written_data)
+      : written_data_(written_data) {}
+  bool IsActive() const { return true; }
+  bool Write(absl::string_view data) override {
+    written_data_.append(std::string(data));
+    return true;
+  }
+  void Flush() override {}
+
+ private:
+  std::string& written_data_;
+};
+
+class FakeEvent : public RtcEvent {
+ public:
+  Type GetType() const override { return RtcEvent::Type::FakeEvent; }
+  bool IsConfigEvent() const override { return false; }
+};
+
+class FakeConfigEvent : public RtcEvent {
+ public:
+  Type GetType() const override { return RtcEvent::Type::FakeEvent; }
+  bool IsConfigEvent() const override { return true; }
+};
+
+class RtcEventLogImplTest : public ::testing::Test {
+ public:
+  static constexpr size_t kMaxEventsInHistory = 2;
+  static constexpr size_t kMaxEventsInConfigHistory = 3;
+  static constexpr TimeDelta kOutputPeriod = TimeDelta::Seconds(2);
+  static constexpr Timestamp kStartTime = Timestamp::Seconds(1);
+
+  GlobalSimulatedTimeController time_controller_{kStartTime};
+  std::unique_ptr<MockEventEncoder> encoder_ =
+      std::make_unique<MockEventEncoder>();
+  MockEventEncoder* encoder_ptr_ = encoder_.get();
+  std::unique_ptr<FakeOutput> output_ =
+      std::make_unique<FakeOutput>(written_data_);
+  FakeOutput* output_ptr_ = output_.get();
+  RtcEventLogImpl event_log_{std::move(encoder_),
+                             time_controller_.GetTaskQueueFactory(),
+                             kMaxEventsInHistory, kMaxEventsInConfigHistory};
+  std::string written_data_;
+};
+
+TEST_F(RtcEventLogImplTest, WritesHeaderAndEventsAndTrailer) {
+  EXPECT_CALL(*encoder_ptr_, EncodeLogStart(kStartTime.us(), kStartTime.us()))
+      .WillOnce(Return("start"));
+  EXPECT_CALL(*encoder_ptr_, EncodeLogEnd(kStartTime.us()))
+      .WillOnce(Return("stop"));
+  EXPECT_CALL(*encoder_ptr_, OnEncode(Property(&RtcEvent::IsConfigEvent, true)))
+      .WillOnce(Return("config"));
+  EXPECT_CALL(*encoder_ptr_,
+              OnEncode(Property(&RtcEvent::IsConfigEvent, false)))
+      .WillOnce(Return("event"));
+  event_log_.StartLogging(std::move(output_), kOutputPeriod.ms());
+  event_log_.Log(std::make_unique<FakeEvent>());
+  event_log_.Log(std::make_unique<FakeConfigEvent>());
+  event_log_.StopLogging();
+  Mock::VerifyAndClearExpectations(encoder_ptr_);
+  EXPECT_TRUE(written_data_ == "startconfigeventstop" ||
+              written_data_ == "starteventconfigstop");
+}
+
+TEST_F(RtcEventLogImplTest, KeepsMostRecentEventsOnStart) {
+  auto e2 = std::make_unique<FakeEvent>();
+  RtcEvent* e2_ptr = e2.get();
+  auto e3 = std::make_unique<FakeEvent>();
+  RtcEvent* e3_ptr = e3.get();
+  event_log_.Log(std::make_unique<FakeEvent>());
+  event_log_.Log(std::move(e2));
+  event_log_.Log(std::move(e3));
+  InSequence s;
+  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*e2_ptr)));
+  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*e3_ptr)));
+  event_log_.StartLogging(std::move(output_), kOutputPeriod.ms());
+  time_controller_.AdvanceTime(TimeDelta::Zero());
+  Mock::VerifyAndClearExpectations(encoder_ptr_);
+}
+
+TEST_F(RtcEventLogImplTest, EncodesEventsOnHistoryFullPostponesLastEncode) {
+  auto e1 = std::make_unique<FakeEvent>();
+  RtcEvent* e1_ptr = e1.get();
+  auto e2 = std::make_unique<FakeEvent>();
+  RtcEvent* e2_ptr = e2.get();
+  auto e3 = std::make_unique<FakeEvent>();
+  RtcEvent* e3_ptr = e3.get();
+  event_log_.StartLogging(std::move(output_), kOutputPeriod.ms());
+  time_controller_.AdvanceTime(TimeDelta::Zero());
+  event_log_.Log(std::move(e1));
+  event_log_.Log(std::move(e2));
+  // Overflows and causes immediate output, and eventual output after the output
+  // period has passed.
+  event_log_.Log(std::move(e3));
+  InSequence s;
+  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*e1_ptr)));
+  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*e2_ptr)));
+  time_controller_.AdvanceTime(TimeDelta::Zero());
+  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*e3_ptr)));
+  time_controller_.AdvanceTime(kOutputPeriod);
+  Mock::VerifyAndClearExpectations(encoder_ptr_);
+}
+
+TEST_F(RtcEventLogImplTest, RewritesConfigEventsOnlyOnRestart) {
+  event_log_.StartLogging(std::make_unique<FakeOutput>(written_data_),
+                          kOutputPeriod.ms());
+  event_log_.Log(std::make_unique<FakeConfigEvent>());
+  event_log_.Log(std::make_unique<FakeEvent>());
+  event_log_.StopLogging();
+  EXPECT_CALL(*encoder_ptr_,
+              OnEncode(Property(&RtcEvent::IsConfigEvent, true)));
+  EXPECT_CALL(*encoder_ptr_,
+              OnEncode(Property(&RtcEvent::IsConfigEvent, false)))
+      .Times(0);
+  event_log_.StartLogging(std::move(output_), kOutputPeriod.ms());
+  time_controller_.AdvanceTime(TimeDelta::Zero());
+  Mock::VerifyAndClearExpectations(encoder_ptr_);
+}
+
+TEST_F(RtcEventLogImplTest, SchedulesWriteAfterOutputDurationPassed) {
+  event_log_.StartLogging(std::make_unique<FakeOutput>(written_data_),
+                          kOutputPeriod.ms());
+  event_log_.Log(std::make_unique<FakeConfigEvent>());
+  event_log_.Log(std::make_unique<FakeEvent>());
+  EXPECT_CALL(*encoder_ptr_,
+              OnEncode(Property(&RtcEvent::IsConfigEvent, true)));
+  EXPECT_CALL(*encoder_ptr_,
+              OnEncode(Property(&RtcEvent::IsConfigEvent, false)));
+  time_controller_.AdvanceTime(kOutputPeriod);
+  Mock::VerifyAndClearExpectations(encoder_ptr_);
+}
+
+}  // namespace
+}  // namespace webrtc