src/storage/lib/watchdog/watchdog_test.cc

// Copyright 2020 The Fuchsia 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 <fuchsia/diagnostics/cpp/fidl.h>
#include <fuchsia/logger/cpp/fidl.h>
#include <lib/async-loop/cpp/loop.h>
#include <lib/async/dispatcher.h>
#include <lib/async/wait.h>
#include <lib/fidl/cpp/binding_set.h>
#include <lib/fpromise/promise.h>
#include <lib/syslog/cpp/log_settings.h>
#include <lib/syslog/cpp/macros.h>
#include <lib/watchdog/operations.h>
#include <lib/watchdog/watchdog.h>
#include <unistd.h>

#include <atomic>
#include <chrono>
#include <cinttypes>
#include <cstddef>
#include <cstdio>
#include <memory>
#include <sstream>
#include <string>
#include <string_view>
#include <thread>
#include <type_traits>
#include <utility>

#include <fbl/unique_fd.h>
#include <src/diagnostics/lib/cpp-log-decoder/log_decoder.h>
#include <src/diagnostics/lib/cpp-log-tester/log_tester.h>
#include <src/lib/diagnostics/accessor2logger/log_message.h>
#include <src/lib/fsl/vmo/sized_vmo.h>
#include <src/lib/fsl/vmo/strings.h>
#include <src/lib/fxl/strings/join_strings.h>
#include <src/lib/fxl/strings/string_printf.h>
#include <src/lib/uuid/uuid.h>
#include <zxtest/zxtest.h>

namespace fs_watchdog {
namespace {

// Default sleep argument for the watchdog
constexpr std::chrono::nanoseconds kSleepDuration = std::chrono::milliseconds(100);

// Custom/overloaded operation timeout
constexpr int kOperationTimeoutSeconds = 1;
constexpr std::chrono::nanoseconds kOperationTimeout =
    std::chrono::seconds(kOperationTimeoutSeconds);

const Options kDefaultOptions = {kSleepDuration, true, kDefaultLogSeverity};
const Options kDisabledOptions = {kSleepDuration, false, kDefaultLogSeverity};

constexpr std::chrono::seconds kPollLimit = std::chrono::seconds(10);

// Test that we can start the watchdog.
TEST(Watchdog, StartTest) {
  auto watchdog = CreateWatchdog(kDefaultOptions);
  ASSERT_TRUE(watchdog->Start().is_ok());
}

// Test that we can shutdown the watchdog.
TEST(Watchdog, ShutDownTest) {
  auto watchdog = CreateWatchdog(kDefaultOptions);
  ASSERT_TRUE(watchdog->Start().is_ok());
  ASSERT_TRUE(watchdog->ShutDown().is_ok());
}

// Test that we can shutdown watchdog without the thread waiting for duration of it's sleep.
TEST(Watchdog, ShutDownImmediatelyTest) {
  auto options = kDefaultOptions;
  options.sleep = std::chrono::hours(1);
  auto watchdog = CreateWatchdog(kDefaultOptions);
  ASSERT_TRUE(watchdog->Start().is_ok());
  std::this_thread::sleep_for(std::chrono::seconds(1));
  auto t1 = std::chrono::steady_clock::now();
  ASSERT_TRUE(watchdog->ShutDown().is_ok());
  auto t2 = std::chrono::steady_clock::now();
  ASSERT_LT(t2 - t1, std::chrono::seconds(10));
}

constexpr const char* kTestOperationName1 = "WatchdogTestOperation1";
constexpr const char* kTestOperationName2 = "WatchdogTestOperation2";
constexpr const char* kTestOperationName3 = "WatchdogTestOperation3";

// These are some of the known messages printed by the watchdog.
const std::string_view kLogMessageOperation("Operation:");
const std::string_view kLogMessageExceededTimeout("exceeded timeout");
const std::string_view kLogMessageTimeout("Timeout");
const std::string_view kLogMessageExceededOperation("exceeded operation:");
const std::string_view kLogMessageCompleted("completed(");

class TestOperation : public OperationBase {
 public:
  explicit TestOperation(const char* operation_name,
                         std::chrono::nanoseconds timeout = kOperationTimeout)
      : operation_name_(operation_name), timeout_(timeout) {}
  std::string_view Name() const final { return operation_name_; }
  std::chrono::nanoseconds Timeout() const final { return timeout_; }

 private:
  // Name of the operation.
  const char* operation_name_ = nullptr;

