ceph/src/rocksdb/logging/auto_roll_logger_test.cc

   1 //  Copyright (c) 2011-present, Facebook, Inc.  All rights reserved.
   2 //  This source code is licensed under both the GPLv2 (found in the
   3 //  COPYING file in the root directory) and Apache 2.0 License
   4 //  (found in the LICENSE.Apache file in the root directory).
   5 //
   6
   7 #ifndef ROCKSDB_LITE
   8
   9 #include "logging/auto_roll_logger.h"
  10
  11 #include <sys/stat.h>
  12
  13 #include <algorithm>
  14 #include <cmath>
  15 #include <fstream>
  16 #include <iostream>
  17 #include <iterator>
  18 #include <string>
  19 #include <thread>
  20 #include <vector>
  21
  22 #include "db/db_test_util.h"
  23 #include "env/emulated_clock.h"
  24 #include "logging/env_logger.h"
  25 #include "logging/logging.h"
  26 #include "port/port.h"
  27 #include "rocksdb/db.h"
  28 #include "rocksdb/file_system.h"
  29 #include "rocksdb/system_clock.h"
  30 #include "test_util/sync_point.h"
  31 #include "test_util/testharness.h"
  32 #include "test_util/testutil.h"
  33
  34 namespace ROCKSDB_NAMESPACE {
  35
  36 // In this test we only want to Log some simple log message with
  37 // no format. LogMessage() provides such a simple interface and
  38 // avoids the [format-security] warning which occurs when you
  39 // call ROCKS_LOG_INFO(logger, log_message) directly.
  40 namespace {
  41 void LogMessage(Logger* logger, const char* message) {
  42   ROCKS_LOG_INFO(logger, "%s", message);
  43 }
  44
  45 void LogMessage(const InfoLogLevel log_level, Logger* logger,
  46                 const char* message) {
  47   Log(log_level, logger, "%s", message);
  48 }
  49 }  // namespace
  50
  51 class AutoRollLoggerTest : public testing::Test {
  52  public:
  53   static void InitTestDb() {
  54     // TODO replace the `system` calls with Env/FileSystem APIs.
  55 #ifdef OS_WIN
  56     // Replace all slashes in the path so windows CompSpec does not
  57     // become confused
  58     std::string testDbDir(kTestDbDir);
  59     std::replace_if(
  60         testDbDir.begin(), testDbDir.end(), [](char ch) { return ch == '/'; },
  61         '\\');
  62     std::string deleteDbDirCmd =
  63         "if exist " + testDbDir + " rd /s /q " + testDbDir;
  64     ASSERT_TRUE(system(deleteDbDirCmd.c_str()) == 0);
  65
  66     std::string testDir(kTestDir);
  67     std::replace_if(
  68         testDir.begin(), testDir.end(), [](char ch) { return ch == '/'; },
  69         '\\');
  70     std::string deleteCmd = "if exist " + testDir + " rd /s /q " + testDir;
  71 #else
  72     std::string deleteCmd = "rm -rf " + kTestDir + " " + kTestDbDir;
  73 #endif
  74     ASSERT_TRUE(system(deleteCmd.c_str()) == 0);
  75     ASSERT_OK(Env::Default()->CreateDir(kTestDir));
  76     ASSERT_OK(Env::Default()->CreateDir(kTestDbDir));
  77   }
  78
  79   void RollLogFileBySizeTest(AutoRollLogger* logger, size_t log_max_size,
  80                              const std::string& log_message);
  81   void RollLogFileByTimeTest(const std::shared_ptr<FileSystem>& fs,
  82                              const std::shared_ptr<SystemClock>& sc,
  83                              AutoRollLogger* logger, size_t time,
  84                              const std::string& log_message);
  85   // return list of files under kTestDir that contains "LOG"
  86   std::vector<std::string> GetLogFiles() {
  87     std::vector<std::string> ret;
  88     std::vector<std::string> files;
  89     Status s = default_env->GetChildren(kTestDir, &files);
  90     // Should call ASSERT_OK() here but it doesn't compile. It's not
  91     // worth the time figuring out why.
  92     EXPECT_TRUE(s.ok());
  93     for (const auto& f : files) {
  94       if (f.find("LOG") != std::string::npos) {
  95         ret.push_back(f);
  96       }
  97     }
  98     return ret;
  99   }
 100
 101   // Delete all log files under kTestDir
 102   void CleanupLogFiles() {
 103     for (const std::string& f : GetLogFiles()) {
 104       ASSERT_OK(default_env->DeleteFile(kTestDir + "/" + f));
 105     }
 106   }
 107
 108   void RollNTimesBySize(Logger* auto_roll_logger, size_t file_num,
 109                         size_t max_log_file_size) {
 110     // Roll the log 4 times, and it will trim to 3 files.
 111     std::string dummy_large_string;
 112     dummy_large_string.assign(max_log_file_size, '=');
 113     auto_roll_logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
 114     for (size_t i = 0; i < file_num + 1; i++) {
 115       // Log enough bytes to trigger at least one roll.
 116       LogMessage(auto_roll_logger, dummy_large_string.c_str());
 117       LogMessage(auto_roll_logger, "");
 118     }
 119   }
 120
 121   static const std::string kSampleMessage;
 122   static const std::string kTestDir;
 123   static const std::string kTestDbDir;
 124   static const std::string kLogFile;
 125   static Env* default_env;
 126 };
 127
 128 const std::string AutoRollLoggerTest::kSampleMessage(
 129     "this is the message to be written to the log file!!");
 130 const std::string AutoRollLoggerTest::kTestDir(
 131     test::PerThreadDBPath("db_log_test"));
 132 const std::string AutoRollLoggerTest::kTestDbDir(
 133     test::PerThreadDBPath("db_log_test_db"));
 134 const std::string AutoRollLoggerTest::kLogFile(
 135     test::PerThreadDBPath("db_log_test") + "/LOG");
 136 Env* AutoRollLoggerTest::default_env = Env::Default();
 137
 138 void AutoRollLoggerTest::RollLogFileBySizeTest(AutoRollLogger* logger,
 139                                                size_t log_max_size,
 140                                                const std::string& log_message) {
 141   logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
 142   ASSERT_EQ(InfoLogLevel::INFO_LEVEL, logger->GetInfoLogLevel());
 143   ASSERT_EQ(InfoLogLevel::INFO_LEVEL,
 144             logger->TEST_inner_logger()->GetInfoLogLevel());
 145   // measure the size of each message, which is supposed
 146   // to be equal or greater than log_message.size()
 147   LogMessage(logger, log_message.c_str());
 148   size_t message_size = logger->GetLogFileSize();
 149   size_t current_log_size = message_size;
 150
 151   // Test the cases when the log file will not be rolled.
 152   while (current_log_size + message_size < log_max_size) {
 153     LogMessage(logger, log_message.c_str());
 154     current_log_size += message_size;
 155     ASSERT_EQ(current_log_size, logger->GetLogFileSize());
 156   }
 157
 158   // Now the log file will be rolled
 159   LogMessage(logger, log_message.c_str());
 160   // Since rotation is checked before actual logging, we need to
 161   // trigger the rotation by logging another message.
 162   LogMessage(logger, log_message.c_str());
 163
 164   ASSERT_TRUE(message_size == logger->GetLogFileSize());
 165 }
 166
 167 void AutoRollLoggerTest::RollLogFileByTimeTest(
 168     const std::shared_ptr<FileSystem>& fs,
 169     const std::shared_ptr<SystemClock>& sc, AutoRollLogger* logger, size_t time,
 170     const std::string& log_message) {
 171   uint64_t expected_ctime;
 172   uint64_t actual_ctime;
 173
 174   uint64_t total_log_size;
 175   EXPECT_OK(fs->GetFileSize(kLogFile, IOOptions(), &total_log_size, nullptr));
 176   expected_ctime = logger->TEST_ctime();
 177   logger->SetCallNowMicrosEveryNRecords(0);
 178
 179   // -- Write to the log for several times, which is supposed
 180   // to be finished before time.
 181   for (int i = 0; i < 10; ++i) {
 182     sc->SleepForMicroseconds(50000);
 183     LogMessage(logger, log_message.c_str());
 184     EXPECT_OK(logger->GetStatus());
 185     // Make sure we always write to the same log file (by
 186     // checking the create time);
 187
 188     actual_ctime = logger->TEST_ctime();
 189
 190     // Also make sure the log size is increasing.
 191     EXPECT_EQ(expected_ctime, actual_ctime);
 192     EXPECT_GT(logger->GetLogFileSize(), total_log_size);
 193     total_log_size = logger->GetLogFileSize();
 194   }
 195
 196   // -- Make the log file expire
 197   sc->SleepForMicroseconds(static_cast<int>(time * 1000000));
 198   LogMessage(logger, log_message.c_str());
 199
 200   // At this time, the new log file should be created.
 201   actual_ctime = logger->TEST_ctime();
 202   EXPECT_LT(expected_ctime, actual_ctime);
 203   EXPECT_LT(logger->GetLogFileSize(), total_log_size);
 204 }
 205
 206 TEST_F(AutoRollLoggerTest, RollLogFileBySize) {
 207   InitTestDb();
 208   size_t log_max_size = 1024 * 5;
 209   size_t keep_log_file_num = 10;
 210
 211   AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(), kTestDir,
 212                         "", log_max_size, 0, keep_log_file_num);
 213
 214   RollLogFileBySizeTest(&logger, log_max_size,
 215                         kSampleMessage + ":RollLogFileBySize");
 216 }
 217
 218 TEST_F(AutoRollLoggerTest, RollLogFileByTime) {
 219   auto nsc =
 220       std::make_shared<EmulatedSystemClock>(SystemClock::Default(), true);
 221
 222   size_t time = 2;
 223   size_t log_size = 1024 * 5;
 224   size_t keep_log_file_num = 10;
 225
 226   InitTestDb();
 227   // -- Test the existence of file during the server restart.
 228   ASSERT_EQ(Status::NotFound(), default_env->FileExists(kLogFile));
 229   AutoRollLogger logger(default_env->GetFileSystem(), nsc, kTestDir, "",
 230                         log_size, time, keep_log_file_num);
 231   ASSERT_OK(default_env->FileExists(kLogFile));
 232
 233   RollLogFileByTimeTest(default_env->GetFileSystem(), nsc, &logger, time,
 234                         kSampleMessage + ":RollLogFileByTime");
 235 }
 236
 237 TEST_F(AutoRollLoggerTest, SetInfoLogLevel) {
 238   InitTestDb();
 239   Options options;
 240   options.info_log_level = InfoLogLevel::FATAL_LEVEL;
 241   options.max_log_file_size = 1024;
 242   std::shared_ptr<Logger> logger;
 243   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 244   auto* auto_roll_logger = dynamic_cast<AutoRollLogger*>(logger.get());
 245   ASSERT_NE(nullptr, auto_roll_logger);
 246   ASSERT_EQ(InfoLogLevel::FATAL_LEVEL, auto_roll_logger->GetInfoLogLevel());
 247   ASSERT_EQ(InfoLogLevel::FATAL_LEVEL,
 248             auto_roll_logger->TEST_inner_logger()->GetInfoLogLevel());
 249   auto_roll_logger->SetInfoLogLevel(InfoLogLevel::DEBUG_LEVEL);
 250   ASSERT_EQ(InfoLogLevel::DEBUG_LEVEL, auto_roll_logger->GetInfoLogLevel());
 251   ASSERT_EQ(InfoLogLevel::DEBUG_LEVEL, logger->GetInfoLogLevel());
 252   ASSERT_EQ(InfoLogLevel::DEBUG_LEVEL,
 253             auto_roll_logger->TEST_inner_logger()->GetInfoLogLevel());
 254 }
 255
 256 TEST_F(AutoRollLoggerTest, OpenLogFilesMultipleTimesWithOptionLog_max_size) {
 257   // If only 'log_max_size' options is specified, then every time
 258   // when rocksdb is restarted, a new empty log file will be created.
 259   InitTestDb();
 260   // WORKAROUND:
 261   // avoid complier's complaint of "comparison between signed
 262   // and unsigned integer expressions" because literal 0 is
 263   // treated as "singed".
 264   size_t kZero = 0;
 265   size_t log_size = 1024;
 266   size_t keep_log_file_num = 10;
 267
 268   AutoRollLogger* logger =
 269       new AutoRollLogger(FileSystem::Default(), SystemClock::Default(),
 270                          kTestDir, "", log_size, 0, keep_log_file_num);
 271
 272   LogMessage(logger, kSampleMessage.c_str());
 273   ASSERT_GT(logger->GetLogFileSize(), kZero);
 274   delete logger;
 275
 276   // reopens the log file and an empty log file will be created.
 277   logger = new AutoRollLogger(FileSystem::Default(), SystemClock::Default(),
 278                               kTestDir, "", log_size, 0, 10);
 279   ASSERT_EQ(logger->GetLogFileSize(), kZero);
 280   delete logger;
 281 }
 282
 283 TEST_F(AutoRollLoggerTest, CompositeRollByTimeAndSizeLogger) {
 284   size_t time = 2, log_max_size = 1024 * 5;
 285   size_t keep_log_file_num = 10;
 286
 287   InitTestDb();
 288
 289   auto nsc =
 290       std::make_shared<EmulatedSystemClock>(SystemClock::Default(), true);
 291   AutoRollLogger logger(FileSystem::Default(), nsc, kTestDir, "", log_max_size,
 292                         time, keep_log_file_num);
 293
 294   // Test the ability to roll by size
 295   RollLogFileBySizeTest(&logger, log_max_size,
 296                         kSampleMessage + ":CompositeRollByTimeAndSizeLogger");
 297
 298   // Test the ability to roll by Time
 299   RollLogFileByTimeTest(FileSystem::Default(), nsc, &logger, time,
 300                         kSampleMessage + ":CompositeRollByTimeAndSizeLogger");
 301 }
 302
 303 #ifndef OS_WIN
 304 // TODO: does not build for Windows because of EnvLogger use below. Need to
 305 // port
 306 TEST_F(AutoRollLoggerTest, CreateLoggerFromOptions) {
 307   DBOptions options;
 308   auto nsc =
 309       std::make_shared<EmulatedSystemClock>(SystemClock::Default(), true);
 310   std::unique_ptr<Env> nse(new CompositeEnvWrapper(Env::Default(), nsc));
 311
 312   std::shared_ptr<Logger> logger;
 313
 314   // Normal logger
 315   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 316   ASSERT_TRUE(dynamic_cast<EnvLogger*>(logger.get()));
 317
 318   // Only roll by size
 319   InitTestDb();
 320   options.max_log_file_size = 1024;
 321   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 322   AutoRollLogger* auto_roll_logger =
 323       dynamic_cast<AutoRollLogger*>(logger.get());
 324   ASSERT_TRUE(auto_roll_logger);
 325   RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
 326                         kSampleMessage + ":CreateLoggerFromOptions - size");
 327
 328   // Only roll by Time
 329   options.env = nse.get();
 330   InitTestDb();
 331   options.max_log_file_size = 0;
 332   options.log_file_time_to_roll = 2;
 333   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 334   auto_roll_logger = dynamic_cast<AutoRollLogger*>(logger.get());
 335   RollLogFileByTimeTest(options.env->GetFileSystem(), nsc, auto_roll_logger,
 336                         options.log_file_time_to_roll,
 337                         kSampleMessage + ":CreateLoggerFromOptions - time");
 338
 339   // roll by both Time and size
 340   InitTestDb();
 341   options.max_log_file_size = 1024 * 5;
 342   options.log_file_time_to_roll = 2;
 343   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 344   auto_roll_logger = dynamic_cast<AutoRollLogger*>(logger.get());
 345   RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
 346                         kSampleMessage + ":CreateLoggerFromOptions - both");
 347   RollLogFileByTimeTest(options.env->GetFileSystem(), nsc, auto_roll_logger,
 348                         options.log_file_time_to_roll,
 349                         kSampleMessage + ":CreateLoggerFromOptions - both");
 350
 351   // Set keep_log_file_num
 352   {
 353     const size_t kFileNum = 3;
 354     InitTestDb();
 355     options.max_log_file_size = 512;
 356     options.log_file_time_to_roll = 2;
 357     options.keep_log_file_num = kFileNum;
 358     ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 359     auto_roll_logger = dynamic_cast<AutoRollLogger*>(logger.get());
 360
 361     // Roll the log 4 times, and it will trim to 3 files.
 362     std::string dummy_large_string;
 363     dummy_large_string.assign(options.max_log_file_size, '=');
 364     auto_roll_logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
 365     for (size_t i = 0; i < kFileNum + 1; i++) {
 366       // Log enough bytes to trigger at least one roll.
 367       LogMessage(auto_roll_logger, dummy_large_string.c_str());
 368       LogMessage(auto_roll_logger, "");
 369     }
 370
 371     std::vector<std::string> files = GetLogFiles();
 372     ASSERT_EQ(kFileNum, files.size());
 373
 374     CleanupLogFiles();
 375   }
 376
 377   // Set keep_log_file_num and dbname is different from
 378   // db_log_dir.
 379   {
 380     const size_t kFileNum = 3;
 381     InitTestDb();
 382     options.max_log_file_size = 512;
 383     options.log_file_time_to_roll = 2;
 384     options.keep_log_file_num = kFileNum;
 385     options.db_log_dir = kTestDir;
 386     ASSERT_OK(CreateLoggerFromOptions(kTestDbDir, options, &logger));
 387     auto_roll_logger = dynamic_cast<AutoRollLogger*>(logger.get());
 388
 389     // Roll the log 4 times, and it will trim to 3 files.
 390     std::string dummy_large_string;
 391     dummy_large_string.assign(options.max_log_file_size, '=');
 392     auto_roll_logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
 393     for (size_t i = 0; i < kFileNum + 1; i++) {
 394       // Log enough bytes to trigger at least one roll.
 395       LogMessage(auto_roll_logger, dummy_large_string.c_str());
 396       LogMessage(auto_roll_logger, "");
 397     }
 398
 399     std::vector<std::string> files = GetLogFiles();
 400     ASSERT_EQ(kFileNum, files.size());
 401     for (const auto& f : files) {
 402       ASSERT_TRUE(f.find("db_log_test_db") != std::string::npos);
 403     }
 404
 405     // Cleaning up those files.
 406     CleanupLogFiles();
 407   }
 408 }
 409
 410 TEST_F(AutoRollLoggerTest, AutoDeleting) {
 411   for (int attempt = 0; attempt < 2; attempt++) {
 412     // In the first attemp, db_log_dir is not set, while in the
 413     // second it is set.
 414     std::string dbname = (attempt == 0) ? kTestDir : "/test/dummy/dir";
 415     std::string db_log_dir = (attempt == 0) ? "" : kTestDir;
 416
 417     InitTestDb();
 418     const size_t kMaxFileSize = 512;
 419     {
 420       size_t log_num = 8;
 421       AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
 422                             dbname, db_log_dir, kMaxFileSize, 0, log_num);
 423       RollNTimesBySize(&logger, log_num, kMaxFileSize);
 424
 425       ASSERT_EQ(log_num, GetLogFiles().size());
 426     }
 427     // Shrink number of files
 428     {
 429       size_t log_num = 5;
 430       AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
 431                             dbname, db_log_dir, kMaxFileSize, 0, log_num);
 432       ASSERT_EQ(log_num, GetLogFiles().size());
 433
 434       RollNTimesBySize(&logger, 3, kMaxFileSize);
 435       ASSERT_EQ(log_num, GetLogFiles().size());
 436     }
 437
 438     // Increase number of files again.
 439     {
 440       size_t log_num = 7;
 441       AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
 442                             dbname, db_log_dir, kMaxFileSize, 0, log_num);
 443       ASSERT_EQ(6, GetLogFiles().size());
 444
 445       RollNTimesBySize(&logger, 3, kMaxFileSize);
 446       ASSERT_EQ(log_num, GetLogFiles().size());
 447     }
 448
 449     CleanupLogFiles();
 450   }
 451 }
 452
 453 TEST_F(AutoRollLoggerTest, LogFlushWhileRolling) {
 454   DBOptions options;
 455   std::shared_ptr<Logger> logger;
 456
 457   InitTestDb();
 458   options.max_log_file_size = 1024 * 5;
 459   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 460   AutoRollLogger* auto_roll_logger =
 461       dynamic_cast<AutoRollLogger*>(logger.get());
 462   ASSERT_TRUE(auto_roll_logger);
 463   ROCKSDB_NAMESPACE::port::Thread flush_thread;
 464
 465   // Notes:
 466   // (1) Need to pin the old logger before beginning the roll, as rolling grabs
 467   //     the mutex, which would prevent us from accessing the old logger. This
 468   //     also marks flush_thread with AutoRollLogger::Flush:PinnedLogger.
 469   // (2) New logger will be cut in AutoRollLogger::RollLogFile only when flush
 470   //     is completed and reference to pinned logger is released.
 471   // (3) EnvLogger::Flush() happens in both threads but its SyncPoints only
 472   //     are enabled in flush_thread (the one pinning the old logger).
 473   ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->LoadDependencyAndMarkers(
 474       {{"AutoRollLogger::Flush:PinnedLogger",
 475         "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit"}},
 476       {{"AutoRollLogger::Flush:PinnedLogger", "EnvLogger::Flush:Begin1"},
 477        {"AutoRollLogger::Flush:PinnedLogger", "EnvLogger::Flush:Begin2"}});
 478   ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->EnableProcessing();
 479
 480   flush_thread = port::Thread([&]() { auto_roll_logger->Flush(); });
 481   TEST_SYNC_POINT(
 482       "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit");
 483   RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
 484                         kSampleMessage + ":LogFlushWhileRolling");
 485   flush_thread.join();
 486   ROCKSDB_NAMESPACE::SyncPoint::GetInstance()->DisableProcessing();
 487 }
 488
 489 #endif  // OS_WIN
 490
 491 TEST_F(AutoRollLoggerTest, InfoLogLevel) {
 492   InitTestDb();
 493
 494   size_t log_size = 8192;
 495   size_t log_lines = 0;
 496   // an extra-scope to force the AutoRollLogger to flush the log file when it
 497   // becomes out of scope.
 498   {
 499     AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
 500                           kTestDir, "", log_size, 0, 10);
 501     for (int log_level = InfoLogLevel::HEADER_LEVEL;
 502          log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
 503       logger.SetInfoLogLevel((InfoLogLevel)log_level);
 504       for (int log_type = InfoLogLevel::DEBUG_LEVEL;
 505            log_type <= InfoLogLevel::HEADER_LEVEL; log_type++) {
 506         // log messages with log level smaller than log_level will not be
 507         // logged.
 508         LogMessage((InfoLogLevel)log_type, &logger, kSampleMessage.c_str());
 509       }
 510       log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
 511     }
 512     for (int log_level = InfoLogLevel::HEADER_LEVEL;
 513          log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
 514       logger.SetInfoLogLevel((InfoLogLevel)log_level);
 515
 516       // again, messages with level smaller than log_level will not be logged.
 517       ROCKS_LOG_HEADER(&logger, "%s", kSampleMessage.c_str());
 518       ROCKS_LOG_DEBUG(&logger, "%s", kSampleMessage.c_str());
 519       ROCKS_LOG_INFO(&logger, "%s", kSampleMessage.c_str());
 520       ROCKS_LOG_WARN(&logger, "%s", kSampleMessage.c_str());
 521       ROCKS_LOG_ERROR(&logger, "%s", kSampleMessage.c_str());
 522       ROCKS_LOG_FATAL(&logger, "%s", kSampleMessage.c_str());
 523       log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
 524     }
 525   }
 526   std::ifstream inFile(AutoRollLoggerTest::kLogFile.c_str());
 527   size_t lines = std::count(std::istreambuf_iterator<char>(inFile),
 528                             std::istreambuf_iterator<char>(), '\n');
 529   ASSERT_EQ(log_lines, lines);
 530   inFile.close();
 531 }
 532
 533 TEST_F(AutoRollLoggerTest, Close) {
 534   InitTestDb();
 535
 536   size_t log_size = 8192;
 537   size_t log_lines = 0;
 538   AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(), kTestDir,
 539                         "", log_size, 0, 10);
 540   for (int log_level = InfoLogLevel::HEADER_LEVEL;
 541        log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
 542     logger.SetInfoLogLevel((InfoLogLevel)log_level);
 543     for (int log_type = InfoLogLevel::DEBUG_LEVEL;
 544          log_type <= InfoLogLevel::HEADER_LEVEL; log_type++) {
 545       // log messages with log level smaller than log_level will not be
 546       // logged.
 547       LogMessage((InfoLogLevel)log_type, &logger, kSampleMessage.c_str());
 548     }
 549     log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
 550   }
 551   for (int log_level = InfoLogLevel::HEADER_LEVEL;
 552        log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
 553     logger.SetInfoLogLevel((InfoLogLevel)log_level);
 554
 555     // again, messages with level smaller than log_level will not be logged.
 556     ROCKS_LOG_HEADER(&logger, "%s", kSampleMessage.c_str());
 557     ROCKS_LOG_DEBUG(&logger, "%s", kSampleMessage.c_str());
 558     ROCKS_LOG_INFO(&logger, "%s", kSampleMessage.c_str());
 559     ROCKS_LOG_WARN(&logger, "%s", kSampleMessage.c_str());
 560     ROCKS_LOG_ERROR(&logger, "%s", kSampleMessage.c_str());
 561     ROCKS_LOG_FATAL(&logger, "%s", kSampleMessage.c_str());
 562     log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
 563   }
 564   ASSERT_EQ(logger.Close(), Status::OK());
 565
 566   std::ifstream inFile(AutoRollLoggerTest::kLogFile.c_str());
 567   size_t lines = std::count(std::istreambuf_iterator<char>(inFile),
 568                             std::istreambuf_iterator<char>(), '\n');
 569   ASSERT_EQ(log_lines, lines);
 570   inFile.close();
 571 }
 572
 573 // Test the logger Header function for roll over logs
 574 // We expect the new logs creates as roll over to carry the headers specified
 575 static std::vector<std::string> GetOldFileNames(const std::string& path) {
 576   std::vector<std::string> ret;
 577
 578   const std::string dirname = path.substr(/*start=*/0, path.find_last_of("/"));
 579   const std::string fname = path.substr(path.find_last_of("/") + 1);
 580
 581   std::vector<std::string> children;
 582   EXPECT_OK(Env::Default()->GetChildren(dirname, &children));
 583
 584   // We know that the old log files are named [path]<something>
 585   // Return all entities that match the pattern
 586   for (auto& child : children) {
 587     if (fname != child && child.find(fname) == 0) {
 588       ret.push_back(dirname + "/" + child);
 589     }
 590   }
 591
 592   return ret;
 593 }
 594
 595 TEST_F(AutoRollLoggerTest, LogHeaderTest) {
 596   static const size_t MAX_HEADERS = 10;
 597   static const size_t LOG_MAX_SIZE = 1024 * 5;
 598   static const std::string HEADER_STR = "Log header line";
 599
 600   // test_num == 0 -> standard call to Header()
 601   // test_num == 1 -> call to Log() with InfoLogLevel::HEADER_LEVEL
 602   for (int test_num = 0; test_num < 2; test_num++) {
 603     InitTestDb();
 604
 605     AutoRollLogger logger(FileSystem::Default(), SystemClock::Default(),
 606                           kTestDir, /*db_log_dir=*/"", LOG_MAX_SIZE,
 607                           /*log_file_time_to_roll=*/0,
 608                           /*keep_log_file_num=*/10);
 609
 610     if (test_num == 0) {
 611       // Log some headers explicitly using Header()
 612       for (size_t i = 0; i < MAX_HEADERS; i++) {
 613         Header(&logger, "%s %" ROCKSDB_PRIszt, HEADER_STR.c_str(), i);
 614       }
 615     } else if (test_num == 1) {
 616       // HEADER_LEVEL should make this behave like calling Header()
 617       for (size_t i = 0; i < MAX_HEADERS; i++) {
 618         ROCKS_LOG_HEADER(&logger, "%s %" ROCKSDB_PRIszt, HEADER_STR.c_str(), i);
 619       }
 620     }
 621
 622     const std::string newfname = logger.TEST_log_fname();
 623
 624     // Log enough data to cause a roll over
 625     int i = 0;
 626     for (size_t iter = 0; iter < 2; iter++) {
 627       while (logger.GetLogFileSize() < LOG_MAX_SIZE) {
 628         Info(&logger, (kSampleMessage + ":LogHeaderTest line %d").c_str(), i);
 629         ++i;
 630       }
 631
 632       Info(&logger, "Rollover");
 633     }
 634
 635     // Flush the log for the latest file
 636     LogFlush(&logger);
 637
 638     const auto oldfiles = GetOldFileNames(newfname);
 639
 640     ASSERT_EQ(oldfiles.size(), (size_t)2);
 641
 642     for (auto& oldfname : oldfiles) {
 643       // verify that the files rolled over
 644       ASSERT_NE(oldfname, newfname);
 645       // verify that the old log contains all the header logs
 646       ASSERT_EQ(test::GetLinesCount(oldfname, HEADER_STR), MAX_HEADERS);
 647     }
 648   }
 649 }
 650
 651 TEST_F(AutoRollLoggerTest, LogFileExistence) {
 652   ROCKSDB_NAMESPACE::DB* db;
 653   ROCKSDB_NAMESPACE::Options options;
 654 #ifdef OS_WIN
 655   // Replace all slashes in the path so windows CompSpec does not
 656   // become confused
 657   std::string testDir(kTestDir);
 658   std::replace_if(
 659       testDir.begin(), testDir.end(), [](char ch) { return ch == '/'; }, '\\');
 660   std::string deleteCmd = "if exist " + testDir + " rd /s /q " + testDir;
 661 #else
 662   std::string deleteCmd = "rm -rf " + kTestDir;
 663 #endif
 664   ASSERT_EQ(system(deleteCmd.c_str()), 0);
 665   options.max_log_file_size = 100 * 1024 * 1024;
 666   options.create_if_missing = true;
 667   ASSERT_OK(ROCKSDB_NAMESPACE::DB::Open(options, kTestDir, &db));
 668   ASSERT_OK(default_env->FileExists(kLogFile));
 669   delete db;
 670 }
 671
 672 TEST_F(AutoRollLoggerTest, FileCreateFailure) {
 673   Options options;
 674   options.max_log_file_size = 100 * 1024 * 1024;
 675   options.db_log_dir = "/a/dir/does/not/exist/at/all";
 676
 677   std::shared_ptr<Logger> logger;
 678   ASSERT_NOK(CreateLoggerFromOptions("", options, &logger));
 679   ASSERT_TRUE(!logger);
 680 }
 681
 682 TEST_F(AutoRollLoggerTest, RenameOnlyWhenExists) {
 683   InitTestDb();
 684   SpecialEnv env(Env::Default());
 685   Options options;
 686   options.env = &env;
 687
 688   // Originally no LOG exists. Should not see a rename.
 689   {
 690     std::shared_ptr<Logger> logger;
 691     ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 692     ASSERT_EQ(0, env.rename_count_);
 693   }
 694
 695   // Now a LOG exists. Create a new one should see a rename.
 696   {
 697     std::shared_ptr<Logger> logger;
 698     ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 699     ASSERT_EQ(1, env.rename_count_);
 700   }
 701 }
 702
 703 TEST_F(AutoRollLoggerTest, RenameError) {
 704   InitTestDb();
 705   SpecialEnv env(Env::Default());
 706   env.rename_error_ = true;
 707   Options options;
 708   options.env = &env;
 709
 710   // Originally no LOG exists. Should not be impacted by rename error.
 711   {
 712     std::shared_ptr<Logger> logger;
 713     ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 714     ASSERT_TRUE(logger != nullptr);
 715   }
 716
 717   // Now a LOG exists. Rename error should cause failure.
 718   {
 719     std::shared_ptr<Logger> logger;
 720     ASSERT_NOK(CreateLoggerFromOptions(kTestDir, options, &logger));
 721     ASSERT_TRUE(logger == nullptr);
 722   }
 723 }
 724
 725 }  // namespace ROCKSDB_NAMESPACE
 726
 727 int main(int argc, char** argv) {
 728   ROCKSDB_NAMESPACE::port::InstallStackTraceHandler();
 729   ::testing::InitGoogleTest(&argc, argv);
 730   return RUN_ALL_TESTS();
 731 }
 732
 733 #else
 734 #include <stdio.h>
 735
 736 int main(int /*argc*/, char** /*argv*/) {
 737   fprintf(stderr,
 738           "SKIPPED as AutoRollLogger is not supported in ROCKSDB_LITE\n");
 739   return 0;
 740 }
 741
 742 #endif  // !ROCKSDB_LITE