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}
diff --git a/api/rtc_event_log/rtc_event.h b/api/rtc_event_log/rtc_event.h
index 8697a25..0bc11ce 100644
--- a/api/rtc_event_log/rtc_event.h
+++ b/api/rtc_event_log/rtc_event.h
@@ -55,7 +55,8 @@
GenericAckReceived,
FrameDecoded,
BeginV3Log = 0x2501580,
- EndV3Log = 0x2501581
+ EndV3Log = 0x2501581,
+ FakeEvent, // For unit testing.
};
RtcEvent();
diff --git a/api/rtc_event_log/rtc_event_log_factory.cc b/api/rtc_event_log/rtc_event_log_factory.cc
index 38a0e4e..a3cb68c 100644
--- a/api/rtc_event_log/rtc_event_log_factory.cc
+++ b/api/rtc_event_log/rtc_event_log_factory.cc
@@ -33,7 +33,8 @@
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
diff --git a/logging/BUILD.gn b/logging/BUILD.gn
index fea5569..3c3c825 100644
--- a/logging/BUILD.gn
+++ b/logging/BUILD.gn
@@ -354,7 +354,10 @@
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 @@
"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 @@
":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 @@
"../test:fileutils",
"../test:test_support",
"../test/logging:log_writer",
+ "../test/time_controller",
"//testing/gtest",
]
absl_deps = [
diff --git a/logging/rtc_event_log/encoder/rtc_event_log_encoder_legacy.cc b/logging/rtc_event_log/encoder/rtc_event_log_encoder_legacy.cc
index 9bc7708..7e137a5 100644
--- a/logging/rtc_event_log/encoder/rtc_event_log_encoder_legacy.cc
+++ b/logging/rtc_event_log/encoder/rtc_event_log_encoder_legacy.cc
@@ -374,6 +374,10 @@
// 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:
diff --git a/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc b/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc
index 9d791d1..4a0b758 100644
--- a/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc
+++ b/logging/rtc_event_log/encoder/rtc_event_log_encoder_new_format.cc
@@ -883,6 +883,10 @@
// 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;
}
}
diff --git a/logging/rtc_event_log/rtc_event_log_impl.cc b/logging/rtc_event_log/rtc_event_log_impl.cc
index a48bbde..6d855f5 100644
--- a/logging/rtc_event_log/rtc_event_log_impl.cc
+++ b/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 @@
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::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::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.
diff --git a/logging/rtc_event_log/rtc_event_log_impl.h b/logging/rtc_event_log/rtc_event_log_impl.h
index 6c64172..6ffed0a 100644
--- a/logging/rtc_event_log/rtc_event_log_impl.h
+++ b/logging/rtc_event_log/rtc_event_log_impl.h
@@ -33,13 +33,26 @@
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 @@
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_);
diff --git a/logging/rtc_event_log/rtc_event_log_impl_unittest.cc b/logging/rtc_event_log/rtc_event_log_impl_unittest.cc
new file mode 100644
index 0000000..d32af8f
--- /dev/null
+++ b/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
