diff --git a/include/spdlog/pattern_formatter-inl.h b/include/spdlog/pattern_formatter-inl.h index e9b0c92e..3ab2ba85 100644 --- a/include/spdlog/pattern_formatter-inl.h +++ b/include/spdlog/pattern_formatter-inl.h @@ -930,15 +930,16 @@ private: }; // attribute formatting: stub +// not sure if stub should print legacy values or nothing class attr_formatter_start final : public flag_formatter { public: explicit attr_formatter_start(padding_info padinfo) : flag_formatter(padinfo, details::attr_flags::start) {} - void format(const details::log_msg &, const std::tm &, memory_buf_t &dest) override + void format(const details::log_msg &, const std::tm &, memory_buf_t &) override { - fmt_helper::append_string_view("", dest); + // fmt_helper::append_string_view("%(", dest); } }; class attr_formatter_stop final : public flag_formatter @@ -947,9 +948,9 @@ public: explicit attr_formatter_stop(padding_info padinfo) : flag_formatter(padinfo, details::attr_flags::stop) {} - void format(const details::log_msg &, const std::tm &, memory_buf_t &dest) override + void format(const details::log_msg &, const std::tm &, memory_buf_t &) override { - fmt_helper::append_string_view("", dest); + // fmt_helper::append_string_view("%)", dest); } }; @@ -959,9 +960,9 @@ public: explicit attr_formatter_key(padding_info padinfo) : flag_formatter(padinfo, details::attr_flags::key) {} - void format(const details::log_msg &, const std::tm &, memory_buf_t &dest) override + void format(const details::log_msg &, const std::tm &, memory_buf_t &) override { - fmt_helper::append_string_view("", dest); + // fmt_helper::append_string_view("%K", dest); } }; @@ -971,9 +972,9 @@ public: explicit attr_formatter_value(padding_info padinfo) : flag_formatter(padinfo, details::attr_flags::value) {} - void format(const details::log_msg &, const std::tm &, memory_buf_t &dest) override + void format(const details::log_msg &, const std::tm &, memory_buf_t &) override { - fmt_helper::append_string_view("", dest); + // fmt_helper::append_string_view("%V", dest); } }; @@ -1145,17 +1146,26 @@ SPDLOG_INLINE void pattern_formatter::format(const details::log_msg &msg, memory f->format(msg, cached_tm_, dest); } } else { - auto it_end = formatters_.begin(); - // ugly formatter iterator, due to needing to go back to previous iterators to repeat kv pairs - for (auto it = formatters_.begin(); it != formatters_.end(); ++it) - { - if ((*it)->flag_ == details::attr_flags::start) { + // ugly formatter iterator, due to needing to go back to previous iterators to repeat kv pairs + for (auto it = formatters_.begin(); it != formatters_.end(); ++it) { + if ((*it)->flag_ != details::attr_flags::start) { + (*it)->format(msg, cached_tm_, dest); + continue; + } + ++it; // start at next symbol, don't need to check start flag + + // first look for stop iterator. If not found consider it the end iterator (repeat the last values for all attributes). + auto stop_it = it; + for (; stop_it != formatters_.end(); ++stop_it) { + if ((*stop_it)->flag_ == details::attr_flags::stop) { + break; + } + } + + // now iterate through attributes, printing the nested format for (const details::attr& a : msg.attributes) { - for (auto it2 = it; it2 != formatters_.end(); ++it2) { - if ((*it2)->flag_ == details::attr_flags::stop) { - it_end = it2; - break; - } else if ((*it2)->flag_ == details::attr_flags::key) { + for (auto it2 = it; it2 != stop_it; ++it2) { + if ((*it2)->flag_ == details::attr_flags::key) { // custom formatting function overload makes this even more messy with reinterpret casts, // will just do manual key addition details::fmt_helper::append_string_view(a.key, dest); @@ -1166,10 +1176,11 @@ SPDLOG_INLINE void pattern_formatter::format(const details::log_msg &msg, memory } } } - it = it_end; + + // skip the nested attributes pattern, go back to normal pattern matching. + if (stop_it != formatters_.end()) it = stop_it; + else it = formatters_.end()-1; } - (*it)->format(msg, cached_tm_, dest); - } } // write eol diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 7fe4791e..e84d156a 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -33,7 +33,8 @@ set(SPDLOG_UTESTS_SOURCES test_create_dir.cpp test_cfg.cpp test_time_point.cpp - test_stopwatch.cpp) + test_stopwatch.cpp + test_attributes.cpp) if(NOT SPDLOG_NO_EXCEPTIONS) list(APPEND SPDLOG_UTESTS_SOURCES test_errors.cpp) diff --git a/tests/test_attributes.cpp b/tests/test_attributes.cpp new file mode 100644 index 00000000..42f7828a --- /dev/null +++ b/tests/test_attributes.cpp @@ -0,0 +1,108 @@ +// make attributes conform to spdlog requirements (thread-safe, exception-safe, etc) +#include "includes.h" +#include "test_sink.h" +#include +#include +#include + +#define TEST_FILENAME "test_logs/attr_test.log" + +// see if multiple async logs to a single file is thread-safe, i.e. produces coherent structured logs +TEST_CASE("async attributes test with threads ", "[attributes]") +{ + auto test_sink = std::make_shared(); + + constexpr int num_loggers = 10; + constexpr int num_msgs = 10; + size_t overrun_counter = 0; + + { + auto tp = std::make_shared(num_loggers * num_msgs, 1); + std::vector> loggers; + for (int i = 0; i < num_loggers; ++i) { + loggers.push_back(std::make_shared( + "attr_logger_"+std::to_string(i), test_sink, tp, spdlog::async_overflow_policy::block)); + } + + std::vector threads; + for (auto lg : loggers) { + threads.emplace_back([=](){ + // push and pop context are not guaranteed to be thread safe + // therefore, messages from the same logger object have to be in the same thread + // to guarantee thread safety, use a different logger object for each thread + for (int i = 0; i < num_msgs; ++i) { + lg->push_context({{"key"+std::to_string(i), "val"+std::to_string(i)}}); + lg->info("testing {}", i); + lg->pop_context(); + } + }); + } + for (auto& th : threads) { + th.join(); + } + + for (auto lg : loggers) { + lg->flush(); + } + overrun_counter += tp->overrun_counter(); + } + + REQUIRE(test_sink->msg_counter() == num_loggers * num_msgs); + REQUIRE(test_sink->flush_counter() == num_loggers); + REQUIRE(overrun_counter == 0); + + // todo: better parsing of keys and values, maybe using regex + for (auto& line : test_sink->lines()) { + REQUIRE(line.find("key") != std::string::npos); + REQUIRE(line.find("val") != std::string::npos); + } +} + +// testing custom patterns, including the new attribute patterns, with many use cases. +// some use cases may result in errors or undesirable behaviour, but the test should not crash. +TEST_CASE("pattern matching with attributes ", "[attributes]") +{ + auto test_sink = std::make_shared(); + auto logger = std::make_shared("attr_logger", test_sink); + std::string msg = "testing"; + logger->push_context({{"key1", "value1"}, {"key2", "value2"}}); + + // a pattern with no stop flag will consider the stop flag as the end + logger->set_pattern("%v%( %K=%V"); + logger->info(msg); + + REQUIRE(test_sink->lines()[test_sink->msg_counter()-1] == msg+" key1=value1 key2=value2"); + + // a pattern with no start flag will be parsed as-is. the new flags will be treated as empty strings. + logger->set_pattern("%v %K=%V%) %v end"); + logger->info("testing"); + + REQUIRE(test_sink->lines()[test_sink->msg_counter()-1] == msg+" = "+msg+" end"); + + // a pattern with nested flags will print those flags for every key-value pair + logger->set_pattern("%(%v %K=%V %)"); + logger->info("testing"); + REQUIRE(test_sink->lines()[test_sink->msg_counter()-1] == msg+" key1=value1 "+msg+" key2=value2 "); + + logger->set_pattern("%v start%( %K=%V%) %v end"); + // zero kv pairs + logger->clear_context(); + logger->push_context({}); + logger->info(msg); + + REQUIRE(test_sink->lines()[test_sink->msg_counter()-1] == msg+" start "+msg+" end"); + + // N kv pairs + for (int i = 0; i < 50; ++i) { + logger->push_context({{"key"+std::to_string(i), "value"+std::to_string(i)}}); + logger->info("testing"); + std::stringstream ss; + ss << msg << " start"; + for (int j = 0; j <= i; ++j) { + ss << " key" << j << "=value" << j; + } + ss << ' ' << msg << " end"; + + REQUIRE(test_sink->lines()[test_sink->msg_counter()-1] == ss.str()); + } +} \ No newline at end of file