attribute testing (#3)

* initial testing of attributes

* updating test cases for new api

* more testing, fixing bugs found

* fixed unused error

* errors might be caused due to passing pointers by reference, these simple pointer passes should be by value

* my only other idea for getting this to work. will experiment

* fixing tests before merge (#4)

* my only other idea for getting this to work. will experiment

* I think I fixed the thread issue, lets see...

* unused lambda capture acting funny

* see if its the context that is causing issues

* unused warning... again

* reverting to basic, see where the issue is in github actions (testing most of it locally)

* this works again?

* some diff cleanup before squash merging

* cleaner search for stop iterator

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
-    // 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) {
-    for (auto it = formatters_.begin(); it != formatters_.end(); ++it)
+            if ((*it)->flag_ != details::attr_flags::start) {
-    {
+                (*it)->format(msg, cached_tm_, dest);
-        if ((*it)->flag_ == details::attr_flags::start) {
+                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) {
+                for (auto it2 = it; it2 != stop_it; ++it2) {
-                    if ((*it2)->flag_ == details::attr_flags::stop) {
+                    if ((*it2)->flag_ == details::attr_flags::key) {
-                        it_end = it2;
-                        break;
-                    } else 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

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)

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 <string>
+#include <sstream>
+#include <thread>
+
+#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<spdlog::sinks::test_sink_mt>();
+
+    constexpr int num_loggers = 10;
+    constexpr int num_msgs = 10;
+    size_t overrun_counter = 0;
+
+    {
+    auto tp = std::make_shared<spdlog::details::thread_pool>(num_loggers * num_msgs, 1);
+    std::vector<std::shared_ptr<spdlog::logger>> loggers;
+    for (int i = 0; i < num_loggers; ++i) {
+        loggers.push_back(std::make_shared<spdlog::async_logger>(
+            "attr_logger_"+std::to_string(i), test_sink, tp, spdlog::async_overflow_policy::block));
+    }
+
+    std::vector<std::thread> 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<spdlog::sinks::test_sink_mt>();
+    auto logger = std::make_shared<spdlog::logger>("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());
+    }
+}