From ad322fd460f7db8034b705196d4e5c230ab87125 Mon Sep 17 00:00:00 2001 From: KjellKod Date: Thu, 7 Nov 2013 01:56:48 -0700 Subject: [PATCH] Updated. LOG(...) calls to uninizialized logger does not make it crash --- g2log/src/crashhandler_unix.cpp | 2 - g2log/src/g2LogMessageBuilder.cpp | 21 +- g2log/src/g2LogMessageBuilder.hpp | 3 +- g2log/src/g2log.hpp | 13 +- g2log/src/g2log.ipp | 58 ++-- g2log/src/g2logmessage.cpp | 17 +- g2log/src/g2logmessage.hpp | 6 +- g2log/src/g2logworker.cpp | 3 +- g2log/test_unit/test_io.cpp | 412 +++++++++++++++++----------- g2log/test_unit/testing_helpers.cpp | 64 ++++- g2log/test_unit/testing_helpers.h | 25 +- 11 files changed, 398 insertions(+), 226 deletions(-) diff --git a/g2log/src/crashhandler_unix.cpp b/g2log/src/crashhandler_unix.cpp index 1fcb0bf..136125d 100644 --- a/g2log/src/crashhandler_unix.cpp +++ b/g2log/src/crashhandler_unix.cpp @@ -134,8 +134,6 @@ namespace g2 { // Triggered by g2log->g2LogWorker after receiving a FATAL trigger // which is LOG(FATAL), CHECK(false) or a fatal signal our signalhandler caught. // --- If LOG(FATAL) or CHECK(false) the signal_number will be SIGABRT - - void exitWithDefaultSignalHandler(int signal_number) { std::cerr << "Exiting - FATAL SIGNAL: " << signal_number << " " << std::flush; struct sigaction action; diff --git a/g2log/src/g2LogMessageBuilder.cpp b/g2log/src/g2LogMessageBuilder.cpp index 832b104..c1c7d54 100644 --- a/g2log/src/g2LogMessageBuilder.cpp +++ b/g2log/src/g2LogMessageBuilder.cpp @@ -23,11 +23,12 @@ namespace g2 { } LogMessageBuilder::~LogMessageBuilder() { - LogMessage log_entry(_message); - if (log_entry.wasFatal()) { - FatalMessageBuilder trigger({log_entry.toString(), SIGABRT}); + if (internal::wasFatal(_message->_level)) { + FatalMessageBuilder trigger({_message, SIGABRT}); return; // FatalMessageBuilder will send to worker at scope exit } + + LogMessage log_entry(_message); internal::saveMessage(log_entry); // message saved to g2LogWorker } @@ -62,16 +63,22 @@ namespace g2 { /// FatalMessageBuilder - FatalMessageBuilder::FatalMessageBuilder(const std::string& exit_message, int fatal_signal) - : _exit_message(exit_message), _fatal_signal(fatal_signal) { - } + FatalMessageBuilder::FatalMessageBuilder(const std::string& exit_message, int signal_id) + : _fatal_message(std::make_shared(exit_message)), _fatal_signal(signal_id) + { } + + + FatalMessageBuilder:: FatalMessageBuilder(std::shared_ptr details, int signal_id) + : _fatal_message(details), _fatal_signal(signal_id) + {} + FatalMessageBuilder::~FatalMessageBuilder() { // At destruction, flushes fatal message to g2LogWorker // either we will stay here until the background worker has received the fatal // message, flushed the crash message to the sinks and exits with the same fatal signal //..... OR it's in unit-test mode then we throw a std::runtime_error (and never hit sleep) - FatalMessage msg(_exit_message, _fatal_signal); + FatalMessage msg(_fatal_message, _fatal_signal); //internal::fatalCall({_exit_message, _fatal_signal}); internal::fatalCall(msg); diff --git a/g2log/src/g2LogMessageBuilder.hpp b/g2log/src/g2LogMessageBuilder.hpp index 3edc790..5ab84d8 100644 --- a/g2log/src/g2LogMessageBuilder.hpp +++ b/g2log/src/g2LogMessageBuilder.hpp @@ -21,9 +21,10 @@ namespace g2 { struct FatalMessageBuilder { //explicit FatalMessageBuilder(const FatalMessage& exit_message); FatalMessageBuilder(const std::string& exit_message, int fatal_signal); + FatalMessageBuilder(std::shared_ptr details, int signal_id); virtual ~FatalMessageBuilder(); - std::string _exit_message; + std::shared_ptr _fatal_message; int _fatal_signal; }; diff --git a/g2log/src/g2log.hpp b/g2log/src/g2log.hpp index 482d476..9b45ec0 100644 --- a/g2log/src/g2log.hpp +++ b/g2log/src/g2log.hpp @@ -72,12 +72,15 @@ namespace g2 { * This is kept for test reasons and should normally not be used */ g2LogWorker* shutDownLogging(); - /** FOR TESTING PURPOSES: @ref g2log.ipp - * By default the g2log will call g2LogWorker::fatal(...) which will + /** By default the g2log will call g2LogWorker::fatal(...) which will * abort() the system after flushing the logs to file. This makes unit * test of FATAL level cumbersome. A work around is to change the - * fatal call' which can be done here */ - void changeFatalInitHandlerForUnitTesting(); + * 'fatal call' which can be done here + * + * The bool return values in the fatal_call is whether or not the fatal_call should + * + */ + void changeFatalInitHandlerForUnitTesting(std::function fatal_call); } // g2::internal } // g2 @@ -89,7 +92,7 @@ namespace g2 { #define INTERNAL_CONTRACT_MESSAGE(boolean_expression) \ - g2::LogMessageBuilder(__FILE__, __LINE__, __PRETTY_FUNCTION__, FATAL).setExpression(boolean_expression) + g2::LogMessageBuilder(__FILE__, __LINE__, __PRETTY_FUNCTION__, g2::internal::CONTRACT).setExpression(boolean_expression) // LOG(level) is the API for the stream log diff --git a/g2log/src/g2log.ipp b/g2log/src/g2log.ipp index 6da11d9..2f7e09d 100644 --- a/g2log/src/g2log.ipp +++ b/g2log/src/g2log.ipp @@ -12,6 +12,7 @@ #include "g2logworker.hpp" #include "g2logmessageimpl.hpp" #include "g2loglevels.hpp" +#include "crashhandler.hpp" #include #include @@ -57,37 +58,48 @@ namespace g2 { g_logger_instance->save(log_entry); } + /** Fatal call saved to logger. This will trigger SIGABRT or other fatal signal + * to exit the program. After saving the fatal message the calling thread + * will sleep forever (i.e. until the background thread catches up, saves the fatal + * message and kills the software with the fatal signal. + */ void fatalCallToLogger(FatalMessage message) { - // real fatal call to loggr - internal::g_logger_instance->fatal(message); - } + if (!internal::isLoggingInitialized()) { + std::ostringstream error; + error << "FATAL CALL but logger is NOT initialized\n" + << "SIGNAL: " << g2::internal::signalName(message.signal_id_) + << "\nMessage: \n" << message.toString() << std::flush; + std::cerr << error; + internal::exitWithDefaultSignalHandler(message.signal_id_); + } - // By default this function pointer goes to \ref fatalCall; - void (*g_fatal_to_g2logworker_function_ptr)(FatalMessage) = fatalCallToLogger; + g_logger_instance->fatal(message); - void fatalCallForUnitTest(FatalMessage fatal_message) { - // mock fatal call, not to logger: used by unit test - assert(internal::g_logger_instance != nullptr); - internal::g_logger_instance->save(fatal_message.copyToLogMessage()); // calling 'save' instead of 'fatal' - throw std::runtime_error(fatal_message.toString()); - } - - /** The default, initial, handling to send a 'fatal' event to g2logworker - * he caller will stay here, eternally, until the software is aborted - * During unit testing the sleep-loop will be interrupted by exception from - * @ref fatalCallForUnitTest */ - void fatalCall(FatalMessage message) { - g_fatal_to_g2logworker_function_ptr(message); while (true) { std::this_thread::sleep_for(std::chrono::seconds(1)); } } - /** Used to REPLACE fatalCallToLogger for fatalCallForUnitTest - * This function switches the function pointer so that only - * 'unitTest' mock-fatal calls are made. */ - void changeFatalInitHandlerForUnitTesting() { - g_fatal_to_g2logworker_function_ptr = fatalCallForUnitTest; + + // By default this function pointer goes to \ref fatalCallToLogger; + std::function g_fatal_to_g2logworker_function_ptr = fatalCallToLogger; + + + /** The default, initial, handling to send a 'fatal' event to g2logworker + * the caller will stay here, eternally, until the software is aborted + * ... in the case of unit testing it is the given "Mock" fatalCall that will + * define the behaviour. + */ + void fatalCall(FatalMessage message) { + g_fatal_to_g2logworker_function_ptr(message); + + } + + // REPLACE fatalCallToLogger for fatalCallForUnitTest + // This function switches the function pointer so that only + // 'unitTest' mock-fatal calls are made. + void changeFatalInitHandlerForUnitTesting(std::function fatal_call) { + g_fatal_to_g2logworker_function_ptr = fatal_call; } } // internal } // g2 diff --git a/g2log/src/g2logmessage.cpp b/g2log/src/g2logmessage.cpp index a52022c..43d8f2e 100644 --- a/g2log/src/g2logmessage.cpp +++ b/g2log/src/g2logmessage.cpp @@ -66,13 +66,6 @@ namespace g2 { return internal::wasFatal(_pimpl->_level); } - // YYYY/MM/DD HH:MM:SS -- ref g2time.hpp/cpp - //out << "\n" << localtime_formatted(system_time, date_formatted); - //out << " " << localtime_formatted(system_time, time_formatted); // TODO: time kommer från LogEntry - //out << "." << std::chrono::duration_cast(steady_time - _steady_start_time).count(); - //out << "\t" << message << std::flush; - - std::string LogMessage::toString() const { std::ostringstream oss; oss << "\n" << timestamp() << "." << microseconds() << "\t"; @@ -123,16 +116,12 @@ namespace g2 { : _pimpl(details) { } - FatalMessage::FatalMessage(const std::string& crash_message, int signal_id) - : LogMessage(std::make_shared(crash_message)), signal_id_(signal_id) - { } - + FatalMessage::FatalMessage(std::shared_ptr details, int signal_id) + : LogMessage(details), signal_id_(signal_id) { } LogMessage FatalMessage::copyToLogMessage() const { return LogMessage(_pimpl); } - - //FatalMessage(const LogMessage& message, int signal_id) - //: _crash_message(message), signal_id_(signal_id) { } + } // g2 diff --git a/g2log/src/g2logmessage.hpp b/g2log/src/g2logmessage.hpp index 25e6ac7..28388e2 100644 --- a/g2log/src/g2logmessage.hpp +++ b/g2log/src/g2logmessage.hpp @@ -53,13 +53,11 @@ namespace g2 { * A thread that causes a FatalMessage will sleep forever until the * application has exited (after message flush) */ struct FatalMessage : public LogMessage { - FatalMessage(const std::string& message, int signal_id); - //FatalMessage(const LogMessage& message, int signal_id); - ~FatalMessage() = default; + FatalMessage(std::shared_ptr details, int signal_id); + ~FatalMessage() = default; LogMessage copyToLogMessage() const; - //mutable LogMessage _crash_message; int signal_id_; }; } // g2 diff --git a/g2log/src/g2logworker.cpp b/g2log/src/g2logworker.cpp index 5a01a95..9be3c0f 100644 --- a/g2log/src/g2logworker.cpp +++ b/g2log/src/g2logworker.cpp @@ -52,8 +52,7 @@ struct g2LogWorkerImpl { } void bgFatal(FatalMessage msg) { - //auto entry = fatal_message._crash_message; - auto fatal_message = msg; + auto fatal_message = msg; fatal_message.stream() << "\nExiting after fatal event. Log flushed sucessfully to disk.\n"; bgSave(fatal_message.copyToLogMessage()); diff --git a/g2log/test_unit/test_io.cpp b/g2log/test_unit/test_io.cpp index ea2cb97..118874b 100644 --- a/g2log/test_unit/test_io.cpp +++ b/g2log/test_unit/test_io.cpp @@ -11,7 +11,6 @@ #include #include -#include #include #include #include @@ -19,26 +18,6 @@ namespace { const int k_wait_time = 5; // 5s wait between LOG/CHECK FATAL till we say it's too long time const std::string log_directory = "./"; - - -bool verifyContent(const std::string &total_text, std::string msg_to_find) { - std::string content(total_text); - size_t location = content.find(msg_to_find); - return (location != std::string::npos); -} - - -std::string readFileToText(std::string filename) { - std::ifstream in; - in.open(filename.c_str(), std::ios_base::in); - if (!in.is_open()) { - return - { }; // error just return empty string - test will 'fault' - } - std::ostringstream oss; - oss << in.rdbuf(); - return oss.str(); -} } // end anonymous namespace @@ -58,17 +37,64 @@ TEST(IO_RestoreFileLogger, Expecting_Fine_To_ShutDownMultipleTimes) { } } +/// THIS MUST BE THE FIRST UNIT TEST TO RUN! If any unit test run before this +/// one then it will fail +TEST(Initialization, No_Logger_Initialized___Expecting_LOG_calls_to_be_Still_OKish) { + { + // Temporarily enable all levels. then go out of scope again. + RestoreFileLogger logger(log_directory); + EXPECT_TRUE(g2::internal::isLoggingInitialized()); + EXPECT_TRUE(g2::logLevel(INFO)); + EXPECT_TRUE(g2::logLevel(FATAL)); + EXPECT_TRUE(g2::logLevel(DEBUG)); + EXPECT_TRUE(g2::logLevel(WARNING)); + } + + EXPECT_FALSE(g2::internal::isLoggingInitialized()); + EXPECT_TRUE(g2::logLevel(INFO)); + EXPECT_TRUE(g2::logLevel(FATAL)); + EXPECT_TRUE(g2::logLevel(DEBUG)); + EXPECT_TRUE(g2::logLevel(WARNING)); + std::string err_msg1 = "Hey. I am not instantiated but I still should not crash. (I am g2logger)"; + std::string err_msg2_ignored = "This uninitialized message should be ignored"; + + try { + LOG(INFO) << err_msg1; + LOG(INFO) << err_msg2_ignored; + + } catch (std::exception& e) { + ADD_FAILURE() << "Should never have thrown even if it is not instantiated"; + } + + RestoreFileLogger logger(log_directory); // now instantiate the logger + auto content = logger.contentSoFar(); + ASSERT_FALSE(verifyContent(content, err_msg1)) << "Content: [" << content << "]"; + + std::string good_msg1 = "This message will pull in also the uninitialized_call message"; + LOG(INFO) << good_msg1; + content = logger.contentSoFar(); // this synchronizes with the LOG(INFO) call. + ASSERT_TRUE(verifyContent(content, err_msg1)) << "Content: [" << content << "]"; + ASSERT_FALSE(verifyContent(content, err_msg2_ignored)) << "Content: [" << content << "]"; + ASSERT_TRUE(verifyContent(content, good_msg1)) << "Content: [" << content << "]"; + + // debug this. it SHOULD crash since we havent fixed the code yet +} + TEST(LOGTest, LOG) { std::string file_content; { RestoreFileLogger logger(log_directory); + EXPECT_TRUE(g2::logLevel(INFO)); + EXPECT_TRUE(g2::logLevel(FATAL)); LOG(INFO) << "test LOG(INFO)"; logger.reset(); // force flush of logger file_content = readFileToText(logger.logFile()); SCOPED_TRACE("LOG_INFO"); // Scope exit be prepared for destructor failure } - ASSERT_TRUE(verifyContent(file_content, "test LOG(INFO)")); + EXPECT_TRUE(verifyContent(file_content, "test LOG(INFO)")); + EXPECT_TRUE(g2::logLevel(INFO)); + EXPECT_TRUE(g2::logLevel(FATAL)); } @@ -106,8 +132,6 @@ TEST(LogTest, LOG_F) { // stream-type log - - TEST(LogTest, LOG) { std::string file_content; { @@ -150,125 +174,90 @@ TEST(LogTest, LOG_IF) { file_content = readFileToText(logger.logFile()); SCOPED_TRACE("LOG_IF"); // Scope exit be prepared for destructor failure } - ASSERT_TRUE(verifyContent(file_content, t_info2)); - ASSERT_FALSE(verifyContent(file_content, t_debug2)); + EXPECT_TRUE(verifyContent(file_content, t_info2)); + EXPECT_FALSE(verifyContent(file_content, t_debug2)); } - - TEST(LogTest, LOGF__FATAL) { RestoreFileLogger logger(log_directory); - try { - LOGF(FATAL, "This message should throw %d", 0); - } catch (std::exception const &e) { - logger.reset(); - std::string file_content = readFileToText(logger.logFile()); - std::cerr << file_content << std::endl << std::flush; - if (verifyContent(e.what(), "EXIT trigger caused by ") && - verifyContent(file_content, "FATAL") && - verifyContent(file_content, "This message should throw")) { - SUCCEED(); - return; - } else { - ADD_FAILURE() << "Didn't throw exception as expected"; - } - } - ADD_FAILURE() << "Didn't throw exception at ALL"; + ASSERT_FALSE(mockFatalWasCalled()); + LOGF(FATAL, "This message should throw %d", 0); + EXPECT_TRUE(mockFatalWasCalled()); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "This message should throw 0")); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "FATAL")); + + logger.reset(); + std::string file_content = readFileToText(logger.logFile()); + EXPECT_TRUE(verifyContent(file_content, "This message should throw 0")); + EXPECT_TRUE(verifyContent(file_content, "FATAL")); } - - TEST(LogTest, LOG_FATAL) { RestoreFileLogger logger(log_directory); - try { - LOG(FATAL) << "This message should throw"; - } catch (std::exception const &e) { - logger.reset(); - std::string file_content = readFileToText(logger.logFile()); - if (verifyContent(e.what(), "EXIT trigger caused by ") && - verifyContent(file_content, "FATAL") && - verifyContent(file_content, "This message should throw")) { - SUCCEED(); - return; - } else { - ADD_FAILURE() << "Didn't throw exception as expected"; - } - } - ADD_FAILURE() << "Didn't throw exception at ALL"; + ASSERT_FALSE(mockFatalWasCalled()); + LOG(FATAL) << "This message should throw"; + EXPECT_TRUE(mockFatalWasCalled()); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "This message should throw")) + << "\ncontent: [[" << mockFatalMessage() << "]]"; + EXPECT_TRUE(verifyContent(mockFatalMessage(), "FATAL")); + + logger.reset(); + std::string file_content = readFileToText(logger.logFile()); + EXPECT_TRUE(verifyContent(file_content, "This message should throw")); + EXPECT_TRUE(verifyContent(file_content, "FATAL")); + EXPECT_TRUE(verifyContent(file_content, "EXIT trigger caused by ")); } - - TEST(LogTest, LOGF_IF__FATAL) { RestoreFileLogger logger(log_directory); - try { - LOGF_IF(FATAL, (2 < 3), "This message%sshould throw", " "); - } catch (std::exception const &e) { - logger.reset(); - std::string file_content = readFileToText(logger.logFile()); - if (verifyContent(e.what(), "EXIT trigger caused by ") && - verifyContent(file_content, "FATAL") && - verifyContent(file_content, "This message should throw")) { - SUCCEED(); - return; - } else { - ADD_FAILURE() << "Didn't throw exception as expected"; - } - } - ADD_FAILURE() << "Didn't throw exception at ALL"; + LOGF_IF(FATAL, (2 < 3), "This message%sshould throw", " "); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "FATAL")); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "This message should throw")); + + logger.reset(); + std::string file_content = readFileToText(logger.logFile()); + EXPECT_TRUE(verifyContent(file_content, "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(file_content, "FATAL")); + EXPECT_TRUE(verifyContent(file_content, "This message should throw")); } - - TEST(LogTest, LOG_IF__FATAL) { RestoreFileLogger logger(log_directory); - try { - LOG_IF(WARNING, (0 != t_info.compare(t_info))) << "This message should NOT be written"; - LOG_IF(FATAL, (0 != t_info.compare(t_info2))) << "This message should throw"; - } catch (std::exception const &e) { - logger.reset(); - std::string file_content = readFileToText(logger.logFile()); - if (verifyContent(e.what(), "EXIT trigger caused by ") && - verifyContent(file_content, "FATAL") && - verifyContent(file_content, "This message should throw") && - (false == verifyContent(file_content, "This message should NOT be written"))) { - SUCCEED(); - return; - } else { - ADD_FAILURE() << "Didn't throw exception as expected"; - } - } - ADD_FAILURE() << "Didn't throw exception at ALL"; + LOG_IF(WARNING, (0 != t_info.compare(t_info))) << "This message should NOT be written"; + EXPECT_FALSE(mockFatalWasCalled()); + LOG_IF(FATAL, (0 != t_info.compare(t_info2))) << "This message should throw. xyz "; + EXPECT_TRUE(mockFatalWasCalled()); + + EXPECT_TRUE(verifyContent(mockFatalMessage(), "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "FATAL")); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "This message should throw. xyz ")); + + logger.reset(); + std::string file_content = readFileToText(logger.logFile()); + EXPECT_TRUE(verifyContent(file_content, "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(file_content, "FATAL")); + EXPECT_TRUE(verifyContent(file_content, "This message should throw. xyz ")); } - - TEST(LogTest, LOG_IF__FATAL__NO_THROW) { RestoreFileLogger logger(log_directory); - try { - LOG_IF(FATAL, (2 > 3)) << "This message%sshould NOT throw"; - } catch (std::exception const &e) { - std::cerr << e.what() << std::endl; - logger.reset(); - ADD_FAILURE() << "Didn't throw exception as expected"; - } - logger.reset(); - SUCCEED(); + LOG_IF(FATAL, (2 > 3)) << "This message%sshould NOT throw"; + ASSERT_FALSE(mockFatalWasCalled()); } // CHECK_F - - TEST(CheckTest, CHECK_F__thisWILL_PrintErrorMsg) { RestoreFileLogger logger(log_directory); - try { - CHECK(1 == 2); - } catch (std::exception const &e) { - logger.reset(); - std::string file_content = readFileToText(logger.logFile()); - if (verifyContent(e.what(), "EXIT trigger caused by ") && - verifyContent(file_content, "FATAL")) { - SUCCEED(); - return; - } - } - ADD_FAILURE() << "Didn't throw exception as expected"; + EXPECT_TRUE(mockFatalMessage().empty()); + EXPECT_FALSE(mockFatalWasCalled()); + + CHECK(1 == 2); + EXPECT_FALSE(mockFatalMessage().empty()); + EXPECT_TRUE(mockFatalWasCalled()); + + logger.reset(); + std::string file_content = readFileToText(logger.logFile()); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(file_content, "FATAL")); } @@ -278,19 +267,12 @@ TEST(CHECK_F_Test, CHECK_F__thisWILL_PrintErrorMsg) { std::string msg2 = "This message is added to throw message and log"; std::string arg1 = "message"; std::string arg2 = "log"; - try { - //CHECK_F(1 >= 2, msg.c_str(), arg1.c_str(), arg2.c_str()); - } catch (std::exception const &e) { - logger.reset(); - std::string file_content = readFileToText(logger.logFile()); - if (verifyContent(e.what(), "EXIT trigger caused by ") && - verifyContent(file_content, "FATAL") && - verifyContent(file_content, msg2)) { - SUCCEED(); - return; - } - } - ADD_FAILURE() << "Didn't throw exception as expected"; + + CHECK_F(1 >= 2, msg.c_str(), arg1.c_str(), arg2.c_str()); + logger.reset(); + std::string file_content = readFileToText(logger.logFile()); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(file_content, "FATAL")); } @@ -300,37 +282,159 @@ TEST(CHECK_Test, CHECK__thisWILL_PrintErrorMsg) { std::string msg2 = "This message is added to throw message and log"; std::string arg1 = "message"; std::string arg2 = "log"; - try { - CHECK(1 >= 2) << msg2; - } catch (std::exception const &e) { - logger.reset(); - std::string file_content = readFileToText(logger.logFile()); - if (verifyContent(e.what(), "EXIT trigger caused by ") && - verifyContent(file_content, "FATAL") && - verifyContent(file_content, msg2)) { - SUCCEED(); - return; - } - } - ADD_FAILURE() << "Didn't throw exception as expected"; + CHECK(1 >= 2) << msg2; + + logger.reset(); + std::string file_content = readFileToText(logger.logFile()); + EXPECT_TRUE(verifyContent(mockFatalMessage(), "EXIT trigger caused by ")); + EXPECT_TRUE(verifyContent(file_content, "FATAL")); + EXPECT_TRUE(verifyContent(file_content, msg2)); } - - TEST(CHECK, CHECK_ThatWontThrow) { RestoreFileLogger logger(log_directory); std::string msg = "This %s should never appear in the %s"; std::string msg2 = "This message should never appear in the log"; std::string arg1 = "message"; std::string arg2 = "log"; + + CHECK(1 == 1); + CHECK_F(1 == 1, msg.c_str(), "message", "log"); + EXPECT_FALSE(mockFatalWasCalled()); + + std::string file_content = readFileToText(logger.logFile()); + EXPECT_FALSE(verifyContent(file_content, msg2)); + EXPECT_FALSE(verifyContent(mockFatalMessage(), msg2)); +} + + +#ifdef G2_DYNAMIC_LOGGING +namespace { + // Restore dynamic levels if turned off + + struct RestoreDynamicLoggingLevels { + RestoreDynamicLoggingLevels() { + }; + ~RestoreDynamicLoggingLevels() { + g2::setLogLevel(DEBUG, false); + g2::setLogLevel(INFO, false); + g2::setLogLevel(WARNING, false); + g2::setLogLevel(FATAL, false); + } + }; +} // anonymous +TEST(DynamicLogging, DynamicLogging_IS_ENABLED) { + RestoreDynamicLoggingLevels raiiLevelRestore; + + ASSERT_TRUE(g2::logLevel(DEBUG)); + ASSERT_TRUE(g2::logLevel(INFO)); + ASSERT_TRUE(g2::logLevel(WARNING)); + ASSERT_TRUE(g2::logLevel(FATAL)); // Yes FATAL can be turned off. Thereby rendering it ineffective. + g2::setLogLevel(DEBUG, false); + ASSERT_FALSE(g2::logLevel(DEBUG)); + ASSERT_TRUE(g2::logLevel(INFO)); + ASSERT_TRUE(g2::logLevel(WARNING)); + ASSERT_TRUE(g2::logLevel(FATAL)); // Yes FATAL can be turned off. Thereby rendering it ineffective. + + g2::setLogLevel(INFO, false); + ASSERT_FALSE(g2::logLevel(DEBUG)); + ASSERT_FALSE(g2::logLevel(INFO)); + ASSERT_TRUE(g2::logLevel(WARNING)); + ASSERT_TRUE(g2::logLevel(FATAL)); // Yes FATAL can be turned off. Thereby rendering it ineffective. + + g2::setLogLevel(WARNING, false); + ASSERT_FALSE(g2::logLevel(DEBUG)); + ASSERT_FALSE(g2::logLevel(INFO)); + ASSERT_FALSE(g2::logLevel(WARNING)); + ASSERT_TRUE(g2::logLevel(FATAL)); // Yes FATAL can be turned off. Thereby rendering it ineffective. + + g2::setLogLevel(FATAL, false); + ASSERT_FALSE(g2::logLevel(DEBUG)); + ASSERT_FALSE(g2::logLevel(INFO)); + ASSERT_FALSE(g2::logLevel(WARNING)); + ASSERT_FALSE(g2::logLevel(FATAL)); // Yes FATAL can be turned off. Thereby rendering it ineffective. +} +TEST(DynamicLogging, DynamicLogging_No_Logs_If_Disabled) { + RestoreFileLogger logger(log_directory); + ASSERT_TRUE(g2::logLevel(DEBUG)); + ASSERT_TRUE(g2::logLevel(INFO)); + ASSERT_TRUE(g2::logLevel(WARNING)); + ASSERT_TRUE(g2::logLevel(FATAL)); + + RestoreDynamicLoggingLevels raiiLevelRestore; + + std::string msg_debugOn = "This %s SHOULD appear in the %s"; + std::string msg_debugOff = "This message should never appear in the log"; + std::string msg_info1 = "This info msg log"; try { - CHECK(1 == 1); - CHECK_F(1 == 1, msg.c_str(), "message", "log"); + LOGF(DEBUG, msg_debugOn.c_str(), "msg", "log"); + auto content = logger.contentSoFar(); + ASSERT_TRUE(verifyContent(content, "This msg SHOULD appear in the log")) << "Content: [" << content << "]"; + + g2::setLogLevel(DEBUG, false); + EXPECT_FALSE(g2::logLevel(DEBUG)); + LOG(DEBUG) << msg_debugOff; + content = logger.contentSoFar(); + ASSERT_FALSE(verifyContent(content, "This message should never appear in the log")) << "Content: [" << content << "]"; + } catch (std::exception const &e) { std::cerr << e.what() << std::endl; ADD_FAILURE() << "Should never have thrown"; } +} +TEST(DynamicLogging, DynamicLogging_No_Fatal_If_Disabled) { + RestoreFileLogger logger(log_directory); + RestoreDynamicLoggingLevels raiiLevelRestore; + ASSERT_TRUE(g2::logLevel(DEBUG)); + ASSERT_TRUE(g2::logLevel(INFO)); + ASSERT_TRUE(g2::logLevel(WARNING)); + ASSERT_TRUE(g2::logLevel(FATAL)); - std::string file_content = readFileToText(logger.logFile()); - ASSERT_FALSE(verifyContent(file_content, msg2)); + std::string msg1 = "This IS fatal (not crash, since it is unit test"; + + LOG(FATAL) << msg1; + EXPECT_TRUE(mockFatalWasCalled()); + EXPECT_FALSE(mockFatalMessage().empty()); + EXPECT_TRUE(verifyContent(mockFatalMessage(), msg1)); + + clearMockFatal(); + EXPECT_FALSE(mockFatalWasCalled()); + + + g2::setLogLevel(FATAL, false); + std::string msg2 = "This is NOT fatal (not crash, since it is unit test. FATAL is disabled"; + LOG(FATAL) << msg2; + EXPECT_FALSE(mockFatalWasCalled()); + EXPECT_TRUE(mockFatalMessage().empty()); } + +TEST(DynamicLogging, DynamicLogging_Check_WillAlsoBeTurnedOffWhen_Fatal_Is_Disabled) { + RestoreFileLogger logger(log_directory); + RestoreDynamicLoggingLevels raiiLevelRestore; + ASSERT_TRUE(g2::logLevel(FATAL)); + + std::string msg1 = "dummy message to check if CHECK worked when fatal is enabled"; + std::string msg2 = "dummy message to check if CHECK worked when fatal is disabled"; + LOG(FATAL) << msg1; + EXPECT_TRUE(mockFatalWasCalled()); + EXPECT_TRUE(verifyContent(mockFatalMessage(), msg1)); + + clearMockFatal(); + EXPECT_FALSE(mockFatalWasCalled()); + + // Disable also CHECK calls + g2::setLogLevel(FATAL, false); + ASSERT_FALSE(g2::logLevel(FATAL)); + LOG(FATAL) << msg2; + EXPECT_FALSE(mockFatalWasCalled()); +} + + + +#else +TEST(DynamicLogging, DynamicLogging_IS_NOT_ENABLED) { + ASSERT_TRUE(g2::logLevel(DEBUG)); + //g2::setLogLevel(DEBUG, false); this line will not compile since G2_DYNAMIC_LOGGING is not enabled. Kept for show. + //ASSERT_FALSE(g2::logLevel(DEBUG)); +} +#endif // Dynamic logging diff --git a/g2log/test_unit/testing_helpers.cpp b/g2log/test_unit/testing_helpers.cpp index 601d7e5..21e127b 100644 --- a/g2log/test_unit/testing_helpers.cpp +++ b/g2log/test_unit/testing_helpers.cpp @@ -4,17 +4,56 @@ #include "testing_helpers.h" #include "g2log.hpp" #include "g2logworker.hpp" -#include "g2filesink.hpp" #include "std2_make_unique.hpp" +#include using namespace std; namespace testing_helpers { + std::string g_mockFatal_message = {}; + int g_mockFatal_signal = -1; + bool g_mockFatalWasCalled = false; + + + std::string mockFatalMessage() { return g_mockFatal_message; } + int mockFatalSignal() { return g_mockFatal_signal; } + bool mockFatalWasCalled() { return g_mockFatalWasCalled; } + + + void mockFatalCall(g2::FatalMessage fatal_message) { + g_mockFatal_message = fatal_message.toString(); + g_mockFatal_signal = fatal_message.signal_id_; + g_mockFatalWasCalled = true; + } + void clearMockFatal() { + g_mockFatal_message = {}; + g_mockFatal_signal = -1; + g_mockFatalWasCalled = false; + } + + bool removeFile(std::string path_to_file) { return (0 == std::remove(path_to_file.c_str())); } - + bool verifyContent(const std::string &total_text, std::string msg_to_find) { + std::string content(total_text); + size_t location = content.find(msg_to_find); + return (location != std::string::npos); + } + + std::string readFileToText(std::string filename) { + std::ifstream in; + in.open(filename.c_str(), std::ios_base::in); + if (!in.is_open()) { + return + { + }; // error just return empty string - test will 'fault' + } + std::ostringstream oss; + oss << in.rdbuf(); + return oss.str(); + } size_t LogFileCleaner::size() { return logs_to_clean_.size(); } @@ -61,24 +100,31 @@ namespace testing_helpers { RestoreFileLogger::RestoreFileLogger(std::string directory) - : scope_(new ScopedLogger) + : _scope(new ScopedLogger), _handle(_scope->get()->addSink(std2::make_unique("UNIT_TEST_LOGGER", directory), &g2::FileSink::fileWrite)) { using namespace g2; - auto filehandler = scope_->get()->addSink(std2::make_unique("UNIT_TEST_LOGGER", directory), &FileSink::fileWrite); + internal::changeFatalInitHandlerForUnitTesting(&mockFatalCall); - internal::changeFatalInitHandlerForUnitTesting(); LOG(INFO) << "Restore logger test "; - auto filename = filehandler->call(&FileSink::fileName); + auto filename = _handle->call(&FileSink::fileName); if (!filename.valid()) ADD_FAILURE(); - log_file_ = filename.get(); + _log_file = filename.get(); } RestoreFileLogger::~RestoreFileLogger() { - scope_.reset(); - if (!removeFile(log_file_)) + _scope.reset(); + if (!removeFile(_log_file)) ADD_FAILURE(); } + std::string RestoreFileLogger::contentSoFar() { + std::future filename = _handle->call(&g2::FileSink::fileName); + EXPECT_TRUE(filename.valid()); + auto file = filename.get(); + return readFileToText(file); + } + + diff --git a/g2log/test_unit/testing_helpers.h b/g2log/test_unit/testing_helpers.h index a831faf..3c8eb26 100644 --- a/g2log/test_unit/testing_helpers.h +++ b/g2log/test_unit/testing_helpers.h @@ -15,10 +15,21 @@ #include #include "g2logworker.hpp" #include "g2logmessage.hpp" +#include "g2filesink.hpp" namespace testing_helpers { + std::string mockFatalMessage(); + int mockFatalSignal(); + bool mockFatalWasCalled(); + void mockFatalCall(g2::FatalMessage fatal_message); + void clearMockFatal(); + bool removeFile(std::string path_to_file); + bool verifyContent(const std::string &total_text, std::string msg_to_find); + std::string readFileToText(std::string filename); + + /** After initializing ScopedCout all std::couts is redirected to the buffer @verbatim @@ -79,19 +90,23 @@ struct RestoreFileLogger { explicit RestoreFileLogger(std::string directory); ~RestoreFileLogger(); - std::unique_ptr scope_; - void reset(){ scope_.reset();} + std::unique_ptr _scope; + void reset(){ _scope.reset();} template typename std::result_of::type callToLogger(Call call, Args&&... args) { - auto func = std::bind(call, scope_->get(), std::forward(args)...); + auto func = std::bind(call, _scope->get(), std::forward(args)...); return func(); } - std::string logFile() { return log_file_; } + std::string logFile() { return _log_file; } + std::string contentSoFar(); + + private: - std::string log_file_; + std::unique_ptr> _handle; + std::string _log_file; };