rocksdb/logging/auto_roll_logger_test.cc

//  Copyright (c) 2011-present, Facebook, Inc.  All rights reserved.
//  This source code is licensed under both the GPLv2 (found in the
//  COPYING file in the root directory) and Apache 2.0 License
//  (found in the LICENSE.Apache file in the root directory).
//

#ifndef ROCKSDB_LITE

#include "logging/auto_roll_logger.h"

#include <sys/stat.h>

#include <algorithm>
#include <cmath>
#include <fstream>
#include <iostream>
#include <iterator>
#include <string>
#include <thread>
#include <vector>

#include "db/db_test_util.h"
#include "env/emulated_clock.h"
#include "logging/logging.h"
#include "port/port.h"
#include "rocksdb/db.h"
#include "rocksdb/file_system.h"
#include "rocksdb/system_clock.h"
#include "test_util/sync_point.h"
#include "test_util/testharness.h"
#include "test_util/testutil.h"

namespace ROCKSDB_NAMESPACE {

// In this test we only want to Log some simple log message with
// no format. LogMessage() provides such a simple interface and
// avoids the [format-security] warning which occurs when you
// call ROCKS_LOG_INFO(logger, log_message) directly.
namespace {
void LogMessage(Logger* logger, const char* message) {
  ROCKS_LOG_INFO(logger, "%s", message);
}

void LogMessage(const InfoLogLevel log_level, Logger* logger,
                const char* message) {
  Log(log_level, logger, "%s", message);
}
}  // namespace

class AutoRollLoggerTest : public testing::Test {
 public:
  static void InitTestDb() {
    // TODO replace the `system` calls with Env/FileSystem APIs.
#ifdef OS_WIN
    // Replace all slashes in the path so windows CompSpec does not
    // become confused
    std::string testDbDir(kTestDbDir);
    std::replace_if(
        testDbDir.begin(), testDbDir.end(), [](char ch) { return ch == '/'; },
        '\\');
    std::string deleteDbDirCmd =
        "if exist " + testDbDir + " rd /s /q " + testDbDir;
    ASSERT_TRUE(system(deleteDbDirCmd.c_str()) == 0);

    std::string testDir(kTestDir);
    std::replace_if(testDir.begin(), testDir.end(),
                    [](char ch) { return ch == '/'; }, '\\');
    std::string deleteCmd = "if exist " + testDir + " rd /s /q " + testDir;
#else
    std::string deleteCmd = "rm -rf " + kTestDir + " " + kTestDbDir;
#endif
    ASSERT_TRUE(system(deleteCmd.c_str()) == 0);
    ASSERT_OK(Env::Default()->CreateDir(kTestDir));
    ASSERT_OK(Env::Default()->CreateDir(kTestDbDir));
  }

  void RollLogFileBySizeTest(AutoRollLogger* logger, size_t log_max_size,
                             const std::string& log_message);
  void RollLogFileByTimeTest(const std::shared_ptr<FileSystem>& fs,
                             const std::shared_ptr<SystemClock>& sc,
                             AutoRollLogger* logger, size_t time,
                             const std::string& log_message);
  // return list of files under kTestDir that contains "LOG"
  std::vector<std::string> GetLogFiles() {
    std::vector<std::string> ret;
    std::vector<std::string> files;
    Status s = default_env->GetChildren(kTestDir, &files);
    // Should call ASSERT_OK() here but it doesn't compile. It's not
    // worth the time figuring out why.
    EXPECT_TRUE(s.ok());
    for (const auto& f : files) {
      if (f.find("LOG") != std::string::npos) {
        ret.push_back(f);
      }
    }
    return ret;
  }

  // Delete all log files under kTestDir
  void CleanupLogFiles() {
    for (const std::string& f : GetLogFiles()) {
      ASSERT_OK(default_env->DeleteFile(kTestDir + "/" + f));
    }
  }

  void RollNTimesBySize(Logger* auto_roll_logger, size_t file_num,
                        size_t max_log_file_size) {
    // Roll the log 4 times, and it will trim to 3 files.
    std::string dummy_large_string;
    dummy_large_string.assign(max_log_file_size, '=');
    auto_roll_logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
    for (size_t i = 0; i < file_num + 1; i++) {
      // Log enough bytes to trigger at least one roll.
      LogMessage(auto_roll_logger, dummy_large_string.c_str());
      LogMessage(auto_roll_logger, "");
    }
  }

