ceph/src/rocksdb/util/auto_roll_logger_test.cc

   1 //  Copyright (c) 2011-present, Facebook, Inc.  All rights reserved.
   2 //  This source code is licensed under the BSD-style license found in the
   3 //  LICENSE file in the root directory of this source tree. An additional grant
   4 //  of patent rights can be found in the PATENTS file in the same directory.
   5 //
   6
   7 #ifndef ROCKSDB_LITE
   8
   9 #include "util/auto_roll_logger.h"
  10 #include <errno.h>
  11 #include <sys/stat.h>
  12 #include <algorithm>
  13 #include <cmath>
  14 #include <fstream>
  15 #include <iostream>
  16 #include <iterator>
  17 #include <string>
  18 #include <thread>
  19 #include <vector>
  20 #include "port/port.h"
  21 #include "rocksdb/db.h"
  22 #include "util/logging.h"
  23 #include "util/sync_point.h"
  24 #include "util/testharness.h"
  25
  26 namespace rocksdb {
  27 namespace {
  28 class NoSleepEnv : public EnvWrapper {
  29  public:
  30   NoSleepEnv(Env* base) : EnvWrapper(base) {}
  31   virtual void SleepForMicroseconds(int micros) override {
  32     fake_time_ += static_cast<uint64_t>(micros);
  33   }
  34
  35   virtual uint64_t NowNanos() override { return fake_time_ * 1000; }
  36
  37   virtual uint64_t NowMicros() override { return fake_time_; }
  38
  39  private:
  40   uint64_t fake_time_ = 6666666666;
  41 };
  42 }  // namespace
  43
  44 class AutoRollLoggerTest : public testing::Test {
  45  public:
  46   static void InitTestDb() {
  47 #ifdef OS_WIN
  48     // Replace all slashes in the path so windows CompSpec does not
  49     // become confused
  50     std::string testDir(kTestDir);
  51     std::replace_if(testDir.begin(), testDir.end(),
  52                     [](char ch) { return ch == '/'; }, '\\');
  53     std::string deleteCmd = "if exist " + testDir + " rd /s /q " + testDir;
  54 #else
  55     std::string deleteCmd = "rm -rf " + kTestDir;
  56 #endif
  57     ASSERT_TRUE(system(deleteCmd.c_str()) == 0);
  58     Env::Default()->CreateDir(kTestDir);
  59   }
  60
  61   void RollLogFileBySizeTest(AutoRollLogger* logger, size_t log_max_size,
  62                              const std::string& log_message);
  63   void RollLogFileByTimeTest(Env*, AutoRollLogger* logger, size_t time,
  64                              const std::string& log_message);
  65
  66   static const std::string kSampleMessage;
  67   static const std::string kTestDir;
  68   static const std::string kLogFile;
  69   static Env* default_env;
  70 };
  71
  72 const std::string AutoRollLoggerTest::kSampleMessage(
  73     "this is the message to be written to the log file!!");
  74 const std::string AutoRollLoggerTest::kTestDir(test::TmpDir() + "/db_log_test");
  75 const std::string AutoRollLoggerTest::kLogFile(test::TmpDir() +
  76                                                "/db_log_test/LOG");
  77 Env* AutoRollLoggerTest::default_env = Env::Default();
  78
  79 // In this test we only want to Log some simple log message with
  80 // no format. LogMessage() provides such a simple interface and
  81 // avoids the [format-security] warning which occurs when you
  82 // call ROCKS_LOG_INFO(logger, log_message) directly.
  83 namespace {
  84 void LogMessage(Logger* logger, const char* message) {
  85   ROCKS_LOG_INFO(logger, "%s", message);
  86 }
  87
  88 void LogMessage(const InfoLogLevel log_level, Logger* logger,
  89                 const char* message) {
  90   Log(log_level, logger, "%s", message);
  91 }
  92 }  // namespace
  93
  94 void AutoRollLoggerTest::RollLogFileBySizeTest(AutoRollLogger* logger,
  95                                                size_t log_max_size,
  96                                                const std::string& log_message) {
  97   logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
  98   // measure the size of each message, which is supposed
  99   // to be equal or greater than log_message.size()
 100   LogMessage(logger, log_message.c_str());
 101   size_t message_size = logger->GetLogFileSize();
 102   size_t current_log_size = message_size;
 103
 104   // Test the cases when the log file will not be rolled.
 105   while (current_log_size + message_size < log_max_size) {
 106     LogMessage(logger, log_message.c_str());
 107     current_log_size += message_size;
 108     ASSERT_EQ(current_log_size, logger->GetLogFileSize());
 109   }
 110
 111   // Now the log file will be rolled
 112   LogMessage(logger, log_message.c_str());
 113   // Since rotation is checked before actual logging, we need to
 114   // trigger the rotation by logging another message.
 115   LogMessage(logger, log_message.c_str());
 116
 117   ASSERT_TRUE(message_size == logger->GetLogFileSize());
 118 }
 119
 120 void AutoRollLoggerTest::RollLogFileByTimeTest(Env* env, AutoRollLogger* logger,
 121                                                size_t time,
 122                                                const std::string& log_message) {
 123   uint64_t expected_ctime;
 124   uint64_t actual_ctime;
 125
 126   uint64_t total_log_size;
 127   EXPECT_OK(env->GetFileSize(kLogFile, &total_log_size));
 128   expected_ctime = logger->TEST_ctime();
 129   logger->SetCallNowMicrosEveryNRecords(0);
 130
 131   // -- Write to the log for several times, which is supposed
 132   // to be finished before time.
 133   for (int i = 0; i < 10; ++i) {
 134     env->SleepForMicroseconds(50000);
 135     LogMessage(logger, log_message.c_str());
 136     EXPECT_OK(logger->GetStatus());
 137     // Make sure we always write to the same log file (by
 138     // checking the create time);
 139
 140     actual_ctime = logger->TEST_ctime();
 141
 142     // Also make sure the log size is increasing.
 143     EXPECT_EQ(expected_ctime, actual_ctime);
 144     EXPECT_GT(logger->GetLogFileSize(), total_log_size);
 145     total_log_size = logger->GetLogFileSize();
 146   }
 147
 148   // -- Make the log file expire
 149   env->SleepForMicroseconds(static_cast<int>(time * 1000000));
 150   LogMessage(logger, log_message.c_str());
 151
 152   // At this time, the new log file should be created.
 153   actual_ctime = logger->TEST_ctime();
 154   EXPECT_LT(expected_ctime, actual_ctime);
 155   EXPECT_LT(logger->GetLogFileSize(), total_log_size);
 156 }
 157
 158 TEST_F(AutoRollLoggerTest, RollLogFileBySize) {
 159     InitTestDb();
 160     size_t log_max_size = 1024 * 5;
 161
 162     AutoRollLogger logger(Env::Default(), kTestDir, "", log_max_size, 0);
 163
 164     RollLogFileBySizeTest(&logger, log_max_size,
 165                           kSampleMessage + ":RollLogFileBySize");
 166 }
 167
 168 TEST_F(AutoRollLoggerTest, RollLogFileByTime) {
 169   NoSleepEnv nse(Env::Default());
 170
 171   size_t time = 2;
 172   size_t log_size = 1024 * 5;
 173
 174   InitTestDb();
 175   // -- Test the existence of file during the server restart.
 176   ASSERT_EQ(Status::NotFound(), default_env->FileExists(kLogFile));
 177   AutoRollLogger logger(&nse, kTestDir, "", log_size, time);
 178   ASSERT_OK(default_env->FileExists(kLogFile));
 179
 180   RollLogFileByTimeTest(&nse, &logger, time,
 181                         kSampleMessage + ":RollLogFileByTime");
 182 }
 183
 184 TEST_F(AutoRollLoggerTest, OpenLogFilesMultipleTimesWithOptionLog_max_size) {
 185   // If only 'log_max_size' options is specified, then every time
 186   // when rocksdb is restarted, a new empty log file will be created.
 187   InitTestDb();
 188   // WORKAROUND:
 189   // avoid complier's complaint of "comparison between signed
 190   // and unsigned integer expressions" because literal 0 is
 191   // treated as "singed".
 192   size_t kZero = 0;
 193   size_t log_size = 1024;
 194
 195   AutoRollLogger* logger = new AutoRollLogger(
 196     Env::Default(), kTestDir, "", log_size, 0);
 197
 198   LogMessage(logger, kSampleMessage.c_str());
 199   ASSERT_GT(logger->GetLogFileSize(), kZero);
 200   delete logger;
 201
 202   // reopens the log file and an empty log file will be created.
 203   logger = new AutoRollLogger(
 204     Env::Default(), kTestDir, "", log_size, 0);
 205   ASSERT_EQ(logger->GetLogFileSize(), kZero);
 206   delete logger;
 207 }
 208
 209 TEST_F(AutoRollLoggerTest, CompositeRollByTimeAndSizeLogger) {
 210   size_t time = 2, log_max_size = 1024 * 5;
 211
 212   InitTestDb();
 213
 214   NoSleepEnv nse(Env::Default());
 215   AutoRollLogger logger(&nse, kTestDir, "", log_max_size, time);
 216
 217   // Test the ability to roll by size
 218   RollLogFileBySizeTest(&logger, log_max_size,
 219                         kSampleMessage + ":CompositeRollByTimeAndSizeLogger");
 220
 221   // Test the ability to roll by Time
 222   RollLogFileByTimeTest(&nse, &logger, time,
 223                         kSampleMessage + ":CompositeRollByTimeAndSizeLogger");
 224 }
 225
 226 #ifndef OS_WIN
 227 // TODO: does not build for Windows because of PosixLogger use below. Need to
 228 // port
 229 TEST_F(AutoRollLoggerTest, CreateLoggerFromOptions) {
 230   DBOptions options;
 231   NoSleepEnv nse(Env::Default());
 232   shared_ptr<Logger> logger;
 233
 234   // Normal logger
 235   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 236   ASSERT_TRUE(dynamic_cast<PosixLogger*>(logger.get()));
 237
 238   // Only roll by size
 239   InitTestDb();
 240   options.max_log_file_size = 1024;
 241   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 242   AutoRollLogger* auto_roll_logger =
 243     dynamic_cast<AutoRollLogger*>(logger.get());
 244   ASSERT_TRUE(auto_roll_logger);
 245   RollLogFileBySizeTest(
 246       auto_roll_logger, options.max_log_file_size,
 247       kSampleMessage + ":CreateLoggerFromOptions - size");
 248
 249   // Only roll by Time
 250   options.env = &nse;
 251   InitTestDb();
 252   options.max_log_file_size = 0;
 253   options.log_file_time_to_roll = 2;
 254   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 255   auto_roll_logger =
 256     dynamic_cast<AutoRollLogger*>(logger.get());
 257   RollLogFileByTimeTest(&nse, auto_roll_logger, options.log_file_time_to_roll,
 258                         kSampleMessage + ":CreateLoggerFromOptions - time");
 259
 260   // roll by both Time and size
 261   InitTestDb();
 262   options.max_log_file_size = 1024 * 5;
 263   options.log_file_time_to_roll = 2;
 264   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 265   auto_roll_logger =
 266     dynamic_cast<AutoRollLogger*>(logger.get());
 267   RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
 268                         kSampleMessage + ":CreateLoggerFromOptions - both");
 269   RollLogFileByTimeTest(&nse, auto_roll_logger, options.log_file_time_to_roll,
 270                         kSampleMessage + ":CreateLoggerFromOptions - both");
 271 }
 272
 273 TEST_F(AutoRollLoggerTest, LogFlushWhileRolling) {
 274   DBOptions options;
 275   shared_ptr<Logger> logger;
 276
 277   InitTestDb();
 278   options.max_log_file_size = 1024 * 5;
 279   ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
 280   AutoRollLogger* auto_roll_logger =
 281       dynamic_cast<AutoRollLogger*>(logger.get());
 282   ASSERT_TRUE(auto_roll_logger);
 283   rocksdb::port::Thread flush_thread;
 284
 285   // Notes:
 286   // (1) Need to pin the old logger before beginning the roll, as rolling grabs
 287   //     the mutex, which would prevent us from accessing the old logger. This
 288   //     also marks flush_thread with AutoRollLogger::Flush:PinnedLogger.
 289   // (2) Need to reset logger during PosixLogger::Flush() to exercise a race
 290   //     condition case, which is executing the flush with the pinned (old)
 291   //     logger after auto-roll logger has cut over to a new logger.
 292   // (3) PosixLogger::Flush() happens in both threads but its SyncPoints only
 293   //     are enabled in flush_thread (the one pinning the old logger).
 294   rocksdb::SyncPoint::GetInstance()->LoadDependencyAndMarkers(
 295       {{"AutoRollLogger::Flush:PinnedLogger",
 296         "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit"},
 297        {"PosixLogger::Flush:Begin1",
 298         "AutoRollLogger::ResetLogger:BeforeNewLogger"},
 299        {"AutoRollLogger::ResetLogger:AfterNewLogger",
 300         "PosixLogger::Flush:Begin2"}},
 301       {{"AutoRollLogger::Flush:PinnedLogger", "PosixLogger::Flush:Begin1"},
 302        {"AutoRollLogger::Flush:PinnedLogger", "PosixLogger::Flush:Begin2"}});
 303   rocksdb::SyncPoint::GetInstance()->EnableProcessing();
 304
 305   flush_thread = port::Thread ([&]() { auto_roll_logger->Flush(); });
 306   TEST_SYNC_POINT(
 307       "AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit");
 308   RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
 309                         kSampleMessage + ":LogFlushWhileRolling");
 310   flush_thread.join();
 311   rocksdb::SyncPoint::GetInstance()->DisableProcessing();
 312 }
 313
 314 #endif  // OS_WIN
 315
 316 TEST_F(AutoRollLoggerTest, InfoLogLevel) {
 317   InitTestDb();
 318
 319   size_t log_size = 8192;
 320   size_t log_lines = 0;
 321   // an extra-scope to force the AutoRollLogger to flush the log file when it
 322   // becomes out of scope.
 323   {
 324     AutoRollLogger logger(Env::Default(), kTestDir, "", log_size, 0);
 325     for (int log_level = InfoLogLevel::HEADER_LEVEL;
 326          log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
 327       logger.SetInfoLogLevel((InfoLogLevel)log_level);
 328       for (int log_type = InfoLogLevel::DEBUG_LEVEL;
 329            log_type <= InfoLogLevel::HEADER_LEVEL; log_type++) {
 330         // log messages with log level smaller than log_level will not be
 331         // logged.
 332         LogMessage((InfoLogLevel)log_type, &logger, kSampleMessage.c_str());
 333       }
 334       log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
 335     }
 336     for (int log_level = InfoLogLevel::HEADER_LEVEL;
 337          log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
 338       logger.SetInfoLogLevel((InfoLogLevel)log_level);
 339
 340       // again, messages with level smaller than log_level will not be logged.
 341       ROCKS_LOG_HEADER(&logger, "%s", kSampleMessage.c_str());
 342       ROCKS_LOG_DEBUG(&logger, "%s", kSampleMessage.c_str());
 343       ROCKS_LOG_INFO(&logger, "%s", kSampleMessage.c_str());
 344       ROCKS_LOG_WARN(&logger, "%s", kSampleMessage.c_str());
 345       ROCKS_LOG_ERROR(&logger, "%s", kSampleMessage.c_str());
 346       ROCKS_LOG_FATAL(&logger, "%s", kSampleMessage.c_str());
 347       log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
 348     }
 349   }
 350   std::ifstream inFile(AutoRollLoggerTest::kLogFile.c_str());
 351   size_t lines = std::count(std::istreambuf_iterator<char>(inFile),
 352                          std::istreambuf_iterator<char>(), '\n');
 353   ASSERT_EQ(log_lines, lines);
 354   inFile.close();
 355 }
 356
 357 // Test the logger Header function for roll over logs
 358 // We expect the new logs creates as roll over to carry the headers specified
 359 static std::vector<std::string> GetOldFileNames(const std::string& path) {
 360   std::vector<std::string> ret;
 361
 362   const std::string dirname = path.substr(/*start=*/0, path.find_last_of("/"));
 363   const std::string fname = path.substr(path.find_last_of("/") + 1);
 364
 365   std::vector<std::string> children;
 366   Env::Default()->GetChildren(dirname, &children);
 367
 368   // We know that the old log files are named [path]<something>
 369   // Return all entities that match the pattern
 370   for (auto& child : children) {
 371     if (fname != child && child.find(fname) == 0) {
 372       ret.push_back(dirname + "/" + child);
 373     }
 374   }
 375
 376   return ret;
 377 }
 378
 379 // Return the number of lines where a given pattern was found in the file
 380 static size_t GetLinesCount(const std::string& fname,
 381                             const std::string& pattern) {
 382   std::stringstream ssbuf;
 383   std::string line;
 384   size_t count = 0;
 385
 386   std::ifstream inFile(fname.c_str());
 387   ssbuf << inFile.rdbuf();
 388
 389   while (getline(ssbuf, line)) {
 390     if (line.find(pattern) != std::string::npos) {
 391       count++;
 392     }
 393   }
 394
 395   return count;
 396 }
 397
 398 TEST_F(AutoRollLoggerTest, LogHeaderTest) {
 399   static const size_t MAX_HEADERS = 10;
 400   static const size_t LOG_MAX_SIZE = 1024 * 5;
 401   static const std::string HEADER_STR = "Log header line";
 402
 403   // test_num == 0 -> standard call to Header()
 404   // test_num == 1 -> call to Log() with InfoLogLevel::HEADER_LEVEL
 405   for (int test_num = 0; test_num < 2; test_num++) {
 406
 407     InitTestDb();
 408
 409     AutoRollLogger logger(Env::Default(), kTestDir, /*db_log_dir=*/ "",
 410                           LOG_MAX_SIZE, /*log_file_time_to_roll=*/ 0);
 411
 412     if (test_num == 0) {
 413       // Log some headers explicitly using Header()
 414       for (size_t i = 0; i < MAX_HEADERS; i++) {
 415         Header(&logger, "%s %d", HEADER_STR.c_str(), i);
 416       }
 417     } else if (test_num == 1) {
 418       // HEADER_LEVEL should make this behave like calling Header()
 419       for (size_t i = 0; i < MAX_HEADERS; i++) {
 420         ROCKS_LOG_HEADER(&logger, "%s %d", HEADER_STR.c_str(), i);
 421       }
 422     }
 423
 424     const std::string newfname = logger.TEST_log_fname();
 425
 426     // Log enough data to cause a roll over
 427     int i = 0;
 428     for (size_t iter = 0; iter < 2; iter++) {
 429       while (logger.GetLogFileSize() < LOG_MAX_SIZE) {
 430         Info(&logger, (kSampleMessage + ":LogHeaderTest line %d").c_str(), i);
 431         ++i;
 432       }
 433
 434       Info(&logger, "Rollover");
 435     }
 436
 437     // Flush the log for the latest file
 438     LogFlush(&logger);
 439
 440     const auto oldfiles = GetOldFileNames(newfname);
 441
 442     ASSERT_EQ(oldfiles.size(), (size_t) 2);
 443
 444     for (auto& oldfname : oldfiles) {
 445       // verify that the files rolled over
 446       ASSERT_NE(oldfname, newfname);
 447       // verify that the old log contains all the header logs
 448       ASSERT_EQ(GetLinesCount(oldfname, HEADER_STR), MAX_HEADERS);
 449     }
 450   }
 451 }
 452
 453 TEST_F(AutoRollLoggerTest, LogFileExistence) {
 454   rocksdb::DB* db;
 455   rocksdb::Options options;
 456 #ifdef OS_WIN
 457   // Replace all slashes in the path so windows CompSpec does not
 458   // become confused
 459   std::string testDir(kTestDir);
 460   std::replace_if(testDir.begin(), testDir.end(),
 461     [](char ch) { return ch == '/'; }, '\\');
 462   std::string deleteCmd = "if exist " + testDir + " rd /s /q " + testDir;
 463 #else
 464   std::string deleteCmd = "rm -rf " + kTestDir;
 465 #endif
 466   ASSERT_EQ(system(deleteCmd.c_str()), 0);
 467   options.max_log_file_size = 100 * 1024 * 1024;
 468   options.create_if_missing = true;
 469   ASSERT_OK(rocksdb::DB::Open(options, kTestDir, &db));
 470   ASSERT_OK(default_env->FileExists(kLogFile));
 471   delete db;
 472 }
 473
 474 }  // namespace rocksdb
 475
 476 int main(int argc, char** argv) {
 477   ::testing::InitGoogleTest(&argc, argv);
 478   return RUN_ALL_TESTS();
 479 }
 480
 481 #else
 482 #include <stdio.h>
 483
 484 int main(int argc, char** argv) {
 485   fprintf(stderr,
 486           "SKIPPED as AutoRollLogger is not supported in ROCKSDB_LITE\n");
 487   return 0;
 488 }
 489
 490 #endif  // !ROCKSDB_LITE