diff --git a/CMakeLists.txt b/CMakeLists.txt index 9c30658c..0248745d 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -218,7 +218,8 @@ set(SPDLOG_HEADERS "include/spdlog/sinks/systemd_sink.h" "include/spdlog/sinks/tcp_sink.h" "include/spdlog/sinks/udp_sink.h" - ) + "include/spdlog/mdc.h" +) set(SPDLOG_SRCS "src/async_logger.cpp" diff --git a/README.md b/README.md index c8553d62..96098993 100644 --- a/README.md +++ b/README.md @@ -138,23 +138,6 @@ void daily_example() ``` ---- -#### Backtrace support -```c++ -// Debug messages can be stored in a ring buffer instead of being logged immediately. -// This is useful to display debug logs only when needed (e.g. when an error happens). -// When needed, call dump_backtrace() to dump them to your log. - -spdlog::enable_backtrace(32); // Store the latest 32 messages in a buffer. -// or my_logger->enable_backtrace(32).. -for(int i = 0; i < 100; i++) -{ - spdlog::debug("Backtrace message {}", i); // not logged yet.. -} -// e.g. if some error happened: -spdlog::dump_backtrace(); // log them now! show the last 32 messages -// or my_logger->dump_backtrace(32).. -``` --- #### Periodic flush @@ -207,6 +190,22 @@ void binary_example() ``` +--- +#### Mapped diagnostic context (MDC) +MDC is a map of contextual information that can be used to enrich log messages. +It is a map of key-value pairs that can be set on a per-thread basis since it is stored in thread-local storage. +```c++ +#include "spdlog/spdlog.h" +#include "spdlog/mdc" +{ + spdlog::mdc::put("key1", "value1"); + spdlog::mdc::put("key2", "value2"); + // use the %& formatter flag to print all MDC values + spdlog::set_pattern("[%H:%M:%S %z] [%^%L%$] [%&] %v"); + spdlog::info("Some log message with context"); +} +``` + --- #### Logger with multi sinks - each with a different format and log level ```c++ diff --git a/example/example.cpp b/example/example.cpp index 41843967..04212612 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -26,7 +26,7 @@ void udp_example(); void custom_flags_example(); void file_events_example(); void replace_default_logger_example(); - +void mdc_example(); // Uncomment to enable source location support. // This will add filename/line/column info to the log (and in to the resulting binary so take care). // #define SPDLOG_SOURCE_LOCATION @@ -75,6 +75,7 @@ int main(int, char *[]) { custom_flags_example(); file_events_example(); replace_default_logger_example(); + mdc_example(); // Flush all *registered* loggers using a worker thread every 3 seconds. // note: registered loggers *must* be thread safe for this to work correctly! @@ -350,3 +351,13 @@ void replace_default_logger_example() { spdlog::set_default_logger(old_logger); } + +#include "spdlog/mdc.h" +void mdc_example() +{ + spdlog::mdc::put("key1", "value1"); + spdlog::mdc::put("key2", "value2"); + // use the %& formatter flag to print all MDC values + spdlog::set_pattern("[%H:%M:%S %z] [%^%L%$] [%&] %v"); + spdlog::info("Some log message with context"); +} diff --git a/src/pattern_formatter.cpp b/src/pattern_formatter.cpp index e7c05f0d..42625c35 100644 --- a/src/pattern_formatter.cpp +++ b/src/pattern_formatter.cpp @@ -7,7 +7,6 @@ #include #include #include -#include #include #include #include @@ -17,6 +16,7 @@ #include "spdlog/details/fmt_helper.h" #include "spdlog/details/log_msg.h" #include "spdlog/details/os.h" +#include #include "spdlog/fmt/fmt.h" #include "spdlog/formatter.h" @@ -811,7 +811,6 @@ public: dest.push_back(']'); dest.push_back(' '); } - // fmt_helper::append_string_view(msg.msg(), dest); fmt_helper::append_string_view(msg.payload, dest); } @@ -820,6 +819,44 @@ private: memory_buf_t cached_datetime_; }; +// Class for formatting Mapped Diagnostic Context (MDC) in log messages. +// Example: [logger-name] [info] [mdc_key_1:mdc_value_1 mdc_key_2:mdc_value_2] some message +template +class mdc_formatter : public flag_formatter { +public: + explicit mdc_formatter(padding_info padinfo) + : flag_formatter(padinfo) {} + + void format(const details::log_msg &, const std::tm &, memory_buf_t &dest) override { + auto mdc_map = mdc::get_context(); + if (mdc_map.empty()) { + ScopedPadder p(0, padinfo_, dest); + return; + } else { + auto last_element = --mdc_map.end(); + for (auto it = mdc_map.begin(); it != mdc_map.end(); ++it) { + auto &pair = *it; + const auto &key = pair.first; + const auto &value = pair.second; + size_t content_size = key.size() + value.size() + 1; // 1 for ':' + + if (it != last_element) { + content_size++; // 1 for ' ' + } + + ScopedPadder p(content_size, padinfo_, dest); + fmt_helper::append_string_view(key, dest); + fmt_helper::append_string_view(":", dest); + fmt_helper::append_string_view(value, dest); + if (it != last_element) { + fmt_helper::append_string_view(" ", dest); + } + } + } + } +}; + + } // namespace details pattern_formatter::pattern_formatter(std::string pattern, @@ -1096,6 +1133,10 @@ void pattern_formatter::handle_flag_(char flag, details::padding_info padding) { formatters_.push_back(std::make_unique>(padding)); break; + case ('&'): + formatters_.push_back(std::make_unique>(padding)); + break; + default: // Unknown flag appears as is auto unknown_flag = std::make_unique(); diff --git a/tests/test_pattern_formatter.cpp b/tests/test_pattern_formatter.cpp index 1da38ed3..fa475380 100644 --- a/tests/test_pattern_formatter.cpp +++ b/tests/test_pattern_formatter.cpp @@ -1,6 +1,7 @@ #include "includes.h" #include "spdlog/sinks/ostream_sink.h" #include "test_sink.h" +#include "spdlog/mdc.h" using spdlog::memory_buf_t; using spdlog::details::to_string_view; @@ -456,3 +457,132 @@ TEST_CASE("override need_localtime", "[pattern_formatter]") { REQUIRE(to_string_view(formatted) == oss.str()); } } + +// Test Mapped Diagnostic Context (mdc) +TEST_CASE("mdc formatter test-1", "[pattern_formatter]") { + spdlog::mdc::put("mdc_key_1", "mdc_value_1"); + spdlog::mdc::put("mdc_key_2", "mdc_value_2"); + + auto formatter = std::make_shared(); + formatter->set_pattern("[%n] [%l] [%&] %v"); + + memory_buf_t formatted; + spdlog::details::log_msg msg(spdlog::source_loc{}, "logger-name", spdlog::level::info, + "some message"); + formatter->format(msg, formatted); + + auto expected = spdlog::fmt_lib::format( + "[logger-name] [info] [mdc_key_1:mdc_value_1 mdc_key_2:mdc_value_2] some message{}", + spdlog::details::os::default_eol); + REQUIRE(to_string_view(formatted) == expected); + + SECTION("Tear down") { spdlog::mdc::clear(); } +} + +TEST_CASE("mdc formatter value update", "[pattern_formatter]") { + spdlog::mdc::put("mdc_key_1", "mdc_value_1"); + spdlog::mdc::put("mdc_key_2", "mdc_value_2"); + + auto formatter = std::make_shared(); + formatter->set_pattern("[%n] [%l] [%&] %v"); + + memory_buf_t formatted_1; + spdlog::details::log_msg msg(spdlog::source_loc{}, "logger-name", spdlog::level::info, + "some message"); + formatter->format(msg, formatted_1); + + auto expected = spdlog::fmt_lib::format( + "[logger-name] [info] [mdc_key_1:mdc_value_1 mdc_key_2:mdc_value_2] some message{}", + spdlog::details::os::default_eol); + + REQUIRE(to_string_view(formatted_1) == expected); + + spdlog::mdc::put("mdc_key_1", "new_mdc_value_1"); + memory_buf_t formatted_2; + formatter->format(msg, formatted_2); + expected = spdlog::fmt_lib::format( + "[logger-name] [info] [mdc_key_1:new_mdc_value_1 mdc_key_2:mdc_value_2] some message{}", + spdlog::details::os::default_eol); + + REQUIRE(to_string_view(formatted_2) == expected); + + SECTION("Tear down") { spdlog::mdc::clear(); } +} + +TEST_CASE("mdc different threads", "[pattern_formatter]") { + auto formatter = std::make_shared(); + formatter->set_pattern("[%n] [%l] [%&] %v"); + spdlog::details::log_msg msg(spdlog::source_loc{}, "logger-name", spdlog::level::info, + "some message"); + + memory_buf_t formatted_2; + + auto lambda_1 = [formatter, msg]() { + spdlog::mdc::put("mdc_key", "thread_1_id"); + memory_buf_t formatted; + formatter->format(msg, formatted); + + auto expected = + spdlog::fmt_lib::format("[logger-name] [info] [mdc_key:thread_1_id] some message{}", + spdlog::details::os::default_eol); + + REQUIRE(to_string_view(formatted) == expected); + }; + + auto lambda_2 = [formatter, msg]() { + spdlog::mdc::put("mdc_key", "thread_2_id"); + memory_buf_t formatted; + formatter->format(msg, formatted); + + auto expected = + spdlog::fmt_lib::format("[logger-name] [info] [mdc_key:thread_2_id] some message{}", + spdlog::details::os::default_eol); + + REQUIRE(to_string_view(formatted) == expected); + }; + + std::thread thread_1(lambda_1); + std::thread thread_2(lambda_2); + + thread_1.join(); + thread_2.join(); + + SECTION("Tear down") { spdlog::mdc::clear(); } +} + +TEST_CASE("mdc remove key", "[pattern_formatter]") { + spdlog::mdc::put("mdc_key_1", "mdc_value_1"); + spdlog::mdc::put("mdc_key_2", "mdc_value_2"); + spdlog::mdc::remove("mdc_key_1"); + + auto formatter = std::make_shared(); + formatter->set_pattern("[%n] [%l] [%&] %v"); + + memory_buf_t formatted; + spdlog::details::log_msg msg(spdlog::source_loc{}, "logger-name", spdlog::level::info, + "some message"); + formatter->format(msg, formatted); + + auto expected = + spdlog::fmt_lib::format("[logger-name] [info] [mdc_key_2:mdc_value_2] some message{}", + spdlog::details::os::default_eol); + REQUIRE(to_string_view(formatted) == expected); + + SECTION("Tear down") { spdlog::mdc::clear(); } +} + +TEST_CASE("mdc empty", "[pattern_formatter]") { + auto formatter = std::make_shared(); + formatter->set_pattern("[%n] [%l] [%&] %v"); + + memory_buf_t formatted; + spdlog::details::log_msg msg(spdlog::source_loc{}, "logger-name", spdlog::level::info, + "some message"); + formatter->format(msg, formatted); + + auto expected = spdlog::fmt_lib::format("[logger-name] [info] [] some message{}", + spdlog::details::os::default_eol); + REQUIRE(to_string_view(formatted) == expected); + + SECTION("Tear down") { spdlog::mdc::clear(); } +}