Fix filesink drop messages improved (#479)

* Fix FileSink dropping messages introduced by 'optionable buffer to x messages' feature Commit 6c6122f introduced a bug where 99 out of 100 logs were actually dumped * Updated unit tests to trigger sink flush bug --------- Co-authored-by: Ryan Ammoury <[email protected]>
KjellKod · Feb 20, 2023 · 4f1224b · 4f1224b
1 parent 43f5edd
commit 4f1224b
Show file tree

Hide file tree

Showing 4 changed files with 11 additions and 6 deletions.
diff --git a/CMakeLists.txt b/CMakeLists.txt
@@ -68,7 +68,7 @@ endif()
 
 # Calculate the version number
 SET(MAJOR_VERSION 2)
-SET(MINOR_VERSION 2)
+SET(MINOR_VERSION 3)
 
 IF ( NOT VERSION )
    IF ( "${CMAKE_HOST_SYSTEM_NAME}" STREQUAL "Windows" )

diff --git a/src/filesink.cpp b/src/filesink.cpp
@@ -62,12 +62,11 @@ namespace g3 {
          _firstEntry = false;
       }
 
-      std::ofstream &out(filestream());
       auto data =  message.get().toString(_log_details_func);
 
       _write_buffer.append(data);
       if (++_write_counter % _write_to_log_every_x_message == 0) {
-         out << message.get().toString(_log_details_func) << std::flush;
+         filestream() << _write_buffer << std::flush;
          _write_buffer.clear();
       }
    }

diff --git a/test_unit/test_io.cpp b/test_unit/test_io.cpp
@@ -155,12 +155,16 @@ TEST(Basics, Shutdown) {
    std::string file_content;
    {
       RestoreFileLogger logger(log_directory);
+      LOG(INFO) << "First message buffered, then flushed";
+      LOG(INFO) << "Second message still in the buffer";
       LOG(INFO) << "Not yet shutdown. This message should make it";
       logger.reset(); // force flush of logger (which will trigger a shutdown)
       LOG(INFO) << "Logger is shutdown,. this message will not make it (but it's safe to try)";
       file_content = readFileToText(logger.logFile()); // logger is already reset
       SCOPED_TRACE("LOG_INFO"); // Scope exit be prepared for destructor failure
    }
+   EXPECT_TRUE(verifyContent(file_content, "First message buffered, then flushed"));
+   EXPECT_TRUE(verifyContent(file_content, "Second message still in the buffer"));
    EXPECT_TRUE(verifyContent(file_content, "Not yet shutdown. This message should make it"));
    EXPECT_FALSE(verifyContent(file_content, "Logger is shutdown,. this message will not make it (but it's safe to try)"));
 }

diff --git a/test_unit/testing_helpers.cpp b/test_unit/testing_helpers.cpp
@@ -26,7 +26,8 @@ namespace testing_helpers {
    std::string g_mockFatal_message = {};
    int g_mockFatal_signal = -1;
    bool g_mockFatalWasCalled = false;
-
+   const size_t kFlushToDiskWithThisInterval = 2;
+
    std::string mockFatalMessage() {
       return g_mockFatal_message;
    }
@@ -110,7 +111,8 @@ namespace testing_helpers {
    }
 
    RestoreFileLogger::RestoreFileLogger(std::string directory)
-   : _scope(new ScopedLogger), _handle(_scope->get()->addSink(std::make_unique<g3::FileSink>("UNIT_TEST_LOGGER", directory), &g3::FileSink::fileWrite)) {
+   : _scope(new ScopedLogger), _handle(_scope->get()->addSink(std::make_unique<g3::FileSink>("UNIT_TEST_LOGGER", 
+         directory, "g3log", kFlushToDiskWithThisInterval), &g3::FileSink::fileWrite)) {
       using namespace g3;
       g3::initializeLogging(_scope->_currentWorker.get());
       clearMockFatal();
@@ -133,7 +135,7 @@ namespace testing_helpers {
       reset();
 
       if (!removeFile(_log_file))
-         ADD_FAILURE();
+        ADD_FAILURE();
    }
 
    std::string RestoreFileLogger::logFile() {