pull/3128/merge
Felix Bruns 2 months ago committed by GitHub
commit 07d93daba3
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194

@ -146,7 +146,8 @@ set(SPDLOG_HEADERS
"include/spdlog/sinks/systemd_sink.h" "include/spdlog/sinks/systemd_sink.h"
"include/spdlog/sinks/tcp_sink.h" "include/spdlog/sinks/tcp_sink.h"
"include/spdlog/sinks/udp_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 set(SPDLOG_SRCS
"src/common.cpp" "src/common.cpp"
"src/logger.cpp" "src/logger.cpp"

@ -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

@ -5,14 +5,23 @@
#include <string> #include <string>
#include "../attributes.h"
#include "../common.h" #include "../common.h"
namespace spdlog { namespace spdlog {
namespace details { namespace details {
struct SPDLOG_API log_msg { struct SPDLOG_API log_msg {
log_msg() = default; 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(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_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(string_view_t logger_name, level lvl, string_view_t msg);
log_msg(const log_msg &other) = default; log_msg(const log_msg &other) = default;
log_msg &operator=(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; source_loc source;
string_view_t payload; string_view_t payload;
log_attributes attributes;
}; };
} // namespace details } // namespace details
} // namespace spdlog } // namespace spdlog

@ -19,6 +19,7 @@
#include "details/err_helper.h" #include "details/err_helper.h"
#include "details/log_msg.h" #include "details/log_msg.h"
#include "sinks/sink.h" #include "sinks/sink.h"
#include "attributes.h"
namespace spdlog { namespace spdlog {
@ -63,20 +64,20 @@ public:
// log with no format string, just string message // log with no format string, just string message
void log(const source_loc &loc, level lvl, string_view_t msg) noexcept { void log(const source_loc &loc, level lvl, string_view_t msg) noexcept {
if (should_log(lvl)) { 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 { void log(level lvl, string_view_t msg) noexcept {
if (should_log(lvl)) { 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 // support for custom time
void log(log_clock::time_point log_time, const source_loc &loc, level lvl, string_view_t msg) noexcept { void log(log_clock::time_point log_time, const source_loc &loc, level lvl, string_view_t msg) noexcept {
if (should_log(lvl)) { 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. // create new logger with same sinks and configuration.
std::shared_ptr<logger> clone(std::string logger_name); std::shared_ptr<logger> clone(std::string logger_name);
log_attributes &attrs();
private: private:
std::string name_; std::string name_;
std::vector<sink_ptr> sinks_; std::vector<sink_ptr> sinks_;
log_attributes attributes;
atomic_level_t level_{level::info}; atomic_level_t level_{level::info};
atomic_level_t flush_level_{level::off}; atomic_level_t flush_level_{level::off};
details::err_helper err_helper_; details::err_helper err_helper_;
@ -178,7 +182,7 @@ private:
try { try {
memory_buf_t buf; memory_buf_t buf;
fmt::vformat_to(std::back_inserter(buf), format_string, fmt::make_format_args(args...)); 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) { } catch (const std::exception &ex) {
err_helper_.handle_ex(name_, loc, ex); err_helper_.handle_ex(name_, loc, ex);
} catch (...) { } catch (...) {

@ -8,6 +8,25 @@
namespace spdlog { namespace spdlog {
namespace details { 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, log_msg::log_msg(const log_clock::time_point log_time,
const source_loc &loc, const source_loc &loc,
const string_view_t logger_name, 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::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::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(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 details
} // namespace spdlog } // namespace spdlog

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

@ -742,6 +742,41 @@ private:
log_clock::time_point last_message_time_; 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 // Full info formatter
// pattern: [%Y-%m-%d %H:%M:%S.%e] [%n] [%l] [%s:%#] %v // pattern: [%Y-%m-%d %H:%M:%S.%e] [%n] [%l] [%s:%#] %v
class default_format_formatter final : public flag_formatter { class default_format_formatter final : public flag_formatter {
@ -824,12 +859,23 @@ public:
dest.push_back(']'); dest.push_back(']');
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); fmt_helper::append_string_view(msg.payload, dest);
} }
private: private:
std::chrono::seconds cache_timestamp_{0}; std::chrono::seconds cache_timestamp_{0};
memory_buf_t cached_datetime_; memory_buf_t cached_datetime_;
attribute_formatter<null_scoped_padder> attribute_formatter_{padding_info{}};
}; };
} // namespace details } // namespace details
@ -1107,6 +1153,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)); formatters_.push_back(std::make_unique<details::elapsed_formatter<Padder, std::chrono::seconds>>(padding));
break; break;
case ('*'):
formatters_.push_back(std::make_unique<details::attribute_formatter<Padder>>(padding));
break;
default: // Unknown flag appears as is default: // Unknown flag appears as is
auto unknown_flag = std::make_unique<details::aggregate_formatter>(); auto unknown_flag = std::make_unique<details::aggregate_formatter>();

@ -51,6 +51,7 @@ set(SPDLOG_UTESTS_SOURCES
test_no_source_location.cpp test_no_source_location.cpp
test_log_level.cpp test_log_level.cpp
test_include_sinks.cpp test_include_sinks.cpp
test_attributes.cpp
test_bin_to_hex.cpp test_bin_to_hex.cpp
test_errors.cpp) test_errors.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);
}
}
}

@ -481,3 +481,80 @@ TEST_CASE("override need_localtime", "[pattern_formatter]") {
REQUIRE(to_string_view(formatted) == oss.str()); 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);
}

Loading…
Cancel
Save