From cd2eb4c0b905132a9062ff8a2a3397978e75cf18 Mon Sep 17 00:00:00 2001 From: Odysseas Georgoudis Date: Wed, 25 Sep 2024 21:49:03 +0100 Subject: [PATCH] exclude CSV loggers from logging error logs in signal handler when using CsvWriter (#589) * exclude CSV loggers from logging error logs in signal handler when using CsvWriter * remove redundant namespace prefix --- CHANGELOG.md | 6 +++ include/quill/Backend.h | 5 ++- include/quill/CsvWriter.h | 29 +++++++------- include/quill/Logger.h | 14 +++---- include/quill/StringRef.h | 6 +-- include/quill/backend/BackendManager.h | 2 +- include/quill/backend/BackendWorker.h | 2 +- include/quill/backend/SignalHandler.h | 41 ++++++++++++-------- include/quill/core/FrontendOptions.h | 2 +- include/quill/core/LoggerManager.h | 11 +++++- include/quill/core/UnboundedSPSCQueue.h | 4 +- include/quill/sinks/FileSink.h | 16 ++++---- test/integration_tests/SignalHandlerTest.cpp | 20 ++++++++++ 13 files changed, 100 insertions(+), 58 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b8b7526e..6e2aa995 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,4 @@ +- [v7.3.0](#v730) - [v7.2.2](#v722) - [v7.2.1](#v721) - [v7.2.0](#v720) @@ -77,6 +78,11 @@ - [v1.1.0](#v110) - [v1.0.0](#v100) +## v7.3.0 + +- Prevented error logs from the `SignalHandler` from being output to CSV files when a `CsvWriter` is in + use. ([#588](https://github.com/odygrd/quill/issues/588)) + ## v7.2.2 - Fixed race condition during DLL unload by ensuring safe cleanup of `ThreadContext` when diff --git a/include/quill/Backend.h b/include/quill/Backend.h index 30d1100c..26829e5e 100644 --- a/include/quill/Backend.h +++ b/include/quill/Backend.h @@ -1,5 +1,5 @@ /** - * @page copyright + * @page copyright * Copyright(c) 2020-present, Odysseas Georgoudis & quill contributors.* @page copyright * Distributed under the MIT License (http://opensource.org/licenses/MIT) */ @@ -220,7 +220,8 @@ class Backend if (!manual_backend_worker) { - QUILL_THROW(QuillError{"acquire_manual_backend_worker() can only be called once per process. " + QUILL_THROW( + QuillError{"acquire_manual_backend_worker() can only be called once per process. " "Additionally, it should " "not be called when start() or start_with_signal_handler() has been invoked"}); } diff --git a/include/quill/CsvWriter.h b/include/quill/CsvWriter.h index 635e8234..c7c1c411 100644 --- a/include/quill/CsvWriter.h +++ b/include/quill/CsvWriter.h @@ -52,7 +52,7 @@ class CsvWriter FilenameAppendOption filename_append = FilenameAppendOption::None) { _logger = Frontend::create_or_get_logger( - filename + "_csv", + _logger_name_prefix + filename, Frontend::create_or_get_sink(filename, [open_mode, filename_append]() { @@ -61,9 +61,9 @@ class CsvWriter cfg.set_filename_append_option(filename_append); return cfg; }()), - quill::PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); + PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); - _logger->template log_statement(quill::LogLevel::None, &header_metadata, TCsvSchema::header); + _logger->template log_statement(LogLevel::None, &_header_metadata, TCsvSchema::header); } /** @@ -74,11 +74,10 @@ class CsvWriter */ CsvWriter(std::string const& unique_name, std::shared_ptr sink) { - _logger = - Frontend::create_or_get_logger(unique_name + "_csv", std::move(sink), - quill::PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); + _logger = Frontend::create_or_get_logger(_logger_name_prefix + unique_name, std::move(sink), + PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); - _logger->template log_statement(quill::LogLevel::None, &header_metadata, TCsvSchema::header); + _logger->template log_statement(LogLevel::None, &_header_metadata, TCsvSchema::header); } /** @@ -90,9 +89,9 @@ class CsvWriter CsvWriter(std::string const& unique_name, std::initializer_list> sinks) { _logger = Frontend::create_or_get_logger( - unique_name + "_csv", sinks, quill::PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); + _logger_name_prefix + unique_name, sinks, PatternFormatterOptions{"%(message)", "", Timezone::GmtTime}); - _logger->template log_statement(quill::LogLevel::None, &header_metadata, TCsvSchema::header); + _logger->template log_statement(LogLevel::None, &_header_metadata, TCsvSchema::header); } /** @@ -112,7 +111,7 @@ class CsvWriter template void append_row(Args&&... fields) { - _logger->template log_statement(quill::LogLevel::None, &line_metadata, fields...); + _logger->template log_statement(LogLevel::None, &_line_metadata, fields...); } /** @@ -122,11 +121,13 @@ class CsvWriter void flush() { _logger->flush_log(); } private: - static constexpr quill::MacroMetadata header_metadata{ - "", "", "{}", nullptr, LogLevel::Info, quill::MacroMetadata::Event::Log}; + static constexpr MacroMetadata _header_metadata{ + "", "", "{}", nullptr, LogLevel::Info, MacroMetadata::Event::Log}; - static constexpr quill::MacroMetadata line_metadata{ - "", "", TCsvSchema::format, nullptr, LogLevel::Info, quill::MacroMetadata::Event::Log}; + static constexpr MacroMetadata _line_metadata{ + "", "", TCsvSchema::format, nullptr, LogLevel::Info, MacroMetadata::Event::Log}; + + static inline std::string _logger_name_prefix {"__csv__"}; LoggerImpl* _logger{nullptr}; }; diff --git a/include/quill/Logger.h b/include/quill/Logger.h index a1198f3f..649d8068 100644 --- a/include/quill/Logger.h +++ b/include/quill/Logger.h @@ -74,22 +74,22 @@ class LoggerImpl : public detail::LoggerBase #ifndef NDEBUG if (has_dynamic_log_level) { - assert((dynamic_log_level != quill::LogLevel::None) && + assert((dynamic_log_level != LogLevel::None) && "When has_dynamic_log_level is set to true then dynamic_log_level should not be None"); } - if (dynamic_log_level != quill::LogLevel::None) + if (dynamic_log_level != LogLevel::None) { - assert((macro_metadata->log_level() == quill::LogLevel::Dynamic) && + assert((macro_metadata->log_level() == LogLevel::Dynamic) && "MacroMetadata LogLevel must be Dynamic when using a dynamic_log_level"); assert(has_dynamic_log_level && "When dynamic_log_level is used then has_dynamic_log_level must also be true"); } - if (macro_metadata->log_level() != quill::LogLevel::Dynamic) + if (macro_metadata->log_level() != LogLevel::Dynamic) { - assert((dynamic_log_level == quill::LogLevel::None) && + assert((dynamic_log_level == LogLevel::None) && "No dynamic_log_level should be set when MacroMetadata LogLevel is not Dynamic"); } @@ -224,7 +224,7 @@ class LoggerImpl : public detail::LoggerBase */ void init_backtrace(uint32_t max_capacity, LogLevel flush_level = LogLevel::None) { - // we do not care about the other fields, except quill::MacroMetadata::Event::InitBacktrace + // we do not care about the other fields, except MacroMetadata::Event::InitBacktrace static constexpr MacroMetadata macro_metadata{ "", "", "{}", nullptr, LogLevel::Critical, MacroMetadata::Event::InitBacktrace}; @@ -244,7 +244,7 @@ class LoggerImpl : public detail::LoggerBase */ void flush_backtrace() { - // we do not care about the other fields, except quill::MacroMetadata::Event::Flush + // we do not care about the other fields, except MacroMetadata::Event::Flush static constexpr MacroMetadata macro_metadata{ "", "", "", nullptr, LogLevel::Critical, MacroMetadata::Event::FlushBacktrace}; diff --git a/include/quill/StringRef.h b/include/quill/StringRef.h index 647afa08..35cad248 100644 --- a/include/quill/StringRef.h +++ b/include/quill/StringRef.h @@ -46,15 +46,15 @@ class StringRef /***/ template <> -struct Codec +struct Codec { - static size_t compute_encoded_size(detail::SizeCacheVector&, quill::utility::StringRef const&) noexcept + static size_t compute_encoded_size(detail::SizeCacheVector&, utility::StringRef const&) noexcept { return sizeof(size_t) + sizeof(uintptr_t); } static void encode(std::byte*& buffer, detail::SizeCacheVector const&, uint32_t&, - quill::utility::StringRef const& no_copy) noexcept + utility::StringRef const& no_copy) noexcept { char const* data = no_copy.get_string_view().data(); std::memcpy(buffer, &data, sizeof(uintptr_t)); diff --git a/include/quill/backend/BackendManager.h b/include/quill/backend/BackendManager.h index d406a590..b31818ff 100644 --- a/include/quill/backend/BackendManager.h +++ b/include/quill/backend/BackendManager.h @@ -22,7 +22,6 @@ class BackendTscClock; namespace detail { - /** * Provides access to common collection class that are used by both the frontend and the backend * components of the logging system @@ -90,6 +89,7 @@ class BackendManager { return &_manual_backend_worker; } + private: BackendWorker _backend_worker; ManualBackendWorker _manual_backend_worker{&_backend_worker}; diff --git a/include/quill/backend/BackendWorker.h b/include/quill/backend/BackendWorker.h index 9a67ee1a..a7b9c3ee 100644 --- a/include/quill/backend/BackendWorker.h +++ b/include/quill/backend/BackendWorker.h @@ -710,7 +710,7 @@ class BackendWorker { transit_event->named_args->clear(); } - + thread_context->_transit_event_buffer->pop_front(); if (flush_flag) diff --git a/include/quill/backend/SignalHandler.h b/include/quill/backend/SignalHandler.h index 2bb9ffa2..67a8b978 100644 --- a/include/quill/backend/SignalHandler.h +++ b/include/quill/backend/SignalHandler.h @@ -58,6 +58,8 @@ class SignalHandlerContext return instance; } + static constexpr std::string_view excluded_logger_name_substr = {"__csv__"}; + std::atomic signal_number{0}; std::atomic lock{0}; std::atomic backend_thread_id{0}; @@ -69,16 +71,16 @@ class SignalHandlerContext ~SignalHandlerContext() = default; }; -#define QUILL_SIGNAL_HANDLER_LOG(logger, log_level, fmt, ...) \ - do \ - { \ - if (logger->template should_log_statement()) \ - { \ - static constexpr quill::MacroMetadata macro_metadata{ \ +#define QUILL_SIGNAL_HANDLER_LOG(logger, log_level, fmt, ...) \ + do \ + { \ + if (logger->template should_log_statement()) \ + { \ + static constexpr quill::MacroMetadata macro_metadata{ \ "SignalHandler:~", "", fmt, nullptr, log_level, quill::MacroMetadata::Event::Log}; \ \ logger->template log_statement(quill::LogLevel::None, ¯o_metadata, ##__VA_ARGS__); \ - } \ + } \ } while (0) /***/ @@ -125,7 +127,8 @@ void on_signal(int32_t signal_number) { std::exit(EXIT_SUCCESS); } - else if (should_reraise_signal) + + if (should_reraise_signal) { // for other signals expect SIGINT and SIGTERM we re-raise std::signal(signal_number, SIG_DFL); @@ -135,7 +138,8 @@ void on_signal(int32_t signal_number) else { // This means signal handler is running on a frontend thread, we can log and flush - LoggerBase* logger_base = detail::LoggerManager::instance().get_valid_logger(); + LoggerBase* logger_base = + detail::LoggerManager::instance().get_valid_logger(SignalHandlerContext::excluded_logger_name_substr); if (logger_base) { @@ -146,7 +150,7 @@ void on_signal(int32_t signal_number) #endif auto logger = reinterpret_cast*>(logger_base); - QUILL_SIGNAL_HANDLER_LOG(logger, quill::LogLevel::Info, "Received signal: {} (signum: {})", + QUILL_SIGNAL_HANDLER_LOG(logger, LogLevel::Info, "Received signal: {} (signum: {})", signal_desc, signal_number); if (signal_number == SIGINT || signal_number == SIGTERM) @@ -156,9 +160,10 @@ void on_signal(int32_t signal_number) logger->flush_log(0); std::exit(EXIT_SUCCESS); } - else if (should_reraise_signal) + + if (should_reraise_signal) { - QUILL_SIGNAL_HANDLER_LOG(logger, quill::LogLevel::Critical, + QUILL_SIGNAL_HANDLER_LOG(logger, LogLevel::Critical, "Program terminated unexpectedly due to signal: {} (signum: {})", signal_desc, signal_number); @@ -246,11 +251,12 @@ BOOL WINAPI on_console_signal(DWORD signal) (signal == CTRL_C_EVENT || signal == CTRL_BREAK_EVENT)) { // Log the interruption and flush log messages - LoggerBase* logger_base = detail::LoggerManager::instance().get_valid_logger(); + LoggerBase* logger_base = + detail::LoggerManager::instance().get_valid_logger(SignalHandlerContext::excluded_logger_name_substr); if (logger_base) { auto logger = reinterpret_cast*>(logger_base); - QUILL_SIGNAL_HANDLER_LOG(logger, quill::LogLevel::Info, + QUILL_SIGNAL_HANDLER_LOG(logger, LogLevel::Info, "Program interrupted by Ctrl+C or Ctrl+Break signal"); // Pass `0` to avoid calling std::this_thread::sleep_for() @@ -273,16 +279,17 @@ LONG WINAPI on_exception(EXCEPTION_POINTERS* exception_p) if ((backend_thread_id != 0) && (current_thread_id != backend_thread_id)) { // Log the interruption and flush log messages - LoggerBase* logger_base = detail::LoggerManager::instance().get_valid_logger(); + LoggerBase* logger_base = + detail::LoggerManager::instance().get_valid_logger(SignalHandlerContext::excluded_logger_name_substr); if (logger_base) { auto logger = reinterpret_cast*>(logger_base); - QUILL_SIGNAL_HANDLER_LOG(logger, quill::LogLevel::Info, "Received exception: {} (Code: {})", + QUILL_SIGNAL_HANDLER_LOG(logger, LogLevel::Info, "Received exception: {} (Code: {})", get_error_message(exception_p->ExceptionRecord->ExceptionCode), exception_p->ExceptionRecord->ExceptionCode); - QUILL_SIGNAL_HANDLER_LOG(logger, quill::LogLevel::Critical, + QUILL_SIGNAL_HANDLER_LOG(logger, LogLevel::Critical, "Program terminated unexpectedly due to exception: {} (Code: {})", get_error_message(exception_p->ExceptionRecord->ExceptionCode), exception_p->ExceptionRecord->ExceptionCode); diff --git a/include/quill/core/FrontendOptions.h b/include/quill/core/FrontendOptions.h index 81afe505..5a78eb6c 100644 --- a/include/quill/core/FrontendOptions.h +++ b/include/quill/core/FrontendOptions.h @@ -25,7 +25,7 @@ struct FrontendOptions * * By default, the library uses an UnboundedBlocking queue, which starts with initial_queue_capacity. */ - static constexpr quill::QueueType queue_type = quill::QueueType::UnboundedBlocking; + static constexpr QueueType queue_type = QueueType::UnboundedBlocking; /** * Initial capacity of the queue. Used for UnboundedBlocking, UnboundedDropping, and diff --git a/include/quill/core/LoggerManager.h b/include/quill/core/LoggerManager.h index eca58f3d..a06cba8b 100644 --- a/include/quill/core/LoggerManager.h +++ b/include/quill/core/LoggerManager.h @@ -18,6 +18,7 @@ #include #include #include +#include #include QUILL_BEGIN_NAMESPACE @@ -69,7 +70,7 @@ class LoggerManager } /***/ - QUILL_NODISCARD LoggerBase* get_valid_logger() const + QUILL_NODISCARD LoggerBase* get_valid_logger(std::string_view exclude_logger_substr = {}) const { // Retrieves any valid logger without the need for constructing a vector LockGuard const lock{_spinlock}; @@ -79,7 +80,13 @@ class LoggerManager // we can not add invalidated loggers as they can be removed at any time if (elem->is_valid_logger()) { - return elem.get(); + // Return the logger only if it does not match the exclude_logger_substr + if (exclude_logger_substr.empty() || + elem->get_logger_name().find(exclude_logger_substr) == std::string::npos) + { + // Return this logger if it's valid and not excluded + return elem.get(); + } } } diff --git a/include/quill/core/UnboundedSPSCQueue.h b/include/quill/core/UnboundedSPSCQueue.h index aeed47bb..8af5dcfe 100644 --- a/include/quill/core/UnboundedSPSCQueue.h +++ b/include/quill/core/UnboundedSPSCQueue.h @@ -106,7 +106,7 @@ class UnboundedSPSCQueue * making it visible to the consumer. * @return a valid point to the buffer */ - template + template QUILL_NODISCARD QUILL_ATTRIBUTE_HOT std::byte* prepare_write(size_t nbytes) { // Try to reserve the bounded queue @@ -200,7 +200,7 @@ class UnboundedSPSCQueue private: /***/ - template + template QUILL_NODISCARD std::byte* _handle_full_queue(size_t nbytes) { // Then it means the queue doesn't have enough size diff --git a/include/quill/sinks/FileSink.h b/include/quill/sinks/FileSink.h index 80b7bf83..ef69d0ad 100644 --- a/include/quill/sinks/FileSink.h +++ b/include/quill/sinks/FileSink.h @@ -432,24 +432,24 @@ class FileSink : public StreamSink * @param time_zone Timezone to use. * @return Updated filename. */ - QUILL_NODISCARD static quill::fs::path _get_updated_filename_with_appended_datetime( - quill::fs::path const& filename, quill::FilenameAppendOption append_to_filename_option, - std::string const& append_filename_format_pattern, quill::Timezone time_zone, + QUILL_NODISCARD static fs::path _get_updated_filename_with_appended_datetime( + fs::path const& filename, FilenameAppendOption append_to_filename_option, + std::string const& append_filename_format_pattern, Timezone time_zone, std::chrono::system_clock::time_point timestamp) { - if ((append_to_filename_option == quill::FilenameAppendOption::None) || (filename == "/dev/null")) + if ((append_to_filename_option == FilenameAppendOption::None) || (filename == "/dev/null")) { return filename; } - if ((append_to_filename_option == quill::FilenameAppendOption::StartCustomTimestampFormat) || - (append_to_filename_option == quill::FilenameAppendOption::StartDate) || - (append_to_filename_option == quill::FilenameAppendOption::StartDateTime)) + if ((append_to_filename_option == FilenameAppendOption::StartCustomTimestampFormat) || + (append_to_filename_option == FilenameAppendOption::StartDate) || + (append_to_filename_option == FilenameAppendOption::StartDateTime)) { return append_datetime_to_filename(filename, append_filename_format_pattern, time_zone, timestamp); } - return quill::fs::path{}; + return fs::path{}; } private: diff --git a/test/integration_tests/SignalHandlerTest.cpp b/test/integration_tests/SignalHandlerTest.cpp index 3defd035..6da7dcc9 100644 --- a/test/integration_tests/SignalHandlerTest.cpp +++ b/test/integration_tests/SignalHandlerTest.cpp @@ -2,21 +2,30 @@ #include "misc/TestUtilities.h" #include "quill/Backend.h" +#include "quill/CsvWriter.h" #include "quill/Frontend.h" #include "quill/LogMacros.h" #include "quill/sinks/FileSink.h" #include +#include #include #include #include using namespace quill; +struct OrderCsvSchema +{ + static constexpr char const* header = "order_id,symbol"; + static constexpr char const* format = "{},{}"; +}; + /***/ TEST_CASE("signal_handler") { static constexpr char const* filename = "signal_handler.log"; + static constexpr char const* csv_filename = "aa.csv"; // use 'aa' because we sort Loggers alphabetically static std::string const logger_name = "logger"; static constexpr size_t number_of_messages = 10; static constexpr size_t number_of_threads = 10; @@ -32,6 +41,11 @@ TEST_CASE("signal_handler") quill::Frontend::preallocate(); + // First we create a CsvWriter to also test that the error message from the SignalHandler will not + // get logged there + auto csv_writer = std::make_unique>(csv_filename); + csv_writer->append_row(13212123, "AAPL"); + std::vector threads; for (size_t i = 0; i < number_of_threads; ++i) @@ -77,6 +91,9 @@ TEST_CASE("signal_handler") std::raise(SIGABRT); { + std::vector const csv_file_contents = quill::testing::file_contents(csv_filename); + REQUIRE_EQ(csv_file_contents.size(), 2); + // Except the log and the signal handler in the logs std::vector const file_contents = quill::testing::file_contents(filename); @@ -105,6 +122,8 @@ TEST_CASE("signal_handler") #endif } + csv_writer.reset(); + // Wait until the backend thread stops for test stability for (Logger* logger : Frontend::get_all_loggers()) { @@ -116,4 +135,5 @@ TEST_CASE("signal_handler") REQUIRE_FALSE(Backend::is_running()); testing::remove_file(filename); + testing::remove_file(csv_filename); } \ No newline at end of file