Merge pull request #441 from alzix/count_discarded

add an option to warn about discarded messages

include/spdlog/details/async_log_helper.h

@@ -27,6 +27,7 @@
 #include <thread>
 #include <utility>
 #include <vector>
+#include <atomic>
 
 namespace spdlog
 {
@@ -185,6 +186,12 @@ private:
     // wait until the queue is empty
     void wait_empty_q();
 
+    // counter for messages discarded due to queue overflow
+    std::atomic<unsigned int> _discarded_msg_count;
+
+    // handle discarded messages
+    void handle_discarded_msg(const std::string& logger_name);
+
 };
 }
 }
@@ -211,7 +218,8 @@ inline spdlog::details::async_log_helper::async_log_helper(
     _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)
+    _worker_thread(&async_log_helper::worker_loop, this),
+    _discarded_msg_count(0)
 {}
 
 // Send to the worker thread termination message(level=off)
@@ -237,16 +245,24 @@ 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)))
     {
-        auto last_op_time = details::os::now();
-        auto now = last_op_time;
-        do
+        if (_overflow_policy != async_overflow_policy::discard_log_msg)
         {
-            now = details::os::now();
-            sleep_or_yield(now, last_op_time);
+            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)));
+        }
+        else
+        {
+#if defined(SPDLOG_ASYNC_COUNT_DISCARDED_MSG)
+            _discarded_msg_count++;
+#endif
         }
-        while (!_q.enqueue(std::move(new_msg)));
     }
 }
 
@@ -305,6 +321,10 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_
             break;
 
         default:
+#if defined(SPDLOG_ASYNC_COUNT_DISCARDED_MSG)
+            handle_discarded_msg(incoming_async_msg.logger_name);
+#endif
+
             log_msg incoming_log_msg;
             incoming_async_msg.fill_log_msg(incoming_log_msg);
             _formatter->format(incoming_log_msg);
@@ -389,5 +409,18 @@ inline void spdlog::details::async_log_helper::set_error_handler(spdlog::log_err
     _err_handler = err_handler;
 }
 
-
+inline void spdlog::details::async_log_helper::handle_discarded_msg(const std::string& logger_name)
+{
+    unsigned int num_of_discarded_messages = _discarded_msg_count.exchange(0);
+    if (num_of_discarded_messages)
+    {
+        log_msg discarded_warning_msg(&logger_name, level::warn);
+        discarded_warning_msg.raw << "Discarded " << num_of_discarded_messages << " messages - logger queue overflow";
+        _formatter->format(discarded_warning_msg);
+        for (auto &s : _sinks)
+        {
+            s->log(discarded_warning_msg);
+        }
+    }
+}
 

include/spdlog/tweakme.h

@@ -120,3 +120,10 @@
 //
 // #define SPDLOG_FINAL final
 ///////////////////////////////////////////////////////////////////////////////
+
+///////////////////////////////////////////////////////////////////////////////
+// Uncomment count in print warning message about number of dropped messages.
+// Only relevant for async_logger with async_overflow_policy::discard_log_msg
+//
+// #define SPDLOG_ASYNC_COUNT_DISCARDED_MSG
+///////////////////////////////////////////////////////////////////////////////

tests/CMakeLists.txt

@@ -10,7 +10,7 @@ find_package(Threads)
 add_library(catch INTERFACE)
 target_include_directories(catch INTERFACE ${CMAKE_CURRENT_SOURCE_DIR})
 
-file(GLOB catch_tests LIST_DIRECTORIES false RELATIVE ${CMAKE_CURRENT_SOURCE_DIR} *.cpp)
+file(GLOB catch_tests LIST_DIRECTORIES false RELATIVE ${CMAKE_CURRENT_SOURCE_DIR} *.cpp *.h *.hpp)
 
 add_executable(catch_tests ${catch_tests})
 target_link_libraries(catch_tests spdlog ${CMAKE_THREAD_LIBS_INIT})

tests/async_logger.cpp

@@ -0,0 +1,38 @@
+
+#include <iostream>
+
+#include "includes.h"
+#include "../include/spdlog/common.h"
+#include "../include/spdlog/tweakme.h"
+
+
+TEST_CASE("async_logging_overflow ", "[async_logging]")
+{
+	std::string filename = "logs/async_log_overflow.txt";
+	auto sink = std::make_shared<spdlog::sinks::simple_file_sink_st>(filename, true);
+	auto logger = std::make_shared<spdlog::async_logger>(
+		"overflow_logger", 
+		sink,
+		2, // queue size
+		spdlog::async_overflow_policy::discard_log_msg
+	);
+	for (int i = 0; i < 8; i++) {
+		logger->info("Message #{}", i);
+	}
+	logger->flush();
+	logger.reset();
+	std::string the_log = file_contents(filename);
+#if defined(SPDLOG_ASYNC_COUNT_DISCARDED_MSG)
+	std::cout << the_log << std::endl;
+	REQUIRE(the_log.find("Dropped 6 messages") != std::string::npos);
+#endif
+}
+
+
+
+
+
+
+
+
+