  static const std::string kSampleMessage;
  static const std::string kTestDir;
  static const std::string kTestDbDir;
  static const std::string kLogFile;
  static Env* default_env;
};

const std::string AutoRollLoggerTest::kSampleMessage(
    "this is the message to be written to the log file!!");
const std::string AutoRollLoggerTest::kTestDir(
    test::PerThreadDBPath("db_log_test"));
const std::string AutoRollLoggerTest::kTestDbDir(
    test::PerThreadDBPath("db_log_test_db"));
const std::string AutoRollLoggerTest::kLogFile(
    test::PerThreadDBPath("db_log_test") + "/LOG");
Env* AutoRollLoggerTest::default_env = Env::Default();

void AutoRollLoggerTest::RollLogFileBySizeTest(AutoRollLogger* logger,
                                               size_t log_max_size,
                                               const std::string& log_message) {
  logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
  ASSERT_EQ(InfoLogLevel::INFO_LEVEL, logger->GetInfoLogLevel());
  ASSERT_EQ(InfoLogLevel::INFO_LEVEL,
            logger->TEST_inner_logger()->GetInfoLogLevel());
  // measure the size of each message, which is supposed
  // to be equal or greater than log_message.size()
  LogMessage(logger, log_message.c_str());
  size_t message_size = logger->GetLogFileSize();
  size_t current_log_size = message_size;

  // Test the cases when the log file will not be rolled.
  while (current_log_size + message_size < log_max_size) {
    LogMessage(logger, log_message.c_str());
    current_log_size += message_size;
    ASSERT_EQ(current_log_size, logger->GetLogFileSize());
  }

  // Now the log file will be rolled
  LogMessage(logger, log_message.c_str());
  // Since rotation is checked before actual logging, we need to
  // trigger the rotation by logging another message.
  LogMessage(logger, log_message.c_str());

  ASSERT_TRUE(message_size == logger->GetLogFileSize());
}

void AutoRollLoggerTest::RollLogFileByTimeTest(
    const std::shared_ptr<FileSystem>& fs,
    const std::shared_ptr<SystemClock>& sc, AutoRollLogger* logger, size_t time,
    const std::string& log_message) {
  uint64_t expected_ctime;
  uint64_t actual_ctime;

  uint64_t total_log_size;
  EXPECT_OK(fs->GetFileSize(kLogFile, IOOptions(), &total_log_size, nullptr));
  expected_ctime = logger->TEST_ctime();
  logger->SetCallNowMicrosEveryNRecords(0);

  // -- Write to the log for several times, which is supposed
  // to be finished before time.
  for (int i = 0; i < 10; ++i) {
    sc->SleepForMicroseconds(50000);
    LogMessage(logger, log_message.c_str());
    EXPECT_OK(logger->GetStatus());
    // Make sure we always write to the same log file (by
    // checking the create time);

    actual_ctime = logger->TEST_ctime();

    // Also make sure the log size is increasing.
    EXPECT_EQ(expected_ctime, actual_ctime);
    EXPECT_GT(logger->GetLogFileSize(), total_log_size);
    total_log_size = logger->GetLogFileSize();
  }

  // -- Make the log file expire
  sc->SleepForMicroseconds(static_cast<int>(time * 1000000));
  LogMessage(logger, log_message.c_str());

  // At this time, the new log file should be created.
  actual_ctime = logger->TEST_ctime();
  EXPECT_LT(expected_ctime, actual_ctime);
  EXPECT_LT(logger->GetLogFileSize(), total_log_size);
}

TEST_F(AutoRollLoggerTest, RollLogFileBySize) {
    InitTestDb();
    size_t log_max_size = 1024 * 5;
    size_t keep_log_file_num = 10;

    AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
                          kTestDir, "", log_max_size, 0, keep_log_file_num);

    RollLogFileBySizeTest(&logger, log_max_size,
                          kSampleMessage + ":RollLogFileBySize");
}

