From f015a128023adb7c3d6bcaf7280c206d29309168 Mon Sep 17 00:00:00 2001 From: Markus Handell Date: Tue, 3 Jan 2023 13:50:30 +0100 Subject: [PATCH] RtcEventLogImpl: Add mocked time test. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Commit-Queue: Markus Handell Reviewed-by: Björn Terelius Cr-Commit-Position: refs/heads/main@{#38987} --- api/rtc_event_log/rtc_event.h | 3 +- api/rtc_event_log/rtc_event_log_factory.cc | 3 +- logging/BUILD.gn | 8 +- .../encoder/rtc_event_log_encoder_legacy.cc | 4 + .../rtc_event_log_encoder_new_format.cc | 4 + logging/rtc_event_log/rtc_event_log_impl.cc | 25 ++- logging/rtc_event_log/rtc_event_log_impl.h | 23 ++- .../rtc_event_log_impl_unittest.cc | 188 ++++++++++++++++++ 8 files changed, 240 insertions(+), 18 deletions(-) create mode 100644 logging/rtc_event_log/rtc_event_log_impl_unittest.cc diff --git a/api/rtc_event_log/rtc_event.h b/api/rtc_event_log/rtc_event.h index 8697a25a74..0bc11ce698 100644 --- a/api/rtc_event_log/rtc_event.h +++ b/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(); diff --git a/api/rtc_event_log/rtc_event_log_factory.cc b/api/rtc_event_log/rtc_event_log_factory.cc index 38a0e4ebd2..a3cb68cf54 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 @@ std::unique_ptr RtcEventLogFactory::Create( if (field_trial::IsEnabled("WebRTC-RtcEventLogKillSwitch")) { return std::make_unique(); } - return std::make_unique(encoding_type, task_queue_factory_); + return std::make_unique( + RtcEventLogImpl::CreateEncoder(encoding_type), task_queue_factory_); #else return std::make_unique(); #endif diff --git a/logging/BUILD.gn b/logging/BUILD.gn index fea5569a7d..3c3c825ec3 100644 --- a/logging/BUILD.gn +++ b/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 = [ 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 9bc770849c..7e137a50cf 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 @@ 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: 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 9d791d1aca..4a0b7584f0 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 @@ 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; } } diff --git a/logging/rtc_event_log/rtc_event_log_impl.cc b/logging/rtc_event_log/rtc_event_log_impl.cc index a48bbdeb8e..6d855f5e05 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 CreateEncoder( +std::unique_ptr RtcEventLogImpl::CreateEncoder( RtcEventLog::EncodingType type) { switch (type) { case RtcEventLog::EncodingType::Legacy: @@ -52,11 +47,14 @@ std::unique_ptr CreateEncoder( return std::unique_ptr(nullptr); } } -} // namespace -RtcEventLogImpl::RtcEventLogImpl(RtcEventLog::EncodingType encoding_type, - TaskQueueFactory* task_queue_factory) - : event_encoder_(CreateEncoder(encoding_type)), +RtcEventLogImpl::RtcEventLogImpl(std::unique_ptr 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 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 event) { std::deque>& 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 6c6417254e..6ffed0ad22 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 @@ 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 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 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 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> 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 0000000000..d32af8fe23 --- /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 +#include + +#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>::const_iterator a, + std::deque>::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 encoder_ = + std::make_unique(); + MockEventEncoder* encoder_ptr_ = encoder_.get(); + std::unique_ptr output_ = + std::make_unique(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()); + event_log_.Log(std::make_unique()); + event_log_.StopLogging(); + Mock::VerifyAndClearExpectations(encoder_ptr_); + EXPECT_TRUE(written_data_ == "startconfigeventstop" || + written_data_ == "starteventconfigstop"); +} + +TEST_F(RtcEventLogImplTest, KeepsMostRecentEventsOnStart) { + auto e2 = std::make_unique(); + RtcEvent* e2_ptr = e2.get(); + auto e3 = std::make_unique(); + RtcEvent* e3_ptr = e3.get(); + event_log_.Log(std::make_unique()); + 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(); + RtcEvent* e1_ptr = e1.get(); + auto e2 = std::make_unique(); + RtcEvent* e2_ptr = e2.get(); + auto e3 = std::make_unique(); + 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(written_data_), + kOutputPeriod.ms()); + event_log_.Log(std::make_unique()); + event_log_.Log(std::make_unique()); + 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(written_data_), + kOutputPeriod.ms()); + event_log_.Log(std::make_unique()); + event_log_.Log(std::make_unique()); + 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