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