Fix JSON logging bug appending cached named arguments to subsequent log statements

CHANGELOG.md

@@ -88,6 +88,9 @@
  and overwritten with a custom format, allowing a single `Logger` to output different formats to various Sinks.
  ([#476](https://github.com/odygrd/quill/issues/476))
 
+- Fixed a bug in JSON logging where previously cached named arguments could erroneously append to subsequent log
+ statements. ([#482](https://github.com/odygrd/quill/issues/482))
+
 ## v4.4.1
 
 - Fixed multiple definitions of `quill::detail::get_error_message` ([#469](https://github.com/odygrd/quill/issues/469))

quill/include/quill/backend/BackendWorker.h

@@ -702,6 +702,12 @@ class BackendWorker
  } // clang-format on
 #endif
 
+ // Finally clean up any remaining fields in the transit event
+ if (transit_event->named_args)
+ {
+ transit_event->named_args->clear();
+ }
+
  // Remove this event and move to the next.
  transit_buffer->pop_front();
 
@@ -1238,10 +1244,6 @@ class BackendWorker
  // named arg logs, we lazy initialise the named args buffer
  transit_event->named_args = std::make_unique<std::vector<std::pair<std::string, std::string>>>();
  }
- else
- {
- transit_event->named_args->clear();
- }
 
  transit_event->named_args->resize(arg_names.size());
 

quill/test/integration_tests/CMakeLists.txt

@@ -63,6 +63,7 @@ quill_add_test(TEST_FlushMultipleLoggers FlushMultipleLoggers.cpp)
 quill_add_test(TEST_FlushWithoutAnyLog FlushWithoutAnyLog.cpp)
 quill_add_test(TEST_JsonConsoleLoggingTest JsonConsoleLoggingTest.cpp)
 quill_add_test(TEST_JsonFileLogging JsonFileLoggingTest.cpp)
+quill_add_test(TEST_JsonVariedParamsLoggingTest JsonVariedParamsLoggingTest.cpp)
 quill_add_test(TEST_LogArgumentsEvaluation LogArgumentsEvaluationTest.cpp)
 quill_add_test(TEST_LogFlushWithSoftLimit LogFlushWithSoftLimitTest.cpp)
 quill_add_test(TEST_MultiFrontendThreads MultiFrontendThreadsTest.cpp)

quill/test/integration_tests/JsonVariedParamsLoggingTest.cpp

@@ -0,0 +1,144 @@
+#include "doctest/doctest.h"
+
+#include "misc/TestUtilities.h"
+#include "quill/Backend.h"
+#include "quill/Frontend.h"
+#include "quill/LogMacros.h"
+#include "quill/bundled/fmt/format.h"
+#include "quill/sinks/JsonFileSink.h"
+
+#include <cstdio>
+#include <optional>
+#include <string>
+#include <thread>
+#include <vector>
+
+using namespace quill;
+
+class CustomJsonFileSink : public JsonFileSink
+{
+public:
+ using JsonFileSink::JsonFileSink;
+
+ void write_log(MacroMetadata const* log_metadata, uint64_t log_timestamp, std::string_view thread_id,
+ std::string_view thread_name, std::string const& process_id, std::string_view logger_name,
+ LogLevel log_level, std::vector<std::pair<std::string, std::string>> const* named_args,
+ std::string_view, std::string_view) override
+ {
+ _json_message.clear();
+
+ _json_message.append(fmtquill::format(R"({{"logger":"{}","log_level":"{}","message":"{}")", logger_name,
+ loglevel_to_string(log_level), log_metadata->message_format()));
+
+ if (named_args)
+ {
+ for (auto const& [key, value] : *named_args)
+ {
+ _json_message.append(",\"");
+ _json_message.append(key);
+ _json_message.append("\":\"");
+ _json_message.append(value);
+ _json_message.append("\"");
+ }
+ }
+
+ _json_message.append("}\n");
+
+ StreamSink::write_log(log_metadata, log_timestamp, thread_id, thread_name, process_id,
+ logger_name, log_level, named_args, std::string_view{},
+ std::string_view{_json_message.data(), _json_message.size()});
+ }
+
+private:
+ detail::FormatBuffer _json_message;
+};
+
+/**
+ * Tests that named args are correctly cleared by logging several messages with and without parameters
+ **/
+TEST_CASE("json_varied_params_logging")
+{
+ static constexpr size_t number_of_messages = 128u;
+ static constexpr char const* filename = "json_varied_params_logging.json";
+
+ // Start the logging backend thread
+ BackendOptions bo;
+ bo.error_notifier = [](std::string const&) {};
+
+ // configure a small transit event capacity to make the transit_events reused
+ bo.transit_event_buffer_initial_capacity = 16;
+ Backend::start(bo);
+
+ std::vector<std::thread> threads;
+
+ // log to json
+ auto json_file_sink = Frontend::create_or_get_sink<CustomJsonFileSink>(
+ filename,
+ []()
+ {
+ JsonFileSinkConfig cfg;
+ cfg.set_open_mode('w');
+ return cfg;
+ }(),
+ FileEventNotifier{});
+
+ Logger* logger =
+ Frontend::create_or_get_logger("root", std::move(json_file_sink),
+ "LOG_%(log_level:<9) %(logger:<12) %(message) [%(named_args)]");
+
+ for (size_t i = 0; i < number_of_messages; ++i)
+ {
+ if (i % 3 == 0)
+ {
+ LOG_INFO(logger, "No parameters");
+ }
+ else if (i % 3 == 1)
+ {
+ LOG_INFO(logger, "One parameter {param_1}", i);
+ }
+ else
+ {
+ LOG_INFO(logger, "Two parameters {param_1} {param_2}", i, i);
+ }
+
+ // flush the log each time so that the transit events are reused
+ logger->flush_log();
+ }
+
+ logger->flush_log();
+ Frontend::remove_logger(logger);
+
+ // Wait until the backend thread stops for test stability
+ Backend::stop();
+
+ // Read file and check
+ std::vector<std::string> const file_contents = quill::testing::file_contents(filename);
+ REQUIRE_EQ(file_contents.size(), number_of_messages);
+
+ for (size_t i = 0; i < number_of_messages; ++i)
+ {
+ if (i % 3 == 0)
+ {
+ std::string const expected_json_statement = R"({"logger":"root","log_level":"INFO","message":"No parameters"})";
+
+ REQUIRE_EQ(file_contents[i], expected_json_statement);
+ }
+ else if (i % 3 == 1)
+ {
+ std::string const expected_json_statement = fmtquill::format(
+ R"({{"logger":"root","log_level":"INFO","message":"One parameter {{param_1}}","param_1":"{}"}})", i);
+
+ REQUIRE_EQ(file_contents[i], expected_json_statement);
+ }
+ else
+ {
+ std::string const expected_json_statement = fmtquill::format(
+ R"({{"logger":"root","log_level":"INFO","message":"Two parameters {{param_1}} {{param_2}}","param_1":"{}","param_2":"{}"}})",
+ i, i);
+
+ REQUIRE_EQ(file_contents[i], expected_json_statement);
+ }
+ }
+
+ testing::remove_file(filename);
+}