Merge pull request #6869 from yzct12345/shiny-logs-in-the-fireplace

logging: Simplify and make thread-safe

src/common/logging/backend.cpp

@@ -2,13 +2,9 @@
 // Licensed under GPLv2 or any later version
 // Refer to the license.txt file included.
 
-#include <algorithm>
 #include <atomic>
 #include <chrono>
 #include <climits>
-#include <condition_variable>
-#include <memory>
-#include <mutex>
 #include <thread>
 #include <vector>
 
@@ -16,104 +12,229 @@
 #include <windows.h> // For OutputDebugStringW
 #endif
 
-#include "common/assert.h"
 #include "common/fs/file.h"
 #include "common/fs/fs.h"
+#include "common/fs/fs_paths.h"
+#include "common/fs/path_util.h"
 #include "common/literals.h"
 
 #include "common/logging/backend.h"
 #include "common/logging/log.h"
 #include "common/logging/text_formatter.h"
 #include "common/settings.h"
+#ifdef _WIN32
 #include "common/string_util.h"
+#endif
 #include "common/threadsafe_queue.h"
 
 namespace Common::Log {
 
+namespace {
+
 /**
- * Static state as a singleton.
+ * Interface for logging backends.
  */
-class Impl {
+class Backend {
 public:
-    static Impl& Instance() {
-        static Impl backend;
-        return backend;
+    virtual ~Backend() = default;
+
+    virtual void Write(const Entry& entry) = 0;
+
+    virtual void EnableForStacktrace() = 0;
+
+    virtual void Flush() = 0;
+};
+
+/**
+ * Backend that writes to stderr and with color
+ */
+class ColorConsoleBackend final : public Backend {
+public:
+    explicit ColorConsoleBackend() = default;
+
+    ~ColorConsoleBackend() override = default;
+
+    void Write(const Entry& entry) override {
+        if (enabled.load(std::memory_order_relaxed)) {
+            PrintColoredMessage(entry);
+        }
     }
 
-    Impl(const Impl&) = delete;
-    Impl& operator=(const Impl&) = delete;
+    void Flush() override {
+        // stderr shouldn't be buffered
+    }
 
-    Impl(Impl&&) = delete;
-    Impl& operator=(Impl&&) = delete;
+    void EnableForStacktrace() override {
+        enabled = true;
+    }
 
-    void PushEntry(Class log_class, Level log_level, const char* filename, unsigned int line_num,
-                   const char* function, std::string message) {
-        message_queue.Push(
-            CreateEntry(log_class, log_level, filename, line_num, function, std::move(message)));
+    void SetEnabled(bool enabled_) {
+        enabled = enabled_;
+    }
+
+private:
+    std::atomic_bool enabled{false};
+};
+
+/**
+ * Backend that writes to a file passed into the constructor
+ */
+class FileBackend final : public Backend {
+public:
+    explicit FileBackend(const std::filesystem::path& filename) {
+        auto old_filename = filename;
+        old_filename += ".old.txt";
+
+        // Existence checks are done within the functions themselves.
+        // We don't particularly care if these succeed or not.
+        static_cast<void>(FS::RemoveFile(old_filename));
+        static_cast<void>(FS::RenameFile(filename, old_filename));
+
+        file = std::make_unique<FS::IOFile>(filename, FS::FileAccessMode::Write,
+                                            FS::FileType::TextFile);
+    }
+
+    ~FileBackend() override = default;
+
+    void Write(const Entry& entry) override {
+        if (!enabled) {
+            return;
+        }
+
+        bytes_written += file->WriteString(FormatLogMessage(entry).append(1, '\n'));
+
+        using namespace Common::Literals;
+        // Prevent logs from exceeding a set maximum size in the event that log entries are spammed.
+        const auto write_limit = Settings::values.extended_logging ? 1_GiB : 100_MiB;
+        const bool write_limit_exceeded = bytes_written > write_limit;
+        if (entry.log_level >= Level::Error || write_limit_exceeded) {
+            if (write_limit_exceeded) {
+                // Stop writing after the write limit is exceeded.
+                // Don't close the file so we can print a stacktrace if necessary
+                enabled = false;
+            }
+            file->Flush();
+        }
+    }
+
+    void Flush() override {
+        file->Flush();
+    }
+
+    void EnableForStacktrace() override {
+        enabled = true;
+        bytes_written = 0;
     }
 
-    void AddBackend(std::unique_ptr<Backend> backend) {
-        std::lock_guard lock{writing_mutex};
-        backends.push_back(std::move(backend));
+private:
+    std::unique_ptr<FS::IOFile> file;
+    bool enabled = true;
+    std::size_t bytes_written = 0;
+};
+
+/**
+ * Backend that writes to Visual Studio's output window
+ */
+class DebuggerBackend final : public Backend {
+public:
+    explicit DebuggerBackend() = default;
+
+    ~DebuggerBackend() override = default;
+
+    void Write(const Entry& entry) override {
+#ifdef _WIN32
+        ::OutputDebugStringW(UTF8ToUTF16W(FormatLogMessage(entry).append(1, '\n')).c_str());
+#endif
     }
 
-    void RemoveBackend(std::string_view backend_name) {
-        std::lock_guard lock{writing_mutex};
+    void Flush() override {}
+
+    void EnableForStacktrace() override {}
+};
+
+bool initialization_in_progress_suppress_logging = false;
 
-        std::erase_if(backends, [&backend_name](const auto& backend) {
-            return backend_name == backend->GetName();
-        });
+/**
+ * Static state as a singleton.
+ */
+class Impl {
+public:
+    static Impl& Instance() {
+        if (!instance) {
+            abort();
+        }
+        return *instance;
     }
 
-    const Filter& GetGlobalFilter() const {
-        return filter;
+    static void Initialize() {
+        if (instance) {
+            abort();
+        }
+        using namespace Common::FS;
+        initialization_in_progress_suppress_logging = true;
+        const auto& log_dir = GetYuzuPath(YuzuPath::LogDir);
+        void(CreateDir(log_dir));
+        Filter filter;
+        filter.ParseFilterString(Settings::values.log_filter.GetValue());
+        instance = std::unique_ptr<Impl, decltype(&Deleter)>(new Impl(log_dir / LOG_FILE, filter),
+                                                             Deleter);
+        initialization_in_progress_suppress_logging = false;
     }
 
+    Impl(const Impl&) = delete;
+    Impl& operator=(const Impl&) = delete;
+
+    Impl(Impl&&) = delete;
+    Impl& operator=(Impl&&) = delete;
+
     void SetGlobalFilter(const Filter& f) {
         filter = f;
     }
 
-    Backend* GetBackend(std::string_view backend_name) {
-        const auto it =
-            std::find_if(backends.begin(), backends.end(),
-                         [&backend_name](const auto& i) { return backend_name == i->GetName(); });
-        if (it == backends.end())
-            return nullptr;
-        return it->get();
+    void SetColorConsoleBackendEnabled(bool enabled) {
+        color_console_backend.SetEnabled(enabled);
+    }
+
+    void PushEntry(Class log_class, Level log_level, const char* filename, unsigned int line_num,
+                   const char* function, std::string message) {
+        if (!filter.CheckMessage(log_class, log_level))
+            return;
+        const Entry& entry =
+            CreateEntry(log_class, log_level, filename, line_num, function, std::move(message));
+        message_queue.Push(entry);
     }
 
 private:
-    Impl() {
-        backend_thread = std::thread([&] {
-            Entry entry;
-            auto write_logs = [&](Entry& e) {
-                std::lock_guard lock{writing_mutex};
-                for (const auto& backend : backends) {
-                    backend->Write(e);
-                }
-            };
-            while (true) {
-                entry = message_queue.PopWait();
-                if (entry.final_entry) {
-                    break;
-                }
-                write_logs(entry);
-            }
+    Impl(const std::filesystem::path& file_backend_filename, const Filter& filter_)
+        : filter{filter_}, file_backend{file_backend_filename}, backend_thread{std::thread([this] {
+              Common::SetCurrentThreadName("yuzu:Log");
+              Entry entry;
+              const auto write_logs = [this, &entry]() {
+                  ForEachBackend([&entry](Backend& backend) { backend.Write(entry); });
+              };
+              while (true) {
+                  entry = message_queue.PopWait();
+                  if (entry.final_entry) {
+                      break;
+                  }
+                  write_logs();
+              }
+              // Drain the logging queue. Only writes out up to MAX_LOGS_TO_WRITE to prevent a
+              // case where a system is repeatedly spamming logs even on close.
+              int max_logs_to_write = filter.IsDebug() ? INT_MAX : 100;
+              while (max_logs_to_write-- && message_queue.Pop(entry)) {
+                  write_logs();
+              }
+          })} {}
 
-            // Drain the logging queue. Only writes out up to MAX_LOGS_TO_WRITE to prevent a
-            // case where a system is repeatedly spamming logs even on close.
-            const int MAX_LOGS_TO_WRITE = filter.IsDebug() ? INT_MAX : 100;
-            int logs_written = 0;
-            while (logs_written++ < MAX_LOGS_TO_WRITE && message_queue.Pop(entry)) {
-                write_logs(entry);
-            }
-        });
+    ~Impl() {
+        StopBackendThread();
     }
 
-    ~Impl() {
-        Entry entry;
-        entry.final_entry = true;
-        message_queue.Push(entry);
+    void StopBackendThread() {
+        Entry stop_entry{};
+        stop_entry.final_entry = true;
+        message_queue.Push(stop_entry);
         backend_thread.join();
     }
 
@@ -135,100 +256,51 @@ private:
         };
     }
 
-    std::mutex writing_mutex;
-    std::thread backend_thread;
-    std::vector<std::unique_ptr<Backend>> backends;
-    MPSCQueue<Entry> message_queue;
-    Filter filter;
-    std::chrono::steady_clock::time_point time_origin{std::chrono::steady_clock::now()};
-};
-
-ConsoleBackend::~ConsoleBackend() = default;
-
-void ConsoleBackend::Write(const Entry& entry) {
-    PrintMessage(entry);
-}
-
-ColorConsoleBackend::~ColorConsoleBackend() = default;
-
-void ColorConsoleBackend::Write(const Entry& entry) {
-    PrintColoredMessage(entry);
-}
-
-FileBackend::FileBackend(const std::filesystem::path& filename) {
-    auto old_filename = filename;
-    old_filename += ".old.txt";
-
-    // Existence checks are done within the functions themselves.
-    // We don't particularly care if these succeed or not.
-    FS::RemoveFile(old_filename);
-    void(FS::RenameFile(filename, old_filename));
-
-    file =
-        std::make_unique<FS::IOFile>(filename, FS::FileAccessMode::Write, FS::FileType::TextFile);
-}
-
-FileBackend::~FileBackend() = default;
+    void ForEachBackend(auto lambda) {
+        lambda(static_cast<Backend&>(debugger_backend));
+        lambda(static_cast<Backend&>(color_console_backend));
+        lambda(static_cast<Backend&>(file_backend));
+    }
 
-void FileBackend::Write(const Entry& entry) {
-    if (!file->IsOpen()) {
-        return;
+    static void Deleter(Impl* ptr) {
+        delete ptr;
     }
 
-    using namespace Common::Literals;
-    // Prevent logs from exceeding a set maximum size in the event that log entries are spammed.
-    constexpr std::size_t MAX_BYTES_WRITTEN = 100_MiB;
-    constexpr std::size_t MAX_BYTES_WRITTEN_EXTENDED = 1_GiB;
+    static inline std::unique_ptr<Impl, decltype(&Deleter)> instance{nullptr, Deleter};
 
-    const bool write_limit_exceeded =
-        bytes_written > MAX_BYTES_WRITTEN_EXTENDED ||
-        (bytes_written > MAX_BYTES_WRITTEN && !Settings::values.extended_logging);
+    Filter filter;
+    DebuggerBackend debugger_backend{};
+    ColorConsoleBackend color_console_backend{};
+    FileBackend file_backend;
 
-    // Close the file after the write limit is exceeded.
-    if (write_limit_exceeded) {
-        file->Close();
-        return;
-    }
+    std::thread backend_thread;
+    MPSCQueue<Entry> message_queue{};
+    std::chrono::steady_clock::time_point time_origin{std::chrono::steady_clock::now()};
+};
+} // namespace
 
-    bytes_written += file->WriteString(FormatLogMessage(entry).append(1, '\n'));
-    if (entry.log_level >= Level::Error) {
-        file->Flush();
-    }
+void Initialize() {
+    Impl::Initialize();
 }
 
-DebuggerBackend::~DebuggerBackend() = default;
-
-void DebuggerBackend::Write(const Entry& entry) {
-#ifdef _WIN32
-    ::OutputDebugStringW(UTF8ToUTF16W(FormatLogMessage(entry).append(1, '\n')).c_str());
-#endif
+void DisableLoggingInTests() {
+    initialization_in_progress_suppress_logging = true;
 }
 
 void SetGlobalFilter(const Filter& filter) {
     Impl::Instance().SetGlobalFilter(filter);
 }
 
-void AddBackend(std::unique_ptr<Backend> backend) {
-    Impl::Instance().AddBackend(std::move(backend));
-}
-
-void RemoveBackend(std::string_view backend_name) {
-    Impl::Instance().RemoveBackend(backend_name);
-}
-
-Backend* GetBackend(std::string_view backend_name) {
-    return Impl::Instance().GetBackend(backend_name);
+void SetColorConsoleBackendEnabled(bool enabled) {
+    Impl::Instance().SetColorConsoleBackendEnabled(enabled);
 }
 
 void FmtLogMessageImpl(Class log_class, Level log_level, const char* filename,
                        unsigned int line_num, const char* function, const char* format,
                        const fmt::format_args& args) {
-    auto& instance = Impl::Instance();
-    const auto& filter = instance.GetGlobalFilter();
-    if (!filter.CheckMessage(log_class, log_level))
-        return;
-
-    instance.PushEntry(log_class, log_level, filename, line_num, function,
-                       fmt::vformat(format, args));
+    if (!initialization_in_progress_suppress_logging) {
+        Impl::Instance().PushEntry(log_class, log_level, filename, line_num, function,
+                                   fmt::vformat(format, args));
+    }
 }
 } // namespace Common::Log

src/common/logging/backend.h

@@ -5,120 +5,21 @@
 #pragma once
 
 #include <filesystem>
-#include <memory>
-#include <string>
-#include <string_view>
 #include "common/logging/filter.h"
-#include "common/logging/log.h"
-
-namespace Common::FS {
-class IOFile;
-}
 
 namespace Common::Log {
 
 class Filter;
 
-/**
- * Interface for logging backends. As loggers can be created and removed at runtime, this can be
- * used by a frontend for adding a custom logging backend as needed
- */
-class Backend {
-public:
-    virtual ~Backend() = default;
-
-    virtual void SetFilter(const Filter& new_filter) {
-        filter = new_filter;
-    }
-    virtual const char* GetName() const = 0;
-    virtual void Write(const Entry& entry) = 0;
-
-private:
-    Filter filter;
-};
-
-/**
- * Backend that writes to stderr without any color commands
- */
-class ConsoleBackend : public Backend {
-public:
-    ~ConsoleBackend() override;
-
-    static const char* Name() {
-        return "console";
-    }
-    const char* GetName() const override {
-        return Name();
-    }
-    void Write(const Entry& entry) override;
-};
-
-/**
- * Backend that writes to stderr and with color
- */
-class ColorConsoleBackend : public Backend {
-public:
-    ~ColorConsoleBackend() override;
-
-    static const char* Name() {
-        return "color_console";
-    }
-
-    const char* GetName() const override {
-        return Name();
-    }
-    void Write(const Entry& entry) override;
-};
+/// Initializes the logging system. This should be the first thing called in main.
+void Initialize();
 
-/**
- * Backend that writes to a file passed into the constructor
- */
-class FileBackend : public Backend {
-public:
-    explicit FileBackend(const std::filesystem::path& filename);
-    ~FileBackend() override;
-
-    static const char* Name() {
-        return "file";
-    }
-
-    const char* GetName() const override {
-        return Name();
-    }
-
-    void Write(const Entry& entry) override;
-
-private:
-    std::unique_ptr<FS::IOFile> file;
-    std::size_t bytes_written = 0;
-};
-
-/**
- * Backend that writes to Visual Studio's output window
- */
-class DebuggerBackend : public Backend {
-public:
-    ~DebuggerBackend() override;
-
-    static const char* Name() {
-        return "debugger";
-    }
-    const char* GetName() const override {
-        return Name();
-    }
-    void Write(const Entry& entry) override;
-};
-
-void AddBackend(std::unique_ptr<Backend> backend);
-
-void RemoveBackend(std::string_view backend_name);
-
-Backend* GetBackend(std::string_view backend_name);
+void DisableLoggingInTests();
 
 /**
- * The global filter will prevent any messages from even being processed if they are filtered. Each
- * backend can have a filter, but if the level is lower than the global filter, the backend will
- * never get the message
+ * The global filter will prevent any messages from even being processed if they are filtered.
  */
 void SetGlobalFilter(const Filter& filter);
-} // namespace Common::Log
+
+void SetColorConsoleBackendEnabled(bool enabled);
+} // namespace Common::Log

src/core/core.cpp

@@ -84,8 +84,6 @@ FileSys::StorageId GetStorageIdForFrontendSlot(
 
 } // Anonymous namespace
 
-/*static*/ System System::s_instance;
-
 FileSys::VirtualFile GetGameFileFromPath(const FileSys::VirtualFilesystem& vfs,
                                          const std::string& path) {
     // To account for split 00+01+etc files.
@@ -425,6 +423,13 @@ struct System::Impl {
 System::System() : impl{std::make_unique<Impl>(*this)} {}
 System::~System() = default;
 
+void System::InitializeGlobalInstance() {
+    if (s_instance) {
+        abort();
+    }
+    s_instance = std::unique_ptr<System>(new System);
+}
+
 CpuManager& System::GetCpuManager() {
     return impl->cpu_manager;
 }

src/core/core.h

@@ -121,9 +121,14 @@ public:
      * @returns Reference to the instance of the System singleton class.
      */
     [[deprecated("Use of the global system instance is deprecated")]] static System& GetInstance() {
-        return s_instance;
+        if (!s_instance) {
+            abort();
+        }
+        return *s_instance;
     }
 
+    static void InitializeGlobalInstance();
+
     /// Enumeration representing the return values of the System Initialize and Load process.
     enum class ResultStatus : u32 {
         Success,             ///< Succeeded
@@ -393,7 +398,7 @@ private:
     struct Impl;
     std::unique_ptr<Impl> impl;
 
-    static System s_instance;
+    inline static std::unique_ptr<System> s_instance{};
 };
 
 } // namespace Core

src/tests/common/param_package.cpp

@@ -4,11 +4,13 @@
 
 #include <catch2/catch.hpp>
 #include <math.h>
+#include "common/logging/backend.h"
 #include "common/param_package.h"
 
 namespace Common {
 
 TEST_CASE("ParamPackage", "[common]") {
+    Common::Log::DisableLoggingInTests();
     ParamPackage original{
         {"abc", "xyz"},
         {"def", "42"},

src/yuzu/debugger/console.cpp

@@ -21,6 +21,7 @@ void ToggleConsole() {
         console_shown = UISettings::values.show_console.GetValue();
     }
 
+    using namespace Common::Log;
 #if defined(_WIN32) && !defined(_DEBUG)
     FILE* temp;
     if (UISettings::values.show_console) {
@@ -29,24 +30,20 @@ void ToggleConsole() {
             freopen_s(&temp, "CONIN$", "r", stdin);
             freopen_s(&temp, "CONOUT$", "w", stdout);
             freopen_s(&temp, "CONOUT$", "w", stderr);
-            Common::Log::AddBackend(std::make_unique<Common::Log::ColorConsoleBackend>());
+            SetColorConsoleBackendEnabled(true);
         }
     } else {
         if (FreeConsole()) {
             // In order to close the console, we have to also detach the streams on it.
             // Just redirect them to NUL if there is no console window
-            Common::Log::RemoveBackend(Common::Log::ColorConsoleBackend::Name());
+            SetColorConsoleBackendEnabled(false);
             freopen_s(&temp, "NUL", "r", stdin);
             freopen_s(&temp, "NUL", "w", stdout);
             freopen_s(&temp, "NUL", "w", stderr);
         }
     }
 #else
-    if (UISettings::values.show_console) {
-        Common::Log::AddBackend(std::make_unique<Common::Log::ColorConsoleBackend>());
-    } else {
-        Common::Log::RemoveBackend(Common::Log::ColorConsoleBackend::Name());
-    }
+    SetColorConsoleBackendEnabled(UISettings::values.show_console.GetValue());
 #endif
 }
 } // namespace Debugger

src/yuzu/main.cpp

@@ -175,21 +175,6 @@ void GMainWindow::ShowTelemetryCallout() {
 
 const int GMainWindow::max_recent_files_item;
 
-static void InitializeLogging() {
-    using namespace Common;
-
-    Log::Filter log_filter;
-    log_filter.ParseFilterString(Settings::values.log_filter.GetValue());
-    Log::SetGlobalFilter(log_filter);
-
-    const auto log_dir = FS::GetYuzuPath(FS::YuzuPath::LogDir);
-    void(FS::CreateDir(log_dir));
-    Log::AddBackend(std::make_unique<Log::FileBackend>(log_dir / LOG_FILE));
-#ifdef _WIN32
-    Log::AddBackend(std::make_unique<Log::DebuggerBackend>());
-#endif
-}
-
 static void RemoveCachedContents() {
     const auto cache_dir = Common::FS::GetYuzuPath(Common::FS::YuzuPath::CacheDir);
     const auto offline_fonts = cache_dir / "fonts";
@@ -207,8 +192,6 @@ GMainWindow::GMainWindow()
     : input_subsystem{std::make_shared<InputCommon::InputSubsystem>()},
       config{std::make_unique<Config>()}, vfs{std::make_shared<FileSys::RealVfsFilesystem>()},
       provider{std::make_unique<FileSys::ManualContentProvider>()} {
-    InitializeLogging();
-
     LoadTranslation();
 
     setAcceptDrops(true);
@@ -3398,6 +3381,7 @@ void GMainWindow::SetDiscordEnabled([[maybe_unused]] bool state) {
 #endif
 
 int main(int argc, char* argv[]) {
+    Common::Log::Initialize();
     Common::DetachedTasks detached_tasks;
     MicroProfileOnThreadCreate("Frontend");
     SCOPE_EXIT({ MicroProfileShutdown(); });
@@ -3437,6 +3421,7 @@ int main(int argc, char* argv[]) {
     // generating shaders
     setlocale(LC_ALL, "C");
 
+    Core::System::InitializeGlobalInstance();
     GMainWindow main_window;
     // After settings have been loaded by GMainWindow, apply the filter
     main_window.show();

src/yuzu_cmd/yuzu.cpp

@@ -74,31 +74,14 @@ static void PrintVersion() {
     std::cout << "yuzu " << Common::g_scm_branch << " " << Common::g_scm_desc << std::endl;
 }
 
-static void InitializeLogging() {
-    using namespace Common;
-
-    Log::Filter log_filter(Log::Level::Debug);
-    log_filter.ParseFilterString(static_cast<std::string>(Settings::values.log_filter));
-    Log::SetGlobalFilter(log_filter);
-
-    Log::AddBackend(std::make_unique<Log::ColorConsoleBackend>());
-
-    const auto& log_dir = FS::GetYuzuPath(FS::YuzuPath::LogDir);
-    void(FS::CreateDir(log_dir));
-    Log::AddBackend(std::make_unique<Log::FileBackend>(log_dir / LOG_FILE));
-#ifdef _WIN32
-    Log::AddBackend(std::make_unique<Log::DebuggerBackend>());
-#endif
-}
-
 /// Application entry point
 int main(int argc, char** argv) {
+    Common::Log::Initialize();
+    Common::Log::SetColorConsoleBackendEnabled(true);
     Common::DetachedTasks detached_tasks;
     Config config;
 
     int option_index = 0;
-
-    InitializeLogging();
 #ifdef _WIN32
     int argc_w;
     auto argv_w = CommandLineToArgvW(GetCommandLineW(), &argc_w);
@@ -163,6 +146,7 @@ int main(int argc, char** argv) {
         return -1;
     }
 
+    Core::System::InitializeGlobalInstance();
     auto& system{Core::System::GetInstance()};
     InputCommon::InputSubsystem input_subsystem;