From 41bb8a2aec76b50c25f216ce09864e66582adec5 Mon Sep 17 00:00:00 2001 From: Yingchun Lai Date: Thu, 23 May 2024 17:54:02 +0800 Subject: [PATCH] refactor(logging): Minor refactor on logging module --- src/runtime/service_api_c.cpp | 111 ++++++++++++++-------------- src/utils/simple_logger.cpp | 131 ++++++++++++++++++++++++---------- src/utils/simple_logger.h | 19 ++++- 3 files changed, 165 insertions(+), 96 deletions(-) diff --git a/src/runtime/service_api_c.cpp b/src/runtime/service_api_c.cpp index 44fbd7096b..5d2918f550 100644 --- a/src/runtime/service_api_c.cpp +++ b/src/runtime/service_api_c.cpp @@ -44,6 +44,7 @@ #include #endif +#include "fmt/core.h" #include "perf_counter/perf_counters.h" #include "runtime/api_layer1.h" #include "runtime/api_task.h" @@ -53,8 +54,6 @@ #include "runtime/rpc/rpc_engine.h" #include "runtime/rpc/rpc_host_port.h" #include "runtime/rpc/rpc_message.h" -#include "security/init.h" -#include "security/negotiation_manager.h" #include "runtime/service_app.h" #include "runtime/service_engine.h" #include "runtime/task/task.h" @@ -63,6 +62,8 @@ #include "runtime/task/task_spec.h" #include "runtime/task/task_worker.h" #include "runtime/tool_api.h" +#include "security/init.h" +#include "security/negotiation_manager.h" #include "utils/api_utilities.h" #include "utils/command_manager.h" #include "utils/config_api.h" @@ -75,6 +76,7 @@ #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" @@ -342,45 +344,29 @@ inline void dsn_global_init() static std::string dsn_log_prefixed_message_func() { - std::string res; - res.resize(100); - char *prefixed_message = const_cast(res.c_str()); - - int tid = dsn::utils::get_current_tid(); - auto t = dsn::task::get_current_task_id(); + 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()) { - sprintf(prefixed_message, - "%6s.%7s%d.%016" PRIx64 ": ", - dsn::task::get_current_node_name(), - dsn::task::get_current_worker2()->pool_spec().name.c_str(), - dsn::task::get_current_worker2()->index(), - t); + 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 { - sprintf(prefixed_message, - "%6s.%7s.%05d.%016" PRIx64 ": ", - dsn::task::get_current_node_name(), - "io-thrd", - tid, - t); + return fmt::format( + "{}.io-thrd.{}.{:016}: ", dsn::task::get_current_node_name(), tid, t); } } else { if (nullptr != dsn::task::get_current_worker2()) { - sprintf(prefixed_message, - "%6s.%7s%u: ", - dsn::task::get_current_node_name(), - dsn::task::get_current_worker2()->pool_spec().name.c_str(), - dsn::task::get_current_worker2()->index()); + return fmt::format("{}.{}{}: ", + dsn::task::get_current_node_name(), + dsn::task::get_current_worker2()->pool_spec().name, + dsn::task::get_current_worker2()->index()); } else { - sprintf(prefixed_message, - "%6s.%7s.%05d: ", - dsn::task::get_current_node_name(), - "io-thrd", - tid); + return fmt::format("{}.io-thrd.{}: ", dsn::task::get_current_node_name(), tid); } } - - return res; } bool run(const char *config_file, @@ -447,14 +433,14 @@ bool run(const char *config_file, spec.dir_log = ::dsn::utils::filesystem::path_combine(cdir, "log"); dsn::utils::filesystem::create_directory(spec.dir_log); - // 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; } @@ -465,7 +451,7 @@ bool run(const char *config_file, // init logging dsn_log_init(spec.logging_factory_name, spec.dir_log, 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 +459,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 +493,37 @@ 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) + // Extract app_names. + std::list app_names_and_indexes; + ::dsn::utils::split_args(app_list.c_str(), app_names_and_indexes, ';'); + 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 = 0; + const auto index_str = name_and_index.back(); + CHECK(dsn::buf2int32(index_str, index), + "'{}' is not a valid index", + index_str); + create_it = (index == sp.index); + } break; } } @@ -540,10 +534,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/simple_logger.cpp b/src/utils/simple_logger.cpp index d54e03025f..0234cee6f8 100644 --- a/src/utils/simple_logger.cpp +++ b/src/utils/simple_logger.cpp @@ -28,10 +28,11 @@ // IWYU pragma: no_include #include -#include +#include +#include #include #include -#include +#include #include #include "absl/strings/string_view.h" @@ -44,7 +45,6 @@ #include "utils/ports.h" #include "utils/process_utils.h" #include "utils/string_conv.h" -#include "utils/strings.h" #include "utils/time_utils.h" DSN_DEFINE_bool(tools.simple_logger, fast_flush, false, "Whether to flush logs immediately"); @@ -60,23 +60,27 @@ 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_DECLARE_string(logging_start_level); namespace dsn { namespace tools { -static void print_header(FILE *fp, log_level_t log_level) +namespace { +int print_header(FILE *fp, log_level_t stderr_start_level, 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 @@ -89,16 +93,43 @@ static void print_header(FILE *fp, log_level_t log_level) dsn::utils::time_ms_to_string(ts / 1000000, time_str); int tid = dsn::utils::get_current_tid(); - fmt::print(fp, - "{}{} ({} {}) {}", - s_level_char[log_level], - time_str, - ts, - tid, - log_prefixed_message_func().c_str()); + 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; } -namespace { +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) { @@ -122,19 +153,33 @@ inline void process_fatal_log(log_level_t log_level) screen_logger::screen_logger(bool short_header) : _short_header(short_header) {} -screen_logger::~screen_logger(void) {} +void screen_logger::print_header(log_level_t log_level) +{ + ::dsn::tools::print_header(stdout, LOG_LEVEL_COUNT, 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, LOG_LEVEL_COUNT, log_level); +} + +void screen_logger::print_body(const char *body, log_level_t log_level) +{ + ::dsn::tools::print_body(stdout, body, LOG_LEVEL_COUNT, 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(stdout, log_level); - if (!_short_header) { - printf("%s:%d:%s(): ", file, line, function); - } - printf("%s\n", str); - + 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); } @@ -222,8 +267,10 @@ 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; @@ -246,41 +293,53 @@ void simple_logger::create_log_file() } } -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); } +void simple_logger::print_header(log_level_t log_level) +{ + ::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) +{ + ::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); +} + 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); - print_header(_log, log_level); - if (!FLAGS_short_header) { - fprintf(_log, "%s:%d:%s(): ", file, line, function); - } - fprintf(_log, "%s\n", str); + 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); } - if (log_level >= _stderr_start_level) { - print_header(stdout, log_level); - if (!FLAGS_short_header) { - printf("%s:%d:%s(): ", file, line, function); - } - printf("%s\n", str); - } - process_fatal_log(log_level); if (++_lines >= 200000) { diff --git a/src/utils/simple_logger.h b/src/utils/simple_logger.h index e9657a8018..7da3241391 100644 --- a/src/utils/simple_logger.h +++ b/src/utils/simple_logger.h @@ -43,7 +43,7 @@ class screen_logger : public logging_provider { public: explicit screen_logger(bool short_header); - ~screen_logger() override; + ~screen_logger() override = default; void log(const char *file, const char *function, @@ -54,6 +54,13 @@ class screen_logger : public logging_provider virtual void flush(); private: + static 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); + static void print_body(const char *body, log_level_t log_level); + ::dsn::utils::ex_lock_nr _lock; const bool _short_header; }; @@ -77,17 +84,25 @@ class simple_logger : public logging_provider 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); + void create_log_file(); 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; FILE *_log; int _start_index; int _index; int _lines; - log_level_t _stderr_start_level; + const log_level_t _stderr_start_level; }; } // namespace tools } // namespace dsn