From 397d4866b3bde68047cf5f1064a3fec85d99700a Mon Sep 17 00:00:00 2001 From: gabime Date: Tue, 28 Mar 2017 01:54:33 +0300 Subject: [PATCH] Fixed issue #396 and added some tests to catch it --- include/spdlog/async_logger.h | 5 + include/spdlog/details/async_log_helper.h | 478 ++++++++++----------- include/spdlog/details/async_logger_impl.h | 13 + include/spdlog/logger.h | 10 +- tests/errors.cpp | 129 ++++-- tests/utils.cpp | 9 +- 6 files changed, 353 insertions(+), 291 deletions(-) diff --git a/include/spdlog/async_logger.h b/include/spdlog/async_logger.h index 1c42fd9c..418d1174 100644 --- a/include/spdlog/async_logger.h +++ b/include/spdlog/async_logger.h @@ -63,6 +63,11 @@ public: //Wait for the queue to be empty, and flush synchronously //Warning: this can potentialy last forever as we wait it to complete void flush() override; + + // Error handler + virtual void set_error_handler(log_err_handler) override; + virtual log_err_handler error_handler() override; + protected: void _sink_it(details::log_msg& msg) override; void _set_formatter(spdlog::formatter_ptr msg_formatter) override; diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index deb8dcc6..c9054f9e 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -32,346 +32,344 @@ namespace spdlog { -namespace details -{ + namespace details + { -class async_log_helper -{ - // Async msg to move to/from the queue - // Movable only. should never be copied - enum class async_msg_type - { - log, - flush, - terminate - }; - struct async_msg - { - std::string logger_name; - level::level_enum level; - log_clock::time_point time; - size_t thread_id; - std::string txt; - async_msg_type msg_type; + class async_log_helper + { + // Async msg to move to/from the queue + // Movable only. should never be copied + enum class async_msg_type + { + log, + flush, + terminate + }; + struct async_msg + { + std::string logger_name; + level::level_enum level; + log_clock::time_point time; + size_t thread_id; + std::string txt; + async_msg_type msg_type; - async_msg() = default; - ~async_msg() = default; + async_msg() = default; + ~async_msg() = default; -async_msg(async_msg&& other) SPDLOG_NOEXCEPT: - logger_name(std::move(other.logger_name)), - level(std::move(other.level)), - time(std::move(other.time)), - txt(std::move(other.txt)), - msg_type(std::move(other.msg_type)) - {} + async_msg(async_msg&& other) SPDLOG_NOEXCEPT: + logger_name(std::move(other.logger_name)), + level(std::move(other.level)), + time(std::move(other.time)), + txt(std::move(other.txt)), + msg_type(std::move(other.msg_type)) + {} - async_msg(async_msg_type m_type) :msg_type(m_type) - {} + async_msg(async_msg_type m_type):msg_type(m_type) + {} - async_msg& operator=(async_msg&& other) SPDLOG_NOEXCEPT - { - logger_name = std::move(other.logger_name); - level = other.level; - time = std::move(other.time); - thread_id = other.thread_id; - txt = std::move(other.txt); - msg_type = other.msg_type; - return *this; - } + async_msg& operator=(async_msg&& other) SPDLOG_NOEXCEPT + { + logger_name = std::move(other.logger_name); + level = other.level; + time = std::move(other.time); + thread_id = other.thread_id; + txt = std::move(other.txt); + msg_type = other.msg_type; + return *this; + } - // never copy or assign. should only be moved.. - async_msg(const async_msg&) = delete; - async_msg& operator=(const async_msg& other) = delete; + // never copy or assign. should only be moved.. + async_msg(const async_msg&) = delete; + async_msg& operator=(const async_msg& other) = delete; - // construct from log_msg - async_msg(const details::log_msg& m) : - level(m.level), - time(m.time), - thread_id(m.thread_id), - txt(m.raw.data(), m.raw.size()), - msg_type(async_msg_type::log) - { + // construct from log_msg + async_msg(const details::log_msg& m): + level(m.level), + time(m.time), + thread_id(m.thread_id), + txt(m.raw.data(), m.raw.size()), + msg_type(async_msg_type::log) + { #ifndef SPDLOG_NO_NAME - logger_name = *m.logger_name; + logger_name = *m.logger_name; #endif - } + } - // copy into log_msg - void fill_log_msg(log_msg &msg) - { - msg.logger_name = &logger_name; - msg.level = level; - msg.time = time; - msg.thread_id = thread_id; - msg.raw << txt; - } - }; + // copy into log_msg + void fill_log_msg(log_msg &msg) + { + msg.logger_name = &logger_name; + msg.level = level; + msg.time = time; + msg.thread_id = thread_id; + msg.raw << txt; + } + }; -public: + public: - using item_type = async_msg; - using q_type = details::mpmc_bounded_queue; + using item_type = async_msg; + using q_type = details::mpmc_bounded_queue; - using clock = std::chrono::steady_clock; + using clock = std::chrono::steady_clock; - async_log_helper(formatter_ptr formatter, - const std::vector& sinks, - size_t queue_size, - const log_err_handler err_handler, - const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, - const std::function& worker_warmup_cb = nullptr, - const std::chrono::milliseconds& flush_interval_ms = std::chrono::milliseconds::zero(), - const std::function& worker_teardown_cb = nullptr); + async_log_helper(formatter_ptr formatter, + const std::vector& sinks, + size_t queue_size, + const log_err_handler err_handler, + const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, + const std::function& worker_warmup_cb = nullptr, + const std::chrono::milliseconds& flush_interval_ms = std::chrono::milliseconds::zero(), + const std::function& worker_teardown_cb = nullptr); - void log(const details::log_msg& msg); + void log(const details::log_msg& msg); - // stop logging and join the back thread - ~async_log_helper(); + // stop logging and join the back thread + ~async_log_helper(); - void set_formatter(formatter_ptr); + void set_formatter(formatter_ptr); - void flush(bool wait_for_q); + void flush(bool wait_for_q); + + void set_error_handler(spdlog::log_err_handler err_handler); + + private: + formatter_ptr _formatter; + std::vector> _sinks; + + // queue of messages to log + q_type _q; + + log_err_handler _err_handler; + + bool _flush_requested; + + bool _terminate_requested; -private: - formatter_ptr _formatter; - std::vector> _sinks; + // overflow policy + const async_overflow_policy _overflow_policy; - // queue of messages to log - q_type _q; + // worker thread warmup callback - one can set thread priority, affinity, etc + const std::function _worker_warmup_cb; - log_err_handler _err_handler; + // auto periodic sink flush parameter + const std::chrono::milliseconds _flush_interval_ms; - bool _flush_requested; + // worker thread teardown callback + const std::function _worker_teardown_cb; - bool _terminate_requested; + // worker thread + std::thread _worker_thread; + void push_msg(async_msg&& new_msg); - // overflow policy - const async_overflow_policy _overflow_policy; + // worker thread main loop + void worker_loop(); - // worker thread warmup callback - one can set thread priority, affinity, etc - const std::function _worker_warmup_cb; + // pop next message from the queue and process it. will set the last_pop to the pop time + // return false if termination of the queue is required + bool process_next_msg(log_clock::time_point& last_pop, log_clock::time_point& last_flush); - // auto periodic sink flush parameter - const std::chrono::milliseconds _flush_interval_ms; + void handle_flush_interval(log_clock::time_point& now, log_clock::time_point& last_flush); - // worker thread teardown callback - const std::function _worker_teardown_cb; + // sleep,yield or return immediatly using the time passed since last message as a hint + static void sleep_or_yield(const spdlog::log_clock::time_point& now, const log_clock::time_point& last_op_time); - // worker thread - std::thread _worker_thread; + // wait until the queue is empty + void wait_empty_q(); - void push_msg(async_msg&& new_msg); - - // worker thread main loop - void worker_loop(); - - // pop next message from the queue and process it. will set the last_pop to the pop time - // return false if termination of the queue is required - bool process_next_msg(log_clock::time_point& last_pop, log_clock::time_point& last_flush); - - void handle_flush_interval(log_clock::time_point& now, log_clock::time_point& last_flush); - - // sleep,yield or return immediatly using the time passed since last message as a hint - static void sleep_or_yield(const spdlog::log_clock::time_point& now, const log_clock::time_point& last_op_time); - - // wait until the queue is empty - void wait_empty_q(); - -}; -} + }; + } } /////////////////////////////////////////////////////////////////////////////// // async_sink class implementation /////////////////////////////////////////////////////////////////////////////// inline spdlog::details::async_log_helper::async_log_helper( - formatter_ptr formatter, - const std::vector& sinks, - size_t queue_size, - log_err_handler err_handler, - const async_overflow_policy overflow_policy, - const std::function& worker_warmup_cb, - const std::chrono::milliseconds& flush_interval_ms, - const std::function& worker_teardown_cb): - _formatter(formatter), - _sinks(sinks), - _q(queue_size), - _err_handler(err_handler), - _flush_requested(false), - _terminate_requested(false), - _overflow_policy(overflow_policy), - _worker_warmup_cb(worker_warmup_cb), - _flush_interval_ms(flush_interval_ms), - _worker_teardown_cb(worker_teardown_cb), - _worker_thread(&async_log_helper::worker_loop, this) + formatter_ptr formatter, + const std::vector& sinks, + size_t queue_size, + log_err_handler err_handler, + const async_overflow_policy overflow_policy, + const std::function& worker_warmup_cb, + const std::chrono::milliseconds& flush_interval_ms, + const std::function& worker_teardown_cb): + _formatter(formatter), + _sinks(sinks), + _q(queue_size), + _err_handler(err_handler), + _flush_requested(false), + _terminate_requested(false), + _overflow_policy(overflow_policy), + _worker_warmup_cb(worker_warmup_cb), + _flush_interval_ms(flush_interval_ms), + _worker_teardown_cb(worker_teardown_cb), + _worker_thread(&async_log_helper::worker_loop, this) {} // Send to the worker thread termination message(level=off) // and wait for it to finish gracefully inline spdlog::details::async_log_helper::~async_log_helper() { - try - { - push_msg(async_msg(async_msg_type::terminate)); - _worker_thread.join(); - } - catch (...) // don't crash in destructor - {} + try { + push_msg(async_msg(async_msg_type::terminate)); + _worker_thread.join(); + } + catch (...) // don't crash in destructor + { + } } //Try to push and block until succeeded (if the policy is not to discard when the queue is full) inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) { - push_msg(async_msg(msg)); + push_msg(async_msg(msg)); } inline void spdlog::details::async_log_helper::push_msg(details::async_log_helper::async_msg&& new_msg) { - if (!_q.enqueue(std::move(new_msg)) && _overflow_policy != async_overflow_policy::discard_log_msg) - { - auto last_op_time = details::os::now(); - auto now = last_op_time; - do - { - now = details::os::now(); - sleep_or_yield(now, last_op_time); - } - while (!_q.enqueue(std::move(new_msg))); - } + if (!_q.enqueue(std::move(new_msg)) && _overflow_policy != async_overflow_policy::discard_log_msg) { + auto last_op_time = details::os::now(); + auto now = last_op_time; + do { + now = details::os::now(); + sleep_or_yield(now, last_op_time); + } while (!_q.enqueue(std::move(new_msg))); + } } // optionally wait for the queue be empty and request flush from the sinks inline void spdlog::details::async_log_helper::flush(bool wait_for_q) { - push_msg(async_msg(async_msg_type::flush)); - if(wait_for_q) - wait_empty_q(); //return only make after the above flush message was processed + push_msg(async_msg(async_msg_type::flush)); + if (wait_for_q) + wait_empty_q(); //return only make after the above flush message was processed } inline void spdlog::details::async_log_helper::worker_loop() { - try - { - if (_worker_warmup_cb) _worker_warmup_cb(); - auto last_pop = details::os::now(); - auto last_flush = last_pop; - while(process_next_msg(last_pop, last_flush)); - if (_worker_teardown_cb) _worker_teardown_cb(); - } - catch (const std::exception &ex) - { - _err_handler(ex.what()); - } - catch (...) - { - _err_handler("Unknown exception"); - } + if (_worker_warmup_cb) _worker_warmup_cb(); + auto last_pop = details::os::now(); + auto last_flush = last_pop; + auto active = true; + while (active) { + try { + active = process_next_msg(last_pop, last_flush); + } + catch (const std::exception &ex) { + _err_handler(ex.what()); + } + catch (...) { + _err_handler("Unknown exception"); + } + } + if (_worker_teardown_cb) _worker_teardown_cb(); + + } // process next message in the queue // return true if this thread should still be active (while no terminate msg was received) inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_point& last_pop, log_clock::time_point& last_flush) { - async_msg incoming_async_msg; + async_msg incoming_async_msg; - if (_q.dequeue(incoming_async_msg)) - { - last_pop = details::os::now(); - switch (incoming_async_msg.msg_type) - { - case async_msg_type::flush: - _flush_requested = true; - break; + if (_q.dequeue(incoming_async_msg)) { + last_pop = details::os::now(); + switch (incoming_async_msg.msg_type) { + case async_msg_type::flush: + _flush_requested = true; + break; - case async_msg_type::terminate: - _flush_requested = true; - _terminate_requested = true; - break; + case async_msg_type::terminate: + _flush_requested = true; + _terminate_requested = true; + break; - default: - log_msg incoming_log_msg; - incoming_async_msg.fill_log_msg(incoming_log_msg); - _formatter->format(incoming_log_msg); - for (auto &s : _sinks) - { - if(s->should_log( incoming_log_msg.level)) - { - s->log(incoming_log_msg); - } - } - } - return true; - } + default: + log_msg incoming_log_msg; + incoming_async_msg.fill_log_msg(incoming_log_msg); + _formatter->format(incoming_log_msg); + for (auto &s : _sinks) { + if (s->should_log(incoming_log_msg.level)) { + s->log(incoming_log_msg); + } + } + } + return true; + } - // Handle empty queue.. - // This is the only place where the queue can terminate or flush to avoid losing messages already in the queue - else - { - auto now = details::os::now(); - handle_flush_interval(now, last_flush); - sleep_or_yield(now, last_pop); - return !_terminate_requested; - } + // Handle empty queue.. + // This is the only place where the queue can terminate or flush to avoid losing messages already in the queue + else { + auto now = details::os::now(); + handle_flush_interval(now, last_flush); + sleep_or_yield(now, last_pop); + return !_terminate_requested; + } } // flush all sinks if _flush_interval_ms has expired inline void spdlog::details::async_log_helper::handle_flush_interval(log_clock::time_point& now, log_clock::time_point& last_flush) { - auto should_flush = _flush_requested || (_flush_interval_ms != std::chrono::milliseconds::zero() && now - last_flush >= _flush_interval_ms); - if (should_flush) - { - for (auto &s : _sinks) - s->flush(); - now = last_flush = details::os::now(); - _flush_requested = false; - } + auto should_flush = _flush_requested || (_flush_interval_ms != std::chrono::milliseconds::zero() && now - last_flush >= _flush_interval_ms); + if (should_flush) { + for (auto &s : _sinks) + s->flush(); + now = last_flush = details::os::now(); + _flush_requested = false; + } } inline void spdlog::details::async_log_helper::set_formatter(formatter_ptr msg_formatter) { - _formatter = msg_formatter; + _formatter = msg_formatter; } // spin, yield or sleep. use the time passed since last message as a hint inline void spdlog::details::async_log_helper::sleep_or_yield(const spdlog::log_clock::time_point& now, const spdlog::log_clock::time_point& last_op_time) { - using namespace std::this_thread; - using std::chrono::milliseconds; - using std::chrono::microseconds; + using namespace std::this_thread; + using std::chrono::milliseconds; + using std::chrono::microseconds; - auto time_since_op = now - last_op_time; + auto time_since_op = now - last_op_time; - // spin upto 50 micros - if (time_since_op <= microseconds(50)) - return; + // spin upto 50 micros + if (time_since_op <= microseconds(50)) + return; - // yield upto 150 micros - if (time_since_op <= microseconds(100)) - return std::this_thread::yield(); + // yield upto 150 micros + if (time_since_op <= microseconds(100)) + return std::this_thread::yield(); - // sleep for 20 ms upto 200 ms - if (time_since_op <= milliseconds(200)) - return sleep_for(milliseconds(20)); + // sleep for 20 ms upto 200 ms + if (time_since_op <= milliseconds(200)) + return sleep_for(milliseconds(20)); - // sleep for 200 ms - return sleep_for(milliseconds(200)); + // sleep for 200 ms + return sleep_for(milliseconds(200)); } // wait for the queue to be empty inline void spdlog::details::async_log_helper::wait_empty_q() { - auto last_op = details::os::now(); - while (_q.approx_size() > 0) - { - sleep_or_yield(details::os::now(), last_op); - } + auto last_op = details::os::now(); + while (_q.approx_size() > 0) { + sleep_or_yield(details::os::now(), last_op); + } +} + +inline void spdlog::details::async_log_helper::set_error_handler(spdlog::log_err_handler err_handler) +{ + _err_handler = err_handler; } diff --git a/include/spdlog/details/async_logger_impl.h b/include/spdlog/details/async_logger_impl.h index 2092f06c..300bad83 100644 --- a/include/spdlog/details/async_logger_impl.h +++ b/include/spdlog/details/async_logger_impl.h @@ -57,6 +57,19 @@ inline void spdlog::async_logger::flush() _async_log_helper->flush(true); } +// Error handler +inline void spdlog::async_logger::set_error_handler(spdlog::log_err_handler err_handler) +{ + _err_handler = err_handler; + _async_log_helper->set_error_handler(err_handler); + +} +inline spdlog::log_err_handler spdlog::async_logger::error_handler() +{ + return _err_handler; +} + + inline void spdlog::async_logger::_set_formatter(spdlog::formatter_ptr msg_formatter) { _formatter = msg_formatter; diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index a6d3022c..9303907b 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -58,11 +58,7 @@ public: const std::string& name() const; void set_pattern(const std::string&); void set_formatter(formatter_ptr); - - // error handler - void set_error_handler(log_err_handler); - log_err_handler error_handler(); - + // automatically call flush() if message level >= log_level void flush_on(level::level_enum log_level); @@ -70,6 +66,10 @@ public: const std::vector& sinks() const; + // error handler + virtual void set_error_handler(log_err_handler); + virtual log_err_handler error_handler(); + protected: virtual void _sink_it(details::log_msg&); virtual void _set_pattern(const std::string&); diff --git a/tests/errors.cpp b/tests/errors.cpp index bcbb64ba..1608733c 100644 --- a/tests/errors.cpp +++ b/tests/errors.cpp @@ -6,59 +6,104 @@ #include + + +class failing_sink: public spdlog::sinks::sink +{ + void log(const spdlog::details::log_msg& msg) override + { + throw std::runtime_error("some error happened during log"); + } + + void flush() + {} +}; + TEST_CASE("default_error_handler", "[errors]]") { - prepare_logdir(); - std::string filename = "logs/simple_log.txt"; + prepare_logdir(); + std::string filename = "logs/simple_log.txt"; - auto logger = spdlog::create("logger", filename, true); - logger->set_pattern("%v"); - logger->info("Test message {} {}", 1); - logger->info("Test message {}", 2); - logger->flush(); + auto logger = spdlog::create("logger", filename, true); + logger->set_pattern("%v"); + logger->info("Test message {} {}", 1); + logger->info("Test message {}", 2); + logger->flush(); - REQUIRE(file_contents(filename) == std::string("Test message 2\n")); - REQUIRE(count_lines(filename) == 1); + REQUIRE(file_contents(filename) == std::string("Test message 2\n")); + REQUIRE(count_lines(filename) == 1); } -struct custom_ex {}; + + +struct custom_ex +{}; TEST_CASE("custom_error_handler", "[errors]]") { - prepare_logdir(); - std::string filename = "logs/simple_log.txt"; - auto logger = spdlog::create("logger", filename, true); - logger->flush_on(spdlog::level::info); - logger->set_error_handler([=](const std::string& msg) - { - throw custom_ex(); - }); - logger->info("Good message #1"); - REQUIRE_THROWS_AS(logger->info("Bad format msg {} {}", "xxx"), custom_ex); - logger->info("Good message #2"); - REQUIRE(count_lines(filename) == 2); + prepare_logdir(); + std::string filename = "logs/simple_log.txt"; + auto logger = spdlog::create("logger", filename, true); + logger->flush_on(spdlog::level::info); + logger->set_error_handler([=](const std::string& msg) { + throw custom_ex(); + }); + logger->info("Good message #1"); + REQUIRE_THROWS_AS(logger->info("Bad format msg {} {}", "xxx"), custom_ex); + logger->info("Good message #2"); + REQUIRE(count_lines(filename) == 2); +} + +TEST_CASE("default_error_handler2", "[errors]]") +{ + + auto logger = spdlog::create("failed_logger"); + logger->set_error_handler([=](const std::string& msg) { + throw custom_ex(); + }); + REQUIRE_THROWS_AS(logger->info("Some message"), custom_ex); } TEST_CASE("async_error_handler", "[errors]]") { - prepare_logdir(); - std::string err_msg("log failed with some msg"); - spdlog::set_async_mode(128); - std::string filename = "logs/simple_async_log.txt"; - { - auto logger = spdlog::create("logger", filename, true); - logger->set_error_handler([=](const std::string& msg) - { - std::ofstream ofs("logs/custom_err.txt"); - if (!ofs) throw std::runtime_error("Failed open logs/custom_err.txt"); - ofs << err_msg; - }); - logger->info("Good message #1"); - logger->info("Bad format msg {} {}", "xxx"); - logger->info("Good message #2"); - spdlog::drop("logger"); //force logger to drain the queue and shutdown - spdlog::set_sync_mode(); - } - REQUIRE(count_lines(filename) == 2); - REQUIRE(file_contents("logs/custom_err.txt") == err_msg); + prepare_logdir(); + std::string err_msg("log failed with some msg"); + spdlog::set_async_mode(128); + std::string filename = "logs/simple_async_log.txt"; + { + auto logger = spdlog::create("logger", filename, true); + logger->set_error_handler([=](const std::string& msg) { + std::ofstream ofs("logs/custom_err.txt"); + if (!ofs) throw std::runtime_error("Failed open logs/custom_err.txt"); + ofs << err_msg; + }); + logger->info("Good message #1"); + logger->info("Bad format msg {} {}", "xxx"); + logger->info("Good message #2"); + spdlog::drop("logger"); //force logger to drain the queue and shutdown + spdlog::set_sync_mode(); + } + REQUIRE(count_lines(filename) == 2); + REQUIRE(file_contents("logs/custom_err.txt") == err_msg); +} + +// Make sure async error handler is executed +TEST_CASE("async_error_handler2", "[errors]]") +{ + prepare_logdir(); + std::string err_msg("This is async handler error message"); + spdlog::set_async_mode(128); + { + auto logger = spdlog::create("failed_logger"); + logger->set_error_handler([=](const std::string& msg) { + std::ofstream ofs("logs/custom_err2.txt"); + if (!ofs) throw std::runtime_error("Failed open logs/custom_err2.txt"); + ofs << err_msg; + }); + logger->info("Hello failure"); + spdlog::drop("failed_logger"); //force logger to drain the queue and shutdown + spdlog::set_sync_mode(); + } + + REQUIRE(file_contents("logs/custom_err2.txt") == err_msg); } diff --git a/tests/utils.cpp b/tests/utils.cpp index 9fe8b162..0593b59d 100644 --- a/tests/utils.cpp +++ b/tests/utils.cpp @@ -4,11 +4,12 @@ void prepare_logdir() { spdlog::drop_all(); #ifdef _WIN32 - auto rv = system("del /F /Q logs\\*"); + system("if not exist logs mkdir logs"); + system("del /F /Q logs\\*"); #else - auto rv = system("rm -f logs/*"); -#endif - (void)rv; + system("mkdir -p logs"); + system("rm -f logs/*"); +#endif }