Fixed issue #396 and added some tests to catch it

This commit is contained in:
gabime 2017-03-28 01:54:33 +03:00
parent 27df6eb4ca
commit 397d4866b3
6 changed files with 353 additions and 291 deletions

View File

@ -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;

View File

@ -135,6 +135,7 @@ public:
void flush(bool wait_for_q);
void set_error_handler(spdlog::log_err_handler err_handler);
private:
formatter_ptr _formatter;
@ -215,13 +216,13 @@ inline spdlog::details::async_log_helper::async_log_helper(
// and wait for it to finish gracefully
inline spdlog::details::async_log_helper::~async_log_helper()
{
try
{
try {
push_msg(async_msg(async_msg_type::terminate));
_worker_thread.join();
}
catch (...) // don't crash in destructor
{}
{
}
}
@ -233,16 +234,13 @@ inline void spdlog::details::async_log_helper::log(const details::log_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)
{
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
{
do {
now = details::os::now();
sleep_or_yield(now, last_op_time);
}
while (!_q.enqueue(std::move(new_msg)));
} while (!_q.enqueue(std::move(new_msg)));
}
}
@ -255,24 +253,26 @@ inline void spdlog::details::async_log_helper::flush(bool wait_for_q)
}
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();
auto active = true;
while (active) {
try {
active = process_next_msg(last_pop, last_flush);
}
catch (const std::exception &ex)
{
catch (const std::exception &ex) {
_err_handler(ex.what());
}
catch (...)
{
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)
@ -280,11 +280,9 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_
{
async_msg incoming_async_msg;
if (_q.dequeue(incoming_async_msg))
{
if (_q.dequeue(incoming_async_msg)) {
last_pop = details::os::now();
switch (incoming_async_msg.msg_type)
{
switch (incoming_async_msg.msg_type) {
case async_msg_type::flush:
_flush_requested = true;
break;
@ -298,10 +296,8 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_
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))
{
for (auto &s : _sinks) {
if (s->should_log(incoming_log_msg.level)) {
s->log(incoming_log_msg);
}
}
@ -311,8 +307,7 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_
// Handle empty queue..
// This is the only place where the queue can terminate or flush to avoid losing messages already in the queue
else
{
else {
auto now = details::os::now();
handle_flush_interval(now, last_flush);
sleep_or_yield(now, last_pop);
@ -324,8 +319,7 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_
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)
{
if (should_flush) {
for (auto &s : _sinks)
s->flush();
now = last_flush = details::os::now();
@ -368,11 +362,15 @@ inline void spdlog::details::async_log_helper::sleep_or_yield(const spdlog::log_
inline void spdlog::details::async_log_helper::wait_empty_q()
{
auto last_op = details::os::now();
while (_q.approx_size() > 0)
{
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;
}

View File

@ -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;

View File

@ -59,10 +59,6 @@ public:
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<sink_ptr>& 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&);

View File

@ -6,6 +6,19 @@
#include<iostream>
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();
@ -22,15 +35,17 @@ TEST_CASE("default_error_handler", "[errors]]")
}
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<spdlog::sinks::simple_file_sink_mt>("logger", filename, true);
logger->flush_on(spdlog::level::info);
logger->set_error_handler([=](const std::string& msg)
{
logger->set_error_handler([=](const std::string& msg) {
throw custom_ex();
});
logger->info("Good message #1");
@ -39,6 +54,16 @@ TEST_CASE("custom_error_handler", "[errors]]")
REQUIRE(count_lines(filename) == 2);
}
TEST_CASE("default_error_handler2", "[errors]]")
{
auto logger = spdlog::create<failing_sink>("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();
@ -47,8 +72,7 @@ TEST_CASE("async_error_handler", "[errors]]")
std::string filename = "logs/simple_async_log.txt";
{
auto logger = spdlog::create<spdlog::sinks::simple_file_sink_mt>("logger", filename, true);
logger->set_error_handler([=](const std::string& msg)
{
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;
@ -62,3 +86,24 @@ TEST_CASE("async_error_handler", "[errors]]")
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<failing_sink>("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);
}

View File

@ -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/*");
system("mkdir -p logs");
system("rm -f logs/*");
#endif
(void)rv;
}