diff --git a/src/failure_detector/test/run.sh b/src/failure_detector/test/run.sh index be8861ea2b..648dbf8bb4 100755 --- a/src/failure_detector/test/run.sh +++ b/src/failure_detector/test/run.sh @@ -40,9 +40,9 @@ while read -r -a line; do echo "run dsn.failure_detector.tests $test_case failed" echo "---- ls ----" ls -l - if find . -name log.1.txt; then - echo "---- tail -n 100 log.1.txt ----" - tail -n 100 `find . -name log.1.txt` + if [ `find . -name skv.log.* | wc -l` -ne 0 ]; then + echo "---- tail -n 100 skv.log.* ----" + tail -n 100 `find . -name skv.log.*` fi if [ -f core ]; then echo "---- gdb ./dsn.failure_detector.tests core ----" diff --git a/src/meta/test/meta_state/run.sh b/src/meta/test/meta_state/run.sh index 62db6b8d26..ff38bc830c 100755 --- a/src/meta/test/meta_state/run.sh +++ b/src/meta/test/meta_state/run.sh @@ -40,9 +40,9 @@ while read -r -a line; do echo "run dsn_meta_state_tests $test_case failed" echo "---- ls ----" ls -l - if find . -name log.1.txt; then - echo "---- tail -n 100 log.1.txt ----" - tail -n 100 `find . -name log.1.txt` + if [ `find . -name skv.log.* | wc -l` -ne 0 ]; then + echo "---- tail -n 100 skv.log.* ----" + tail -n 100 `find . -name skv.log.*` fi if [ -f core ]; then echo "---- gdb ./dsn_meta_state_tests core ----" diff --git a/src/meta/test/run.sh b/src/meta/test/run.sh index fe9a116961..497250e23c 100755 --- a/src/meta/test/run.sh +++ b/src/meta/test/run.sh @@ -54,9 +54,9 @@ if [ $? -ne 0 ]; then echo "run dsn.meta.test failed" echo "---- ls ----" ls -l - if find . -name log.1.txt; then - echo "---- tail -n 100 log.1.txt ----" - tail -n 100 `find . -name log.1.txt` + if [ `find . -name skv.log.* | wc -l` -ne 0 ]; then + echo "---- tail -n 100 skv.log.* ----" + tail -n 100 `find . -name skv.log.*` fi if [ -f core ]; then echo "---- gdb ./dsn.meta.test core ----" diff --git a/src/replica/backup/test/run.sh b/src/replica/backup/test/run.sh index eb88404940..a80ba9cd34 100755 --- a/src/replica/backup/test/run.sh +++ b/src/replica/backup/test/run.sh @@ -45,7 +45,7 @@ fi ./dsn_replica_backup_test if [ $? -ne 0 ]; then - tail -n 100 data/log/log.1.txt + tail -n 100 `find . -name skv.log.*` if [ -f core ]; then gdb ./dsn_replica_backup_test core -ex "bt" fi diff --git a/src/replica/bulk_load/test/run.sh b/src/replica/bulk_load/test/run.sh index 7689036b02..27b309928e 100755 --- a/src/replica/bulk_load/test/run.sh +++ b/src/replica/bulk_load/test/run.sh @@ -45,7 +45,7 @@ fi ./dsn_replica_bulk_load_test if [ $? -ne 0 ]; then - tail -n 100 data/log/log.1.txt + tail -n 100 `find . -name skv.log.*` if [ -f core ]; then gdb ./dsn_replica_bulk_load_test core -ex "bt" fi diff --git a/src/replica/duplication/test/run.sh b/src/replica/duplication/test/run.sh index 90dee780db..40052c3408 100755 --- a/src/replica/duplication/test/run.sh +++ b/src/replica/duplication/test/run.sh @@ -45,7 +45,7 @@ fi ./dsn_replica_dup_test if [ $? -ne 0 ]; then - tail -n 100 data/log/log.1.txt + tail -n 100 `find . -name skv.log.*` if [ -f core ]; then gdb ./dsn_replica_dup_test core -ex "bt" fi diff --git a/src/replica/split/test/run.sh b/src/replica/split/test/run.sh index bd75b96198..b05dd7d8e8 100755 --- a/src/replica/split/test/run.sh +++ b/src/replica/split/test/run.sh @@ -45,7 +45,7 @@ fi ./dsn_replica_split_test if [ $? -ne 0 ]; then - tail -n 100 data/log/log.1.txt + tail -n 100 `find . -name skv.log.*` if [ -f core ]; then gdb ./dsn_replica_split_test core -ex "bt" fi diff --git a/src/replica/storage/simple_kv/run.sh b/src/replica/storage/simple_kv/run.sh index cf7c0380c2..b9dcc128d5 100755 --- a/src/replica/storage/simple_kv/run.sh +++ b/src/replica/storage/simple_kv/run.sh @@ -62,9 +62,9 @@ if [ -f core ] || ! grep ERR_OK out > /dev/null ; then ls -l echo "---- head -n 100 out ----" head -n 100 out - if [ -f data/logs/log.1.txt ]; then - echo "---- tail -n 100 log.1.txt ----" - tail -n 100 data/logs/log.1.txt + if [ `find data/logs -name skv.log.* | wc -l` -ne 0 ]; then + echo "---- tail -n 100 skv.log.* ----" + tail -n 100 `find data/logs -name skv.log.*` fi if [ -f core ]; then echo "---- gdb ./dsn.replication.simple_kv core ----" diff --git a/src/replica/storage/simple_kv/test/run.sh b/src/replica/storage/simple_kv/test/run.sh index 9c8d07328b..d76b456c8b 100755 --- a/src/replica/storage/simple_kv/test/run.sh +++ b/src/replica/storage/simple_kv/test/run.sh @@ -52,8 +52,8 @@ function run_single() echo "${bin} ${prefix}.ini ${prefix}.act" ${bin} ${prefix}.ini ${prefix}.act ret=$? - if find . -name log.1.txt &>/dev/null; then - log=`find . -name log.1.txt` + if [ `find . -name skv.log.* | wc -l` -ne 0 ]; then + log=`find . -name skv.log.*` cat ${log} | grep -v FAILURE_DETECT | grep -v BEACON | grep -v beacon | grep -v THREAD_POOL_FD >${prefix}.log rm ${log} fi diff --git a/src/runtime/global_config.h b/src/runtime/global_config.h index 65d62bdddd..3004bfe6f6 100644 --- a/src/runtime/global_config.h +++ b/src/runtime/global_config.h @@ -169,8 +169,7 @@ struct service_spec std::vector threadpool_specs; std::vector app_specs; - // auto-set - std::string dir_log; + std::string log_dir; service_spec() {} bool init(); @@ -186,6 +185,11 @@ CONFIG_FLD_STRING_LIST(toollets, CONFIG_FLD_STRING(data_dir, "./data", "The default directory to place the all the data, logs, coredump files, and etc.") +CONFIG_FLD_STRING_BY_KEY( + log_dir, + "log_dir", + "", + "The directory to place the logs especially. 'data_dir' will be used if it's empty.") CONFIG_FLD( bool, bool, diff --git a/src/runtime/service_api_c.cpp b/src/runtime/service_api_c.cpp index 44fbd7096b..0ee3f3d182 100644 --- a/src/runtime/service_api_c.cpp +++ b/src/runtime/service_api_c.cpp @@ -443,18 +443,27 @@ bool run(const char *config_file, ::dsn::utils::coredump::init(); - // setup log dir - spec.dir_log = ::dsn::utils::filesystem::path_combine(cdir, "log"); - dsn::utils::filesystem::create_directory(spec.dir_log); + // Setup log directory. + // If log_dir is not set, use data_dir/log instead. + if (spec.log_dir.empty()) { + spec.log_dir = ::dsn::utils::filesystem::path_combine(spec.data_dir, "log"); + fmt::print(stdout, "log_dir is not set, use '{}' instead\n", spec.log_dir); + } + // Validate log_dir. + if (!dsn::utils::filesystem::is_absolute_path(spec.log_dir)) { + fmt::print(stderr, "log_dir({}) should be set with an absolute path\n", spec.log_dir); + return false; + } + dsn::utils::filesystem::create_directory(spec.log_dir); - // init tools + // Initialize tools. dsn_all.tool.reset(::dsn::utils::factory_store<::dsn::tools::tool_app>::create( spec.tool.c_str(), ::dsn::PROVIDER_TYPE_MAIN, spec.tool.c_str())); dsn_all.tool->install(spec); - // init app specs + // Initialize app specs. if (!spec.init_app_specs()) { - printf("error in config file %s, exit ...\n", config_file); + fmt::print(stderr, "error in config file {}, exit ...\n", config_file); return false; } @@ -462,10 +471,27 @@ bool run(const char *config_file, ::MallocExtension::instance()->SetMemoryReleaseRate(FLAGS_tcmalloc_release_rate); #endif - // init logging - dsn_log_init(spec.logging_factory_name, spec.dir_log, dsn_log_prefixed_message_func); + // Extract app_names. + std::list app_names_and_indexes; + ::dsn::utils::split_args(app_list.c_str(), app_names_and_indexes, ';'); + std::vector app_names; + for (const auto &app_name_and_index : app_names_and_indexes) { + std::vector name_and_index; + ::dsn::utils::split_args(app_name_and_index.c_str(), name_and_index, '@'); + if (name_and_index.empty()) { + fmt::print(stderr, "app_name should be specified in '{}'", app_name_and_index); + return false; + } + app_names.push_back(name_and_index[0]); + } + + // Initialize logging. + dsn_log_init(spec.logging_factory_name, + spec.log_dir, + fmt::format("{}", fmt::join(app_names, ".")), + dsn_log_prefixed_message_func); - // prepare minimum necessary + // Prepare the minimum necessary. ::dsn::service_engine::instance().init_before_toollets(spec); LOG_INFO("process({}) start: {}, date: {}", @@ -473,10 +499,10 @@ bool run(const char *config_file, dsn::utils::process_start_millis(), dsn::utils::process_start_date_time_mills()); - // init toollets - for (auto it = spec.toollets.begin(); it != spec.toollets.end(); ++it) { - auto tlet = - dsn::tools::internal_use_only::get_toollet(it->c_str(), ::dsn::PROVIDER_TYPE_MAIN); + // Initialize toollets. + for (const auto &toollet_name : spec.toollets) { + auto tlet = dsn::tools::internal_use_only::get_toollet(toollet_name.c_str(), + ::dsn::PROVIDER_TYPE_MAIN); CHECK_NOTNULL(tlet, "toolet not found"); tlet->install(spec); } @@ -507,29 +533,34 @@ bool run(const char *config_file, } } - // split app_name and app_index - std::list applistkvs; - ::dsn::utils::split_args(app_list.c_str(), applistkvs, ';'); - // init apps for (auto &sp : spec.app_specs) { - if (!sp.run) + if (!sp.run) { continue; + } bool create_it = false; - // create all apps - if (app_list == "") { + if (app_list.empty()) { create_it = true; } else { - for (auto &kv : applistkvs) { - std::list argskvs; - ::dsn::utils::split_args(kv.c_str(), argskvs, '@'); - if (std::string("apps.") + argskvs.front() == sp.config_section) { - if (argskvs.size() < 2) + for (const auto &app_name_and_index : app_names_and_indexes) { + std::vector name_and_index; + ::dsn::utils::split_args(app_name_and_index.c_str(), name_and_index, '@'); + CHECK(!name_and_index.empty(), + "app_name should be specified in '{}'", + app_name_and_index); + if (std::string("apps.") + name_and_index.front() == sp.config_section) { + if (name_and_index.size() < 2) { create_it = true; - else - create_it = (std::stoi(argskvs.back()) == sp.index); + } else { + int32_t index; + const auto index_str = name_and_index.back(); + CHECK(dsn::buf2int32(index_str, index), + "'{}' is not an valid index", + index_str); + create_it = (index == sp.index); + } break; } } @@ -540,10 +571,11 @@ bool run(const char *config_file, } } - if (dsn::service_engine::instance().get_all_nodes().size() == 0) { - printf("no app are created, usually because \n" - "app_name is not specified correctly, should be 'xxx' in [apps.xxx]\n" - "or app_index (1-based) is greater than specified count in config file\n"); + if (dsn::service_engine::instance().get_all_nodes().empty()) { + fmt::print(stderr, + "no app are created, usually because \n" + "app_name is not specified correctly, should be 'xxx' in [apps.xxx]\n" + "or app_index (1-based) is greater than specified count in config file\n"); exit(1); } diff --git a/src/utils/config_helper.h b/src/utils/config_helper.h index aeda3048c9..1010b68ab6 100644 --- a/src/utils/config_helper.h +++ b/src/utils/config_helper.h @@ -49,9 +49,12 @@ section, #fld, default_value ? default_value->fld : default_fld_value, dsptr); #define CONFIG_FLD_STRING(fld, default_fld_value, dsptr) \ + CONFIG_FLD_STRING_BY_KEY(fld, #fld, default_fld_value, dsptr) + +#define CONFIG_FLD_STRING_BY_KEY(fld, key, default_fld_value, dsptr) \ val.fld = dsn_config_get_value_string( \ section, \ - #fld, \ + key, \ (val.fld.length() > 0 && val.fld != std::string(default_fld_value)) \ ? val.fld.c_str() \ : (default_value ? default_value->fld.c_str() : default_fld_value), \ diff --git a/src/utils/filesystem.cpp b/src/utils/filesystem.cpp index ec414767cc..41b93c94b6 100644 --- a/src/utils/filesystem.cpp +++ b/src/utils/filesystem.cpp @@ -29,6 +29,7 @@ #include #include #include +#include #include #include #include @@ -49,6 +50,7 @@ #include "utils/fmt_logging.h" #include "utils/ports.h" #include "utils/safe_strerror_posix.h" +#include "errors.h" #define getcwd_ getcwd #define rmdir_ rmdir @@ -492,6 +494,12 @@ bool create_file(const std::string &path) return true; } +bool is_absolute_path(const std::string &path) +{ + boost::filesystem::path p(path); + return p.is_absolute(); +} + bool get_absolute_path(const std::string &path1, std::string &path2) { bool succ; @@ -901,6 +909,36 @@ bool check_dir_rw(const std::string &path, std::string &err_msg) return true; } +error_s glob(const std::string &path_pattern, std::vector &path_list) +{ + glob_t result; + auto cleanup = dsn::defer([&] { ::globfree(&result); }); + + errno = 0; + int ret = ::glob(path_pattern.c_str(), GLOB_TILDE | GLOB_ERR, NULL, &result); + switch (ret) { + case 0: + break; + + case GLOB_NOMATCH: + return error_s::ok(); + + case GLOB_NOSPACE: + return error_s::make(ERR_FS_INTERNAL, "glob out of memory"); + + default: + std::string error(errno == 0 ? "unknown error" : safe_strerror(errno)); + return error_s::make(ERR_FS_INTERNAL, + fmt::format("glob failed for '{}': {}", path_pattern, error)); + } + + for (size_t i = 0; i < result.gl_pathc; ++i) { + path_list.emplace_back(result.gl_pathv[i]); + } + + return error_s::ok(); +} + } // namespace filesystem } // namespace utils } // namespace dsn diff --git a/src/utils/filesystem.h b/src/utils/filesystem.h index 29524c9c3c..3c370044ce 100644 --- a/src/utils/filesystem.h +++ b/src/utils/filesystem.h @@ -32,6 +32,7 @@ #include #include +#include "utils/errors.h" #include "utils/error_code.h" #ifndef _XOPEN_SOURCE @@ -69,6 +70,8 @@ namespace filesystem { void get_normalized_path(const std::string &path, std::string &npath); +bool is_absolute_path(const std::string &path); + bool get_absolute_path(const std::string &path1, std::string &path2); std::string remove_file_name(const std::string &path); @@ -165,6 +168,13 @@ bool create_directory(const std::string &path, // call `create_directory` before to make `path` exist bool check_dir_rw(const std::string &path, /*out*/ std::string &err_msg); +// Finds paths on the filesystem matching a pattern. +// +// The found pathnames are added to the 'paths' vector. If no pathnames are +// found matching the pattern, no paths are added to the vector and an OK +// status is returned. +error_s glob(const std::string &path_pattern, std::vector &path_list); + } // namespace filesystem } // namespace utils } // namespace dsn diff --git a/src/utils/logging.cpp b/src/utils/logging.cpp index 294305b3fa..25b9ac7cdd 100644 --- a/src/utils/logging.cpp +++ b/src/utils/logging.cpp @@ -72,7 +72,8 @@ static void log_on_sys_exit(::dsn::sys_exit_type) } void dsn_log_init(const std::string &logging_factory_name, - const std::string &dir_log, + const std::string &log_dir, + const std::string &role_name, std::function dsn_log_prefixed_message_func) { log_start_level = enum_from_string(FLAGS_logging_start_level, LOG_LEVEL_INVALID); @@ -86,7 +87,7 @@ void dsn_log_init(const std::string &logging_factory_name, } dsn::logging_provider *logger = dsn::utils::factory_store::create( - logging_factory_name.c_str(), dsn::PROVIDER_TYPE_MAIN, dir_log.c_str()); + logging_factory_name.c_str(), dsn::PROVIDER_TYPE_MAIN, log_dir.c_str(), role_name.c_str()); dsn::logging_provider::set_logger(logger); if (dsn_log_prefixed_message_func != nullptr) { diff --git a/src/utils/logging_provider.h b/src/utils/logging_provider.h index 5061cee49f..ef11521a75 100644 --- a/src/utils/logging_provider.h +++ b/src/utils/logging_provider.h @@ -40,12 +40,12 @@ class logging_provider { public: template - static logging_provider *create(const char *log_dir) + static logging_provider *create(const char *log_dir, const char *role_name) { - return new T(log_dir); + return new T(log_dir, role_name); } - typedef logging_provider *(*factory)(const char *); + typedef logging_provider *(*factory)(const char *, const char *); public: virtual ~logging_provider() = default; @@ -87,5 +87,6 @@ bool register_component_provider(const char *name, } // namespace dsn extern void dsn_log_init(const std::string &logging_factory_name, - const std::string &dir_log, + const std::string &log_dir, + const std::string &role_name, std::function dsn_log_prefixed_message_func); diff --git a/src/utils/simple_logger.cpp b/src/utils/simple_logger.cpp index d54e03025f..41dbb468cc 100644 --- a/src/utils/simple_logger.cpp +++ b/src/utils/simple_logger.cpp @@ -28,6 +28,7 @@ // IWYU pragma: no_include #include +#include #include #include #include @@ -43,10 +44,18 @@ #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/strings.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, @@ -60,23 +69,29 @@ DSN_DEFINE_uint64( max_number_of_log_files_on_disk, 20, "The maximum number of log files to be reserved on disk, older logs are deleted automatically"); +DSN_DEFINE_validator(max_number_of_log_files_on_disk, + [](int32_t value) -> bool { return value > 0; }); DSN_DEFINE_string( tools.simple_logger, stderr_start_level, "LOG_LEVEL_WARNING", "The lowest level of log messages to be copied to stderr in addition to log files"); -DSN_DEFINE_validator(stderr_start_level, [](const char *level) -> bool { - return !dsn::utils::equals(level, "LOG_LEVEL_INVALID"); +DSN_DEFINE_validator(stderr_start_level, [](const char *value) -> bool { + const auto level = enum_from_string(value, LOG_LEVEL_INVALID); + return LOG_LEVEL_DEBUG <= level && level <= LOG_LEVEL_FATAL; }); +DSN_DEFINE_string(tools.simple_logger, base_name, "pegasus", "The default base name for log file"); + DSN_DECLARE_string(logging_start_level); namespace dsn { namespace tools { -static void print_header(FILE *fp, log_level_t log_level) +namespace { +void print_header(FILE *fp, log_level_t log_level) { - // The leading character of each log lines, corresponding to the log level + // The leading character of each log line, corresponding to the log level // D: Debug // I: Info // W: Warning @@ -90,16 +105,14 @@ static void print_header(FILE *fp, log_level_t log_level) int tid = dsn::utils::get_current_tid(); fmt::print(fp, - "{}{} ({} {}) {}", + "{}{} ({} {:#04x}) {}", s_level_char[log_level], time_str, ts, tid, - log_prefixed_message_func().c_str()); + log_prefixed_message_func()); } -namespace { - inline void process_fatal_log(log_level_t log_level) { if (dsn_likely(log_level < LOG_LEVEL_FATAL)) { @@ -144,46 +157,16 @@ void screen_logger::log( void screen_logger::flush() { ::fflush(stdout); } -simple_logger::simple_logger(const char *log_dir) +simple_logger::simple_logger(const char *log_dir, const char *role_name) : _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(fmt::format("{}.log", utils::is_empty(role_name) ? FLAGS_base_name : role_name)); + _file_name_prefix = fmt::format("{}.", symlink_name); + _symlink_path = utils::filesystem::path_combine(_log_dir, symlink_name); create_log_file(); @@ -222,40 +205,105 @@ simple_logger::simple_logger(const char *log_dir) void simple_logger::create_log_file() { + // Close the current log file if it is opened. if (_log != nullptr) { ::fclose(_log); + _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::fprintf(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::fprintf(stderr, "Failed to symlink %s 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::fprintf( + 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::fprintf(stderr, + "Failed to stat {}: {}\n", + matching_file_path, + dsn::utils::safe_strerror(errno)); + continue; + } + + int64_t mtime = s.st_mtim.tv_sec * 1000000 + s.st_mtim.tv_nsec / 1000; + 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::fprintf(stderr, + "Failed to remove redundant log file {}: {}\n", + matching_file, + dsn::utils::safe_strerror(errno)); } } } -simple_logger::~simple_logger(void) +simple_logger::~simple_logger() { utils::auto_lock<::dsn::utils::ex_lock> l(_lock); ::fclose(_log); + _log = nullptr; } void simple_logger::flush() { utils::auto_lock<::dsn::utils::ex_lock> l(_lock); ::fflush(_log); + ::fflush(stderr); ::fflush(stdout); } @@ -264,6 +312,7 @@ void simple_logger::log( { utils::auto_lock<::dsn::utils::ex_lock> l(_lock); + CHECK_NOTNULL(_log, "Log file hasn't been initialized yet"); print_header(_log, log_level); if (!FLAGS_short_header) { fprintf(_log, "%s:%d:%s(): ", file, line, function); @@ -283,7 +332,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 e9657a8018..3baea1fb95 100644 --- a/src/utils/simple_logger.h +++ b/src/utils/simple_logger.h @@ -43,6 +43,7 @@ class screen_logger : public logging_provider { public: explicit screen_logger(bool short_header); + explicit screen_logger(const char *, const char *) : _short_header(true) {} ~screen_logger() override; void log(const char *file, @@ -65,7 +66,9 @@ class screen_logger : public logging_provider class simple_logger : public logging_provider { public: - simple_logger(const char *log_dir); + // 'log_dir' is the directory to store log files, 'role_name' is the name of the process, + // such as 'replica_server', 'meta_server' in Pegasus. + simple_logger(const char *log_dir, const char *role_name); ~simple_logger() override; void log(const char *file, @@ -79,15 +82,23 @@ class simple_logger : public logging_provider private: 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; - log_level_t _stderr_start_level; + // The byte size of the current log file. + uint64_t _file_bytes; + const log_level_t _stderr_start_level; }; } // namespace tools } // namespace dsn diff --git a/src/utils/test/file_system_test.cpp b/src/utils/test/file_system_test.cpp index 66a224f9e5..82c7c92382 100644 --- a/src/utils/test/file_system_test.cpp +++ b/src/utils/test/file_system_test.cpp @@ -175,6 +175,37 @@ TEST(filesystem_test, verify_file_test) remove_path(fname); } +TEST(filesystem_test, absolute_path_test) +{ + const std::string kTestDir = "absolute_path_test"; + ASSERT_TRUE(create_directory(kTestDir)); + ASSERT_FALSE(is_absolute_path(kTestDir)); + + std::string abs_path; + ASSERT_TRUE(get_absolute_path(kTestDir, abs_path)); + ASSERT_TRUE(is_absolute_path(abs_path)); +} + +TEST(filesystem_test, glob_test) +{ + const std::string kTestDir = "glob_test"; + ASSERT_TRUE(create_directory(kTestDir)); + std::vector filenames = {"fuzz", "fuzzy", "fuzzyiest", "buzz"}; + std::vector> matchers = { + {"file", 0}, {"fuzz", 1}, {"fuzz*", 3}, {"?uzz", 2}, + }; + + for (const auto &name : filenames) { + ASSERT_TRUE(create_file(path_combine(kTestDir, name))); + } + + for (const auto & [ path_pattern, matched_count ] : matchers) { + std::vector matches; + ASSERT_TRUE(glob(path_combine(kTestDir, path_pattern), matches)) << path_pattern; + ASSERT_EQ(matched_count, matches.size()) << path_pattern; + } +} + } // namespace filesystem } // namespace utils } // namespace dsn diff --git a/src/utils/test/logger.cpp b/src/utils/test/logger.cpp index 70d6ef1e2b..3de6271f2c 100644 --- a/src/utils/test/logger.cpp +++ b/src/utils/test/logger.cpp @@ -24,13 +24,13 @@ * THE SOFTWARE. */ -#include #include #include #include #include #include #include +#include #include #include #include @@ -50,25 +50,49 @@ namespace tools { namespace { -void get_log_file_index(std::vector &log_index) +static void get_log_files(std::set &files) { std::vector sub_list; - ASSERT_TRUE(dsn::utils::filesystem::get_subfiles("./", sub_list, false)); + ASSERT_TRUE(utils::filesystem::get_subfiles("./", sub_list, false)); + files.clear(); + std::regex pattern(R"(skv\.log\.[0-9]{8}_[0-9]{6}_[0-9]{3})"); for (const auto &path : sub_list) { - const auto &name = dsn::utils::filesystem::get_file_name(path); - if (!boost::algorithm::starts_with(name, "log.")) { - continue; + std::string name(utils::filesystem::get_file_name(path)); + if (std::regex_match(name, pattern)) { + ASSERT_TRUE(files.insert(name).second); } - if (!boost::algorithm::ends_with(name, ".txt")) { - continue; + } +} + +static void compare_log_files(const std::set &before_files, + const std::set &after_files) +{ + ASSERT_FALSE(after_files.empty()); + + if (after_files.size() == before_files.size() + 1) { + for (auto it1 = before_files.begin(), it2 = after_files.begin(); it1 != before_files.end(); + ++it1, ++it2) { + ASSERT_EQ(*it1, *it2); } + } else if (after_files.size() == before_files.size()) { + auto it1 = before_files.begin(); + auto it2 = after_files.begin(); + ASSERT_NE(*it1, *it2); - int index; - if (1 != sscanf(name.c_str(), "log.%d.txt", &index)) { - continue; + for (++it1; it1 != before_files.end(); ++it1, ++it2) { + ASSERT_EQ(*it1, *it2); } - log_index.push_back(index); + } else { + ASSERT_TRUE(false) << "Invalid number of log files, before=" << before_files.size() + << ", after=" << after_files.size(); + } +} + +static void clear_files(const std::set &file_name_list) +{ + for (const auto &name : file_name_list) { + EXPECT_TRUE(dsn::utils::filesystem::remove_path(name)); } } @@ -112,18 +136,29 @@ TEST(LoggerTest, SimpleLogger) // 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; + get_log_files(before_files); + + auto logger = std::make_unique("./", "SimpleLogger"); for (unsigned int i = 0; i != 1000; ++i) { LOG_PRINT(logger.get(), "{}", "test_print"); } logger->flush(); + + std::set after_files; + get_log_files(after_files); + + compare_log_files(before_files, after_files); + + ::usleep(2000); } - 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 files; + get_log_files(files); + ASSERT_FALSE(files.empty()); + ASSERT_EQ(FLAGS_max_number_of_log_files_on_disk, files.size()); + clear_files(files); remove_test_dir(); } diff --git a/src/utils/test/main.cpp b/src/utils/test/main.cpp index 2be6302e1a..0bdfb7f7a5 100644 --- a/src/utils/test/main.cpp +++ b/src/utils/test/main.cpp @@ -25,7 +25,7 @@ GTEST_API_ int main(int argc, char **argv) { testing::InitGoogleTest(&argc, argv); - dsn_log_init("dsn::tools::simple_logger", "./", nullptr); + dsn_log_init("dsn::tools::simple_logger", "./", "test", nullptr); dsn::flags_initialize(); diff --git a/src/utils/test/run.sh b/src/utils/test/run.sh index 90698a718f..9a6b1bb493 100755 --- a/src/utils/test/run.sh +++ b/src/utils/test/run.sh @@ -36,9 +36,9 @@ if [ $? -ne 0 ]; then echo "run dsn_utils_tests failed" echo "---- ls ----" ls -l - if find . -name log.1.txt; then - echo "---- tail -n 100 log.1.txt ----" - tail -n 100 `find . -name log.1.txt` + if [ `find . -name skv.log.* | wc -l` -ne 0 ]; then + echo "---- tail -n 100 skv.log.* ----" + tail -n 100 `find . -name skv.log.*` fi if [ -f core ]; then echo "---- gdb ./dsn_utils_tests core ----" diff --git a/src/utils/test/time_utils_test.cpp b/src/utils/test/time_utils_test.cpp index 35838aaf78..843ab69f3c 100644 --- a/src/utils/test/time_utils_test.cpp +++ b/src/utils/test/time_utils_test.cpp @@ -94,7 +94,7 @@ void test_time_ms_to_string(T &str) std::string actual_str(str); - // Time differ between time zones. + // Time differs between time zones. // // The real time 2020-11-11 18:45:06.136 (UTC+8) // so it must be 2020-11-1x xx:45:06.136. @@ -114,5 +114,20 @@ TEST(time_utils, time_ms_to_str) test_time_ms_to_string(str); } +TEST(time_utils, time_ms_to_sequent_str) +{ + std::string str; + time_ms_to_sequent_string(1605091506136, str); + + std::string actual_str(str); + + // Time differs between time zones. + // + // The real time 20201111_184506_136 (UTC+8) + // so it must be 2020111x_xx4506_136. + ASSERT_EQ(std::string("2020111"), actual_str.substr(0, 7)); + ASSERT_EQ(std::string("4506_136"), actual_str.substr(11, 8)); +} + } // namespace utils } // namespace dsn diff --git a/src/utils/time_utils.cpp b/src/utils/time_utils.cpp index 34504fc993..ff26530a52 100644 --- a/src/utils/time_utils.cpp +++ b/src/utils/time_utils.cpp @@ -50,5 +50,14 @@ namespace utils { static_cast(ts_ms % 1000)); } +/*extern*/ void time_ms_to_sequent_string(uint64_t ts_ms, std::string &str) +{ + str.clear(); + struct tm tmp; + auto ret = get_localtime(ts_ms, &tmp); + fmt::format_to( + std::back_inserter(str), "{:%Y%m%d_%H%M%S}_{}", *ret, static_cast(ts_ms % 1000)); +} + } // namespace utils } // namespace dsn diff --git a/src/utils/time_utils.h b/src/utils/time_utils.h index f89eebf8f2..546bea0ef2 100644 --- a/src/utils/time_utils.h +++ b/src/utils/time_utils.h @@ -47,13 +47,16 @@ static struct tm *get_localtime(uint64_t ts_ms, struct tm *tm_buf) return localtime_r(&t, tm_buf); } -// get time string, which format is yyyy-MM-dd hh:mm:ss.SSS +// Get time string, which format is yyyy-MM-dd hh:mm:ss.SSS // NOTE: using char* as output is usually unsafe, remember to initialize its memory as zero before // calling 'time_ms_to_string'. Please use std::string as the output argument as long as it's // possible. extern void time_ms_to_string(uint64_t ts_ms, char *str); extern void time_ms_to_string(uint64_t ts_ms, std::string &str); +// Get time string, which format is yyyyMMdd_hhmmss_SSS +extern void time_ms_to_sequent_string(uint64_t ts_ms, std::string &str); + // get date string with format of 'yyyy-MM-dd' from given timestamp inline void time_ms_to_date(uint64_t ts_ms, char *str, int len) { diff --git a/src/zookeeper/test/run.sh b/src/zookeeper/test/run.sh index 38608a28b3..fcb414b765 100755 --- a/src/zookeeper/test/run.sh +++ b/src/zookeeper/test/run.sh @@ -37,9 +37,9 @@ if [ $? -ne 0 ]; then echo "run dsn.zookeeper.tests failed" echo "---- ls ----" ls -l - if find . -name log.1.txt; then - echo "---- tail -n 100 log.1.txt ----" - tail -n 100 `find . -name log.1.txt` + if [ `find . -name skv.log.* | wc -l` -ne 0 ]; then + echo "---- tail -n 100 skv.log.* ----" + tail -n 100 `find . -name skv.log.*` fi if [ -f core ]; then echo "---- gdb ./dsn.zookeeper.tests core ----"