]>
Commit | Line | Data |
---|---|---|
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 | 26 | namespace ROCKSDB_NAMESPACE { |
7c673cae FG |
27 | namespace { |
28 | class 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. | |
48 | namespace { | |
49 | void LogMessage(Logger* logger, const char* message) { | |
50 | ROCKS_LOG_INFO(logger, "%s", message); | |
51 | } | |
52 | ||
53 | void LogMessage(const InfoLogLevel log_level, Logger* logger, | |
54 | const char* message) { | |
55 | Log(log_level, logger, "%s", message); | |
56 | } | |
57 | } // namespace | |
58 | ||
7c673cae FG |
59 | class 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 | ||
122 | const std::string AutoRollLoggerTest::kSampleMessage( | |
123 | "this is the message to be written to the log file!!"); | |
11fdf7f2 TL |
124 | const std::string AutoRollLoggerTest::kTestDir( |
125 | test::PerThreadDBPath("db_log_test")); | |
126 | const std::string AutoRollLoggerTest::kLogFile( | |
127 | test::PerThreadDBPath("db_log_test") + "/LOG"); | |
7c673cae FG |
128 | Env* AutoRollLoggerTest::default_env = Env::Default(); |
129 | ||
7c673cae FG |
130 | void 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 | ||
159 | void 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 | ||
197 | TEST_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 | ||
209 | TEST_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 |
226 | TEST_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 |
245 | TEST_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 | ||
270 | TEST_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 | |
292 | TEST_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 | ||
394 | TEST_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 | ||
437 | TEST_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 | ||
480 | TEST_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 |
521 | TEST_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 | |
562 | static 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 |
582 | TEST_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 | ||
638 | TEST_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 |
659 | TEST_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 | |
670 | int 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 | 678 | int 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 |