From 882fc1a5fddb912de1fab61df290f8c696ee12fa Mon Sep 17 00:00:00 2001 From: Yingchun Lai Date: Fri, 24 May 2024 17:54:07 +0800 Subject: [PATCH] feat(logging): Use timestamp instead of index in log files and limit file size and count --- src/utils/simple_logger.cpp | 172 ++++++++++++++++++++++++------------ src/utils/simple_logger.h | 21 ++++- src/utils/test/logger.cpp | 166 ++++++++++++++++++++++------------ 3 files changed, 241 insertions(+), 118 deletions(-) diff --git a/src/utils/simple_logger.cpp b/src/utils/simple_logger.cpp index 0234cee6f8..14d3ac19b3 100644 --- a/src/utils/simple_logger.cpp +++ b/src/utils/simple_logger.cpp @@ -26,27 +26,41 @@ #include "utils/simple_logger.h" +#include +#include // IWYU pragma: no_include #include #include -#include +#include +#include +#include #include #include -#include +#include +#include #include #include "absl/strings/string_view.h" #include "runtime/api_layer1.h" #include "utils/command_manager.h" +#include "utils/errors.h" #include "utils/fail_point.h" #include "utils/filesystem.h" #include "utils/flags.h" #include "utils/fmt_logging.h" #include "utils/ports.h" #include "utils/process_utils.h" +#include "utils/safe_strerror_posix.h" #include "utils/string_conv.h" #include "utils/time_utils.h" +DSN_DEFINE_uint64(tools.simple_logger, + max_log_file_bytes, + 64 * 1024 * 1024, + "The maximum bytes of a log file. A new log file will be created if the current " + "log file exceeds this size."); +DSN_DEFINE_validator(max_log_file_bytes, [](int32_t value) -> bool { return value > 0; }); + DSN_DEFINE_bool(tools.simple_logger, fast_flush, false, "Whether to flush logs immediately"); DSN_DEFINE_bool(tools.simple_logger, short_header, @@ -192,43 +206,13 @@ void screen_logger::flush() { ::fflush(stdout); } simple_logger::simple_logger(const char *log_dir) : _log_dir(std::string(log_dir)), _log(nullptr), - // we assume all valid entries are positive - _start_index(0), - _index(1), - _lines(0), + _file_bytes(0), _stderr_start_level(enum_from_string(FLAGS_stderr_start_level, LOG_LEVEL_INVALID)) { - // check existing log files - std::vector sub_list; - CHECK(dsn::utils::filesystem::get_subfiles(_log_dir, sub_list, false), - "Fail to get subfiles in {}", - _log_dir); - for (auto &fpath : sub_list) { - auto &&name = dsn::utils::filesystem::get_file_name(fpath); - if (name.length() <= 8 || name.substr(0, 4) != "log.") { - continue; - } - - int index; - if (1 != sscanf(name.c_str(), "log.%d.txt", &index) || index <= 0) { - continue; - } - - if (index > _index) { - _index = index; - } - - if (_start_index == 0 || index < _start_index) { - _start_index = index; - } - } - sub_list.clear(); - - if (_start_index == 0) { - _start_index = _index; - } else { - ++_index; - } + // Use 'role_name' if it is specified, otherwise use 'base_name'. + const std::string symlink_name("log"); + _file_name_prefix = fmt::format("{}.", symlink_name); + _symlink_path = utils::filesystem::path_combine(_log_dir, symlink_name); create_log_file(); @@ -273,22 +257,94 @@ void simple_logger::create_log_file() _log = nullptr; } - _lines = 0; - - std::stringstream str; - str << _log_dir << "/log." << _index++ << ".txt"; - _log = ::fopen(str.str().c_str(), "w+"); - - // TODO: move gc out of criticial path - while (_index - _start_index > FLAGS_max_number_of_log_files_on_disk) { - std::stringstream str2; - str2 << "log." << _start_index++ << ".txt"; - auto dp = utils::filesystem::path_combine(_log_dir, str2.str()); - if (utils::filesystem::file_exists(dp)) { - if (::remove(dp.c_str()) != 0) { - // if remove failed, just print log and ignore it. - printf("Failed to remove garbage log file %s\n", dp.c_str()); - } + // Reset the file size. + _file_bytes = 0; + + // Open the new log file. + uint64_t ts = dsn::utils::get_current_physical_time_ns(); + std::string time_str; + ::dsn::utils::time_ms_to_sequent_string(ts / 1000000, time_str); + const std::string file_name(fmt::format("{}{}", _file_name_prefix, time_str)); + const std::string path(utils::filesystem::path_combine(_log_dir, file_name)); + _log = ::fopen(path.c_str(), "w+"); + CHECK_NOTNULL(_log, "Failed to fopen {}: {}", path, dsn::utils::safe_strerror(errno)); + + // Unlink the latest log file. + if (::unlink(_symlink_path.c_str()) != 0) { + if (errno != ENOENT) { + fmt::print(stderr, + "Failed to unlink {}: {}\n", + _symlink_path, + dsn::utils::safe_strerror(errno)); + } + } + + // Create a new symlink to the newly created log file. + if (::symlink(file_name.c_str(), _symlink_path.c_str()) != 0) { + fmt::print(stderr, + "Failed to symlink {} as {}: {}\n", + file_name, + _symlink_path, + dsn::utils::safe_strerror(errno)); + } + + // Remove redundant log files. + remove_redundant_files(); +} + +void simple_logger::remove_redundant_files() +{ + // Collect log files. + const auto file_path_pattern = + fmt::format("{}*", utils::filesystem::path_combine(_log_dir, _file_name_prefix)); + std::vector matching_files; + const auto es = dsn::utils::filesystem::glob(file_path_pattern, matching_files); + if (!es) { + fmt::print( + stderr, "{}: Failed to glob '{}', error \n", es.description(), file_path_pattern); + return; + } + + // Skip if the number of log files is not exceeded. + auto max_matches = static_cast(FLAGS_max_number_of_log_files_on_disk); + if (matching_files.size() <= max_matches) { + return; + } + + // Collect mtimes of log files. + std::vector> matching_file_mtimes; + for (auto &matching_file_path : matching_files) { + struct stat s; + if (::stat(matching_file_path.c_str(), &s) != 0) { + fmt::print(stderr, + "Failed to stat {}: {}\n", + matching_file_path, + dsn::utils::safe_strerror(errno)); + continue; + } + +#ifdef __APPLE__ + int64_t mtime = s.st_mtimespec.tv_sec * 1000000 + s.st_mtimespec.tv_nsec / 1000; +#else + int64_t mtime = s.st_mtim.tv_sec * 1000000 + s.st_mtim.tv_nsec / 1000; +#endif + matching_file_mtimes.emplace_back(mtime, std::move(matching_file_path)); + } + + // Use mtime to determine which matching files to delete. This could + // potentially be ambiguous, depending on the resolution of last-modified + // timestamp in the filesystem, but that is part of the contract. + std::sort(matching_file_mtimes.begin(), matching_file_mtimes.end()); + matching_file_mtimes.resize(matching_file_mtimes.size() - max_matches); + + // Remove redundant log files. + for (const auto & [ _, matching_file ] : matching_file_mtimes) { + if (::remove(matching_file.c_str()) != 0) { + // If remove failed, just print log and ignore it. + fmt::print(stderr, + "Failed to remove redundant log file {}: {}\n", + matching_file, + dsn::utils::safe_strerror(errno)); } } } @@ -310,7 +366,7 @@ void simple_logger::flush() void simple_logger::print_header(log_level_t log_level) { - ::dsn::tools::print_header(_log, _stderr_start_level, log_level); + add_bytes_if_valid(::dsn::tools::print_header(_log, _stderr_start_level, log_level)); } void simple_logger::print_long_header(const char *file, @@ -318,13 +374,13 @@ void simple_logger::print_long_header(const char *file, const int line, log_level_t log_level) { - ::dsn::tools::print_long_header( - _log, file, function, line, FLAGS_short_header, _stderr_start_level, log_level); + add_bytes_if_valid(::dsn::tools::print_long_header( + _log, file, function, line, FLAGS_short_header, _stderr_start_level, log_level)); } void simple_logger::print_body(const char *body, log_level_t log_level) { - ::dsn::tools::print_body(_log, body, _stderr_start_level, log_level); + add_bytes_if_valid(::dsn::tools::print_body(_log, body, _stderr_start_level, log_level)); } void simple_logger::log( @@ -342,7 +398,7 @@ void simple_logger::log( process_fatal_log(log_level); - if (++_lines >= 200000) { + if (_file_bytes >= FLAGS_max_log_file_bytes) { create_log_file(); } } diff --git a/src/utils/simple_logger.h b/src/utils/simple_logger.h index 7da3241391..3a8b0015ab 100644 --- a/src/utils/simple_logger.h +++ b/src/utils/simple_logger.h @@ -26,11 +26,13 @@ #pragma once +#include #include #include #include "utils/api_utilities.h" #include "utils/logging_provider.h" +#include "utils/ports.h" #include "utils/synchronize.h" namespace dsn { @@ -91,17 +93,30 @@ class simple_logger : public logging_provider log_level_t log_level); void print_body(const char *body, log_level_t log_level); + inline void add_bytes_if_valid(int bytes) + { + if (dsn_likely(bytes > 0)) { + _file_bytes += static_cast(bytes); + } + } + void create_log_file(); + void remove_redundant_files(); private: ::dsn::utils::ex_lock _lock; // use recursive lock to avoid dead lock when flush() is called // in signal handler if cored for bad logging format reason. // The directory to store log files. const std::string _log_dir; + // The path of the symlink to the latest log file. + std::string _symlink_path; + // The prefix of the log file names. The actual log files are prefixed by '_file_name_prefix' + // and postfixed by timestamp. + std::string _file_name_prefix; + // The current log file descriptor. FILE *_log; - int _start_index; - int _index; - int _lines; + // The byte size of the current log file. + uint64_t _file_bytes; const log_level_t _stderr_start_level; }; } // namespace tools diff --git a/src/utils/test/logger.cpp b/src/utils/test/logger.cpp index 70d6ef1e2b..9ba8fa6c55 100644 --- a/src/utils/test/logger.cpp +++ b/src/utils/test/logger.cpp @@ -24,15 +24,14 @@ * THE SOFTWARE. */ -#include -#include #include -#include #include -#include #include +#include +#include #include #include +#include #include #include "gtest/gtest.h" @@ -40,91 +39,144 @@ #include "utils/filesystem.h" #include "utils/flags.h" #include "utils/logging_provider.h" -#include "utils/safe_strerror_posix.h" #include "utils/simple_logger.h" +#include "utils/test_macros.h" DSN_DECLARE_uint64(max_number_of_log_files_on_disk); namespace dsn { namespace tools { +class logger_test : public testing::Test +{ +public: + void SetUp() override + { + // Deregister commands to avoid re-register error. + dsn::logging_provider::instance()->deregister_commands(); + } +}; -namespace { - -void get_log_file_index(std::vector &log_index) +class simple_logger_test : public logger_test { - std::vector sub_list; - ASSERT_TRUE(dsn::utils::filesystem::get_subfiles("./", sub_list, false)); +public: + void SetUp() override + { + logger_test::SetUp(); + + std::string cwd; + ASSERT_TRUE(dsn::utils::filesystem::get_current_directory(cwd)); + // NOTE: Don't name the dir with "test", otherwise the whole utils test dir would be + // removed. + test_dir = dsn::utils::filesystem::path_combine(cwd, "simple_logger_test"); + + NO_FATALS(prepare_test_dir()); + std::set files; + NO_FATALS(get_log_files(files)); + NO_FATALS(clear_files(files)); + } - for (const auto &path : sub_list) { - const auto &name = dsn::utils::filesystem::get_file_name(path); - if (!boost::algorithm::starts_with(name, "log.")) { - continue; - } - if (!boost::algorithm::ends_with(name, ".txt")) { - continue; + void get_log_files(std::set &file_names) + { + std::vector sub_list; + ASSERT_TRUE(utils::filesystem::get_subfiles(test_dir, sub_list, false)); + + file_names.clear(); + std::regex pattern(R"(log\.log\.[0-9]{8}_[0-9]{6}_[0-9]{3})"); + for (const auto &path : sub_list) { + std::string name(utils::filesystem::get_file_name(path)); + if (std::regex_match(name, pattern)) { + ASSERT_TRUE(file_names.insert(name).second); + } } + } - int index; - if (1 != sscanf(name.c_str(), "log.%d.txt", &index)) { - continue; + void compare_log_files(const std::set &before_files, + const std::set &after_files) + { + ASSERT_FALSE(after_files.empty()); + + // One new log file is created. + if (after_files.size() == before_files.size() + 1) { + // All the file names are the same. + for (auto it1 = before_files.begin(), it2 = after_files.begin(); + it1 != before_files.end(); + ++it1, ++it2) { + ASSERT_EQ(*it1, *it2); + } + // The number of log files is the same, but they have rolled. + } else if (after_files.size() == before_files.size()) { + auto it1 = before_files.begin(); + auto it2 = after_files.begin(); + // The first file is different, the one in 'before_files' is older. + ASSERT_NE(*it1, *it2); + + // The rest of the files are the same. + for (++it1; it1 != before_files.end(); ++it1, ++it2) { + ASSERT_EQ(*it1, *it2); + } + } else { + ASSERT_TRUE(false) << "Invalid number of log files, before=" << before_files.size() + << ", after=" << after_files.size(); } - log_index.push_back(index); } -} -// Don't name the dir with "./test", otherwise the whole utils test dir would be removed. -const std::string kTestDir("./test_logger"); + void clear_files(const std::set &file_names) + { + for (const auto &file_name : file_names) { + ASSERT_TRUE(dsn::utils::filesystem::remove_path(file_name)); + } + } -void prepare_test_dir() -{ - ASSERT_TRUE(dsn::utils::filesystem::create_directory(kTestDir)); - ASSERT_EQ(0, ::chdir(kTestDir.c_str())); -} + void prepare_test_dir() + { + ASSERT_TRUE(dsn::utils::filesystem::create_directory(test_dir)) << test_dir; + } -void remove_test_dir() -{ - ASSERT_EQ(0, ::chdir("..")) << "chdir failed, err = " << dsn::utils::safe_strerror(errno); - ASSERT_TRUE(dsn::utils::filesystem::remove_path(kTestDir)) << "remove_directory " << kTestDir - << " failed"; -} + void remove_test_dir() + { + ASSERT_TRUE(dsn::utils::filesystem::remove_path(test_dir)) << test_dir; + } -} // anonymous namespace +public: + std::string test_dir; +}; #define LOG_PRINT(logger, ...) \ (logger)->log( \ __FILE__, __FUNCTION__, __LINE__, LOG_LEVEL_DEBUG, fmt::format(__VA_ARGS__).c_str()) -TEST(LoggerTest, SimpleLogger) +TEST_F(logger_test, screen_logger_test) { - // Deregister commands to avoid re-register error. - dsn::logging_provider::instance()->deregister_commands(); - - { - auto logger = std::make_unique(true); - LOG_PRINT(logger.get(), "{}", "test_print"); - std::thread t([](screen_logger *lg) { LOG_PRINT(lg, "{}", "test_print"); }, logger.get()); - t.join(); - - logger->flush(); - } - - prepare_test_dir(); + auto logger = std::make_unique(true); + LOG_PRINT(logger.get(), "{}", "test_print"); + std::thread t([](screen_logger *lg) { LOG_PRINT(lg, "{}", "test_print"); }, logger.get()); + t.join(); + logger->flush(); +} +TEST_F(simple_logger_test, redundant_log_test) +{ // Create redundant log files to test if their number could be restricted. for (unsigned int i = 0; i < FLAGS_max_number_of_log_files_on_disk + 10; ++i) { - auto logger = std::make_unique("./"); + std::set before_files; + NO_FATALS(get_log_files(before_files)); + + auto logger = std::make_unique(test_dir.c_str()); for (unsigned int i = 0; i != 1000; ++i) { LOG_PRINT(logger.get(), "{}", "test_print"); } logger->flush(); - } - std::vector index; - get_log_file_index(index); - ASSERT_FALSE(index.empty()); - ASSERT_EQ(FLAGS_max_number_of_log_files_on_disk, index.size()); + std::set after_files; + NO_FATALS(get_log_files(after_files)); + NO_FATALS(compare_log_files(before_files, after_files)); + ::usleep(2000); + } - remove_test_dir(); + std::set files; + NO_FATALS(get_log_files(files)); + ASSERT_FALSE(files.empty()); + ASSERT_EQ(FLAGS_max_number_of_log_files_on_disk, files.size()); } } // namespace tools