auto_roll_logger_test.cc 24 KB

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