From 0b3412172c9dc118f2be7af487bdf23ad1b588c4 Mon Sep 17 00:00:00 2001 From: Yingchun Lai Date: Tue, 30 Jul 2024 01:14:09 +0800 Subject: [PATCH] feat(logging): Introduce spdlog and remove simple_logger and screen_logger --- .licenserc.yaml | 4 - cmake_modules/BaseFunctions.cmake | 2 + src/http/pprof_http_service.cpp | 6 +- .../duplication/meta_duplication_service.cpp | 5 +- src/replica/replica_2pc.cpp | 5 +- src/runtime/rpc/rpc_host_port.cpp | 4 +- src/runtime/service_api_c.cpp | 34 +- src/runtime/tool_api.h | 1 - src/security/sasl_init.cpp | 12 +- src/utils/CMakeLists.txt | 3 +- src/utils/api_utilities.h | 7 +- src/utils/fmt_logging.h | 47 +- src/utils/logging.cpp | 219 +++++---- src/utils/logging.h | 42 ++ src/utils/logging_provider.h | 95 ---- src/utils/simple_logger.cpp | 425 ------------------ src/utils/simple_logger.h | 124 ----- src/utils/test/logger.cpp | 183 -------- src/utils/test/logging.cpp | 54 +-- src/utils/test/main.cpp | 4 +- src/utils/timer.h | 37 +- 21 files changed, 290 insertions(+), 1023 deletions(-) create mode 100644 src/utils/logging.h delete mode 100644 src/utils/logging_provider.h delete mode 100644 src/utils/simple_logger.cpp delete mode 100644 src/utils/simple_logger.h delete mode 100644 src/utils/test/logger.cpp diff --git a/.licenserc.yaml b/.licenserc.yaml index b8e45b5ec4..486cbf5c45 100644 --- a/.licenserc.yaml +++ b/.licenserc.yaml @@ -165,7 +165,6 @@ header: - 'src/runtime/global_config.h' - 'src/common/gpid.h' - 'src/runtime/rpc/group_address.h' - - 'src/utils/logging_provider.h' - 'src/runtime/rpc/message_parser.h' - 'src/runtime/rpc/network.h' - 'src/runtime/rpc/rpc_address.cpp' @@ -617,8 +616,6 @@ header: - 'src/utils/lockp.std.h' - 'src/utils/logging.cpp' - 'src/utils/shared_io_service.h' - - 'src/utils/simple_logger.cpp' - - 'src/utils/simple_logger.h' - 'src/utils/strings.cpp' - 'src/utils/test/CMakeLists.txt' - 'src/utils/test/clear.sh' @@ -637,7 +634,6 @@ header: - 'src/utils/test/join_point_test.cpp' - 'src/utils/test/json_helper_test.cpp' - 'src/utils/test/lock.std.cpp' - - 'src/utils/test/logger.cpp' - 'src/utils/test/logging.cpp' - 'src/utils/test/output_utils_test.cpp' - 'src/utils/test/priority_queue.cpp' diff --git a/cmake_modules/BaseFunctions.cmake b/cmake_modules/BaseFunctions.cmake index 33c819fbb5..97e9470632 100644 --- a/cmake_modules/BaseFunctions.cmake +++ b/cmake_modules/BaseFunctions.cmake @@ -208,6 +208,8 @@ function(dsn_setup_compiler_flags) if(${BUILD_TEST}) add_definitions(-DMOCK_TEST) endif() + add_definitions(-DSPDLOG_FMT_EXTERNAL) + add_definitions(-DSPDLOG_ACTIVE_LEVEL=SPDLOG_LEVEL_DEBUG) set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} -std=c++17 -gdwarf-4" CACHE STRING "" FORCE) diff --git a/src/http/pprof_http_service.cpp b/src/http/pprof_http_service.cpp index d7246ae69d..bcb154732d 100644 --- a/src/http/pprof_http_service.cpp +++ b/src/http/pprof_http_service.cpp @@ -98,7 +98,7 @@ static bool has_ext(const std::string &name, const std::string &ext) static int extract_symbols_from_binary(std::map &addr_map, const lib_info &lib_info) { - SCOPED_LOG_TIMING(INFO, "load {}", lib_info.path); + SCOPED_LOG_TIMING(info, "load {}", lib_info.path); std::string cmd = "nm -C -p "; cmd.append(lib_info.path); std::stringstream ss; @@ -195,7 +195,7 @@ static int extract_symbols_from_binary(std::map &addr_ma static void load_symbols() { - SCOPED_LOG_TIMING(INFO, "load all symbols"); + SCOPED_LOG_TIMING(info, "load all symbols"); auto fp = fopen("/proc/self/maps", "r"); if (fp == nullptr) { return; @@ -267,7 +267,7 @@ static void load_symbols() extract_symbols_from_binary(symbol_map, info); size_t num_removed = 0; - LOG_TIMING_IF(INFO, num_removed > 0, "removed {} entries", num_removed); + LOG_TIMING_IF(info, num_removed > 0, "removed {} entries", num_removed); bool last_is_empty = false; for (auto it = symbol_map.begin(); it != symbol_map.end();) { if (it->second.empty()) { diff --git a/src/meta/duplication/meta_duplication_service.cpp b/src/meta/duplication/meta_duplication_service.cpp index 4f0d7f816e..1cdb2f3bb4 100644 --- a/src/meta/duplication/meta_duplication_service.cpp +++ b/src/meta/duplication/meta_duplication_service.cpp @@ -55,6 +55,7 @@ #include "utils/ports.h" #include "utils/string_conv.h" #include "utils/zlocks.h" +#include "spdlog/common.h" DSN_DECLARE_bool(dup_ignore_other_cluster_ids); @@ -174,10 +175,10 @@ void meta_duplication_service::do_modify_duplication(std::shared_ptr } while (0) #define LOG_WARNING_DUP_HINT_AND_RETURN_IF_NOT(expr, resp, ec, ...) \ - LOG_DUP_HINT_AND_RETURN_IF_NOT(expr, resp, ec, LOG_LEVEL_WARNING, __VA_ARGS__) + LOG_DUP_HINT_AND_RETURN_IF_NOT(expr, resp, ec, spdlog::level::warn, __VA_ARGS__) #define LOG_ERROR_DUP_HINT_AND_RETURN_IF_NOT(expr, resp, ec, ...) \ - LOG_DUP_HINT_AND_RETURN_IF_NOT(expr, resp, ec, LOG_LEVEL_ERROR, __VA_ARGS__) + LOG_DUP_HINT_AND_RETURN_IF_NOT(expr, resp, ec, spdlog::level::err, __VA_ARGS__) // This call will not recreate if the duplication // with the same app name and remote end point already exists. diff --git a/src/replica/replica_2pc.cpp b/src/replica/replica_2pc.cpp index 8f48438d1a..824c3bed8e 100644 --- a/src/replica/replica_2pc.cpp +++ b/src/replica/replica_2pc.cpp @@ -77,6 +77,7 @@ #include "utils/ports.h" #include "utils/thread_access_checker.h" #include "utils/uniq_timestamp_us.h" +#include "spdlog/common.h" DSN_DEFINE_bool(replication, reject_write_when_disk_insufficient, @@ -238,13 +239,13 @@ void replica::init_prepare(mutation_ptr &mu, bool reconciliation, bool pop_all_c const auto request_count = mu->client_requests.size(); mu->data.header.last_committed_decree = last_committed_decree(); - log_level_t level = LOG_LEVEL_DEBUG; + spdlog::level::level_enum level = spdlog::level::debug; if (mu->data.header.decree == invalid_decree) { mu->set_id(get_ballot(), _prepare_list->max_decree() + 1); // print a debug log if necessary if (FLAGS_prepare_decree_gap_for_debug_logging > 0 && mu->get_decree() % FLAGS_prepare_decree_gap_for_debug_logging == 0) - level = LOG_LEVEL_INFO; + level = spdlog::level::info; mu->set_timestamp(_uniq_timestamp_us.next()); } else { mu->set_id(get_ballot(), mu->data.header.decree); diff --git a/src/runtime/rpc/rpc_host_port.cpp b/src/runtime/rpc/rpc_host_port.cpp index 42ed764010..b7a3cf54bf 100644 --- a/src/runtime/rpc/rpc_host_port.cpp +++ b/src/runtime/rpc/rpc_host_port.cpp @@ -55,7 +55,7 @@ host_port host_port::from_address(rpc_address addr) { host_port hp; SCOPED_LOG_SLOW_EXECUTION( - WARNING, 100, "construct host_port '{}' from rpc_address '{}'", hp, addr); + warn, 100, "construct host_port '{}' from rpc_address '{}'", hp, addr); switch (addr.type()) { case HOST_TYPE_IPV4: { const auto s = lookup_hostname(htonl(addr.ip()), &hp._host); @@ -81,7 +81,7 @@ host_port host_port::from_string(const std::string &host_port_str) { host_port hp; SCOPED_LOG_SLOW_EXECUTION( - WARNING, 100, "construct host_port '{}' from string '{}'", hp, host_port_str); + warn, 100, "construct host_port '{}' from string '{}'", hp, host_port_str); const auto pos = host_port_str.find_last_of(':'); if (dsn_unlikely(pos == std::string::npos)) { return hp; diff --git a/src/runtime/service_api_c.cpp b/src/runtime/service_api_c.cpp index f4ed022344..165377b807 100644 --- a/src/runtime/service_api_c.cpp +++ b/src/runtime/service_api_c.cpp @@ -75,12 +75,12 @@ #include "utils/flags.h" #include "utils/fmt_logging.h" #include "utils/join_point.h" -#include "utils/logging_provider.h" #include "utils/process_utils.h" #include "utils/string_conv.h" #include "utils/strings.h" #include "utils/sys_exit_hook.h" #include "utils/threadpool_spec.h" +#include "utils/logging.h" DSN_DEFINE_bool( core, @@ -343,33 +343,6 @@ inline void dsn_global_init() dsn::service_engine::instance(); } -static std::string dsn_log_prefixed_message_func() -{ - const int tid = dsn::utils::get_current_tid(); - const auto t = dsn::task::get_current_task_id(); - if (t) { - if (nullptr != dsn::task::get_current_worker2()) { - return fmt::format("{}.{}{}.{:016}: ", - dsn::task::get_current_node_name(), - dsn::task::get_current_worker2()->pool_spec().name, - dsn::task::get_current_worker2()->index(), - t); - } else { - return fmt::format( - "{}.io-thrd.{}.{:016}: ", dsn::task::get_current_node_name(), tid, t); - } - } else { - if (nullptr != dsn::task::get_current_worker2()) { - return fmt::format("{}.{}{}: ", - dsn::task::get_current_node_name(), - dsn::task::get_current_worker2()->pool_spec().name, - dsn::task::get_current_worker2()->index()); - } else { - return fmt::format("{}.io-thrd.{}: ", dsn::task::get_current_node_name(), tid); - } - } -} - bool run(const char *config_file, const char *config_arguments, bool is_server, @@ -473,10 +446,7 @@ bool run(const char *config_file, } // Initialize logging. - dsn_log_init(spec.logging_factory_name, - spec.log_dir, - fmt::format("{}", fmt::join(app_names, ".")), - dsn_log_prefixed_message_func); + dsn_log_init(spec.log_dir, fmt::format("{}", fmt::join(app_names, "."))); // Prepare the minimum necessary. ::dsn::service_engine::instance().init_before_toollets(spec); diff --git a/src/runtime/tool_api.h b/src/runtime/tool_api.h index c9e145a435..18135be614 100644 --- a/src/runtime/tool_api.h +++ b/src/runtime/tool_api.h @@ -52,7 +52,6 @@ Component providers define the interface for the local components (e.g., network // providers #include "utils/factory_store.h" #include "utils/join_point.h" -#include "utils/logging_provider.h" // IWYU pragma: keep namespace dsn { class service_node; diff --git a/src/security/sasl_init.cpp b/src/security/sasl_init.cpp index 1f9712c34c..b0a6eda975 100644 --- a/src/security/sasl_init.cpp +++ b/src/security/sasl_init.cpp @@ -27,24 +27,26 @@ #include "utils/flags.h" #include "utils/fmt_logging.h" #include "utils/synchronize.h" +#include "spdlog/common.h" +#include "spdlog/spdlog.h" DSN_DEFINE_string(security, sasl_plugin_path, "/usr/lib/sasl2", "path to search sasl plugins"); namespace dsn { namespace security { -log_level_t get_log_level(int level) +spdlog::level::level_enum get_log_level(int level) { switch (level) { case SASL_LOG_ERR: - return LOG_LEVEL_ERROR; + return spdlog::level::err; case SASL_LOG_FAIL: case SASL_LOG_WARN: - return LOG_LEVEL_WARNING; + return spdlog::level::warn; case SASL_LOG_NOTE: - return LOG_LEVEL_INFO; + return spdlog::level::info; default: - return LOG_LEVEL_DEBUG; + return spdlog::level::debug; } } diff --git a/src/utils/CMakeLists.txt b/src/utils/CMakeLists.txt index 337ac2591b..91ea0cc8ea 100644 --- a/src/utils/CMakeLists.txt +++ b/src/utils/CMakeLists.txt @@ -37,7 +37,8 @@ set(MY_PROJ_LIBS lz4 zstd snappy - absl::strings) + absl::strings + spdlog) # Extra files that will be installed set(MY_BINPLACES "") diff --git a/src/utils/api_utilities.h b/src/utils/api_utilities.h index ec0733ae5c..76f07a678c 100644 --- a/src/utils/api_utilities.h +++ b/src/utils/api_utilities.h @@ -31,6 +31,7 @@ #include "utils/enum_helper.h" #include "utils/fmt_utils.h" #include "utils/ports.h" +#include "spdlog/common.h" /*! @defgroup logging Logging Service @@ -65,12 +66,6 @@ ENUM_END(log_level_t) USER_DEFINED_ENUM_FORMATTER(log_level_t) -// logs with level smaller than this start_level will not be logged -extern log_level_t log_start_level; -extern log_level_t get_log_start_level(); -extern void set_log_start_level(log_level_t level); -extern void global_log( - const char *file, const char *function, const int line, log_level_t log_level, const char *str); extern void dsn_coredump(); #define dreturn_not_ok_logged(err, ...) \ diff --git a/src/utils/fmt_logging.h b/src/utils/fmt_logging.h index 97e751a48c..8c4eb453b8 100644 --- a/src/utils/fmt_logging.h +++ b/src/utils/fmt_logging.h @@ -19,28 +19,51 @@ #pragma once +#include #include #include #include "utils/api_utilities.h" +#include "spdlog/common.h" +#include "spdlog/spdlog.h" +#include "utils/logging.h" -// The macros below no longer use the default snprintf method for log message formatting, -// instead we use fmt::format. -// TODO(wutao1): prevent construction of std::string for each log. +extern spdlog::level::level_enum g_stderr_start_level; +extern spdlog::level::level_enum g_file_log_start_level; +extern std::shared_ptr g_stderr_logger; +extern std::shared_ptr g_file_logger; -// __FILENAME__ macro comes from the cmake, in which we calculate a filename without path. #define LOG(level, ...) \ do { \ - if (level >= log_start_level) \ - global_log( \ - __FILENAME__, __FUNCTION__, __LINE__, level, fmt::format(__VA_ARGS__).c_str()); \ + const auto _lvl = (level); \ + if (_lvl < g_file_log_start_level) { \ + break; \ + } \ + if (dsn_likely(!!g_file_logger)) { \ + g_file_logger->log(_lvl, __VA_ARGS__); \ + } else { \ + g_stderr_logger->log(_lvl, __VA_ARGS__); \ + } \ + } while (false) + +#define LOG_ON_LEVEL(UPPER_CASE_LEVEL, lower_case_level, ...) \ + do { \ + if (lower_case_level >= g_stderr_start_level) { \ + SPDLOG_LOGGER_##UPPER_CASE_LEVEL(g_stderr_logger, __VA_ARGS__); \ + } \ + if (dsn_likely(!!g_file_logger)) { \ + SPDLOG_LOGGER_##UPPER_CASE_LEVEL(g_file_logger, __VA_ARGS__); \ + if (dsn_unlikely(lower_case_level == spdlog::level::critical)) { \ + dsn_coredump(); \ + } \ + } \ } while (false) -#define LOG_DEBUG(...) LOG(LOG_LEVEL_DEBUG, __VA_ARGS__) -#define LOG_INFO(...) LOG(LOG_LEVEL_INFO, __VA_ARGS__) -#define LOG_WARNING(...) LOG(LOG_LEVEL_WARNING, __VA_ARGS__) -#define LOG_ERROR(...) LOG(LOG_LEVEL_ERROR, __VA_ARGS__) -#define LOG_FATAL(...) LOG(LOG_LEVEL_FATAL, __VA_ARGS__) +#define LOG_DEBUG(...) LOG_ON_LEVEL(DEBUG, spdlog::level::debug, __VA_ARGS__) +#define LOG_INFO(...) LOG_ON_LEVEL(INFO, spdlog::level::info, __VA_ARGS__) +#define LOG_WARNING(...) LOG_ON_LEVEL(WARN, spdlog::level::warn, __VA_ARGS__) +#define LOG_ERROR(...) LOG_ON_LEVEL(ERROR, spdlog::level::err, __VA_ARGS__) +#define LOG_FATAL(...) LOG_ON_LEVEL(CRITICAL, spdlog::level::critical, __VA_ARGS__) #define LOG_WARNING_IF(x, ...) \ do { \ diff --git a/src/utils/logging.cpp b/src/utils/logging.cpp index 66aeeb8aef..d96b963d8c 100644 --- a/src/utils/logging.cpp +++ b/src/utils/logging.cpp @@ -31,107 +31,176 @@ #include #include "runtime/tool_api.h" -#include "simple_logger.h" #include "utils/api_utilities.h" #include "utils/factory_store.h" #include "utils/flags.h" #include "utils/fmt_logging.h" #include "utils/join_point.h" -#include "utils/logging_provider.h" #include "utils/sys_exit_hook.h" +#include "spdlog/common.h" +#include "spdlog/spdlog.h" +#include "spdlog/sinks/rotating_file_sink.h" +#include "spdlog/sinks/stdout_sinks.h" +#include "utils/command_manager.h" DSN_DEFINE_string(core, logging_start_level, "LOG_LEVEL_INFO", "Logs with level larger than or equal to this level be logged"); +DSN_DEFINE_validator(logging_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_bool(core, logging_flush_on_exit, true, "Whether to flush the logs when the process exits"); -log_level_t log_start_level = LOG_LEVEL_INFO; - -namespace dsn { - -using namespace tools; -DSN_REGISTER_COMPONENT_PROVIDER(screen_logger, "dsn::tools::screen_logger"); -DSN_REGISTER_COMPONENT_PROVIDER(simple_logger, "dsn::tools::simple_logger"); - -std::function log_prefixed_message_func = []() -> std::string { return ": "; }; - -void set_log_prefixed_message_func(std::function func) -{ - log_prefixed_message_func = std::move(func); -} -} // namespace dsn - -static void log_on_sys_exit(::dsn::sys_exit_type) +DSN_DEFINE_bool(tools.simple_logger, + short_header, + false, + "Whether to use short header (excluding " + "file, file number and function name " + "fields in each line)"); + +DSN_DEFINE_bool(tools.simple_logger, fast_flush, false, "Whether to flush logs every second"); + +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_uint64( + tools.simple_logger, + 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, base_name, "pegasus", "The default base name for log file"); + +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 *value) -> bool { + const auto level = enum_from_string(value, LOG_LEVEL_INVALID); + return LOG_LEVEL_DEBUG <= level && level <= LOG_LEVEL_FATAL; +}); + +std::shared_ptr g_stderr_logger = spdlog::stderr_logger_mt("stderr"); +std::shared_ptr g_file_logger; + +static std::map to_spdlog_levels = { + {LOG_LEVEL_DEBUG, spdlog::level::debug}, + {LOG_LEVEL_INFO, spdlog::level::info}, + {LOG_LEVEL_WARNING, spdlog::level::warn}, + {LOG_LEVEL_ERROR, spdlog::level::err}, + {LOG_LEVEL_FATAL, spdlog::level::critical}}; +static std::vector> log_cmds; + +spdlog::level::level_enum g_stderr_start_level; +spdlog::level::level_enum g_file_log_start_level; + +void dsn_log_init(const std::string &log_dir, const std::string &role_name) { - dsn::logging_provider *logger = dsn::logging_provider::instance(); - logger->flush(); -} - -void dsn_log_init(const std::string &logging_factory_name, - const std::string &log_dir, - const std::string &role_name, - const std::function &dsn_log_prefixed_message_func) -{ - log_start_level = enum_from_string(FLAGS_logging_start_level, LOG_LEVEL_INVALID); - - CHECK_NE_MSG( - log_start_level, LOG_LEVEL_INVALID, "invalid [core] logging_start_level specified"); + g_file_logger = spdlog::rotating_logger_mt( + "file", + fmt::format("{}/{}.log", log_dir, role_name.empty() ? FLAGS_base_name : role_name), + FLAGS_max_log_file_bytes, + FLAGS_max_number_of_log_files_on_disk); + // _symlink_path = utils::filesystem::path_combine(_log_dir, symlink_name); + const auto spdlog_start_level = + to_spdlog_levels[enum_from_string(FLAGS_logging_start_level, LOG_LEVEL_INVALID)]; + g_file_log_start_level = spdlog_start_level; + g_file_logger->set_level(spdlog_start_level); + g_stderr_start_level = + to_spdlog_levels[enum_from_string(FLAGS_stderr_start_level, LOG_LEVEL_INVALID)]; + g_file_logger->flush_on(spdlog::level::err); + g_stderr_logger->flush_on(spdlog::level::err); + if (FLAGS_fast_flush) { + spdlog::flush_every(std::chrono::seconds(1)); + } // register log flush on exit if (FLAGS_logging_flush_on_exit) { - ::dsn::tools::sys_exit.put_back(log_on_sys_exit, "log.flush"); + // ::dsn::tools::sys_exit.put_back(log_on_sys_exit, "log.flush"); } - dsn::logging_provider *logger = dsn::utils::factory_store::create( - 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) { - dsn::set_log_prefixed_message_func(dsn_log_prefixed_message_func); + // See: https://github.com/gabime/spdlog/wiki/3.-Custom-formatting#pattern-flags + auto formatter = std::make_unique(); + if (FLAGS_short_header) { + static const std::string kPattern = "%L%Y-%m-%d %H:%M:%S.%e %t %* %v"; + formatter->add_flag('*').set_pattern(kPattern); + } else { + static const std::string kPattern = "%L%Y-%m-%d %H:%M:%S.%e %t %* %s:%#:%!(): %v"; + formatter->add_flag('*').set_pattern(kPattern); } + spdlog::set_formatter(std::move(formatter)); + + // Flush when exit + // ::fflush(_log); + // ::fflush(stderr); + // ::fflush(stdout); + // TODO(yingchun): simple_logger is destroyed after command_manager, so will cause crash like + // "assertion expression: [_handlers.empty()] All commands must be deregistered before + // command_manager is destroyed, however 'flush-log' is still registered". + // We need to fix it. + log_cmds.emplace_back(::dsn::command_manager::instance().register_single_command( + "flush-log", "Flush log to stderr or file", "", [](const std::vector &args) { + // TODO(yingchun): not support now! + return "Flush done."; + })); + + log_cmds.emplace_back(::dsn::command_manager::instance().register_single_command( + "reset-log-start-level", + "Reset the log start level", + "[DEBUG | INFO | WARNING | ERROR | FATAL]", + [](const std::vector &args) { + log_level_t start_level; + if (args.empty()) { + start_level = enum_from_string(FLAGS_logging_start_level, LOG_LEVEL_INVALID); + } else { + std::string level_str = "LOG_LEVEL_" + args[0]; + start_level = enum_from_string(level_str.c_str(), LOG_LEVEL_INVALID); + if (start_level == LOG_LEVEL_INVALID) { + return "ERROR: invalid level '" + args[0] + "'"; + } + } + g_file_logger->set_level(to_spdlog_levels[start_level]); + return std::string("OK, current level is ") + enum_to_string(start_level); + })); } -log_level_t get_log_start_level() { return log_start_level; } - -void set_log_start_level(log_level_t level) { log_start_level = level; } - -void global_log( - const char *file, const char *function, const int line, log_level_t log_level, const char *str) -{ - dsn::logging_provider *logger = dsn::logging_provider::instance(); - logger->log(file, function, line, log_level, str); -} - -namespace dsn { - -std::unique_ptr logging_provider::_logger; - -logging_provider *logging_provider::instance() -{ - static std::unique_ptr default_logger(create_default_instance()); - return _logger ? _logger.get() : default_logger.get(); -} - -logging_provider *logging_provider::create_default_instance() +std::string log_prefixed_message_func() { - return new tools::screen_logger(nullptr, nullptr); -} - -void logging_provider::set_logger(logging_provider *logger) { _logger.reset(logger); } + const static thread_local int tid = dsn::utils::get_current_tid(); + const auto t = dsn::task::get_current_task_id(); + if (t) { + if (nullptr != dsn::task::get_current_worker2()) { + return fmt::format("{}.{}{}.{:016}", + dsn::task::get_current_node_name(), + dsn::task::get_current_worker2()->pool_spec().name, + dsn::task::get_current_worker2()->index(), + t); + } + return fmt::format("{}.io-thrd.{}.{:016}", dsn::task::get_current_node_name(), tid, t); + } -namespace tools { -namespace internal_use_only { -bool register_component_provider(const char *name, - logging_provider::factory f, - ::dsn::provider_type type) -{ - return dsn::utils::factory_store::register_factory(name, f, type); + if (nullptr != dsn::task::get_current_worker2()) { + const static thread_local std::string prefix = + fmt::format("{}.{}{}", + dsn::task::get_current_node_name(), + dsn::task::get_current_worker2()->pool_spec().name, + dsn::task::get_current_worker2()->index()); + return prefix; + } + const static thread_local std::string prefix = + fmt::format("{}.io-thrd.{}", dsn::task::get_current_node_name(), tid); + return prefix; } -} // namespace internal_use_only -} // namespace tools -} // namespace dsn diff --git a/src/utils/logging.h b/src/utils/logging.h new file mode 100644 index 0000000000..7c9a7fc41c --- /dev/null +++ b/src/utils/logging.h @@ -0,0 +1,42 @@ +// Licensed to the Apache Software Foundation (ASF) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The ASF licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +#pragma once + +#include + +#include "spdlog/pattern_formatter.h" + +extern std::string log_prefixed_message_func(); + +class pegasus_formatter_flag : public spdlog::custom_flag_formatter +{ +public: + void + format(const spdlog::details::log_msg &, const std::tm &, spdlog::memory_buf_t &dest) override + { + const auto prefix = log_prefixed_message_func(); + dest.append(prefix.data(), prefix.data() + prefix.size()); + } + + std::unique_ptr clone() const override + { + return spdlog::details::make_unique(); + } +}; + +extern void dsn_log_init(const std::string &log_dir, const std::string &role_name); diff --git a/src/utils/logging_provider.h b/src/utils/logging_provider.h deleted file mode 100644 index ec6bec53d0..0000000000 --- a/src/utils/logging_provider.h +++ /dev/null @@ -1,95 +0,0 @@ -/* - * The MIT License (MIT) - * - * Copyright (c) 2015 Microsoft Corporation - * - * -=- Robust Distributed System Nucleus (rDSN) -=- - * - * Permission is hereby granted, free of charge, to any person obtaining a copy - * of this software and associated documentation files (the "Software"), to deal - * in the Software without restriction, including without limitation the rights - * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell - * copies of the Software, and to permit persons to whom the Software is - * furnished to do so, subject to the following conditions: - * - * The above copyright notice and this permission notice shall be included in - * all copies or substantial portions of the Software. - * - * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR - * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, - * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE - * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER - * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, - * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN - * THE SOFTWARE. - */ - -#pragma once - -#include "utils/api_utilities.h" -#include "utils/command_manager.h" -#include "utils/factory_store.h" - -namespace dsn { - -/*! -@addtogroup tool-api-providers -@{ -*/ -class logging_provider -{ -public: - template - static logging_provider *create(const char *log_dir, const char *role_name) - { - return new T(log_dir, role_name); - } - - typedef logging_provider *(*factory)(const char *, const char *); - -public: - virtual ~logging_provider() = default; - - // singleton - static logging_provider *instance(); - - // not thread-safe - static void set_logger(logging_provider *logger); - - virtual void log(const char *file, - const char *function, - const int line, - log_level_t log_level, - const char *str) = 0; - - virtual void flush() = 0; - - void deregister_commands() { _cmds.clear(); } - -protected: - static std::unique_ptr _logger; - - static logging_provider *create_default_instance(); - - logging_provider(log_level_t stderr_start_level) : _stderr_start_level(stderr_start_level) {} - - std::vector> _cmds; - const log_level_t _stderr_start_level; -}; - -void set_log_prefixed_message_func(std::function func); -extern std::function log_prefixed_message_func; - -namespace tools { -namespace internal_use_only { -bool register_component_provider(const char *name, - logging_provider::factory f, - ::dsn::provider_type type); -} // namespace internal_use_only -} // namespace tools -} // namespace dsn - -extern void dsn_log_init(const std::string &logging_factory_name, - const std::string &log_dir, - const std::string &role_name, - const std::function &dsn_log_prefixed_message_func); diff --git a/src/utils/simple_logger.cpp b/src/utils/simple_logger.cpp deleted file mode 100644 index 6e56cbbca9..0000000000 --- a/src/utils/simple_logger.cpp +++ /dev/null @@ -1,425 +0,0 @@ -/* - * The MIT License (MIT) - * - * Copyright (c) 2015 Microsoft Corporation - * - * -=- Robust Distributed System Nucleus (rDSN) -=- - * - * Permission is hereby granted, free of charge, to any person obtaining a copy - * of this software and associated documentation files (the "Software"), to deal - * in the Software without restriction, including without limitation the rights - * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell - * copies of the Software, and to permit persons to whom the Software is - * furnished to do so, subject to the following conditions: - * - * The above copyright notice and this permission notice shall be included in - * all copies or substantial portions of the Software. - * - * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR - * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, - * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE - * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER - * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, - * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN - * THE SOFTWARE. - */ - -#include "utils/simple_logger.h" - -#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/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, - false, - "Whether to use short header (excluding " - "file, file number and function name " - "fields in each line)"); - -DSN_DEFINE_uint64( - tools.simple_logger, - 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.screen_logger, - stderr_start_level_on_stdout, - "LOG_LEVEL_WARNING", - "The lowest level of log messages to be copied to stderr in addition to stdout"); -DSN_DEFINE_validator(stderr_start_level_on_stdout, [](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, - 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 *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 { -namespace { -int print_header(FILE *fp, log_level_t stderr_start_level, log_level_t log_level) -{ - // The leading character of each log line, corresponding to the log level - // D: Debug - // I: Info - // W: Warning - // E: Error - // F: Fatal - static char s_level_char[] = "DIWEF"; - - uint64_t ts = dsn_now_ns(); - std::string time_str; - dsn::utils::time_ms_to_string(ts / 1000000, time_str); - - int tid = dsn::utils::get_current_tid(); - const auto header = fmt::format( - "{}{} ({} {}) {}", s_level_char[log_level], time_str, ts, tid, log_prefixed_message_func()); - const int written_size = fmt::fprintf(fp, "%s", header.c_str()); - if (log_level >= stderr_start_level) { - fmt::fprintf(stderr, "%s", header.c_str()); - } - return written_size; -} - -int print_long_header(FILE *fp, - const char *file, - const char *function, - const int line, - bool short_header, - log_level_t stderr_start_level, - log_level_t log_level) -{ - if (short_header) { - return 0; - } - - const auto long_header = fmt::format("{}:{}:{}(): ", file, line, function); - const int written_size = fmt::fprintf(fp, "%s", long_header.c_str()); - if (log_level >= stderr_start_level) { - fmt::fprintf(stderr, "%s", long_header.c_str()); - } - return written_size; -} - -int print_body(FILE *fp, const char *body, log_level_t stderr_start_level, log_level_t log_level) -{ - const int written_size = fmt::fprintf(fp, "%s\n", body); - if (log_level >= stderr_start_level) { - fmt::fprintf(stderr, "%s\n", body); - } - return written_size; -} - -inline void process_fatal_log(log_level_t log_level) -{ - if (dsn_likely(log_level < LOG_LEVEL_FATAL)) { - return; - } - - bool coredump = true; - FAIL_POINT_INJECT_NOT_RETURN_F("coredump_for_fatal_log", [&coredump](absl::string_view str) { - CHECK(buf2bool(str, coredump), - "invalid coredump toggle for fatal log, should be true or false: {}", - str); - }); - - if (dsn_likely(coredump)) { - dsn_coredump(); - } -} - -} // anonymous namespace - -screen_logger::screen_logger(const char *, const char *) - : logging_provider(enum_from_string(FLAGS_stderr_start_level_on_stdout, LOG_LEVEL_INVALID)), - _short_header(true) -{ -} - -void screen_logger::print_header(log_level_t log_level) -{ - ::dsn::tools::print_header(stdout, _stderr_start_level, log_level); -} - -void screen_logger::print_long_header(const char *file, - const char *function, - const int line, - log_level_t log_level) -{ - ::dsn::tools::print_long_header( - stdout, file, function, line, _short_header, _stderr_start_level, log_level); -} - -void screen_logger::print_body(const char *body, log_level_t log_level) -{ - ::dsn::tools::print_body(stdout, body, _stderr_start_level, log_level); -} - -void screen_logger::log( - const char *file, const char *function, const int line, log_level_t log_level, const char *str) -{ - utils::auto_lock<::dsn::utils::ex_lock_nr> l(_lock); - - print_header(log_level); - print_long_header(file, function, line, log_level); - print_body(str, log_level); - if (log_level >= LOG_LEVEL_ERROR) { - ::fflush(stdout); - } - - process_fatal_log(log_level); -} - -void screen_logger::flush() { ::fflush(stdout); } - -simple_logger::simple_logger(const char *log_dir, const char *role_name) - : logging_provider(enum_from_string(FLAGS_stderr_start_level, LOG_LEVEL_INVALID)), - _log_dir(std::string(log_dir)), - _log(nullptr), - _file_bytes(0) -{ - // 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(); - - // TODO(yingchun): simple_logger is destroyed after command_manager, so will cause crash like - // "assertion expression: [_handlers.empty()] All commands must be deregistered before - // command_manager is destroyed, however 'flush-log' is still registered". - // We need to fix it. - _cmds.emplace_back(::dsn::command_manager::instance().register_single_command( - "flush-log", - "Flush log to stderr or file", - "", - [this](const std::vector &args) { - this->flush(); - return "Flush done."; - })); - - _cmds.emplace_back(::dsn::command_manager::instance().register_single_command( - "reset-log-start-level", - "Reset the log start level", - "[DEBUG | INFO | WARNING | ERROR | FATAL]", - [](const std::vector &args) { - log_level_t start_level; - if (args.size() == 0) { - start_level = enum_from_string(FLAGS_logging_start_level, LOG_LEVEL_INVALID); - } else { - std::string level_str = "LOG_LEVEL_" + args[0]; - start_level = enum_from_string(level_str.c_str(), LOG_LEVEL_INVALID); - if (start_level == LOG_LEVEL_INVALID) { - return "ERROR: invalid level '" + args[0] + "'"; - } - } - set_log_start_level(start_level); - return std::string("OK, current level is ") + enum_to_string(start_level); - })); -} - -void simple_logger::create_log_file() -{ - // Close the current log file if it is opened. - if (_log != nullptr) { - ::fclose(_log); - _log = nullptr; - } - - // 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)); - } - } -} - -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); -} - -void simple_logger::print_header(log_level_t 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, - const char *function, - const int line, - log_level_t 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) -{ - add_bytes_if_valid(::dsn::tools::print_body(_log, body, _stderr_start_level, log_level)); -} - -void simple_logger::log( - const char *file, const char *function, const int line, log_level_t log_level, const char *str) -{ - utils::auto_lock<::dsn::utils::ex_lock> l(_lock); - - CHECK_NOTNULL(_log, "Log file hasn't been initialized yet"); - print_header(log_level); - print_long_header(file, function, line, log_level); - print_body(str, log_level); - if (FLAGS_fast_flush || log_level >= LOG_LEVEL_ERROR) { - ::fflush(_log); - } - - process_fatal_log(log_level); - - if (_file_bytes >= FLAGS_max_log_file_bytes) { - create_log_file(); - } -} - -} // namespace tools -} // namespace dsn diff --git a/src/utils/simple_logger.h b/src/utils/simple_logger.h deleted file mode 100644 index 5437c0fe6a..0000000000 --- a/src/utils/simple_logger.h +++ /dev/null @@ -1,124 +0,0 @@ -/* - * The MIT License (MIT) - * - * Copyright (c) 2015 Microsoft Corporation - * - * -=- Robust Distributed System Nucleus (rDSN) -=- - * - * Permission is hereby granted, free of charge, to any person obtaining a copy - * of this software and associated documentation files (the "Software"), to deal - * in the Software without restriction, including without limitation the rights - * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell - * copies of the Software, and to permit persons to whom the Software is - * furnished to do so, subject to the following conditions: - * - * The above copyright notice and this permission notice shall be included in - * all copies or substantial portions of the Software. - * - * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR - * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, - * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE - * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER - * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, - * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN - * THE SOFTWARE. - */ - -#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 { -namespace tools { - -/* - * screen_logger provides a logger which writes to terminal. - */ -class screen_logger : public logging_provider -{ -public: - explicit screen_logger(const char *, const char *); - ~screen_logger() override = default; - - void log(const char *file, - const char *function, - const int line, - log_level_t log_level, - const char *str) override; - - virtual void flush(); - -private: - void print_header(log_level_t log_level); - void print_long_header(const char *file, - const char *function, - const int line, - log_level_t log_level); - void print_body(const char *body, log_level_t log_level); - - ::dsn::utils::ex_lock_nr _lock; - const bool _short_header; -}; - -/* - * simple_logger provides a logger which writes to file. - * The max number of lines in a logger file is 200000. - */ -class simple_logger : public logging_provider -{ -public: - // '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, - const char *function, - const int line, - log_level_t log_level, - const char *str) override; - - void flush() override; - -private: - void print_header(log_level_t log_level); - void print_long_header(const char *file, - const char *function, - const int line, - 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; - // The byte size of the current log file. - uint64_t _file_bytes; -}; -} // namespace tools -} // namespace dsn diff --git a/src/utils/test/logger.cpp b/src/utils/test/logger.cpp deleted file mode 100644 index e60e8fe5d4..0000000000 --- a/src/utils/test/logger.cpp +++ /dev/null @@ -1,183 +0,0 @@ -/* - * The MIT License (MIT) - * - * Copyright (c) 2015 Microsoft Corporation - * - * -=- Robust Distributed System Nucleus (rDSN) -=- - * - * Permission is hereby granted, free of charge, to any person obtaining a copy - * of this software and associated documentation files (the "Software"), to deal - * in the Software without restriction, including without limitation the rights - * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell - * copies of the Software, and to permit persons to whom the Software is - * furnished to do so, subject to the following conditions: - * - * The above copyright notice and this permission notice shall be included in - * all copies or substantial portions of the Software. - * - * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR - * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, - * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE - * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER - * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, - * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN - * THE SOFTWARE. - */ - -#include -#include -#include -#include -#include -#include -#include -#include - -#include "gtest/gtest.h" -#include "gutil/map_util.h" -#include "utils/api_utilities.h" -#include "utils/filesystem.h" -#include "utils/flags.h" -#include "utils/logging_provider.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(); - } -}; - -class simple_logger_test : public logger_test -{ -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)); - } - - 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"(SimpleLogger\.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(gutil::InsertIfNotPresent(&file_names, name)); - } - } - } - - 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(); - } - } - - 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(test_dir)) << test_dir; - } - - void remove_test_dir() - { - ASSERT_TRUE(dsn::utils::filesystem::remove_path(test_dir)) << test_dir; - } - -public: - std::string test_dir; -}; - -#define LOG_PRINT(logger, ...) \ - (logger)->log( \ - __FILE__, __FUNCTION__, __LINE__, LOG_LEVEL_DEBUG, fmt::format(__VA_ARGS__).c_str()) - -TEST_F(logger_test, screen_logger_test) -{ - auto logger = std::make_unique(nullptr, nullptr); - 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) { - std::set before_files; - NO_FATALS(get_log_files(before_files)); - - auto logger = std::make_unique(test_dir.c_str(), "SimpleLogger"); - for (unsigned int i = 0; i != 1000; ++i) { - LOG_PRINT(logger.get(), "{}", "test_print"); - } - logger->flush(); - - std::set after_files; - NO_FATALS(get_log_files(after_files)); - NO_FATALS(compare_log_files(before_files, after_files)); - ::usleep(2000); - } - - 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 -} // namespace dsn diff --git a/src/utils/test/logging.cpp b/src/utils/test/logging.cpp index 64eccf29e2..6c640ad44a 100644 --- a/src/utils/test/logging.cpp +++ b/src/utils/test/logging.cpp @@ -33,61 +33,53 @@ #include "utils/fail_point.h" #include "utils/fmt_logging.h" #include "utils/timer.h" +#include "spdlog/common.h" +#include "spdlog/spdlog.h" TEST(LoggingTest, GlobalLog) { - std::cout << "logging start level = " << enum_to_string(get_log_start_level()) << std::endl; - global_log(__FILENAME__, __FUNCTION__, __LINE__, LOG_LEVEL_INFO, "in TEST(core, logging)"); + std::cout << "logging start level = " << spdlog::level::to_short_c_str(g_file_log_start_level) + << std::endl; + LOG(spdlog::level::info, "in TEST(LoggingTest, GlobalLog)"); } TEST(LoggingTest, GlobalLogBig) { std::string big_str(128000, 'x'); - global_log(__FILENAME__, __FUNCTION__, __LINE__, LOG_LEVEL_INFO, big_str.c_str()); + LOG(spdlog::level::info, big_str.c_str()); } TEST(LoggingTest, LogMacro) { - struct test_case - { - log_level_t level; - std::string str; - } tests[] = {{LOG_LEVEL_DEBUG, "This is a test"}, - {LOG_LEVEL_DEBUG, "\\x00%d\\x00\\x01%n/nm"}, - {LOG_LEVEL_INFO, "\\x00%d\\x00\\x01%n/nm"}, - {LOG_LEVEL_WARNING, "\\x00%d\\x00\\x01%n/nm"}, - {LOG_LEVEL_ERROR, "\\x00%d\\x00\\x01%n/nm"}, - {LOG_LEVEL_FATAL, "\\x00%d\\x00\\x01%n/nm"}}; - - dsn::fail::setup(); - dsn::fail::cfg("coredump_for_fatal_log", "void(false)"); - - for (auto test : tests) { - // Test logging_provider::log. - LOG(test.level, "LOG: sortkey = {}", test.str); - } + std::string str1 = "This is a test"; + std::string str2 = "\\x00%d\\x00\\x01%n/nm"; - dsn::fail::teardown(); + LOG_DEBUG("LOG: sortkey = {}", str1); + LOG_DEBUG("LOG: sortkey = {}", str2); + LOG_INFO("LOG: sortkey = {}", str2); + LOG_WARNING("LOG: sortkey = {}", str2); + LOG_ERROR("LOG: sortkey = {}", str2); + ASSERT_DEATH(LOG_FATAL("LOG: sortkey = {}", str2), "LOG: sortkey ="); } TEST(LoggingTest, TestLogTiming) { - LOG_TIMING_PREFIX_IF(INFO, true, "prefix", "foo test{}", 0) {} - LOG_TIMING_IF(INFO, true, "no_prefix foo test{}", 1) {} - LOG_TIMING_PREFIX(INFO, "prefix", "foo test{}", 2) {} - LOG_TIMING(INFO, "foo test{}", 3){} + LOG_TIMING_PREFIX_IF(info, true, "prefix", "foo test{}", 0) {} + LOG_TIMING_IF(info, true, "no_prefix foo test{}", 1) {} + LOG_TIMING_PREFIX(info, "prefix", "foo test{}", 2) {} + LOG_TIMING(info, "foo test{}", 3){} { - SCOPED_LOG_TIMING(INFO, "bar {}", 0); - SCOPED_LOG_SLOW_EXECUTION(INFO, 1, "bar {}", 1); - SCOPED_LOG_SLOW_EXECUTION_PREFIX(INFO, 1, "prefix", "bar {}", 1); + SCOPED_LOG_TIMING(info, "bar {}", 0); + SCOPED_LOG_SLOW_EXECUTION(info, 1, "bar {}", 1); + SCOPED_LOG_SLOW_EXECUTION_PREFIX(info, 1, "prefix", "bar {}", 1); } - LOG_SLOW_EXECUTION(INFO, 1, "baz {}", 0) {} + LOG_SLOW_EXECUTION(info, 1, "baz {}", 0) {} // Previous implementations of the above macro confused clang-tidy's use-after-move // check and generated false positives. std::string s1 = "hello"; std::string s2; - LOG_SLOW_EXECUTION(INFO, 1, "baz") + LOG_SLOW_EXECUTION(info, 1, "baz") { LOG_INFO(s1); s2 = std::move(s1); diff --git a/src/utils/test/main.cpp b/src/utils/test/main.cpp index 0bdfb7f7a5..521d5fa7f2 100644 --- a/src/utils/test/main.cpp +++ b/src/utils/test/main.cpp @@ -19,13 +19,13 @@ #include #include "utils/flags.h" -#include "utils/logging_provider.h" +#include "utils/logging.h" GTEST_API_ int main(int argc, char **argv) { testing::InitGoogleTest(&argc, argv); - dsn_log_init("dsn::tools::simple_logger", "./", "test", nullptr); + dsn_log_init("./", "test"); dsn::flags_initialize(); diff --git a/src/utils/timer.h b/src/utils/timer.h index ee5113ac73..0a79d79d3c 100644 --- a/src/utils/timer.h +++ b/src/utils/timer.h @@ -22,12 +22,14 @@ #include "utils/api_utilities.h" #include "utils/chrono_literals.h" #include "utils/fmt_logging.h" +#include "spdlog/common.h" +#include "spdlog/spdlog.h" /// These macros are inspired by Apache Kudu /// https://github.com/apache/kudu/blob/1.17.0/src/kudu/util/stopwatch.h. // Macro for logging timing of a block. Usage: -// LOG_TIMING_PREFIX_IF(INFO, FLAGS_should_record_time, "Tablet X: ", "doing some task") { +// LOG_TIMING_PREFIX_IF(info, FLAGS_should_record_time, "Tablet X: ", "doing some task") { // ... some task which takes some time // } // If FLAGS_should_record_time is true, yields a log like: @@ -39,7 +41,7 @@ for (dsn::timer_internal::LogTiming _l(__FILENAME__, \ __FUNCTION__, \ __LINE__, \ - LOG_LEVEL_##severity, \ + spdlog::level::severity, \ prefix, \ fmt::format(__VA_ARGS__), \ -1, \ @@ -63,7 +65,7 @@ dsn::timer_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILENAME__, \ __FUNCTION__, \ __LINE__, \ - LOG_LEVEL_##severity, \ + spdlog::level::severity, \ "", \ fmt::format(__VA_ARGS__), \ -1, \ @@ -74,7 +76,7 @@ dsn::timer_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILENAME__, \ __FUNCTION__, \ __LINE__, \ - LOG_LEVEL_##severity, \ + spdlog::level::severity, \ "", \ fmt::format(__VA_ARGS__), \ max_expected_millis, \ @@ -85,14 +87,14 @@ dsn::timer_internal::LogTiming VARNAME_LINENUM(_log_timing)(__FILENAME__, \ __FUNCTION__, \ __LINE__, \ - LOG_LEVEL_##severity, \ + spdlog::level::severity, \ prefix, \ fmt::format(__VA_ARGS__), \ max_expected_millis, \ true) // Macro for logging timing of a block. Usage: -// LOG_SLOW_EXECUTION(INFO, 5, "doing some task") { +// LOG_SLOW_EXECUTION(info, 5, "doing some task") { // ... some task which takes some time // } // when slower than 5 milliseconds, yields a log like: @@ -102,7 +104,7 @@ for (dsn::timer_internal::LogTiming _l(__FILENAME__, \ __FUNCTION__, \ __LINE__, \ - LOG_LEVEL_##severity, \ + spdlog::level::severity, \ "", \ fmt::format(__VA_ARGS__), \ max_expected_millis, \ @@ -158,7 +160,7 @@ class LogTiming LogTiming(const char *file, const char *function, int line, - log_level_t severity, + spdlog::level::level_enum severity, std::string prefix, std::string description, int64_t max_expected_millis, @@ -196,7 +198,7 @@ class LogTiming const char *file_; const char *function_; const int line_; - const log_level_t severity_; + const spdlog::level::level_enum severity_; const std::string prefix_; const std::string description_; const int64_t max_expected_millis_; @@ -210,15 +212,14 @@ class LogTiming stopwatch_.stop(); auto ms = stopwatch_.m_elapsed(); if (max_expected_millis < 0 || ms.count() > max_expected_millis) { - global_log(file_, - function_, - line_, - severity_, - fmt::format("{}ime spent {}: {}ms", - prefix_.empty() ? "T" : fmt::format("{} t", prefix_), - description_, - ms.count()) - .c_str()); + spdlog::log(severity_, + "{}:{}:{}() {}ime spent {}: {}ms", + file_, + line_, + function_, + prefix_.empty() ? "T" : fmt::format("{} t", prefix_), + description_, + ms.count()); } } };