structured log improvements

CHANGELOG.md

@@ -1,4 +1,4 @@
-- [v3.5.2](#v352)
+- [v3.6.0](#v360)
 - [v3.5.1](#v351)
 - [v3.5.0](#v350)
 - [v3.4.1](#v341)
@@ -55,13 +55,18 @@
 - [v1.1.0](#v110)
 - [v1.0.0](#v100)
 
-## v3.5.2
+## v3.6.0
 
 - 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.
+- Implemented a new attribute called `%(structured_keys)` within the `PatternFormatter` to facilitate the inclusion
+  of keys in messages when using structured log formatting. This addition is useful for instances where logging occurs
+  in both JSON and regular log formats, enabling the display of keys within the regular log-formatted messages.
+  See
+  updated [example_json_structured_log.cpp](https://github.com/odygrd/quill/blob/master/examples/example_json_structured_log.cpp)
 
 ## v3.5.1
 

examples/example_json_structured_log.cpp

@@ -3,7 +3,7 @@
 #include <regex>
 
 /**
- * Trivial logging example
+ * Structured logging example
  */
 
 int main()
@@ -34,16 +34,33 @@ int main()
   quill::start();
 
   // log to the json file ONLY by using the default logger
-  quill::Logger* logger = quill::get_logger();
+  // This is only logged to the file
+  quill::Logger* logger = quill::create_logger("json_only");
   for (int i = 0; i < 2; ++i)
   {
     LOG_INFO(logger, "{method} to {endpoint} took {elapsed} ms", "POST", "http://", 10 * i);
   }
 
   // or create another logger tha logs e.g. to stdout and to the json file at the same time
-  quill::Logger* dual_logger = quill::create_logger("dual_logger", {quill::stdout_handler(), json_handler});
+  // json is logged to the file
+  // regural log is logged to stdout
+  quill::Logger* flex_logger = quill::create_logger("both_formats", {quill::stdout_handler(), json_handler});
   for (int i = 2; i < 4; ++i)
   {
-    LOG_INFO(dual_logger, "{method} to {endpoint} took {elapsed} ms", "POST", "http://", 10 * i);
+    LOG_INFO(flex_logger, "{method} to {endpoint} took {elapsed} ms", "POST", "http://", 10 * i);
+  }
+
+  // same as the above with the inclusion of keys
+
+  // create a custom stdout_handler to change the format
+  auto custom_stdout_handler = quill::stdout_handler("custom_stdout");
+  custom_stdout_handler->set_pattern("%(ascii_time) [%(thread)] %(fileline:<28) LOG_%(level_name:<9) "
+      "%(logger_name:<12) %(message) [%(structured_keys)]");
+
+  // Logged to both file as json and to stdout with the inclusion of keys for stdout
+  quill::Logger* skey_logger = quill::create_logger("with_skey", {std::move(custom_stdout_handler), json_handler});
+  for (int i = 2; i < 4; ++i)
+  {
+    LOG_INFO(skey_logger, "Method elapsed time [{method}, {endpoint}, {duration}]", "POST", "http://", 10 * i);
   }
 }

quill/include/quill/PatternFormatter.h

@@ -57,6 +57,7 @@ class PatternFormatter
     FileLine,
     Message,
     CustomTags,
+    StructuredKeys,
     ATTR_NR_ITEMS
   };
 
@@ -98,7 +99,9 @@ class PatternFormatter
   QUILL_NODISCARD QUILL_ATTRIBUTE_HOT fmt_buffer_t const& format(
     std::chrono::nanoseconds timestamp, std::string_view thread_id, std::string_view thread_name,
     std::string_view process_id, std::string_view logger_name, std::string_view log_level,
-    MacroMetadata const& macro_metadata, transit_event_fmt_buffer_t const& log_msg);
+    MacroMetadata const& macro_metadata,
+    std::vector<std::pair<std::string, transit_event_fmt_buffer_t>> const& structured_kvs,
+    transit_event_fmt_buffer_t const& log_msg);
 
   QUILL_ATTRIBUTE_HOT std::string_view format_timestamp(std::chrono::nanoseconds timestamp);
 
@@ -110,19 +113,20 @@ class PatternFormatter
    * The following attribute names can be used with the corresponding placeholder in a %-style format string.
    * @note: The same attribute can not be used twice in the same format pattern
    *
-   * %(ascii_time)    - Human-readable time when the LogRecord was created
-   * %(filename)      - Source file where the logging call was issued
-   * %(pathname)      - Full source file where the logging call was issued
-   * %(function_name) - Name of function containing the logging call
-   * %(level_name)    - Text logging level for the messageText logging level for the message
-   * %(level_id)      - Single letter id
-   * %(lineno)        - Source line number where the logging call was issued
-   * %(logger_name)   - Name of the logger used to log the call.
-   * %(message)       - The logged message
-   * %(thread)        - Thread ID
-   * %(thread_name)   - Thread Name if set
-   * %(process)       - Process ID
-   * %(custom_tags)   - Appends custom tags to the message when _WITH_TAGS macros are used.
+   * %(ascii_time)      - Human-readable time when the LogRecord was created
+   * %(filename)        - Source file where the logging call was issued
+   * %(pathname)        - Full source file where the logging call was issued
+   * %(function_name)   - Name of function containing the logging call
+   * %(level_name)      - Text logging level for the messageText logging level for the message
+   * %(level_id)        - Single letter id
+   * %(lineno)          - Source line number where the logging call was issued
+   * %(logger_name)     - Name of the logger used to log the call.
+   * %(message)         - The logged message
+   * %(thread)          - Thread ID
+   * %(thread_name)     - Thread Name if set
+   * %(process)         - Process ID
+   * %(custom_tags)     - Appends custom tags to the message when _WITH_TAGS macros are used.
+   * %(structured_keys) - Appends keys to the message. Only applicable with structured message formatting; remains empty otherwise.
    *
    * @throws on invalid format string
    */
@@ -148,6 +152,7 @@ class PatternFormatter
 private:
   std::string _format;
   std::string _custom_tags;
+  std::string _structured_keys;
   /** Each named argument in the format_pattern is mapped in order to this array **/
   std::array<size_t, Attribute::ATTR_NR_ITEMS> _order_index{};
   std::array<fmtquill::basic_format_arg<fmtquill::format_context>, Attribute::ATTR_NR_ITEMS> _args{};

quill/include/quill/Quill.h

@@ -33,8 +33,8 @@ namespace quill
 
 /** Version Info **/
 constexpr uint32_t VersionMajor{3};
-constexpr uint32_t VersionMinor{5};
-constexpr uint32_t VersionPatch{2};
+constexpr uint32_t VersionMinor{6};
+constexpr uint32_t VersionPatch{0};
 constexpr uint32_t Version{VersionMajor * 10000 + VersionMinor * 100 + VersionPatch};
 
 /** forward declarations **/

quill/include/quill/TransitEvent.h

@@ -85,7 +85,7 @@ struct TransitEvent
   char const* thread_id;
   char const* thread_name;
   transit_event_fmt_buffer_t formatted_msg; /** buffer for message **/
-  std::vector<std::pair<std::string, std::string>> structured_kvs;
+  std::vector<std::pair<std::string, transit_event_fmt_buffer_t>> structured_kvs;
   std::optional<LogLevel> log_level_override{std::nullopt};
   std::atomic<bool>* flush_flag{nullptr}; /** This is only used in the case of Event::Flush **/
 };

quill/include/quill/detail/Serialize.h

@@ -352,15 +352,16 @@ 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<std::string>* structured_keys);
+  std::vector<std::pair<std::string, transit_event_fmt_buffer_t>>* structured_kvs);
 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<std::string>* structured_values)
+  std::vector<fmtquill::basic_format_arg<fmtquill::format_context>>& args,
+  std::vector<std::pair<std::string, transit_event_fmt_buffer_t>>* structured_kvs)
 {
   std::string error;
   constexpr size_t num_dtors = fmtquill::detail::count<need_call_dtor_for<Args>()...>();
@@ -375,13 +376,14 @@ 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 (structured_kvs)
     {
       // 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)
+      for (size_t i = 0; i < args.size(); ++i)
       {
-        structured_values->emplace_back(fmtquill::vformat("{}", fmtquill::basic_format_args(&arg, 1)));
+        fmtquill::vformat_to(std::back_inserter((*structured_kvs)[i].second), "{}",
+                             fmtquill::basic_format_args(&args[i], 1));
       }
     }
   }

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

