structured log bug fix and improvements

CHANGELOG.md

@@ -58,6 +58,10 @@
 ## v3.5.2
 
 - Fixed `QUILL_LOGGER_CALL_NOFN_LIMIT` macros. ([#381](https://github.com/odygrd/quill/pull/381))
+- Resolved a bug that caused reading destructed arguments when structured logging format was used.
+- Modified member access from `private` to `protected` in `ConsoleHandler` for potential inheritance purposes.
+- Eliminated redundant whitespaces within `JsonFileHandler`.
+- Fixed `JsonFileHandler` to notify the file event notifier before log message writes.
 
 ## v3.5.1
 

quill/include/quill/detail/Serialize.h

@@ -43,8 +43,7 @@ template <typename Arg>
 QUILL_NODISCARD constexpr bool is_type_of_c_array()
 {
   using ArgType = remove_cvref_t<Arg>;
-  return std::is_array_v<ArgType> &&
-    std::is_same_v<remove_cvref_t<std::remove_extent_t<ArgType>>, char>;
+  return std::is_array_v<ArgType> && std::is_same_v<remove_cvref_t<std::remove_extent_t<ArgType>>, char>;
 }
 
 template <typename Arg>
@@ -352,21 +351,21 @@ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT constexpr std::byte* encode_args(size_t* c_s
  */
 using FormatToFn = std::pair<std::byte*, std::string> (*)(
   std::string_view format, std::byte* data, transit_event_fmt_buffer_t& out,
-  std::vector<fmtquill::basic_format_arg<fmtquill::format_context>>& args);
+  std::vector<fmtquill::basic_format_arg<fmtquill::format_context>>& args,
+  std::vector<std::string>* structured_keys);
 using PrintfFormatToFn = std::pair<std::byte*, std::string> (*)(
   std::string_view format, std::byte* data, transit_event_fmt_buffer_t& out,
   std::vector<fmtquill::basic_format_arg<fmtquill::printf_context>>& args);
 
 template <typename... Args>
 QUILL_NODISCARD QUILL_ATTRIBUTE_HOT std::pair<std::byte*, std::string> format_to(
   std::string_view format, std::byte* data, transit_event_fmt_buffer_t& out,
-  std::vector<fmtquill::basic_format_arg<fmtquill::format_context>>& args)
+  std::vector<fmtquill::basic_format_arg<fmtquill::format_context>>& args, std::vector<std::string>* structured_values)
 {
   std::string error;
   constexpr size_t num_dtors = fmtquill::detail::count<need_call_dtor_for<Args>()...>();
   std::byte* dtor_args[(std::max)(num_dtors, static_cast<size_t>(1))];
 
-  args.clear();
   std::byte* ret = decode_args<fmtquill::format_context, 0, Args...>(data, args, dtor_args);
 
   out.clear();
@@ -375,6 +374,16 @@ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT std::pair<std::byte*, std::string> format_to
   {
     fmtquill::vformat_to(std::back_inserter(out), format,
                          fmtquill::basic_format_args(args.data(), sizeof...(Args)));
+
+    if (structured_values)
+    {
+      // if we are processing a structured log we need to pass the values of the args here
+      // At the end of the function we will be destructing the args
+      for (auto const& arg : args)
+      {
+        structured_values->emplace_back(fmtquill::vformat("{}", fmtquill::basic_format_args(&arg, 1)));
+      }
+    }
   }
 #if !defined(QUILL_NO_EXCEPTIONS)
   QUILL_CATCH(std::exception const& e)
@@ -386,6 +395,7 @@ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT std::pair<std::byte*, std::string> format_to
 #endif
 
   destruct_args<0, Args...>(dtor_args);
+  args.clear();
 
   return std::make_pair(ret, std::move(error));
 }
@@ -399,7 +409,6 @@ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT std::pair<std::byte*, std::string> printf_fo
   constexpr size_t num_dtors = fmtquill::detail::count<need_call_dtor_for<Args>()...>();
   std::byte* dtor_args[(std::max)(num_dtors, static_cast<size_t>(1))];
 
-  args.clear();
   std::byte* ret = decode_args<fmtquill::printf_context, 0, Args...>(data, args, dtor_args);
 
   out.clear();
@@ -419,6 +428,7 @@ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT std::pair<std::byte*, std::string> printf_fo
 #endif
 
   destruct_args<0, Args...>(dtor_args);
+  args.clear();
 
   return std::make_pair(ret, std::move(error));
 }