  // Timeout for this operation.
  std::chrono::nanoseconds timeout_;
};

class TestOperationTracker : public FsOperationTracker {
 public:
  TestOperationTracker(OperationBase* operation, WatchdogInterface* watchdog, bool track = true)
      : FsOperationTracker(operation, watchdog, track) {}
  void OnTimeOut(FILE* out_stream) const final { handler_called_++; }

  bool TimeoutHandlerCalled() const { return handler_called_ > 0; }

  int TimeoutHandlerCalledCount() const { return handler_called_; }

 private:
  // Incremented on each call to TimeoutHandler.
  mutable std::atomic<int> handler_called_ = 0;
};

// Returns true if the number of occurances of string |substr| in string |str|
// matches expected.
bool CheckOccurance(const std::string& str, const std::string_view substr, int expected) {
  int count = 0;
  std::string::size_type start = 0;

  while ((start = str.find(substr, start)) != std::string::npos) {
    ++count;
    start += substr.length();
  }

  return count == expected;
}

// Polls until timeout, returning early if the result is true, otherwise returns the result of the
// callback.
bool PollUntilTrueOrTimeout(const std::function<bool()>& callback,
                            const std::chrono::seconds& timeout) {
  auto expiry = std::chrono::steady_clock::now() + timeout;
  while (std::chrono::steady_clock::now() <= expiry) {
    if (callback()) {
      return true;
    }
    std::this_thread::sleep_for(kSleepDuration);
  }
  return callback();
}

TEST(Watchdog, TryToAddDuplicate) {
  auto watchdog = CreateWatchdog(kDefaultOptions);
  EXPECT_TRUE(watchdog->Start().is_ok());
  TestOperation op(kTestOperationName1, kOperationTimeout);
  TestOperationTracker tracker(&op, watchdog.get());
  auto result = watchdog->Track(&tracker);
  ASSERT_FALSE(result.is_ok());
  ASSERT_EQ(result.error_value(), ZX_ERR_ALREADY_EXISTS);
}

TEST(Watchdog, TryToAddDuplicateAfterTimeout) {
  [[maybe_unused]] auto fd_pair = log_tester::SetupFakeLog();
  auto watchdog = CreateWatchdog(kDefaultOptions);
  EXPECT_TRUE(watchdog->Start().is_ok());
  TestOperation op(kTestOperationName1, kOperationTimeout);
  TestOperationTracker tracker(&op, watchdog.get());
  ASSERT_TRUE(
      PollUntilTrueOrTimeout([&tracker]() { return tracker.TimeoutHandlerCalled(); }, kPollLimit));
  ASSERT_EQ(watchdog->Track(&tracker).error_value(), ZX_ERR_ALREADY_EXISTS);
}

TEST(Watchdog, StartDisabledWatchdog) {
  auto watchdog = CreateWatchdog(kDisabledOptions);
  ASSERT_EQ(watchdog->Start().error_value(), ZX_ERR_BAD_STATE);
}

TEST(Watchdog, StartRunningWatchdog) {
  auto watchdog = CreateWatchdog(kDefaultOptions);
  EXPECT_OK(watchdog->Start());
  ASSERT_EQ(watchdog->Start().error_value(), ZX_ERR_BAD_STATE);
}

TEST(Watchdog, ShutDownUnstarted) {
  auto watchdog = CreateWatchdog(kDefaultOptions);
  ASSERT_EQ(watchdog->ShutDown().error_value(), ZX_ERR_BAD_STATE);
}

TEST(Watchdog, ShutDownAgain) {
  auto watchdog = CreateWatchdog(kDefaultOptions);
  EXPECT_OK(watchdog->Start());
  EXPECT_TRUE(watchdog->ShutDown().is_ok());
  ASSERT_EQ(watchdog->ShutDown().error_value(), ZX_ERR_BAD_STATE);
}

TEST(Watchdog, TrackWithDisabledWatchdog) {
  auto watchdog = CreateWatchdog(kDisabledOptions);
  EXPECT_FALSE(watchdog->Start().is_ok());
  TestOperation op(kTestOperationName1, kOperationTimeout);
  TestOperationTracker tracker(&op, watchdog.get(), false);
  ASSERT_EQ(watchdog->Track(&tracker).error_value(), ZX_ERR_BAD_STATE);
}

TEST(Watchdog, RemoveUntrackedOperation) {
  auto watchdog = CreateWatchdog(kDefaultOptions);
  EXPECT_TRUE(watchdog->Start().is_ok());
  OperationTrackerId id;
  {
    TestOperation op(kTestOperationName1, kOperationTimeout);
    TestOperationTracker tracker(&op, watchdog.get(), false);
    id = tracker.GetId();
  }
  ASSERT_EQ(watchdog->Untrack(id).error_value(), ZX_ERR_NOT_FOUND);
}

TEST(Watchdog, OperationTimesOut) {
  auto fd_pair = log_tester::SetupFakeLog();
  {
    auto watchdog = CreateWatchdog(kDefaultOptions);
    EXPECT_TRUE(watchdog->Start().is_ok());
    {
      TestOperation op(kTestOperationName1, kOperationTimeout);
      TestOperationTracker tracker(&op, watchdog.get());
      ASSERT_TRUE(PollUntilTrueOrTimeout([&tracker]() { return tracker.TimeoutHandlerCalled(); },
                                         kPollLimit));
    }
  }
  auto str = log_tester::RetrieveLogs(std::move(fd_pair));

  // Find known strings.
  ASSERT_TRUE(CheckOccurance(str, kLogMessageOperation, 1));
  ASSERT_TRUE(CheckOccurance(str, kLogMessageExceededTimeout, 1));
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName1, 2));
}