TEST_F(AutoRollLoggerTest, RollLogFileByTime) {
  auto nsc =
      std::make_shared<EmulatedSystemClock>(SystemClock::Default(), true);

  size_t time = 2;
  size_t log_size = 1024 * 5;
  size_t keep_log_file_num = 10;

  InitTestDb();
  // -- Test the existence of file during the server restart.
  ASSERT_EQ(Status::NotFound(), default_env->FileExists(kLogFile));
  AutoRollLogger logger(default_env->GetFileSystem(), nsc, kTestDir, "",
                        log_size, time, keep_log_file_num);
  ASSERT_OK(default_env->FileExists(kLogFile));

  RollLogFileByTimeTest(default_env->GetFileSystem(), nsc, &logger, time,
                        kSampleMessage + ":RollLogFileByTime");
}

TEST_F(AutoRollLoggerTest, SetInfoLogLevel) {
  InitTestDb();
  Options options;
  options.info_log_level = InfoLogLevel::FATAL_LEVEL;
  options.max_log_file_size = 1024;
  std::shared_ptr<Logger> logger;
  ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
  auto* auto_roll_logger = dynamic_cast<AutoRollLogger*>(logger.get());
  ASSERT_NE(nullptr, auto_roll_logger);
  ASSERT_EQ(InfoLogLevel::FATAL_LEVEL, auto_roll_logger->GetInfoLogLevel());
  ASSERT_EQ(InfoLogLevel::FATAL_LEVEL,
            auto_roll_logger->TEST_inner_logger()->GetInfoLogLevel());
  auto_roll_logger->SetInfoLogLevel(InfoLogLevel::DEBUG_LEVEL);
  ASSERT_EQ(InfoLogLevel::DEBUG_LEVEL, auto_roll_logger->GetInfoLogLevel());
  ASSERT_EQ(InfoLogLevel::DEBUG_LEVEL, logger->GetInfoLogLevel());
  ASSERT_EQ(InfoLogLevel::DEBUG_LEVEL,
            auto_roll_logger->TEST_inner_logger()->GetInfoLogLevel());
}

TEST_F(AutoRollLoggerTest, OpenLogFilesMultipleTimesWithOptionLog_max_size) {
  // If only 'log_max_size' options is specified, then every time
  // when rocksdb is restarted, a new empty log file will be created.
  InitTestDb();
  // WORKAROUND:
  // avoid complier's complaint of "comparison between signed
  // and unsigned integer expressions" because literal 0 is
  // treated as "singed".
  size_t kZero = 0;
  size_t log_size = 1024;
  size_t keep_log_file_num = 10;

  AutoRollLogger* logger =
      new AutoRollLogger(FileSystem::Default(), SystemClock::Default(),
                         kTestDir, "", log_size, 0, keep_log_file_num);

  LogMessage(logger, kSampleMessage.c_str());
  ASSERT_GT(logger->GetLogFileSize(), kZero);
  delete logger;

  // reopens the log file and an empty log file will be created.
  logger = new AutoRollLogger(FileSystem::Default(), SystemClock::Default(),
                              kTestDir, "", log_size, 0, 10);
  ASSERT_EQ(logger->GetLogFileSize(), kZero);
  delete logger;
}

TEST_F(AutoRollLoggerTest, CompositeRollByTimeAndSizeLogger) {
  size_t time = 2, log_max_size = 1024 * 5;
  size_t keep_log_file_num = 10;

  InitTestDb();

  auto nsc =
      std::make_shared<EmulatedSystemClock>(SystemClock::Default(), true);
  AutoRollLogger logger(FileSystem::Default(), nsc, kTestDir, "", log_max_size,
                        time, keep_log_file_num);

  // Test the ability to roll by size
  RollLogFileBySizeTest(&logger, log_max_size,
                        kSampleMessage + ":CompositeRollByTimeAndSizeLogger");

  // Test the ability to roll by Time
  RollLogFileByTimeTest(FileSystem::Default(), nsc, &logger, time,
                        kSampleMessage + ":CompositeRollByTimeAndSizeLogger");
}