@@ -434,8 +444,7 @@ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT constexpr std::pair<MacroMetadata, std::pair
 {
   if constexpr (!IsPrintfFormat)
   {
-    constexpr auto ret =
-      std::make_pair(TAnonymousStruct{}(), std::make_pair(format_to<Args...>, nullptr));
+    constexpr auto ret = std::make_pair(TAnonymousStruct{}(), std::make_pair(format_to<Args...>, nullptr));
     return ret;
   }
   else
@@ -455,7 +464,9 @@ struct Header
 public:
   Header() = default;
   Header(MetadataFormatFn metadata_and_format_fn, LoggerDetails const* logger_details, uint64_t timestamp)
-    : metadata_and_format_fn(metadata_and_format_fn), logger_details(logger_details), timestamp(timestamp){}
+    : metadata_and_format_fn(metadata_and_format_fn), logger_details(logger_details), timestamp(timestamp)
+  {
+  }
 
   MetadataFormatFn metadata_and_format_fn{nullptr};
   LoggerDetails const* logger_details{nullptr};

quill/include/quill/detail/backend/BackendWorker.h

@@ -208,6 +208,7 @@ class BackendWorker
 
   std::vector<fmtquill::basic_format_arg<fmtquill::format_context>> _args; /** Format args tmp storage as member to avoid reallocation */
   std::vector<fmtquill::basic_format_arg<fmtquill::printf_context>> _printf_args; /** Format args tmp storage as member to avoid reallocation */
+  std::vector<std::string> _structured_values;
   std::vector<std::weak_ptr<Handler>> _active_handlers_cache;
 
   BacktraceStorage _backtrace_log_message_storage; /** Stores a vector of backtrace messages per logger name */

quill/include/quill/handlers/ConsoleHandler.h

@@ -209,7 +209,8 @@ class ConsoleHandler : public StreamHandler
   QUILL_NODISCARD ConsoleColours::WORD _set_foreground_colour(ConsoleColours::WORD attributes);
 #endif
 
-private:
+protected:
+  // protected in case someone wants to derive from this class and create a custom one, e.g. for json logging to stdout
   ConsoleColours _console_colours;
 };
-} // namespace quill
+} // namespace quill

quill/src/detail/backend/BackendWorker.cpp

@@ -147,7 +147,9 @@ bool BackendWorker::_get_transit_event_from_queue(std::byte*& read_pos, ThreadCo
       assert(!macro_metadata.is_structured_log_template() &&
              "structured log templates are not supported for wide characters");
 
-      auto const [pos, error] = format_to_fn(format_str, read_pos, transit_event->formatted_msg, _args);
+      auto const [pos, error] = 
+        format_to_fn(format_str, read_pos, transit_event->formatted_msg, _args, nullptr);
+
       read_pos = pos;
 
       if (QUILL_UNLIKELY(!error.empty()))
@@ -177,7 +179,8 @@ bool BackendWorker::_get_transit_event_from_queue(std::byte*& read_pos, ThreadCo
           auto const& [fmt_str, structured_keys] = search->second;
           s_keys = &structured_keys;
 
-          auto const [pos, error] = format_to_fn(fmt_str, read_pos, transit_event->formatted_msg, _args);
+          auto const [pos, error] =
+            format_to_fn(fmt_str, read_pos, transit_event->formatted_msg, _args, &_structured_values);
 
           read_pos = pos;
 
@@ -197,7 +200,8 @@ bool BackendWorker::_get_transit_event_from_queue(std::byte*& read_pos, ThreadCo
             _structured_fmt_str, std::make_pair(fmt_str, std::move(structured_keys)));
           s_keys = &(res.first->second.second);
 
-          auto const [pos, error] = format_to_fn(fmt_str, read_pos, transit_event->formatted_msg, _args);
+          auto const [pos, error] =
+            format_to_fn(fmt_str, read_pos, transit_event->formatted_msg, _args, &_structured_values);
 
           read_pos = pos;
 
@@ -208,29 +212,22 @@ bool BackendWorker::_get_transit_event_from_queue(std::byte*& read_pos, ThreadCo
           }
         }
 
-        // format the values to strings
-        std::vector<std::string> structured_values;
-        structured_values.reserve(s_keys->size());
-        for (auto const& arg : _args)
-        {
-          structured_values.emplace_back(fmtquill::vformat("{}", fmtquill::basic_format_args(&arg, 1)));
-        }
-
         // store them as kv pair
         transit_event->structured_kvs.clear();
         for (size_t i = 0; i < s_keys->size(); ++i)
         {
-          transit_event->structured_kvs.emplace_back((*s_keys)[i], std::move(structured_values[i]));
+          transit_event->structured_kvs.emplace_back((*s_keys)[i], std::move(_structured_values[i]));
         }
+        _structured_values.clear();
       }
       else
       {
         // regular logs
         if (format_to_fn)
         {
           // fmt style format
-          auto const [pos, error] =
-            format_to_fn(macro_metadata.message_format(), read_pos, transit_event->formatted_msg, _args);
+          auto const [pos, error] = format_to_fn(macro_metadata.message_format(), read_pos,
+                                                 transit_event->formatted_msg, _args, nullptr);
 
           read_pos = pos;
 
@@ -488,4 +485,4 @@ void BackendWorker::_resync_rdtsc_clock()
     }
   }
 }
-} // namespace quill::detail
+} // namespace quill::detail

quill/src/handlers/JsonFileHandler.cpp

