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