#ifndef OS_WIN
// TODO: does not build for Windows because of PosixLogger use below. Need to
// port
TEST_F(AutoRollLoggerTest, CreateLoggerFromOptions) {
  DBOptions options;
  auto nsc =
      std::make_shared<EmulatedSystemClock>(SystemClock::Default(), true);
  std::unique_ptr<Env> nse(new CompositeEnvWrapper(Env::Default(), nsc));

  std::shared_ptr<Logger> logger;

  // Normal logger
  ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
  ASSERT_TRUE(dynamic_cast<PosixLogger*>(logger.get()));

  // Only roll by size
  InitTestDb();
  options.max_log_file_size = 1024;
  ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
  AutoRollLogger* auto_roll_logger =
    dynamic_cast<AutoRollLogger*>(logger.get());
  ASSERT_TRUE(auto_roll_logger);
  RollLogFileBySizeTest(
      auto_roll_logger, options.max_log_file_size,
      kSampleMessage + ":CreateLoggerFromOptions - size");

  // Only roll by Time
  options.env = nse.get();
  InitTestDb();
  options.max_log_file_size = 0;
  options.log_file_time_to_roll = 2;
  ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
  auto_roll_logger =
    dynamic_cast<AutoRollLogger*>(logger.get());
  RollLogFileByTimeTest(options.env->GetFileSystem(), nsc, auto_roll_logger,
                        options.log_file_time_to_roll,
                        kSampleMessage + ":CreateLoggerFromOptions - time");

  // roll by both Time and size
  InitTestDb();
  options.max_log_file_size = 1024 * 5;
  options.log_file_time_to_roll = 2;
  ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
  auto_roll_logger =
    dynamic_cast<AutoRollLogger*>(logger.get());
  RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
                        kSampleMessage + ":CreateLoggerFromOptions - both");
  RollLogFileByTimeTest(options.env->GetFileSystem(), nsc, auto_roll_logger,
                        options.log_file_time_to_roll,
                        kSampleMessage + ":CreateLoggerFromOptions - both");

  // Set keep_log_file_num
  {
    const size_t kFileNum = 3;
    InitTestDb();
    options.max_log_file_size = 512;
    options.log_file_time_to_roll = 2;
    options.keep_log_file_num = kFileNum;
    ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
    auto_roll_logger = dynamic_cast<AutoRollLogger*>(logger.get());

    // Roll the log 4 times, and it will trim to 3 files.
    std::string dummy_large_string;
    dummy_large_string.assign(options.max_log_file_size, '=');
    auto_roll_logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
    for (size_t i = 0; i < kFileNum + 1; i++) {
      // Log enough bytes to trigger at least one roll.
      LogMessage(auto_roll_logger, dummy_large_string.c_str());
      LogMessage(auto_roll_logger, "");
    }

    std::vector<std::string> files = GetLogFiles();
    ASSERT_EQ(kFileNum, files.size());

    CleanupLogFiles();
  }

  // Set keep_log_file_num and dbname is different from
  // db_log_dir.
  {
    const size_t kFileNum = 3;
    InitTestDb();
    options.max_log_file_size = 512;
    options.log_file_time_to_roll = 2;
    options.keep_log_file_num = kFileNum;
    options.db_log_dir = kTestDir;
    ASSERT_OK(CreateLoggerFromOptions(kTestDbDir, options, &logger));
    auto_roll_logger = dynamic_cast<AutoRollLogger*>(logger.get());

    // Roll the log 4 times, and it will trim to 3 files.
    std::string dummy_large_string;
    dummy_large_string.assign(options.max_log_file_size, '=');
    auto_roll_logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
    for (size_t i = 0; i < kFileNum + 1; i++) {
      // Log enough bytes to trigger at least one roll.
      LogMessage(auto_roll_logger, dummy_large_string.c_str());
      LogMessage(auto_roll_logger, "");
    }

    std::vector<std::string> files = GetLogFiles();
    ASSERT_EQ(kFileNum, files.size());
    for (const auto& f : files) {
      ASSERT_TRUE(f.find("db_log_test_db") != std::string::npos);
    }

    // Cleaning up those files.
    CleanupLogFiles();
  }
}

