Merge 85a05357ae into 22405cf9ae

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"

include/spdlog/attributes.h

@@ -0,0 +1,102 @@
+#pragma once
+
+#include <spdlog/common.h>
+
+#include <map>
+#include <mutex>
+
+
+namespace spdlog {
+
+class SPDLOG_API log_attributes {
+public:
+    using attr_map_t = std::map<std::string, std::string>;
+    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<bool, const_iter> 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<std::mutex> lock() const { return std::lock_guard(attrs_mtx); }
+
+    mutable std::mutex attrs_mtx;
+    attr_map_t attrs;
+};
+
+}  // namespace spdlog

include/spdlog/details/log_msg.h

@@ -5,14 +5,23 @@
 
 #include <string>
 
+#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

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 @@ public:
     // 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 @@ public:
     // create new logger with same sinks and configuration.
     std::shared_ptr<logger> clone(std::string logger_name);
 
+    log_attributes &attrs();
+
 private:
     std::string name_;
     std::vector<sink_ptr> 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 @@ private:
         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 (...) {

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

src/logger.cpp

@@ -81,4 +81,7 @@ void logger::flush_() noexcept {
         }
     }
 }
+
+log_attributes &logger::attrs() { return attributes; }
+
 }  // namespace spdlog

src/pattern_formatter.cpp

@@ -739,6 +739,41 @@ private:
     log_clock::time_point last_message_time_;
 };
 
+template <typename ScopedPadder>
+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 @@ public:
             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<null_scoped_padder> 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<details::elapsed_formatter<Padder, std::chrono::seconds>>(padding));
             break;
 
+        case ('*'):
+            formatters_.push_back(std::make_unique<details::attribute_formatter<Padder>>(padding));
+            break;
+
         default:  // Unknown flag appears as is
             auto unknown_flag = std::make_unique<details::aggregate_formatter>();
 

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)
 

tests/test_attributes.cpp

@@ -0,0 +1,202 @@
+#include <future>
+
+#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<logger, std::shared_ptr<sinks::test_sink_st>> make_logger() {
+    auto test_sink = std::make_shared<sinks::test_sink_st>();
+    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<sinks::test_sink_st>();
+    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<log_attributes::attr_map_t::value_type> 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<log_attributes::attr_map_t::value_type> 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<log_attributes::attr_map_t::value_type> 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<log_attributes::attr_map_t::value_type> attrs{
+        {"my_key", "my_value"},
+        {"my_key2", "my_value2"},
+    };
+    std::vector<log_attributes::attr_map_t::value_type> 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<spdlog::sinks::test_sink_mt>();
+    auto logger = spdlog::logger("logger", mt_sink);
+    logger.set_pattern("[%n] [%*]");
+
+    // put attributes with multiple threads simultaneously
+    std::vector<std::future<void>> 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);
+        }
+    }
+}

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<spdlog::pattern_formatter>();
+    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<spdlog::pattern_formatter>();
+    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<spdlog::pattern_formatter>();
+    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<spdlog::pattern_formatter>();
+    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);
+}