feat(logging): Introduce spdlog and remove simple_logger and screen_l…

…ogger

.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'

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)
 

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<uintptr_t, std::string> &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<uintptr_t, std::string> &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()) {

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<app_state>
     } 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.

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);

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;

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);

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;

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;
     }
 }
 

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 "")

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, ...)                                                            \

src/utils/fmt_logging.h

@@ -19,28 +19,51 @@
 
 #pragma once
 
+#include <memory>
 #include <fmt/ostream.h>
 #include <rocksdb/status.h>
 
 #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<spdlog::logger> g_stderr_logger;
+extern std::shared_ptr<spdlog::logger> 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 {                                                                                           \