TEST_F(AutoRollLoggerTest, AutoDeleting) {
  for (int attempt = 0; attempt < 2; attempt++) {
    // In the first attemp, db_log_dir is not set, while in the
    // second it is set.
    std::string dbname = (attempt == 0) ? kTestDir : "/test/dummy/dir";
    std::string db_log_dir = (attempt == 0) ? "" : kTestDir;

    InitTestDb();
    const size_t kMaxFileSize = 512;
    {
      size_t log_num = 8;
      AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
                            dbname, db_log_dir, kMaxFileSize, 0, log_num);
      RollNTimesBySize(&logger, log_num, kMaxFileSize);

      ASSERT_EQ(log_num, GetLogFiles().size());
    }
    // Shrink number of files
    {
      size_t log_num = 5;
      AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
                            dbname, db_log_dir, kMaxFileSize, 0, log_num);
      ASSERT_EQ(log_num, GetLogFiles().size());

      RollNTimesBySize(&logger, 3, kMaxFileSize);
      ASSERT_EQ(log_num, GetLogFiles().size());
    }

    // Increase number of files again.
    {
      size_t log_num = 7;
      AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
                            dbname, db_log_dir, kMaxFileSize, 0, log_num);
      ASSERT_EQ(6, GetLogFiles().size());

      RollNTimesBySize(&logger, 3, kMaxFileSize);
      ASSERT_EQ(log_num, GetLogFiles().size());
    }

    CleanupLogFiles();
  }
}

TEST_F(AutoRollLoggerTest, LogFlushWhileRolling) {
  DBOptions options;
  std::shared_ptr<Logger> logger;

  InitTestDb();
  options.max_log_file_size = 1024 * 5;
  ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
  AutoRollLogger* auto_roll_logger =
      dynamic_cast<AutoRollLogger*>(logger.get());
  ASSERT_TRUE(auto_roll_logger);
  ROCKSDB_NAMESPACE::port::Thread flush_thread;

  // Notes:
  // (1) Need to pin the old logger before beginning the roll, as rolling grabs
  //     the mutex, which would prevent us from accessing the old logger. This
  //     also marks flush_thread with AutoRollLogger::Flush:PinnedLogger.
  // (2) Need to reset logger during PosixLogger::Flush() to exercise a race
  //     condition case, which is executing the flush with the pinned (old)
  //     logger after auto-roll logger has cut over to a new logger.
  // (3) PosixLogger::Flush() happens in both threads but its SyncPoints only
  //     are enabled in flush_thread (the one pinning the old logger).
  ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->LoadDependencyAndMarkers(
      {{"AutoRollLogger::Flush:PinnedLogger",
        "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit"},
       {"PosixLogger::Flush:Begin1",
        "AutoRollLogger::ResetLogger:BeforeNewLogger"},
       {"AutoRollLogger::ResetLogger:AfterNewLogger",
        "PosixLogger::Flush:Begin2"}},
      {{"AutoRollLogger::Flush:PinnedLogger", "PosixLogger::Flush:Begin1"},
       {"AutoRollLogger::Flush:PinnedLogger", "PosixLogger::Flush:Begin2"}});
  ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->EnableProcessing();

  flush_thread = port::Thread([&]() { auto_roll_logger->Flush(); });
  TEST_SYNC_POINT(
      "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit");
  RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
                        kSampleMessage + ":LogFlushWhileRolling");
  flush_thread.join();
  ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing();
}

#endif  // OS_WIN

TEST_F(AutoRollLoggerTest, InfoLogLevel) {
  InitTestDb();

  size_t log_size = 8192;
  size_t log_lines = 0;
  // an extra-scope to force the AutoRollLogger to flush the log file when it
  // becomes out of scope.
  {
    AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
                          kTestDir, "", log_size, 0, 10);
    for (int log_level = InfoLogLevel::HEADER_LEVEL;
         log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
      logger.SetInfoLogLevel((InfoLogLevel)log_level);
      for (int log_type = InfoLogLevel::DEBUG_LEVEL;
           log_type <= InfoLogLevel::HEADER_LEVEL; log_type++) {
        // log messages with log level smaller than log_level will not be
        // logged.
        LogMessage((InfoLogLevel)log_type, &logger, kSampleMessage.c_str());
      }
      log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
    }
    for (int log_level = InfoLogLevel::HEADER_LEVEL;
         log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
      logger.SetInfoLogLevel((InfoLogLevel)log_level);

      // again, messages with level smaller than log_level will not be logged.
      ROCKS_LOG_HEADER(&logger, "%s", kSampleMessage.c_str());
      ROCKS_LOG_DEBUG(&logger, "%s", kSampleMessage.c_str());
      ROCKS_LOG_INFO(&logger, "%s", kSampleMessage.c_str());
      ROCKS_LOG_WARN(&logger, "%s", kSampleMessage.c_str());
      ROCKS_LOG_ERROR(&logger, "%s", kSampleMessage.c_str());
      ROCKS_LOG_FATAL(&logger, "%s", kSampleMessage.c_str());
      log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
    }
  }
  std::ifstream inFile(AutoRollLoggerTest::kLogFile.c_str());
  size_t lines = std::count(std::istreambuf_iterator<char>(inFile),
                         std::istreambuf_iterator<char>(), '\n');
  ASSERT_EQ(log_lines, lines);
  inFile.close();
}

