diff --git a/CHANGELOG.md b/CHANGELOG.md index 1954c74b..2d34b4ad 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -75,9 +75,12 @@ ## v7.0.0 - TBD -- Simplified the log tags API. The `Tags` class has been removed. You now pass a `char const*` directly to the macros. Additionally, macros previously named `WITH_TAGS` have been renamed to `_TAGS`. For example, `LOG_INFO_WITH_TAGS` is now `LOG_INFO_TAGS`. +- Simplified the log tags API. The `Tags` class has been removed. You now pass a `char const*` directly to the macros. + Additionally, macros previously named `WITH_TAGS` have been renamed to `_TAGS`. For example, `LOG_INFO_WITH_TAGS` is + now `LOG_INFO_TAGS`. - Renamed `backend_cpu_affinity` to `cpu_affinity` in `BackendOptions` to improve consistency. -- Simplified project structure by removing the extra quill directory and made minor CMake improvements; `include/quill` is now directly in the root. +- Simplified project structure by removing the extra quill directory and made minor CMake improvements; `include/quill` + is now directly in the root. - Added support for `std::string` with custom allocator. ([#524](https://github.com/odygrd/quill/issues/524)) - Added a new log level `NOTICE`, for capturing significant events that aren't errors or warnings. It fits between `INFO` and `WARNING` for logging important runtime events that require @@ -90,6 +93,15 @@ - Minor performance enhancement in the frontend by replacing `std::vector` with an `InlinedVector` for caching sizes (e.g. string arguments). - Fixed order of evaluation for `Codec::pair::compute_encoded_size()` to prevent side effects observed on MSVC +- Introduced the `add_metadata_to_multi_line_logs` option in `PatternFormatter`. This option, now enabled by default, + appends metadata such as timestamps and log levels to every line of multiline log entries, ensuring consistent log + output. To restore the previous behavior, set this option to false when creating a `Logger` + using `Frontend::create_or_get_logger(...)`. Note that this option is ignored when logging JSON using named arguments + in the format message. ([#534](https://github.com/odygrd/quill/pull/534)) +- The functions `Frontend::create_or_get_logger(...)` now takes an additional + parameter, `add_metadata_to_multi_line_logs`. +- `JSON` sinks now automatically remove any `\n` characters from format messages, ensuring the emission of valid `JSON` + messages even when `\n` is present in the format. ## v6.1.2 diff --git a/benchmarks/backend_throughput/quill_backend_throughput.cpp b/benchmarks/backend_throughput/quill_backend_throughput.cpp index f4ca1ae3..08c3b67e 100644 --- a/benchmarks/backend_throughput/quill_backend_throughput.cpp +++ b/benchmarks/backend_throughput/quill_backend_throughput.cpp @@ -37,7 +37,8 @@ int main() quill::Logger* logger = quill::Frontend::create_or_get_logger( "bench_logger", std::move(file_sink), - "%(time) [%(thread_id)] %(short_source_location) %(log_level) %(message)"); + "%(time) [%(thread_id)] %(short_source_location) %(log_level) %(message)", "%H:%M:%S.%Qns", + quill::Timezone::LocalTime, false); quill::Frontend::preallocate(); diff --git a/benchmarks/backend_throughput/quill_backend_throughput_no_buffering.cpp b/benchmarks/backend_throughput/quill_backend_throughput_no_buffering.cpp index d8cd2463..b227d171 100644 --- a/benchmarks/backend_throughput/quill_backend_throughput_no_buffering.cpp +++ b/benchmarks/backend_throughput/quill_backend_throughput_no_buffering.cpp @@ -38,7 +38,9 @@ int main() quill::Logger* logger = quill::Frontend::create_or_get_logger( "bench_logger", std::move(file_sink), - "%(time) [%(thread_id)] %(short_source_location) %(log_level) %(message)"); + "%(time) [%(thread_id)] %(short_source_location) %(log_level) %(message)", "%H:%M:%S.%Qns", + quill::Timezone::LocalTime, false); + ; quill::Frontend::preallocate(); diff --git a/benchmarks/hot_path_latency/quill_hot_path_rdtsc_clock.cpp b/benchmarks/hot_path_latency/quill_hot_path_rdtsc_clock.cpp index a6e4a8c8..52ca6884 100644 --- a/benchmarks/hot_path_latency/quill_hot_path_rdtsc_clock.cpp +++ b/benchmarks/hot_path_latency/quill_hot_path_rdtsc_clock.cpp @@ -56,7 +56,8 @@ void quill_benchmark(std::vector const& thread_count_array, Logger* logger = Frontend::create_or_get_logger( "bench_logger", std::move(file_sink), - "%(time) [%(thread_id)] %(short_source_location) %(log_level) %(message)"); + "%(time) [%(thread_id)] %(short_source_location) %(log_level) %(message)", "%H:%M:%S.%Qns", + quill::Timezone::LocalTime, false); /** LOGGING THREAD FUNCTIONS - on_start, on_exit, log_func must be implemented **/ /** those run on a several thread(s). It can be one or multiple threads based on THREAD_LIST_COUNT config */ diff --git a/benchmarks/hot_path_latency/quill_hot_path_system_clock.cpp b/benchmarks/hot_path_latency/quill_hot_path_system_clock.cpp index bcf329f3..d1b2d412 100644 --- a/benchmarks/hot_path_latency/quill_hot_path_system_clock.cpp +++ b/benchmarks/hot_path_latency/quill_hot_path_system_clock.cpp @@ -57,7 +57,7 @@ void quill_benchmark(std::vector const& thread_count_array, Logger* logger = Frontend::create_or_get_logger( "bench_logger", std::move(file_sink), "%(time) [%(thread_id)] %(short_source_location) %(log_level) %(message)", "%H:%M:%S.%Qns", - quill::Timezone::LocalTime, quill::ClockSourceType::System); + quill::Timezone::LocalTime, false, quill::ClockSourceType::System); /** LOGGING THREAD FUNCTIONS - on_start, on_exit, log_func must be implemented **/ /** those run on a several thread(s). It can be one or multiple threads based on THREAD_LIST_COUNT config */ diff --git a/examples/system_clock_logging.cpp b/examples/system_clock_logging.cpp index d5d2cf11..d7236b1c 100644 --- a/examples/system_clock_logging.cpp +++ b/examples/system_clock_logging.cpp @@ -23,7 +23,7 @@ int main() quill::Logger* logger = quill::Frontend::create_or_get_logger( "root", std::move(console_sink), "%(time) [%(process_id)] [%(thread_id)] %(logger) - %(message)", - "%D %H:%M:%S.%Qms %z", quill::Timezone::GmtTime, quill::ClockSourceType::System); + "%D %H:%M:%S.%Qms %z", quill::Timezone::GmtTime, false, quill::ClockSourceType::System); // Change the LogLevel to print everything logger->set_log_level(quill::LogLevel::TraceL3); diff --git a/examples/user_clock_source.cpp b/examples/user_clock_source.cpp index 102911a0..4d9c82fe 100644 --- a/examples/user_clock_source.cpp +++ b/examples/user_clock_source.cpp @@ -64,7 +64,7 @@ int main() quill::Logger* logger = quill::Frontend::create_or_get_logger( "root", std::move(console_sink), "%(time) %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) %(message)", - "%D %H:%M:%S.%Qns", quill::Timezone::LocalTime, quill::ClockSourceType::User, &simulated_clock); + "%D %H:%M:%S.%Qns", quill::Timezone::LocalTime, false, quill::ClockSourceType::User, &simulated_clock); // Change the LogLevel to print everything logger->set_log_level(quill::LogLevel::TraceL3); diff --git a/include/quill/Frontend.h b/include/quill/Frontend.h index 5f245962..cb70af1a 100644 --- a/include/quill/Frontend.h +++ b/include/quill/Frontend.h @@ -42,8 +42,8 @@ class FrontendImpl QUILL_ATTRIBUTE_COLD static void preallocate() { uint32_t const volatile spsc_queue_capacity = detail::get_local_thread_context() - ->template get_spsc_queue() - .capacity(); + ->template get_spsc_queue() + .capacity(); // On windows and c++17, QUILL_MAYBE_UNUSED won't work (void)spsc_queue_capacity; @@ -81,8 +81,12 @@ class FrontendImpl * @param format_pattern The format pattern for log messages. * @param time_pattern The time pattern for log timestamps. * @param timestamp_timezone The timezone for log timestamps. + * @param add_metadata_to_multi_line_logs If true, ensures that metadata (such as timestamps and log levels) is appended to every line in multi-line log entries, maintaining consistency in log outputs. + * Note: This option is ignored when logging `JSON` with named arguments in the format message. + * Note: This option only applies to multi-line log entries. It can be disabled if you prefer not to append metadata or if your logs are exclusively single-line entries. * @param clock_source The clock source for log timestamps. * @param user_clock A pointer to a custom user clock. + * * @return Logger* A pointer to the created or retrieved logger. */ static logger_t* create_or_get_logger( @@ -90,7 +94,8 @@ class FrontendImpl std::string const& format_pattern = "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) " "%(message)", - std::string const& time_pattern = "%H:%M:%S.%Qns", Timezone timestamp_timezone = Timezone::LocalTime, + std::string const& time_pattern = "%H:%M:%S.%Qns", + Timezone timestamp_timezone = Timezone::LocalTime, bool add_metadata_to_multi_line_logs = true, ClockSourceType clock_source = ClockSourceType::Tsc, UserClockSource* user_clock = nullptr) { std::vector> sinks; @@ -98,7 +103,7 @@ class FrontendImpl return _cast_to_logger(detail::LoggerManager::instance().create_or_get_logger( logger_name, static_cast>&&>(sinks), format_pattern, - time_pattern, timestamp_timezone, clock_source, user_clock)); + time_pattern, timestamp_timezone, add_metadata_to_multi_line_logs, clock_source, user_clock)); } /** @@ -109,6 +114,9 @@ class FrontendImpl * @param format_pattern The format pattern for log messages. * @param time_pattern The time pattern for log timestamps. * @param timestamp_timezone The timezone for log timestamps. + * @param add_metadata_to_multi_line_logs If true, ensures that metadata (such as timestamps and log levels) is appended to every line in multi-line log entries, maintaining consistency in log outputs. + * Note: This option is ignored when logging `JSON` with named arguments in the format message. + * Note: This option only applies to multi-line log entries. It can be disabled if you prefer not to append metadata or if your logs are exclusively single-line entries. * @param clock_source The clock source for log timestamps. * @param user_clock A pointer to a custom user clock. * @return Logger* A pointer to the created or retrieved logger. @@ -118,12 +126,13 @@ class FrontendImpl std::string const& format_pattern = "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) " "%(message)", - std::string const& time_pattern = "%H:%M:%S.%Qns", Timezone timestamp_timezone = Timezone::LocalTime, + std::string const& time_pattern = "%H:%M:%S.%Qns", + Timezone timestamp_timezone = Timezone::LocalTime, bool add_metadata_to_multi_line_logs = true, ClockSourceType clock_source = ClockSourceType::Tsc, UserClockSource* user_clock = nullptr) { return _cast_to_logger(detail::LoggerManager::instance().create_or_get_logger( logger_name, std::vector>{sinks}, format_pattern, time_pattern, - timestamp_timezone, clock_source, user_clock)); + timestamp_timezone, add_metadata_to_multi_line_logs, clock_source, user_clock)); } /** @@ -212,4 +221,4 @@ class FrontendImpl using Frontend = FrontendImpl; -QUILL_END_NAMESPACE \ No newline at end of file +QUILL_END_NAMESPACE diff --git a/include/quill/Logger.h b/include/quill/Logger.h index 7d5c66be..00bc8b7b 100644 --- a/include/quill/Logger.h +++ b/include/quill/Logger.h @@ -313,11 +313,11 @@ class LoggerImpl : public detail::LoggerBase /***/ LoggerImpl(std::string logger_name, std::vector> sinks, std::string format_pattern, std::string time_pattern, Timezone timestamp_timezone, - ClockSourceType clock_source, UserClockSource* user_clock) + bool add_metadata_to_multi_line_logs, ClockSourceType clock_source, UserClockSource* user_clock) : detail::LoggerBase(static_cast(logger_name), static_cast>&&>(sinks), - static_cast(format_pattern), - static_cast(time_pattern), timestamp_timezone, clock_source, user_clock) + static_cast(format_pattern), static_cast(time_pattern), + timestamp_timezone, add_metadata_to_multi_line_logs, clock_source, user_clock) { if (this->user_clock) diff --git a/include/quill/backend/BackendWorker.h b/include/quill/backend/BackendWorker.h index 30a08484..336b302e 100644 --- a/include/quill/backend/BackendWorker.h +++ b/include/quill/backend/BackendWorker.h @@ -494,6 +494,8 @@ class BackendWorker { if (logger->pattern_formatter && (logger->pattern_formatter->format_pattern() == transit_event->logger_base->format_pattern) && + (logger->pattern_formatter->get_add_metadata_to_multi_line_logs() == + transit_event->logger_base->add_metadata_to_multi_line_logs) && (logger->pattern_formatter->timestamp_formatter().time_format() == transit_event->logger_base->time_pattern) && (logger->pattern_formatter->timestamp_formatter().timestamp_timezone() == @@ -512,7 +514,7 @@ class BackendWorker // Didn't find an existing formatter need to create a new pattern formatter transit_event->logger_base->pattern_formatter = std::make_shared( transit_event->logger_base->format_pattern, transit_event->logger_base->time_pattern, - transit_event->logger_base->timezone); + transit_event->logger_base->timezone, transit_event->logger_base->add_metadata_to_multi_line_logs); } } @@ -737,7 +739,7 @@ class BackendWorker { if (transit_event.log_level() != LogLevel::Backtrace) { - _write_transit_event_to_sinks(transit_event); + _dispatch_transit_event_to_sinks(transit_event); // We also need to check the severity of the log message here against the backtrace // Check if we should also flush the backtrace messages: @@ -750,7 +752,7 @@ class BackendWorker if (transit_event.logger_base->backtrace_storage) { transit_event.logger_base->backtrace_storage->process( - [this](TransitEvent const& te) { _write_transit_event_to_sinks(te); }); + [this](TransitEvent const& te) { _dispatch_transit_event_to_sinks(te); }); } } } @@ -786,8 +788,8 @@ class BackendWorker if (transit_event.logger_base->backtrace_storage) { // process all records in backtrace for this logger and log them - transit_event.logger_base->backtrace_storage->process([this](TransitEvent const& te) - { _write_transit_event_to_sinks(te); }); + transit_event.logger_base->backtrace_storage->process( + [this](TransitEvent const& te) { _dispatch_transit_event_to_sinks(te); }); } } else if (transit_event.macro_metadata->event() == MacroMetadata::Event::Flush) @@ -803,13 +805,10 @@ class BackendWorker } /** - * Write a transit event + * Dispatches a transit event */ - QUILL_ATTRIBUTE_HOT void _write_transit_event_to_sinks(TransitEvent const& transit_event) const + QUILL_ATTRIBUTE_HOT void _dispatch_transit_event_to_sinks(TransitEvent const& transit_event) const { - std::string_view const log_message = - std::string_view{transit_event.formatted_msg.data(), transit_event.formatted_msg.size()}; - std::string_view const log_level_description = detail::log_level_to_string(transit_event.log_level(), _options.log_level_descriptions.data(), _options.log_level_descriptions.size()); @@ -818,6 +817,64 @@ class BackendWorker detail::log_level_to_string(transit_event.log_level(), _options.log_level_short_codes.data(), _options.log_level_short_codes.size()); + if (transit_event.logger_base->pattern_formatter->get_add_metadata_to_multi_line_logs() && + (!transit_event.named_args || transit_event.named_args->empty())) + { + // This is only supported when named_args are not used + _process_multi_line_message(transit_event, log_level_description, log_level_short_code); + } + else + { + // if the log_message ends with \n we should exclude it + size_t const log_message_size = + transit_event.formatted_msg.data()[transit_event.formatted_msg.size() - 1] == '\n' + ? transit_event.formatted_msg.size() - 2 + : transit_event.formatted_msg.size(); + + // process the whole message without adding metadata to each line + _write_log_statement(transit_event, log_level_description, log_level_short_code, + std::string_view{transit_event.formatted_msg.data(), log_message_size}); + } + } + + /** + * Splits and writes a transit event that has multiple lines + */ + QUILL_ATTRIBUTE_HOT void _process_multi_line_message(TransitEvent const& transit_event, + std::string_view const& log_level_description, + std::string_view const& log_level_short_code) const + { + auto const msg = + std::string_view{transit_event.formatted_msg.data(), transit_event.formatted_msg.size()}; + + size_t start = 0; + while (start < msg.size()) + { + size_t const end = msg.find_first_of('\n', start); + + if (end == std::string_view::npos) + { + // Handle the last line or a single line without a newline + _write_log_statement(transit_event, log_level_description, log_level_short_code, + std::string_view(msg.data() + start, msg.size() - start)); + break; + } + + // Write the current line + _write_log_statement(transit_event, log_level_description, log_level_short_code, + std::string_view(msg.data() + start, end - start)); + start = end + 1; + } + } + + /** + * Formats and writes the log statement to each sink + */ + QUILL_ATTRIBUTE_HOT void _write_log_statement(TransitEvent const& transit_event, + std::string_view const& log_level_description, + std::string_view const& log_level_short_code, + std::string_view const& log_message) const + { std::string_view const log_statement = transit_event.logger_base->pattern_formatter->format( transit_event.timestamp, transit_event.thread_id, transit_event.thread_name, _process_id, transit_event.logger_base->logger_name, log_level_description, log_level_short_code, @@ -825,7 +882,6 @@ class BackendWorker for (auto& sink : transit_event.logger_base->sinks) { - // If all filters are okay we write this message to the file if (sink->apply_all_filters(transit_event.macro_metadata, transit_event.timestamp, transit_event.thread_id, transit_event.thread_name, transit_event.logger_base->logger_name, transit_event.log_level(), diff --git a/include/quill/backend/PatternFormatter.h b/include/quill/backend/PatternFormatter.h index de829ae6..0dc60c4c 100644 --- a/include/quill/backend/PatternFormatter.h +++ b/include/quill/backend/PatternFormatter.h @@ -92,6 +92,7 @@ class PatternFormatter * * @param time_format The format of the date. Same as strftime() format with extra specifiers `%Qms` `%Qus` `Qns` * @param timestamp_timezone The timezone of the timestamp, local_time or gmt_time + * @param add_metadata_to_multi_line_logs If true, ensures that metadata (e.g., timestamp, log level) is added to every line of multiline log entries, maintaining consistency across all log outputs. * * @throws on invalid format string */ @@ -99,22 +100,27 @@ class PatternFormatter std::string format_pattern = "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) " "%(logger:<12) %(message)", - std::string const& time_format = "%H:%M:%S.%Qns", Timezone timestamp_timezone = Timezone::LocalTime) - : _format_pattern(std::move(format_pattern)), _timestamp_formatter(time_format, timestamp_timezone) + std::string const& time_format = "%H:%M:%S.%Qns", + Timezone timestamp_timezone = Timezone::LocalTime, bool add_metadata_to_multi_line_logs = true) + : _format_pattern(std::move(format_pattern)), + _add_metadata_to_multi_line_logs(add_metadata_to_multi_line_logs), + _timestamp_formatter(time_format, timestamp_timezone) { _set_pattern(); } + /***/ PatternFormatter(PatternFormatter const& other) = delete; - PatternFormatter(PatternFormatter&& other) noexcept = delete; PatternFormatter& operator=(PatternFormatter const& other) = delete; - PatternFormatter& operator=(PatternFormatter&& other) noexcept = delete; - /** - * Destructor - */ + /***/ + PatternFormatter& operator=(PatternFormatter&& other) noexcept = default; + PatternFormatter(PatternFormatter&& other) noexcept = default; + + /***/ ~PatternFormatter() = default; + /***/ QUILL_NODISCARD QUILL_ATTRIBUTE_HOT std::string_view format( uint64_t timestamp, std::string_view thread_id, std::string_view thread_name, std::string_view process_id, std::string_view logger, std::string_view log_level_description, @@ -240,6 +246,7 @@ class PatternFormatter return std::string_view{_formatted_log_message_buffer.data(), _formatted_log_message_buffer.size()}; } + /***/ QUILL_ATTRIBUTE_HOT std::string_view format_timestamp(std::chrono::nanoseconds timestamp) { return _timestamp_formatter.format_timestamp(timestamp); @@ -254,6 +261,12 @@ class PatternFormatter /***/ QUILL_NODISCARD std::string const& format_pattern() const noexcept { return _format_pattern; } + /***/ + QUILL_NODISCARD bool get_add_metadata_to_multi_line_logs() const noexcept + { + return _add_metadata_to_multi_line_logs; + } + private: void _set_pattern() { @@ -494,6 +507,7 @@ class PatternFormatter std::array _order_index{}; std::array, Attribute::ATTR_NR_ITEMS> _args{}; std::bitset _is_set_in_pattern; + bool _add_metadata_to_multi_line_logs; /** class responsible for formatting the timestamp */ detail::TimestampFormatter _timestamp_formatter; diff --git a/include/quill/core/LoggerBase.h b/include/quill/core/LoggerBase.h index 5e274a81..316a7394 100644 --- a/include/quill/core/LoggerBase.h +++ b/include/quill/core/LoggerBase.h @@ -35,13 +35,14 @@ class LoggerBase public: /***/ LoggerBase(std::string logger_name, std::vector> sinks, - std::string format_pattern, std::string time_pattern, Timezone timezone, + std::string format_pattern, std::string time_pattern, Timezone timezone, bool add_metadata_to_multi_line_logs, ClockSourceType clock_source, UserClockSource* user_clock) : format_pattern(static_cast(format_pattern)), time_pattern(static_cast(time_pattern)), logger_name(static_cast(logger_name)), user_clock(user_clock), timezone(timezone), + add_metadata_to_multi_line_logs(add_metadata_to_multi_line_logs), clock_source(clock_source) { #ifndef NDEBUG @@ -135,6 +136,7 @@ class LoggerBase std::string logger_name; /* Set by the frontend, accessed by the frontend AND backend */ UserClockSource* user_clock{nullptr}; /* A non owned pointer to a custom timestamp clock, valid only when provided. used by frontend only */ Timezone timezone; /* Set by the frontend and accessed by the backend to initialise PatternFormatter */ + bool add_metadata_to_multi_line_logs; /* Set by the frontend and accessed by the backend to initialise PatternFormatter */ ClockSourceType clock_source; /* Set by the frontend and accessed by the frontend AND backend */ std::atomic log_level{LogLevel::Info}; /* used by frontend only */ std::atomic backtrace_flush_level{LogLevel::None}; /** Updated by the frontend at any time, accessed by the backend */ diff --git a/include/quill/core/LoggerManager.h b/include/quill/core/LoggerManager.h index ca5ada5b..4c161f1f 100644 --- a/include/quill/core/LoggerManager.h +++ b/include/quill/core/LoggerManager.h @@ -115,7 +115,7 @@ class LoggerManager template LoggerBase* create_or_get_logger(std::string const& logger_name, std::vector> sinks, std::string const& format_pattern, - std::string const& time_pattern, Timezone timestamp_timezone, + std::string const& time_pattern, Timezone timestamp_timezone, bool add_metadata_to_multi_line_logs, ClockSourceType clock_source, UserClockSource* user_clock) { LockGuard const lock{_spinlock}; @@ -126,8 +126,8 @@ class LoggerManager { // If logger pointer is null, create a new logger instance. std::unique_ptr new_logger{ - new TLogger{logger_name, static_cast>&&>(sinks), - format_pattern, time_pattern, timestamp_timezone, clock_source, user_clock}}; + new TLogger{logger_name, static_cast>&&>(sinks), format_pattern, + time_pattern, timestamp_timezone, add_metadata_to_multi_line_logs, clock_source, user_clock}}; _insert_logger(static_cast&&>(new_logger)); diff --git a/include/quill/sinks/JsonConsoleSink.h b/include/quill/sinks/JsonConsoleSink.h index 1d815d2c..60e89821 100644 --- a/include/quill/sinks/JsonConsoleSink.h +++ b/include/quill/sinks/JsonConsoleSink.h @@ -13,6 +13,7 @@ #include "quill/sinks/StreamSink.h" #include +#include #include #include #include @@ -49,10 +50,29 @@ class JsonConsoleSink : public StreamSink { _json_message.clear(); + char const* message_format; + + if (strchr(log_metadata->message_format(), '\n') != nullptr) + { + // The format string contains at least one new line and that would break the json message, it needs to be removed + _format = log_metadata->message_format(); + + for (size_t pos = 0; (pos = _format.find('\n', pos)) != std::string::npos; pos++) + { + _format.replace(pos, 1, " "); + } + + message_format = _format.data(); + } + else + { + message_format = log_metadata->message_format(); + } + _json_message.append(fmtquill::format( R"({{"timestamp":"{}","file_name":"{}","line":"{}","thread_id":"{}","logger":"{}","log_level":"{}","message":"{}")", std::to_string(log_timestamp), log_metadata->file_name(), log_metadata->line(), thread_id, - logger_name, log_level_description, log_metadata->message_format())); + logger_name, log_level_description, message_format)); if (named_args) { @@ -75,6 +95,7 @@ class JsonConsoleSink : public StreamSink private: detail::FormatBuffer _json_message; + std::string _format; }; QUILL_END_NAMESPACE \ No newline at end of file diff --git a/include/quill/sinks/JsonFileSink.h b/include/quill/sinks/JsonFileSink.h index 65684600..8d15ef01 100644 --- a/include/quill/sinks/JsonFileSink.h +++ b/include/quill/sinks/JsonFileSink.h @@ -15,6 +15,7 @@ #include "quill/sinks/StreamSink.h" #include +#include #include #include #include @@ -65,10 +66,29 @@ class JsonFileSink : public FileSink { _json_message.clear(); + char const* message_format; + + if (strchr(log_metadata->message_format(), '\n') != nullptr) + { + // The format string contains at least one new line and that would break the json message, it needs to be removed + _format = log_metadata->message_format(); + + for (size_t pos = 0; (pos = _format.find('\n', pos)) != std::string::npos; pos++) + { + _format.replace(pos, 1, " "); + } + + message_format = _format.data(); + } + else + { + message_format = log_metadata->message_format(); + } + _json_message.append(fmtquill::format( R"({{"timestamp":"{}","file_name":"{}","line":"{}","thread_id":"{}","logger":"{}","log_level":"{}","message":"{}")", std::to_string(log_timestamp), log_metadata->file_name(), log_metadata->line(), thread_id, - logger_name, log_level_description, log_metadata->message_format())); + logger_name, log_level_description, message_format)); if (named_args) { @@ -91,6 +111,7 @@ class JsonFileSink : public FileSink private: detail::FormatBuffer _json_message; + std::string _format; }; QUILL_END_NAMESPACE \ No newline at end of file diff --git a/test/integration_tests/CMakeLists.txt b/test/integration_tests/CMakeLists.txt index ab13a9af..5c6e3bbf 100644 --- a/test/integration_tests/CMakeLists.txt +++ b/test/integration_tests/CMakeLists.txt @@ -65,10 +65,12 @@ 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_JsonMultilineMetadataTest JsonMultilineMetadataTest.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_add_test(TEST_MultilineMetadataTest MultilineMetadataTest.cpp) quill_add_test(TEST_MultipleSinksSameLogger MultipleSinksSameLoggerTest.cpp) quill_add_test(TEST_RotatingSinkDailyRotation RotatingSinkDailyRotationTest.cpp) quill_add_test(TEST_RotatingSinkKeepOldest RotatingSinkKeepOldestTest.cpp) diff --git a/test/integration_tests/JsonMultilineMetadataTest.cpp b/test/integration_tests/JsonMultilineMetadataTest.cpp new file mode 100644 index 00000000..f0c13c41 --- /dev/null +++ b/test/integration_tests/JsonMultilineMetadataTest.cpp @@ -0,0 +1,150 @@ +#include "doctest/doctest.h" + +#include "misc/TestUtilities.h" +#include "quill/Backend.h" +#include "quill/Frontend.h" +#include "quill/LogMacros.h" +#include "quill/sinks/FileSink.h" +#include "quill/sinks/JsonFileSink.h" + +#include +#include +#include + +using namespace quill; + +/***/ +TEST_CASE("json_multi_line_metadata") +{ + static constexpr char const* filename = "json_multi_line_metadata.log"; + static constexpr char const* json_filename = "json_multi_line_metadata.json"; + static std::string const logger_name_a = "logger_a"; + static std::string const logger_name_b = "logger_b"; + + // Start the logging backend thread + Backend::start(); + + Frontend::preallocate(); + + // Set writing logging to a file + auto file_sink = Frontend::create_or_get_sink( + filename, + []() + { + FileSinkConfig cfg; + cfg.set_open_mode('w'); + return cfg; + }(), + FileEventNotifier{}); + + auto json_file_sink = Frontend::create_or_get_sink( + json_filename, + []() + { + JsonFileSinkConfig cfg; + cfg.set_open_mode('w'); + return cfg; + }(), + FileEventNotifier{}); + + Logger* logger_a = Frontend::create_or_get_logger( + logger_name_a, std::initializer_list>{json_file_sink, file_sink}, + "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) " + "%(message) %(caller_function)", + "%H:%M:%S.%Qns", Timezone::LocalTime, true); + + Logger* logger_b = Frontend::create_or_get_logger( + logger_name_b, std::initializer_list>{json_file_sink, file_sink}, + "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) " + "%(message) %(caller_function)", + "%H:%M:%S.%Qns", Timezone::LocalTime, false); + + LOG_INFO(logger_a, "This is a multiline info message.\nLine 2: {val_1}.\nLine 3: {val_2}.", + "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_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"); + + logger_a->flush_log(); + Frontend::remove_logger(logger_a); + Frontend::remove_logger(logger_b); + + // Wait until the backend thread stops for test stability + Backend::stop(); + + // Read file and check + std::vector const file_contents = quill::testing::file_contents(filename); + REQUIRE_EQ(file_contents.size(), 18); + + std::string expected_string = logger_name_a + " This is a multiline info message."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 2: data1."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 3: data2. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " Warning: Multiple issues detected:"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "1. issue1."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "2. issue2."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "3. issue3. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " Another multiline info message."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 2: data1."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_b + " This is a multiline info message."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 2: data3."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 3: data4."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_b + " Warning: Multiple issues detected:"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "1. issue4."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "2. issue5."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "3. issue6. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_b + " Another multiline info message."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 2: data DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + std::vector const file_contents_json = quill::testing::file_contents(json_filename); + REQUIRE_EQ(file_contents_json.size(), 6); + + expected_string = R"("logger":"logger_a","log_level":"INFO","message":"This is a multiline info message. Line 2: {val_1}. Line 3: {val_2}.","val_1":"data1","val_2":"data2"})"; + REQUIRE(quill::testing::file_contains(file_contents_json, expected_string)); + + expected_string = R"("logger":"logger_b","log_level":"INFO","message":"Another multiline info message. Line 2: {val_1} ","val_1":"data1"})"; + REQUIRE(quill::testing::file_contains(file_contents_json, expected_string)); + + testing::remove_file(filename); + testing::remove_file(json_filename); +} \ No newline at end of file diff --git a/test/integration_tests/MultiFrontendThreadsTest.cpp b/test/integration_tests/MultiFrontendThreadsTest.cpp index 3ee3299b..f54e3238 100644 --- a/test/integration_tests/MultiFrontendThreadsTest.cpp +++ b/test/integration_tests/MultiFrontendThreadsTest.cpp @@ -50,7 +50,7 @@ TEST_CASE("multi_frontend_threads") logger_name_prefix + std::to_string(i), std::move(file_sink), "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) " "%(message)", - "%Y-%m-%d %H:%M:%S.%Qns", Timezone::GmtTime, ClockSourceType::System); + "%Y-%m-%d %H:%M:%S.%Qns", Timezone::GmtTime, false, ClockSourceType::System); for (size_t j = 0; j < number_of_messages; ++j) { diff --git a/test/integration_tests/MultilineMetadataTest.cpp b/test/integration_tests/MultilineMetadataTest.cpp new file mode 100644 index 00000000..269063d1 --- /dev/null +++ b/test/integration_tests/MultilineMetadataTest.cpp @@ -0,0 +1,129 @@ +#include "doctest/doctest.h" + +#include "misc/TestUtilities.h" +#include "quill/Backend.h" +#include "quill/Frontend.h" +#include "quill/LogMacros.h" +#include "quill/sinks/FileSink.h" + +#include +#include +#include + +using namespace quill; + +/***/ +TEST_CASE("multi_line_metadata") +{ + static constexpr char const* filename = "multi_line_metadata.log"; + static std::string const logger_name_a = "logger_a"; + static std::string const logger_name_b = "logger_b"; + + // Start the logging backend thread + Backend::start(); + + Frontend::preallocate(); + + // Set writing logging to a file + auto file_sink = Frontend::create_or_get_sink( + filename, + []() + { + FileSinkConfig cfg; + cfg.set_open_mode('w'); + return cfg; + }(), + FileEventNotifier{}); + + Logger* logger_a = Frontend::create_or_get_logger( + logger_name_a, file_sink, + "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) " + "%(message) %(caller_function)", + "%H:%M:%S.%Qns", Timezone::LocalTime, true); + + Logger* logger_b = Frontend::create_or_get_logger( + logger_name_b, file_sink, + "%(time) [%(thread_id)] %(short_source_location:<28) LOG_%(log_level:<9) %(logger:<12) " + "%(message) %(caller_function)", + "%H:%M:%S.%Qns", Timezone::LocalTime, false); + + LOG_INFO(logger_a, "This is a multiline info message.\nLine 2: {}.\nLine 3: {}.", "data1", + "data2"); + LOG_WARNING(logger_a, "Warning: Multiple issues detected:\n1. {}.\n2. {}.\n3. {}.", "issue1", + "issue2", "issue3"); + LOG_INFO(logger_a, "Another multiline info message.\nLine 2: {}\n", "data1", "data2"); + + LOG_INFO(logger_b, "This is a multiline info message.\nLine 2: {}.\nLine 3: {}.", "data3", + "data4"); + LOG_WARNING(logger_b, "Warning: Multiple issues detected:\n1. {}.\n2. {}.\n3. {}.", "issue4", + "issue5", "issue6"); + LOG_INFO(logger_b, "Another multiline info message.\nLine 2: {}\n", "data1", "data2"); + + logger_a->flush_log(); + Frontend::remove_logger(logger_a); + Frontend::remove_logger(logger_b); + + // Wait until the backend thread stops for test stability + Backend::stop(); + + // Read file and check + std::vector const file_contents = quill::testing::file_contents(filename); + REQUIRE_EQ(file_contents.size(), 18); + + std::string expected_string = + logger_name_a + " This is a multiline info message. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " Line 2: data1. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " Line 3: data2. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " Warning: Multiple issues detected: DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " 1. issue1. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " 2. issue2. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " 3. issue3. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " Another multiline info message. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_a + " Line 2: data1 DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_b + " This is a multiline info message."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 2: data3."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 3: data4."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_b + " Warning: Multiple issues detected:"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "1. issue4."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "2. issue5."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "3. issue6. DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = logger_name_b + " Another multiline info message."; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + expected_string = "Line 2: data DOCTEST_ANON_FUNC_2"; + REQUIRE(quill::testing::file_contains(file_contents, expected_string)); + + testing::remove_file(filename); +} \ No newline at end of file diff --git a/test/integration_tests/UserClockSourceTest.cpp b/test/integration_tests/UserClockSourceTest.cpp index 9af54648..b675e2de 100644 --- a/test/integration_tests/UserClockSourceTest.cpp +++ b/test/integration_tests/UserClockSourceTest.cpp @@ -68,10 +68,11 @@ TEST_CASE("user_clock_source") }(), FileEventNotifier{}); - Logger* logger = Frontend::create_or_get_logger(logger_name, std::move(file_sink), - "%(time) %(log_level) %(logger:<16) %(message)", // format - "%Y-%m-%d %H:%M:%S.%Qms", // timestamp format - quill::Timezone::GmtTime, ClockSourceType::User, &uct); + Logger* logger = + Frontend::create_or_get_logger(logger_name, std::move(file_sink), + "%(time) %(log_level) %(logger:<16) %(message)", // format + "%Y-%m-%d %H:%M:%S.%Qms", // timestamp format + quill::Timezone::GmtTime, false, ClockSourceType::User, &uct); for (size_t i = 0; i < number_of_messages; ++i) { diff --git a/test/unit_tests/LoggerManagerTest.cpp b/test/unit_tests/LoggerManagerTest.cpp index 02483590..75422d1f 100644 --- a/test/unit_tests/LoggerManagerTest.cpp +++ b/test/unit_tests/LoggerManagerTest.cpp @@ -23,13 +23,13 @@ TEST_CASE("create_get_remove_logger") "logger_1", std::move(sinks), "%(time) [%(thread_id)] %(short_source_location:<28) " "LOG_%(log_level:<9) %(logger:<12) %(message)", - "%H:%M:%S.%Qns", quill::Timezone::GmtTime, ClockSourceType::Tsc, nullptr); + "%H:%M:%S.%Qns", quill::Timezone::GmtTime, false, ClockSourceType::Tsc, nullptr); LoggerBase* logger_2 = lm.create_or_get_logger( "logger_2", std::initializer_list>{sink}, "[%(thread_id)] %(short_source_location:<28) " "LOG_%(log_level:<9) %(logger:<12) %(message)", - "%H:%M:%S.%Qns", quill::Timezone::GmtTime, ClockSourceType::Tsc, nullptr); + "%H:%M:%S.%Qns", quill::Timezone::GmtTime, false, ClockSourceType::Tsc, nullptr); REQUIRE_EQ(logger_1->get_logger_name(), "logger_1"); REQUIRE_EQ(logger_2->get_logger_name(), "logger_2"); diff --git a/test/unit_tests/LoggerTest.cpp b/test/unit_tests/LoggerTest.cpp index b4b12621..d2eb1acd 100644 --- a/test/unit_tests/LoggerTest.cpp +++ b/test/unit_tests/LoggerTest.cpp @@ -24,7 +24,7 @@ TEST_CASE("check_logger") "logger_1", std::move(sinks), "%(time) [%(thread_id)] %(short_source_location:<28) " "LOG_%(log_level:<9) %(logger:<12) %(message)", - "%H:%M:%S.%Qns", quill::Timezone::GmtTime, ClockSourceType::Tsc, nullptr)); + "%H:%M:%S.%Qns", quill::Timezone::GmtTime, false, ClockSourceType::Tsc, nullptr)); // Check default log level REQUIRE_EQ(logger_1->get_log_level(), LogLevel::Info); @@ -50,7 +50,7 @@ TEST_CASE("logger_should_log") "logger_1", std::move(sinks), "%(time) [%(thread_id)] %(short_source_location:<28) " "LOG_%(log_level:<9) %(logger:<12) %(message)", - "%H:%M:%S.%Qns", quill::Timezone::GmtTime, ClockSourceType::Tsc, nullptr)); + "%H:%M:%S.%Qns", quill::Timezone::GmtTime, false, ClockSourceType::Tsc, nullptr)); REQUIRE_UNARY_FALSE(logger_1->should_log_statement()); REQUIRE(logger_1->should_log_statement()); diff --git a/test/unit_tests/PatternFormatterTest.cpp b/test/unit_tests/PatternFormatterTest.cpp index 7c1c2bdc..67bbaa03 100644 --- a/test/unit_tests/PatternFormatterTest.cpp +++ b/test/unit_tests/PatternFormatterTest.cpp @@ -450,4 +450,45 @@ TEST_CASE("empty_format_pattern") REQUIRE_EQ(formatted_string, expected_string); } +TEST_CASE("pattern_timestamp_move_constructor") +{ + // Custom pattern with part 1 and part 3 + PatternFormatter pattern_formatter{ + "%(time) [%(thread_id)] %(file_name):%(line_number) LOG_%(log_level) %(logger) " + "%(message) [%(caller_function)]", + "%m-%d-%Y %H:%M:%S.%Qns", Timezone::GmtTime}; + + PatternFormatter pattern_formatter_move{std::move(pattern_formatter)}; + + uint64_t const ts{1579815761000023000}; + char const* thread_id = "31341"; + std::string const logger_name = "test_logger"; + MacroMetadata macro_metadata{__FILE__ ":" QUILL_STRINGIFY(__LINE__), + __func__, + "This the {1} formatter {0}", + nullptr, + LogLevel::Debug, + MacroMetadata::Event::Log}; + + // Format to a buffer + fmtquill::memory_buffer log_msg; + fmtquill::format_to(std::back_inserter(log_msg), + fmtquill::runtime(macro_metadata.message_format()), "pattern", 1234); + + std::vector> named_args; + + auto const& formatted_buffer = pattern_formatter_move.format( + ts, thread_id, thread_name, process_id, logger_name, "DEBUG", "D", macro_metadata, &named_args, + std::string_view{log_msg.data(), log_msg.size()}); + + // Convert the buffer to a string + std::string const formatted_string = fmtquill::to_string(formatted_buffer); + + std::string const expected_string = + "01-23-2020 21:42:41.000023000 [31341] PatternFormatterTest.cpp:466 LOG_DEBUG test_logger " + "This the 1234 formatter pattern [DOCTEST_ANON_FUNC_27]\n"; + + REQUIRE_EQ(formatted_string, expected_string); +} + TEST_SUITE_END();