Revision 0d4a2b733070a1bd52f981313f9e17f126701407 authored by Yi Wu on 04 August 2017, 20:09:56 UTC, committed by Facebook Github Bot on 04 August 2017, 20:12:07 UTC
Summary: The FsyncFiles background job call Fsync() periodically for blob files. However it can access WritableFileWriter concurrently with a Put() or Write(). And WritableFileWriter does not support concurrent access. It will lead to WritableFileWriter buffer being flush with same content twice, and blob file end up corrupted. Fixing by simply let FsyncFiles hold write_mutex_. Closes https://github.com/facebook/rocksdb/pull/2685 Differential Revision: D5561908 Pulled By: yiwu-arbug fbshipit-source-id: f0bb5bcab0e05694e053b8c49eab43640721e872
1 parent 627c9f1
auto_roll_logger_test.cc
// Copyright (c) 2011-present, Facebook, Inc. All rights reserved.
// This source code is licensed under both the GPLv2 (found in the
// COPYING file in the root directory) and Apache 2.0 License
// (found in the LICENSE.Apache file in the root directory).
//
#ifndef ROCKSDB_LITE
#include "util/auto_roll_logger.h"
#include <errno.h>
#include <sys/stat.h>
#include <algorithm>
#include <cmath>
#include <fstream>
#include <iostream>
#include <iterator>
#include <string>
#include <thread>
#include <vector>
#include "port/port.h"
#include "rocksdb/db.h"
#include "util/logging.h"
#include "util/sync_point.h"
#include "util/testharness.h"
namespace rocksdb {
namespace {
class NoSleepEnv : public EnvWrapper {
public:
NoSleepEnv(Env* base) : EnvWrapper(base) {}
virtual void SleepForMicroseconds(int micros) override {
fake_time_ += static_cast<uint64_t>(micros);
}
virtual uint64_t NowNanos() override { return fake_time_ * 1000; }
virtual uint64_t NowMicros() override { return fake_time_; }
private:
uint64_t fake_time_ = 6666666666;
};
} // namespace
class AutoRollLoggerTest : public testing::Test {
public:
static void InitTestDb() {
#ifdef OS_WIN
// Replace all slashes in the path so windows CompSpec does not
// become confused
std::string testDir(kTestDir);
std::replace_if(testDir.begin(), testDir.end(),
[](char ch) { return ch == '/'; }, '\\');
std::string deleteCmd = "if exist " + testDir + " rd /s /q " + testDir;
#else
std::string deleteCmd = "rm -rf " + kTestDir;
#endif
ASSERT_TRUE(system(deleteCmd.c_str()) == 0);
Env::Default()->CreateDir(kTestDir);
}
void RollLogFileBySizeTest(AutoRollLogger* logger, size_t log_max_size,
const std::string& log_message);
void RollLogFileByTimeTest(Env*, AutoRollLogger* logger, size_t time,
const std::string& log_message);
static const std::string kSampleMessage;
static const std::string kTestDir;
static const std::string kLogFile;
static Env* default_env;
};
const std::string AutoRollLoggerTest::kSampleMessage(
"this is the message to be written to the log file!!");
const std::string AutoRollLoggerTest::kTestDir(test::TmpDir() + "/db_log_test");
const std::string AutoRollLoggerTest::kLogFile(test::TmpDir() +
"/db_log_test/LOG");
Env* AutoRollLoggerTest::default_env = Env::Default();
// In this test we only want to Log some simple log message with
// no format. LogMessage() provides such a simple interface and
// avoids the [format-security] warning which occurs when you
// call ROCKS_LOG_INFO(logger, log_message) directly.
namespace {
void LogMessage(Logger* logger, const char* message) {
ROCKS_LOG_INFO(logger, "%s", message);
}
void LogMessage(const InfoLogLevel log_level, Logger* logger,
const char* message) {
Log(log_level, logger, "%s", message);
}
} // namespace
void AutoRollLoggerTest::RollLogFileBySizeTest(AutoRollLogger* logger,
size_t log_max_size,
const std::string& log_message) {
logger->SetInfoLogLevel(InfoLogLevel::INFO_LEVEL);
// measure the size of each message, which is supposed
// to be equal or greater than log_message.size()
LogMessage(logger, log_message.c_str());
size_t message_size = logger->GetLogFileSize();
size_t current_log_size = message_size;
// Test the cases when the log file will not be rolled.
while (current_log_size + message_size < log_max_size) {
LogMessage(logger, log_message.c_str());
current_log_size += message_size;
ASSERT_EQ(current_log_size, logger->GetLogFileSize());
}
// Now the log file will be rolled
LogMessage(logger, log_message.c_str());
// Since rotation is checked before actual logging, we need to
// trigger the rotation by logging another message.
LogMessage(logger, log_message.c_str());
ASSERT_TRUE(message_size == logger->GetLogFileSize());
}
void AutoRollLoggerTest::RollLogFileByTimeTest(Env* env, AutoRollLogger* logger,
size_t time,
const std::string& log_message) {
uint64_t expected_ctime;
uint64_t actual_ctime;
uint64_t total_log_size;
EXPECT_OK(env->GetFileSize(kLogFile, &total_log_size));
expected_ctime = logger->TEST_ctime();
logger->SetCallNowMicrosEveryNRecords(0);
// -- Write to the log for several times, which is supposed
// to be finished before time.
for (int i = 0; i < 10; ++i) {
env->SleepForMicroseconds(50000);
LogMessage(logger, log_message.c_str());
EXPECT_OK(logger->GetStatus());
// Make sure we always write to the same log file (by
// checking the create time);
actual_ctime = logger->TEST_ctime();
// Also make sure the log size is increasing.
EXPECT_EQ(expected_ctime, actual_ctime);
EXPECT_GT(logger->GetLogFileSize(), total_log_size);
total_log_size = logger->GetLogFileSize();
}
// -- Make the log file expire
env->SleepForMicroseconds(static_cast<int>(time * 1000000));
LogMessage(logger, log_message.c_str());
// At this time, the new log file should be created.
actual_ctime = logger->TEST_ctime();
EXPECT_LT(expected_ctime, actual_ctime);
EXPECT_LT(logger->GetLogFileSize(), total_log_size);
}
TEST_F(AutoRollLoggerTest, RollLogFileBySize) {
InitTestDb();
size_t log_max_size = 1024 * 5;
AutoRollLogger logger(Env::Default(), kTestDir, "", log_max_size, 0);
RollLogFileBySizeTest(&logger, log_max_size,
kSampleMessage + ":RollLogFileBySize");
}
TEST_F(AutoRollLoggerTest, RollLogFileByTime) {
NoSleepEnv nse(Env::Default());
size_t time = 2;
size_t log_size = 1024 * 5;
InitTestDb();
// -- Test the existence of file during the server restart.
ASSERT_EQ(Status::NotFound(), default_env->FileExists(kLogFile));
AutoRollLogger logger(&nse, kTestDir, "", log_size, time);
ASSERT_OK(default_env->FileExists(kLogFile));
RollLogFileByTimeTest(&nse, &logger, time,
kSampleMessage + ":RollLogFileByTime");
}
TEST_F(AutoRollLoggerTest, OpenLogFilesMultipleTimesWithOptionLog_max_size) {
// If only 'log_max_size' options is specified, then every time
// when rocksdb is restarted, a new empty log file will be created.
InitTestDb();
// WORKAROUND:
// avoid complier's complaint of "comparison between signed
// and unsigned integer expressions" because literal 0 is
// treated as "singed".
size_t kZero = 0;
size_t log_size = 1024;
AutoRollLogger* logger = new AutoRollLogger(
Env::Default(), kTestDir, "", log_size, 0);
LogMessage(logger, kSampleMessage.c_str());
ASSERT_GT(logger->GetLogFileSize(), kZero);
delete logger;
// reopens the log file and an empty log file will be created.
logger = new AutoRollLogger(
Env::Default(), kTestDir, "", log_size, 0);
ASSERT_EQ(logger->GetLogFileSize(), kZero);
delete logger;
}
TEST_F(AutoRollLoggerTest, CompositeRollByTimeAndSizeLogger) {
size_t time = 2, log_max_size = 1024 * 5;
InitTestDb();
NoSleepEnv nse(Env::Default());
AutoRollLogger logger(&nse, kTestDir, "", log_max_size, time);
// Test the ability to roll by size
RollLogFileBySizeTest(&logger, log_max_size,
kSampleMessage + ":CompositeRollByTimeAndSizeLogger");
// Test the ability to roll by Time
RollLogFileByTimeTest(&nse, &logger, time,
kSampleMessage + ":CompositeRollByTimeAndSizeLogger");
}
#ifndef OS_WIN
// TODO: does not build for Windows because of PosixLogger use below. Need to
// port
TEST_F(AutoRollLoggerTest, CreateLoggerFromOptions) {
DBOptions options;
NoSleepEnv nse(Env::Default());
shared_ptr<Logger> logger;
// Normal logger
ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
ASSERT_TRUE(dynamic_cast<PosixLogger*>(logger.get()));
// Only roll by size
InitTestDb();
options.max_log_file_size = 1024;
ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
AutoRollLogger* auto_roll_logger =
dynamic_cast<AutoRollLogger*>(logger.get());
ASSERT_TRUE(auto_roll_logger);
RollLogFileBySizeTest(
auto_roll_logger, options.max_log_file_size,
kSampleMessage + ":CreateLoggerFromOptions - size");
// Only roll by Time
options.env = &nse;
InitTestDb();
options.max_log_file_size = 0;
options.log_file_time_to_roll = 2;
ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
auto_roll_logger =
dynamic_cast<AutoRollLogger*>(logger.get());
RollLogFileByTimeTest(&nse, auto_roll_logger, options.log_file_time_to_roll,
kSampleMessage + ":CreateLoggerFromOptions - time");
// roll by both Time and size
InitTestDb();
options.max_log_file_size = 1024 * 5;
options.log_file_time_to_roll = 2;
ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
auto_roll_logger =
dynamic_cast<AutoRollLogger*>(logger.get());
RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
kSampleMessage + ":CreateLoggerFromOptions - both");
RollLogFileByTimeTest(&nse, auto_roll_logger, options.log_file_time_to_roll,
kSampleMessage + ":CreateLoggerFromOptions - both");
}
TEST_F(AutoRollLoggerTest, LogFlushWhileRolling) {
DBOptions options;
shared_ptr<Logger> logger;
InitTestDb();
options.max_log_file_size = 1024 * 5;
ASSERT_OK(CreateLoggerFromOptions(kTestDir, options, &logger));
AutoRollLogger* auto_roll_logger =
dynamic_cast<AutoRollLogger*>(logger.get());
ASSERT_TRUE(auto_roll_logger);
rocksdb::port::Thread flush_thread;
// Notes:
// (1) Need to pin the old logger before beginning the roll, as rolling grabs
// the mutex, which would prevent us from accessing the old logger. This
// also marks flush_thread with AutoRollLogger::Flush:PinnedLogger.
// (2) Need to reset logger during PosixLogger::Flush() to exercise a race
// condition case, which is executing the flush with the pinned (old)
// logger after auto-roll logger has cut over to a new logger.
// (3) PosixLogger::Flush() happens in both threads but its SyncPoints only
// are enabled in flush_thread (the one pinning the old logger).
rocksdb::SyncPoint::GetInstance()->LoadDependencyAndMarkers(
{{"AutoRollLogger::Flush:PinnedLogger",
"AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit"},
{"PosixLogger::Flush:Begin1",
"AutoRollLogger::ResetLogger:BeforeNewLogger"},
{"AutoRollLogger::ResetLogger:AfterNewLogger",
"PosixLogger::Flush:Begin2"}},
{{"AutoRollLogger::Flush:PinnedLogger", "PosixLogger::Flush:Begin1"},
{"AutoRollLogger::Flush:PinnedLogger", "PosixLogger::Flush:Begin2"}});
rocksdb::SyncPoint::GetInstance()->EnableProcessing();
flush_thread = port::Thread ([&]() { auto_roll_logger->Flush(); });
TEST_SYNC_POINT(
"AutoRollLoggerTest::LogFlushWhileRolling:PreRollAndPostThreadInit");
RollLogFileBySizeTest(auto_roll_logger, options.max_log_file_size,
kSampleMessage + ":LogFlushWhileRolling");
flush_thread.join();
rocksdb::SyncPoint::GetInstance()->DisableProcessing();
}
#endif // OS_WIN
TEST_F(AutoRollLoggerTest, InfoLogLevel) {
InitTestDb();
size_t log_size = 8192;
size_t log_lines = 0;
// an extra-scope to force the AutoRollLogger to flush the log file when it
// becomes out of scope.
{
AutoRollLogger logger(Env::Default(), kTestDir, "", log_size, 0);
for (int log_level = InfoLogLevel::HEADER_LEVEL;
log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
logger.SetInfoLogLevel((InfoLogLevel)log_level);
for (int log_type = InfoLogLevel::DEBUG_LEVEL;
log_type <= InfoLogLevel::HEADER_LEVEL; log_type++) {
// log messages with log level smaller than log_level will not be
// logged.
LogMessage((InfoLogLevel)log_type, &logger, kSampleMessage.c_str());
}
log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
}
for (int log_level = InfoLogLevel::HEADER_LEVEL;
log_level >= InfoLogLevel::DEBUG_LEVEL; log_level--) {
logger.SetInfoLogLevel((InfoLogLevel)log_level);
// again, messages with level smaller than log_level will not be logged.
ROCKS_LOG_HEADER(&logger, "%s", kSampleMessage.c_str());
ROCKS_LOG_DEBUG(&logger, "%s", kSampleMessage.c_str());
ROCKS_LOG_INFO(&logger, "%s", kSampleMessage.c_str());
ROCKS_LOG_WARN(&logger, "%s", kSampleMessage.c_str());
ROCKS_LOG_ERROR(&logger, "%s", kSampleMessage.c_str());
ROCKS_LOG_FATAL(&logger, "%s", kSampleMessage.c_str());
log_lines += InfoLogLevel::HEADER_LEVEL - log_level + 1;
}
}
std::ifstream inFile(AutoRollLoggerTest::kLogFile.c_str());
size_t lines = std::count(std::istreambuf_iterator<char>(inFile),
std::istreambuf_iterator<char>(), '\n');
ASSERT_EQ(log_lines, lines);
inFile.close();
}
// Test the logger Header function for roll over logs
// We expect the new logs creates as roll over to carry the headers specified
static std::vector<std::string> GetOldFileNames(const std::string& path) {
std::vector<std::string> ret;
const std::string dirname = path.substr(/*start=*/0, path.find_last_of("/"));
const std::string fname = path.substr(path.find_last_of("/") + 1);
std::vector<std::string> children;
Env::Default()->GetChildren(dirname, &children);
// We know that the old log files are named [path]<something>
// Return all entities that match the pattern
for (auto& child : children) {
if (fname != child && child.find(fname) == 0) {
ret.push_back(dirname + "/" + child);
}
}
return ret;
}
// Return the number of lines where a given pattern was found in the file
static size_t GetLinesCount(const std::string& fname,
const std::string& pattern) {
std::stringstream ssbuf;
std::string line;
size_t count = 0;
std::ifstream inFile(fname.c_str());
ssbuf << inFile.rdbuf();
while (getline(ssbuf, line)) {
if (line.find(pattern) != std::string::npos) {
count++;
}
}
return count;
}
TEST_F(AutoRollLoggerTest, LogHeaderTest) {
static const size_t MAX_HEADERS = 10;
static const size_t LOG_MAX_SIZE = 1024 * 5;
static const std::string HEADER_STR = "Log header line";
// test_num == 0 -> standard call to Header()
// test_num == 1 -> call to Log() with InfoLogLevel::HEADER_LEVEL
for (int test_num = 0; test_num < 2; test_num++) {
InitTestDb();
AutoRollLogger logger(Env::Default(), kTestDir, /*db_log_dir=*/ "",
LOG_MAX_SIZE, /*log_file_time_to_roll=*/ 0);
if (test_num == 0) {
// Log some headers explicitly using Header()
for (size_t i = 0; i < MAX_HEADERS; i++) {
Header(&logger, "%s %d", HEADER_STR.c_str(), i);
}
} else if (test_num == 1) {
// HEADER_LEVEL should make this behave like calling Header()
for (size_t i = 0; i < MAX_HEADERS; i++) {
ROCKS_LOG_HEADER(&logger, "%s %d", HEADER_STR.c_str(), i);
}
}
const std::string newfname = logger.TEST_log_fname();
// Log enough data to cause a roll over
int i = 0;
for (size_t iter = 0; iter < 2; iter++) {
while (logger.GetLogFileSize() < LOG_MAX_SIZE) {
Info(&logger, (kSampleMessage + ":LogHeaderTest line %d").c_str(), i);
++i;
}
Info(&logger, "Rollover");
}
// Flush the log for the latest file
LogFlush(&logger);
const auto oldfiles = GetOldFileNames(newfname);
ASSERT_EQ(oldfiles.size(), (size_t) 2);
for (auto& oldfname : oldfiles) {
// verify that the files rolled over
ASSERT_NE(oldfname, newfname);
// verify that the old log contains all the header logs
ASSERT_EQ(GetLinesCount(oldfname, HEADER_STR), MAX_HEADERS);
}
}
}
TEST_F(AutoRollLoggerTest, LogFileExistence) {
rocksdb::DB* db;
rocksdb::Options options;
#ifdef OS_WIN
// Replace all slashes in the path so windows CompSpec does not
// become confused
std::string testDir(kTestDir);
std::replace_if(testDir.begin(), testDir.end(),
[](char ch) { return ch == '/'; }, '\\');
std::string deleteCmd = "if exist " + testDir + " rd /s /q " + testDir;
#else
std::string deleteCmd = "rm -rf " + kTestDir;
#endif
ASSERT_EQ(system(deleteCmd.c_str()), 0);
options.max_log_file_size = 100 * 1024 * 1024;
options.create_if_missing = true;
ASSERT_OK(rocksdb::DB::Open(options, kTestDir, &db));
ASSERT_OK(default_env->FileExists(kLogFile));
delete db;
}
} // namespace rocksdb
int main(int argc, char** argv) {
::testing::InitGoogleTest(&argc, argv);
return RUN_ALL_TESTS();
}
#else
#include <stdio.h>
int main(int argc, char** argv) {
fprintf(stderr,
"SKIPPED as AutoRollLogger is not supported in ROCKSDB_LITE\n");
return 0;
}
#endif // !ROCKSDB_LITE
![swh spinner](/static/img/swh-spinner.gif)
Computing file changes ...