From b43c81ac855e7be469535d6c48ad1005de41125d Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Fri, 17 Dec 2021 11:02:35 -0800 Subject: [PATCH 01/21] Make GoogleBenchmark URL configurable so it can be fetched via ssh --- CMakeLists.txt | 2 ++ bench/CMakeLists.txt | 6 +++--- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index 21577e5084..8f1b00a2aa 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -71,6 +71,8 @@ option(SPDLOG_BUILD_TESTS_HO "Build tests using the header only version" OFF) # bench options option(SPDLOG_BUILD_BENCH "Build benchmarks (Requires https://github.com/google/benchmark.git to be installed)" OFF) +option(SPDLOG_GOOGLEBENCHMARK_URL "Url of googlebenchmark git repository" https://github.com/google/benchmark.git) +# git@github.com:google/benchmark.git # sanitizer options option(SPDLOG_SANITIZE_ADDRESS "Enable address sanitizer in tests" OFF) diff --git a/bench/CMakeLists.txt b/bench/CMakeLists.txt index 144f50b830..69d73a8b79 100644 --- a/bench/CMakeLists.txt +++ b/bench/CMakeLists.txt @@ -17,10 +17,10 @@ if(NOT benchmark_FOUND) message(STATUS "Downloading GoogleBenchmark") include(FetchContent) - # disable tests - set(BENCHMARK_ENABLE_TESTING OFF CACHE INTERNAL "") + # disable tests + set(BENCHMARK_ENABLE_TESTING OFF CACHE INTERNAL "") # Do not build and run googlebenchmark tests - FetchContent_Declare(googlebenchmark GIT_REPOSITORY https://github.com/google/benchmark.git GIT_TAG v1.6.0) + FetchContent_Declare(googlebenchmark GIT_REPOSITORY ${SPDLOG_GOOGLEBENCHMARK_URL} GIT_TAG v1.6.0) FetchContent_MakeAvailable(googlebenchmark) else() message(FATAL_ERROR "GoogleBenchmark is missing. Use CMake >= 3.11 or download it") From 9a168afebc699c525440f215e2f6c236b6429aad Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Fri, 17 Dec 2021 14:37:10 -0800 Subject: [PATCH 02/21] Added slog method --- include/spdlog/common.h | 8 ++++ include/spdlog/logger.h | 15 +++++-- include/spdlog/structured_spdlog.h | 63 ++++++++++++++++++++++++++++++ tests/CMakeLists.txt | 1 + tests/includes.h | 3 +- tests/test_structured.cpp | 51 ++++++++++++++++++++++++ 6 files changed, 136 insertions(+), 5 deletions(-) create mode 100644 include/spdlog/structured_spdlog.h create mode 100644 tests/test_structured.cpp diff --git a/include/spdlog/common.h b/include/spdlog/common.h index 9903463c60..1d30fa9ae9 100644 --- a/include/spdlog/common.h +++ b/include/spdlog/common.h @@ -15,6 +15,7 @@ #include #include #include +#include #ifdef SPDLOG_USE_STD_FORMAT # include @@ -319,6 +320,13 @@ struct file_event_handlers {} }; +using FieldValue = std::variant; //TODO +struct Field { + spdlog::string_view_t name; + FieldValue value; +}; +constexpr auto NO_FIELDS = std::array(); + namespace details { // make_unique support for pre c++14 diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index a8abae419a..1257d8fa22 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -84,10 +84,16 @@ class SPDLOG_API logger logger &operator=(logger other) SPDLOG_NOEXCEPT; void swap(spdlog::logger &other) SPDLOG_NOEXCEPT; + template + void slog(source_loc loc, level::level_enum lvl, const std::array& fields, format_string_t fmt, Args &&... args) + { + log_(loc, lvl, fields, fmt, std::forward(args)...); + } + template void log(source_loc loc, level::level_enum lvl, format_string_t fmt, Args &&... args) { - log_(loc, lvl, fmt, std::forward(args)...); + log_(loc, lvl, NO_FIELDS, fmt, std::forward(args)...); } template @@ -180,7 +186,7 @@ class SPDLOG_API logger template void log(source_loc loc, level::level_enum lvl, wformat_string_t fmt, Args &&... args) { - log_(loc, lvl, fmt, std::forward(args)...); + log_(loc, lvl, NO_FIELDS, fmt, std::forward(args)...); } template @@ -352,8 +358,8 @@ class SPDLOG_API logger details::backtracer tracer_; // common implementation for after templated public api has been resolved - template - void log_(source_loc loc, level::level_enum lvl, string_view_t fmt, Args &&... args) + template + void log_(source_loc loc, level::level_enum lvl, const std::array& fields, string_view_t fmt, Args &&... args) { bool log_enabled = should_log(lvl); bool traceback_enabled = tracer_.enabled(); @@ -369,6 +375,7 @@ class SPDLOG_API logger memory_buf_t buf; fmt::detail::vformat_to(buf, fmt, fmt::make_format_args(std::forward(args)...)); #endif + (void) fields; details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size())); log_it_(log_msg, log_enabled, traceback_enabled); } diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h new file mode 100644 index 0000000000..d8e7230a12 --- /dev/null +++ b/include/spdlog/structured_spdlog.h @@ -0,0 +1,63 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +// spdlog main header file. +// see example.cpp for usage example + +#ifndef STRUCTURED_SPDLOG_H +#define STRUCTURED_SPDLOG_H + +#pragma once + +#include "spdlog.h" + +namespace spdlog { + + template + constexpr int count_leading_fields(ArgTypes... args [[maybe_unused]]) { + return 0; + } + template + constexpr int count_leading_fields(const Field&& field, ArgTypes... args) { + return 1 + count_leading_fields(args...); + } + + // Stop on empty arg list + template + void fill_fields(std::array & result [[maybe_unused]], int n [[maybe_unused]]) { + } + + // Stop on first non-field value + template + void fill_fields(std::array & result [[maybe_unused]], int n [[maybe_unused]], ArgTypes... args [[maybe_unused]] ) { + } + + template + void fill_fields(std::array & result, int n, const Field& f, ArgTypes... args) { + result[n] = f; + fill_fields(result, n+1, args...); + } + + template + std::array build_fields(ArgTypes... args) { + std::array result; + fill_fields(result, 0, args...); + return result; + } + + template + Field F(string_view_t name, const T& val) { + Field f={name, val}; + return f; + } + + template + inline void slog(source_loc source, level::level_enum lvl, const std::array& fields, format_string_t fmt, Args &&... args) + { + default_logger_raw()->slog(source, lvl, fields, fmt, std::forward(args)...); + } + + +} + +#endif // STRUCTURED_SPDLOG_H diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 7fe4791eb1..9aeb438f8b 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -32,6 +32,7 @@ set(SPDLOG_UTESTS_SOURCES test_backtrace.cpp test_create_dir.cpp test_cfg.cpp + test_structured.cpp test_time_point.cpp test_stopwatch.cpp) diff --git a/tests/includes.h b/tests/includes.h index 7285873a81..f5392b6132 100644 --- a/tests/includes.h +++ b/tests/includes.h @@ -23,4 +23,5 @@ #include "spdlog/sinks/ostream_sink.h" #include "spdlog/sinks/rotating_file_sink.h" #include "spdlog/sinks/stdout_color_sinks.h" -#include "spdlog/pattern_formatter.h" \ No newline at end of file +#include "spdlog/pattern_formatter.h" +#include "spdlog/structured_spdlog.h" diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp new file mode 100644 index 0000000000..b55c83ecea --- /dev/null +++ b/tests/test_structured.cpp @@ -0,0 +1,51 @@ +#include "includes.h" +#include "test_sink.h" + +template +std::string log_info(const std::array& fields, const T &what, ArgTypes&&... args) +{ + std::ostringstream oss; + auto oss_sink = std::make_shared(oss); + + spdlog::logger oss_logger("oss", oss_sink); + oss_logger.set_pattern("%v"); + oss_logger.slog({}, spdlog::level::info, fields, what, args...); + + return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); +} + +TEST_CASE("fields ", "[field_construction]") +{ + spdlog::F("var", 1); + spdlog::F("var", "val"); + + std::string str1("str"); + spdlog::F(str1, 1); +} + +TEST_CASE("field_array ", "[field_array_construction]") +{ + auto array0 = spdlog::build_fields(); + REQUIRE(array0.size() == 0); + + auto array1 = spdlog::build_fields(spdlog::F("var", 1)); + REQUIRE(array1.size() == 1); + REQUIRE(to_string(array1[0].name) == "var"); + REQUIRE(std::get(array1[0].value) == 1); + + auto array2 = spdlog::build_fields(spdlog::F("var", 1), spdlog::F("var2", "two")); + REQUIRE(array2.size() == 2); + REQUIRE(to_string(array2[0].name) == "var"); + REQUIRE(std::get(array2[0].value) == 1); + REQUIRE(to_string(array2[1].name) == "var2"); + REQUIRE(to_string(std::get(array2[1].value)) == "two"); +} + +TEST_CASE("field_logging ", "[field_logging]") +{ + // No fields + REQUIRE(log_info(spdlog::NO_FIELDS, "Hello") == "Hello"); + + // Some fields + REQUIRE(log_info(spdlog::build_fields(spdlog::F("k", 1)), "Hello") == "Hello"); +} From cdfce2440927ba08b555fc417029be9ca9ac6b88 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Tue, 11 Jan 2022 12:02:10 -0800 Subject: [PATCH 03/21] Add log_msg support --- include/spdlog/details/log_msg-inl.h | 21 +++++++-- include/spdlog/details/log_msg.h | 5 +++ include/spdlog/details/log_msg_buffer-inl.h | 49 ++++++++++++++++++++- include/spdlog/logger.h | 18 +++++--- tests/test_structured.cpp | 38 ++++++++++++++++ 5 files changed, 119 insertions(+), 12 deletions(-) diff --git a/include/spdlog/details/log_msg-inl.h b/include/spdlog/details/log_msg-inl.h index c6e8a7e04f..aba64c60b7 100644 --- a/include/spdlog/details/log_msg-inl.h +++ b/include/spdlog/details/log_msg-inl.h @@ -13,7 +13,7 @@ namespace spdlog { namespace details { SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::source_loc loc, string_view_t a_logger_name, - spdlog::level::level_enum lvl, spdlog::string_view_t msg) + spdlog::level::level_enum lvl, spdlog::string_view_t msg, const Field * fields, size_t field_count) : logger_name(a_logger_name) , level(lvl) , time(log_time) @@ -22,15 +22,30 @@ SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::s #endif , source(loc) , payload(msg) +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + , field_data(const_cast(fields)) + , field_data_count(field_count) +#endif +{} + +SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::source_loc loc, string_view_t a_logger_name, + spdlog::level::level_enum lvl, spdlog::string_view_t msg) + : log_msg(log_time, loc, a_logger_name, lvl, msg, nullptr, 0) {} SPDLOG_INLINE log_msg::log_msg( spdlog::source_loc loc, string_view_t a_logger_name, spdlog::level::level_enum lvl, spdlog::string_view_t msg) - : log_msg(os::now(), loc, a_logger_name, lvl, msg) + : log_msg(os::now(), loc, a_logger_name, lvl, msg, nullptr, 0) +{} + +SPDLOG_INLINE log_msg::log_msg( + spdlog::source_loc loc, string_view_t a_logger_name, spdlog::level::level_enum lvl, spdlog::string_view_t msg, + const Field * fields, size_t field_count) + : log_msg(os::now(), loc, a_logger_name, lvl, msg, fields, field_count) {} SPDLOG_INLINE log_msg::log_msg(string_view_t a_logger_name, spdlog::level::level_enum lvl, spdlog::string_view_t msg) - : log_msg(os::now(), source_loc{}, a_logger_name, lvl, msg) + : log_msg(os::now(), source_loc{}, a_logger_name, lvl, msg, nullptr, 0) {} } // namespace details diff --git a/include/spdlog/details/log_msg.h b/include/spdlog/details/log_msg.h index fed51abdf6..adcbc87515 100644 --- a/include/spdlog/details/log_msg.h +++ b/include/spdlog/details/log_msg.h @@ -11,7 +11,9 @@ namespace details { struct SPDLOG_API log_msg { log_msg() = default; + log_msg(log_clock::time_point log_time, source_loc loc, string_view_t logger_name, level::level_enum lvl, string_view_t msg, const Field * fields, size_t field_count); log_msg(log_clock::time_point log_time, source_loc loc, string_view_t logger_name, level::level_enum lvl, string_view_t msg); + log_msg(source_loc loc, string_view_t logger_name, level::level_enum lvl, string_view_t msg, const Field * fields, size_t field_count); log_msg(source_loc loc, string_view_t logger_name, level::level_enum lvl, string_view_t msg); log_msg(string_view_t logger_name, level::level_enum lvl, string_view_t msg); log_msg(const log_msg &other) = default; @@ -28,6 +30,9 @@ struct SPDLOG_API log_msg source_loc source; string_view_t payload; + + Field *field_data{nullptr}; + size_t field_data_count{0}; }; } // namespace details } // namespace spdlog diff --git a/include/spdlog/details/log_msg_buffer-inl.h b/include/spdlog/details/log_msg_buffer-inl.h index 84d83dc2fe..952a7fbbb0 100644 --- a/include/spdlog/details/log_msg_buffer-inl.h +++ b/include/spdlog/details/log_msg_buffer-inl.h @@ -7,12 +7,26 @@ # include #endif +#include + namespace spdlog { namespace details { SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg &orig_msg) : log_msg{orig_msg} { +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + // Start with struct copies so that objects stay nicely aligned, but strings + // can be packed in at the end + buffer.append(reinterpret_cast(field_data), reinterpret_cast(field_data + field_data_count)); + for (size_t i=0; i < field_data_count; i++) { + buffer.append(field_data[i].name); + auto string_view_p = std::get_if(&field_data[i].value); + if (string_view_p) { + buffer.append(string_view_p->begin(), string_view_p->end()); + } + } +#endif buffer.append(logger_name.begin(), logger_name.end()); buffer.append(payload.begin(), payload.end()); update_string_views(); @@ -21,6 +35,18 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg &orig_msg) SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg_buffer &other) : log_msg{other} { +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + // Start with struct copies so that objects stay nicely aligned, but strings + // can be packed in at the end + buffer.append(reinterpret_cast(field_data), reinterpret_cast(field_data + field_data_count)); + for (size_t i=0; i < field_data_count; i++) { + buffer.append(field_data[i].name); + auto string_view_p = std::get_if(&field_data[i].value); + if (string_view_p) { + buffer.append(string_view_p->begin(), string_view_p->end()); + } + } +#endif buffer.append(logger_name.begin(), logger_name.end()); buffer.append(payload.begin(), payload.end()); update_string_views(); @@ -28,6 +54,7 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg_buffer &other) SPDLOG_INLINE log_msg_buffer::log_msg_buffer(log_msg_buffer &&other) SPDLOG_NOEXCEPT : log_msg{other}, buffer{std::move(other.buffer)} { + std::cout << "this_count=" << field_data_count << " other_count=" << other.field_data_count << std::endl; update_string_views(); } @@ -44,14 +71,32 @@ SPDLOG_INLINE log_msg_buffer &log_msg_buffer::operator=(log_msg_buffer &&other) { log_msg::operator=(other); buffer = std::move(other.buffer); + if (field_data_count != other.field_data_count) { + abort(); + } update_string_views(); return *this; } SPDLOG_INLINE void log_msg_buffer::update_string_views() { - logger_name = string_view_t{buffer.data(), logger_name.size()}; - payload = string_view_t{buffer.data() + logger_name.size(), payload.size()}; +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + field_data = reinterpret_cast(buffer.data()); + size_t offset = sizeof(Field) * field_data_count; + for (size_t i=0; i < field_data_count; i++) { + field_data[i].name = string_view_t{buffer.data() + offset, field_data[i].name.size()}; + offset += field_data[i].name.size(); + auto string_view_p = std::get_if(&field_data[i].value); + if (string_view_p) { + field_data[i].value = FieldValue(string_view_t{buffer.data() + offset, string_view_p->size()}); + offset += string_view_p->size(); + } + } +#endif + logger_name = string_view_t{buffer.data() + offset, logger_name.size()}; + offset += logger_name.size(); + payload = string_view_t{buffer.data() + offset, payload.size()}; + offset += payload.size(); } } // namespace details diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index 1257d8fa22..2d557be6bc 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -87,13 +87,18 @@ class SPDLOG_API logger template void slog(source_loc loc, level::level_enum lvl, const std::array& fields, format_string_t fmt, Args &&... args) { - log_(loc, lvl, fields, fmt, std::forward(args)...); + log_(loc, lvl, fields.data(), N, fmt, std::forward(args)...); + } + template + void slog(source_loc loc, level::level_enum lvl, const std::array& fields, format_string_t fmt, Args &&... args) + { + log_(loc, lvl, nullptr, 0, fmt, std::forward(args)...); } template void log(source_loc loc, level::level_enum lvl, format_string_t fmt, Args &&... args) { - log_(loc, lvl, NO_FIELDS, fmt, std::forward(args)...); + log_(loc, lvl, nullptr, 0, fmt, std::forward(args)...); } template @@ -186,7 +191,7 @@ class SPDLOG_API logger template void log(source_loc loc, level::level_enum lvl, wformat_string_t fmt, Args &&... args) { - log_(loc, lvl, NO_FIELDS, fmt, std::forward(args)...); + log_(loc, lvl, {}, fmt, std::forward(args)...); } template @@ -358,8 +363,8 @@ class SPDLOG_API logger details::backtracer tracer_; // common implementation for after templated public api has been resolved - template - void log_(source_loc loc, level::level_enum lvl, const std::array& fields, string_view_t fmt, Args &&... args) + template + void log_(source_loc loc, level::level_enum lvl, const Field * fields, size_t num_fields, string_view_t fmt, Args &&... args) { bool log_enabled = should_log(lvl); bool traceback_enabled = tracer_.enabled(); @@ -375,8 +380,7 @@ class SPDLOG_API logger memory_buf_t buf; fmt::detail::vformat_to(buf, fmt, fmt::make_format_args(std::forward(args)...)); #endif - (void) fields; - details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size())); + details::log_msg log_msg(loc, name_, lvl, string_view_t(buf.data(), buf.size()), fields, num_fields); log_it_(log_msg, log_enabled, traceback_enabled); } SPDLOG_LOGGER_CATCH(loc) diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index b55c83ecea..15e2f57d92 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -1,6 +1,9 @@ #include "includes.h" #include "test_sink.h" +#include "spdlog/details/log_msg_buffer.h" + + template std::string log_info(const std::array& fields, const T &what, ArgTypes&&... args) { @@ -49,3 +52,38 @@ TEST_CASE("field_logging ", "[field_logging]") // Some fields REQUIRE(log_info(spdlog::build_fields(spdlog::F("k", 1)), "Hello") == "Hello"); } + +TEST_CASE("buffered_msg_field_copies ", "[structured]") +{ + std::unique_ptr test1; + { + auto array2 = spdlog::build_fields(spdlog::F("var", 1), spdlog::F("var2", "two")); + spdlog::details::log_msg test_input1(spdlog::source_loc{}, "name", spdlog::level::info, "msg", array2.data(), array2.size()); + test1 = std::make_unique(test_input1); + } + REQUIRE(test1->field_data_count == 2); + REQUIRE(test1->field_data[0].name == "var"); + REQUIRE(std::get(test1->field_data[0].value) == 1); + REQUIRE(test1->field_data[1].name == "var2"); + REQUIRE(std::get(test1->field_data[1].value) == "two"); +} + +TEST_CASE("async_structured ", "[structured]") +{ + auto test_sink = std::make_shared(); + test_sink->set_delay(std::chrono::milliseconds(1)); + size_t queue_size = 4; + size_t messages = 1024; + + auto tp = std::make_shared(queue_size, 1); + auto logger = std::make_shared("as", test_sink, tp, spdlog::async_overflow_policy::overrun_oldest); + for (size_t i = 0; i < messages; i++) + { + // Build on the stack so it's out of scope + std::string test_string("abcdefghijklmnopqrstuvwxyz"); + logger->slog({}, spdlog::level::info, spdlog::build_fields(spdlog::F("str", test_string)), "test msg"); + } + REQUIRE(test_sink->msg_counter() < messages); + REQUIRE(test_sink->msg_counter() > 0); + REQUIRE(tp->overrun_counter() > 0); +} From a9fd0ea29e9cd2d17ab217b478f0bc563e8cf59a Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Wed, 12 Jan 2022 12:16:55 -0800 Subject: [PATCH 04/21] Cleaned up structured logging tests --- tests/test_structured.cpp | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index 15e2f57d92..6c04e7bc68 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -12,21 +12,23 @@ std::string log_info(const std::array& fields, const T &what, spdlog::logger oss_logger("oss", oss_sink); oss_logger.set_pattern("%v"); - oss_logger.slog({}, spdlog::level::info, fields, what, args...); + oss_logger.slog({}, spdlog::level::info, fields, what, std::forward(args)...); return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); } -TEST_CASE("fields ", "[field_construction]") +TEST_CASE("fields ", "[structured]") { + // Can we construct fields of all types with lvalues? spdlog::F("var", 1); spdlog::F("var", "val"); + // Can we construct fields with rvalues? std::string str1("str"); - spdlog::F(str1, 1); + spdlog::F(str1, str1); } -TEST_CASE("field_array ", "[field_array_construction]") +TEST_CASE("build_fields ", "[structured]") { auto array0 = spdlog::build_fields(); REQUIRE(array0.size() == 0); @@ -44,13 +46,16 @@ TEST_CASE("field_array ", "[field_array_construction]") REQUIRE(to_string(std::get(array2[1].value)) == "two"); } -TEST_CASE("field_logging ", "[field_logging]") +TEST_CASE("field_logging ", "[structured]") { // No fields REQUIRE(log_info(spdlog::NO_FIELDS, "Hello") == "Hello"); // Some fields REQUIRE(log_info(spdlog::build_fields(spdlog::F("k", 1)), "Hello") == "Hello"); + + // Fields and fmt + REQUIRE(log_info(spdlog::build_fields(spdlog::F("k", 1)), "Hello {}", "world") == "Hello world"); } TEST_CASE("buffered_msg_field_copies ", "[structured]") From e3f3e65cab8f8b2e470b64959f11384c2c958d7c Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Thu, 13 Jan 2022 10:37:04 -0800 Subject: [PATCH 05/21] Added json formatter --- include/spdlog/common.h | 2 +- include/spdlog/json_formatter-inl.h | 302 ++++++++++++++++++++++++++++ include/spdlog/json_formatter.h | 71 +++++++ src/spdlog.cpp | 1 + tests/CMakeLists.txt | 1 + tests/includes.h | 1 + tests/test_json_formatter.cpp | 111 ++++++++++ 7 files changed, 488 insertions(+), 1 deletion(-) create mode 100644 include/spdlog/json_formatter-inl.h create mode 100644 include/spdlog/json_formatter.h create mode 100644 tests/test_json_formatter.cpp diff --git a/include/spdlog/common.h b/include/spdlog/common.h index 1d30fa9ae9..51bf0f2325 100644 --- a/include/spdlog/common.h +++ b/include/spdlog/common.h @@ -320,7 +320,7 @@ struct file_event_handlers {} }; -using FieldValue = std::variant; //TODO +using FieldValue = std::variant; //TODO struct Field { spdlog::string_view_t name; FieldValue value; diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h new file mode 100644 index 0000000000..c329f65d7a --- /dev/null +++ b/include/spdlog/json_formatter-inl.h @@ -0,0 +1,302 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#pragma once + +#ifndef SPDLOG_HEADER_ONLY +# include +#endif + +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include + +namespace spdlog { + +namespace details { + +constexpr char hex_digits[] = "0123456789abcdef"; + +// 5 -> escape to \uXXXXX +// 1 -> escape to \n, \r or the like +constexpr uint8_t extra_chars_lookup[256] = { + 5, 5, 5, 5, 5, 5, 5, 5, 1, 1, 1, 5, 1, 1, 5, 5, // 0x0x + 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, // 0x1x + 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x2x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x3x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x4x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, // 0x5x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x6x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x7x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x8x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x9x + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xAx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xBx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xCx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xDx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xEx + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xFx +}; + +void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset) +{ + // Check to see if we have any characters that must be escaped + // See https://datatracker.ietf.org/doc/html/rfc8259#section-7 + // Note that only certain ASCII characters need to be; all non-ASCII + // utf-8 codepoints can pass right through + + // TODO: Note that this code is not correct for UTF-8 inputs; if we have + // a UTF-8 value like \u03a3 (Sigma), the UTF-8 encoding is \xCE\xA3, and + // it will be encoded as \u00ce\u00a3 rather than \u03a3. + // + // We need to actually parse the input as utf-8 codepoints to + // know which bytes are consumed in multi-byte utf-8 encodings + // See https://datatracker.ietf.org/doc/html/rfc3629 + + // TODO: widechar support + static_assert(sizeof(dest[0]) ==1, "Wide chars are not supported by escape_to_end yet"); + + size_t extra_chars_required = 0; + for (auto i=start_offset; i < dest.size(); i++) { + uint8_t c = dest[i]; // need to make it unsigned + extra_chars_required += extra_chars_lookup[c]; + } + if (extra_chars_required == 0) { + return; // No escaping to be done + } + size_t original_size = dest.size(); + dest.resize(dest.size() + extra_chars_required); + + // Work backward until done + auto start_p = dest.data() + start_offset; + auto src_p = dest.data() + original_size - 1; + auto dest_p = src_p + extra_chars_required; + while (src_p >= start_p) { + uint8_t c = *src_p; + switch(extra_chars_lookup[c]) { + case 5: + dest_p -= 5; + dest_p[0] = '\\'; + dest_p[1] = 'u'; + dest_p[2] = '0'; + dest_p[3] = '0'; + dest_p[4] = hex_digits[(c >> 4) & 0x0f]; + dest_p[5] = hex_digits[c & 0x0f]; + break; + case 1: + dest_p -= 1; + dest_p[0] = '\\'; + switch(c) { + case '"': + dest_p[1] = '"'; + break; + case '\\': + dest_p[1] = '\\'; + break; + case '\b': + dest_p[1] = 'b'; + break; + case '\f': + dest_p[1] = 'f'; + break; + case '\n': + dest_p[1] = 'n'; + break; + case '\r': + dest_p[1] = 'r'; + break; + case '\t': + dest_p[1] = 't'; + break; + default: + abort(); // should never get here + } // switch(c) + break; + case 0: + *dest_p = c; + break; + default: + abort(); // should never get here + } // switch(extra_chars_lookup[c]) + + dest_p--; + src_p--; + } + + // They should have converged at the start + assert(dest_p == src_p); +} + +class escaped_message_flag : public spdlog::custom_flag_formatter +{ +public: + void format(const spdlog::details::log_msg &msg, const std::tm &, spdlog::memory_buf_t &dest) override + { + size_t start_offset = dest.size(); + fmt_helper::append_string_view(msg.payload, dest); + escape_to_end(dest, start_offset); + } + + std::unique_ptr clone() const override + { + return spdlog::details::make_unique(); + } +}; + +class field_data_flag : public spdlog::custom_flag_formatter +{ +public: + void format(const spdlog::details::log_msg &msg, const std::tm &, spdlog::memory_buf_t &dest) override + { + if (msg.field_data_count > 0 && dest.size() > 0 && dest[dest.size()-1] != '{') { + dest.push_back(','); + dest.push_back(' '); + } + + // TODO: should we keep a hash table of field names->escaped field names? + // If the same fields keep cropping up and have to be escaped again and again it could have + // a small but noticeable impact on performance + for (size_t i=0; i < msg.field_data_count; i++) { + if (i > 0) { + dest.push_back(','); + dest.push_back(' '); + } + auto &field = msg.field_data[i]; + dest.push_back('"'); + size_t offset = dest.size(); + details::fmt_helper::append_string_view(field.name, dest); + escape_to_end(dest, offset); + dest.push_back('"'); + dest.push_back(':'); + + switch(field.value.index()) { + case 0: + dest.push_back('"'); + offset = dest.size(); + details::fmt_helper::append_string_view(std::get(field.value), dest); + escape_to_end(dest, offset); + dest.push_back('"'); + break; + case 1: + fmt_helper::append_int(std::get(field.value), dest); + break; + case 2: + //TODO: optimize this and get rid of allocations + details::fmt_helper::append_string_view(std::to_string(std::get(field.value)), dest); + break; + } + } + } + + std::unique_ptr clone() const override + { + return spdlog::details::make_unique(); + } +}; +} // namespace details + + +SPDLOG_INLINE json_formatter::json_formatter( + pattern_time_type time_type, std::string eol) + : escaped_time_field_name_("ts") + , escaped_message_field_name_("msg") + , escaped_source_loc_field_name_("source") + , escaped_level_field_name_("level") + , escaped_thread_id_field_name_("thread_id") + , internal_formatter_("", time_type, eol) +{ + internal_formatter_.add_flag('V'); + internal_formatter_.add_flag('~'); + compile_pattern(); +} + +SPDLOG_INLINE json_formatter::json_formatter( + std::string escaped_time_field_name, + std::string escaped_message_field_name, + std::string escaped_source_loc_field_name, + std::string escaped_level_field_name, + std::string escaped_thread_id_field_name + ) + : escaped_time_field_name_(escaped_time_field_name) + , escaped_message_field_name_(escaped_message_field_name) + , escaped_source_loc_field_name_(escaped_source_loc_field_name) + , escaped_level_field_name_(escaped_level_field_name) + , escaped_thread_id_field_name_(escaped_thread_id_field_name) + , internal_formatter_("") +{ + internal_formatter_.add_flag('V'); + internal_formatter_.add_flag('~'); + compile_pattern(); +} + +SPDLOG_INLINE std::unique_ptr json_formatter::clone() const +{ + // time_type and eol aren't exposed; clone and overwrite the clone's formatter + // TODO: be able to set the eol_ and time_format_ when we clone + return std::make_unique( + escaped_time_field_name_, escaped_message_field_name_, escaped_source_loc_field_name_, escaped_level_field_name_, escaped_thread_id_field_name_); +} + +SPDLOG_INLINE void json_formatter::compile_pattern() +{ + // Having enumerated fields is a losing battle; we should just have field->pattern, and escape any pattern that isn't + // known-good as a post-process. We need hooks into the pattern formatter to post-process the outputs or walk + // each field and append-then-escape + + // TODO: support custom flag formatters + + memory_buf_t buffer; + buffer.push_back('{'); + if (!escaped_time_field_name_.empty()) { + buffer.push_back('"'); + details::fmt_helper::append_string_view(escaped_time_field_name_, buffer); + details::fmt_helper::append_string_view("\":\"%Y-%m-%dT%H:%M:%S.%f%z\", ", buffer); // don't escape; all values are OK + } + if (!escaped_message_field_name_.empty()) { + buffer.push_back('"'); + details::fmt_helper::append_string_view(escaped_message_field_name_, buffer); + details::fmt_helper::append_string_view("\":\"%V\", ", buffer); // %V --> %v with escaping + } + if (!escaped_source_loc_field_name_.empty()) { + buffer.push_back('"'); + details::fmt_helper::append_string_view(escaped_source_loc_field_name_, buffer); + details::fmt_helper::append_string_view("\":\"%@\", ", buffer); // TODO: escape source filenames; they can have unicode + } + if (!escaped_level_field_name_.empty()) { + buffer.push_back('"'); + details::fmt_helper::append_string_view(escaped_level_field_name_, buffer); + details::fmt_helper::append_string_view("\":\"%l\", ", buffer); // don't escape; all values are OK + } + if (!escaped_thread_id_field_name_.empty()) { + buffer.push_back('"'); + details::fmt_helper::append_string_view(escaped_thread_id_field_name_, buffer); + details::fmt_helper::append_string_view("\":%t, ", buffer); // don't escape; integer + } + + // Strip trailing space if it's there + if (buffer[buffer.size() -1] == ' ') { + buffer.resize(buffer.size() -1); + } + if (buffer[buffer.size() -1] == ',') { + buffer.resize(buffer.size() -1); + } + // %~ for field data and closing brace + details::fmt_helper::append_string_view("%~}", buffer); + internal_formatter_.set_pattern(to_string(buffer)); +} + +SPDLOG_INLINE void json_formatter::format(const details::log_msg &msg, memory_buf_t &dest) +{ + internal_formatter_.format(msg, dest); +} + +} // namespace spdlog diff --git a/include/spdlog/json_formatter.h b/include/spdlog/json_formatter.h new file mode 100644 index 0000000000..ae2279dc3d --- /dev/null +++ b/include/spdlog/json_formatter.h @@ -0,0 +1,71 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#pragma once + +#include +#include +#include +#include +#include + +#include +#include +#include + +#include +#include +#include + +namespace spdlog { + +class SPDLOG_API json_formatter final : public formatter +{ +public: + // Default construction + explicit json_formatter(pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol); + + // To support cloning; note that it takes default time_type and eol + explicit json_formatter( + std::string escaped_time_field_name, + std::string escaped_message_field_name, + std::string escaped_source_loc_field_name, + std::string escaped_level_field_name, + std::string escaped_thread_id_field_name + ); + + // Set field name to "" to not emit the field + json_formatter & set_time_field(string_view_t time_field_name, pattern_time_type); + json_formatter & set_message_field(string_view_t message_field_name); + json_formatter & set_source_loc_field(string_view_t source_loc_field_name); + json_formatter & set_level_field(string_view_t level_field_name); + json_formatter & set_thread_id_field(string_view_t thread_id_field_name); + + json_formatter(const json_formatter &other) = delete; + json_formatter &operator=(const json_formatter &other) = delete; + + std::unique_ptr clone() const override; + void format(const details::log_msg &msg, memory_buf_t &dest) override; + +private: + void compile_pattern(); + + pattern_time_type pattern_time_type_; + std::string escaped_time_field_name_; + std::string escaped_message_field_name_; + std::string escaped_source_loc_field_name_; + std::string escaped_level_field_name_; + std::string escaped_thread_id_field_name_; + + spdlog::pattern_formatter internal_formatter_; +}; + +namespace details { + void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset); +} // namespace details + +} // namespace spdlog + +#ifdef SPDLOG_HEADER_ONLY +# include "json_formatter-inl.h" +#endif diff --git a/src/spdlog.cpp b/src/spdlog.cpp index c86d8fff59..958d8798d3 100644 --- a/src/spdlog.cpp +++ b/src/spdlog.cpp @@ -10,6 +10,7 @@ #include #include #include +#include #include #include #include diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 9aeb438f8b..ad1055221c 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -19,6 +19,7 @@ set(SPDLOG_UTESTS_SOURCES test_daily_logger.cpp test_misc.cpp test_eventlog.cpp + test_json_formatter.cpp test_pattern_formatter.cpp test_async.cpp test_registry.cpp diff --git a/tests/includes.h b/tests/includes.h index f5392b6132..43df8734e3 100644 --- a/tests/includes.h +++ b/tests/includes.h @@ -23,5 +23,6 @@ #include "spdlog/sinks/ostream_sink.h" #include "spdlog/sinks/rotating_file_sink.h" #include "spdlog/sinks/stdout_color_sinks.h" +#include "spdlog/json_formatter.h" #include "spdlog/pattern_formatter.h" #include "spdlog/structured_spdlog.h" diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp new file mode 100644 index 0000000000..5dec25ca49 --- /dev/null +++ b/tests/test_json_formatter.cpp @@ -0,0 +1,111 @@ +#include "includes.h" +#include "test_sink.h" + +#include + +using spdlog::memory_buf_t; +using spdlog::NO_FIELDS; +using Catch::Matchers::Matches; + +// log to str and return it +template +static std::string log_to_str(const std::string &msg, const std::array& fields, const Args &... args) +{ + std::ostringstream oss; + auto oss_sink = std::make_shared(oss); + spdlog::logger oss_logger("json_tester", oss_sink); + oss_logger.set_level(spdlog::level::info); + + oss_logger.set_formatter(std::unique_ptr(new spdlog::json_formatter(args...))); + oss_logger.slog(spdlog::source_loc{"source.cpp", 99, "fn"}, spdlog::level::info, fields, msg); + + return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); +} + +TEST_CASE("json basic output", "[json_formatter]") +{ + // Test fields with static outputs + REQUIRE(log_to_str("hello", NO_FIELDS, "", "MSG", "SRC", "LEVEL", "") == R"({"MSG":"hello", "SRC":"source.cpp:99", "LEVEL":"info"})"); + + // Tests with regex outputs + REQUIRE_THAT(log_to_str("hello", NO_FIELDS, "", "", "", "", "THREAD"), Matches(R"(\{"THREAD":[0-9]+\})")); + // Time regex lifted from https://www.myintervals.com/blog/2009/05/20/iso-8601-date-validation-that-doesnt-suck/ + // Trimmed of leading ^ and trailing $ + constexpr char ISO8601_REGEX[] = R"(([\+-]?\d{4}(?!\d{2}\b))((-?)((0[1-9]|1[0-2])(\3([12]\d|0[1-9]|3[01]))?|W([0-4]\d|5[0-2])(-?[1-7])?|(00[1-9]|0[1-9]\d|[12]\d{2}|3([0-5]\d|6[1-6])))([T\s]((([01]\d|2[0-3])((:?)[0-5]\d)?|24\:?00)([\.,]\d+(?!:))?)?(\17[0-5]\d([\.,]\d+)?)?([zZ]|([\+-])([01]\d|2[0-3]):?([0-5]\d)?)?)?)?)"; + std::string time_output_regex = std::string(R"(\{"TM":")") + std::string(ISO8601_REGEX) + std::string(R"("\})"); + REQUIRE_THAT(log_to_str("hello", NO_FIELDS, "TM", "", "", "", ""), Matches(time_output_regex)); + + // Fields alone + auto fields = spdlog::build_fields(spdlog::F("f1", 1), spdlog::F("f2", "two"), spdlog::F("f3", 3.0)); + REQUIRE(log_to_str("hello", fields, "", "", "", "", "") == R"({"f1":1, "f2":"two", "f3":3.000000})"); + + // Fields with message + REQUIRE(log_to_str("hello", fields, "", "MSG", "", "", "") == R"({"MSG":"hello", "f1":1, "f2":"two", "f3":3.000000})"); +} + +TEST_CASE("json escaping", "[json_formatter]") +{ + // No escaping + memory_buf_t buffer; + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("hello", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "hello"); + + // Escaping in the middle + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("hello_\x1d_goodbye", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "hello_\\u001d_goodbye"); + + // Escaping at beginning and end + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("\x1d_hello_\x1a", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "\\u001d_hello_\\u001a"); + + // Wholly escaped + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("\x1d", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "\\u001d"); + + // Null string + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == ""); + + // Special characters + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + spdlog::details::fmt_helper::append_string_view("\\\r\n\t\b\f\"", buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == "\\\\\\r\\n\\t\\b\\f\\\""); + + // Not escaped + buffer.resize(256 - 39); + char *p = &buffer[0]; + for (int c=0; c <= 255; c++) { + if (c <= 0x1f || c == '"' || c == '\\' || c == '\b' || c == '\f' || c == '\n' || c == '\r' || c == '\t') + continue; + *(p++) = static_cast(c); + } + auto before = to_string(buffer); + spdlog::details::escape_to_end(buffer, 0); + REQUIRE(to_string(buffer) == before); + + // Skipping alread-esacped parts + buffer.resize(0); + memset(&buffer[0], '~', buffer.capacity()); + std::string already_done{"\\\"foo\": \""}; + spdlog::details::fmt_helper::append_string_view(already_done, buffer); + spdlog::details::fmt_helper::append_string_view("bar\n", buffer); + spdlog::details::escape_to_end(buffer, already_done.size()); + REQUIRE(to_string(buffer) == "\\\"foo\": \"bar\\n"); + +} From b7fd915d66b96314efca39261bfff09ce6e54f28 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Fri, 14 Jan 2022 06:49:46 -0800 Subject: [PATCH 06/21] Moved JSON formatter to be artibrary-flag-based --- include/spdlog/json_formatter-inl.h | 275 +++++++++++++++------------- include/spdlog/json_formatter.h | 57 +++--- tests/test_json_formatter.cpp | 72 ++++++-- 3 files changed, 242 insertions(+), 162 deletions(-) diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h index c329f65d7a..663b2250df 100644 --- a/include/spdlog/json_formatter-inl.h +++ b/include/spdlog/json_formatter-inl.h @@ -47,6 +47,10 @@ constexpr uint8_t extra_chars_lookup[256] = { 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0xFx }; +// TODO: make a version that can take a list of [start,end] ranges; we can then +// write the whole line to the dest buffer and do one pass of escaping: count, +// realloc, escape + void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset) { // Check to see if we have any characters that must be escaped @@ -136,167 +140,186 @@ void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset) assert(dest_p == src_p); } -class escaped_message_flag : public spdlog::custom_flag_formatter +SPDLOG_INLINE bool pattern_needs_escaping(string_view_t pattern) { -public: - void format(const spdlog::details::log_msg &msg, const std::tm &, spdlog::memory_buf_t &dest) override - { - size_t start_offset = dest.size(); - fmt_helper::append_string_view(msg.payload, dest); - escape_to_end(dest, start_offset); - } + // Look for any % pattern that isn't in our whitelist of known-doesn't-need-escaping patterns + // Anything that can only emit printable ASCII is OK. - std::unique_ptr clone() const override - { - return spdlog::details::make_unique(); - } -}; + constexpr char KNOWN_CLEAN_PATTERNS[] = "LtplLaAbBcCYDxmdHIMSefFprRTXzE%#oiuO"; -class field_data_flag : public spdlog::custom_flag_formatter -{ -public: - void format(const spdlog::details::log_msg &msg, const std::tm &, spdlog::memory_buf_t &dest) override - { - if (msg.field_data_count > 0 && dest.size() > 0 && dest[dest.size()-1] != '{') { - dest.push_back(','); - dest.push_back(' '); - } + for (size_t i=0; i < pattern.size(); i++) { + // Check for % flags + uint8_t c = static_cast(pattern[i]); + if (c == '%' && i < pattern.size() - 1) { + i++; + c = static_cast(pattern[i]); - // TODO: should we keep a hash table of field names->escaped field names? - // If the same fields keep cropping up and have to be escaped again and again it could have - // a small but noticeable impact on performance - for (size_t i=0; i < msg.field_data_count; i++) { - if (i > 0) { - dest.push_back(','); - dest.push_back(' '); - } - auto &field = msg.field_data[i]; - dest.push_back('"'); - size_t offset = dest.size(); - details::fmt_helper::append_string_view(field.name, dest); - escape_to_end(dest, offset); - dest.push_back('"'); - dest.push_back(':'); - - switch(field.value.index()) { - case 0: - dest.push_back('"'); - offset = dest.size(); - details::fmt_helper::append_string_view(std::get(field.value), dest); - escape_to_end(dest, offset); - dest.push_back('"'); - break; - case 1: - fmt_helper::append_int(std::get(field.value), dest); - break; - case 2: - //TODO: optimize this and get rid of allocations - details::fmt_helper::append_string_view(std::to_string(std::get(field.value)), dest); + // TODO: make this a binary search + bool flag_char_is_clean = false; + for (auto clean: KNOWN_CLEAN_PATTERNS) { + if (clean == c) { + flag_char_is_clean = true; break; + } + } + if (!flag_char_is_clean) { + return true; } } + + // Check for json-escaped character in pattern + if (extra_chars_lookup[c] != 0) { + return true; + } } + return false; +} - std::unique_ptr clone() const override - { - return spdlog::details::make_unique(); +SPDLOG_INLINE pattern_field::pattern_field(const std::string &name, const std::string &pattern, json_field_type field_type, pattern_time_type pattern_time_type_) : + formatter_(std::make_unique(pattern, pattern_time_type_, "")), + field_type_(field_type) +{ + // TODO - make this all one pattern {"name": "%v", }; since we know the prefix and suffix length, + // we can do one call to format(), then escape just the questionable data + memory_buf_t value_prefix; + value_prefix.push_back('"'); + fmt_helper::append_string_view(name, value_prefix); + escape_to_end(value_prefix, 1); + value_prefix.push_back('"'); + value_prefix.push_back(':'); + value_prefix_ = to_string(value_prefix); + + output_needs_escaping_ = pattern_needs_escaping(pattern); +} + +SPDLOG_INLINE pattern_field::pattern_field(const std::string &value_prefix, formatter* formatter, json_field_type field_type, bool output_needs_escaping) : + value_prefix_(value_prefix), formatter_(std::move(formatter->clone())), field_type_(field_type), output_needs_escaping_(output_needs_escaping) +{ +} + +SPDLOG_INLINE std::unique_ptr pattern_field::clone() +{ + return std::make_unique(value_prefix_, formatter_.get(), field_type_, output_needs_escaping_); +} + +SPDLOG_INLINE void pattern_field::format(const details::log_msg &msg, memory_buf_t &dest) +{ + fmt_helper::append_string_view(value_prefix_, dest); + if (field_type_ == json_field_type::STRING) { + dest.push_back('"'); } -}; + size_t start_offset = dest.size(); + formatter_->format(msg, dest); + if (output_needs_escaping_) { + escape_to_end(dest, start_offset); + } + if (field_type_ == json_field_type::STRING) { + fmt_helper::append_string_view("\", ", dest); + } else { + fmt_helper::append_string_view(", ", dest); + } +} + } // namespace details -SPDLOG_INLINE json_formatter::json_formatter( - pattern_time_type time_type, std::string eol) - : escaped_time_field_name_("ts") - , escaped_message_field_name_("msg") - , escaped_source_loc_field_name_("source") - , escaped_level_field_name_("level") - , escaped_thread_id_field_name_("thread_id") - , internal_formatter_("", time_type, eol) +SPDLOG_INLINE json_formatter::json_formatter(pattern_time_type time_type, std::string eol) : + pattern_time_type_(time_type), + eol_(eol) { - internal_formatter_.add_flag('V'); - internal_formatter_.add_flag('~'); - compile_pattern(); } -SPDLOG_INLINE json_formatter::json_formatter( - std::string escaped_time_field_name, - std::string escaped_message_field_name, - std::string escaped_source_loc_field_name, - std::string escaped_level_field_name, - std::string escaped_thread_id_field_name - ) - : escaped_time_field_name_(escaped_time_field_name) - , escaped_message_field_name_(escaped_message_field_name) - , escaped_source_loc_field_name_(escaped_source_loc_field_name) - , escaped_level_field_name_(escaped_level_field_name) - , escaped_thread_id_field_name_(escaped_thread_id_field_name) - , internal_formatter_("") +SPDLOG_INLINE json_formatter& json_formatter::add_default_fields() { - internal_formatter_.add_flag('V'); - internal_formatter_.add_flag('~'); - compile_pattern(); + return add_field("time", ISO8601_FLAGS).add_field("level", "%l"). + add_field("msg", "%v", json_field_type::STRING).add_field("src_loc", "%@"); } -SPDLOG_INLINE std::unique_ptr json_formatter::clone() const +SPDLOG_INLINE json_formatter &json_formatter::add_field(std::string field_name, std::string pattern, json_field_type field_type) { - // time_type and eol aren't exposed; clone and overwrite the clone's formatter - // TODO: be able to set the eol_ and time_format_ when we clone - return std::make_unique( - escaped_time_field_name_, escaped_message_field_name_, escaped_source_loc_field_name_, escaped_level_field_name_, escaped_thread_id_field_name_); + fields_.emplace_back( + std::make_unique(field_name, pattern, field_type, pattern_time_type_) + ); + return *this; } -SPDLOG_INLINE void json_formatter::compile_pattern() + +SPDLOG_INLINE std::unique_ptr json_formatter::clone() const { + auto result = std::make_unique(pattern_time_type_, eol_); + for (auto &field: fields_) { + result->fields_.emplace_back(std::move(field->clone())); + } + return result; +} + +// SPDLOG_INLINE void json_formatter::compile_pattern() +// { // Having enumerated fields is a losing battle; we should just have field->pattern, and escape any pattern that isn't // known-good as a post-process. We need hooks into the pattern formatter to post-process the outputs or walk // each field and append-then-escape +// } + +SPDLOG_INLINE void json_formatter::format_data_fields(const Field * fields, size_t field_count, spdlog::memory_buf_t &dest) +{ + // TODO: should we keep a hash table of field names->escaped field names? + // If the same fields keep cropping up and have to be escaped again and again it could have + // a small but noticeable impact on performance + for (size_t i=0; i < field_count; i++) { + auto &field = fields[i]; + dest.push_back('"'); + size_t offset = dest.size(); + details::fmt_helper::append_string_view(field.name, dest); + details::escape_to_end(dest, offset); + dest.push_back('"'); + dest.push_back(':'); + + switch(field.value.index()) { + case 0: + dest.push_back('"'); + offset = dest.size(); + details::fmt_helper::append_string_view(std::get(field.value), dest); + details::escape_to_end(dest, offset); + dest.push_back('"'); + break; + case 1: + details::fmt_helper::append_int(std::get(field.value), dest); + break; + case 2: + //TODO: optimize this and get rid of allocations + details::fmt_helper::append_string_view(std::to_string(std::get(field.value)), dest); + break; + } + + dest.push_back(','); + dest.push_back(' '); + } +} + + +SPDLOG_INLINE void json_formatter::format(const details::log_msg &msg, memory_buf_t &dest) +{ // TODO: support custom flag formatters + // TODO: all safe fields can be compiled into one pattern formatter memory_buf_t buffer; - buffer.push_back('{'); - if (!escaped_time_field_name_.empty()) { - buffer.push_back('"'); - details::fmt_helper::append_string_view(escaped_time_field_name_, buffer); - details::fmt_helper::append_string_view("\":\"%Y-%m-%dT%H:%M:%S.%f%z\", ", buffer); // don't escape; all values are OK - } - if (!escaped_message_field_name_.empty()) { - buffer.push_back('"'); - details::fmt_helper::append_string_view(escaped_message_field_name_, buffer); - details::fmt_helper::append_string_view("\":\"%V\", ", buffer); // %V --> %v with escaping - } - if (!escaped_source_loc_field_name_.empty()) { - buffer.push_back('"'); - details::fmt_helper::append_string_view(escaped_source_loc_field_name_, buffer); - details::fmt_helper::append_string_view("\":\"%@\", ", buffer); // TODO: escape source filenames; they can have unicode - } - if (!escaped_level_field_name_.empty()) { - buffer.push_back('"'); - details::fmt_helper::append_string_view(escaped_level_field_name_, buffer); - details::fmt_helper::append_string_view("\":\"%l\", ", buffer); // don't escape; all values are OK - } - if (!escaped_thread_id_field_name_.empty()) { - buffer.push_back('"'); - details::fmt_helper::append_string_view(escaped_thread_id_field_name_, buffer); - details::fmt_helper::append_string_view("\":%t, ", buffer); // don't escape; integer + dest.push_back('{'); + + for (auto &field_ptr: fields_) { + field_ptr->format(msg, dest); } + format_data_fields(msg.field_data, msg.field_data_count, dest); // Strip trailing space if it's there - if (buffer[buffer.size() -1] == ' ') { - buffer.resize(buffer.size() -1); + if (dest[dest.size() -1] == ' ') { + dest.resize(dest.size() -1); } - if (buffer[buffer.size() -1] == ',') { - buffer.resize(buffer.size() -1); + if (dest[dest.size() -1] == ',') { + dest.resize(dest.size() -1); } - // %~ for field data and closing brace - details::fmt_helper::append_string_view("%~}", buffer); - internal_formatter_.set_pattern(to_string(buffer)); -} - -SPDLOG_INLINE void json_formatter::format(const details::log_msg &msg, memory_buf_t &dest) -{ - internal_formatter_.format(msg, dest); + dest.push_back('}'); + details::fmt_helper::append_string_view(eol_, dest); } } // namespace spdlog diff --git a/include/spdlog/json_formatter.h b/include/spdlog/json_formatter.h index ae2279dc3d..d3dd52ca38 100644 --- a/include/spdlog/json_formatter.h +++ b/include/spdlog/json_formatter.h @@ -19,27 +19,41 @@ namespace spdlog { +constexpr char ISO8601_FLAGS[] = "%Y-%m-%dT%H:%M:%S.%f%z"; + +enum class json_field_type {NUMERIC, STRING}; +namespace details { + void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset); + bool pattern_needs_escaping(string_view_t pattern); + + class pattern_field { + public: + pattern_field(const std::string &name, const std::string &pattern, json_field_type field_type, pattern_time_type pattern_time_type_); + pattern_field(const std::string &name, formatter* formatter, json_field_type field_type, bool output_needs_escaping); + + pattern_field(const pattern_field &other) = delete; + pattern_field &operator=(const pattern_field &other) = delete; + + void format(const details::log_msg &msg, memory_buf_t &dest); + + std::unique_ptr clone(); + private: + std::string value_prefix_; // {"name":} + std::unique_ptr formatter_; + json_field_type field_type_; + bool output_needs_escaping_; + }; +} // namespace details + class SPDLOG_API json_formatter final : public formatter { public: + // Default construction explicit json_formatter(pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol); + json_formatter &add_field(std::string field_name, std::string pattern, json_field_type field_type = json_field_type::STRING); + json_formatter &add_default_fields(); - // To support cloning; note that it takes default time_type and eol - explicit json_formatter( - std::string escaped_time_field_name, - std::string escaped_message_field_name, - std::string escaped_source_loc_field_name, - std::string escaped_level_field_name, - std::string escaped_thread_id_field_name - ); - - // Set field name to "" to not emit the field - json_formatter & set_time_field(string_view_t time_field_name, pattern_time_type); - json_formatter & set_message_field(string_view_t message_field_name); - json_formatter & set_source_loc_field(string_view_t source_loc_field_name); - json_formatter & set_level_field(string_view_t level_field_name); - json_formatter & set_thread_id_field(string_view_t thread_id_field_name); json_formatter(const json_formatter &other) = delete; json_formatter &operator=(const json_formatter &other) = delete; @@ -48,21 +62,14 @@ class SPDLOG_API json_formatter final : public formatter void format(const details::log_msg &msg, memory_buf_t &dest) override; private: - void compile_pattern(); + void format_data_fields(const Field * fields, size_t field_count, spdlog::memory_buf_t &dest); pattern_time_type pattern_time_type_; - std::string escaped_time_field_name_; - std::string escaped_message_field_name_; - std::string escaped_source_loc_field_name_; - std::string escaped_level_field_name_; - std::string escaped_thread_id_field_name_; + std::string eol_; - spdlog::pattern_formatter internal_formatter_; + std::vector> fields_; }; -namespace details { - void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset); -} // namespace details } // namespace spdlog diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp index 5dec25ca49..8a6bc5a739 100644 --- a/tests/test_json_formatter.cpp +++ b/tests/test_json_formatter.cpp @@ -5,18 +5,34 @@ using spdlog::memory_buf_t; using spdlog::NO_FIELDS; +using spdlog::json_field_type; using Catch::Matchers::Matches; // log to str and return it +struct field_patterns { + std::string name; + std::string pattern; + spdlog::json_field_type field_type = json_field_type::STRING; +}; + template -static std::string log_to_str(const std::string &msg, const std::array& fields, const Args &... args) +static std::string log_to_str(const std::string &msg, const std::array& fields, + std::initializer_list patterns, bool use_default_patterns = false) { std::ostringstream oss; auto oss_sink = std::make_shared(oss); spdlog::logger oss_logger("json_tester", oss_sink); oss_logger.set_level(spdlog::level::info); - oss_logger.set_formatter(std::unique_ptr(new spdlog::json_formatter(args...))); + auto formatter = new spdlog::json_formatter; + if (!use_default_patterns) { + for (auto &pattern: patterns) { + formatter->add_field(pattern.name, pattern.pattern, pattern.field_type); + } + } else { + formatter->add_default_fields(); + } + oss_logger.set_formatter(std::unique_ptr(formatter)); oss_logger.slog(spdlog::source_loc{"source.cpp", 99, "fn"}, spdlog::level::info, fields, msg); return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); @@ -24,23 +40,43 @@ static std::string log_to_str(const std::string &msg, const std::array Date: Fri, 14 Jan 2022 19:22:37 -0800 Subject: [PATCH 07/21] Refactor to be C++11 compatible --- cmake/pch.h.in | 258 -------------------- include/spdlog/common.h | 48 +++- include/spdlog/details/log_msg_buffer-inl.h | 18 +- include/spdlog/json_formatter-inl.h | 58 +++-- include/spdlog/structured_spdlog-inl.h | 57 +++++ include/spdlog/structured_spdlog.h | 31 +-- src/spdlog.cpp | 1 + tests/test_json_formatter.cpp | 23 +- tests/test_structured.cpp | 75 +++++- 9 files changed, 233 insertions(+), 336 deletions(-) delete mode 100644 cmake/pch.h.in create mode 100644 include/spdlog/structured_spdlog-inl.h diff --git a/cmake/pch.h.in b/cmake/pch.h.in deleted file mode 100644 index a5f9415071..0000000000 --- a/cmake/pch.h.in +++ /dev/null @@ -1,258 +0,0 @@ -// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. -// Distributed under the MIT License (http://opensource.org/licenses/MIT) - -#pragma once - -// details/pattern_formatter-inl.h -// fmt/bin_to_hex.h -// fmt/bundled/format-inl.h -#include - -// details/file_helper-inl.h -// details/os-inl.h -// fmt/bundled/core.h -// fmt/bundled/posix.h -// logger-inl.h -// sinks/daily_file_sink.h -// sinks/stdout_sinks.h -#include - -// details/os-inl.h -// fmt/bundled/posix.h -#include - -// details/os-inl.h -// details/pattern_formatter-inl.h -// fmt/bundled/core.h -// fmt/bundled/format-inl.h -#include - -// details/os-inl.h -// details/os.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// fmt/bundled/chrono.h -// sinks/daily_file_sink.h -// sinks/rotating_file_sink-inl.h -#include - -// fmt/bundled/format-inl.h -#include - -// fmt/bundled/format-inl.h -#include - -// fmt/bundled/format-inl.h -// fmt/bundled/format.h -#include - -// fmt/bundled/format-inl.h -#include - -// details/file_helper-inl.h -// fmt/bundled/format.h -// fmt/bundled/posix.h -// sinks/rotating_file_sink-inl.h -#include - -// details/circular_q.h -// details/thread_pool-inl.h -// fmt/bundled/format-inl.h -#include - -// async_logger-inl.h -// cfg/helpers-inl.h -// log_levels.h -// common.h -// details/file_helper-inl.h -// details/log_msg.h -// details/os-inl.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// details/registry-inl.h -// details/registry.h -// details/tcp_client-windows.h -// details/tcp_client.h -// fmt/bundled/core.h -// sinks/android_sink.h -// sinks/ansicolor_sink.h -// sinks/basic_file_sink.h -// sinks/daily_file_sink.h -// sinks/dup_filter_sink.h -// sinks/msvc_sink.h -// sinks/ringbuffer_sink.h -// sinks/rotating_file_sink-inl.h -// sinks/rotating_file_sink.h -// sinks/syslog_sink.h -// sinks/tcp_sink.h -// sinks/win_eventlog_sink.h -// sinks/wincolor_sink.h -// spdlog.h: -#include - -// cfg/helpers-inl.h -// fmt/bundled/chrono.h -#include - -// fmt/bundled/ostream.h -// sinks/ostream_sink.h -#include - -// cfg/log_levels.h -// details/registry-inl.h -// details/registry.h -#include - -// details/circular_q.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// details/thread_pool.h -// fmt/bundled/compile.h -// logger.h -// sinks/dist_sink.h -// sinks/ringbuffer_sink.h -// sinks/win_eventlog_sink.h -#include - -// details/os-inl.h -// details/pattern_formatter-inl.h -// sinks/ansicolor_sink.h -// sinks/syslog_sink.h -// sinks/systemd_sink.h -// sinks/wincolor_sink.h -#include - -// details/file_helper-inl.h -// details/file_helper.h -// sinks/rotating_file_sink-inl.h -#include - -// details/os-inl.h -// fmt/bundled/format.h -// fmt/bundled/printf.h -#include - -// common.h -// details/backtracer.h -// details/null_mutex.h -#include - -// common.h -// details/backtracer.h -// details/null_mutex.h -#include - -// common.h -#include - -// common.h -#include - -// common.h -// details/fmt_helper.h -// fmt/bundled/core.h -// fmt/bundled/ranges.h -#include - -// cfg/helpers-inl.h -// details/null_mutex.h -// details/pattern_formatter-inl.h -#include - -// async.h -// async_logger-inl.h -// common.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// details/registry-inl.h -// details/registry.h -// details/thread_pool.h -// fmt/bundled/format.h -// sinks/ansicolor_sink.h -// sinks/base_sink-inl.h -// sinks/dist_sink.h -// sinks/stdout_sinks-inl.h -// sinks/wincolor_sink.h -// spdlog.h -#include - -// async.h -// common.h -// details/backtracer.h -// details/periodic_worker.h -// details/registry-inl.h -// details/registry.h -// details/thread_pool.h -// sinks/tcp_sink.h -// spdlog.h -#include - -// details/mpmc_blocking_q.h -// details/periodic_worker.h -#include - -// details/os-inl.h -// fmt/bundled/format.h -// fmt/bundled/printf.h -// sinks/dist_sink.h -#include - -// common.h -// details/file_helper-inl.h -// details/fmt_helper.h -// details/os-inl.h -// details/pattern_formatter-inl.h -// details/pattern_formatter.h -// details/periodic_worker.h -// details/registry-inl.h -// details/registry.h -// details/thread_pool.h -// fmt/bundled/chrono.h -// sinks/android_sink.h -// sinks/daily_file_sink.h -// sinks/dup_filter_sink.h -// sinks/rotating_file_sink-inl.h -// sinks/rotating_file_sink.h -// sinks/tcp_sink.h -// spdlog.h -#include - -// details/file_helper-inl.h -// details/os-inl.h -// details/pattern_formatter-inl.h -// details/periodic_worker.h -// details/thread_pool.h -// sinks/android_sink.h -#include - -// async.h -// details/backtracer.h -// details/console_globals.h -// details/mpmc_blocking_q.h -// details/pattern_formatter-inl.h -// details/periodic_worker.h -// details/registry.h -// sinks/android_sink.h -// sinks/ansicolor_sink.h -// sinks/basic_file_sink.h -// sinks/daily_file_sink.h -// sinks/dist_sink.h -// sinks/dup_filter_sink.h -// sinks/msvc_sink.h -// sinks/null_sink.h -// sinks/ostream_sink.h -// sinks/ringbuffer_sink.h -// sinks/rotating_file_sink-inl.h -// sinks/rotating_file_sink.h -// sinks/tcp_sink.h -// sinks/win_eventlog_sink.h -// sinks/wincolor_sink.h -// -// color_sinks.cpp -// file_sinks.cpp -// spdlog.cpp -// stdout_sinks.cpp -#include - -// spdlog -#include \ No newline at end of file diff --git a/include/spdlog/common.h b/include/spdlog/common.h index 51bf0f2325..c57622b03f 100644 --- a/include/spdlog/common.h +++ b/include/spdlog/common.h @@ -15,7 +15,6 @@ #include #include #include -#include #ifdef SPDLOG_USE_STD_FORMAT # include @@ -320,11 +319,54 @@ struct file_event_handlers {} }; -using FieldValue = std::variant; //TODO +// Cover all fundamental types for C++ plus string_view +// see https://en.cppreference.com/w/cpp/language/types +// This would be better handled by a C++14 std::variant type, but we want to stay C++11-compatible +enum class FieldValueType { + STRING_VIEW, + SHORT, USHORT, INT, UINT, LONG, ULONG, LONGLONG, ULONGLONG, + BOOL, + CHAR, UCHAR, WCHAR, + FLOAT, DOUBLE, LONGDOUBLE +}; + struct Field { spdlog::string_view_t name; - FieldValue value; + FieldValueType value_type; + union { + string_view_t string_view_; + short short_; unsigned short ushort_; int int_; unsigned int uint_; + long long_; unsigned long ulong_; long long longlong_; unsigned long long ulonglong_; + bool bool_; + char char_; unsigned char uchar_; wchar_t wchar_; + float float_; double double_; long double longdouble_; + }; + Field(const string_view_t &field_name, FieldValueType field_type) : + name(field_name), value_type(field_type) {}; + Field() : name{}, value_type(FieldValueType::INT), int_(0) {} + + Field(const string_view_t &field_name, string_view_t val): name(field_name), value_type(FieldValueType::STRING_VIEW), string_view_(val) {} + Field(const string_view_t &field_name, short val): name(field_name), value_type(FieldValueType::SHORT), short_ (val) {} + Field(const string_view_t &field_name, unsigned short val): name(field_name), value_type(FieldValueType::USHORT), ushort_ (val) {} + Field(const string_view_t &field_name, int val): name(field_name), value_type(FieldValueType::INT), int_ (val) {} + Field(const string_view_t &field_name, unsigned int val): name(field_name), value_type(FieldValueType::UINT), uint_ (val) {} + Field(const string_view_t &field_name, long val): name(field_name), value_type(FieldValueType::LONG), long_ (val) {} + Field(const string_view_t &field_name, unsigned long val): name(field_name), value_type(FieldValueType::ULONG), ulong_ (val) {} + Field(const string_view_t &field_name, long long val): name(field_name), value_type(FieldValueType::LONGLONG), longlong_ (val) {} + Field(const string_view_t &field_name, unsigned long long val): name(field_name), value_type(FieldValueType::ULONGLONG), ulonglong_ (val) {} + Field(const string_view_t &field_name, bool val): name(field_name), value_type(FieldValueType::BOOL), bool_ (val) {} + Field(const string_view_t &field_name, char val): name(field_name), value_type(FieldValueType::CHAR), char_ (val) {} + Field(const string_view_t &field_name, unsigned char val): name(field_name), value_type(FieldValueType::UCHAR), uchar_ (val) {} + Field(const string_view_t &field_name, wchar_t val): name(field_name), value_type(FieldValueType::WCHAR), wchar_ (val) {} + Field(const string_view_t &field_name, float val): name(field_name), value_type(FieldValueType::FLOAT), float_ (val) {} + Field(const string_view_t &field_name, double val): name(field_name), value_type(FieldValueType::DOUBLE), double_ (val) {} + Field(const string_view_t &field_name, long double val): name(field_name), value_type(FieldValueType::LONGDOUBLE), longdouble_ (val) {} + + // Catch static strings so they don't get converted to bools + template + Field(const string_view_t &field_name, const char (&val)[N]): name(field_name), value_type(FieldValueType::STRING_VIEW), string_view_{val, N-1} {} }; +using F=Field; constexpr auto NO_FIELDS = std::array(); namespace details { diff --git a/include/spdlog/details/log_msg_buffer-inl.h b/include/spdlog/details/log_msg_buffer-inl.h index 952a7fbbb0..a735f57a0e 100644 --- a/include/spdlog/details/log_msg_buffer-inl.h +++ b/include/spdlog/details/log_msg_buffer-inl.h @@ -21,9 +21,8 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg &orig_msg) buffer.append(reinterpret_cast(field_data), reinterpret_cast(field_data + field_data_count)); for (size_t i=0; i < field_data_count; i++) { buffer.append(field_data[i].name); - auto string_view_p = std::get_if(&field_data[i].value); - if (string_view_p) { - buffer.append(string_view_p->begin(), string_view_p->end()); + if (field_data[i].value_type == FieldValueType::STRING_VIEW) { + buffer.append(field_data[i].string_view_.begin(), field_data[i].string_view_.end()); } } #endif @@ -41,9 +40,8 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg_buffer &other) buffer.append(reinterpret_cast(field_data), reinterpret_cast(field_data + field_data_count)); for (size_t i=0; i < field_data_count; i++) { buffer.append(field_data[i].name); - auto string_view_p = std::get_if(&field_data[i].value); - if (string_view_p) { - buffer.append(string_view_p->begin(), string_view_p->end()); + if (field_data[i].value_type == FieldValueType::STRING_VIEW) { + buffer.append(field_data[i].string_view_.begin(), field_data[i].string_view_.end()); } } #endif @@ -86,10 +84,10 @@ SPDLOG_INLINE void log_msg_buffer::update_string_views() for (size_t i=0; i < field_data_count; i++) { field_data[i].name = string_view_t{buffer.data() + offset, field_data[i].name.size()}; offset += field_data[i].name.size(); - auto string_view_p = std::get_if(&field_data[i].value); - if (string_view_p) { - field_data[i].value = FieldValue(string_view_t{buffer.data() + offset, string_view_p->size()}); - offset += string_view_p->size(); + if (field_data[i].value_type == FieldValueType::STRING_VIEW) { + auto &data_value = field_data[i].string_view_; + data_value = {buffer.data() + offset, data_value.size()}; + offset += data_value.size(); } } #endif diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h index 663b2250df..b674de82e6 100644 --- a/include/spdlog/json_formatter-inl.h +++ b/include/spdlog/json_formatter-inl.h @@ -11,6 +11,7 @@ #include #include #include +#include #include #include @@ -176,7 +177,7 @@ SPDLOG_INLINE bool pattern_needs_escaping(string_view_t pattern) } SPDLOG_INLINE pattern_field::pattern_field(const std::string &name, const std::string &pattern, json_field_type field_type, pattern_time_type pattern_time_type_) : - formatter_(std::make_unique(pattern, pattern_time_type_, "")), + formatter_(details::make_unique(pattern, pattern_time_type_, "")), field_type_(field_type) { // TODO - make this all one pattern {"name": "%v", }; since we know the prefix and suffix length, @@ -199,7 +200,7 @@ SPDLOG_INLINE pattern_field::pattern_field(const std::string &value_prefix, form SPDLOG_INLINE std::unique_ptr pattern_field::clone() { - return std::make_unique(value_prefix_, formatter_.get(), field_type_, output_needs_escaping_); + return make_unique(value_prefix_, formatter_.get(), field_type_, output_needs_escaping_); } SPDLOG_INLINE void pattern_field::format(const details::log_msg &msg, memory_buf_t &dest) @@ -238,7 +239,7 @@ SPDLOG_INLINE json_formatter& json_formatter::add_default_fields() SPDLOG_INLINE json_formatter &json_formatter::add_field(std::string field_name, std::string pattern, json_field_type field_type) { fields_.emplace_back( - std::make_unique(field_name, pattern, field_type, pattern_time_type_) + details::make_unique(field_name, pattern, field_type, pattern_time_type_) ); return *this; } @@ -246,20 +247,35 @@ SPDLOG_INLINE json_formatter &json_formatter::add_field(std::string field_name, SPDLOG_INLINE std::unique_ptr json_formatter::clone() const { - auto result = std::make_unique(pattern_time_type_, eol_); + auto result = details::make_unique(pattern_time_type_, eol_); for (auto &field: fields_) { result->fields_.emplace_back(std::move(field->clone())); } return result; } -// SPDLOG_INLINE void json_formatter::compile_pattern() -// { - // Having enumerated fields is a losing battle; we should just have field->pattern, and escape any pattern that isn't - // known-good as a post-process. We need hooks into the pattern formatter to post-process the outputs or walk - // each field and append-then-escape - -// } +SPDLOG_INLINE bool is_numeric(FieldValueType type) +{ + switch(type) { + case FieldValueType::STRING_VIEW: return false; + case FieldValueType::SHORT: return true; + case FieldValueType::USHORT: return true; + case FieldValueType::INT: return true; + case FieldValueType::UINT: return true; + case FieldValueType::LONG: return true; + case FieldValueType::ULONG: return true; + case FieldValueType::LONGLONG: return true; + case FieldValueType::ULONGLONG: return true; + case FieldValueType::BOOL: return true; // in JSON, it is + case FieldValueType::CHAR: return false; + case FieldValueType::UCHAR: return true; + case FieldValueType::WCHAR: return false; + case FieldValueType::FLOAT: return true; + case FieldValueType::DOUBLE: return true; + case FieldValueType::LONGDOUBLE: return true; + } + abort(); // we should never get here +} SPDLOG_INLINE void json_formatter::format_data_fields(const Field * fields, size_t field_count, spdlog::memory_buf_t &dest) { @@ -275,21 +291,15 @@ SPDLOG_INLINE void json_formatter::format_data_fields(const Field * fields, size dest.push_back('"'); dest.push_back(':'); - switch(field.value.index()) { - case 0: + bool numeric = is_numeric(field.value_type); + if (!numeric) { dest.push_back('"'); - offset = dest.size(); - details::fmt_helper::append_string_view(std::get(field.value), dest); - details::escape_to_end(dest, offset); + } + size_t start_offset = dest.size(); + details::append_value(field, dest); + details::escape_to_end(dest, start_offset); + if (!numeric) { dest.push_back('"'); - break; - case 1: - details::fmt_helper::append_int(std::get(field.value), dest); - break; - case 2: - //TODO: optimize this and get rid of allocations - details::fmt_helper::append_string_view(std::to_string(std::get(field.value)), dest); - break; } dest.push_back(','); diff --git a/include/spdlog/structured_spdlog-inl.h b/include/spdlog/structured_spdlog-inl.h new file mode 100644 index 0000000000..b8d441e891 --- /dev/null +++ b/include/spdlog/structured_spdlog-inl.h @@ -0,0 +1,57 @@ +// Copyright(c) 2015-present, Gabi Melman & spdlog contributors. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) + +#ifndef STRUCTURED_SPDLOG_INL_H +#define STRUCTURED_SPDLOG_INL_H + +#pragma once + +#ifndef SPDLOG_HEADER_ONLY +# include +#endif + +namespace spdlog { +namespace details { + +SPDLOG_INLINE void append_value(const Field &field, memory_buf_t &dest) +{ + switch(field.value_type) { + case FieldValueType::STRING_VIEW: { + auto *buf_ptr = field.string_view_.data(); + dest.append(buf_ptr, buf_ptr + field.string_view_.size()); + break; + } + case FieldValueType::SHORT: details::fmt_helper::append_int(field.short_, dest); break; + case FieldValueType::USHORT: details::fmt_helper::append_int(field.ushort_, dest); break; + case FieldValueType::INT: details::fmt_helper::append_int(field.int_, dest); break; + case FieldValueType::UINT: details::fmt_helper::append_int(field.uint_, dest); break; + case FieldValueType::LONG: details::fmt_helper::append_int(field.long_, dest); break; + case FieldValueType::ULONG: details::fmt_helper::append_int(field.ulong_, dest); break; + case FieldValueType::LONGLONG: details::fmt_helper::append_int(field.longlong_, dest); break; + case FieldValueType::ULONGLONG: details::fmt_helper::append_int(field.ulonglong_, dest); break; + + case FieldValueType::BOOL: details::fmt_helper::append_string_view(field.bool_?"true":"false", dest); break; + + case FieldValueType::CHAR: dest.push_back(field.char_); break; + case FieldValueType::UCHAR: details::fmt_helper::append_int(field.uchar_, dest); break; + case FieldValueType::WCHAR: details::fmt_helper::append_string_view(std::to_string(field.wchar_), dest); break; + + // TODO: optimize these to only have at most one reallocation + case FieldValueType::FLOAT: details::fmt_helper::append_string_view(std::to_string(field.float_), dest); break; + case FieldValueType::DOUBLE: details::fmt_helper::append_string_view(std::to_string(field.double_), dest); break; + case FieldValueType::LONGDOUBLE: details::fmt_helper::append_string_view(std::to_string(field.longdouble_), dest); break; + } +} + +SPDLOG_INLINE std::string value_to_string(const Field &field) +{ + memory_buf_t buf; + append_value(field, buf); + return to_string(buf); +} + +} // namespace details + +} // namespace spdlog + +#endif diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index d8e7230a12..0bce31d28d 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -12,44 +12,29 @@ #include "spdlog.h" namespace spdlog { - - template - constexpr int count_leading_fields(ArgTypes... args [[maybe_unused]]) { - return 0; - } - template - constexpr int count_leading_fields(const Field&& field, ArgTypes... args) { - return 1 + count_leading_fields(args...); - } +namespace details { + void append_value(const Field &field, memory_buf_t &dest); + std::string value_to_string(const Field &field); +} // Stop on empty arg list template void fill_fields(std::array & result [[maybe_unused]], int n [[maybe_unused]]) { } - // Stop on first non-field value - template - void fill_fields(std::array & result [[maybe_unused]], int n [[maybe_unused]], ArgTypes... args [[maybe_unused]] ) { - } - template void fill_fields(std::array & result, int n, const Field& f, ArgTypes... args) { result[n] = f; - fill_fields(result, n+1, args...); + fill_fields(result, n+1, std::forward(args)...); } template std::array build_fields(ArgTypes... args) { std::array result; - fill_fields(result, 0, args...); + fill_fields(result, 0, std::forward(args)...); return result; } - template - Field F(string_view_t name, const T& val) { - Field f={name, val}; - return f; - } template inline void slog(source_loc source, level::level_enum lvl, const std::array& fields, format_string_t fmt, Args &&... args) @@ -61,3 +46,7 @@ namespace spdlog { } #endif // STRUCTURED_SPDLOG_H + +#ifdef SPDLOG_HEADER_ONLY +# include "structured_spdlog-inl.h" +#endif diff --git a/src/spdlog.cpp b/src/spdlog.cpp index 958d8798d3..60c1fcac42 100644 --- a/src/spdlog.cpp +++ b/src/spdlog.cpp @@ -12,6 +12,7 @@ #include #include #include +#include #include #include #include diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp index 8a6bc5a739..77afe69b81 100644 --- a/tests/test_json_formatter.cpp +++ b/tests/test_json_formatter.cpp @@ -12,8 +12,12 @@ using Catch::Matchers::Matches; struct field_patterns { std::string name; std::string pattern; - spdlog::json_field_type field_type = json_field_type::STRING; + spdlog::json_field_type field_type; + + field_patterns(const std::string &_name, const std::string &_pattern, spdlog::json_field_type _field_type = json_field_type::STRING) : + name(_name), pattern(_pattern), field_type(_field_type) {} }; +using P = field_patterns; template static std::string log_to_str(const std::string &msg, const std::array& fields, @@ -41,7 +45,7 @@ static std::string log_to_str(const std::string &msg, const std::array + #include "spdlog/details/log_msg_buffer.h" @@ -17,7 +19,7 @@ std::string log_info(const std::array& fields, const T &what, return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); } -TEST_CASE("fields ", "[structured]") +TEST_CASE("fields", "[structured]") { // Can we construct fields of all types with lvalues? spdlog::F("var", 1); @@ -26,9 +28,14 @@ TEST_CASE("fields ", "[structured]") // Can we construct fields with rvalues? std::string str1("str"); spdlog::F(str1, str1); + + // Can we construct fields with rvalues? + const char * cstr = "str"; + auto cstr_f = spdlog::F(cstr, cstr); + REQUIRE(cstr_f.value_type == spdlog::FieldValueType::INT); } -TEST_CASE("build_fields ", "[structured]") +TEST_CASE("build_fields", "[structured]") { auto array0 = spdlog::build_fields(); REQUIRE(array0.size() == 0); @@ -36,17 +43,20 @@ TEST_CASE("build_fields ", "[structured]") auto array1 = spdlog::build_fields(spdlog::F("var", 1)); REQUIRE(array1.size() == 1); REQUIRE(to_string(array1[0].name) == "var"); - REQUIRE(std::get(array1[0].value) == 1); + REQUIRE(array1[0].value_type == spdlog::FieldValueType::INT); + REQUIRE(array1[0].int_ == 1); auto array2 = spdlog::build_fields(spdlog::F("var", 1), spdlog::F("var2", "two")); REQUIRE(array2.size() == 2); REQUIRE(to_string(array2[0].name) == "var"); - REQUIRE(std::get(array2[0].value) == 1); + REQUIRE(array2[0].value_type == spdlog::FieldValueType::INT); + REQUIRE(array2[0].int_ == 1); REQUIRE(to_string(array2[1].name) == "var2"); - REQUIRE(to_string(std::get(array2[1].value)) == "two"); + REQUIRE(array2[1].value_type == spdlog::FieldValueType::STRING_VIEW); + REQUIRE(array2[1].string_view_ == "two"); } -TEST_CASE("field_logging ", "[structured]") +TEST_CASE("field_logging", "[structured]") { // No fields REQUIRE(log_info(spdlog::NO_FIELDS, "Hello") == "Hello"); @@ -58,19 +68,66 @@ TEST_CASE("field_logging ", "[structured]") REQUIRE(log_info(spdlog::build_fields(spdlog::F("k", 1)), "Hello {}", "world") == "Hello world"); } +template +void test_numeric_to_string() { + T zero_val = {}; + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", zero_val)) == std::to_string(zero_val)); + + T min_val = std::numeric_limits::min(); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", min_val)) == std::to_string(min_val)); + + T max_val = std::numeric_limits::max(); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", max_val)) == std::to_string(max_val)); + + T lowest_val = std::numeric_limits::lowest(); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", lowest_val)) == std::to_string(lowest_val)); +} + +TEST_CASE("to_string", "[structured]") +{ + // Numerics + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + test_numeric_to_string(); + + // string_view + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", "")) == ""); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", "data")) == "data"); + + // bool + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", true)) == "true"); + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", false)) == "false"); + + // char + REQUIRE(spdlog::details::value_to_string(spdlog::Field("", 'c')) == "c"); + +} + + TEST_CASE("buffered_msg_field_copies ", "[structured]") { std::unique_ptr test1; { auto array2 = spdlog::build_fields(spdlog::F("var", 1), spdlog::F("var2", "two")); spdlog::details::log_msg test_input1(spdlog::source_loc{}, "name", spdlog::level::info, "msg", array2.data(), array2.size()); - test1 = std::make_unique(test_input1); + test1 = spdlog::details::make_unique(test_input1); } REQUIRE(test1->field_data_count == 2); REQUIRE(test1->field_data[0].name == "var"); - REQUIRE(std::get(test1->field_data[0].value) == 1); + REQUIRE(test1->field_data[0].value_type == spdlog::FieldValueType::INT); + REQUIRE(test1->field_data[0].int_ == 1); REQUIRE(test1->field_data[1].name == "var2"); - REQUIRE(std::get(test1->field_data[1].value) == "two"); + REQUIRE(test1->field_data[1].value_type == spdlog::FieldValueType::STRING_VIEW); + REQUIRE(test1->field_data[1].string_view_ == "two"); } TEST_CASE("async_structured ", "[structured]") From 1c0ccbc65f0ce1a8748787bd297b36cc645adb98 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Tue, 18 Jan 2022 13:52:53 -0800 Subject: [PATCH 08/21] Added public integration points for structured logging --- include/spdlog/json_formatter-inl.h | 25 +++++-- include/spdlog/json_formatter.h | 32 +++++++-- include/spdlog/logger.h | 10 +-- include/spdlog/structured_spdlog.h | 70 ++++++++++++------- tests/test_json_formatter.cpp | 53 ++++++-------- tests/test_structured.cpp | 105 +++++++++++++++++++--------- 6 files changed, 182 insertions(+), 113 deletions(-) diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h index b674de82e6..21a76ccde4 100644 --- a/include/spdlog/json_formatter-inl.h +++ b/include/spdlog/json_formatter-inl.h @@ -25,11 +25,11 @@ namespace spdlog { namespace details { -constexpr char hex_digits[] = "0123456789abcdef"; +SPDLOG_CONSTEXPR char hex_digits[] = "0123456789abcdef"; // 5 -> escape to \uXXXXX // 1 -> escape to \n, \r or the like -constexpr uint8_t extra_chars_lookup[256] = { +SPDLOG_CONSTEXPR uint8_t extra_chars_lookup[256] = { 5, 5, 5, 5, 5, 5, 5, 5, 1, 1, 1, 5, 1, 1, 5, 5, // 0x0x 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, // 0x1x 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, // 0x2x @@ -52,7 +52,7 @@ constexpr uint8_t extra_chars_lookup[256] = { // write the whole line to the dest buffer and do one pass of escaping: count, // realloc, escape -void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset) +SPDLOG_INLINE void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset) { // Check to see if we have any characters that must be escaped // See https://datatracker.ietf.org/doc/html/rfc8259#section-7 @@ -176,8 +176,8 @@ SPDLOG_INLINE bool pattern_needs_escaping(string_view_t pattern) return false; } -SPDLOG_INLINE pattern_field::pattern_field(const std::string &name, const std::string &pattern, json_field_type field_type, pattern_time_type pattern_time_type_) : - formatter_(details::make_unique(pattern, pattern_time_type_, "")), +SPDLOG_INLINE pattern_field::pattern_field(string_view_t name, string_view_t pattern, json_field_type field_type, pattern_time_type pattern_time_type_) : + formatter_(details::make_unique(to_string(pattern), pattern_time_type_, "")), field_type_(field_type) { // TODO - make this all one pattern {"name": "%v", }; since we know the prefix and suffix length, @@ -198,9 +198,10 @@ SPDLOG_INLINE pattern_field::pattern_field(const std::string &value_prefix, form { } -SPDLOG_INLINE std::unique_ptr pattern_field::clone() +SPDLOG_INLINE std::unique_ptr pattern_field::clone() const { - return make_unique(value_prefix_, formatter_.get(), field_type_, output_needs_escaping_); + // Clone using private ctor + return std::unique_ptr(new pattern_field(value_prefix_, formatter_.get(), field_type_, output_needs_escaping_)); } SPDLOG_INLINE void pattern_field::format(const details::log_msg &msg, memory_buf_t &dest) @@ -224,10 +225,20 @@ SPDLOG_INLINE void pattern_field::format(const details::log_msg &msg, memory_buf } // namespace details +SPDLOG_INLINE json_formatter::json_formatter(std::initializer_list field_defs, pattern_time_type time_type, std::string eol) : + pattern_time_type_(time_type), + eol_(eol) +{ + for (auto &def: field_defs) { + fields_.emplace_back(details::make_unique(def.field_name, def.pattern, def.field_type, pattern_time_type_)); + } +} + SPDLOG_INLINE json_formatter::json_formatter(pattern_time_type time_type, std::string eol) : pattern_time_type_(time_type), eol_(eol) { + add_default_fields(); } SPDLOG_INLINE json_formatter& json_formatter::add_default_fields() diff --git a/include/spdlog/json_formatter.h b/include/spdlog/json_formatter.h index d3dd52ca38..7e6f275584 100644 --- a/include/spdlog/json_formatter.h +++ b/include/spdlog/json_formatter.h @@ -19,25 +19,25 @@ namespace spdlog { -constexpr char ISO8601_FLAGS[] = "%Y-%m-%dT%H:%M:%S.%f%z"; - +SPDLOG_CONSTEXPR char ISO8601_FLAGS[] = "%Y-%m-%dT%H:%M:%S.%f%z"; enum class json_field_type {NUMERIC, STRING}; + namespace details { void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset); bool pattern_needs_escaping(string_view_t pattern); class pattern_field { public: - pattern_field(const std::string &name, const std::string &pattern, json_field_type field_type, pattern_time_type pattern_time_type_); - pattern_field(const std::string &name, formatter* formatter, json_field_type field_type, bool output_needs_escaping); + pattern_field(string_view_t name, string_view_t pattern, json_field_type field_type, pattern_time_type pattern_time_type_); pattern_field(const pattern_field &other) = delete; pattern_field &operator=(const pattern_field &other) = delete; void format(const details::log_msg &msg, memory_buf_t &dest); - std::unique_ptr clone(); + std::unique_ptr clone() const; private: + pattern_field(const std::string &name, formatter* formatter, json_field_type field_type, bool output_needs_escaping); std::string value_prefix_; // {"name":} std::unique_ptr formatter_; json_field_type field_type_; @@ -45,12 +45,30 @@ namespace details { }; } // namespace details +struct pattern_field_definition { + std::string field_name; + std::string pattern; + json_field_type field_type = json_field_type::STRING; + + pattern_field_definition(string_view_t name, string_view_t pattern, json_field_type field_type = json_field_type::STRING) : + field_name(to_string(name)), pattern(to_string(pattern)), field_type(field_type) {} +}; class SPDLOG_API json_formatter final : public formatter { public: - // Default construction - explicit json_formatter(pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol); + // With default fields + json_formatter(pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol); + + // With user-selected fields + json_formatter(std::initializer_list fields, pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol); + + // Can't pass initializer_list through std::forward calls, including make_unique + static std::unique_ptr make_unique(std::initializer_list fields, pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol) + { + return std::unique_ptr(new json_formatter(fields, time_type, eol)); + } + json_formatter &add_field(std::string field_name, std::string pattern, json_field_type field_type = json_field_type::STRING); json_formatter &add_default_fields(); diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index 2d557be6bc..0ac971ce42 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -84,15 +84,9 @@ class SPDLOG_API logger logger &operator=(logger other) SPDLOG_NOEXCEPT; void swap(spdlog::logger &other) SPDLOG_NOEXCEPT; - template - void slog(source_loc loc, level::level_enum lvl, const std::array& fields, format_string_t fmt, Args &&... args) + void log(source_loc loc, level::level_enum lvl, std::initializer_list fields, string_view_t msg) { - log_(loc, lvl, fields.data(), N, fmt, std::forward(args)...); - } - template - void slog(source_loc loc, level::level_enum lvl, const std::array& fields, format_string_t fmt, Args &&... args) - { - log_(loc, lvl, nullptr, 0, fmt, std::forward(args)...); + log_(loc, lvl, fields.begin(), fields.size(), msg); } template diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index 0bce31d28d..d49786ffb6 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -17,30 +17,52 @@ namespace details { std::string value_to_string(const Field &field); } - // Stop on empty arg list - template - void fill_fields(std::array & result [[maybe_unused]], int n [[maybe_unused]]) { - } - - template - void fill_fields(std::array & result, int n, const Field& f, ArgTypes... args) { - result[n] = f; - fill_fields(result, n+1, std::forward(args)...); - } - - template - std::array build_fields(ArgTypes... args) { - std::array result; - fill_fields(result, 0, std::forward(args)...); - return result; - } - - - template - inline void slog(source_loc source, level::level_enum lvl, const std::array& fields, format_string_t fmt, Args &&... args) - { - default_logger_raw()->slog(source, lvl, fields, fmt, std::forward(args)...); - } +inline void log(source_loc source, level::level_enum lvl, std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source, lvl, fields, msg); +} + + +inline void log(level::level_enum lvl, std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, lvl, fields, msg); +} + + +inline void trace(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::trace, fields, msg); +} + + +inline void debug(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::debug, fields, msg); +} + + +inline void info(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::info, fields, msg); +} + + +inline void warn(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::warn, fields, msg); +} + + +inline void error(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::err, fields, msg); +} + + +inline void critical(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::critical, fields, msg); +} } diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp index 77afe69b81..6d8499f206 100644 --- a/tests/test_json_formatter.cpp +++ b/tests/test_json_formatter.cpp @@ -4,59 +4,46 @@ #include using spdlog::memory_buf_t; -using spdlog::NO_FIELDS; using spdlog::json_field_type; using Catch::Matchers::Matches; -// log to str and return it -struct field_patterns { - std::string name; - std::string pattern; - spdlog::json_field_type field_type; - - field_patterns(const std::string &_name, const std::string &_pattern, spdlog::json_field_type _field_type = json_field_type::STRING) : - name(_name), pattern(_pattern), field_type(_field_type) {} -}; -using P = field_patterns; - -template -static std::string log_to_str(const std::string &msg, const std::array& fields, - std::initializer_list patterns, bool use_default_patterns = false) +template +static std::string log_to_str(const std::string &msg, std::initializer_list fields, + std::initializer_list patterns, bool use_default_patterns = false) { std::ostringstream oss; auto oss_sink = std::make_shared(oss); spdlog::logger oss_logger("json_tester", oss_sink); oss_logger.set_level(spdlog::level::info); - auto formatter = new spdlog::json_formatter; + spdlog::json_formatter *formatter; if (!use_default_patterns) { - for (auto &pattern: patterns) { - formatter->add_field(pattern.name, pattern.pattern, pattern.field_type); - } + formatter = new spdlog::json_formatter(patterns); } else { - formatter->add_default_fields(); + formatter = new spdlog::json_formatter(); } oss_logger.set_formatter(std::unique_ptr(formatter)); - oss_logger.slog(spdlog::source_loc{"source.cpp", 99, "fn"}, spdlog::level::info, fields, msg); + oss_logger.log(spdlog::source_loc{"source.cpp", 99, "fn"}, spdlog::level::info, fields, msg); return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); } TEST_CASE("json basic output", "[json_formatter]") { - // // Test fields with static outputs - REQUIRE(log_to_str("hello", NO_FIELDS, {P{"MSG", "%v"}, P{"SRC", "%@"}, P{"LEVEL", "%l"}}) == R"({"MSG":"hello", "SRC":"source.cpp:99", "LEVEL":"info"})"); - - // // Tests with regex outputs - REQUIRE_THAT(log_to_str("hello", NO_FIELDS, {{"THREAD","%t", json_field_type::NUMERIC}}), Matches(R"(\{"THREAD":[0-9]+\})")); - // // ISO8601 regex lifted from https://www.myintervals.com/blog/2009/05/20/iso-8601-date-validation-that-doesnt-suck/ - // // Trimmed of leading ^ and trailing $ + // Test fields with static outputs + using JF=spdlog::pattern_field_definition; + REQUIRE(log_to_str("hello", {}, {JF{"MSG", "%v"}, JF{"SRC", "%@"}, JF{"LEVEL", "%l"}}) == R"({"MSG":"hello", "SRC":"source.cpp:99", "LEVEL":"info"})"); + + // Tests with regex outputs + REQUIRE_THAT(log_to_str("hello", {}, {{"THREAD","%t", json_field_type::NUMERIC}}), Matches(R"(\{"THREAD":[0-9]+\})")); + // ISO8601 regex lifted from https://www.myintervals.com/blog/2009/05/20/iso-8601-date-validation-that-doesnt-suck/ + // Trimmed of leading ^ and trailing $ constexpr char ISO8601_REGEX[] = R"(([\+-]?\d{4}(?!\d{2}\b))((-?)((0[1-9]|1[0-2])(\3([12]\d|0[1-9]|3[01]))?|W([0-4]\d|5[0-2])(-?[1-7])?|(00[1-9]|0[1-9]\d|[12]\d{2}|3([0-5]\d|6[1-6])))([T\s]((([01]\d|2[0-3])((:?)[0-5]\d)?|24\:?00)([\.,]\d+(?!:))?)?(\17[0-5]\d([\.,]\d+)?)?([zZ]|([\+-])([01]\d|2[0-3]):?([0-5]\d)?)?)?)?)"; std::string time_output_regex = std::string(R"(\{"TM":")") + std::string(ISO8601_REGEX) + std::string(R"("\})"); - REQUIRE_THAT(log_to_str("hello", NO_FIELDS, {{"TM", spdlog::ISO8601_FLAGS}}), Matches(time_output_regex)); + REQUIRE_THAT(log_to_str("hello", {}, {{"TM", spdlog::ISO8601_FLAGS}}), Matches(time_output_regex)); // Fields alone - auto fields = spdlog::build_fields(spdlog::F("f1", 1), spdlog::F("f2", "two"), spdlog::F("f3", 3.0), spdlog::F("f4",true)); + auto fields = {spdlog::F("f1", 1), spdlog::F("f2", "two"), spdlog::F("f3", 3.0), spdlog::F("f4",true)}; REQUIRE(log_to_str("hello", fields, {}) == R"({"f1":1, "f2":"two", "f3":3.000000, "f4":true})"); // Fields with message @@ -77,10 +64,10 @@ TEST_CASE("json basic output", "[json_formatter]") TEST_CASE("json escaped output", "[json_formatter]") { - REQUIRE(log_to_str("hello_\x1a", NO_FIELDS, {{"MSG", "%v"}}) == R"({"MSG":"hello_\u001a"})"); - REQUIRE(log_to_str("hello", NO_FIELDS, {{"MSG_\x1a", "%v"}}) == R"({"MSG_\u001a":"hello"})"); + REQUIRE(log_to_str("hello_\x1a", {}, {{"MSG", "%v"}}) == R"({"MSG":"hello_\u001a"})"); + REQUIRE(log_to_str("hello", {}, {{"MSG_\x1a", "%v"}}) == R"({"MSG_\u001a":"hello"})"); - auto fields = spdlog::build_fields(spdlog::F("hello_\x1a", "goodbye_\x1b")); + auto fields = {spdlog::F("hello_\x1a", "goodbye_\x1b")}; REQUIRE(log_to_str("", fields, {}) == R"({"hello_\u001a":"goodbye_\u001b"})"); } diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index 59f4c31235..1697a81cb1 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -5,16 +5,17 @@ #include "spdlog/details/log_msg_buffer.h" +using spdlog::F; -template -std::string log_info(const std::array& fields, const T &what, ArgTypes&&... args) + +std::string log_info(std::initializer_list fields, spdlog::string_view_t what) { std::ostringstream oss; auto oss_sink = std::make_shared(oss); spdlog::logger oss_logger("oss", oss_sink); oss_logger.set_pattern("%v"); - oss_logger.slog({}, spdlog::level::info, fields, what, std::forward(args)...); + oss_logger.log({}, spdlog::level::info, fields, what); return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); } @@ -22,8 +23,8 @@ std::string log_info(const std::array& fields, const T &what, TEST_CASE("fields", "[structured]") { // Can we construct fields of all types with lvalues? - spdlog::F("var", 1); - spdlog::F("var", "val"); + F("var", 1); + F("var", "val"); // Can we construct fields with rvalues? std::string str1("str"); @@ -35,37 +36,13 @@ TEST_CASE("fields", "[structured]") REQUIRE(cstr_f.value_type == spdlog::FieldValueType::INT); } -TEST_CASE("build_fields", "[structured]") -{ - auto array0 = spdlog::build_fields(); - REQUIRE(array0.size() == 0); - - auto array1 = spdlog::build_fields(spdlog::F("var", 1)); - REQUIRE(array1.size() == 1); - REQUIRE(to_string(array1[0].name) == "var"); - REQUIRE(array1[0].value_type == spdlog::FieldValueType::INT); - REQUIRE(array1[0].int_ == 1); - - auto array2 = spdlog::build_fields(spdlog::F("var", 1), spdlog::F("var2", "two")); - REQUIRE(array2.size() == 2); - REQUIRE(to_string(array2[0].name) == "var"); - REQUIRE(array2[0].value_type == spdlog::FieldValueType::INT); - REQUIRE(array2[0].int_ == 1); - REQUIRE(to_string(array2[1].name) == "var2"); - REQUIRE(array2[1].value_type == spdlog::FieldValueType::STRING_VIEW); - REQUIRE(array2[1].string_view_ == "two"); -} - TEST_CASE("field_logging", "[structured]") { // No fields - REQUIRE(log_info(spdlog::NO_FIELDS, "Hello") == "Hello"); + REQUIRE(log_info({}, "Hello") == "Hello"); // Some fields - REQUIRE(log_info(spdlog::build_fields(spdlog::F("k", 1)), "Hello") == "Hello"); - - // Fields and fmt - REQUIRE(log_info(spdlog::build_fields(spdlog::F("k", 1)), "Hello {}", "world") == "Hello world"); + REQUIRE(log_info({F("k", 1)}, "Hello") == "Hello"); } template @@ -117,8 +94,8 @@ TEST_CASE("buffered_msg_field_copies ", "[structured]") { std::unique_ptr test1; { - auto array2 = spdlog::build_fields(spdlog::F("var", 1), spdlog::F("var2", "two")); - spdlog::details::log_msg test_input1(spdlog::source_loc{}, "name", spdlog::level::info, "msg", array2.data(), array2.size()); + auto array2 = {F("var", 1), F("var2", "two")}; + spdlog::details::log_msg test_input1(spdlog::source_loc{}, "name", spdlog::level::info, "msg", array2.begin(), array2.size()); test1 = spdlog::details::make_unique(test_input1); } REQUIRE(test1->field_data_count == 2); @@ -143,9 +120,69 @@ TEST_CASE("async_structured ", "[structured]") { // Build on the stack so it's out of scope std::string test_string("abcdefghijklmnopqrstuvwxyz"); - logger->slog({}, spdlog::level::info, spdlog::build_fields(spdlog::F("str", test_string)), "test msg"); + logger->log({}, spdlog::level::info, {F("str", test_string)}, "test msg"); } REQUIRE(test_sink->msg_counter() < messages); REQUIRE(test_sink->msg_counter() > 0); REQUIRE(tp->overrun_counter() > 0); } + + +#if SPDLOG_ACTIVE_LEVEL != SPDLOG_LEVEL_DEBUG +# error "Invalid SPDLOG_ACTIVE_LEVEL in test. Should be SPDLOG_LEVEL_DEBUG" +#endif + +#define TEST_FILENAME "test_logs/structured_macro_log" +std::string last_line(const std::string &str) { + if (str.empty()) { + return ""; + } + auto start = str.begin(); + auto curr = str.end() - 1; + + // Skip last line + while ((*curr == '\n' || *curr == '\r') && curr != start) { + curr--; + } + auto end = curr + 1; // end is exclusive + + while (curr != start && *(curr-1) != '\n' && *(curr-1) != '\r' && curr != start) { + curr--; + } + return std::string(curr, end); +} + + +TEST_CASE("structured macros", "[structuredX]") +{ + prepare_logdir(); + spdlog::filename_t filename = SPDLOG_FILENAME_T(TEST_FILENAME); + + auto logger = spdlog::create("logger", filename); + auto formatter = spdlog::json_formatter::make_unique({{"msg", "%v"}}); + logger->set_formatter(std::move(formatter)); + logger->set_level(spdlog::level::trace); + + SPDLOG_LOGGER_TRACE(logger, {}, "Test message 1"); + SPDLOG_LOGGER_DEBUG(logger, {F("f", 0)}, "Test message 2"); + logger->flush(); + + REQUIRE(last_line(file_contents(TEST_FILENAME)) == R"({"msg":"Test message 2", "f":0})"); + REQUIRE(count_lines(TEST_FILENAME) == 1); + + auto orig_default_logger = spdlog::default_logger(); + spdlog::set_default_logger(logger); + + SPDLOG_TRACE({}, "Test message 3"); + SPDLOG_DEBUG({{"f",1}}, "Test message 4"); + logger->flush(); + + require_message_count(TEST_FILENAME, 2); + REQUIRE(last_line(file_contents(TEST_FILENAME)) == R"({"msg":"Test message 4", "f":1})"); + + spdlog::error({F("f",2)}, "Test message 5"); + logger->flush(); + REQUIRE(last_line(file_contents(TEST_FILENAME)) == R"({"msg":"Test message 5", "f":2})"); + + spdlog::set_default_logger(std::move(orig_default_logger)); +} From ef237508f67d3a881d93ce43521a1edee2c051d5 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Wed, 19 Jan 2022 07:13:43 -0800 Subject: [PATCH 09/21] Added structured field MVP to pattern_formatter --- include/spdlog/pattern_formatter-inl.h | 43 ++++++++++++++++++++++++++ tests/test_structured.cpp | 13 ++++---- 2 files changed, 49 insertions(+), 7 deletions(-) diff --git a/include/spdlog/pattern_formatter-inl.h b/include/spdlog/pattern_formatter-inl.h index ec727032b9..1a7ce3b38f 100644 --- a/include/spdlog/pattern_formatter-inl.h +++ b/include/spdlog/pattern_formatter-inl.h @@ -12,6 +12,10 @@ #include #include #include +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +#include +#endif + #include #include @@ -691,6 +695,30 @@ class v_formatter final : public flag_formatter } }; +template +class V_formatter final : public flag_formatter +{ +public: + explicit V_formatter(padding_info padinfo) + : flag_formatter(padinfo) + {} + + // This is just a starting MVP. We probably want to be able to + // customize separators, color the key and value separately, + // and lots more expressive things + void format(const details::log_msg &msg, const std::tm &, memory_buf_t &dest) override + { + // TODO: padding + for (size_t i=0; i < msg.field_data_count; i++) { + dest.push_back(' '); + Field &field = msg.field_data[i]; + fmt_helper::append_string_view(field.name, dest); + dest.push_back(':'); + details::append_value(field, dest); + } + } +}; + class ch_formatter final : public flag_formatter { public: @@ -1005,6 +1033,17 @@ class full_formatter final : public flag_formatter } // fmt_helper::append_string_view(msg.msg(), dest); fmt_helper::append_string_view(msg.payload, dest); + + // structured fields +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + for (size_t i=0; i < msg.field_data_count; i++) { + dest.push_back(' '); + Field &field = msg.field_data[i]; + fmt_helper::append_string_view(field.name, dest); + dest.push_back(':'); + details::append_value(field, dest); + } +#endif } private: @@ -1119,6 +1158,10 @@ SPDLOG_INLINE void pattern_formatter::handle_flag_(char flag, details::padding_i formatters_.push_back(details::make_unique>(padding)); break; + case ('V'): // the structured fields + formatters_.push_back(details::make_unique>(padding)); + break; + case ('a'): // weekday formatters_.push_back(details::make_unique>(padding)); break; diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index 1697a81cb1..2ec477d087 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -14,7 +14,7 @@ std::string log_info(std::initializer_list fields, spdlog::string auto oss_sink = std::make_shared(oss); spdlog::logger oss_logger("oss", oss_sink); - oss_logger.set_pattern("%v"); + oss_logger.set_pattern("%v%V"); oss_logger.log({}, spdlog::level::info, fields, what); return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); @@ -42,7 +42,7 @@ TEST_CASE("field_logging", "[structured]") REQUIRE(log_info({}, "Hello") == "Hello"); // Some fields - REQUIRE(log_info({F("k", 1)}, "Hello") == "Hello"); + REQUIRE(log_info({F("k", 1)}, "Hello") == "Hello k:1"); } template @@ -159,15 +159,14 @@ TEST_CASE("structured macros", "[structuredX]") spdlog::filename_t filename = SPDLOG_FILENAME_T(TEST_FILENAME); auto logger = spdlog::create("logger", filename); - auto formatter = spdlog::json_formatter::make_unique({{"msg", "%v"}}); - logger->set_formatter(std::move(formatter)); + logger->set_pattern("%v%V"); logger->set_level(spdlog::level::trace); SPDLOG_LOGGER_TRACE(logger, {}, "Test message 1"); SPDLOG_LOGGER_DEBUG(logger, {F("f", 0)}, "Test message 2"); logger->flush(); - REQUIRE(last_line(file_contents(TEST_FILENAME)) == R"({"msg":"Test message 2", "f":0})"); + REQUIRE(last_line(file_contents(TEST_FILENAME)) == "Test message 2 f:0"); REQUIRE(count_lines(TEST_FILENAME) == 1); auto orig_default_logger = spdlog::default_logger(); @@ -178,11 +177,11 @@ TEST_CASE("structured macros", "[structuredX]") logger->flush(); require_message_count(TEST_FILENAME, 2); - REQUIRE(last_line(file_contents(TEST_FILENAME)) == R"({"msg":"Test message 4", "f":1})"); + REQUIRE(last_line(file_contents(TEST_FILENAME)) == "Test message 4 f:1"); spdlog::error({F("f",2)}, "Test message 5"); logger->flush(); - REQUIRE(last_line(file_contents(TEST_FILENAME)) == R"({"msg":"Test message 5", "f":2})"); + REQUIRE(last_line(file_contents(TEST_FILENAME)) == "Test message 5 f:2"); spdlog::set_default_logger(std::move(orig_default_logger)); } From 57b035a7310488c5b452e570de277fb5a5058c31 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Wed, 19 Jan 2022 09:13:37 -0800 Subject: [PATCH 10/21] Added threadlocal context variables --- include/spdlog/common-inl.h | 11 ++ include/spdlog/common.h | 6 +- include/spdlog/details/log_msg-inl.h | 1 + include/spdlog/details/log_msg.h | 2 + include/spdlog/json_formatter-inl.h | 52 +++++---- include/spdlog/json_formatter.h | 2 +- include/spdlog/pattern_formatter-inl.h | 9 ++ include/spdlog/structured_spdlog-inl.h | 100 +++++++++++++++++ include/spdlog/structured_spdlog.h | 145 ++++++++++++++++++------- tests/test_json_formatter.cpp | 7 ++ tests/test_structured.cpp | 58 +++++++++- 11 files changed, 321 insertions(+), 72 deletions(-) diff --git a/include/spdlog/common-inl.h b/include/spdlog/common-inl.h index 9fd2bcb547..fd26ef8526 100644 --- a/include/spdlog/common-inl.h +++ b/include/spdlog/common-inl.h @@ -79,4 +79,15 @@ SPDLOG_INLINE void throw_spdlog_ex(std::string msg) SPDLOG_THROW(spdlog_ex(std::move(msg))); } +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +namespace details { + +SPDLOG_INLINE std::shared_ptr& threadlocal_context_head() { + thread_local std::shared_ptr context_head; + return context_head; +} + +} // namespace details +#endif // SPDLOG_NO_STRUCTURED_SPDLOG + } // namespace spdlog diff --git a/include/spdlog/common.h b/include/spdlog/common.h index c57622b03f..22dd9a4e9f 100644 --- a/include/spdlog/common.h +++ b/include/spdlog/common.h @@ -367,7 +367,11 @@ struct Field { Field(const string_view_t &field_name, const char (&val)[N]): name(field_name), value_type(FieldValueType::STRING_VIEW), string_view_{val, N-1} {} }; using F=Field; -constexpr auto NO_FIELDS = std::array(); + +namespace details { + class context_data; + SPDLOG_API std::shared_ptr& threadlocal_context_head(); +} namespace details { // make_unique support for pre c++14 diff --git a/include/spdlog/details/log_msg-inl.h b/include/spdlog/details/log_msg-inl.h index aba64c60b7..065d43d3a8 100644 --- a/include/spdlog/details/log_msg-inl.h +++ b/include/spdlog/details/log_msg-inl.h @@ -25,6 +25,7 @@ SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::s #ifndef SPDLOG_NO_STRUCTURED_SPDLOG , field_data(const_cast(fields)) , field_data_count(field_count) + , context_field_data(threadlocal_context_head()) #endif {} diff --git a/include/spdlog/details/log_msg.h b/include/spdlog/details/log_msg.h index adcbc87515..e4c72d8039 100644 --- a/include/spdlog/details/log_msg.h +++ b/include/spdlog/details/log_msg.h @@ -8,6 +8,7 @@ namespace spdlog { namespace details { +class context_data; struct SPDLOG_API log_msg { log_msg() = default; @@ -33,6 +34,7 @@ struct SPDLOG_API log_msg Field *field_data{nullptr}; size_t field_data_count{0}; + std::shared_ptr context_field_data; }; } // namespace details } // namespace spdlog diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h index 21a76ccde4..97ebd19ba6 100644 --- a/include/spdlog/json_formatter-inl.h +++ b/include/spdlog/json_formatter-inl.h @@ -288,34 +288,31 @@ SPDLOG_INLINE bool is_numeric(FieldValueType type) abort(); // we should never get here } -SPDLOG_INLINE void json_formatter::format_data_fields(const Field * fields, size_t field_count, spdlog::memory_buf_t &dest) +SPDLOG_INLINE void json_formatter::format_data_field(const Field &field, spdlog::memory_buf_t &dest) { // TODO: should we keep a hash table of field names->escaped field names? // If the same fields keep cropping up and have to be escaped again and again it could have // a small but noticeable impact on performance - for (size_t i=0; i < field_count; i++) { - auto &field = fields[i]; - dest.push_back('"'); - size_t offset = dest.size(); - details::fmt_helper::append_string_view(field.name, dest); - details::escape_to_end(dest, offset); - dest.push_back('"'); - dest.push_back(':'); - - bool numeric = is_numeric(field.value_type); - if (!numeric) { - dest.push_back('"'); - } - size_t start_offset = dest.size(); - details::append_value(field, dest); - details::escape_to_end(dest, start_offset); - if (!numeric) { - dest.push_back('"'); - } - - dest.push_back(','); - dest.push_back(' '); + dest.push_back('"'); + size_t offset = dest.size(); + details::fmt_helper::append_string_view(field.name, dest); + details::escape_to_end(dest, offset); + dest.push_back('"'); + dest.push_back(':'); + + bool numeric = is_numeric(field.value_type); + if (!numeric) { + dest.push_back('"'); } + size_t start_offset = dest.size(); + details::append_value(field, dest); + details::escape_to_end(dest, start_offset); + if (!numeric) { + dest.push_back('"'); + } + + dest.push_back(','); + dest.push_back(' '); } @@ -330,7 +327,14 @@ SPDLOG_INLINE void json_formatter::format(const details::log_msg &msg, memory_bu for (auto &field_ptr: fields_) { field_ptr->format(msg, dest); } - format_data_fields(msg.field_data, msg.field_data_count, dest); + for (size_t i=0; i < msg.field_data_count; i++) { + format_data_field(msg.field_data[i], dest); + } + if (msg.context_field_data) { + for (auto &field: *msg.context_field_data) { + format_data_field(field, dest); + } + } // Strip trailing space if it's there if (dest[dest.size() -1] == ' ') { diff --git a/include/spdlog/json_formatter.h b/include/spdlog/json_formatter.h index 7e6f275584..3655d37c72 100644 --- a/include/spdlog/json_formatter.h +++ b/include/spdlog/json_formatter.h @@ -80,7 +80,7 @@ class SPDLOG_API json_formatter final : public formatter void format(const details::log_msg &msg, memory_buf_t &dest) override; private: - void format_data_fields(const Field * fields, size_t field_count, spdlog::memory_buf_t &dest); + void format_data_field(const Field &field, spdlog::memory_buf_t &dest); pattern_time_type pattern_time_type_; std::string eol_; diff --git a/include/spdlog/pattern_formatter-inl.h b/include/spdlog/pattern_formatter-inl.h index 1a7ce3b38f..aea01e5f51 100644 --- a/include/spdlog/pattern_formatter-inl.h +++ b/include/spdlog/pattern_formatter-inl.h @@ -716,6 +716,15 @@ class V_formatter final : public flag_formatter dest.push_back(':'); details::append_value(field, dest); } + + if (msg.context_field_data) { + for (auto &field: *msg.context_field_data) { + dest.push_back(' '); + fmt_helper::append_string_view(field.name, dest); + dest.push_back(':'); + details::append_value(field, dest); + } + } } }; diff --git a/include/spdlog/structured_spdlog-inl.h b/include/spdlog/structured_spdlog-inl.h index b8d441e891..9698df6994 100644 --- a/include/spdlog/structured_spdlog-inl.h +++ b/include/spdlog/structured_spdlog-inl.h @@ -50,8 +50,108 @@ SPDLOG_INLINE std::string value_to_string(const Field &field) return to_string(buf); } + +SPDLOG_INLINE context_data::context_data(std::shared_ptr parent_fields, const Field * fields, size_t num_fields) : + parent_fields_(parent_fields), fields_(fields, fields + num_fields) +{ + // Find total required storage + size_t size = 0; + for (auto &field: fields_) { + size += field.name.size(); + if (field.value_type == FieldValueType::STRING_VIEW) { + size += field.string_view_.size(); + } + } + buffers_.resize(size); + + // Copy any string views into buffers_ and point the string view to the new copy + size_t offset = 0; + for (auto &field: fields_) { + size_t field_size = field.name.size(); + std::memcpy(&buffers_[offset], field.name.data(), field_size); + field.name = string_view_t(&buffers_[offset], field_size); + offset += field_size; + + if (field.value_type == FieldValueType::STRING_VIEW) { + field_size = field.string_view_.size(); + std::memcpy(&buffers_[offset], field.string_view_.data(), field_size); + field.string_view_ = string_view_t(&buffers_[offset], field_size); + offset += field_size; + } + } + + assert(offset == buffers_.size()); +} + +SPDLOG_INLINE context_data::~context_data() +{ + buffers_.resize(0); +} + } // namespace details + +// +// Contexts +// +SPDLOG_INLINE context::context(std::initializer_list fields) +{ + if (fields.size() > 0) { + std::shared_ptr& context_head = details::threadlocal_context_head(); + + context_to_restore_ = context_head; + + auto new_context_head = std::make_shared(context_head, fields.begin(), fields.size()); + context_head = new_context_head; + } else { + // Never store a link with zero fields; iterator++ needs to know that when it follows a traversal, it will + // be pointing to context_data with at least one field. + // When this goes out of context, just put the same head back + context_to_restore_ = details::threadlocal_context_head(); + } +} +SPDLOG_INLINE context::~context() +{ + details::threadlocal_context_head() = context_to_restore_; +} + +// context_iterators +SPDLOG_INLINE context_iterator& context_iterator::operator++() +{ + if (data_ && (++idx_ == data_->fields_.size())) { + data_ = data_->parent_fields_.get(); // may be nullptr + idx_ = 0; + } + return *this; +} + +SPDLOG_INLINE context_iterator::reference context_iterator::operator*() +{ + return data_->fields_[idx_]; +} +SPDLOG_INLINE context_iterator::pointer context_iterator::operator->() +{ + return &data_->fields_[idx_]; +} + +// snapshots +SPDLOG_INLINE details::context_snapshot snapshot_context_fields() +{ + return details::threadlocal_context_head(); +} + +SPDLOG_INLINE replacement_context::replacement_context(details::context_snapshot data) : + old_context_fields_(details::threadlocal_context_head()) +{ + details::threadlocal_context_head() = data; +} + +SPDLOG_INLINE replacement_context::~replacement_context() +{ + details::threadlocal_context_head() = old_context_fields_; +} + + } // namespace spdlog #endif diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index d49786ffb6..b1707040c8 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -11,61 +11,126 @@ #include "spdlog.h" -namespace spdlog { -namespace details { - void append_value(const Field &field, memory_buf_t &dest); - std::string value_to_string(const Field &field); -} - -inline void log(source_loc source, level::level_enum lvl, std::initializer_list fields, string_view_t msg) -{ - default_logger_raw()->log(source, lvl, fields, msg); -} +#include - -inline void log(level::level_enum lvl, std::initializer_list fields, string_view_t msg) -{ - default_logger_raw()->log(source_loc{}, lvl, fields, msg); -} - - -inline void trace(std::initializer_list fields, string_view_t msg) -{ - default_logger_raw()->log(source_loc{}, level::trace, fields, msg); -} +namespace spdlog { -inline void debug(std::initializer_list fields, string_view_t msg) +SPDLOG_API struct context_iterator { - default_logger_raw()->log(source_loc{}, level::debug, fields, msg); -} + /** + For formatters, walk all of the current context fields for formatting and display. + if (msg.context_field_data) { + for (auto &field: *msg.context_field_data) { + std::cout << to_string(field.name) << "=" << spdlog::details::value_to_string(field) << " "; + } + } + **/ + using iterator_catecory = std::forward_iterator_tag; + using value_type = Field; + using pointer = const Field*; + using reference = const Field&; -inline void info(std::initializer_list fields, string_view_t msg) -{ - default_logger_raw()->log(source_loc{}, level::info, fields, msg); -} + context_iterator(details::context_data* ctx, size_t idx) : + data_(ctx), idx_(idx) {} + reference operator*(); + pointer operator->(); -inline void warn(std::initializer_list fields, string_view_t msg) -{ - default_logger_raw()->log(source_loc{}, level::warn, fields, msg); -} + // Prefix increment + context_iterator& operator++(); + // Postfix increment + context_iterator operator++(int) { context_iterator result(data_,idx_); ++result; return result; } -inline void error(std::initializer_list fields, string_view_t msg) -{ - default_logger_raw()->log(source_loc{}, level::err, fields, msg); -} + friend bool operator== (const context_iterator& a, const context_iterator& b) { return a.data_ == b.data_ && a.idx_ == b.idx_; }; + friend bool operator!= (const context_iterator& a, const context_iterator& b) { return a.data_ != b.data_ || a.idx_ != b.idx_; }; +private: + details::context_data* data_; + size_t idx_; +}; -inline void critical(std::initializer_list fields, string_view_t msg) -{ - default_logger_raw()->log(source_loc{}, level::critical, fields, msg); +namespace details { + void SPDLOG_API append_value(const Field &field, memory_buf_t &dest); + std::string SPDLOG_API value_to_string(const Field &field); + + // A linked list of context_data field collections + // TODO(opt): implement caching flattened parents + // We can track how many times there has been another context that + // points to this one as a parent. As an optimization, we can accumulate all of + // the fields of the parents into fields_ when the number of children gets to 2 or 3 + // NB: If number of children gets to (very large), reset it to (something small) to guard + // against wraparound at MAX_INT + // TODO(opt): lazily use shared_ptr + // If we're not submitting to a multithreaded logger or snapshotting, we can just use raw pointers + // instead of taking the cache miss of an atomic operation in the shared_ptr. We should + // benchmark to see how much it costs us in the single-threaded case + SPDLOG_API struct context_data { + std::shared_ptr parent_fields_; + std::vector fields_; + memory_buf_t buffers_; // storage for strings in fields_ + + context_data(std::shared_ptr parent_fields, const Field * fields, size_t num_fields); + ~context_data(); + + // Iterator support + context_iterator begin() { return context_iterator(this, 0); } + context_iterator end() { return context_iterator(nullptr, 0); } + }; + + // Thread-local context fields + using context_snapshot = std::shared_ptr; } -} +/** + Using context_fields to represent the state of the application: + + NOTE: it is important that the context variable has a name, or it will go out of scope immediately. + RIGHT: spdlog::context ctx({{"field",value}}); + WRONG: spdlog::context({{"field",value}}); + + void bar() { + spdlog::info({{"processing", "bar"}}); // prints "program:contextfield_demo running:foo processing:bar" + std::thread th([ctx_snapshot=snapshot_context_fields()] { // copy the threadlocal context for use in another thread + spdlog::replacement_context ctx(ctx_snapshot); // Log with ctx_snapshot while ctx is still on the stack + spdlog::info({{"function", "in_thread"}}); // prints "program:contextfield_demo running:foo function:in_thread" + }); + th.join(); + } + + void foo() { + spdlog::context ctx({{"running", "foo"}}); // set context on the stack; goes away after ctx goes out of scope + bar(); + } + + int main() { + auto formatter = spdlog::json_formatter::make_unique({{"program", "contextfield_demo"}}); // process-wide context + spdlog::default_logger()->set_formatter(formatter); + foo(); + } +**/ +class SPDLOG_API context final { +public: + context(std::initializer_list fields); + ~context(); +private: + std::shared_ptr context_to_restore_; +}; + +SPDLOG_API details::context_snapshot snapshot_context_fields(); +class SPDLOG_API replacement_context final { +public: + replacement_context(details::context_snapshot data); + ~replacement_context(); +private: + std::shared_ptr old_context_fields_; +}; + + +} // namespace spdlog #endif // STRUCTURED_SPDLOG_H diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp index 6d8499f206..e42929c451 100644 --- a/tests/test_json_formatter.cpp +++ b/tests/test_json_formatter.cpp @@ -49,6 +49,13 @@ TEST_CASE("json basic output", "[json_formatter]") // Fields with message REQUIRE(log_to_str("hello", fields, {{"MSG", "%v"}}) == R"({"MSG":"hello", "f1":1, "f2":"two", "f3":3.000000, "f4":true})"); + // Fields with context + { + spdlog::context ctx1({{"c1",10}}); + spdlog::context ctx2({{"c2",11}}); + REQUIRE(log_to_str("hello", fields, {{"MSG", "%v"}}) == R"({"MSG":"hello", "f1":1, "f2":"two", "f3":3.000000, "f4":true, "c2":11, "c1":10})"); + } + // Default output static const std::string DEFAULT_RESULT_REGEX = std::string("\\{") + R"("time":")" + ISO8601_REGEX + R"(", )" + diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index 2ec477d087..d511bc4c00 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -122,6 +122,7 @@ TEST_CASE("async_structured ", "[structured]") std::string test_string("abcdefghijklmnopqrstuvwxyz"); logger->log({}, spdlog::level::info, {F("str", test_string)}, "test msg"); } + logger->flush(); REQUIRE(test_sink->msg_counter() < messages); REQUIRE(test_sink->msg_counter() > 0); REQUIRE(tp->overrun_counter() > 0); @@ -153,7 +154,7 @@ std::string last_line(const std::string &str) { } -TEST_CASE("structured macros", "[structuredX]") +TEST_CASE("structured macros", "[structured]") { prepare_logdir(); spdlog::filename_t filename = SPDLOG_FILENAME_T(TEST_FILENAME); @@ -173,15 +174,60 @@ TEST_CASE("structured macros", "[structuredX]") spdlog::set_default_logger(logger); SPDLOG_TRACE({}, "Test message 3"); - SPDLOG_DEBUG({{"f",1}}, "Test message 4"); + SPDLOG_DEBUG({F("f",1)}, "Test message 4"); logger->flush(); require_message_count(TEST_FILENAME, 2); REQUIRE(last_line(file_contents(TEST_FILENAME)) == "Test message 4 f:1"); - spdlog::error({F("f",2)}, "Test message 5"); - logger->flush(); - REQUIRE(last_line(file_contents(TEST_FILENAME)) == "Test message 5 f:2"); - spdlog::set_default_logger(std::move(orig_default_logger)); } + +TEST_CASE("structured context", "[structured]") +{ + { + spdlog::context ctx({{"c1","1"}}); + REQUIRE(log_info({}, "Hello") == "Hello c1:1"); + } + + { + spdlog::context ctx1({{"c1","1"}}); + { + spdlog::context ctx2({{"c2","2"}}); + REQUIRE(log_info({}, "Hello") == "Hello c2:2 c1:1"); + } + REQUIRE(log_info({}, "Hello") == "Hello c1:1"); + } + + REQUIRE(log_info({}, "Hello") == "Hello"); +} + +TEST_CASE("structured snapshots", "[structured]") +{ + enum steps {START, CTX_REPLACED, LOG_IN_THREAD}; + std::atomic step{steps::START}; + + std::unique_ptr thread; + { + spdlog::context inner_ctx({{"c1","1"}}); + thread = std::make_unique( + [ctx_snapshot=spdlog::snapshot_context_fields(), &step] { + spdlog::replacement_context ctx(ctx_snapshot); + step = steps::CTX_REPLACED; + while(step != LOG_IN_THREAD) ; // spin until ready + REQUIRE(log_info({}, "Hello") == "Hello c1:1"); + }); + } + // inner_ctx should be fully out of scope at this point + + // Wait for the context to be replaced in the thread, but verify + // that it doesn't affect the context of the main thread + while(step != CTX_REPLACED) ; + spdlog::context main_ctx({{"c2","2"}}); + REQUIRE(log_info({}, "Hello") == "Hello c2:2"); + + // Verify that setting the context on the main thread doesn't + // effect the test thread + step = LOG_IN_THREAD; + thread->join(); +} From 2b1aa5e8700cb010c32cedb0cbc0a97ba3eaff46 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Wed, 19 Jan 2022 09:50:32 -0800 Subject: [PATCH 11/21] Code cleanup and add SPDLOG_NO_STRUCTURED_SPDLOG to CMakeLists.txt --- CMakeLists.txt | 2 ++ include/spdlog/details/log_msg-inl.h | 7 ++++++- include/spdlog/details/log_msg.h | 2 ++ include/spdlog/details/log_msg_buffer-inl.h | 9 ++------- include/spdlog/json_formatter-inl.h | 8 ++++++++ include/spdlog/pattern_formatter-inl.h | 5 +++++ include/spdlog/structured_spdlog-inl.h | 12 +++++++++++- include/spdlog/structured_spdlog.h | 12 +++++++++--- tests/test_json_formatter.cpp | 4 ++++ tests/test_structured.cpp | 5 +++++ 10 files changed, 54 insertions(+), 12 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index 8f1b00a2aa..7ca764c6ea 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -121,6 +121,7 @@ option( SPDLOG_NO_ATOMIC_LEVELS "prevent spdlog from using of std::atomic log levels (use only if your code never modifies log levels concurrently" OFF) +option(SPDLOG_NO_STRUCTURED_SPDLOG "Turn off structured support for a small speed increase" OFF) option(SPDLOG_DISABLE_DEFAULT_LOGGER "Disable default logger creation" OFF) # clang-tidy @@ -233,6 +234,7 @@ foreach( SPDLOG_NO_THREAD_ID SPDLOG_NO_TLS SPDLOG_NO_ATOMIC_LEVELS + SPDLOG_NO_STRUCTURED_SPDLOG SPDLOG_DISABLE_DEFAULT_LOGGER SPDLOG_USE_STD_FORMAT) if(${SPDLOG_OPTION}) diff --git a/include/spdlog/details/log_msg-inl.h b/include/spdlog/details/log_msg-inl.h index 065d43d3a8..da8bc170b6 100644 --- a/include/spdlog/details/log_msg-inl.h +++ b/include/spdlog/details/log_msg-inl.h @@ -27,7 +27,12 @@ SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::s , field_data_count(field_count) , context_field_data(threadlocal_context_head()) #endif -{} +{ +#ifdef SPDLOG_NO_STRUCTURED_SPDLOG + (void) fields; + (void) field_count; +#endif +} SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::source_loc loc, string_view_t a_logger_name, spdlog::level::level_enum lvl, spdlog::string_view_t msg) diff --git a/include/spdlog/details/log_msg.h b/include/spdlog/details/log_msg.h index e4c72d8039..9bb0af63df 100644 --- a/include/spdlog/details/log_msg.h +++ b/include/spdlog/details/log_msg.h @@ -32,9 +32,11 @@ struct SPDLOG_API log_msg source_loc source; string_view_t payload; +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG Field *field_data{nullptr}; size_t field_data_count{0}; std::shared_ptr context_field_data; +#endif // SPDLOG_NO_STRUCTURED_SPDLOG }; } // namespace details } // namespace spdlog diff --git a/include/spdlog/details/log_msg_buffer-inl.h b/include/spdlog/details/log_msg_buffer-inl.h index a735f57a0e..b9e27a5def 100644 --- a/include/spdlog/details/log_msg_buffer-inl.h +++ b/include/spdlog/details/log_msg_buffer-inl.h @@ -7,8 +7,6 @@ # include #endif -#include - namespace spdlog { namespace details { @@ -52,7 +50,6 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg_buffer &other) SPDLOG_INLINE log_msg_buffer::log_msg_buffer(log_msg_buffer &&other) SPDLOG_NOEXCEPT : log_msg{other}, buffer{std::move(other.buffer)} { - std::cout << "this_count=" << field_data_count << " other_count=" << other.field_data_count << std::endl; update_string_views(); } @@ -69,18 +66,16 @@ SPDLOG_INLINE log_msg_buffer &log_msg_buffer::operator=(log_msg_buffer &&other) { log_msg::operator=(other); buffer = std::move(other.buffer); - if (field_data_count != other.field_data_count) { - abort(); - } update_string_views(); return *this; } SPDLOG_INLINE void log_msg_buffer::update_string_views() { + size_t offset = 0; #ifndef SPDLOG_NO_STRUCTURED_SPDLOG field_data = reinterpret_cast(buffer.data()); - size_t offset = sizeof(Field) * field_data_count; + offset = sizeof(Field) * field_data_count; for (size_t i=0; i < field_data_count; i++) { field_data[i].name = string_view_t{buffer.data() + offset, field_data[i].name.size()}; offset += field_data[i].name.size(); diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h index 97ebd19ba6..2ca1295665 100644 --- a/include/spdlog/json_formatter-inl.h +++ b/include/spdlog/json_formatter-inl.h @@ -290,6 +290,7 @@ SPDLOG_INLINE bool is_numeric(FieldValueType type) SPDLOG_INLINE void json_formatter::format_data_field(const Field &field, spdlog::memory_buf_t &dest) { +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG // TODO: should we keep a hash table of field names->escaped field names? // If the same fields keep cropping up and have to be escaped again and again it could have // a small but noticeable impact on performance @@ -313,6 +314,10 @@ SPDLOG_INLINE void json_formatter::format_data_field(const Field &field, spdlog: dest.push_back(','); dest.push_back(' '); +#else + (void) field; + (void) dest; +#endif } @@ -327,6 +332,8 @@ SPDLOG_INLINE void json_formatter::format(const details::log_msg &msg, memory_bu for (auto &field_ptr: fields_) { field_ptr->format(msg, dest); } + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG for (size_t i=0; i < msg.field_data_count; i++) { format_data_field(msg.field_data[i], dest); } @@ -335,6 +342,7 @@ SPDLOG_INLINE void json_formatter::format(const details::log_msg &msg, memory_bu format_data_field(field, dest); } } +#endif // Strip trailing space if it's there if (dest[dest.size() -1] == ' ') { diff --git a/include/spdlog/pattern_formatter-inl.h b/include/spdlog/pattern_formatter-inl.h index aea01e5f51..f106975ee8 100644 --- a/include/spdlog/pattern_formatter-inl.h +++ b/include/spdlog/pattern_formatter-inl.h @@ -708,6 +708,7 @@ class V_formatter final : public flag_formatter // and lots more expressive things void format(const details::log_msg &msg, const std::tm &, memory_buf_t &dest) override { +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG // TODO: padding for (size_t i=0; i < msg.field_data_count; i++) { dest.push_back(' '); @@ -725,6 +726,10 @@ class V_formatter final : public flag_formatter details::append_value(field, dest); } } +#else + (void) msg; + (void) dest; +#endif // SPDLOG_NO_STRUCTURED_SPDLOG } }; diff --git a/include/spdlog/structured_spdlog-inl.h b/include/spdlog/structured_spdlog-inl.h index 9698df6994..10f141a8c2 100644 --- a/include/spdlog/structured_spdlog-inl.h +++ b/include/spdlog/structured_spdlog-inl.h @@ -1,6 +1,8 @@ // Copyright(c) 2015-present, Gabi Melman & spdlog contributors. // Distributed under the MIT License (http://opensource.org/licenses/MIT) +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + #ifndef STRUCTURED_SPDLOG_INL_H #define STRUCTURED_SPDLOG_INL_H @@ -10,6 +12,12 @@ # include #endif +// TODO(opt): static field names on the stack +// Rather than passing std::initializer_list, I intuit that we should be able to construct +// templates such that log_ eventually gets passed a std::array && names and +// std::array && values. The names will in most cases be constexprs and can be built +// entirely in the data segment, and the runtime will be copying only the value data in + namespace spdlog { namespace details { @@ -154,4 +162,6 @@ SPDLOG_INLINE replacement_context::~replacement_context() } // namespace spdlog -#endif +#endif // STRUCTURED_SPDLOG_INL_H + +#endif // SPDLOG_NO_STRUCTURED_SPDLOG diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index b1707040c8..0268876e44 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -1,8 +1,7 @@ // Copyright(c) 2015-present, Gabi Melman & spdlog contributors. // Distributed under the MIT License (http://opensource.org/licenses/MIT) -// spdlog main header file. -// see example.cpp for usage example +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG #ifndef STRUCTURED_SPDLOG_H #define STRUCTURED_SPDLOG_H @@ -86,7 +85,7 @@ namespace details { /** - Using context_fields to represent the state of the application: + Using cotext to represent the state of the application: NOTE: it is important that the context variable has a name, or it will go out of scope immediately. RIGHT: spdlog::context ctx({{"field",value}}); @@ -107,6 +106,11 @@ namespace details { } int main() { + // Text output + spdlog::default_logger()->set_pattern("%v%V"); // or just use the default + foo(); + + // JSON output auto formatter = spdlog::json_formatter::make_unique({{"program", "contextfield_demo"}}); // process-wide context spdlog::default_logger()->set_formatter(formatter); foo(); @@ -133,6 +137,8 @@ class SPDLOG_API replacement_context final { } // namespace spdlog #endif // STRUCTURED_SPDLOG_H +#endif // NO_STRUCTURED_SPDLOG + #ifdef SPDLOG_HEADER_ONLY # include "structured_spdlog-inl.h" diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp index e42929c451..0ceeca8622 100644 --- a/tests/test_json_formatter.cpp +++ b/tests/test_json_formatter.cpp @@ -42,6 +42,7 @@ TEST_CASE("json basic output", "[json_formatter]") std::string time_output_regex = std::string(R"(\{"TM":")") + std::string(ISO8601_REGEX) + std::string(R"("\})"); REQUIRE_THAT(log_to_str("hello", {}, {{"TM", spdlog::ISO8601_FLAGS}}), Matches(time_output_regex)); +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG // Fields alone auto fields = {spdlog::F("f1", 1), spdlog::F("f2", "two"), spdlog::F("f3", 3.0), spdlog::F("f4",true)}; REQUIRE(log_to_str("hello", fields, {}) == R"({"f1":1, "f2":"two", "f3":3.000000, "f4":true})"); @@ -67,6 +68,7 @@ TEST_CASE("json basic output", "[json_formatter]") R"("f3":3.0+, )" + R"("f4":true})"; REQUIRE_THAT(log_to_str("hello", fields, {}, true), Matches(DEFAULT_RESULT_REGEX)); +#endif // SPDLOG_NO_STRUCTURED_SPDLOG } TEST_CASE("json escaped output", "[json_formatter]") @@ -74,8 +76,10 @@ TEST_CASE("json escaped output", "[json_formatter]") REQUIRE(log_to_str("hello_\x1a", {}, {{"MSG", "%v"}}) == R"({"MSG":"hello_\u001a"})"); REQUIRE(log_to_str("hello", {}, {{"MSG_\x1a", "%v"}}) == R"({"MSG_\u001a":"hello"})"); +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG auto fields = {spdlog::F("hello_\x1a", "goodbye_\x1b")}; REQUIRE(log_to_str("", fields, {}) == R"({"hello_\u001a":"goodbye_\u001b"})"); +#endif // SPDLOG_NO_STRUCTURED_SPDLOG } TEST_CASE("json escaping", "[json_formatter]") diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index d511bc4c00..dfd4e6afd5 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -1,3 +1,5 @@ +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + #include "includes.h" #include "test_sink.h" @@ -231,3 +233,6 @@ TEST_CASE("structured snapshots", "[structured]") step = LOG_IN_THREAD; thread->join(); } + + +#endif // SPDLOG_NO_STRUCTURED_SPDLOG From 4014269e2354ddcbeb77c173838fa6f2f82658b2 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Wed, 19 Jan 2022 11:55:51 -0800 Subject: [PATCH 12/21] Removed overly clever code in buffer_log_msg_buffer --- include/spdlog/common.h | 1 + include/spdlog/details/log_msg_buffer-inl.h | 20 +++++++++++--------- include/spdlog/details/log_msg_buffer.h | 4 ++++ tests/test_structured.cpp | 5 +++-- 4 files changed, 19 insertions(+), 11 deletions(-) diff --git a/include/spdlog/common.h b/include/spdlog/common.h index 22dd9a4e9f..ab6bbf3dd7 100644 --- a/include/spdlog/common.h +++ b/include/spdlog/common.h @@ -15,6 +15,7 @@ #include #include #include +#include #ifdef SPDLOG_USE_STD_FORMAT # include diff --git a/include/spdlog/details/log_msg_buffer-inl.h b/include/spdlog/details/log_msg_buffer-inl.h index b9e27a5def..251c4e2a3a 100644 --- a/include/spdlog/details/log_msg_buffer-inl.h +++ b/include/spdlog/details/log_msg_buffer-inl.h @@ -14,9 +14,10 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg &orig_msg) : log_msg{orig_msg} { #ifndef SPDLOG_NO_STRUCTURED_SPDLOG - // Start with struct copies so that objects stay nicely aligned, but strings - // can be packed in at the end - buffer.append(reinterpret_cast(field_data), reinterpret_cast(field_data + field_data_count)); + field_buffer = std::vector(field_data, field_data + field_data_count); + field_data = field_buffer.data(); + + // Copy strings from fields for (size_t i=0; i < field_data_count; i++) { buffer.append(field_data[i].name); if (field_data[i].value_type == FieldValueType::STRING_VIEW) { @@ -33,9 +34,10 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg_buffer &other) : log_msg{other} { #ifndef SPDLOG_NO_STRUCTURED_SPDLOG - // Start with struct copies so that objects stay nicely aligned, but strings - // can be packed in at the end - buffer.append(reinterpret_cast(field_data), reinterpret_cast(field_data + field_data_count)); + field_buffer = std::vector(field_data, field_data + field_data_count); + field_data = field_buffer.data(); + + // Copy strings from fields for (size_t i=0; i < field_data_count; i++) { buffer.append(field_data[i].name); if (field_data[i].value_type == FieldValueType::STRING_VIEW) { @@ -48,7 +50,7 @@ SPDLOG_INLINE log_msg_buffer::log_msg_buffer(const log_msg_buffer &other) update_string_views(); } -SPDLOG_INLINE log_msg_buffer::log_msg_buffer(log_msg_buffer &&other) SPDLOG_NOEXCEPT : log_msg{other}, buffer{std::move(other.buffer)} +SPDLOG_INLINE log_msg_buffer::log_msg_buffer(log_msg_buffer &&other) SPDLOG_NOEXCEPT : log_msg{other}, buffer{std::move(other.buffer)}, field_buffer{std::move(other.field_buffer)} { update_string_views(); } @@ -58,6 +60,7 @@ SPDLOG_INLINE log_msg_buffer &log_msg_buffer::operator=(const log_msg_buffer &ot log_msg::operator=(other); buffer.clear(); buffer.append(other.buffer.data(), other.buffer.data() + other.buffer.size()); + field_buffer = other.field_buffer; update_string_views(); return *this; } @@ -66,6 +69,7 @@ SPDLOG_INLINE log_msg_buffer &log_msg_buffer::operator=(log_msg_buffer &&other) { log_msg::operator=(other); buffer = std::move(other.buffer); + field_buffer = std::move(other.field_buffer); update_string_views(); return *this; } @@ -74,8 +78,6 @@ SPDLOG_INLINE void log_msg_buffer::update_string_views() { size_t offset = 0; #ifndef SPDLOG_NO_STRUCTURED_SPDLOG - field_data = reinterpret_cast(buffer.data()); - offset = sizeof(Field) * field_data_count; for (size_t i=0; i < field_data_count; i++) { field_data[i].name = string_view_t{buffer.data() + offset, field_data[i].name.size()}; offset += field_data[i].name.size(); diff --git a/include/spdlog/details/log_msg_buffer.h b/include/spdlog/details/log_msg_buffer.h index 8105506563..118388cf16 100644 --- a/include/spdlog/details/log_msg_buffer.h +++ b/include/spdlog/details/log_msg_buffer.h @@ -5,6 +5,8 @@ #include +#include + namespace spdlog { namespace details { @@ -14,6 +16,8 @@ namespace details { class SPDLOG_API log_msg_buffer : public log_msg { memory_buf_t buffer; + std::vector field_buffer; + void update_string_views(); public: diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index dfd4e6afd5..7822a7c042 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -212,8 +212,9 @@ TEST_CASE("structured snapshots", "[structured]") std::unique_ptr thread; { spdlog::context inner_ctx({{"c1","1"}}); - thread = std::make_unique( - [ctx_snapshot=spdlog::snapshot_context_fields(), &step] { + auto ctx_snapshot=spdlog::snapshot_context_fields(); + thread = spdlog::details::make_unique( + [ctx_snapshot, &step] { spdlog::replacement_context ctx(ctx_snapshot); step = steps::CTX_REPLACED; while(step != LOG_IN_THREAD) ; // spin until ready From 0cbd31e1507ec3b70b43a129a180842d52dc67d2 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Wed, 19 Jan 2022 17:10:44 -0800 Subject: [PATCH 13/21] Fix up examples and readme --- README.md | 148 ++++++++++++++++++++++------ bench/bench.cpp | 64 +++++++++++- example/example.cpp | 18 +++- include/spdlog/json_formatter-inl.h | 4 +- include/spdlog/json_formatter.h | 2 +- include/spdlog/spdlog.h | 34 +++++++ include/spdlog/structured_spdlog.h | 2 +- 7 files changed, 234 insertions(+), 38 deletions(-) diff --git a/README.md b/README.md index caac8f6ce9..15f9237b02 100644 --- a/README.md +++ b/README.md @@ -2,7 +2,101 @@ Very fast, header-only/compiled, C++ logging library. [![Build Status](https://app.travis-ci.com/gabime/spdlog.svg?branch=v1.x)](https://app.travis-ci.com/gabime/spdlog)  [![Build status](https://ci.appveyor.com/api/projects/status/d2jnxclg20vd0o50?svg=true&branch=v1.x)](https://ci.appveyor.com/project/gabime/spdlog) [![Release](https://img.shields.io/github/release/gabime/spdlog.svg)](https://github.com/gabime/spdlog/releases/latest) -## Install +## Using Structured spdlog +```c++ +#include "spdlog/structured_spdlog.h" +#include "spdlog/json_formatter.h" + +int main() +{ + // Output structured data + spdlog::info({{"field1","value1"}, {"field2",2.0}}, "Log fields and values"); + //--> [2022-01-19 15:52:03.301] [info] Log fields and values field1:value1 field2:2.000000 + + // Set up a json formatter. Not required, but very useful for parsing logs + spdlog::set_formatter(std::make_unique()); + SPDLOG_INFO({{"field1","value2"}, {"field2",4.0}}, "JSON logging is good for fields"); + //--> {"time":"2022-01-19T15:52:03.301814-08:00", "level":"info", + // "msg":"JSON logging is good for fields", "src_loc":"example.cpp:56", + // "field1":"value2", "field2":4.000000} + + // Put current context on the stack and have it included in subsequent log statements + { + spdlog::context ctx({{"txn_id",12292338}}); + SPDLOG_INFO("Starting txn"); + //--> {"time":..., "msg":"Starting txn", "txn_id":12292338} + } + + // Put your favorite pattern fields into the json + spdlog::set_formatter(spdlog::json_formatter::make_unique( + {{"thread_id","%t",spdlog::json_field_type::NUMERIC}, {"msg","%v"}})); + { + spdlog::context ctx({{"txn_id",60841}}); + SPDLOG_INFO("New txn"); + //--> {"thread_id":10468, "msg":"New txn", "txn_id":60841} + } + + // Carry contexts across your favorite thread pool + spdlog::context inner_ctx({{"outer","ctx"}}); + auto ctx_snapshot=spdlog::snapshot_context_fields(); + std::thread thread = spdlog::details::make_unique( + [ctx_snapshot] { + spdlog::context thread_ctx({{"position",1}}); + spdlog::info("Started a thread"); + spdlog::replacement_context ctx(ctx_snapshot); // Replace the existing contexts + spdlog::context thread_ctx2({{"superposition",2}}); + spdlog::info("In a thread"); + }); + thread.join(); + //--> {"msg":"Started a thread", "position":1} + // {"msg":"In a thread", "superposition":2, "outer":"ctx"} + +} +``` + +## Structured performance +(on a 24-CPU Broadwell VM) + +Summary: +* If compiled with -DSPDLOG_NO_STRUCUTRED_SPDLOG=ON, no statistically significant slowdown +* w/ structured on, ~6% slowdown (independent of depth of stack contexts) +* w/ json output, ~50% slowdown (definite room for optimizations) + +| benchmark | origin/v1.x | structured_v0
-DSPDLOG_NO_STRUCUTRED_SPDLOG=ON | structured_v0 | +|-------------|-------------|----------------|-------------| +| basic_st | 2.34M/s ± 0.04M/s | 2.25M/s ± 0.05M/s | 2.20M/s ± 0.06M/s | +| 1x basic_mt | 2.15M/s ± 0.04M/s | 2.09M/s ± 0.04M/s | 2.03M/s ± 0.05M/s | +| 4x basic_mt | 1.24M/s ± 0.02M/s | 1.24M/s ± 0.02M/s | 1.20M/s ± 0.02M/s | +| field_st | | | 2.28M/s ± 0.04M/s | +| 1ctx_st | | | 2.25M/s ± 0.04M/s | +| 10ctx_st | | | 2.24M/s ± 0.04M/s | +| field_json_st | | | 1.15M/s ± 0.02M/s | + +* All numbers reported with 95% confidence interval over 100 runs +* Run with ``cmake -DCMAKE_BUILD_TYPE=Release -DSPDLOG_BUILD_BENCH=ON && make -j && for i in {1..100}; do bench/bench > "/tmp/spdlog-`git rev-parse HEAD`-`date +%s`"; done`` +* New benchmarks: + * field_st: Implement ``bench_fields`` with ``log->log(spdlog::source_loc{}, spdlog::level::info, {{"msg number",i}}, "Hello logger");`` + * 1ctx: ``spdlog::context ctx({{"ctx", 1}}); bench_fields(iters, basic_1ctx_st);`` + * 10ctx: ``spdlog::context ctx1({{"ctx", 1}}); spdlog::context ctx2({{"ctx", 1}}); ...; bench_fields(iters, basic_10ctx_st);`` + * field_json_st: ``basic_json_st->set_formatter(spdlog::details::make_unique()); bench_fields(iters, basic_json_st);`` + +## Structured TODOs + +* Optimization + * Current implementation was written for efficiency, but not optimized yet +* wchar support +* Complete the set of convenience functions + * e.g. ``spdlog::log(level, fields, msg); + * Note that it intentionally doesn't expose Fields + fmt+args; we've found it's generally best to move things to fields whenever you touch the logging + * If you really need to you can use ``fmt::format()`` for the message +* Test on all combinations of builds + * Tested on linux, with and without -DSPDLOG_NO_STRUCUTRED_SPDLOG set +* Custom tags w/ JSON formatter +* Printing objects to JSON +* Format specifiers for floats on the stack + + +## Install #### Header only version Copy the include [folder](https://github.com/gabime/spdlog/tree/v1.x/include/spdlog) to your build tree and use a C++11 compiler. @@ -12,7 +106,7 @@ $ git clone https://github.com/gabime/spdlog.git $ cd spdlog && mkdir build && cd build $ cmake .. && make -j ``` - + see example [CMakeLists.txt](https://github.com/gabime/spdlog/blob/v1.x/example/CMakeLists.txt) on how to use. ## Platforms @@ -53,30 +147,30 @@ $ cmake .. && make -j * Log filtering - log levels can be modified in runtime as well as in compile time. * Support for loading log levels from argv or from environment var. * [Backtrace](#backtrace-support) support - store debug messages in a ring buffer and display later on demand. - + ## Usage samples #### Basic usage ```c++ #include "spdlog/spdlog.h" -int main() +int main() { spdlog::info("Welcome to spdlog!"); spdlog::error("Some error message with arg: {}", 1); - + spdlog::warn("Easy padding in numbers like {:08d}", 12); spdlog::critical("Support for int: {0:d}; hex: {0:x}; oct: {0:o}; bin: {0:b}", 42); spdlog::info("Support for floats {:03.2f}", 1.23456); spdlog::info("Positional args are {1} {0}..", "too", "supported"); spdlog::info("{:<30}", "left aligned"); - + spdlog::set_level(spdlog::level::debug); // Set global log level to debug - spdlog::debug("This message should be displayed.."); - + spdlog::debug("This message should be displayed.."); + // change log pattern spdlog::set_pattern("[%H:%M:%S %z] [%n] [%^---%L---%$] [thread %t] %v"); - + // Compile time log levels // define SPDLOG_ACTIVE_LEVEL to desired level SPDLOG_TRACE("Some trace message with param {}", 42); @@ -92,8 +186,8 @@ int main() void stdout_example() { // create color multi threaded logger - auto console = spdlog::stdout_color_mt("console"); - auto err_logger = spdlog::stderr_color_mt("stderr"); + auto console = spdlog::stdout_color_mt("console"); + auto err_logger = spdlog::stderr_color_mt("stderr"); spdlog::get("console")->info("loggers can be retrieved from a global registry using the spdlog::get(logger_name)"); } ``` @@ -104,7 +198,7 @@ void stdout_example() #include "spdlog/sinks/basic_file_sink.h" void basic_logfile_example() { - try + try { auto logger = spdlog::basic_logger_mt("basic_logger", "logs/basic-log.txt"); } @@ -175,9 +269,9 @@ spdlog::flush_every(std::chrono::seconds(3)); #include "spdlog/stopwatch.h" void stopwatch_example() { - spdlog::stopwatch sw; + spdlog::stopwatch sw; spdlog::debug("Elapsed {}", sw); - spdlog::debug("Elapsed {:.3}", sw); + spdlog::debug("Elapsed {:.3}", sw); } ``` @@ -243,13 +337,13 @@ void async_example() // spdlog::init_thread_pool(8192, 1); // queue with 8k items and 1 backing thread. auto async_file = spdlog::basic_logger_mt("async_file_logger", "logs/async_log.txt"); // alternatively: - // auto async_file = spdlog::create_async("async_file_logger", "logs/async_log.txt"); + // auto async_file = spdlog::create_async("async_file_logger", "logs/async_log.txt"); } ``` --- -#### Asynchronous logger with multi sinks +#### Asynchronous logger with multi sinks ```c++ #include "spdlog/sinks/stdout_color_sinks.h" #include "spdlog/sinks/rotating_file_sink.h" @@ -264,7 +358,7 @@ void multi_sink_example2() spdlog::register_logger(logger); } ``` - + --- #### User defined types ```c++ @@ -289,7 +383,7 @@ void user_defined_example() --- #### User defined flags in the log pattern -```c++ +```c++ // Log patterns can contain custom flags. // the following example will add new flag '%*' - which will be bound to a instance. #include "spdlog/pattern_formatter.h" @@ -309,7 +403,7 @@ public: }; void custom_flags_example() -{ +{ auto formatter = std::make_unique(); formatter->add_flag('*').set_pattern("[%n] [%*] [%^%l%$] %v"); spdlog::set_formatter(std::move(formatter)); @@ -330,7 +424,7 @@ void err_handler_example() ``` --- -#### syslog +#### syslog ```c++ #include "spdlog/sinks/syslog_sink.h" void syslog_example() @@ -341,7 +435,7 @@ void syslog_example() } ``` --- -#### Android example +#### Android example ```c++ #include "spdlog/sinks/android_sink.h" void android_example() @@ -377,7 +471,7 @@ $ ./example --- #### Log file open/close event handlers ```c++ -// You can get callbacks from spdlog before/after log file has been opened or closed. +// You can get callbacks from spdlog before/after log file has been opened or closed. // This is useful for cleanup procedures or for adding someting the start/end of the log files. void file_events_example() { @@ -387,7 +481,7 @@ void file_events_example() handlers.after_open = [](spdlog::filename_t filename, std::FILE *fstream) { fputs("After opening\n", fstream); }; handlers.before_close = [](spdlog::filename_t filename, std::FILE *fstream) { fputs("Before closing\n", fstream); }; handlers.after_close = [](spdlog::filename_t filename) { spdlog::info("After closing {}", filename); }; - auto my_logger = spdlog::basic_logger_st("some_logger", "logs/events-sample.txt", true, handlers); + auto my_logger = spdlog::basic_logger_st("some_logger", "logs/events-sample.txt", true, handlers); } ``` @@ -437,16 +531,16 @@ Below are some [benchmarks](https://github.com/gabime/spdlog/blob/v1.x/bench/ben [info] Messages : 1,000,000 [info] Threads : 10 [info] Queue : 8,192 slots -[info] Queue memory : 8,192 x 272 = 2,176 KB +[info] Queue memory : 8,192 x 272 = 2,176 KB [info] ------------------------------------------------- -[info] +[info] [info] ********************************* [info] Queue Overflow Policy: block [info] ********************************* [info] Elapsed: 1.70784 secs 585,535/sec [info] Elapsed: 1.69805 secs 588,910/sec [info] Elapsed: 1.7026 secs 587,337/sec -[info] +[info] [info] ********************************* [info] Queue Overflow Policy: overrun [info] ********************************* @@ -462,5 +556,3 @@ Documentation can be found in the [wiki](https://github.com/gabime/spdlog/wiki/1 --- Thanks to [JetBrains](https://www.jetbrains.com/?from=spdlog) for donating product licenses to help develop **spdlog** - - diff --git a/bench/bench.cpp b/bench/bench.cpp index 8a46837a6a..d5309c1530 100644 --- a/bench/bench.cpp +++ b/bench/bench.cpp @@ -30,6 +30,13 @@ void bench(int howmany, std::shared_ptr log); void bench_mt(int howmany, std::shared_ptr log, size_t thread_count); +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +#include "spdlog/structured_spdlog.h" +#include "spdlog/json_formatter.h" + +void bench_fields(int howmany, std::shared_ptr log); +#endif // SPDLOG_NO_STRUCTURED_SPDLOG + // void bench_default_api(int howmany, std::shared_ptr log); // void bench_c_string(int howmany, std::shared_ptr log); @@ -108,6 +115,37 @@ void bench_single_threaded(int iters) empty_logger_tracing->set_level(spdlog::level::off); empty_logger_tracing->enable_backtrace(32); bench(iters, empty_logger_tracing); + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + spdlog::info(""); + auto basic_field_st = spdlog::basic_logger_st("basic_fields_st", "logs/basic_fields_st.log", true); + bench_fields(iters, basic_field_st); + + auto basic_json_st = spdlog::basic_logger_st("basic_json_st", "logs/basic_json_st.log", true); + basic_json_st->set_formatter(spdlog::details::make_unique()); + bench_fields(iters, basic_json_st); + + { + spdlog::context ctx({{"ctx", 1}}); + auto basic_1ctx_st = spdlog::basic_logger_st("basic_1ctx_st", "logs/basic_1ctx_st.log", true); + bench_fields(iters, basic_1ctx_st); + } + + { + spdlog::context ctx0({{"ctx", 1}}); + spdlog::context ctx1({{"ctx", 1}}); + spdlog::context ctx2({{"ctx", 1}}); + spdlog::context ctx3({{"ctx", 1}}); + spdlog::context ctx4({{"ctx", 1}}); + spdlog::context ctx5({{"ctx", 1}}); + spdlog::context ctx6({{"ctx", 1}}); + spdlog::context ctx7({{"ctx", 1}}); + spdlog::context ctx8({{"ctx", 1}}); + spdlog::context ctx9({{"ctx", 1}}); + auto basic_10ctx_st = spdlog::basic_logger_st("basic_10ctx_st", "logs/basic_10ctx_st.log", true); + bench_fields(iters, basic_10ctx_st); + } +#endif } int main(int argc, char *argv[]) @@ -145,6 +183,30 @@ int main(int argc, char *argv[]) return EXIT_SUCCESS; } + +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +void bench_fields(int howmany, std::shared_ptr log) +{ + using std::chrono::duration; + using std::chrono::duration_cast; + using std::chrono::high_resolution_clock; + + auto start = high_resolution_clock::now(); + for (auto i = 0; i < howmany; ++i) + { + log->log(spdlog::source_loc{}, spdlog::level::info, {{"msg number",i}}, "Hello logger"); + } + + auto delta = high_resolution_clock::now() - start; + auto delta_d = duration_cast>(delta).count(); + + spdlog::info(spdlog::fmt_lib::format( + std::locale("en_US.UTF-8"), "{:<30} Elapsed: {:0.2f} secs {:>16L}/sec", log->name(), delta_d, int(howmany / delta_d))); + spdlog::drop(log->name()); +} +#endif + + void bench(int howmany, std::shared_ptr log) { using std::chrono::duration; @@ -245,4 +307,4 @@ void bench_c_string(int howmany, std::shared_ptr log) spdlog::info("{:<30} Elapsed: {:0.2f} secs {:>16}/sec", log->name(), delta_d, int(howmany / delta_d)); } -*/ \ No newline at end of file +*/ diff --git a/example/example.cpp b/example/example.cpp index c1251b1bed..a87db8a117 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -27,6 +27,7 @@ void file_events_example(); void replace_default_logger_example(); #include "spdlog/spdlog.h" +#include "spdlog/json_formatter.h" #include "spdlog/cfg/env.h" // support for loading levels from the environment variable #include "spdlog/fmt/ostr.h" // support for user defined types @@ -49,6 +50,13 @@ int main(int, char *[]) spdlog::set_level(spdlog::level::trace); // Set specific logger's log level spdlog::debug("This message should be displayed.."); +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + // Structured data + spdlog::info({{"field1","value1"}, {"field2",2.0}}, "You can output data with fields and values"); + spdlog::set_formatter(spdlog::details::make_unique()); + SPDLOG_INFO({{"field1","value2"}, {"field2",4.0}}, "JSON logging is good for fields"); +#endif + // Customize msg format for all loggers spdlog::set_pattern("[%H:%M:%S %z] [%^%L%$] [thread %t] %v"); spdlog::info("This an info message with custom format"); @@ -199,8 +207,8 @@ void vector_example() spdlog::info("Vector example: {}", vec); } -#else -void vector_example() {} +#else +void vector_example() {} #endif // ! DSPDLOG_USE_STD_FORMAT @@ -266,7 +274,7 @@ template<> struct fmt_lib::formatter : fmt_lib::formatter { auto format(my_type my, format_context &ctx) -> decltype(ctx.out()) - { + { return fmt_lib::format_to(ctx.out(), "[my_type i={}]", my.i); } }; @@ -359,9 +367,9 @@ void replace_default_logger_example() auto new_logger = spdlog::basic_logger_mt("new_default_logger", "logs/new-default-log.txt", true); spdlog::set_default_logger(new_logger); - spdlog::set_level(spdlog::level::info); + spdlog::set_level(spdlog::level::info); spdlog::debug("This message should not be displayed!"); - spdlog::set_level(spdlog::level::trace); + spdlog::set_level(spdlog::level::trace); spdlog::debug("This message should be displayed.."); spdlog::set_default_logger(old_logger); diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h index 2ca1295665..dca8adb697 100644 --- a/include/spdlog/json_formatter-inl.h +++ b/include/spdlog/json_formatter-inl.h @@ -244,7 +244,7 @@ SPDLOG_INLINE json_formatter::json_formatter(pattern_time_type time_type, std::s SPDLOG_INLINE json_formatter& json_formatter::add_default_fields() { return add_field("time", ISO8601_FLAGS).add_field("level", "%l"). - add_field("msg", "%v", json_field_type::STRING).add_field("src_loc", "%@"); + add_field("msg", "%v", json_field_type::STRING).add_field("src_loc", "%s:%#"); } SPDLOG_INLINE json_formatter &json_formatter::add_field(std::string field_name, std::string pattern, json_field_type field_type) @@ -258,7 +258,7 @@ SPDLOG_INLINE json_formatter &json_formatter::add_field(std::string field_name, SPDLOG_INLINE std::unique_ptr json_formatter::clone() const { - auto result = details::make_unique(pattern_time_type_, eol_); + auto result = make_unique({}, pattern_time_type_, eol_); for (auto &field: fields_) { result->fields_.emplace_back(std::move(field->clone())); } diff --git a/include/spdlog/json_formatter.h b/include/spdlog/json_formatter.h index 3655d37c72..7ed5966724 100644 --- a/include/spdlog/json_formatter.h +++ b/include/spdlog/json_formatter.h @@ -63,7 +63,7 @@ class SPDLOG_API json_formatter final : public formatter // With user-selected fields json_formatter(std::initializer_list fields, pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol); - // Can't pass initializer_list through std::forward calls, including make_unique + // Can't pass initializer_list through std::forward calls, including std::make_unique static std::unique_ptr make_unique(std::initializer_list fields, pattern_time_type time_type = pattern_time_type::local, std::string eol = spdlog::details::os::default_eol) { return std::unique_ptr(new json_formatter(fields, time_type, eol)); diff --git a/include/spdlog/spdlog.h b/include/spdlog/spdlog.h index 65d3e9d59f..18d7f585b1 100644 --- a/include/spdlog/spdlog.h +++ b/include/spdlog/spdlog.h @@ -187,6 +187,40 @@ inline void log(level::level_enum lvl, const T &msg) default_logger_raw()->log(lvl, msg); } +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG +inline void trace(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::trace, fields, msg); +} + +inline void debug(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::debug, fields, msg); +} + +inline void info(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::info, fields, msg); +} + +inline void warn(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::warn, fields, msg); +} + +inline void error(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::err, fields, msg); +} + +inline void critical(std::initializer_list fields, string_view_t msg) +{ + default_logger_raw()->log(source_loc{}, level::critical, fields, msg); +} +#endif // SPDLOG_NO_STRUCTURED_SPDLOG + + + #ifdef SPDLOG_WCHAR_TO_UTF8_SUPPORT template inline void log(source_loc source, level::level_enum lvl, wformat_string_t fmt, Args &&... args) diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index 0268876e44..e3cfe45973 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -8,7 +8,7 @@ #pragma once -#include "spdlog.h" +#include "spdlog/common.h" #include From 7e706606177c163fdcd74341077daa7c9311008c Mon Sep 17 00:00:00 2001 From: bobhansen Date: Fri, 21 Jan 2022 13:36:05 -0500 Subject: [PATCH 14/21] Code review updates Co-authored-by: Ben --- README.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index 15f9237b02..708b16bc9d 100644 --- a/README.md +++ b/README.md @@ -58,7 +58,8 @@ int main() (on a 24-CPU Broadwell VM) Summary: -* If compiled with -DSPDLOG_NO_STRUCUTRED_SPDLOG=ON, no statistically significant slowdown +* If compiled with -DSPDLOG_NO_STRUCTURED_SPDLOG=ON, no statistically significant slowdown + * w/ structured on, ~6% slowdown (independent of depth of stack contexts) * w/ json output, ~50% slowdown (definite room for optimizations) From 9799e67243c06775b7c55f18d4822935b98820e3 Mon Sep 17 00:00:00 2001 From: bobhansen Date: Fri, 21 Jan 2022 14:16:35 -0500 Subject: [PATCH 15/21] Apply suggestions from code review Co-authored-by: Ben --- README.md | 9 ++++++--- include/spdlog/details/log_msg-inl.h | 1 + include/spdlog/structured_spdlog.h | 2 +- tests/test_json_formatter.cpp | 2 +- 4 files changed, 9 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 708b16bc9d..31590389d6 100644 --- a/README.md +++ b/README.md @@ -63,7 +63,8 @@ Summary: * w/ structured on, ~6% slowdown (independent of depth of stack contexts) * w/ json output, ~50% slowdown (definite room for optimizations) -| benchmark | origin/v1.x | structured_v0
-DSPDLOG_NO_STRUCUTRED_SPDLOG=ON | structured_v0 | +| benchmark | origin/v1.x | structured_v0
-DSPDLOG_NO_STRUCTURED_SPDLOG=ON | structured_v0 | + |-------------|-------------|----------------|-------------| | basic_st | 2.34M/s ± 0.04M/s | 2.25M/s ± 0.05M/s | 2.20M/s ± 0.06M/s | | 1x basic_mt | 2.15M/s ± 0.04M/s | 2.09M/s ± 0.04M/s | 2.03M/s ± 0.05M/s | @@ -87,11 +88,13 @@ Summary: * Current implementation was written for efficiency, but not optimized yet * wchar support * Complete the set of convenience functions - * e.g. ``spdlog::log(level, fields, msg); + * e.g. ``spdlog::log(level, fields, msg);`` + * Note that it intentionally doesn't expose Fields + fmt+args; we've found it's generally best to move things to fields whenever you touch the logging * If you really need to you can use ``fmt::format()`` for the message * Test on all combinations of builds - * Tested on linux, with and without -DSPDLOG_NO_STRUCUTRED_SPDLOG set + * Tested on linux, with and without -DSPDLOG_NO_STRUCTURED_SPDLOG set + * Custom tags w/ JSON formatter * Printing objects to JSON * Format specifiers for floats on the stack diff --git a/include/spdlog/details/log_msg-inl.h b/include/spdlog/details/log_msg-inl.h index da8bc170b6..4fccc2d30e 100644 --- a/include/spdlog/details/log_msg-inl.h +++ b/include/spdlog/details/log_msg-inl.h @@ -29,6 +29,7 @@ SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::s #endif { #ifdef SPDLOG_NO_STRUCTURED_SPDLOG + // Prevent unused argument warning (void) fields; (void) field_count; #endif diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index e3cfe45973..a6f7ff6fd3 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -85,7 +85,7 @@ namespace details { /** - Using cotext to represent the state of the application: + Using context to represent the state of the application: NOTE: it is important that the context variable has a name, or it will go out of scope immediately. RIGHT: spdlog::context ctx({{"field",value}}); diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp index 0ceeca8622..007ee59e08 100644 --- a/tests/test_json_formatter.cpp +++ b/tests/test_json_formatter.cpp @@ -138,7 +138,7 @@ TEST_CASE("json escaping", "[json_formatter]") spdlog::details::escape_to_end(buffer, 0); REQUIRE(to_string(buffer) == before); - // Skipping alread-esacped parts + // Skipping already-escaped parts buffer.resize(0); memset(&buffer[0], '~', buffer.capacity()); std::string already_done{"\\\"foo\": \""}; From a07e60bccb36e47bbc9395938614b22647387915 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Fri, 21 Jan 2022 12:24:29 -0800 Subject: [PATCH 16/21] Code review follow-ups --- CMakeLists.txt | 1 - include/spdlog/json_formatter-inl.h | 18 ++++++++++++++--- include/spdlog/structured_spdlog.h | 2 +- tests/test_json_formatter.cpp | 3 ++- tests/test_structured.cpp | 31 ++++++++++++++++++++--------- 5 files changed, 40 insertions(+), 15 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index 7ca764c6ea..3344ac4042 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -72,7 +72,6 @@ option(SPDLOG_BUILD_TESTS_HO "Build tests using the header only version" OFF) # bench options option(SPDLOG_BUILD_BENCH "Build benchmarks (Requires https://github.com/google/benchmark.git to be installed)" OFF) option(SPDLOG_GOOGLEBENCHMARK_URL "Url of googlebenchmark git repository" https://github.com/google/benchmark.git) -# git@github.com:google/benchmark.git # sanitizer options option(SPDLOG_SANITIZE_ADDRESS "Enable address sanitizer in tests" OFF) diff --git a/include/spdlog/json_formatter-inl.h b/include/spdlog/json_formatter-inl.h index dca8adb697..a9ce87b078 100644 --- a/include/spdlog/json_formatter-inl.h +++ b/include/spdlog/json_formatter-inl.h @@ -29,6 +29,7 @@ SPDLOG_CONSTEXPR char hex_digits[] = "0123456789abcdef"; // 5 -> escape to \uXXXXX // 1 -> escape to \n, \r or the like +// 0 -> do not escape SPDLOG_CONSTEXPR uint8_t extra_chars_lookup[256] = { 5, 5, 5, 5, 5, 5, 5, 5, 1, 1, 1, 5, 1, 1, 5, 5, // 0x0x 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, 5, // 0x1x @@ -67,6 +68,11 @@ SPDLOG_INLINE void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset // know which bytes are consumed in multi-byte utf-8 encodings // See https://datatracker.ietf.org/doc/html/rfc3629 + // The checks are implemented by looking up in the extra_chars table that encodes + // how many extra bytes we need for each character. 0 implies it doesn't + // need to be escaped; 1 means that it's an encoded caracter (\r, \n, and the like), + // and 5 means that it needs to be unicode-escaped (\u0000). + // TODO: widechar support static_assert(sizeof(dest[0]) ==1, "Wide chars are not supported by escape_to_end yet"); @@ -143,8 +149,14 @@ SPDLOG_INLINE void escape_to_end(spdlog::memory_buf_t &dest, size_t start_offset SPDLOG_INLINE bool pattern_needs_escaping(string_view_t pattern) { - // Look for any % pattern that isn't in our whitelist of known-doesn't-need-escaping patterns - // Anything that can only emit printable ASCII is OK. + // As a performance boost, we know that there are certain spdlog %.. patterns + // that can only produce non-escaped ASCII. We can write those values + // straight out to the JSON without needing to check them for illegal characters + // + // Scan the user-supplied pattern to see if it contains text that needs to be + // escaped, or a pattern that is not in the KNOWN_CLEAN list + // We check for needs-to-be-escaped characters by checking the extra_chars table; + // anything that requires 0 extra chars doesn't need to be escaped. constexpr char KNOWN_CLEAN_PATTERNS[] = "LtplLaAbBcCYDxmdHIMSefFprRTXzE%#oiuO"; @@ -155,7 +167,7 @@ SPDLOG_INLINE bool pattern_needs_escaping(string_view_t pattern) i++; c = static_cast(pattern[i]); - // TODO: make this a binary search + // TODO(opt): make this a hash lookup bool flag_char_is_clean = false; for (auto clean: KNOWN_CLEAN_PATTERNS) { if (clean == c) { diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index a6f7ff6fd3..4a945f8211 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -26,7 +26,7 @@ SPDLOG_API struct context_iterator } } **/ - using iterator_catecory = std::forward_iterator_tag; + using iterator_category = std::forward_iterator_tag; using value_type = Field; using pointer = const Field*; using reference = const Field&; diff --git a/tests/test_json_formatter.cpp b/tests/test_json_formatter.cpp index 007ee59e08..8c0fa9f9ac 100644 --- a/tests/test_json_formatter.cpp +++ b/tests/test_json_formatter.cpp @@ -127,7 +127,8 @@ TEST_CASE("json escaping", "[json_formatter]") REQUIRE(to_string(buffer) == "\\\\\\r\\n\\t\\b\\f\\\""); // Not escaped - buffer.resize(256 - 39); + constexpr size_t NUM_ESCAPED_CHARS = 39; // 32 that are <= 0x1f, and 7 that are \r, \n, etc. + buffer.resize(256 - NUM_ESCAPED_CHARS); char *p = &buffer[0]; for (int c=0; c <= 255; c++) { if (c <= 0x1f || c == '"' || c == '\\' || c == '\b' || c == '\f' || c == '\n' || c == '\r' || c == '\t') diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index 7822a7c042..e8b112e8b5 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -24,18 +24,31 @@ std::string log_info(std::initializer_list fields, spdlog::string TEST_CASE("fields", "[structured]") { - // Can we construct fields of all types with lvalues? - F("var", 1); - F("var", "val"); - - // Can we construct fields with rvalues? - std::string str1("str"); - spdlog::F(str1, str1); - // Can we construct fields with rvalues? + spdlog::F f_int("var", 1); + REQUIRE(f_int.value_type == spdlog::FieldValueType::INT); + + spdlog::F f_str_literal("var", "val"); + REQUIRE(f_str_literal.value_type == spdlog::FieldValueType::STRING_VIEW); + + // Can we construct fields with lvalues? + std::string str2("str"); + spdlog::F(str2, str1); + REQUIRE(str1.value_type == spdlog::FieldValueType::STRING_VIEW); + + // Const chars are troublesome; we really, really want the string literals to + // use their compile-time length, and std::strings to use their O(1) run-time + // length. The const char (&val)[N] and string_view constructors take care of + // those. + // If we include a const char * constructor, it will be preferred for string + // literals (unless we can arrange some template magic that works for C++11 and + // above). String literals will then have an O(n) cost, and that's no good + // If we don't include a const char * constructor, the compiler erases const char * + // to void *, which for historical resons binds to bool before anything else. + // So, for now, const char * maps to bool. :-| const char * cstr = "str"; auto cstr_f = spdlog::F(cstr, cstr); - REQUIRE(cstr_f.value_type == spdlog::FieldValueType::INT); + REQUIRE(cstr_f.value_type == spdlog::FieldValueType::BOOL); } TEST_CASE("field_logging", "[structured]") From 99b3dfe257d07eb16077767b6c8c4c68d8b9bf28 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Tue, 25 Jan 2022 12:03:25 -0800 Subject: [PATCH 17/21] Add context::reset --- include/spdlog/structured_spdlog-inl.h | 20 ++++++++++++++++++++ include/spdlog/structured_spdlog.h | 5 +++++ 2 files changed, 25 insertions(+) diff --git a/include/spdlog/structured_spdlog-inl.h b/include/spdlog/structured_spdlog-inl.h index 10f141a8c2..296f2c69ac 100644 --- a/include/spdlog/structured_spdlog-inl.h +++ b/include/spdlog/structured_spdlog-inl.h @@ -118,11 +118,31 @@ SPDLOG_INLINE context::context(std::initializer_list fields) context_to_restore_ = details::threadlocal_context_head(); } } + SPDLOG_INLINE context::~context() { details::threadlocal_context_head() = context_to_restore_; } +SPDLOG_INLINE void context::reset(std::initializer_list fields) +{ + auto parent_ptr = context_to_restore_; + + if (fields.size() > 0) { + auto new_context_head = std::make_shared(parent_ptr, fields.begin(), fields.size()); + details::threadlocal_context_head() = new_context_head; + } else { + // Reset current state to the parent of the old state + details::threadlocal_context_head() = parent_ptr; + + // Never store a link with zero fields; iterator++ needs to know that when it follows a traversal, it will + // be pointing to context_data with at least one field. + // When this goes out of context, just put the same head back + context_to_restore_ = parent_ptr; + } +} + + // context_iterators SPDLOG_INLINE context_iterator& context_iterator::operator++() { diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index 4a945f8211..3faad70c13 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -120,6 +120,11 @@ class SPDLOG_API context final { public: context(std::initializer_list fields); ~context(); + + // Replaces the contents of a context already on the stack with new values. + // Useful for putting at the top of a processing loop to hold the context and + // only reset it when something changes + void reset(std::initializer_list fields); private: std::shared_ptr context_to_restore_; }; From d48e56763467ca72971aaacd3cf942cd1f000953 Mon Sep 17 00:00:00 2001 From: bobhansen Date: Mon, 14 Feb 2022 16:36:01 -0500 Subject: [PATCH 18/21] Fixed table rendering in readme.md --- README.md | 1 - 1 file changed, 1 deletion(-) diff --git a/README.md b/README.md index 31590389d6..d66b2b8794 100644 --- a/README.md +++ b/README.md @@ -64,7 +64,6 @@ Summary: * w/ json output, ~50% slowdown (definite room for optimizations) | benchmark | origin/v1.x | structured_v0
-DSPDLOG_NO_STRUCTURED_SPDLOG=ON | structured_v0 | - |-------------|-------------|----------------|-------------| | basic_st | 2.34M/s ± 0.04M/s | 2.25M/s ± 0.05M/s | 2.20M/s ± 0.06M/s | | 1x basic_mt | 2.15M/s ± 0.04M/s | 2.09M/s ± 0.04M/s | 2.03M/s ± 0.05M/s | From 6cbf5752dccfb2e1967fa7a7e885bd357575874e Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Mon, 4 Apr 2022 14:24:41 -0700 Subject: [PATCH 19/21] Fixup lvalue field test --- tests/test_structured.cpp | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index e8b112e8b5..721b64c369 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -32,9 +32,10 @@ TEST_CASE("fields", "[structured]") REQUIRE(f_str_literal.value_type == spdlog::FieldValueType::STRING_VIEW); // Can we construct fields with lvalues? + std::string str1("key"); std::string str2("str"); - spdlog::F(str2, str1); - REQUIRE(str1.value_type == spdlog::FieldValueType::STRING_VIEW); + spdlog::F str_f(str1, str2); + REQUIRE(str_f.value_type == spdlog::FieldValueType::STRING_VIEW); // Const chars are troublesome; we really, really want the string literals to // use their compile-time length, and std::strings to use their O(1) run-time From 8c1c963b1715e77746cec26c1c60514a5423ab5f Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Mon, 4 Apr 2022 14:40:52 -0700 Subject: [PATCH 20/21] Added replacement_context with additional context --- include/spdlog/structured_spdlog-inl.h | 9 +++++++-- include/spdlog/structured_spdlog.h | 22 +++++++++++++++++++++- tests/test_structured.cpp | 20 ++++++++++++++++++++ 3 files changed, 48 insertions(+), 3 deletions(-) diff --git a/include/spdlog/structured_spdlog-inl.h b/include/spdlog/structured_spdlog-inl.h index 296f2c69ac..befdbf5b90 100644 --- a/include/spdlog/structured_spdlog-inl.h +++ b/include/spdlog/structured_spdlog-inl.h @@ -168,10 +168,15 @@ SPDLOG_INLINE details::context_snapshot snapshot_context_fields() return details::threadlocal_context_head(); } -SPDLOG_INLINE replacement_context::replacement_context(details::context_snapshot data) : +SPDLOG_INLINE replacement_context::replacement_context(details::context_snapshot data, std::initializer_list fields) : old_context_fields_(details::threadlocal_context_head()) { - details::threadlocal_context_head() = data; + if (fields.size() == 0) { + details::threadlocal_context_head() = data; + } else { + auto new_context_head = std::make_shared(data, fields.begin(), fields.size()); + details::threadlocal_context_head() = new_context_head; + } } SPDLOG_INLINE replacement_context::~replacement_context() diff --git a/include/spdlog/structured_spdlog.h b/include/spdlog/structured_spdlog.h index 3faad70c13..24d9dd0896 100644 --- a/include/spdlog/structured_spdlog.h +++ b/include/spdlog/structured_spdlog.h @@ -129,10 +129,30 @@ class SPDLOG_API context final { std::shared_ptr context_to_restore_; }; +/** + replacement_context replaces the current thread's entire context with a snapshot + of context from another thread. Useful when work is being passed via lambdas to + threadpools for execution. + + Can also be constructed with additional context for this instance. For example: + spdlog::context ctx({{"outer", "val"}}); + std::thread th([ctx_snapshot=snapshot_context_fields()] { // copy the threadlocal context for use in another thread + spdlog::replacement_context ctx(ctx_snapshot, + {{"thread_id"}, std::this_thread::get_id()}}); // Restore outer context with additional local context + spdlog::info({{"function", "in_thread"}}); // prints "outer:val thread_id:169 function:in_thread" + }); + th.join(); + +**/ SPDLOG_API details::context_snapshot snapshot_context_fields(); class SPDLOG_API replacement_context final { public: - replacement_context(details::context_snapshot data); + // Temporarily replace the current thread-local context with a snapshot from another thread + replacement_context(details::context_snapshot data) : replacement_context(data, {}) {}; + + // Temporarily replace the current thread-local context with a snapshot from another thread + // and additional local context + replacement_context(details::context_snapshot data, std::initializer_list fields); ~replacement_context(); private: std::shared_ptr old_context_fields_; diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index 721b64c369..140ec43888 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -250,4 +250,24 @@ TEST_CASE("structured snapshots", "[structured]") } +TEST_CASE("structured snapshots with ctx", "[structured]") +{ + std::unique_ptr thread; + { + spdlog::context inner_ctx({{"c1","1"}}); + auto ctx_snapshot=spdlog::snapshot_context_fields(); + thread = spdlog::details::make_unique( + [ctx_snapshot] { + { + spdlog::replacement_context ctx(ctx_snapshot, {{"c2", 2}}); + REQUIRE(log_info({}, "Hello") == "Hello c2:2 c1:1"); + } + REQUIRE(log_info({}, "Middle") == "Middle"); + }); + } + thread->join(); + REQUIRE(log_info({}, "Bye") == "Bye"); +} + + #endif // SPDLOG_NO_STRUCTURED_SPDLOG From 9efbaa5c421eac9562fece6b7ee581b6390cd0d9 Mon Sep 17 00:00:00 2001 From: Bob Hansen Date: Tue, 5 Apr 2022 13:47:11 -0700 Subject: [PATCH 21/21] Added info() and logger->info() et al. convenience functions --- include/spdlog/logger.h | 43 +++++++++++++++++++++++++++++++++++++++ tests/test_structured.cpp | 4 ++++ 2 files changed, 47 insertions(+) diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index 0ac971ce42..39c89168f4 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -266,6 +266,49 @@ class SPDLOG_API logger } #endif +#ifndef SPDLOG_NO_STRUCTURED_SPDLOG + void log(level::level_enum lvl, std::initializer_list fields, string_view_t msg) + { + log(source_loc{}, lvl, fields, msg); + } + + template + void trace(std::initializer_list fields, const T &msg) + { + log(level::trace, fields, msg); + } + + template + void debug(std::initializer_list fields, const T &msg) + { + log(level::debug, fields, msg); + } + + template + void info(std::initializer_list fields, const T &msg) + { + log(level::info, fields, msg); + } + + template + void warn(std::initializer_list fields, const T &msg) + { + log(level::warn, fields, msg); + } + + template + void error(std::initializer_list fields, const T &msg) + { + log(level::err, fields, msg); + } + + template + void critical(std::initializer_list fields, const T &msg) + { + log(level::critical, fields, msg); + } +#endif + template void trace(const T &msg) { diff --git a/tests/test_structured.cpp b/tests/test_structured.cpp index 140ec43888..7b5f8a4ec3 100644 --- a/tests/test_structured.cpp +++ b/tests/test_structured.cpp @@ -59,6 +59,10 @@ TEST_CASE("field_logging", "[structured]") // Some fields REQUIRE(log_info({F("k", 1)}, "Hello") == "Hello k:1"); + + // Test level calls + spdlog::info({{"field", 1}}, "Hello"); + spdlog::default_logger()->info({{"field", 2}}, "Hello"); } template