fix(logging): add logging namespace and create logging::init method (#2336)

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;
           }
 

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;
   }
 

src/logging.cpp

@@ -4,9 +4,11 @@
  */
 
 // standard includes
+#include <fstream>
 #include <iostream>
 
 // lib includes
+#include <boost/core/null_deleter.hpp>
 #include <boost/log/attributes/clock.hpp>
 #include <boost/log/common.hpp>
 #include <boost/log/expressions.hpp>
@@ -16,6 +18,10 @@
 // local includes
 #include "logging.h"
 
+extern "C" {
+#include <libavutil/log.h>
+}
+
 using namespace std::literals;
 
 namespace bl = boost::log;
@@ -29,45 +35,182 @@ bl::sources::severity_logger<int> warning(3);  // Strange events
 bl::sources::severity_logger<int> error(4);  // Recoverable errors
 bl::sources::severity_logger<int> fatal(5);  // Unrecoverable errors
 
-/**
+BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", int)
- * @brief Flush the log.
- *
- * EXAMPLES:
- * ```cpp
- * log_flush();
- * ```
- */
-void
-log_flush() {
-  sink->flush();
-}
 
-/**
+namespace logging {
- * @brief Print help to stdout.
+  /**
- * @param name The name of the program.
+   * @brief A destructor that restores the initial state.
- *
+   */
- * EXAMPLES:
+  deinit_t::~deinit_t() {
- * ```cpp
+    deinit();
- * print_help("sunshine");
+  }
- * ```
+
- */
+  /**
-void
+   * @brief Deinitialize the logging system.
-print_help(const char *name) {
+   *
-  std::cout
+   * EXAMPLES:
-    << "Usage: "sv << name << " [options] [/path/to/configuration_file] [--cmd]"sv << std::endl
+   * ```cpp
-    << "    Any configurable option can be overwritten with: \"name=value\""sv << std::endl
+   * deinit();
-    << std::endl
+   * ```
-    << "    Note: The configuration will be created if it doesn't exist."sv << std::endl
+   */
-    << std::endl
+  void
-    << "    --help                    | print help"sv << std::endl
+  deinit() {
-    << "    --creds username password | set user credentials for the Web manager"sv << std::endl
+    log_flush();
-    << "    --version                 | print the version of sunshine"sv << std::endl
+    bl::core::get()->remove_sink(sink);
-    << std::endl
+    sink.reset();
-    << "    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
+   * @brief Initialize the logging system.
-    << "        -2 | Force replacement of headers in video stream"sv << std::endl
+   * @param min_log_level The minimum log level to output.
-    << "        -p | Enable/Disable UPnP"sv << std::endl
+   * @param log_file The log file to write to.
-    << std::endl;
+   * @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<deinit_t>
+  init(int min_log_level, const std::string &log_file) {
+    if (sink) {
+      // Deinitialize the logging system before reinitializing it. This can probably only ever be hit in tests.
+      deinit();
+    }
+
+    setup_av_logging(min_log_level);
+
+    sink = boost::make_shared<text_sink>();
+
+    boost::shared_ptr<std::ostream> stream { &std::cout, boost::null_deleter() };
+    sink->locked_backend()->add_stream(stream);
+    sink->locked_backend()->add_stream(boost::make_shared<std::ofstream>(log_file));
+    sink->set_filter(severity >= min_log_level);
+
+    sink->set_formatter([](const bl::record_view &view, bl::formatting_ostream &os) {
+      constexpr const char *message = "Message";
+      constexpr const char *severity = "Severity";
+      constexpr int DATE_BUFFER_SIZE = 21 + 2 + 1;  // Full string plus ": \0"
+
+      auto log_level = view.attribute_values()[severity].extract<int>().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<std::string>();
+    });
+
+    // 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<deinit_t>();
+  }
+
+  /**
+   * @brief Setup AV logging.
+   * @param min_log_level The log level.
+   */
+  void
+  setup_av_logging(int min_log_level) {
+    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;
+      }
+    });
+  }
+
+  /**
+   * @brief Flush the log.
+   *
+   * EXAMPLES:
+   * ```cpp
+   * log_flush();
+   * ```
+   */
+  void
+  log_flush() {
+    if (sink) {
+      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

src/logging.h

@@ -10,7 +10,6 @@
 #include <boost/log/common.hpp>
 #include <boost/log/sinks.hpp>
 
-extern boost::shared_ptr<boost::log::sinks::asynchronous_sink<boost::log::sinks::text_ostream_backend>> sink;
 using text_sink = boost::log::sinks::asynchronous_sink<boost::log::sinks::text_ostream_backend>;
 
 extern boost::log::sources::severity_logger<int> verbose;
@@ -20,8 +19,20 @@ extern boost::log::sources::severity_logger<int> warning;
 extern boost::log::sources::severity_logger<int> error;
 extern boost::log::sources::severity_logger<int> fatal;
 
-// functions
+namespace logging {
-void
+  class deinit_t {
-log_flush();
+  public:
-void
+    ~deinit_t();
-print_help(const char *name);
+  };
+
+  void
+  deinit();
+  [[nodiscard]] std::unique_ptr<deinit_t>
+  init(int min_log_level, const std::string &log_file);
+  void
+  setup_av_logging(int min_log_level);
+  void
+  log_flush();
+  void
+  print_help(const char *name);
+}  // namespace logging

src/main.cpp

@@ -8,9 +8,6 @@
 #include <fstream>
 #include <iostream>
 
-// lib includes
-#include <boost/log/expressions.hpp>
-
 // local includes
 #include "confighttp.h"
 #include "entry_handler.h"
@@ -26,19 +23,10 @@
 #include "video.h"
 
 extern "C" {
-#include <libavutil/log.h>
 #include <rs.h>
 }
 
 using namespace std::literals;
-namespace bl = boost::log;
-
-struct NoDelete {
-  void
-  operator()(void *) {}
-};
-
-BOOST_LOG_ATTRIBUTE_KEYWORD(severity, "Severity", int)
 
 std::map<int, std::function<void()>> signal_handlers;
 void
@@ -118,84 +106,10 @@ main(int argc, char *argv[]) {
     return 0;
   }
 
-  if (config::sunshine.min_log_level >= 1) {
+  auto log_deinit_guard = logging::init(config::sunshine.min_log_level, config::sunshine.log_file);
-    av_log_set_level(AV_LOG_QUIET);
+  if (!log_deinit_guard) {
+    BOOST_LOG(error) << "Logging failed to initialize"sv;
   }
-  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<text_sink>();
-
-  boost::shared_ptr<std::ostream> stream { &std::cout, NoDelete {} };
-  sink->locked_backend()->add_stream(stream);
-  sink->locked_backend()->add_stream(boost::make_shared<std::ofstream>(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<int>().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<std::string>();
-  });
-
-  // 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();
+  auto platf_deinit_guard = platf::init();
-  if (!deinit_guard) {
+  if (!platf_deinit_guard) {
     BOOST_LOG(error) << "Platform failed to initialize"sv;
   }
 

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;

tests/conftest.cpp

@@ -5,16 +5,16 @@
 #include <boost/log/expressions.hpp>
 #include <boost/log/sinks/sync_frontend.hpp>
 #include <boost/log/sinks/text_ostream_backend.hpp>
-#include <boost/log/trivial.hpp>
 #include <boost/shared_ptr.hpp>
 
 #include <src/globals.h>
+#include <src/logging.h>
 #include <src/platform/common.h>
 
 #include <tests/utils.h>
 
-namespace logging = boost::log;
+namespace boost_logging = boost::log;
-namespace sinks = logging::sinks;
+namespace sinks = boost_logging::sinks;
 
 // Undefine the original TEST macro
 #undef TEST
@@ -40,6 +40,9 @@ protected:
   // we can possibly use some internal googletest functions to capture stdout and stderr, but I have not tested this
   // https://stackoverflow.com/a/33186201/11214013
 
+  // Add a member variable for deinit_guard
+  std::unique_ptr<logging::deinit_t> deinit_guard;
+
   // Add a member variable to store the sink
   boost::shared_ptr<sinks::synchronous_sink<sinks::text_ostream_backend>> test_sink;
 
@@ -79,7 +82,7 @@ protected:
     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 +90,11 @@ protected:
     // todo: do this only once
     // setup a mail object
     mail::man = std::make_shared<safe::mail_raw_t>();
+
+    deinit_guard = logging::init(0, "test.log");
+    if (!deinit_guard) {
+      FAIL() << "Logging failed to initialize";
+    }
   }
 
   void
@@ -121,7 +129,7 @@ protected:
     }
 
     // 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();
   }
 

tests/unit/test_logging.cpp

@@ -0,0 +1,75 @@
+/**
+ * @file tests/test_logging.cpp
+ * @brief Test src/logging.*.
+ */
+#include <fstream>
+
+#include <src/logging.h>
+
+#include <tests/conftest.cpp>
+
+class LoggerInitTest: public virtual BaseTest, public ::testing::WithParamInterface<int> {
+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";
+
+  // deinit the BaseTest logger
+  BaseTest::deinit_guard.reset();
+
+  auto log_deinit = logging::init(logLevel, logFilePath);
+  if (!log_deinit) {
+    FAIL() << "Failed to initialize logging";
+  }
+}
+
+TEST(LogFlushTest, CheckLogFile) {
+  // 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);
+}

tests/unit/test_video.cpp

@@ -21,10 +21,6 @@ protected:
     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