// SPDX-FileCopyrightText: 2002-2024 PCSX2 Dev Team // SPDX-License-Identifier: GPL-3.0+ #include "common/Console.h" #include "common/Assertions.h" #include "common/FileSystem.h" #include "common/SmallString.h" #include "common/Timer.h" #include "fmt/format.h" #include #include #ifdef _WIN32 #include "common/RedtapeWindows.h" #else #include #endif using namespace std::string_view_literals; // Dummy objects, need to get rid of them... ConsoleLogWriter Console; ConsoleLogWriter DevCon; #ifdef _DEBUG ConsoleLogWriter DbgConWriter; #else NullLogWriter DbgConWriter; #endif #define TIMESTAMP_FORMAT_STRING "[{:10.4f}] " #define TIMESTAMP_PRINTF_STRING "[%10.4f] " namespace Log { static void WriteToConsole(LOGLEVEL level, ConsoleColors color, std::string_view message); static void WriteToDebug(LOGLEVEL level, ConsoleColors color, std::string_view message); static void WriteToFile(LOGLEVEL level, ConsoleColors color, std::string_view message); static void UpdateMaxLevel(); static void ExecuteCallbacks(LOGLEVEL level, ConsoleColors color, std::string_view message); static Common::Timer::Value s_start_timestamp = Common::Timer::GetCurrentValue(); static LOGLEVEL s_max_level = LOGLEVEL_NONE; static LOGLEVEL s_console_level = LOGLEVEL_NONE; static LOGLEVEL s_debug_level = LOGLEVEL_NONE; static LOGLEVEL s_file_level = LOGLEVEL_NONE; static LOGLEVEL s_host_level = LOGLEVEL_NONE; static bool s_log_timestamps = true; static FileSystem::ManagedCFilePtr s_file_handle; static std::string s_file_path; static std::mutex s_file_mutex; static HostCallbackType s_host_callback; #ifdef _WIN32 static HANDLE s_hConsoleStdIn = NULL; static HANDLE s_hConsoleStdOut = NULL; static HANDLE s_hConsoleStdErr = NULL; #endif } // namespace Log float Log::GetCurrentMessageTime() { return static_cast(Common::Timer::ConvertValueToSeconds(Common::Timer::GetCurrentValue() - s_start_timestamp)); } __ri void Log::WriteToConsole(LOGLEVEL level, ConsoleColors color, std::string_view message) { static constexpr std::string_view s_ansi_color_codes[ConsoleColors_Count] = { "\033[0m"sv, // default "\033[30m\033[1m"sv, // black "\033[32m"sv, // green "\033[31m"sv, // red "\033[34m"sv, // blue "\033[35m"sv, // magenta "\033[35m"sv, // orange (FIXME) "\033[37m"sv, // gray "\033[36m"sv, // cyan "\033[33m"sv, // yellow "\033[37m"sv, // white "\033[30m\033[1m"sv, // strong black "\033[31m\033[1m"sv, // strong red "\033[32m\033[1m"sv, // strong green "\033[34m\033[1m"sv, // strong blue "\033[35m\033[1m"sv, // strong magenta "\033[35m\033[1m"sv, // strong orange (FIXME) "\033[37m\033[1m"sv, // strong gray "\033[36m\033[1m"sv, // strong cyan "\033[33m\033[1m"sv, // strong yellow "\033[37m\033[1m"sv, // strong white }; static constexpr size_t BUFFER_SIZE = 512; SmallStackString buffer; buffer.reserve(32 + message.length()); buffer.append(s_ansi_color_codes[color]); if (s_log_timestamps) buffer.append_format(TIMESTAMP_FORMAT_STRING, Log::GetCurrentMessageTime()); buffer.append(message); buffer.append('\n'); #ifdef _WIN32 const HANDLE hOutput = (level <= LOGLEVEL_WARNING) ? s_hConsoleStdErr : s_hConsoleStdOut; // Convert to UTF-16 first so Unicode characters display correctly. NT is going to do it anyway... wchar_t wbuf[BUFFER_SIZE]; wchar_t* wmessage_buf = wbuf; int wmessage_buflen = static_cast(std::size(wbuf) - 1); if (buffer.length() >= std::size(wbuf)) { wmessage_buflen = static_cast(buffer.length()); wmessage_buf = static_cast(std::malloc(static_cast(wmessage_buflen) * sizeof(wchar_t))); if (!wmessage_buf) return; } const int wmessage_size = MultiByteToWideChar(CP_UTF8, 0, buffer.data(), static_cast(buffer.length()), wmessage_buf, wmessage_buflen); if (wmessage_size <= 0) goto cleanup; DWORD chars_written; WriteConsoleW(hOutput, wmessage_buf, static_cast(wmessage_size), &chars_written, nullptr); cleanup: if (wmessage_buf != wbuf) std::free(wmessage_buf); #else const int fd = (level <= LOGLEVEL_WARNING) ? STDERR_FILENO : STDOUT_FILENO; write(fd, buffer.data(), buffer.length()); #endif } bool Log::IsConsoleOutputEnabled() { return (s_console_level > LOGLEVEL_NONE); } void Log::SetConsoleOutputLevel(LOGLEVEL level) { if (s_console_level == level) return; const bool was_enabled = (s_console_level > LOGLEVEL_NONE); const bool now_enabled = (level > LOGLEVEL_NONE); s_console_level = level; UpdateMaxLevel(); if (was_enabled == now_enabled) return; // Worst that happens here is we write to a bad handle.. #if defined(_WIN32) static constexpr auto enable_virtual_terminal_processing = [](HANDLE hConsole) { DWORD old_mode; if (!GetConsoleMode(hConsole, &old_mode)) return; // already enabled? if (old_mode & ENABLE_VIRTUAL_TERMINAL_PROCESSING) return; SetConsoleMode(hConsole, old_mode | ENABLE_VIRTUAL_TERMINAL_PROCESSING); }; // On windows, no console is allocated by default on a windows based application static bool console_was_allocated = false; static HANDLE old_stdin = NULL; static HANDLE old_stdout = NULL; static HANDLE old_stderr = NULL; if (now_enabled) { old_stdin = GetStdHandle(STD_INPUT_HANDLE); old_stdout = GetStdHandle(STD_OUTPUT_HANDLE); old_stderr = GetStdHandle(STD_ERROR_HANDLE); if (!old_stdout) { // Attach to the parent console if we're running from a command window if (!AttachConsole(ATTACH_PARENT_PROCESS) && !AllocConsole()) return; s_hConsoleStdIn = GetStdHandle(STD_INPUT_HANDLE); s_hConsoleStdOut = GetStdHandle(STD_OUTPUT_HANDLE); s_hConsoleStdErr = GetStdHandle(STD_ERROR_HANDLE); enable_virtual_terminal_processing(s_hConsoleStdOut); enable_virtual_terminal_processing(s_hConsoleStdErr); std::FILE* fp; freopen_s(&fp, "CONIN$", "r", stdin); freopen_s(&fp, "CONOUT$", "w", stdout); freopen_s(&fp, "CONOUT$", "w", stderr); console_was_allocated = true; } else { s_hConsoleStdIn = old_stdin; s_hConsoleStdOut = old_stdout; s_hConsoleStdErr = old_stderr; } } else { if (console_was_allocated) { console_was_allocated = false; std::FILE* fp; freopen_s(&fp, "NUL:", "w", stderr); freopen_s(&fp, "NUL:", "w", stdout); freopen_s(&fp, "NUL:", "w", stdin); SetStdHandle(STD_ERROR_HANDLE, old_stderr); SetStdHandle(STD_OUTPUT_HANDLE, old_stdout); SetStdHandle(STD_INPUT_HANDLE, old_stdin); s_hConsoleStdIn = NULL; s_hConsoleStdOut = NULL; s_hConsoleStdErr = NULL; FreeConsole(); } } #endif } __ri void Log::WriteToDebug(LOGLEVEL level, ConsoleColors color, std::string_view message) { #ifdef _WIN32 static constexpr size_t BUFFER_SIZE = 512; // Convert to UTF-16 first so Unicode characters display correctly. NT is going to do it anyway... wchar_t wbuf[BUFFER_SIZE]; wchar_t* wmessage_buf = wbuf; int wmessage_buflen = static_cast(std::size(wbuf) - 1); if (message.length() >= std::size(wbuf)) { wmessage_buflen = static_cast(message.length()); wmessage_buf = static_cast(std::malloc((static_cast(wmessage_buflen) + 2) * sizeof(wchar_t))); if (!wmessage_buf) return; } int wmessage_size = 0; if (!message.empty()) [[likely]] { wmessage_size = MultiByteToWideChar(CP_UTF8, 0, message.data(), static_cast(message.length()), wmessage_buf, wmessage_buflen); if (wmessage_size <= 0) goto cleanup; } wmessage_buf[wmessage_size++] = L'\n'; wmessage_buf[wmessage_size++] = 0; OutputDebugStringW(wmessage_buf); cleanup: if (wmessage_buf != wbuf) std::free(wmessage_buf); #endif } bool Log::IsDebugOutputAvailable() { #ifdef _WIN32 return IsDebuggerPresent(); #else return false; #endif } bool Log::IsDebugOutputEnabled() { return (s_console_level > LOGLEVEL_NONE); } void Log::SetDebugOutputLevel(LOGLEVEL level) { s_debug_level = level; UpdateMaxLevel(); } __ri void Log::WriteToFile(LOGLEVEL level, ConsoleColors color, std::string_view message) { std::unique_lock lock(s_file_mutex); if (!s_file_handle) [[unlikely]] return; if (!message.empty()) [[likely]] { if (s_log_timestamps) { std::fprintf(s_file_handle.get(), TIMESTAMP_PRINTF_STRING "%.*s\n", GetCurrentMessageTime(), static_cast(message.size()), message.data()); } else { std::fprintf(s_file_handle.get(), "%.*s\n", static_cast(message.size()), message.data()); } } else { if (s_log_timestamps) { std::fprintf(s_file_handle.get(), TIMESTAMP_PRINTF_STRING "\n", GetCurrentMessageTime()); } else { std::fputc('\n', s_file_handle.get()); } } std::fflush(s_file_handle.get()); } bool Log::IsFileOutputEnabled() { return (s_file_level > LOGLEVEL_NONE); } bool Log::SetFileOutputLevel(LOGLEVEL level, std::string path) { std::unique_lock lock(s_file_mutex); const bool was_enabled = (s_file_level > LOGLEVEL_NONE); const bool new_enabled = (level > LOGLEVEL_NONE && !path.empty()); if (was_enabled != new_enabled || (new_enabled && path == s_file_path)) { if (new_enabled) { if (!s_file_handle || s_file_path != path) { s_file_handle.reset(); s_file_handle = FileSystem::OpenManagedCFile(path.c_str(), "wb"); if (s_file_handle) { s_file_path = std::move(path); } else { s_file_path = {}; if (IsConsoleOutputEnabled()) WriteToConsole(LOGLEVEL_ERROR, Color_StrongRed, TinyString::from_format("Failed to open log file '{}'", path)); } } } else { s_file_handle.reset(); s_file_path = {}; } } s_file_level = s_file_handle ? level : LOGLEVEL_NONE; UpdateMaxLevel(); return IsFileOutputEnabled(); } std::FILE* Log::GetFileLogHandle() { std::unique_lock lock(s_file_mutex); return s_file_handle.get(); } bool Log::IsHostOutputEnabled() { return (s_host_level > LOGLEVEL_NONE); } void Log::SetHostOutputLevel(LOGLEVEL level, HostCallbackType callback) { s_host_callback = callback; s_host_level = callback ? level : LOGLEVEL_NONE; UpdateMaxLevel(); } bool Log::AreTimestampsEnabled() { return s_log_timestamps; } void Log::SetTimestampsEnabled(bool enabled) { s_log_timestamps = enabled; } LOGLEVEL Log::GetMaxLevel() { return s_max_level; } __ri void Log::UpdateMaxLevel() { s_max_level = std::max(s_console_level, std::max(s_debug_level, std::max(s_file_level, s_host_level))); } void Log::ExecuteCallbacks(LOGLEVEL level, ConsoleColors color, std::string_view message) { // TODO: Cache the message time. // Split newlines into separate messages. std::string_view::size_type start_pos = 0; if (std::string_view::size_type end_pos = message.find('\n'); end_pos != std::string::npos) [[unlikely]] { for (;;) { std::string_view message_line; if (start_pos != end_pos) message_line = message.substr(start_pos, (end_pos == std::string_view::npos) ? end_pos : end_pos - start_pos); ExecuteCallbacks(level, color, message_line); if (end_pos == std::string_view::npos) return; start_pos = end_pos + 1; end_pos = message.find('\n', start_pos); } return; } pxAssert(level > LOGLEVEL_NONE); if (level <= s_console_level) WriteToConsole(level, color, message); if (level <= s_debug_level) WriteToDebug(level, color, message); if (level <= s_file_level) WriteToFile(level, color, message); if (level <= s_host_level) { // double check in case of race here const HostCallbackType callback = s_host_callback; if (callback) s_host_callback(level, color, message); } } void Log::Write(LOGLEVEL level, ConsoleColors color, std::string_view message) { if (level > s_max_level) return; ExecuteCallbacks(level, color, message); } void Log::Writef(LOGLEVEL level, ConsoleColors color, const char* format, ...) { std::va_list ap; va_start(ap, format); Writev(level, color, format, ap); va_end(ap); } void Log::Writev(LOGLEVEL level, ConsoleColors color, const char* format, va_list ap) { if (level > s_max_level) return; std::va_list ap_copy; va_copy(ap_copy, ap); #ifdef _WIN32 const u32 required_size = static_cast(_vscprintf(format, ap_copy)); #else const u32 required_size = std::vsnprintf(nullptr, 0, format, ap_copy); #endif va_end(ap_copy); if (required_size < 512) { char buffer[512]; const int len = std::vsnprintf(buffer, std::size(buffer), format, ap); if (len > 0) ExecuteCallbacks(level, color, std::string_view(buffer, static_cast(len))); } else { char* buffer = new char[required_size + 1]; const int len = std::vsnprintf(buffer, required_size + 1, format, ap); if (len > 0) ExecuteCallbacks(level, color, std::string_view(buffer, static_cast(len))); delete[] buffer; } } void Log::WriteFmtArgs(LOGLEVEL level, ConsoleColors color, fmt::string_view fmt, fmt::format_args args) { if (level > s_max_level) return; fmt::memory_buffer buffer; fmt::vformat_to(std::back_inserter(buffer), fmt, args); ExecuteCallbacks(level, color, std::string_view(buffer.data(), buffer.size())); }