@@ -208,7 +208,6 @@ 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/src/PatternFormatter.cpp

@@ -24,7 +24,8 @@ PatternFormatter::Attribute attribute_from_string(std::string const& attribute_n
     {"process", PatternFormatter::Attribute::Process},
     {"fileline", PatternFormatter::Attribute::FileLine},
     {"message", PatternFormatter::Attribute::Message},
-    {"custom_tags", PatternFormatter::Attribute::CustomTags}};
+    {"custom_tags", PatternFormatter::Attribute::CustomTags},
+    {"structured_keys", PatternFormatter::Attribute::StructuredKeys}};
 
   auto const search = attr_map.find(attribute_name);
 
@@ -202,7 +203,8 @@ void PatternFormatter::_set_pattern(std::string format_pattern)
     _is_set_in_pattern, std::string{format_pattern}, "ascii_time"_a = "", "filename"_a = "",
     "function_name"_a = "", "level_name"_a = "", "level_id"_a = "", "lineno"_a = "",
     "logger_name"_a = "", "pathname"_a = "", "thread"_a = "", "thread_name"_a = "",
-    "process"_a = "", "fileline"_a = "", "message"_a = "", "custom_tags"_a = "");
+    "process"_a = "", "fileline"_a = "", "message"_a = "", "custom_tags"_a = "",
+    "structured_keys"_a = "");
 
   _set_arg<Attribute::AsciiTime>(std::string_view("ascii_time"));
   _set_arg<Attribute::FileName>(std::string_view("filename"));