TEST(Watchdog, NoTimeoutsWhenDisabled) {
  auto fd_pair = log_tester::SetupFakeLog();
  {
    auto watchdog = CreateWatchdog(kDisabledOptions);
    EXPECT_TRUE(watchdog->Start().is_error());
    TestOperation op(kTestOperationName1, kOperationTimeout);
    {
      TestOperationTracker tracker(&op, watchdog.get(), false);
      ASSERT_EQ(watchdog->Track(&tracker).error_value(), ZX_ERR_BAD_STATE);
      std::this_thread::sleep_for(std::chrono::seconds(kOperationTimeoutSeconds + 1));
      ASSERT_FALSE(tracker.TimeoutHandlerCalled());
    }
  }
  auto str = log_tester::RetrieveLogs(std::move(fd_pair));
  // Find known strings.
  ASSERT_TRUE(CheckOccurance(str, kLogMessageOperation, 0));
  ASSERT_TRUE(CheckOccurance(str, kLogMessageExceededTimeout, 0));
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName1, 0));
}

TEST(Watchdog, NoTimeoutsWhenShutDown) {
  auto fd_pair = log_tester::SetupFakeLog();
  {
    auto watchdog = CreateWatchdog(kDefaultOptions);
    EXPECT_TRUE(watchdog->Start().is_ok());
    EXPECT_TRUE(watchdog->ShutDown().is_ok());
    TestOperation op(kTestOperationName1, kOperationTimeout);
    {
      TestOperationTracker tracker(&op, watchdog.get());
      std::this_thread::sleep_for(std::chrono::seconds(kOperationTimeoutSeconds + 1));
      ASSERT_FALSE(tracker.TimeoutHandlerCalled());
    }
  }
  auto str = log_tester::RetrieveLogs(std::move(fd_pair));
  // Find known strings.
  ASSERT_TRUE(CheckOccurance(str, kLogMessageOperation, 0));
  ASSERT_TRUE(CheckOccurance(str, kLogMessageExceededTimeout, 0));
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName1, 0));
}

TEST(Watchdog, OperationDoesNotTimesOut) {
  auto fd_pair = log_tester::SetupFakeLog();
  {
    auto watchdog = CreateWatchdog(kDefaultOptions);
    EXPECT_TRUE(watchdog->Start().is_ok());
    TestOperation op(kTestOperationName1, kOperationTimeout + std::chrono::seconds(10));
    {
      TestOperationTracker tracker(&op, watchdog.get());
      std::this_thread::sleep_for(std::chrono::seconds(kOperationTimeoutSeconds));
      ASSERT_FALSE(tracker.TimeoutHandlerCalled());
    }
  }
  auto str = log_tester::RetrieveLogs(std::move(fd_pair));
  // We should not find known strings.
  ASSERT_TRUE(CheckOccurance(str, kLogMessageOperation, 0));
  ASSERT_TRUE(CheckOccurance(str, kLogMessageExceededTimeout, 0));
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName1, 0));
}

