power_manager/common/activity_logger_test.cc

// Copyright 2016 The Chromium OS Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "power_manager/common/activity_logger.h"

#include <base/macros.h>
#include <base/memory/ptr_util.h>
#include <gtest/gtest.h>

#include "power_manager/common/clock.h"

namespace power_manager {

class ActivityLoggerTest : public testing::Test {
 public:
  ActivityLoggerTest() : kName("test activity") {}
  ActivityLoggerTest(const ActivityLoggerTest&) = delete;
  ActivityLoggerTest& operator=(const ActivityLoggerTest&) = delete;

  ~ActivityLoggerTest() override {}

  // Initialize |logger| for testing. Ownership remains with the caller.
  void Init(BaseActivityLogger* logger) {
    logger_ = logger;
    logger_->clock_for_test()->set_current_time_for_testing(
        base::TimeTicks::FromInternalValue(100));  // Arbitrary.
    logger_->SetLogCallbackForTest(
        base::Bind(&ActivityLoggerTest::SaveMessage, base::Unretained(this)));
  }

  void AdvanceTime(base::TimeDelta delta) {
    CHECK(logger_);
    logger_->clock_for_test()->set_current_time_for_testing(
        logger_->clock_for_test()->GetCurrentTime() + delta);
  }

  std::string PopMessage() {
    std::string message = last_message_;
    last_message_.clear();
    return message;
  }

 protected:
  const std::string kName;

  BaseActivityLogger* logger_;  // Not owned.

 private:
  // BaseActivityLogger::LogCallback that just saves messages passed to it.
  void SaveMessage(const std::string& message) {
    EXPECT_FALSE(message.empty()) << "Got request to log empty message";
    EXPECT_TRUE(last_message_.empty())
        << "Got request to log \"" << message << "\" before previous message \""
        << last_message_ << "\" was popped";
    last_message_ = message;
  }

