Skip to content

Commit

Permalink
Add support for extra arguments in JSON output and %(named_args) pl…
Browse files Browse the repository at this point in the history
…aceholder with positional indexing
  • Loading branch information
odygrd authored Sep 17, 2024
1 parent 069f719 commit 069aad7
Show file tree
Hide file tree
Showing 6 changed files with 71 additions and 32 deletions.
16 changes: 16 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -94,6 +94,22 @@
- Fixed incorrect log level short codes introduced in v7 after adding NOTICE. Using `%(log_level_short_code)` in the
formatter could incorrectly map `LOG_ERROR` to `"C"` and LOG_WARNING
to `"E"`. ([#564](https://github.com/odygrd/quill/issues/564))
- When the placeholder `%(named_args)` is enabled in the pattern formatter or when logging in JSON format, any extra
arguments passed in the log message without a key name will also be displayed in the JSON output with keys
corresponding to their positional indexes. This allows additional details to be included in the JSON while keeping the
log message clean. For example ([#563](https://github.com/odygrd/quill/discussions/563)):

```cpp
LOG_INFO(hybrid_logger, "Operation {name} completed with code {code}", "Update", 123, "Data synced successfully");
```
This will output:
```
Operation Update completed with code 123
```
And the corresponding JSON will be:
```
{"timestamp":"1726582319816776867","file_name":"json_file_logging.cpp","line":"71","thread_id":"25462","logger":"hybrid_logger","log_level":"INFO","message":"Operation {name} completed with code {code}","name":"Update","code":"123","_2":"Data synced successfully"}
```
## v7.1.0
Expand Down
18 changes: 13 additions & 5 deletions examples/json_file_logging.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -51,15 +51,23 @@ int main()
auto json_sink_2 = quill::Frontend::get_sink("example_json.log");
auto console_sink = quill::Frontend::create_or_get_sink<quill::ConsoleSink>("console_sink_id_1");

// We set a custom format pattern here to also include the named_args
// Define a custom format pattern for console logging, which includes named arguments in the output.
// If you prefer to omit named arguments from the log messages, you can remove the "[%(named_args)]" part.
quill::PatternFormatterOptions console_log_pattern = quill::PatternFormatterOptions{
"%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<20) "
"%(message) [%(named_args)]"};

// Create a logger named "hybrid_logger" that writes to both a JSON sink and a console sink.
// Note: The JSON sink uses its own internal format, so the custom format defined here
// will only apply to the console output (via console_sink).
quill::Logger* hybrid_logger = quill::Frontend::create_or_get_logger(
"hybrid_logger", {std::move(json_sink_2), std::move(console_sink)},
quill::PatternFormatterOptions{
"%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<20) "
"%(message) [%(named_args)]"});
"hybrid_logger", {std::move(json_sink_2), std::move(console_sink)}, console_log_pattern);

for (int i = 2; i < 4; ++i)
{
LOG_INFO(hybrid_logger, "{method} to {endpoint} took {elapsed} ms", "POST", "http://", 10 * i);
}

LOG_INFO(hybrid_logger, "Operation {name} completed with code {code}", "Update", 123,
"Data synced successfully");
}
14 changes: 12 additions & 2 deletions include/quill/backend/BackendWorker.h
Original file line number Diff line number Diff line change
Expand Up @@ -1290,9 +1290,11 @@ class BackendWorker

for (size_t i = 0; i < named_args.size(); ++i)
{
// orig_arg_names[i].second is special format syntax for the named argument if provided, eg name:.2f
if (!orig_arg_names[i].second.empty())
// We need an additional check here because named_args can have a size greater than orig_arg_names
// This is because we are adding the arguments without a name with a placeholder name
if ((i < orig_arg_names.size()) && !orig_arg_names[i].second.empty())
{
// orig_arg_names[i].second is special format syntax for the named argument if provided, eg name:.2f
format_string += fmtquill::format("{{{}}}", orig_arg_names[i].second);
}
else
Expand Down Expand Up @@ -1326,6 +1328,7 @@ class BackendWorker
start = end + delimiter.length();
}

// last value
if (idx < named_args.size())
{
named_args[idx].second = formatted_values_str.substr(start);
Expand Down Expand Up @@ -1360,6 +1363,13 @@ class BackendWorker
(*transit_event->named_args)[i].first = arg_names[i].first;
}

for (size_t i = arg_names.size(); i < static_cast<size_t>(_format_args_store.size()); ++i)
{
// we do not have a named_arg for the argument value here so we just append its index as a placeholder
transit_event->named_args->push_back(
std::pair<std::string, std::string>(fmtquill::format("_{}", i), std::string{}));
}

// Then populate all the values of each arg
QUILL_TRY
{
Expand Down
49 changes: 27 additions & 22 deletions test/integration_tests/JsonFileLoggingTest.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -93,17 +93,6 @@ TEST_CASE("json_file_logging")
"%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) "
"%(message) [%(named_args)]"});

if (i == 0)
{
// log a message without any args, only from the first thread
LOG_INFO(logger, "Hello from thread");

// Log a message with non-printable chars
const char* npcs = "Example\u0003String\u0004";

LOG_INFO(logger, "contains non-printable {npcs}", npcs);
}

for (size_t j = 0; j < number_of_messages; ++j)
{
LOG_INFO(logger,
Expand All @@ -114,8 +103,19 @@ TEST_CASE("json_file_logging")

if (i == 0)
{
// log a message without any args, only from the first thread
LOG_INFO(logger, "Hello from thread");

// Log a message with non-printable chars
const char* npcs = "Example\u0003String\u0004";

LOG_INFO(logger, "contains non-printable {npcs}", npcs);

// log an invalid format for testing, only from the first thread
LOG_INFO(logger, "invalid format [{%f}]", 321.1);

// json extras
LOG_INFO(logger, "A {name} with {type} extras", "message", "json", 1234, "json_extra");
}
});
}
Expand All @@ -139,24 +139,23 @@ TEST_CASE("json_file_logging")
std::vector<std::string> const file_contents = quill::testing::file_contents(json_filename);
std::vector<std::string> const file_contents_s = quill::testing::file_contents(filename);