TEST_F(AutoRollLoggerTest, Close) {
  InitTestDb();

  size_t log_size = 8192;
  size_t log_lines = 0;
  AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(), kTestDir,
                        "", log_size, 0, 10);
  for (int log_level = InfoLogLevel::HEADER_LEVEL;
       log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
    logger.SetInfoLogLevel((InfoLogLevel)log_level);
    for (int log_type = InfoLogLevel::DEBUG_LEVEL;
         log_type <= InfoLogLevel::HEADER_LEVEL; log_type++) {
      // log messages with log level smaller than log_level will not be
      // logged.
      LogMessage((InfoLogLevel)log_type, &logger, kSampleMessage.c_str());
    }
    log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
  }
  for (int log_level = InfoLogLevel::HEADER_LEVEL;
       log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
    logger.SetInfoLogLevel((InfoLogLevel)log_level);

    // again, messages with level smaller than log_level will not be logged.
    ROCKS_LOG_HEADER(&logger, "%s", kSampleMessage.c_str());
    ROCKS_LOG_DEBUG(&logger, "%s", kSampleMessage.c_str());
    ROCKS_LOG_INFO(&logger, "%s", kSampleMessage.c_str());
    ROCKS_LOG_WARN(&logger, "%s", kSampleMessage.c_str());
    ROCKS_LOG_ERROR(&logger, "%s", kSampleMessage.c_str());
    ROCKS_LOG_FATAL(&logger, "%s", kSampleMessage.c_str());
    log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
  }
  ASSERT_EQ(logger.Close(), Status::OK());

  std::ifstream inFile(AutoRollLoggerTest::kLogFile.c_str());
  size_t lines = std::count(std::istreambuf_iterator<char>(inFile),
                         std::istreambuf_iterator<char>(), '\n');
  ASSERT_EQ(log_lines, lines);
  inFile.close();
}

// Test the logger Header function for roll over logs
// We expect the new logs creates as roll over to carry the headers specified
static std::vector<std::string> GetOldFileNames(const std::string& path) {
  std::vector<std::string> ret;

  const std::string dirname = path.substr(/*start=*/0, path.find_last_of("/"));
  const std::string fname = path.substr(path.find_last_of("/") + 1);

  std::vector<std::string> children;
  EXPECT_OK(Env::Default()->GetChildren(dirname, &children));

  // We know that the old log files are named [path]<something>
  // Return all entities that match the pattern
  for (auto& child : children) {
    if (fname != child && child.find(fname) == 0) {
      ret.push_back(dirname + "/" + child);
    }
  }

  return ret;
}

