Skip to content

Commit f249eb0

Browse files
committed
provide overridden format for log_statement in filter
1 parent 4c63364 commit f249eb0

File tree

6 files changed

+182
-26
lines changed

6 files changed

+182
-26
lines changed

CHANGELOG.md

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -179,6 +179,13 @@
179179
- `QUILL_LOG_RUNTIME_METADATA_SHALLOW` - Will take everything as reference. This is used when logging with
180180
compile-time metadata and using, for example, a dynamic log-level such as `LOG_DYNAMIC`.
181181

182+
- When a Sink with override `PatternFormatterOptions` is used and if no other sink exists using the `Logger`
183+
`PatternFormatterOptions`, then the backend thread will no longer perform a redundant format log statement.
184+
185+
- When using a sink with overridden `PatternFormatterOptions`, the `log_statement` that is passed to the
186+
`Filter::filter()` will now be formatted based on the overridden options instead of using the `Logger`
187+
`PatternFormatterOptions`.
188+
182189
- Update bundled `libfmt` to `v11.2.0`
183190

184191
### API Changes

README.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -373,7 +373,7 @@ Logging 4 million times the message `"Iteration: {} int: {} double: {}"`
373373
| [MS BinLog (binary log)](http://github.com/Morgan-Stanley/binlog) | 62.12 | 64 ms |
374374
| [BqLog (binary log)](https://github.com/Tencent/BqLog) | 15.24 | 262 ms |
375375
| [XTR](https://github.com/choll/xtr) | 8.25 | 484 ms |
376-
| [Quill](http://github.com/odygrd/quill) | 5.30 | 754 ms |
376+
| [Quill](http://github.com/odygrd/quill) | 5.15 | 776 ms |
377377
| [spdlog](http://github.com/gabime/spdlog) | 4.32 | 925 ms |
378378
| [fmtlog](http://github.com/MengRao/fmtlog) | 2.77 | 1443 ms |
379379
| [Reckless](http://github.com/mattiasflodin/reckless) | 2.72 | 1471 ms |

include/quill/backend/BackendWorker.h

Lines changed: 36 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -988,35 +988,52 @@ class BackendWorker
988988
std::string_view const& log_level_short_code,
989989
std::string_view const& log_message) const
990990
{
991-
std::string_view const log_statement = transit_event.logger_base->_pattern_formatter->format(
992-
transit_event.timestamp, thread_id, thread_name, _process_id,
993-
transit_event.logger_base->_logger_name, log_level_description, log_level_short_code,
994-
*transit_event.macro_metadata, transit_event.get_named_args(), log_message);
991+
std::string_view default_log_statement;
995992

993+
// Process each sink with the appropriate formatting and filtering
996994
for (auto& sink : transit_event.logger_base->_sinks)
997995
{
998-
if (sink->apply_all_filters(transit_event.macro_metadata, transit_event.timestamp, thread_id,
999-
thread_name, transit_event.logger_base->_logger_name,
1000-
transit_event.log_level(), log_message, log_statement))
1001-
{
1002-
std::string_view log_to_write = log_statement;
996+
std::string_view log_to_write;
1003997

1004-
// If the sink has an override pattern formatter to use, prepare the override formatted statement
1005-
if (sink->_override_pattern_formatter_options)
998+
// Determine which formatted log to use
999+
if (!sink->_override_pattern_formatter_options)
1000+
{
1001+
if (default_log_statement.empty())
10061002
{
1007-
if (!sink->_override_pattern_formatter)
1008-
{
1009-
sink->_override_pattern_formatter =
1010-
std::make_shared<PatternFormatter>(*sink->_override_pattern_formatter_options);
1011-
}
1012-
1013-
log_to_write = sink->_override_pattern_formatter->format(
1003+
// Use the default formatted log statement, here by checking empty() we try to format once
1004+
// even for multiple sinks
1005+
default_log_statement = transit_event.logger_base->_pattern_formatter->format(
10141006
transit_event.timestamp, thread_id, thread_name, _process_id,
10151007
transit_event.logger_base->_logger_name, log_level_description, log_level_short_code,
10161008
*transit_event.macro_metadata, transit_event.get_named_args(), log_message);
10171009
}
10181010

1019-
// Forward the message using the computed log statement
1011+
log_to_write = default_log_statement;
1012+
}
1013+
else
1014+
{
1015+
// Sink has override_pattern_formatter_options, we do not include PatternFormatter
1016+
// in the frontend fo this reason we init PatternFormatter here
1017+
if (!sink->_override_pattern_formatter)
1018+
{
1019+
// Initialize override formatter if needed
1020+
sink->_override_pattern_formatter =
1021+
std::make_shared<PatternFormatter>(*sink->_override_pattern_formatter_options);
1022+
}
1023+
1024+
// Use the sink's override formatter
1025+
log_to_write = sink->_override_pattern_formatter->format(
1026+
transit_event.timestamp, thread_id, thread_name, _process_id,
1027+
transit_event.logger_base->_logger_name, log_level_description, log_level_short_code,
1028+
*transit_event.macro_metadata, transit_event.get_named_args(), log_message);
1029+
}
1030+
1031+
// Apply filters now that we have the formatted log
1032+
if (sink->apply_all_filters(transit_event.macro_metadata, transit_event.timestamp, thread_id,
1033+
thread_name, transit_event.logger_base->_logger_name,
1034+
transit_event.log_level(), log_message, log_to_write))
1035+
{
1036+
// Forward the message using the computed log statement that passed the filter
10201037
sink->write_log(transit_event.macro_metadata, transit_event.timestamp, thread_id,
10211038
thread_name, _process_id, transit_event.logger_base->_logger_name,
10221039
transit_event.log_level(), log_level_description, log_level_short_code,

test/integration_tests/CMakeLists.txt

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -98,6 +98,7 @@ quill_add_test(TEST_SignalHandlerLogger SignalHandlerLoggerTest.cpp)
9898
quill_add_test(TEST_SingleFrontendThreadMultipleLoggers SingleFrontendThreadMultipleLoggersTest.cpp)
9999
quill_add_test(TEST_SingleFrontendThread SingleFrontendThreadTest.cpp)
100100
quill_add_test(TEST_SinkFilter SinkFilterTest.cpp)
101+
quill_add_test(TEST_SinkFilterOverrideFormat SinkFilterOverrideFormatTest.cpp)
101102
quill_add_test(TEST_StdArrayLogging StdArrayLoggingTest.cpp)
102103
quill_add_test(TEST_StdChronoLogging StdChronoLoggingTest.cpp)
103104
quill_add_test(TEST_StdDequeLogging StdDequeLoggingTest.cpp)
Lines changed: 137 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,137 @@
1+
#include "doctest/doctest.h"
2+
3+
#include "misc/TestUtilities.h"
4+
#include "quill/Backend.h"
5+
#include "quill/Frontend.h"
6+
#include "quill/LogMacros.h"
7+
#include "quill/sinks/FileSink.h"
8+
9+
#include <cstdio>
10+
#include <string>
11+
#include <vector>
12+
13+
using namespace quill;
14+
15+
class FileFilterA : public Filter
16+
{
17+
public:
18+
FileFilterA() : Filter("FileFilterA") {}
19+
20+
QUILL_NODISCARD bool filter(quill::MacroMetadata const* log_metadata, uint64_t /** log_timestamp **/,
21+
std::string_view /** thread_id **/, std::string_view /** thread_name **/,
22+
std::string_view /** logger_name **/, quill::LogLevel /** log_level **/,
23+
std::string_view /** log_message **/, std::string_view log_statement) noexcept override
24+
{
25+
if (log_metadata->log_level() < LogLevel::Warning)
26+
{
27+
// we expect to match the override format pattern here
28+
REQUIRE_EQ(log_statement, std::string{"Lorem ipsum dolor sit amet, consectetur adipiscing elit [file]\n"});
29+
return true;
30+
}
31+
return false;
32+
}
33+
};
34+
35+
class FileFilterB : public Filter
36+
{
37+
public:
38+
FileFilterB() : Filter("FileFilterB") {}
39+
40+
bool filter(quill::MacroMetadata const* log_metadata, uint64_t /** log_timestamp **/,
41+
std::string_view /** thread_id **/, std::string_view /** thread_name **/,
42+
std::string_view /** logger_name **/, quill::LogLevel /** log_level **/,
43+
std::string_view /** log_message **/, std::string_view log_statement) noexcept override
44+
{
45+
if (log_metadata->log_level() >= LogLevel::Warning)
46+
{
47+
// we expect to match the override format pattern here
48+
REQUIRE_EQ(log_statement, std::string{"Nulla tempus, libero at dignissim viverra, lectus libero finibus ante [logger]\n"});
49+
return true;
50+
}
51+
return false;
52+
}
53+
};
54+
55+
/***/
56+
TEST_CASE("sink_filter_override_format")
57+
{
58+
// Tests that when we override the format of a sink, the filter gets the overridden format in log_statement
59+
static constexpr char const* filename_a = "sink_filter_a.log";
60+
static constexpr char const* filename_b = "sink_filter_b.log";
61+
static std::string const logger_name = "logger";
62+
63+
// Start the logging backend thread
64+
Backend::start();
65+
66+
// Set writing logging to a file
67+
auto file_sink_a = Frontend::create_or_get_sink<FileSink>(
68+
filename_a,
69+
[]()
70+
{
71+
// Override format
72+
PatternFormatterOptions formatter_options_file_sink_a;
73+
formatter_options_file_sink_a.format_pattern = "%(message) [file]";
74+
75+
FileSinkConfig cfg;
76+
cfg.set_open_mode('w');
77+
cfg.set_override_pattern_formatter_options(formatter_options_file_sink_a);
78+
return cfg;
79+
}(),
80+
FileEventNotifier{});
81+
82+
// log to filename_a anything below warning
83+
std::unique_ptr<Filter> filter_a = std::make_unique<FileFilterA>();
84+
85+
// Also test get_filter_name()
86+
REQUIRE_EQ(filter_a->get_filter_name(), std::string_view{"FileFilterA"});
87+
88+
// Add the filter
89+
file_sink_a->add_filter(std::move(filter_a));
90+
91+
// Try to add the same again (same name)
92+
std::unique_ptr<Filter> filter_a_2 = std::make_unique<FileFilterA>();
93+
REQUIRE_EQ(filter_a_2->get_filter_name(), std::string_view{"FileFilterA"});
94+
REQUIRE_THROWS_AS(file_sink_a->add_filter(std::move(filter_a_2)), QuillError);
95+
96+
auto file_sink_b = Frontend::create_or_get_sink<FileSink>(
97+
filename_b,
98+
[]()
99+
{
100+
// No format override for file_sink_b
101+
FileSinkConfig cfg;
102+
cfg.set_open_mode('w');
103+
return cfg;
104+
}(),
105+
FileEventNotifier{});
106+
107+
// log to filename_b warning, error, critical
108+
file_sink_b->add_filter(std::make_unique<FileFilterB>());
109+
110+
Logger* logger =
111+
Frontend::create_or_get_logger(logger_name, {std::move(file_sink_a), std::move(file_sink_b)},
112+
PatternFormatterOptions{"%(message) [logger]"});
113+
114+
LOG_INFO(logger, "Lorem ipsum dolor sit amet, consectetur adipiscing elit");
115+
LOG_ERROR(logger, "Nulla tempus, libero at dignissim viverra, lectus libero finibus ante");
116+
117+
// Let all log get flushed to the file
118+
logger->flush_log();
119+
Frontend::remove_logger(logger);
120+
121+
// Wait until the backend thread stops for test stability
122+
Backend::stop();
123+
124+
// Read file and check
125+
std::vector<std::string> const file_contents_a = quill::testing::file_contents(filename_a);
126+
REQUIRE_EQ(file_contents_a.size(), 1);
127+
REQUIRE(quill::testing::file_contains(
128+
file_contents_a, std::string{"Lorem ipsum dolor sit amet, consectetur adipiscing elit [file]"}));
129+
130+
std::vector<std::string> const file_contents_b = quill::testing::file_contents(filename_b);
131+
REQUIRE_EQ(file_contents_b.size(), 1);
132+
REQUIRE(quill::testing::file_contains(
133+
file_contents_b, std::string{"Nulla tempus, libero at dignissim viverra, lectus libero finibus ante [logger]"}));
134+
135+
testing::remove_file(filename_a);
136+
testing::remove_file(filename_b);
137+
}

test/integration_tests/SinkFilterTest.cpp

Lines changed: 0 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -12,9 +12,6 @@
1212

1313
using namespace quill;
1414

15-
/**
16-
* Filter class for our file handler
17-
*/
1815
class FileFilterA : public Filter
1916
{
2017
public:
@@ -34,9 +31,6 @@ class FileFilterA : public Filter
3431
}
3532
};
3633

37-
/**
38-
* Filter for the stdout handler
39-
*/
4034
class FileFilterB : public Filter
4135
{
4236
public:

0 commit comments

Comments
 (0)