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
pull/2687/head
Bailey Chittle 3 years ago committed by Bailey Chittle
parent b800164d11
commit 3d27666650

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

@ -48,7 +48,8 @@ set(SPDLOG_UTESTS_SOURCES
test_custom_callbacks.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)

@ -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());
}
}
Loading…
Cancel
Save