From 4f1224b9d52d7bfe74fde2bf31f88733ce04d19d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kjell=20Hedstr=C3=B6m?= Date: Mon, 20 Feb 2023 06:16:34 -0700 Subject: [PATCH] Fix filesink drop messages improved (#479) * Fix FileSink dropping messages introduced by 'optionable buffer to x messages' feature Commit 6c6122fafc79e92fc94a851b3ff83f87e8b80398 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 --- CMakeLists.txt | 2 +- src/filesink.cpp | 3 +-- test_unit/test_io.cpp | 4 ++++ test_unit/testing_helpers.cpp | 8 +++++--- 4 files changed, 11 insertions(+), 6 deletions(-) diff --git a/CMakeLists.txt b/CMakeLists.txt index d8d3c71d..83ded10f 100644 --- 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 index 0b7cee3b..5058697f 100644 --- 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 index d5220cd1..61646d78 100644 --- 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 index 5e3055c4..acb1ae6f 100644 --- 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("UNIT_TEST_LOGGER", directory), &g3::FileSink::fileWrite)) { + : _scope(new ScopedLogger), _handle(_scope->get()->addSink(std::make_unique("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() {