TEST_F(AutoRollLoggerTest, LogHeaderTest) {
  static const size_t MAX_HEADERS = 10;
  static const size_t LOG_MAX_SIZE = 1024 * 5;
  static const std::string HEADER_STR = "Log header line";

  // test_num == 0 -> standard call to Header()
  // test_num == 1 -> call to Log() with InfoLogLevel::HEADER_LEVEL
  for (int test_num = 0; test_num < 2; test_num++) {

    InitTestDb();

    AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
                          kTestDir, /*db_log_dir=*/"", LOG_MAX_SIZE,
                          /*log_file_time_to_roll=*/0,
                          /*keep_log_file_num=*/10);

    if (test_num == 0) {
      // Log some headers explicitly using Header()
      for (size_t i = 0; i < MAX_HEADERS; i++) {
        Header(&logger, "%s %" ROCKSDB_PRIszt, HEADER_STR.c_str(), i);
      }
    } else if (test_num == 1) {
      // HEADER_LEVEL should make this behave like calling Header()
      for (size_t i = 0; i < MAX_HEADERS; i++) {
        ROCKS_LOG_HEADER(&logger, "%s %" ROCKSDB_PRIszt, HEADER_STR.c_str(), i);
      }
    }

    const std::string newfname = logger.TEST_log_fname();

    // Log enough data to cause a roll over
    int i = 0;
    for (size_t iter = 0; iter < 2; iter++) {
      while (logger.GetLogFileSize() < LOG_MAX_SIZE) {
        Info(&logger, (kSampleMessage + ":LogHeaderTest line %d").c_str(), i);
        ++i;
      }

      Info(&logger, "Rollover");
    }

    // Flush the log for the latest file
    LogFlush(&logger);

    const auto oldfiles = GetOldFileNames(newfname);

    ASSERT_EQ(oldfiles.size(), (size_t) 2);

    for (auto& oldfname : oldfiles) {
      // verify that the files rolled over
      ASSERT_NE(oldfname, newfname);
      // verify that the old log contains all the header logs
      ASSERT_EQ(test::GetLinesCount(oldfname, HEADER_STR), MAX_HEADERS);
    }
  }
}

TEST_F(AutoRollLoggerTest, LogFileExistence) {
  ROCKSDB_NAMESPACE::DB* db;
  ROCKSDB_NAMESPACE::Options options;
#ifdef OS_WIN
  // Replace all slashes in the path so windows CompSpec does not
  // become confused
  std::string testDir(kTestDir);
  std::replace_if(testDir.begin(), testDir.end(),
    [](char ch) { return ch == '/'; }, '\\');
  std::string deleteCmd = "if exist " + testDir + " rd /s /q " + testDir;
#else
  std::string deleteCmd = "rm -rf " + kTestDir;
#endif
  ASSERT_EQ(system(deleteCmd.c_str()), 0);
  options.max_log_file_size = 100 * 1024 * 1024;
  options.create_if_missing = true;
  ASSERT_OK(ROCKSDB_NAMESPACE::DB::Open(options, kTestDir, &db));
  ASSERT_OK(default_env->FileExists(kLogFile));
  delete db;
}

TEST_F(AutoRollLoggerTest, FileCreateFailure) {
  Options options;
  options.max_log_file_size = 100 * 1024 * 1024;
  options.db_log_dir = "/a/dir/does/not/exist/at/all";

  std::shared_ptr<Logger> logger;
  ASSERT_NOK(CreateLoggerFromOptions("", options, &logger));
  ASSERT_TRUE(!logger);
}

TEST_F(AutoRollLoggerTest, RenameOnlyWhenExists) {
  InitTestDb();
  SpecialEnv env(Env::Default());
  Options options;
  options.env = &env;

  // Originally no LOG exists. Should not see a rename.
  {
    std::shared_ptr<Logger> logger;
    ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
    ASSERT_EQ(0, env.rename_count_);
  }

  // Now a LOG exists. Create a new one should see a rename.
  {
    std::shared_ptr<Logger> logger;
    ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
    ASSERT_EQ(1, env.rename_count_);
  }
}

TEST_F(AutoRollLoggerTest, RenameError) {
  InitTestDb();
  SpecialEnv env(Env::Default());
  env.rename_error_ = true;
  Options options;
  options.env = &env;

  // Originally no LOG exists. Should not be impacted by rename error.
  {
    std::shared_ptr<Logger> logger;
    ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
    ASSERT_TRUE(logger != nullptr);
  }

  // Now a LOG exists. Rename error should cause failure.
  {
    std::shared_ptr<Logger> logger;
    ASSERT_NOK(CreateLoggerFromOptions(kTestDir, options, &logger));
    ASSERT_TRUE(logger == nullptr);
  }
}

}  // namespace ROCKSDB_NAMESPACE

int main(int argc, char** argv) {
  ::testing::InitGoogleTest(&argc, argv);
  return RUN_ALL_TESTS();
}

#else
#include <stdio.h>

int main(int /*argc*/, char** /*argv*/) {
  fprintf(stderr,
          "SKIPPED as AutoRollLogger is not supported in ROCKSDB_LITE\n");
  return 0;
}

#endif  // !ROCKSDB_LITE