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