@@ -11,18 +11,18 @@ void JsonFileHandler::write(fmt_buffer_t const& formatted_log_message, TransitEv
   _json_message.clear();
 
   _json_message.append(fmtquill::format(
-    R"({{ "timestamp": "{}", "file": "{}", "line": "{}", "thread_id": "{}", "logger": "{}", "level": "{}", "message": "{}")",
+    R"({{"timestamp":"{}","file":"{}","line":"{}","thread_id":"{}","logger":"{}","level":"{}","message":"{}")",
     _formatter->format_timestamp(std::chrono::nanoseconds{log_event.header.timestamp}),
     macro_metadata.filename(), macro_metadata.lineno(), log_event.thread_id,
     log_event.header.logger_details->name(), log_event.log_level_as_str(), macro_metadata.message_format()));
 
   for (auto const& [key, value] : log_event.structured_kvs)
   {
-    _json_message.append(fmtquill::format(R"(, "{}": "{}")", key, value));
+    _json_message.append(fmtquill::format(R"(,"{}":"{}")", key, value));
   }
 
-  _json_message.append(std::string_view{" }\n"});
+  _json_message.append(std::string_view{"}\n"});
 
-  detail::fwrite_fully(_json_message.data(), sizeof(char), _json_message.size(), _file);
+  StreamHandler::write(_json_message, log_event);
 }
 } // namespace quill

quill/src/handlers/StreamHandler.cpp

@@ -69,7 +69,7 @@ StreamHandler::StreamHandler(fs::path stream, FILE* file /* = nullptr */,
 }
 
 /***/
-void StreamHandler::write(fmt_buffer_t const& formatted_log_message, TransitEvent const& log_event)
+void StreamHandler::write(fmt_buffer_t const& formatted_log_message, TransitEvent const&)
 {
   if (_file_event_notifier.before_write)
   {

quill/test/QuillStructuredLogTest.cpp

@@ -5,10 +5,44 @@
 #include "quill/detail/misc/FileUtilities.h"
 #include "quill/handlers/JsonFileHandler.h"
 #include <cstdio>
+#include <optional>
 #include <string>
 
 TEST_SUITE_BEGIN("QuillStructuredLog");
 
+class CustomTest
+{
+public:
+  CustomTest() = default;
+  CustomTest(uint32_t i, std::string const& s) : _i(i), _s(s) {}
+
+  virtual ~CustomTest() {};
+
+  friend std::ostream& operator<<(std::ostream& os, CustomTest const& obj)
+  {
+    if (obj._i && obj._s)
+    {
+      os << "i: " << *obj._i << ", s: " << *obj._s;
+    }
+
+    return os;
+  }
+
+private:
+  std::optional<uint32_t> _i;
+  std::optional<std::string> _s;
+};
+
+template <>
+struct fmtquill::formatter<CustomTest> : ostream_formatter
+{
+};
+
+template <>
+struct quill::copy_loggable<CustomTest> : std::true_type
+{
+};
+
 // Note: This thread is flushing using the main() gtest test thread. This means that no-other test should have used flush()
 // on the main gtest test thread as the main thread's thread context is not re-added.
 // Other tests use flush() but within their spawned threads.
@@ -62,7 +96,9 @@ void test_quill_log(char const* test_id, std::string const& filename, std::strin
 
         for (uint32_t j = 0; j < number_of_messages; ++j)
         {
-          LOG_INFO(logger, "Hello from thread {thread_index} this is message {message_num}", i, j);
+          LOG_INFO(logger,
+                   "Hello from thread {thread_index} this is message {message_num} [{custom}]", i,
+                   j, CustomTest{j, std::to_string(j)});
         }
       });
   }
@@ -98,12 +134,14 @@ void test_quill_log(char const* test_id, std::string const& filename, std::strin
       // check json log
       std::string expected_logger_name = "jlogger_" + std::string{test_id} + "_" + std::to_string(i);
 
-      std::string expected_json_string = std::string{"\"logger\": \""} + expected_logger_name +
+      std::string expected_json_string = std::string{"\"logger\":\""} + expected_logger_name +
         std::string{
-          "\", \"level\": \"INFO\", \"message\": \"Hello from thread {thread_index} this is "
-          "message {message_num}\", "} +
-        std::string{"\"thread_index\": \""} + std::to_string(i) +
-        std::string{"\", \"message_num\": \""} + std::to_string(j) + std::string{"\""};
+          "\",\"level\":\"INFO\",\"message\":\"Hello from thread {thread_index} this is "
+          "message {message_num} [{custom}]\","} +
+        std::string{"\"thread_index\":\""} + std::to_string(i) +
+        std::string{"\",\"message_num\":\""} + std::to_string(j) +
+        std::string{"\",\"custom\":\"i: "} + std::to_string(j) + ", s: " + std::to_string(j) +
+        std::string{"\""};
 
       REQUIRE(quill::testing::file_contains(file_contents, expected_json_string));