logging/rtc_event_log/rtc_event_log_impl_unittest.cc

/*
 *  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 <cstddef>
#include <cstdint>
#include <deque>
#include <memory>
#include <optional>
#include <string>
#include <utility>

#include "absl/strings/string_view.h"
#include "api/rtc_event_log/rtc_event.h"
#include "api/rtc_event_log_output.h"
#include "api/units/time_delta.h"
#include "api/units/timestamp.h"
#include "logging/rtc_event_log/encoder/rtc_event_log_encoder.h"
#include "rtc_base/checks.h"
#include "test/create_test_environment.h"
#include "test/gmock.h"
#include "test/gtest.h"
#include "test/time_controller/simulated_time_controller.h"

namespace webrtc {
namespace {

using ::testing::_;
using ::testing::InSequence;
using ::testing::Mock;
using ::testing::Property;
using ::testing::Ref;
using ::testing::Return;

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 override { return is_active_; }
  bool Write(absl::string_view data) override {
    RTC_DCHECK(is_active_);
    if (fails_write_) {
      is_active_ = false;
      fails_write_ = false;
      return false;
    } else {
      written_data_.append(std::string(data));
      return true;
    }
  }
  void Flush() override {}

  void FailsNextWrite() { fails_write_ = true; }

 private:
  std::string& written_data_;
  bool is_active_ = true;
  bool fails_write_ = false;
};

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 = 5;
  static constexpr TimeDelta kOutputPeriod = TimeDelta::Seconds(2);
  static constexpr Timestamp kStartTime = Timestamp::Seconds(1);

  GlobalSimulatedTimeController time_controller_{kStartTime};
  std::string written_data_;  // This must be destroyed after the event_log_.
  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_{CreateTestEnvironment({.time = &time_controller_}),
                             std::move(encoder_), kMaxEventsInHistory,
                             kMaxEventsInConfigHistory};
};

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, KeepsConfigEventsOnStart) {
  // The config-history is supposed to be unbounded and never overflow.
  auto c1 = std::make_unique<FakeConfigEvent>();
  RtcEvent* c1_ptr = c1.get();
  auto c2 = std::make_unique<FakeConfigEvent>();
  RtcEvent* c2_ptr = c2.get();
  auto c3 = std::make_unique<FakeConfigEvent>();
  RtcEvent* c3_ptr = c3.get();
  event_log_.Log(std::move(c1));
  event_log_.Log(std::move(c2));
  event_log_.Log(std::move(c3));
  InSequence s;
  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*c1_ptr)));
  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*c2_ptr)));
  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*c3_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, RewritesAllConfigEventsOnlyOnRestart) {
  auto c1 = std::make_unique<FakeConfigEvent>();
  RtcEvent* c1_ptr = c1.get();
  auto c2 = std::make_unique<FakeConfigEvent>();
  RtcEvent* c2_ptr = c2.get();
  auto c3 = std::make_unique<FakeConfigEvent>();
  RtcEvent* c3_ptr = c3.get();
  auto c4 = std::make_unique<FakeConfigEvent>();
  RtcEvent* c4_ptr = c4.get();
  auto c5 = std::make_unique<FakeConfigEvent>();
  RtcEvent* c5_ptr = c5.get();
  // Keep the config event before start.
  event_log_.Log(std::move(c1));
  // Start logging.
  event_log_.StartLogging(std::make_unique<FakeOutput>(written_data_),
                          kOutputPeriod.ms());
  event_log_.Log(std::move(c2));
  event_log_.Log(std::move(c3));
  event_log_.StopLogging();
  time_controller_.AdvanceTime(TimeDelta::Zero());
  // Restart logging.
  event_log_.StartLogging(std::make_unique<FakeOutput>(written_data_),
                          kOutputPeriod.ms());
  event_log_.Log(std::move(c4));
  event_log_.Log(std::move(c5));
  event_log_.Log(std::make_unique<FakeEvent>());
  event_log_.StopLogging();
  time_controller_.AdvanceTime(TimeDelta::Zero());
  InSequence s;
  // Rewrite all config events in sequence on next restart.
  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*c1_ptr)));
  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*c2_ptr)));
  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*c3_ptr)));
  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*c4_ptr)));
  EXPECT_CALL(*encoder_ptr_, OnEncode(Ref(*c5_ptr)));
  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, SetsEventTimestampOnLog) {
  // Silence expected, but unimportant calls for this test.
  EXPECT_CALL(*encoder_ptr_, EncodeLogStart);
  EXPECT_CALL(*encoder_ptr_, EncodeLogEnd);
  // Setup the main expectation of this test.
  // Right value for the `expected_log_time` would be set later during the test.
  std::optional<Timestamp> expected_log_time;
  EXPECT_CALL(*encoder_ptr_, OnEncode).WillOnce([&](const RtcEvent& event) {
    // This should be called after expected_log_time is set.
    EXPECT_TRUE(expected_log_time.has_value());
    EXPECT_EQ(event.timestamp(), expected_log_time);
    return "";
  });

  event_log_.StartLogging(std::make_unique<FakeOutput>(written_data_),
                          kOutputPeriod.ms());
  auto event = std::make_unique<FakeEvent>();
  // Change time to have different time of construction of the event, and
  // time of logging the event. In production code they are normally about the
  // same.
  time_controller_.AdvanceTime(TimeDelta::Millis(100));

  expected_log_time = time_controller_.GetClock()->CurrentTime();
  event_log_.Log(std::move(event));

  // Cleanup: stop the `event_log_` to wait until all events are written.
  bool stopped = false;
  event_log_.StopLogging([&] { stopped = true; });
  EXPECT_TRUE(time_controller_.Wait([&] { return stopped; }));
}

TEST_F(RtcEventLogImplTest, SchedulesWriteAfterOutputDurationPassed) {
  event_log_.StartLogging(std::move(output_), 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_);
}

TEST_F(RtcEventLogImplTest, DoNotDropEventsIfHistoryFullAfterStarted) {
  constexpr size_t kNumberOfEvents = 10 * kMaxEventsInHistory;

  event_log_.StartLogging(std::move(output_), kOutputPeriod.ms());
  event_log_.Log(std::make_unique<FakeConfigEvent>());
  for (size_t i = 0; i < kNumberOfEvents; i++) {
    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)))
      .Times(kNumberOfEvents);
  time_controller_.AdvanceTime(kOutputPeriod);
  Mock::VerifyAndClearExpectations(encoder_ptr_);
}

TEST_F(RtcEventLogImplTest, StopOutputOnWriteFailure) {
  constexpr size_t kNumberOfEvents = 10;
  constexpr size_t kFailsWriteOnEventsCount = 5;

  size_t number_of_encoded_events = 0;
  EXPECT_CALL(*encoder_ptr_, OnEncode(_))
      .WillRepeatedly([this, &number_of_encoded_events]() {
        ++number_of_encoded_events;
        if (number_of_encoded_events == kFailsWriteOnEventsCount) {
          output_ptr_->FailsNextWrite();
        }
        return std::string();
      });

  event_log_.StartLogging(std::move(output_), kOutputPeriod.ms());

  // Fails `RtcEventLogOutput` on the last event.
  for (size_t i = 0; i < kFailsWriteOnEventsCount; i++) {
    event_log_.Log(std::make_unique<FakeEvent>());
  }
  time_controller_.AdvanceTime(kOutputPeriod);
  // Expect that the remainder events are not encoded.
  for (size_t i = kFailsWriteOnEventsCount; i < kNumberOfEvents; i++) {
    event_log_.Log(std::make_unique<FakeEvent>());
  }
  time_controller_.AdvanceTime(kOutputPeriod);
  event_log_.StopLogging();

  EXPECT_EQ(number_of_encoded_events, kFailsWriteOnEventsCount);

  Mock::VerifyAndClearExpectations(encoder_ptr_);
}

}  // namespace
}  // namespace webrtc