From 833bb360a35574846f2bd44484cf4aeb89254f6e Mon Sep 17 00:00:00 2001 From: gabime Date: Sat, 4 Jan 2025 11:32:08 +0200 Subject: [PATCH] Handle exceptions in async sink --- include/spdlog/logger.h | 3 +-- include/spdlog/sinks/async_sink.h | 7 ++++--- src/sinks/async_sink.cpp | 32 ++++++++++++++++++++++++++----- tests/test_async.cpp | 9 +++++++++ tests/test_sink.h | 20 ++++++++++++++++++- 5 files changed, 60 insertions(+), 11 deletions(-) diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index cab598392..d430229fb 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -209,8 +209,7 @@ class SPDLOG_API logger { void flush_(); [[nodiscard]] bool should_flush_(const details::log_msg &msg) const; - // handle errors during logging. - // default handler prints the error to stderr at max rate of 1 message/sec. + // default handler prints the error to stderr void err_handler_(const std::string &msg); }; diff --git a/include/spdlog/sinks/async_sink.h b/include/spdlog/sinks/async_sink.h index e782620a0..3096c6e42 100644 --- a/include/spdlog/sinks/async_sink.h +++ b/include/spdlog/sinks/async_sink.h @@ -70,9 +70,10 @@ class SPDLOG_API async_sink final : public sink { using queue_t = details::mpmc_blocking_queue; void send_message_(async_log_msg::type msg_type, const details::log_msg &msg) const; - void backend_loop_() const; - void backend_log_(const details::log_msg &msg) const; - void backend_flush_() const; + void backend_loop_(); + void backend_log_(const details::log_msg &msg) ; + void backend_flush_(); + void err_handler_(const std::string &msg); config config_; std::unique_ptr q_; diff --git a/src/sinks/async_sink.cpp b/src/sinks/async_sink.cpp index aa386b6e2..b9154c745 100644 --- a/src/sinks/async_sink.cpp +++ b/src/sinks/async_sink.cpp @@ -82,7 +82,7 @@ void async_sink::send_message_(async_log_msg::type msg_type, const details::log_ } } -void async_sink::backend_loop_() const { +void async_sink::backend_loop_() { details::async_log_msg incoming_msg; for (;;) { q_->dequeue(incoming_msg); @@ -101,19 +101,41 @@ void async_sink::backend_loop_() const { } } -void async_sink::backend_log_(const details::log_msg &msg) const { +void async_sink::backend_log_(const details::log_msg &msg) { for (const auto &sink : config_.sinks) { if (sink->should_log(msg.log_level)) { - sink->log(msg); + try { + sink->log(msg); + } catch (const std::exception &ex) { + err_handler_(std::string("async log failed: ") + ex.what()); + } } } } -void async_sink::backend_flush_() const { +void async_sink::backend_flush_() { for (const auto &sink : config_.sinks) { - sink->flush(); + try { + sink->flush(); + } catch (const std::exception &ex) { + err_handler_(std::string("async flush failed: ") + ex.what()); + } catch (...) { + err_handler_("Async flush failed with unknown exception"); + } } } +void async_sink::err_handler_(const std::string &message) { + using std::chrono::system_clock; + const auto now = system_clock::now(); + const auto tm_time = details::os::localtime(system_clock::to_time_t(now)); + char date_buf[64]; + std::strftime(date_buf, sizeof(date_buf), "%Y-%m-%d %H:%M:%S", &tm_time); +#if defined(USING_R) && defined(R_R_H) // if in R environment + REprintf("[*** LOG ERROR ***] [%s] [%s] %s\n", date_buf, name().c_str(), message.c_str()); +#else + std::fprintf(stderr, "[*** LOG ERROR ***] [%s] %s\n", date_buf, message.c_str()); +#endif +} } // namespace sinks } // namespace spdlog diff --git a/tests/test_async.cpp b/tests/test_async.cpp index db55572b5..406b1b870 100644 --- a/tests/test_async.cpp +++ b/tests/test_async.cpp @@ -286,3 +286,12 @@ TEST_CASE("level-off", "[async]") { REQUIRE(test_sink->msg_counter() == 0); REQUIRE(test_sink->flush_counter() == 0); } + +TEST_CASE("backend_ex", "[async]") { + const auto test_sink = std::make_shared(); + test_sink->set_exception(std::runtime_error("test backend exception")); + constexpr size_t queue_size = 16; + auto [logger, async_sink] = creat_async_logger(queue_size, test_sink); + REQUIRE_NOTHROW(logger->info("Hello message")); + REQUIRE_NOTHROW(logger->flush()); +} diff --git a/tests/test_sink.h b/tests/test_sink.h index 13eaada28..5bbfd434a 100644 --- a/tests/test_sink.h +++ b/tests/test_sink.h @@ -8,6 +8,7 @@ #include #include #include +#include #include "spdlog/details/null_mutex.h" #include "spdlog/details/os.h" @@ -36,6 +37,14 @@ class test_sink : public base_sink { delay_ = delay; } + void set_exception(const std::runtime_error& ex) { + exception_ptr_ = std::make_exception_ptr(ex); + } + + void clear_exception() { + exception_ptr_ = nullptr; + } + // return last output without the eol std::vector lines() { std::lock_guard lock(base_sink::mutex_); @@ -44,6 +53,9 @@ class test_sink : public base_sink { protected: void sink_it_(const details::log_msg &msg) override { + if (exception_ptr_) { + std::rethrow_exception(exception_ptr_); + } memory_buf_t formatted; base_sink::formatter_->format(msg, formatted); // save the line without the eol @@ -55,12 +67,18 @@ class test_sink : public base_sink { std::this_thread::sleep_for(delay_); } - void flush_() override { flush_counter_++; } + void flush_() override { + if (exception_ptr_) { + std::rethrow_exception(exception_ptr_); + } + flush_counter_++; + } size_t msg_counter_{0}; size_t flush_counter_{0}; std::chrono::milliseconds delay_{std::chrono::milliseconds::zero()}; std::vector lines_; + std::exception_ptr exception_ptr_; // will be thrown on next log or flush if not null }; using test_sink_mt = test_sink;