From 77e7eb0b8b32fc57d7935fc81f3fc9aef7ef7ff5 Mon Sep 17 00:00:00 2001 From: ReenigneArcher <42013603+ReenigneArcher@users.noreply.github.com> Date: Sat, 30 Mar 2024 21:06:34 -0400 Subject: [PATCH] fix(logging): add logging namespace and create logging::init method --- src/config.cpp | 6 +- src/entry_handler.cpp | 6 +- src/logging.cpp | 211 +++++++++++++++++++++++++++++------- src/logging.h | 23 +++- src/main.cpp | 102 ++--------------- src/stream.cpp | 2 +- tests/conftest.cpp | 15 ++- tests/unit/test_logging.cpp | 78 +++++++++++++ tests/unit/test_video.cpp | 5 - 9 files changed, 291 insertions(+), 157 deletions(-) create mode 100644 tests/unit/test_logging.cpp diff --git a/src/config.cpp b/src/config.cpp index 29a18f637b9..97b2e929194 100644 --- a/src/config.cpp +++ b/src/config.cpp @@ -1184,7 +1184,7 @@ namespace config { auto line = argv[x]; if (line == "--help"sv) { - print_help(*argv); + logging::print_help(*argv); return 1; } #ifdef _WIN32 @@ -1204,7 +1204,7 @@ namespace config { break; } if (apply_flags(line + 1)) { - print_help(*argv); + logging::print_help(*argv); return -1; } } @@ -1218,7 +1218,7 @@ namespace config { else { TUPLE_EL(var, 1, parse_option(line, line_end)); if (!var) { - print_help(*argv); + logging::print_help(*argv); return -1; } diff --git a/src/entry_handler.cpp b/src/entry_handler.cpp index 146a4dfb07b..8d17b7d270a 100644 --- a/src/entry_handler.cpp +++ b/src/entry_handler.cpp @@ -87,12 +87,12 @@ namespace args { * * EXAMPLES: * ```cpp - * print_help("sunshine", 0, nullptr); + * help("sunshine", 0, nullptr); * ``` */ int help(const char *name, int argc, char *argv[]) { - print_help(name); + logging::print_help(name); return 0; } @@ -109,7 +109,7 @@ namespace args { */ int version(const char *name, int argc, char *argv[]) { - std::cout << PROJECT_NAME << " version: v" << PROJECT_VER << std::endl; + // version was already logged at startup return 0; } diff --git a/src/logging.cpp b/src/logging.cpp index 70a2ae82a00..f31f2b604e6 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -4,6 +4,7 @@ */ // standard includes +#include #include // lib includes @@ -16,6 +17,10 @@ // local includes #include "logging.h" +extern "C" { +#include +} + using namespace std::literals; namespace bl = boost::log; @@ -29,45 +34,169 @@ bl::sources::severity_logger warning(3); // Strange events bl::sources::severity_logger error(4); // Recoverable errors bl::sources::severity_logger fatal(5); // Unrecoverable errors -/** - * @brief Flush the log. - * - * EXAMPLES: - * ```cpp - * log_flush(); - * ``` - */ -void -log_flush() { - sink->flush(); -} +struct NoDelete { + void + operator()(void *) {} +}; -/** - * @brief Print help to stdout. - * @param name The name of the program. - * - * EXAMPLES: - * ```cpp - * print_help("sunshine"); - * ``` - */ -void -print_help(const char *name) { - std::cout - << "Usage: "sv << name << " [options] [/path/to/configuration_file] [--cmd]"sv << std::endl - << " Any configurable option can be overwritten with: \"name=value\""sv << std::endl - << std::endl - << " Note: The configuration will be created if it doesn't exist."sv << std::endl - << std::endl - << " --help | print help"sv << std::endl - << " --creds username password | set user credentials for the Web manager"sv << std::endl - << " --version | print the version of sunshine"sv << std::endl - << std::endl - << " flags"sv << std::endl - << " -0 | Read PIN from stdin"sv << std::endl - << " -1 | Do not load previously saved state and do retain any state after shutdown"sv << std::endl - << " | Effectively starting as if for the first time without overwriting any pairings with your devices"sv << std::endl - << " -2 | Force replacement of headers in video stream"sv << std::endl - << " -p | Enable/Disable UPnP"sv << std::endl - << std::endl; -} +BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", int) + +namespace logging { + /** + * @brief A destructor that restores the initial state. + */ + deinit_t::~deinit_t() { + deinit(); + } + + /** + * @brief Deinitialize the logging system. + * + * EXAMPLES: + * ```cpp + * deinit(); + * ``` + */ + void + deinit() { + log_flush(); + bl::core::get()->remove_sink(sink); + sink.reset(); + } + + /** + * @brief Initialize the logging system. + * @param min_log_level The minimum log level to output. + * @param log_file The log file to write to. + * @returns A deinit_t object that will deinitialize the logging system when it goes out of scope. + * + * EXAMPLES: + * ```cpp + * log_init(2, "sunshine.log"); + * ``` + */ + [[nodiscard]] std::unique_ptr + init(int min_log_level, const std::string &log_file) { + if (min_log_level >= 1) { + av_log_set_level(AV_LOG_QUIET); + } + else { + av_log_set_level(AV_LOG_DEBUG); + } + av_log_set_callback([](void *ptr, int level, const char *fmt, va_list vl) { + static int print_prefix = 1; + char buffer[1024]; + + av_log_format_line(ptr, level, fmt, vl, buffer, sizeof(buffer), &print_prefix); + if (level <= AV_LOG_ERROR) { + // We print AV_LOG_FATAL at the error level. FFmpeg prints things as fatal that + // are expected in some cases, such as lack of codec support or similar things. + BOOST_LOG(error) << buffer; + } + else if (level <= AV_LOG_WARNING) { + BOOST_LOG(warning) << buffer; + } + else if (level <= AV_LOG_INFO) { + BOOST_LOG(info) << buffer; + } + else if (level <= AV_LOG_VERBOSE) { + // AV_LOG_VERBOSE is less verbose than AV_LOG_DEBUG + BOOST_LOG(debug) << buffer; + } + else { + BOOST_LOG(verbose) << buffer; + } + }); + + sink = boost::make_shared(); + + boost::shared_ptr stream { &std::cout, NoDelete {} }; + sink->locked_backend()->add_stream(stream); + sink->locked_backend()->add_stream(boost::make_shared(log_file)); + sink->set_filter(severity >= min_log_level); + + sink->set_formatter([message = "Message"s, severity = "Severity"s](const bl::record_view &view, bl::formatting_ostream &os) { + constexpr int DATE_BUFFER_SIZE = 21 + 2 + 1; // Full string plus ": \0" + + auto log_level = view.attribute_values()[severity].extract().get(); + + std::string_view log_type; + switch (log_level) { + case 0: + log_type = "Verbose: "sv; + break; + case 1: + log_type = "Debug: "sv; + break; + case 2: + log_type = "Info: "sv; + break; + case 3: + log_type = "Warning: "sv; + break; + case 4: + log_type = "Error: "sv; + break; + case 5: + log_type = "Fatal: "sv; + break; + }; + + char _date[DATE_BUFFER_SIZE]; + std::time_t t = std::time(nullptr); + strftime(_date, DATE_BUFFER_SIZE, "[%Y:%m:%d:%H:%M:%S]: ", std::localtime(&t)); + + os << _date << log_type << view.attribute_values()[message].extract(); + }); + + // Flush after each log record to ensure log file contents on disk isn't stale. + // This is particularly important when running from a Windows service. + sink->locked_backend()->auto_flush(true); + + bl::core::get()->add_sink(sink); + return std::make_unique(); + } + + /** + * @brief Flush the log. + * + * EXAMPLES: + * ```cpp + * log_flush(); + * ``` + */ + void + log_flush() { + sink->flush(); + } + + /** + * @brief Print help to stdout. + * @param name The name of the program. + * + * EXAMPLES: + * ```cpp + * print_help("sunshine"); + * ``` + */ + void + print_help(const char *name) { + std::cout + << "Usage: "sv << name << " [options] [/path/to/configuration_file] [--cmd]"sv << std::endl + << " Any configurable option can be overwritten with: \"name=value\""sv << std::endl + << std::endl + << " Note: The configuration will be created if it doesn't exist."sv << std::endl + << std::endl + << " --help | print help"sv << std::endl + << " --creds username password | set user credentials for the Web manager"sv << std::endl + << " --version | print the version of sunshine"sv << std::endl + << std::endl + << " flags"sv << std::endl + << " -0 | Read PIN from stdin"sv << std::endl + << " -1 | Do not load previously saved state and do retain any state after shutdown"sv << std::endl + << " | Effectively starting as if for the first time without overwriting any pairings with your devices"sv << std::endl + << " -2 | Force replacement of headers in video stream"sv << std::endl + << " -p | Enable/Disable UPnP"sv << std::endl + << std::endl; + } +} // namespace logging diff --git a/src/logging.h b/src/logging.h index 47a08555a0b..7a1b2b95e5d 100644 --- a/src/logging.h +++ b/src/logging.h @@ -10,6 +10,9 @@ #include #include +// local includes +#include + extern boost::shared_ptr> sink; using text_sink = boost::log::sinks::asynchronous_sink; @@ -20,8 +23,18 @@ extern boost::log::sources::severity_logger warning; extern boost::log::sources::severity_logger error; extern boost::log::sources::severity_logger fatal; -// functions -void -log_flush(); -void -print_help(const char *name); +namespace logging { + class deinit_t { + public: + ~deinit_t(); + }; + + void + deinit(); + [[nodiscard]] std::unique_ptr + init(int min_log_level, const std::string &log_file); + void + log_flush(); + void + print_help(const char *name); +} // namespace logging diff --git a/src/main.cpp b/src/main.cpp index a3901448680..22d9e4c4beb 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -8,9 +8,6 @@ #include #include -// lib includes -#include - // local includes #include "confighttp.h" #include "entry_handler.h" @@ -26,19 +23,10 @@ #include "video.h" extern "C" { -#include #include } using namespace std::literals; -namespace bl = boost::log; - -struct NoDelete { - void - operator()(void *) {} -}; - -BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", int) std::map> signal_handlers; void @@ -118,84 +106,10 @@ main(int argc, char *argv[]) { return 0; } - if (config::sunshine.min_log_level >= 1) { - av_log_set_level(AV_LOG_QUIET); - } - else { - av_log_set_level(AV_LOG_DEBUG); + auto log_deinit_guard = logging::init(config::sunshine.min_log_level, config::sunshine.log_file); + if (!log_deinit_guard) { + BOOST_LOG(error) << "Logging failed to initialize"sv; } - av_log_set_callback([](void *ptr, int level, const char *fmt, va_list vl) { - static int print_prefix = 1; - char buffer[1024]; - - av_log_format_line(ptr, level, fmt, vl, buffer, sizeof(buffer), &print_prefix); - if (level <= AV_LOG_ERROR) { - // We print AV_LOG_FATAL at the error level. FFmpeg prints things as fatal that - // are expected in some cases, such as lack of codec support or similar things. - BOOST_LOG(error) << buffer; - } - else if (level <= AV_LOG_WARNING) { - BOOST_LOG(warning) << buffer; - } - else if (level <= AV_LOG_INFO) { - BOOST_LOG(info) << buffer; - } - else if (level <= AV_LOG_VERBOSE) { - // AV_LOG_VERBOSE is less verbose than AV_LOG_DEBUG - BOOST_LOG(debug) << buffer; - } - else { - BOOST_LOG(verbose) << buffer; - } - }); - - sink = boost::make_shared(); - - boost::shared_ptr stream { &std::cout, NoDelete {} }; - sink->locked_backend()->add_stream(stream); - sink->locked_backend()->add_stream(boost::make_shared(config::sunshine.log_file)); - sink->set_filter(severity >= config::sunshine.min_log_level); - - sink->set_formatter([message = "Message"s, severity = "Severity"s](const bl::record_view &view, bl::formatting_ostream &os) { - constexpr int DATE_BUFFER_SIZE = 21 + 2 + 1; // Full string plus ": \0" - - auto log_level = view.attribute_values()[severity].extract().get(); - - std::string_view log_type; - switch (log_level) { - case 0: - log_type = "Verbose: "sv; - break; - case 1: - log_type = "Debug: "sv; - break; - case 2: - log_type = "Info: "sv; - break; - case 3: - log_type = "Warning: "sv; - break; - case 4: - log_type = "Error: "sv; - break; - case 5: - log_type = "Fatal: "sv; - break; - }; - - char _date[DATE_BUFFER_SIZE]; - std::time_t t = std::time(nullptr); - strftime(_date, DATE_BUFFER_SIZE, "[%Y:%m:%d:%H:%M:%S]: ", std::localtime(&t)); - - os << _date << log_type << view.attribute_values()[message].extract(); - }); - - // Flush after each log record to ensure log file contents on disk isn't stale. - // This is particularly important when running from a Windows service. - sink->locked_backend()->auto_flush(true); - - bl::core::get()->add_sink(sink); - auto fg = util::fail_guard(log_flush); // logging can begin at this point // if anything is logged prior to this point, it will appear in stdout, but not in the log viewer in the UI @@ -227,7 +141,7 @@ main(int argc, char *argv[]) { nvprefs_instance.modify_application_profile(); // Modify global settings, undo file is produced in the process to restore after improper termination nvprefs_instance.modify_global_profile(); - // Unload dynamic library to survive driver reinstallation + // Unload dynamic library to survive driver re-installation nvprefs_instance.unload(); } @@ -320,7 +234,7 @@ main(int argc, char *argv[]) { auto task = []() { BOOST_LOG(fatal) << "10 seconds passed, yet Sunshine's still running: Forcing shutdown"sv; - log_flush(); + logging::log_flush(); lifetime::debug_trap(); }; force_shutdown = task_pool.pushDelayed(task, 10s).task_id; @@ -333,7 +247,7 @@ main(int argc, char *argv[]) { auto task = []() { BOOST_LOG(fatal) << "10 seconds passed, yet Sunshine's still running: Forcing shutdown"sv; - log_flush(); + logging::log_flush(); lifetime::debug_trap(); }; force_shutdown = task_pool.pushDelayed(task, 10s).task_id; @@ -346,8 +260,8 @@ main(int argc, char *argv[]) { // If any of the following fail, we log an error and continue event though sunshine will not function correctly. // This allows access to the UI to fix configuration problems or view the logs. - auto deinit_guard = platf::init(); - if (!deinit_guard) { + auto platf_deinit_guard = platf::init(); + if (!platf_deinit_guard) { BOOST_LOG(error) << "Platform failed to initialize"sv; } diff --git a/src/stream.cpp b/src/stream.cpp index 9c146804523..df5b3d96194 100644 --- a/src/stream.cpp +++ b/src/stream.cpp @@ -1814,7 +1814,7 @@ namespace stream { // The alternative is that Sunshine can never start another session until it's manually restarted. auto task = []() { BOOST_LOG(fatal) << "Hang detected! Session failed to terminate in 10 seconds."sv; - log_flush(); + logging::log_flush(); lifetime::debug_trap(); }; auto force_kill = task_pool.pushDelayed(task, 10s).task_id; diff --git a/tests/conftest.cpp b/tests/conftest.cpp index 0f2da8eecc6..56971b9deb2 100644 --- a/tests/conftest.cpp +++ b/tests/conftest.cpp @@ -5,16 +5,16 @@ #include #include #include -#include #include #include +#include #include #include -namespace logging = boost::log; -namespace sinks = logging::sinks; +namespace boost_logging = boost::log; +namespace sinks = boost_logging::sinks; // Undefine the original TEST macro #undef TEST @@ -79,7 +79,7 @@ class BaseTest: public ::testing::Test { test_sink->locked_backend()->add_stream(stream); // Register the sink in the logging core (BOOST_LOG) - logging::core::get()->add_sink(test_sink); + boost_logging::core::get()->add_sink(test_sink); sbuf = std::cout.rdbuf(); // save cout buffer (std::cout) std::cout.rdbuf(cout_buffer.rdbuf()); // redirect cout to buffer (std::cout) @@ -87,6 +87,11 @@ class BaseTest: public ::testing::Test { // todo: do this only once // setup a mail object mail::man = std::make_shared(); + + auto deinit_guard = logging::init(0, "test.log"); + if (!deinit_guard) { + FAIL() << "Logging failed to initialize"; + } } void @@ -121,7 +126,7 @@ class BaseTest: public ::testing::Test { } // Remove the sink from the logging core (BOOST_LOG) - logging::core::get()->remove_sink(test_sink); + boost_logging::core::get()->remove_sink(test_sink); test_sink.reset(); } diff --git a/tests/unit/test_logging.cpp b/tests/unit/test_logging.cpp new file mode 100644 index 00000000000..153a58cd01a --- /dev/null +++ b/tests/unit/test_logging.cpp @@ -0,0 +1,78 @@ +/** + * @file tests/test_logging.cpp + * @brief Test src/logging.*. + */ +#include + +#include + +#include + +class LoggerInitTest: public virtual BaseTest, public ::testing::WithParamInterface { +protected: + void + SetUp() override { + BaseTest::SetUp(); + } + + void + TearDown() override { + BaseTest::TearDown(); + } +}; +INSTANTIATE_TEST_SUITE_P( + LogLevel, + LoggerInitTest, + ::testing::Values( + 0, + 1, + 2, + 3, + 4, + 5)); +TEST_P(LoggerInitTest, InitLogging) { + int logLevel = GetParam(); + std::string logFilePath = "test_log_" + std::to_string(logLevel) + ".log"; + + auto log_deinit = logging::init(logLevel, logFilePath); + if (!log_deinit) { + FAIL() << "Failed to initialize logging"; + } +} + +TEST(LogFlushTest, CheckLogFile) { + // todo: why do we need to initialize logging here, when it's already done in the BaseTest fixture? + auto log_deinit = logging::init(0, "test.log"); + if (!log_deinit) { + FAIL() << "Failed to initialize logging"; + } + + // Write a log message + BOOST_LOG(info) << "Test message"; + + // Call log_flush + logging::log_flush(); + + // Check the contents of the log file + std::ifstream log_file("test.log"); + std::string line; + bool found = false; + while (std::getline(log_file, line)) { + if (line.find("Test message") != std::string::npos) { + found = true; + break; + } + } + + EXPECT_TRUE(found); +} + +TEST(PrintHelpTest, CheckOutput) { + std::string name = "test"; + logging::print_help(name.c_str()); + + std::string output = cout_buffer.str(); + + EXPECT_NE(output.find("Usage: " + name), std::string::npos); + EXPECT_NE(output.find("--help"), std::string::npos); +} diff --git a/tests/unit/test_video.cpp b/tests/unit/test_video.cpp index b1a664f74ef..ec96bdb2686 100644 --- a/tests/unit/test_video.cpp +++ b/tests/unit/test_video.cpp @@ -21,10 +21,6 @@ class EncoderTest: public virtual BaseTest, public PlatformInitBase, public ::te bool isEncoderValid; isEncoderValid = video::validate_encoder(*encoder, false); - // todo: av logging is not redirected to boost so it will be visible whether the test passes or fails - // move this code to logging - // https://github.com/LizardByte/Sunshine/blob/5606840c8983b714a0e442c42d887a49807715e1/src/main.cpp#L118 - if (!isEncoderValid) { // if encoder is software fail, otherwise skip if (encoder == &video::software && std::string(TESTS_SOFTWARE_ENCODER_UNAVAILABLE) == "fail") { @@ -49,7 +45,6 @@ INSTANTIATE_TEST_SUITE_P( EncoderVariants, EncoderTest, ::testing::Values( -// todo: all encoders crash on windows, probably due to platf not being initialized (which also crashes) #if !defined(__APPLE__) std::make_tuple(video::nvenc.name, &video::nvenc), #endif