diff --git a/CMakeLists.txt b/CMakeLists.txt index 6bb6abb15..66faa2358 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -146,7 +146,8 @@ set(SPDLOG_HEADERS "include/spdlog/sinks/systemd_sink.h" "include/spdlog/sinks/tcp_sink.h" "include/spdlog/sinks/udp_sink.h" - "include/spdlog/sinks/async_sink.h") + "include/spdlog/sinks/async_sink.h" + "include/spdlog/attributes.h") set(SPDLOG_SRCS "src/common.cpp" "src/logger.cpp" diff --git a/include/spdlog/attributes.h b/include/spdlog/attributes.h new file mode 100644 index 000000000..33a65c871 --- /dev/null +++ b/include/spdlog/attributes.h @@ -0,0 +1,102 @@ +#pragma once + +#include + +#include +#include + + +namespace spdlog { + +class SPDLOG_API log_attributes { +public: + using attr_map_t = std::map; + using key_t = attr_map_t::key_type; + using value_t = attr_map_t::mapped_type; + using const_iter = attr_map_t::const_iterator; + + class SPDLOG_API log_attr_context { + public: + log_attr_context(log_attributes& parent, attr_map_t const& attrs) + : parent_(parent), + tmp_attrs_{attrs} { + parent_.put(attrs); + } + explicit log_attr_context(log_attributes& parent) + : log_attr_context(parent, {}) {} + + ~log_attr_context() { + for (auto&& key_value : tmp_attrs_) parent_.remove(key_value.first); + } + + private: + log_attributes& parent_; + attr_map_t tmp_attrs_; + }; + + log_attributes() = default; + log_attributes(const log_attributes& other) { put(other.get_map()); } + log_attributes& operator=(const log_attributes& other) { + if (this != &other) { + clear(); + put(other.get_map()); + } + return *this; + } + + void put(attr_map_t const& attributes) { + auto lck = lock(); + for (auto const& attribute : attributes) attrs.insert_or_assign(attribute.first, attribute.second); + } + void put(const key_t& key, const value_t& value) { put({{key, value}}); } + + void remove(const key_t& key) { + auto lck = lock(); + auto value_it = attrs.find(key); + if (value_it != attrs.end()) { + attrs.erase(key); + } + } + + void clear() { + auto lck = lock(); + attrs.clear(); + } + + bool empty() const { + auto lck = lock(); + return attrs.empty(); + } + + // return {true, iter} if found, {false, end} otherwise + std::pair const get(key_t const& key) const { + auto lck = lock(); + auto value_it = attrs.find(key); + + return std::make_pair(value_it != attrs.end(), value_it); + } + + // provide a local copy of the attributes to be free of race issues + // alternative is to lock the attr_map while the formatter iterates over it + attr_map_t get_map() const { + auto lck = lock(); + return attrs; + } + + // RAII-wrapper that inserts a couple of attributes and removes them upon destruction + log_attr_context scoped_ctx(attr_map_t const& attributes) { return log_attr_context(*this, attributes); } + log_attr_context scoped_ctx(key_t key, value_t value) { return log_attr_context(*this, {{key, value}}); } + + bool empty() { + auto lck = lock(); + return attrs.empty(); + } + +private: + std::lock_guard lock() const { return std::lock_guard(attrs_mtx); } + + mutable std::mutex attrs_mtx; + attr_map_t attrs; +}; + +} // namespace spdlog \ No newline at end of file diff --git a/include/spdlog/details/log_msg.h b/include/spdlog/details/log_msg.h index 1badf9e8d..e575597de 100644 --- a/include/spdlog/details/log_msg.h +++ b/include/spdlog/details/log_msg.h @@ -5,14 +5,23 @@ #include +#include "../attributes.h" #include "../common.h" namespace spdlog { namespace details { struct SPDLOG_API log_msg { log_msg() = default; + log_msg(log_clock::time_point log_time, + const source_loc &loc, + string_view_t logger_name, + level lvl, + string_view_t msg, + log_attributes attributes); log_msg(log_clock::time_point log_time, const source_loc &loc, string_view_t logger_name, level lvl, string_view_t msg); log_msg(const source_loc &loc, string_view_t logger_name, level lvl, string_view_t msg); + log_msg(const source_loc &loc, string_view_t logger_name, level lvl, string_view_t msg, log_attributes attributes); + log_msg(string_view_t logger_name, level lvl, string_view_t msg, log_attributes attributes); log_msg(string_view_t logger_name, level lvl, string_view_t msg); log_msg(const log_msg &other) = default; log_msg &operator=(const log_msg &other) = default; @@ -28,6 +37,7 @@ struct SPDLOG_API log_msg { source_loc source; string_view_t payload; + log_attributes attributes; }; } // namespace details } // namespace spdlog diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index dbd932fa8..2df3032d8 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -19,6 +19,7 @@ #include "details/err_helper.h" #include "details/log_msg.h" #include "sinks/sink.h" +#include "attributes.h" namespace spdlog { @@ -63,20 +64,20 @@ class SPDLOG_API logger { // log with no format string, just string message void log(const source_loc &loc, level lvl, string_view_t msg) noexcept { if (should_log(lvl)) { - sink_it_(details::log_msg(loc, name_, lvl, msg)); + sink_it_(details::log_msg(loc, name_, lvl, msg, attributes)); } } void log(level lvl, string_view_t msg) noexcept { if (should_log(lvl)) { - sink_it_(details::log_msg(source_loc{}, name_, lvl, msg)); + sink_it_(details::log_msg(source_loc{}, name_, lvl, msg, attributes)); } } // support for custom time void log(log_clock::time_point log_time, const source_loc &loc, level lvl, string_view_t msg) noexcept { if (should_log(lvl)) { - sink_it_(details::log_msg(log_time, loc, name_, lvl, msg)); + sink_it_(details::log_msg(log_time, loc, name_, lvl, msg, attributes)); } } @@ -160,9 +161,12 @@ class SPDLOG_API logger { // create new logger with same sinks and configuration. std::shared_ptr clone(std::string logger_name); + log_attributes &attrs(); + private: std::string name_; std::vector sinks_; + log_attributes attributes; atomic_level_t level_{level::info}; atomic_level_t flush_level_{level::off}; details::err_helper err_helper_; @@ -178,7 +182,7 @@ class SPDLOG_API logger { try { memory_buf_t buf; fmt::vformat_to(std::back_inserter(buf), format_string, fmt::make_format_args(args...)); - sink_it_(details::log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size()))); + sink_it_(details::log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size()), attributes)); } catch (const std::exception &ex) { err_helper_.handle_ex(name_, loc, ex); } catch (...) { diff --git a/src/details/log_msg.cpp b/src/details/log_msg.cpp index 80f4b0a6d..d2231aa7e 100644 --- a/src/details/log_msg.cpp +++ b/src/details/log_msg.cpp @@ -8,6 +8,25 @@ namespace spdlog { namespace details { +log_msg::log_msg(const log_clock::time_point log_time, + const source_loc &loc, + const string_view_t logger_name, + const level lvl, + const string_view_t msg, + const log_attributes attributes) + : logger_name(logger_name), + log_level(lvl), + time(log_time), +#ifdef SPDLOG_NO_THREAD_ID + thread_id(0), +#else + thread_id(os::thread_id()), +#endif + source(loc), + payload(msg), + attributes(attributes) { +} + log_msg::log_msg(const log_clock::time_point log_time, const source_loc &loc, const string_view_t logger_name, @@ -26,10 +45,16 @@ log_msg::log_msg(const log_clock::time_point log_time, } log_msg::log_msg(const source_loc &loc, const string_view_t logger_name, const level lvl, const string_view_t msg) - : log_msg(os::now(), loc, logger_name, lvl, msg) {} + : log_msg(os::now(), loc, logger_name, lvl, msg, {}) {} + +log_msg::log_msg(const source_loc &loc, string_view_t logger_name, level lvl, string_view_t msg, log_attributes attributes) + : log_msg(os::now(), loc, logger_name, lvl, msg, attributes) {} log_msg::log_msg(const string_view_t logger_name, const level lvl, const string_view_t msg) : log_msg(os::now(), source_loc{}, logger_name, lvl, msg) {} +log_msg::log_msg(const string_view_t logger_name, const level lvl, const string_view_t msg, const log_attributes attributes) + : log_msg(os::now(), source_loc{}, logger_name, lvl, msg, attributes) {} + } // namespace details } // namespace spdlog diff --git a/src/logger.cpp b/src/logger.cpp index dc480bae2..258c8700f 100644 --- a/src/logger.cpp +++ b/src/logger.cpp @@ -81,4 +81,7 @@ void logger::flush_() noexcept { } } } + +log_attributes &logger::attrs() { return attributes; } + } // namespace spdlog diff --git a/src/pattern_formatter.cpp b/src/pattern_formatter.cpp index 0456121ed..fd668c745 100644 --- a/src/pattern_formatter.cpp +++ b/src/pattern_formatter.cpp @@ -739,6 +739,41 @@ class elapsed_formatter final : public flag_formatter { log_clock::time_point last_message_time_; }; +template +class attribute_formatter final : public flag_formatter { +public: + explicit attribute_formatter(padding_info padinfo) + : flag_formatter(padinfo) {} + + void format(const details::log_msg &msg, const std::tm &, memory_buf_t &dest) override { + if (msg.attributes.empty()) { + ScopedPadder p(0, padinfo_, dest); + return; + } else { + const auto &attributes = msg.attributes.get_map(); + format_attributes(attributes, dest); + } + } + + void format_attributes(const spdlog::log_attributes::attr_map_t &attributes, memory_buf_t &dest) { + for (auto it = attributes.begin(); it != attributes.end(); ++it) { + bool last_item = std::next(it) == attributes.end(); + auto &attribute = *it; + const auto &key = attribute.first; + const auto &value = attribute.second; + size_t content_size = key.size() + value.size() + 1; // 1 for ':' + + if (!last_item) 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 (!last_item) fmt_helper::append_string_view(" ", dest); + } + } +}; + // Full info formatter // pattern: [%Y-%m-%d %H:%M:%S.%e] [%n] [%l] [%s:%#] %v class default_format_formatter final : public flag_formatter { @@ -821,12 +856,23 @@ class default_format_formatter final : public flag_formatter { dest.push_back(']'); dest.push_back(' '); } + + // add attributes if present + if (!msg.attributes.empty()) { + dest.push_back('['); + const auto &attributes = msg.attributes.get_map(); + attribute_formatter_.format_attributes(attributes, dest); + dest.push_back(']'); + dest.push_back(' '); + } + fmt_helper::append_string_view(msg.payload, dest); } private: std::chrono::seconds cache_timestamp_{0}; memory_buf_t cached_datetime_; + attribute_formatter attribute_formatter_{padding_info{}}; }; } // namespace details @@ -1104,6 +1150,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/CMakeLists.txt b/tests/CMakeLists.txt index acd02d024..5a4b2c6d5 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -51,6 +51,7 @@ set(SPDLOG_UTESTS_SOURCES test_no_source_location.cpp test_log_level.cpp test_include_sinks.cpp + test_attributes.cpp test_bin_to_hex.cpp test_errors.cpp) diff --git a/tests/test_attributes.cpp b/tests/test_attributes.cpp new file mode 100644 index 000000000..b4882057c --- /dev/null +++ b/tests/test_attributes.cpp @@ -0,0 +1,202 @@ +#include + +#include "includes.h" +#include "spdlog/sinks/stdout_sinks.h" +#include "spdlog/spdlog.h" +#include "test_sink.h" + +using namespace spdlog; + +std::string format_attrs(std::string_view const log_name, log_attributes::attr_map_t const& attrs = {}) { + std::string fmt_attrs; + for (auto&& attr : attrs) fmt_attrs += fmt_lib::format("{}:{} ", attr.first, attr.second); + if (!fmt_attrs.empty()) fmt_attrs.pop_back(); + + return fmt_lib::format("[{}] [{}]", log_name, fmt_attrs); +} + +std::pair> make_logger() { + auto test_sink = std::make_shared(); + auto log = logger("logger", test_sink); + log.set_pattern("[%n] [%*]"); + return std::make_pair(log, test_sink); +} + +TEST_CASE("attribute test - multiple (single thread)") { + auto test_sink = std::make_shared(); + logger log_a("log_a", test_sink); + logger log_b("log_b", test_sink); + log_a.set_pattern("[%n] [%*]"); + log_b.set_pattern("[%n] [%*]"); + + log_a.attrs().put("my_key", "my_value"); + + log_a.info("Hello"); + log_b.info("Hello"); + + auto expected_log_a = format_attrs("log_a", {{"my_key", "my_value"}}); + auto expected_log_b = format_attrs("log_b"); + + auto [found, value] = log_a.attrs().get("my_key"); + REQUIRE(found); + REQUIRE(value->first == "my_key"); + REQUIRE(value->second == "my_value"); + + auto [not_found, _] = log_a.attrs().get("my_non_existent_key"); + REQUIRE(!not_found); + + auto lines = test_sink->lines(); + REQUIRE(lines.size() == 2); + REQUIRE(lines[0] == expected_log_a); + REQUIRE(lines[1] == expected_log_b); +} + +TEST_CASE("attribute test - remove") { + std::vector attrs{ + {"my_key", "my_value"}, + {"my_key2", "my_value2"}, + }; + + auto [log, test_sink] = make_logger(); + + log.attrs().put(attrs[0].first, attrs[0].second); + log.attrs().put(attrs[1].first, attrs[1].second); + + log.info(""); + auto expected_log = format_attrs("logger", {attrs.begin(), attrs.end()}); + + REQUIRE(!test_sink->lines().empty()); + REQUIRE(test_sink->lines().back() == expected_log); + + log.attrs().remove(attrs.front().first); + log.info(""); + expected_log = format_attrs("logger", {attrs.begin() + 1, attrs.end()}); + REQUIRE(test_sink->lines().back() == expected_log); + + log.attrs().remove(attrs.back().first); + log.info(""); + expected_log = format_attrs("logger"); + REQUIRE(test_sink->lines().back() == expected_log); +} + +TEST_CASE("attribute test - from range") { + std::vector attrs{ + {"my_key", "my_value"}, + {"my_key2", "my_value2"}, + }; + + auto [log, test_sink] = make_logger(); + + log.attrs().put({attrs.begin(), attrs.end()}); + log.info(""); + auto expected_log = format_attrs("logger", {attrs.begin(), attrs.end()}); + + REQUIRE(!test_sink->lines().empty()); + REQUIRE(test_sink->lines().back() == expected_log); +} + +TEST_CASE("attribute test - scoped") { + std::vector attrs{ + {"my_key", "my_value"}, + {"my_key2", "my_value2"}, + }; + + auto [log, test_sink] = make_logger(); + + auto key_value = std::make_pair("additional_key", "additional_value"); + { + // add the attributes in scope + auto ctx = log.attrs().scoped_ctx({attrs.begin(), attrs.end()}); + log.info(""); + auto expected_log = format_attrs("logger", {attrs.begin(), attrs.end()}); + + REQUIRE(!test_sink->lines().empty()); + REQUIRE(test_sink->lines().back() == expected_log); + + // remove one of the scoped attributes + log.attrs().remove(attrs.front().first); + log.info(""); + expected_log = format_attrs("logger", {attrs.begin() + 1, attrs.end()}); + REQUIRE(test_sink->lines().back() == expected_log); + + // add another non-scoped attribute + log.attrs().put(key_value.first, key_value.second); + log.info(""); + expected_log = format_attrs("logger", {attrs[1], key_value}); + REQUIRE(test_sink->lines().back() == expected_log); + } + + log.info(""); + auto expected_log = format_attrs("logger", {key_value}); +} + +TEST_CASE("attribute test - nested scoped") { + std::vector attrs{ + {"my_key", "my_value"}, + {"my_key2", "my_value2"}, + }; + std::vector nested_attrs{ + {"nested_key", "nested_value"}, + {"nested_key2", "nested_value2"}, + }; + + auto [log, test_sink] = make_logger(); + + { + // add the attributes in scope + auto ctx = log.attrs().scoped_ctx({attrs.begin(), attrs.end()}); + log.info(""); + auto expected_log = format_attrs("logger", {attrs.begin(), attrs.end()}); + + REQUIRE(!test_sink->lines().empty()); + REQUIRE(test_sink->lines().back() == expected_log); + + // add another scoped context + { + auto ctx_nested = log.attrs().scoped_ctx({nested_attrs.begin(), nested_attrs.end()}); + log.info(""); + log_attributes::attr_map_t all_attrs{attrs.begin(), attrs.end()}; + all_attrs.insert(nested_attrs.begin(), nested_attrs.end()); + expected_log = format_attrs("logger", {all_attrs.begin(), all_attrs.end()}); + REQUIRE(test_sink->lines().back() == expected_log); + } + + // delete nested scope + log.info(""); + expected_log = format_attrs("logger", {attrs.begin(), attrs.end()}); + REQUIRE(test_sink->lines().back() == expected_log); + } + + log.info(""); + auto expected_log = format_attrs("logger"); +} + +TEST_CASE("attribute test - multi threaded") { + const unsigned int n_tasks = std::thread::hardware_concurrency(); + constexpr auto n_values = 30; + auto mt_sink = std::make_shared(); + auto logger = spdlog::logger("logger", mt_sink); + logger.set_pattern("[%n] [%*]"); + + // put attributes with multiple threads simultaneously + std::vector> tasks; + for (unsigned int i = 0; i < n_tasks; ++i) { + auto task = std::async([&logger, i, n_values] { + for (auto j = 0; j < n_values; ++j) + logger.attrs().put(fmt_lib::format("log_{}_key_{}", i, j), fmt_lib::format("log_{}_value_{}", i, j)); + }); + tasks.emplace_back(std::move(task)); + } + + for (auto&& task : tasks) task.wait(); + + logger.info(""); + REQUIRE(!mt_sink->lines().empty()); + auto log_line = mt_sink->lines().back(); + for (unsigned int i = 0; i < n_tasks; ++i) { + for (auto j = 0; j < n_values; ++j) { + auto search_term = fmt_lib::format("log_{0}_key_{1}:log_{0}_value_{1}", i, j); + REQUIRE(log_line.find(search_term) != std::string::npos); + } + } +} \ No newline at end of file diff --git a/tests/test_pattern_formatter.cpp b/tests/test_pattern_formatter.cpp index 85f2114b9..c915a5ec1 100644 --- a/tests/test_pattern_formatter.cpp +++ b/tests/test_pattern_formatter.cpp @@ -455,3 +455,80 @@ TEST_CASE("override need_localtime", "[pattern_formatter]") { REQUIRE(to_string_view(formatted) == oss.str()); } } + +TEST_CASE("attribute formatter test-1", "[pattern_formatter]") { + spdlog::log_attributes attributes; + attributes.put("attribute_key_1", "attribute_value_1"); + attributes.put("attribute_key_2", "attribute_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", attributes); + formatter->format(msg, formatted); + + auto expected = spdlog::fmt_lib::format( + "[logger-name] [info] [attribute_key_1:attribute_value_1 attribute_key_2:attribute_value_2] some message{}", + spdlog::details::os::default_eol); + REQUIRE(to_string_view(formatted) == expected); +} + +TEST_CASE("attribute formatter value update", "[pattern_formatter]") { + spdlog::log_attributes attributes; + attributes.put("attribute_key_1", "attribute_value_1"); + attributes.put("attribute_key_2", "attribute_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", attributes); + formatter->format(msg, formatted_1); + + auto expected = spdlog::fmt_lib::format( + "[logger-name] [info] [attribute_key_1:attribute_value_1 attribute_key_2:attribute_value_2] some message{}", + spdlog::details::os::default_eol); + + REQUIRE(to_string_view(formatted_1) == expected); + + msg.attributes.put("attribute_key_1", "new_attribute_value_1"); + memory_buf_t formatted_2; + formatter->format(msg, formatted_2); + expected = spdlog::fmt_lib::format( + "[logger-name] [info] [attribute_key_1:new_attribute_value_1 attribute_key_2:attribute_value_2] some message{}", + spdlog::details::os::default_eol); + + REQUIRE(to_string_view(formatted_2) == expected); +} + +TEST_CASE("attribute remove key", "[pattern_formatter]") { + spdlog::log_attributes attributes; + attributes.put("attribute_key_1", "attribute_value_1"); + attributes.put("attribute_key_2", "attribute_value_2"); + attributes.remove("attribute_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", attributes); + formatter->format(msg, formatted); + + auto expected = spdlog::fmt_lib::format("[logger-name] [info] [attribute_key_2:attribute_value_2] some message{}", + spdlog::details::os::default_eol); + REQUIRE(to_string_view(formatted) == expected); +} + +TEST_CASE("attribute empty", "[pattern_formatter]") { + spdlog::log_attributes attributes; + 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", attributes); + 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); +}