REQUIRE_EQ(file_contents.size(), number_of_messages * number_of_threads + 3);
REQUIRE_EQ(file_contents_s.size(), number_of_messages * number_of_threads + 3);
REQUIRE_EQ(file_contents.size(), number_of_messages * number_of_threads + 4);
REQUIRE_EQ(file_contents_s.size(), number_of_messages * number_of_threads + 4);

for (size_t i = 0; i < number_of_threads; ++i)
{
// for each thread
for (size_t j = 0; j < number_of_messages; ++j)
{
// check json log
std::string expected_json_string = std::string{"\"logger\":\""} + logger_name_prefix +
std::string expected_json_string = std::string{R"("logger":")"} + logger_name_prefix +
std::to_string(i) +
std::string{
"\",\"log_level\":\"INFO\",\"message\":\"Hello from thread {thread_index} this is "
"message {message_num} [{custom}, {double:.2f}]\","} +
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{"\",\"double\":\"3.17\""};
std::string{R"("thread_index":")"} + std::to_string(i) +
std::string{R"(","message_num":")"} + std::to_string(j) + std::string{R"(","custom":"i: )"} +
std::to_string(j) + ", s: " + std::to_string(j) + std::string{R"(","double":"3.17")"};

REQUIRE(quill::testing::file_contains(file_contents, expected_json_string));

Expand All @@ -170,21 +169,27 @@ TEST_CASE("json_file_logging")
REQUIRE(quill::testing::file_contains(file_contents_s, expected_string));
}

std::string expected_no_args_json = "\"log_level\":\"INFO\",\"message\":\"Hello from thread\"";
std::string expected_no_args_json = R"("log_level":"INFO","message":"Hello from thread")";
std::string expected_no_args_fmt = "Hello from thread";
REQUIRE(quill::testing::file_contains(file_contents, expected_no_args_json));
REQUIRE(quill::testing::file_contains(file_contents_s, expected_no_args_fmt));

std::string expected_non_printable_json = "\"npcs\":\"Example\\x03String\\x04\"";
std::string expected_non_printable_json = R"("npcs":"Example\x03String\x04")";
std::string expected_non_printable_fmt = "contains non-printable Example\\x03String\\x04";
REQUIRE(quill::testing::file_contains(file_contents, expected_non_printable_json));
REQUIRE(quill::testing::file_contains(file_contents_s, expected_non_printable_fmt));

std::string expected_invalid_fmt_json =
"\"log_level\":\"INFO\",\"message\":\"invalid format [{%f}]\"";
std::string expected_invalid_fmt_json = R"("log_level":"INFO","message":"invalid format [{%f}]")";
std::string expected_invalid_fmt = "invalid format [{%f}]\", location: \"";
REQUIRE(quill::testing::file_contains(file_contents, expected_invalid_fmt_json));
REQUIRE(quill::testing::file_contains(file_contents_s, expected_invalid_fmt));

std::string expected_extras_json =
R"("message":"A {name} with {type} extras","name":"message","type":"json","_2":"1234","_3":"json_extra")";
std::string expected_extras_fmt =
"A message with json extras [name: message, type: json, _2: 1234, _3: json_extra]";
REQUIRE(quill::testing::file_contains(file_contents, expected_extras_json));
REQUIRE(quill::testing::file_contains(file_contents_s, expected_extras_fmt));
}

testing::remove_file(json_filename);
Expand Down
4 changes: 2 additions & 2 deletions test/integration_tests/JsonMultilineMetadataTest.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -65,13 +65,13 @@ TEST_CASE("json_multi_line_metadata")
"data1", "data2");
LOG_WARNING(logger_a, "Warning: Multiple issues detected:\n1. {val_1}.\n2. {val_2}.\n3. {val_3}.",
"issue1", "issue2", "issue3");
LOG_INFO(logger_a, "Another multiline info message.\nLine 2: {val_1}\n", "data1", "data2");
LOG_INFO(logger_a, "Another multiline info message.\nLine 2: {val_1}\n", "data1");

LOG_INFO(logger_b, "This is a multiline info message.\nLine 2: {val_1}.\nLine 3: {val_2}.",
"data3", "data4");
LOG_WARNING(logger_b, "Warning: Multiple issues detected:\n1. {val_1}.\n2. {val_2}.\n3. {val_3}.",
"issue4", "issue5", "issue6");
LOG_INFO(logger_b, "Another multiline info message.\nLine 2: {val_1}\n", "data1", "data2");
LOG_INFO(logger_b, "Another multiline info message.\nLine 2: {val_1}\n", "data1");

logger_a->flush_log();
Frontend::remove_logger(logger_a);
Expand Down
2 changes: 1 addition & 1 deletion test/integration_tests/JsonVariedParamsLoggingTest.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -59,7 +59,7 @@ class CustomJsonFileSink : public JsonFileSink
**/
TEST_CASE("json_varied_params_logging")
{
static constexpr size_t number_of_messages = 128u;
static constexpr size_t number_of_messages = 127u;
static constexpr char const* filename = "json_varied_params_logging.json";

// Start the logging backend thread
Expand Down

0 comments on commit 069aad7

Please sign in to comment.