diff options
Diffstat (limited to 'src/common/logging.cpp')
| -rw-r--r-- | src/common/logging.cpp | 454 |
1 files changed, 454 insertions, 0 deletions
diff --git a/src/common/logging.cpp b/src/common/logging.cpp new file mode 100644 index 0000000000..c2f964af3e --- /dev/null +++ b/src/common/logging.cpp @@ -0,0 +1,454 @@ +// SPDX-FileCopyrightText: Copyright 2026 Eden Emulator Project +// SPDX-License-Identifier: GPL-3.0-or-later + +// SPDX-FileCopyrightText: 2014 Citra Emulator Project +// SPDX-License-Identifier: GPL-2.0-or-later + +#include <atomic> +#include <chrono> +#include <climits> +#include <cstdlib> +#include <regex> +#include <thread> + +#if defined(__ANDROID__) +#include <android/log.h> +#endif +#ifdef _WIN32 +#include <windows.h> // For OutputDebugStringW +#else +#include <fcntl.h> +#include <unistd.h> +#endif + +#include <boost/algorithm/string/replace.hpp> +#include <fmt/ranges.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/polyfill_thread.h" +#include "common/thread.h" + +#include "common/logging.h" +#include "common/settings.h" +#include "common/string_util.h" +#include "common/bounded_threadsafe_queue.h" + +namespace Common::Log { + +namespace { + +/// @brief Returns the name of the passed log class as a C-string. Subclasses are separated by periods +/// instead of underscores as in the enumeration. +/// @note GetClassName is a macro defined by Windows.h, grrr... +const char* GetLogClassName(Class log_class) { + switch (log_class) { +#define CLS(x) case Class::x: return #x; +#define SUB(x, y) case Class::x##_##y: return #x "." #y; +#include "common/log_classes.inc" +#undef CLS +#undef SUB + default: return "?"; + } +} + +/// @brief Returns the name of the passed log level as a C-string. +const char* GetLevelName(Level log_level) { + switch (log_level) { +#define LVL(x) case Level::x: return #x; + LVL(Trace) + LVL(Debug) + LVL(Info) + LVL(Warning) + LVL(Error) + LVL(Critical) +#undef LVL + default: return "?"; + } +} + +} + +// Some IDEs prefer <file>:<line> instead, so let's just do that :) +std::string FormatLogMessage(const Entry& entry) noexcept { + if (!entry.filename) return ""; + auto const time_seconds = uint32_t(entry.timestamp.count() / 1000000); + auto const time_fractional = uint32_t(entry.timestamp.count() % 1000000); + auto const class_name = GetLogClassName(entry.log_class); + auto const level_name = GetLevelName(entry.log_level); + return fmt::format("[{:4d}.{:06d}] {} <{}> {}:{}:{}: {}", time_seconds, time_fractional, class_name, level_name, entry.filename, entry.line_num, entry.function, entry.message); +} + +namespace { +template <typename It> +Level GetLevelByName(const It begin, const It end) { + for (u32 i = 0; i < u32(Level::Count); ++i) { + const char* level_name = GetLevelName(Level(i)); + if (Common::ComparePartialString(begin, end, level_name)) + return Level(i); + } + return Level::Count; +} + +template <typename It> +Class GetClassByName(const It begin, const It end) { + for (u32 i = 0; i < u32(Class::Count); ++i) { + const char* level_name = GetLogClassName(Class(i)); + if (Common::ComparePartialString(begin, end, level_name)) + return Class(i); + } + return Class::Count; +} + +template <typename Iterator> +bool ParseFilterRule(Filter& instance, Iterator begin, Iterator end) { + auto level_separator = std::find(begin, end, ':'); + if (level_separator == end) { + LOG_ERROR(Log, "Invalid log filter. Must specify a log level after `:`: {}", std::string(begin, end)); + return false; + } + const Level level = GetLevelByName(level_separator + 1, end); + if (level == Level::Count) { + LOG_ERROR(Log, "Unknown log level in filter: {}", std::string(begin, end)); + return false; + } + if (Common::ComparePartialString(begin, level_separator, "*")) { + instance.class_levels.fill(level); + return true; + } + const Class log_class = GetClassByName(begin, level_separator); + if (log_class == Class::Count) { + LOG_ERROR(Log, "Unknown log class in filter: {}", std::string(begin, end)); + return false; + } + instance.SetClassLevel(log_class, level); + return true; +} +} // Anonymous namespace + +void Filter::ParseFilterString(std::string_view filter_view) { + auto clause_begin = filter_view.cbegin(); + while (clause_begin != filter_view.cend()) { + auto clause_end = std::find(clause_begin, filter_view.cend(), ' '); + // If clause isn't empty + if (clause_end != clause_begin) { + ParseFilterRule(*this, clause_begin, clause_end); + } + if (clause_end != filter_view.cend()) { + // Skip over the whitespace + ++clause_end; + } + clause_begin = clause_end; + } +} + +namespace { + +/// @brief Trims up to and including the last of ../, ..\, src/, src\ in a string +/// do not be fooled this isn't generating new strings on .rodata :) +constexpr const char* TrimSourcePath(std::string_view source) noexcept { + const auto rfind = [source](const std::string_view match) { + return source.rfind(match) == source.npos ? 0 : (source.rfind(match) + match.size()); + }; + auto idx = (std::max)({rfind("src/"), rfind("src\\"), rfind("../"), rfind("..\\")}); + return source.data() + idx; +} + +/// @brief Interface for logging backends. +struct Backend { + virtual ~Backend() noexcept = default; + virtual void Write(const Entry& entry) noexcept = 0; + virtual void Flush() noexcept = 0; +}; + +/// @brief Formatting specifier (to use with printf) of the equivalent fmt::format() expression +#define CCB_PRINTF_FMT "[%4d.%06d] %s <%s> %s:%u:%s: %s" + +/// @brief Instead of using fmt::format() just use the system's formatting capabilities directly +struct DirectFormatArgs { + const char *class_name; + const char *level_name; + uint32_t time_seconds; + uint32_t time_fractional; +}; +[[nodiscard]] inline DirectFormatArgs GetDirectFormatArgs(Entry const& entry) noexcept { + return { + .class_name = GetLogClassName(entry.log_class), + .level_name = GetLevelName(entry.log_level), + .time_seconds = uint32_t(entry.timestamp.count() / 1000000), + .time_fractional = uint32_t(entry.timestamp.count() % 1000000), + }; +} + +/// @brief Backend that writes to stdout and with color +struct ColorConsoleBackend final : public Backend { +#ifdef _WIN32 + explicit ColorConsoleBackend() noexcept { + console_handle = GetStdHandle(STD_ERROR_HANDLE); + GetConsoleScreenBufferInfo(console_handle, &original_info); + } + ~ColorConsoleBackend() noexcept override { + SetConsoleTextAttribute(console_handle, original_info.wAttributes); + } + void Write(const Entry& entry) noexcept override { + if (enabled && console_handle != INVALID_HANDLE_VALUE) { + WORD color = WORD([&entry]() { + switch (entry.log_level) { + case Level::Debug: return FOREGROUND_GREEN | FOREGROUND_BLUE; // Cyan + case Level::Info: return FOREGROUND_RED | FOREGROUND_GREEN | FOREGROUND_BLUE; // Bright gray + case Level::Warning: return FOREGROUND_RED | FOREGROUND_GREEN | FOREGROUND_INTENSITY; + case Level::Error: return FOREGROUND_RED | FOREGROUND_INTENSITY; + case Level::Critical: return FOREGROUND_RED | FOREGROUND_BLUE | FOREGROUND_INTENSITY; + default: break; + } + return FOREGROUND_INTENSITY; // Grey + }()); + SetConsoleTextAttribute(console_handle, color); + auto const df = GetDirectFormatArgs(entry); + std::fprintf(stdout, CCB_PRINTF_FMT "\n", df.time_seconds, df.time_fractional, df.class_name, df.level_name, entry.filename, entry.line_num, entry.function, entry.message.c_str()); + } + } + void Flush() noexcept override {} + CONSOLE_SCREEN_BUFFER_INFO original_info = {}; + HANDLE console_handle = INVALID_HANDLE_VALUE; + std::atomic_bool enabled = false; +#else // ^^^ Windows vvv POSIX + explicit ColorConsoleBackend() noexcept {} + ~ColorConsoleBackend() noexcept override {} + void Write(const Entry& entry) noexcept override { + if (enabled) { +#define ESC "\x1b" + auto const color_str = [&entry]() -> const char* { + switch (entry.log_level) { +#define CCB_MAKE_COLOR_FMT(X) ESC X CCB_PRINTF_FMT ESC "[0m\n" + case Level::Debug: return CCB_MAKE_COLOR_FMT("[0;36m"); // Cyan + case Level::Info: return CCB_MAKE_COLOR_FMT("[0;37m"); // Bright gray + case Level::Warning: return CCB_MAKE_COLOR_FMT("[1;33m"); // Bright yellow + case Level::Error: return CCB_MAKE_COLOR_FMT("[1;31m"); // Bright red + case Level::Critical: return CCB_MAKE_COLOR_FMT("[1;35m"); // Bright magenta + default: return CCB_MAKE_COLOR_FMT("[1;30m"); // Grey +#undef CCB_MAKE_COLOR_FMT + } + }(); + auto const df = GetDirectFormatArgs(entry); + std::fprintf(stdout, color_str, df.time_seconds, df.time_fractional, df.class_name, df.level_name, entry.filename, entry.line_num, entry.function, entry.message.c_str()); +#undef ESC + } + } + void Flush() noexcept override {} + std::atomic_bool enabled = false; +#endif +}; + +#ifndef __OPENORBIS__ +/// @brief Backend that writes to a file passed into the constructor +struct FileBackend final : public Backend { + explicit FileBackend(const std::filesystem::path& filename) noexcept { + 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. + void(FS::RemoveFile(old_filename)); + void(FS::RenameFile(filename, old_filename)); + file.emplace(filename, FS::FileAccessMode::Write, FS::FileType::TextFile); + } + ~FileBackend() noexcept override = default; + + void Write(const Entry& entry) noexcept override { + if (!enabled) + return; + + auto message = FormatLogMessage(entry).append(1, '\n'); +#ifndef __ANDROID__ + if (Settings::values.censor_username.GetValue()) { + // This must be a static otherwise it would get checked on EVERY + // instance of logging an entry... + static std::string username = []() -> std::string { + // in order of precedence + // LOGNAME usually works on UNIX, USERNAME on Windows + // Some UNIX systems suck and don't use LOGNAME so we also + // need USER :( + for (auto const var : { "LOGNAME", "USERNAME", "USER", }) + if (auto const s = ::getenv(var); s != nullptr) + return std::string{s}; + return std::string{}; + }(); + if (!username.empty()) + boost::replace_all(message, username, "user"); + } +#endif + bytes_written += file->WriteString(message); + + // Option to log each line rather than 4k buffers + if (Settings::values.log_flush_line.GetValue()) + file->Flush(); + + 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.GetValue() ? 1_GiB : 100_MiB; + const bool write_limit_exceeded = bytes_written > write_limit; + if (entry.log_level >= Level::Error || write_limit_exceeded) { + // Stop writing after the write limit is exceeded. + // Don't close the file so we can print a stacktrace if necessary + if (write_limit_exceeded) + enabled = false; + file->Flush(); + } + } + + void Flush() noexcept override { + file->Flush(); + } +private: + std::optional<FS::IOFile> file; + std::size_t bytes_written = 0; + bool enabled = true; +}; +#endif + +#ifdef _WIN32 +/// @brief Backend that writes to Visual Studio's output window +struct DebuggerBackend final : public Backend { + explicit DebuggerBackend() noexcept = default; + ~DebuggerBackend() noexcept override = default; + void Write(const Entry& entry) noexcept override { + ::OutputDebugStringW(UTF8ToUTF16W(FormatLogMessage(entry).append(1, '\n')).c_str()); + } + void Flush() noexcept override {} +}; +#endif +#ifdef ANDROID +/// @brief Backend that writes to the Android logcat +struct LogcatBackend : public Backend { + explicit LogcatBackend() noexcept = default; + ~LogcatBackend() noexcept override = default; + void Write(const Entry& entry) noexcept override { + android_LogPriority android_log_priority = [&]() { + switch (entry.log_level) { + case Level::Debug: return ANDROID_LOG_DEBUG; + case Level::Info: return ANDROID_LOG_INFO; + case Level::Warning: return ANDROID_LOG_WARN; + case Level::Error: return ANDROID_LOG_ERROR; + case Level::Critical: return ANDROID_LOG_FATAL; + case Level::Count: + case Level::Trace: return ANDROID_LOG_VERBOSE; + } + }(); + auto const df = GetDirectFormatArgs(entry); + __android_log_print(android_log_priority, "YuzuNative", CCB_PRINTF_FMT, df.time_seconds, df.time_fractional, df.class_name, df.level_name, entry.filename, entry.line_num, entry.function, entry.message.c_str()); + } + void Flush() noexcept override {} +}; +#endif + +/// @brief Static state as a singleton. +struct Impl { + // Well, I mean it's the default constructor! + explicit Impl() noexcept : filter(Level::Trace) {} + + void StartBackendThread() noexcept { + backend_thread = std::jthread([this](std::stop_token stop_token) { + Common::SetCurrentThreadName("Logger"); + Entry entry; + const auto write_logs = [this, &entry]() { + ForEachBackend([&entry](Backend& backend) { + backend.Write(entry); + }); + }; + do { + message_queue.PopWait(entry, stop_token); + write_logs(); + } while (!stop_token.stop_requested()); + // 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.TryPop(entry)) + write_logs(); + }); + } + + void StopBackendThread() noexcept { + backend_thread.request_stop(); + if (backend_thread.joinable()) + backend_thread.join(); + ForEachBackend([](Backend& backend) { backend.Flush(); }); + } + + void ForEachBackend(auto lambda) noexcept { + lambda(static_cast<Backend&>(color_console_backend)); +#ifndef __OPENORBIS__ + if (file_backend) + lambda(static_cast<Backend&>(*file_backend)); +#endif +#ifdef _WIN32 + lambda(static_cast<Backend&>(debugger_backend)); +#endif +#ifdef ANDROID + lambda(static_cast<Backend&>(lc_backend)); +#endif + } + + Filter filter; + ColorConsoleBackend color_console_backend{}; +#ifndef __OPENORBIS__ + std::optional<FileBackend> file_backend; +#endif +#ifdef _WIN32 + DebuggerBackend debugger_backend{}; +#endif +#ifdef ANDROID + LogcatBackend lc_backend{}; +#endif + MPSCQueue<Entry> message_queue{}; + std::chrono::steady_clock::time_point time_origin{std::chrono::steady_clock::now()}; + std::jthread backend_thread; +}; +} // namespace + +// Constructor shall NOT depend upon Settings() or whatever +// it's ran at global static ctor() time... so BE CAREFUL MFER! +static Common::Log::Impl logging_instance{}; + +void Initialize() { + logging_instance.filter.ParseFilterString(Settings::values.log_filter.GetValue()); +#ifndef __OPENORBIS__ + using namespace Common::FS; + const auto& log_dir = GetEdenPath(EdenPath::LogDir); + void(CreateDir(log_dir)); + logging_instance.file_backend.emplace(log_dir / LOG_FILE); +#endif +} + +void Start() { + logging_instance.StartBackendThread(); +} + +void Stop() { + logging_instance.StopBackendThread(); +} + +void SetGlobalFilter(const Filter& filter) { + logging_instance.filter = filter; +} + +void SetColorConsoleBackendEnabled(bool enabled) { + logging_instance.color_console_backend.enabled = enabled; +} + +void FmtLogMessageImpl(Class log_class, Level log_level, const char* filename, unsigned int line_num, const char* function, fmt::string_view format, const fmt::format_args& args) { + if (logging_instance.filter.CheckMessage(log_class, log_level)) { + logging_instance.message_queue.EmplaceWait(Entry{ + .message = fmt::vformat(format, args), + .timestamp = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now() - logging_instance.time_origin), + .log_class = log_class, + .log_level = log_level, + .filename = TrimSourcePath(filename), + .function = function, + .line_num = line_num, + }); + } +} +} // namespace Common::Log |