TEST(Watchdog, MultipleOperationsTimeout) {
  auto fd_pair = log_tester::SetupFakeLog();
  {
    auto watchdog = CreateWatchdog(kDefaultOptions);
    EXPECT_TRUE(watchdog->Start().is_ok());
    {
      TestOperation op1(kTestOperationName1, kOperationTimeout);
      TestOperation op2(kTestOperationName2, kOperationTimeout);
      TestOperation op3(kTestOperationName3, kOperationTimeout + kPollLimit * 4);
      TestOperationTracker tracker1(&op1, watchdog.get());
      TestOperationTracker tracker3(&op3, watchdog.get());
      TestOperationTracker tracker2(&op2, watchdog.get());
      ASSERT_TRUE(PollUntilTrueOrTimeout([&tracker1]() { return tracker1.TimeoutHandlerCalled(); },
                                         kPollLimit));
      ASSERT_TRUE(PollUntilTrueOrTimeout([&tracker2]() { return tracker2.TimeoutHandlerCalled(); },
                                         kPollLimit));
      ASSERT_FALSE(tracker3.TimeoutHandlerCalled());
    }
  }
  auto str = log_tester::RetrieveLogs(std::move(fd_pair));
  // Find known strings.
  ASSERT_TRUE(CheckOccurance(str, kLogMessageOperation, 2));
  ASSERT_TRUE(CheckOccurance(str, kLogMessageExceededTimeout, 2));
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName1, 2));
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName2, 2));
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName3, 0));
}

TEST(Watchdog, LoggedOnlyOnce) {
  auto fd_pair = log_tester::SetupFakeLog();
  {
    auto watchdog = CreateWatchdog(kDefaultOptions);
    EXPECT_TRUE(watchdog->Start().is_ok());
    TestOperation op(kTestOperationName1, kOperationTimeout);
    {
      TestOperationTracker tracker(&op, watchdog.get());

      // Sleep as long as it takes to scan in-flight operation twice.
      std::this_thread::sleep_for(std::chrono::seconds((2 * kOperationTimeoutSeconds) + 1));
      ASSERT_TRUE(PollUntilTrueOrTimeout([&tracker]() { return tracker.TimeoutHandlerCalled(); },
                                         kPollLimit));
      ASSERT_EQ(tracker.TimeoutHandlerCalledCount(), 1);
    }
  }
  auto str = log_tester::RetrieveLogs(std::move(fd_pair));
  // Find known strings.
  ASSERT_TRUE(CheckOccurance(str, kLogMessageOperation, 1));
  ASSERT_TRUE(CheckOccurance(str, kLogMessageExceededTimeout, 1));

  // Operation name gets printed twice - once when timesout and once when it
  // completes
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName1, 2));
}

TEST(Watchdog, DelayedCompletionLogging) {
  auto fd_pair = log_tester::SetupFakeLog();
  {
    auto watchdog = CreateWatchdog(kDefaultOptions);
    EXPECT_TRUE(watchdog->Start().is_ok());
    TestOperation op(kTestOperationName1, kOperationTimeout);
    {
      TestOperationTracker tracker(&op, watchdog.get());

      // Sleep as long as it takes to scan in-flight operation twice.
      std::this_thread::sleep_for(std::chrono::seconds((2 * kOperationTimeoutSeconds) + 1));
      ASSERT_TRUE(PollUntilTrueOrTimeout([&tracker]() { return tracker.TimeoutHandlerCalled(); },
                                         kPollLimit));
      ASSERT_EQ(tracker.TimeoutHandlerCalledCount(), 1);
    }
  }
  auto str = log_tester::RetrieveLogs(std::move(fd_pair));
  // Find known strings.
  ASSERT_TRUE(CheckOccurance(str, kLogMessageTimeout, 1));
  ASSERT_TRUE(CheckOccurance(str, kLogMessageExceededOperation, 1));
  ASSERT_TRUE(CheckOccurance(str, kLogMessageCompleted, 1));

  // Operation name gets printed twice - once when timesout and once when it
  // completes
  ASSERT_TRUE(CheckOccurance(str, kTestOperationName1, 2));
}

// Define a an operation(of Append type) with new timeout and track it.
TEST(Watchdog, TrackFsOperationType) {
  static const FsOperationType kMyfsAppendOperation(FsOperationType::CommonFsOperation::Append,
                                                    std::chrono::nanoseconds(1000000000));

  auto watchdog = CreateWatchdog(kDefaultOptions);
  EXPECT_TRUE(watchdog->Start().is_ok());

  FsOperationTracker tracker(&kMyfsAppendOperation, watchdog.get());
}
}  // namespace

}  // namespace fs_watchdog