@@ -218,13 +220,15 @@ void PatternFormatter::_set_pattern(std::string format_pattern)
   _set_arg<Attribute::FileLine>(std::string_view("fileline"));
   _set_arg<Attribute::Message>(std::string_view("message"));
   _set_arg<Attribute::CustomTags>(std::string_view("custom_tags"));
+  _set_arg<Attribute::StructuredKeys>(std::string_view("structured_keys"));
 }
 
 /***/
 fmt_buffer_t const& PatternFormatter::format(std::chrono::nanoseconds timestamp, std::string_view thread_id,
                                              std::string_view thread_name, std::string_view process_id,
                                              std::string_view logger_name, std::string_view log_level,
                                              MacroMetadata const& macro_metadata,
+                                             std::vector<std::pair<std::string, transit_event_fmt_buffer_t>> const& structured_kvs,
                                              transit_event_fmt_buffer_t const& log_msg)
 {
   // clear out existing buffer
@@ -297,6 +301,22 @@ fmt_buffer_t const& PatternFormatter::format(std::chrono::nanoseconds timestamp,
     _set_arg_val<Attribute::FileLine>(macro_metadata.fileline());
   }
 
+  if (_is_set_in_pattern[Attribute::StructuredKeys])
+  {
+    _structured_keys.clear();
+    for (size_t i = 0; i < structured_kvs.size(); ++i)
+    {
+      _structured_keys += structured_kvs[i].first;
+
+      if (i != structured_kvs.size() - 1)
+      {
+        _structured_keys += ", ";
+      }
+    }
+
+    _set_arg_val<Attribute::StructuredKeys>(_structured_keys);
+  }
+
   if (_is_set_in_pattern[Attribute::CustomTags])
   {
     if (macro_metadata.custom_tags())

quill/src/detail/backend/BackendWorker.cpp

@@ -167,20 +167,29 @@ bool BackendWorker::_get_transit_event_from_queue(std::byte*& read_pos, ThreadCo
                "format_to_fn must be set for structured log templates, printf format is not "
                "support for structured log templates");
 
+        transit_event->structured_kvs.clear();
+
         // using the message_format as key for lookups
         _structured_fmt_str.assign(macro_metadata.message_format().data(),
                                    macro_metadata.message_format().size());
 
-        std::vector<std::string> const* s_keys;
-
         // for messages containing named arguments threat them as structured logs
         if (auto const search = _slog_templates.find(_structured_fmt_str); search != std::cend(_slog_templates))
         {
+          // process structured log that structured keys exist in our map
           auto const& [fmt_str, structured_keys] = search->second;
-          s_keys = &structured_keys;
 
+          transit_event->structured_kvs.resize(structured_keys.size());
+
+          // We first populate the structured keys in the transit buffer
+          for (size_t i = 0; i < structured_keys.size(); ++i)
+          {
+            transit_event->structured_kvs[i].first = structured_keys[i];
+          }
+
+          // Now we format the message and also populate the values of each structured key
           auto const [pos, error] =
-            format_to_fn(fmt_str, read_pos, transit_event->formatted_msg, _args, &_structured_values);
+            format_to_fn(fmt_str, read_pos, transit_event->formatted_msg, _args, &transit_event->structured_kvs);
 
           read_pos = pos;
 
@@ -192,16 +201,24 @@ bool BackendWorker::_get_transit_event_from_queue(std::byte*& read_pos, ThreadCo
         }
         else
         {
-          auto [fmt_str, structured_keys] =
-            _process_structured_log_template(macro_metadata.message_format());
+          // process structured log that structured keys are processed for the first time
+          // parse structured keys and stored them to our lookup map
+          auto const [res_it, inserted] = _slog_templates.try_emplace(
+            _structured_fmt_str, _process_structured_log_template(macro_metadata.message_format()));
+
+          auto const& [fmt_str, structured_keys] = res_it->second;
 
-          // insert the results
-          auto res = _slog_templates.try_emplace(
-            _structured_fmt_str, std::make_pair(fmt_str, std::move(structured_keys)));
-          s_keys = &(res.first->second.second);
+          transit_event->structured_kvs.resize(structured_keys.size());
 
+          // We first populate the structured keys in the transit buffer
+          for (size_t i = 0; i < structured_keys.size(); ++i)
+          {
+            transit_event->structured_kvs[i].first = structured_keys[i];
+          }
+
+          // Now we format the message and also populate the values of each structured key
           auto const [pos, error] =
-            format_to_fn(fmt_str, read_pos, transit_event->formatted_msg, _args, &_structured_values);
+            format_to_fn(fmt_str, read_pos, transit_event->formatted_msg, _args, &transit_event->structured_kvs);
 
           read_pos = pos;
 
@@ -211,14 +228,6 @@ bool BackendWorker::_get_transit_event_from_queue(std::byte*& read_pos, ThreadCo
             _notification_handler(fmtquill::format("Quill ERROR: {}", error));
           }
         }
-
-        // 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]));
-        }
-        _structured_values.clear();
       }
       else
       {
@@ -286,6 +295,8 @@ bool BackendWorker::_get_transit_event_from_queue(std::byte*& read_pos, ThreadCo
 /***/
 std::pair<std::string, std::vector<std::string>> BackendWorker::_process_structured_log_template(std::string_view fmt_template) noexcept
 {
+  // It would be nice to do this at compile time and store it in macro metadata, but without
+  // constexpr vector and string in c++17 it is not possible
   std::string fmt_str;
   std::vector<std::string> keys;
 
@@ -351,7 +362,8 @@ void BackendWorker::_write_transit_event(TransitEvent const& transit_event) cons
     auto const& formatted_log_message_buffer = handler->formatter().format(
       std::chrono::nanoseconds{transit_event.header.timestamp}, transit_event.thread_id,
       transit_event.thread_name, _process_id, transit_event.header.logger_details->name(),
-      transit_event.log_level_as_str(), macro_metadata, transit_event.formatted_msg);
+      transit_event.log_level_as_str(), macro_metadata, transit_event.structured_kvs,
+      transit_event.formatted_msg);
 
     // If all filters are okay we write this message to the file
     if (handler->apply_filters(transit_event.thread_id,

quill/src/handlers/JsonFileHandler.cpp

@@ -18,7 +18,7 @@ void JsonFileHandler::write(fmt_buffer_t const& formatted_log_message, TransitEv
 
   for (auto const& [key, value] : log_event.structured_kvs)
   {
-    _json_message.append(fmtquill::format(R"(,"{}":"{}")", key, value));
+    _json_message.append(fmtquill::format(R"(,"{}":"{}")", key, std::string_view {value.data(), value.size()}));
   }
 
   _json_message.append(std::string_view{"}\n"});