  // The last message passed to SaveMessage().
  std::string last_message_;
};

TEST_F(ActivityLoggerTest, StartStopNoDelay) {
  StartStopActivityLogger logger(kName, base::TimeDelta(), base::TimeDelta());
  Init(&logger);
  EXPECT_EQ("", PopMessage());

  // A message should be logged immediately every time activity starts or stops.
  logger.OnActivityStarted();
  EXPECT_EQ(kName + " started", PopMessage());
  EXPECT_EQ(base::TimeDelta(), logger.GetStoppedTimerDelayForTest());
  logger.OnActivityStopped();
  EXPECT_EQ(kName + " stopped", PopMessage());
  logger.OnActivityStarted();
  EXPECT_EQ(kName + " started", PopMessage());
}

TEST_F(ActivityLoggerTest, StartStopWithDelay) {
  const base::TimeDelta kStoppedDelay = base::TimeDelta::FromSeconds(5);
  StartStopActivityLogger logger(kName, kStoppedDelay, base::TimeDelta());
  Init(&logger);
  EXPECT_EQ("", PopMessage());

  // Start the activity. The "stopped" timer shouldn't be running.
  logger.OnActivityStarted();
  EXPECT_EQ(kName + " started", PopMessage());
  EXPECT_EQ(base::TimeDelta(), logger.GetStoppedTimerDelayForTest());

  // Immediately stopping the activity should start the "stopped" timer but not
  // log anything.
  logger.OnActivityStopped();
  EXPECT_EQ("", PopMessage());
  EXPECT_EQ(kStoppedDelay, logger.GetStoppedTimerDelayForTest());

  // Starting the activity again should stop the timer but not log.
  logger.OnActivityStarted();
  EXPECT_EQ("", PopMessage());
  EXPECT_EQ(base::TimeDelta(), logger.GetStoppedTimerDelayForTest());

  // Stop the activity a second time. This time, wait for the timer to fire,
  // which should result in the "stopped" message being logged with the delay.
  logger.OnActivityStopped();
  EXPECT_EQ(kStoppedDelay, logger.GetStoppedTimerDelayForTest());
  AdvanceTime(kStoppedDelay);
  ASSERT_TRUE(logger.TriggerStoppedTimerForTest());
  EXPECT_EQ(kName + " stopped 5 sec ago", PopMessage());

  // Starting the activity again now should log a message immediately.
  logger.OnActivityStarted();
  EXPECT_EQ(kName + " started", PopMessage());
}

TEST_F(ActivityLoggerTest, StartStopWithOngoing) {
  const base::TimeDelta kStoppedDelay = base::TimeDelta::FromSeconds(5);
  const base::TimeDelta kOngoingDelay = base::TimeDelta::FromSeconds(30);
  StartStopActivityLogger logger(kName, kStoppedDelay, kOngoingDelay);
  Init(&logger);
  EXPECT_EQ("", PopMessage());

  EXPECT_EQ(base::TimeDelta(), logger.GetOngoingTimerDelayForTest());
  logger.OnActivityStarted();
  EXPECT_EQ(kName + " started", PopMessage());

  // After activity starts, the "ongoing" timer should be started. Whenever it
  // fires, the "ongoing" message should be logged.
  EXPECT_EQ(kOngoingDelay, logger.GetOngoingTimerDelayForTest());
  AdvanceTime(kOngoingDelay);
  ASSERT_TRUE(logger.TriggerOngoingTimerForTest());
  EXPECT_EQ(kName + " ongoing", PopMessage());

  EXPECT_EQ(kOngoingDelay, logger.GetOngoingTimerDelayForTest());
  AdvanceTime(kOngoingDelay);
  ASSERT_TRUE(logger.TriggerOngoingTimerForTest());
  EXPECT_EQ(kName + " ongoing", PopMessage());

  // The "ongoing" timer should be stopped immediately when activity stops.
  logger.OnActivityStopped();
  EXPECT_EQ("", PopMessage());
  EXPECT_EQ(base::TimeDelta(), logger.GetOngoingTimerDelayForTest());

  // It should be started again when activity starts.
  logger.OnActivityStarted();
  EXPECT_EQ("", PopMessage());
  EXPECT_EQ(kOngoingDelay, logger.GetOngoingTimerDelayForTest());
  AdvanceTime(kOngoingDelay);
  ASSERT_TRUE(logger.TriggerOngoingTimerForTest());
  EXPECT_EQ(kName + " ongoing", PopMessage());
}

TEST_F(ActivityLoggerTest, StartStopDuplicateStop) {
  StartStopActivityLogger logger(kName, base::TimeDelta(), base::TimeDelta());
  Init(&logger);
  logger.OnActivityStarted();
  EXPECT_EQ(kName + " started", PopMessage());

  // A second OnActivityStopped() call shouldn't log the "stopped" message a
  // second time.
  logger.OnActivityStopped();
  EXPECT_EQ(kName + " stopped", PopMessage());
  logger.OnActivityStopped();
  EXPECT_EQ("", PopMessage());
}

TEST_F(ActivityLoggerTest, PeriodicNoOngoing) {
  const base::TimeDelta kStoppedDelay = base::TimeDelta::FromSeconds(10);
  PeriodicActivityLogger logger(kName, kStoppedDelay, base::TimeDelta());
  Init(&logger);
  EXPECT_EQ("", PopMessage());

  // The first report should be logged immediately, but subsequent reports
  // before the "stopped" timer has fired shouldn't be logged.
  logger.OnActivityReported();
  EXPECT_EQ(kName + " reported", PopMessage());
  logger.OnActivityReported();
  EXPECT_EQ("", PopMessage());

  // We should log when the "stopped" timer fires.
  EXPECT_EQ(kStoppedDelay, logger.GetStoppedTimerDelayForTest());
  AdvanceTime(kStoppedDelay);
  ASSERT_TRUE(logger.TriggerStoppedTimerForTest());
  EXPECT_EQ(kName + " stopped; last reported 10 sec ago", PopMessage());

  // A new report should be logged now that activity has stopped.
  logger.OnActivityReported();
  EXPECT_EQ(kName + " reported", PopMessage());
}

TEST_F(ActivityLoggerTest, PeriodicWithOngoing) {
  const base::TimeDelta kStoppedDelay = base::TimeDelta::FromSeconds(20);
  const base::TimeDelta kOngoingDelay = base::TimeDelta::FromSeconds(25);
  PeriodicActivityLogger logger(kName, kStoppedDelay, kOngoingDelay);
  Init(&logger);
  EXPECT_EQ("", PopMessage());

  // Start the activity.
  logger.OnActivityReported();
  EXPECT_EQ(kName + " reported", PopMessage());
  EXPECT_EQ(kOngoingDelay, logger.GetOngoingTimerDelayForTest());

  // Send a second report after 15 seconds to keep the activity going.
  AdvanceTime(base::TimeDelta::FromSeconds(15));
  logger.OnActivityReported();
  EXPECT_EQ("", PopMessage());

  // Advance the clock the remaining 10 seconds to the ongoing interval.
  AdvanceTime(base::TimeDelta::FromSeconds(10));
  ASSERT_TRUE(logger.TriggerOngoingTimerForTest());
  EXPECT_EQ(kName + " ongoing; last reported 10 sec ago", PopMessage());

  // Now let the "stopped" timer fire 10 seconds later and check that the
  // "ongoing" timer is also stopped.
  AdvanceTime(base::TimeDelta::FromSeconds(10));
  ASSERT_TRUE(logger.TriggerStoppedTimerForTest());
  EXPECT_EQ(kName + " stopped; last reported 20 sec ago", PopMessage());
  EXPECT_EQ(base::TimeDelta(), logger.GetOngoingTimerDelayForTest());
}

TEST_F(ActivityLoggerTest, OngoingState) {
  const base::TimeDelta kOngoingDelay = base::TimeDelta::FromSeconds(10);
  OngoingStateActivityLogger logger(kOngoingDelay);
  Init(&logger);
  EXPECT_EQ("", PopMessage());

  logger.OnStateChanged("a");
  EXPECT_EQ("", PopMessage());
  EXPECT_EQ(kOngoingDelay, logger.GetOngoingTimerDelayForTest());
  AdvanceTime(kOngoingDelay);
  ASSERT_TRUE(logger.TriggerOngoingTimerForTest());
  EXPECT_EQ("a", PopMessage());

  AdvanceTime(kOngoingDelay / 2);
  logger.OnStateChanged("b");
  AdvanceTime(kOngoingDelay / 2);
  ASSERT_TRUE(logger.TriggerOngoingTimerForTest());
  EXPECT_EQ("b", PopMessage());

  logger.OnStateChanged("");
  EXPECT_EQ(base::TimeDelta(), logger.GetOngoingTimerDelayForTest());
}

}  // namespace power_manager