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