Better Logging (to file, console, VS Output) (#55)

* [refactor/audio] Rename ResumeThread to ResumeAudioThread
The name was clashing with an MSVC function name that's included with spdlog.

* [logging] Port everything to the new logging system

* [usability] Warn about corrupt/encrypted (s)elf instead of crashing.

* [logging] Initial logging framework

Defines LOG_* macros for different log levels, where * is either TRACE, DEBUG, INFO, WARN, ERROR or CRITICAL.

Additionally, it defines LOG_*_IF (same log levels), for conditional logging, with the first argument being the condition.

.gitmodules

@@ -22,3 +22,6 @@
 [submodule "src/external/sdl2-cmake-scripts"]
 	path = src/external/sdl2-cmake-scripts
 	url = https://github.com/tcbrindle/sdl2-cmake-scripts.git
+[submodule "src/external/spdlog"]
+	path = src/external/spdlog
+	url = https://github.com/gabime/spdlog.git

src/emulator/audio/CMakeLists.txt

@@ -8,3 +8,4 @@ src/audio.cpp
 
 target_include_directories(audio PUBLIC include)
 target_link_libraries(audio PUBLIC sdl2 vita-headers)
+target_link_libraries(audio PRIVATE util)

src/emulator/audio/include/audio/functions.h

@@ -23,6 +23,6 @@
 
 struct AudioState;
 
-typedef std::function<void(SceUID)> ResumeThread;
+typedef std::function<void(SceUID)> ResumeAudioThread;
 
-bool init(AudioState &state, ResumeThread resume_thread);
+bool init(AudioState &state, ResumeAudioThread resume_thread);

src/emulator/audio/include/audio/state.h

@@ -29,7 +29,7 @@
 #include <SDL_audio.h>
 
 typedef std::shared_ptr<SDL_AudioStream> AudioStreamPtr;
-typedef std::function<void(SceUID)> ResumeThread;
+typedef std::function<void(SceUID)> ResumeAudioThread;
 
 struct AudioOutput {
     const uint8_t *buf = nullptr;
@@ -62,7 +62,7 @@ typedef std::shared_ptr<void> AudioDevicePtr;
 
 struct ReadOnlyAudioState {
     SDL_AudioSpec spec;
-    ResumeThread resume_thread;
+    ResumeAudioThread resume_thread;
 };
 
 struct AudioCallbackState {

src/emulator/audio/src/audio.cpp

@@ -24,7 +24,7 @@
 
 static const int stream_put_granularity = 512;
 
-static void mix_out_port(uint8_t *stream, uint8_t *temp_buffer, int len, AudioOutPort &port, const ResumeThread &resume_thread) {
+static void mix_out_port(uint8_t *stream, uint8_t *temp_buffer, int len, AudioOutPort &port, const ResumeAudioThread &resume_thread) {
     int available_to_get = SDL_AudioStreamAvailable(port.callback.stream.get());
     assert(available_to_get >= 0);
 
@@ -86,7 +86,7 @@ static void close_audio(void *) {
     SDL_CloseAudio();
 }
 
-bool init(AudioState &state, ResumeThread resume_thread) {
+bool init(AudioState &state, ResumeAudioThread resume_thread) {
     state.ro.resume_thread = resume_thread;
 
     SDL_AudioSpec desired = {};

src/emulator/cpu/src/cpu.cpp

@@ -20,6 +20,7 @@
 #include <disasm/functions.h>
 #include <disasm/state.h>
 #include <mem/ptr.h>
+#include <util/log.h>
 
 #include <unicorn/unicorn.h>
 
@@ -59,12 +60,12 @@ static void code_hook(uc_engine *uc, uint64_t address, uint32_t size, void *user
     const size_t buffer_size = GB(4) - address;
     const bool thumb = is_thumb_mode(uc);
     const std::string disassembly = disassemble(state.disasm, code, buffer_size, address, thumb);
-    std::cout << std::hex << std::setw(8) << address << std::dec << " " << disassembly << std::endl;
+	LOG_TRACE("{:#08x} {}", address, disassembly);
 }
 
 static void log_memory_access(const char *type, Address address, int size, int64_t value, const MemState &mem) {
     const char *const name = mem_name(address, mem);
-    std::cout << type << " " << size << " bytes, address 0x" << std::hex << address << " (" << name << "), value 0x" << value << std::dec << std::endl;
+	LOG_TRACE("{} {} bytes, address {:#08x} ( {} ), value {:#x}", type, size, address, name, value);
 }
 
 static void read_hook(uc_engine *uc, uc_mem_type type, uint64_t address, int size, int64_t value, void *user_data) {

src/emulator/host/CMakeLists.txt

@@ -12,5 +12,5 @@ version.cpp
 configure_file(src/version.cpp.in version.cpp)
 
 target_include_directories(host PUBLIC include)
-target_link_libraries(host PUBLIC audio cpu ctrl gxm io kernel mem)
+target_link_libraries(host PUBLIC audio cpu ctrl gxm io kernel mem spdlog util)
 target_link_libraries(host PRIVATE nids sdl2)

src/emulator/host/src/host.cpp

@@ -27,6 +27,7 @@
 #include <kernel/thread_state.h>
 #include <nids/functions.h>
 #include <util/lock_and_find.h>
+#include <util/log.h>
 
 #include <SDL_events.h>
 #include <SDL_filesystem.h>
@@ -58,7 +59,7 @@ bool init(HostState &state) {
     const std::unique_ptr<char, void (&)(void *)> base_path(SDL_GetBasePath(), SDL_free);
     const std::unique_ptr<char, void (&)(void *)> pref_path(SDL_GetPrefPath(org_name, app_name), SDL_free);
 
-    const ResumeThread resume_thread = [&state](SceUID thread_id) {
+    const ResumeAudioThread resume_thread = [&state](SceUID thread_id) {
         const ThreadStatePtr thread = lock_and_find(thread_id, state.kernel.threads, state.kernel.mutex);
         const std::unique_lock<std::mutex> lock(thread->mutex);
         assert(thread->to_do == ThreadToDo::wait);
@@ -91,8 +92,7 @@ bool handle_events(HostState &host) {
 void call_import(HostState &host, uint32_t nid, SceUID thread_id) {
     if (LOG_IMPORT_CALLS) {
         const char *const name = import_name(nid);
-        const char prev_fill = std::cout.fill();
-        std::cout << "NID " << std::hex << std::setw(8) << std::setfill('0') << nid << std::setfill(prev_fill) << std::dec << " (" << name << ") called." << std::endl;
+		LOG_TRACE("NID {:#08x} ({})) called", nid, name);
     }
 
     ImportFn *const fn = resolve_import(nid);

src/emulator/io/CMakeLists.txt

@@ -8,3 +8,4 @@ add_library(
 
 target_include_directories(io PUBLIC include)
 target_link_libraries(io PUBLIC miniz vita-headers)
+target_link_libraries(io PRIVATE util)

src/emulator/io/src/io.cpp

@@ -18,6 +18,7 @@
 #include <io/functions.h>
 
 #include <io/state.h>
+#include <util/log.h>
 
 #include <psp2/io/fcntl.h>
 
@@ -141,7 +142,7 @@ SceUID open_file(IOState &io, const char *path, int flags, const char *pref_path
         int i = 5;
         if (path[5] == '/') i++;
         const ZipFilePtr file = open_zip(*io.vpk, &path[i]);
-		
+
         if (!file) {
             return -1;
         }
@@ -165,7 +166,6 @@ SceUID open_file(IOState &io, const char *path, int flags, const char *pref_path
         return fd;
     } else if (strncmp(path, "uma0:", 5) == 0) {
         std::string file_path = translate_path("uma0", path, pref_path);
-
         const char *const open_mode = translate_open_mode(flags);
         const FilePtr file(fopen(file_path.c_str(), open_mode), delete_file);
         if (!file) {
@@ -222,7 +222,7 @@ int write_file(SceUID fd, const void *data, SceSize size, const IOState &io) {
     if (tty_file != io.tty_files.end()) {
         if(tty_file->second == TTY_OUT){
             std::string s(reinterpret_cast<char const*>(data),size);
-            std::cout << s;
+            LOG_INFO("*** TTY: {}", s);
             return size;
         }
 

src/emulator/load_self.cpp

@@ -20,6 +20,7 @@
 #include "relocation.h"
 
 #include <nids/functions.h>
+#include <util/log.h>
 
 #include <elfio/elf_types.hpp>
 #define SCE_ELF_DEFS_TARGET
@@ -45,8 +46,7 @@ static bool load_func_imports(const uint32_t *nids, const Ptr<uint32_t> *entries
 
         if (LOG_IMPORTS) {
             const char *const name = import_name(nid);
-            const char prev_fill = std::cout.fill();
-            std::cout << "\tNID " << std::hex << std::setw(8) << std::setfill('0') << nid << std::setfill(prev_fill) << " (" << name << ") at 0x" << entry.address() << std::dec << std::endl;
+			LOG_DEBUG( "\tNID {:#08x} ({}) at {:#x}", nid, name, entry.address());
         }
 
         uint32_t *const stub = entry.get(mem);
@@ -66,7 +66,7 @@ static bool load_imports(const sce_module_info_raw &module, Ptr<const void> segm
     for (const sce_module_imports_raw *imports = imports_begin; imports < imports_end; imports = reinterpret_cast<const sce_module_imports_raw *>(reinterpret_cast<const uint8_t *>(imports) + imports->size)) {
         if (LOG_IMPORTS) {
             const char *const lib_name = Ptr<const char>(imports->module_name).get(mem);
-            std::cout << "Loading imports from " << lib_name << std::endl;
+            LOG_INFO("Loading imports from {}", lib_name);
         }
 
         assert(imports->version == 1);
@@ -86,6 +86,15 @@ static bool load_imports(const sce_module_info_raw &module, Ptr<const void> segm
 bool load_self(Ptr<const void> &entry_point, MemState &mem, const void *self) {
     const uint8_t *const self_bytes = static_cast<const uint8_t *>(self);
     const SCE_header &self_header = *static_cast<const SCE_header *>(self);
+
+    // assumes little endian host
+    // TODO: do it in a better way, perhaps with user-defined literals that do the conversion automatically (magic != "SCE\0"_u32)
+    if (!memcmp(&self_header.magic, "\0ECS", 4))
+    {
+        LOG_CRITICAL("(S)ELF is corrupt or encrypted. Decryption not yet supported.");
+        return false;
+    }
+
     const uint8_t *const elf_bytes = self_bytes + self_header.elf_offset;
     const Elf32_Ehdr &elf = *reinterpret_cast<const Elf32_Ehdr *>(elf_bytes);
     const unsigned int module_info_segment_index = static_cast<unsigned int>(elf.e_entry >> 30);
@@ -104,7 +113,7 @@ bool load_self(Ptr<const void> &entry_point, MemState &mem, const void *self) {
         if (src.p_type == PT_LOAD) {
             const Ptr<void> address(alloc(mem, src.p_memsz, "segment"));
             if (!address) {
-                std::cerr << "Failed to allocate memory for segment." << std::endl;
+                LOG_ERROR("Failed to allocate memory for segment.");
                 return false;
             }
 

src/emulator/main.cpp

@@ -22,6 +22,7 @@
 #include <host/version.h>
 #include <kernel/thread_functions.h>
 #include <util/string_convert.h>
+#include <util/log.h>
 
 #include <SDL.h>
 
@@ -47,7 +48,7 @@ static bool is_macos_process_arg(const char *arg) {
 
 static void error(const std::string& message, SDL_Window *window = nullptr) {
     if (SDL_ShowSimpleMessageBox(SDL_MESSAGEBOX_ERROR, "Error", message.c_str(), window) < 0) {
-        std::cerr << message << std::endl;
+        LOG_ERROR("SDL Error: {}", message);
     }
 }
 
@@ -58,7 +59,9 @@ static void term_sdl(const void *succeeded) {
 }
 
 int main(int argc, char *argv[]) {
-    std::cout << window_title << std::endl;
+	init_logging();
+
+	LOG_INFO("{}", window_title);
 
     ProgramArgsWide argv_wide = process_args(argc, argv);
 
@@ -101,8 +104,9 @@ int main(int argc, char *argv[]) {
     if (!load_vpk(entry_point, host.io, host.mem, path)) {
         std::string message = "Failed to load \"";
         message += wide_to_utf(path);
-        message += "\".";
-        error(message, host.window.get());
+        message += "\"";
+        message += "\nSee console output for details.";
+        error(message.c_str(), host.window.get());
         return ModuleLoadFailed;
     }
 

src/emulator/mem/CMakeLists.txt

@@ -7,3 +7,4 @@ add_library(
 )
 
 target_include_directories(mem PUBLIC include)
+target_link_libraries(mem PUBLIC util spdlog)

src/emulator/module/CMakeLists.txt

@@ -10,5 +10,5 @@ add_library(
 )
 
 target_include_directories(module PUBLIC include)
-target_link_libraries(module PUBLIC host microprofile)
+target_link_libraries(module PUBLIC host microprofile util spdlog)
 target_link_libraries(module PRIVATE util)

src/emulator/module/src/module.cpp

@@ -16,6 +16,7 @@
 // 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
 
 #include <module/module.h>
+#include <util/log.h>
 
 #include <iostream>
 #include <mutex>
@@ -28,14 +29,13 @@ static NameSet logged;
 
 int unimplemented(const char *name) {
     bool inserted = false;
-
     {
         const std::lock_guard<std::mutex> lock(mutex);
         inserted = logged.insert(name).second;
     }
 
     if (inserted) {
-        std::cerr << ">>> " << name << " <<< Unimplemented import called." << std::endl;
+        LOG_WARN(">>> {} <<< Unimplemented import called.", name);
     }
 
     return 0;
@@ -50,7 +50,7 @@ int error(const char *name, int error) {
     }
 
     if (inserted) {
-        std::cerr << ">>> " << name << " <<< returned 0x" << std::hex << std::uppercase << error << std::endl;
+		LOG_ERROR(">>> {} <<< returned {:#X}", name, error);
     }
 
     return error;

src/emulator/modules/SceGxm/src/SceGxm.cpp

@@ -18,6 +18,7 @@
 #include <SceGxm/exports.h>
 
 #include "gxm.h"
+#include <util/log.h>
 
 #include <glbinding/Binding.h>
 
@@ -57,7 +58,9 @@ static void before_callback(const FunctionCall &fn) {
 static void after_callback(const FunctionCall &fn) {
     MICROPROFILE_LEAVE();
     for (GLenum error = glGetError(); error != GL_NO_ERROR; error = glGetError()) {
-        std::cerr << "OpenGL: " << fn.function->name() << " set error " << error << "." << std::endl;
+        std::stringstream gl_error;
+        gl_error << error;
+        LOG_ERROR("OpenGL: {} set error {}.", fn.function->name(), gl_error.str());
         assert(false);
     }
 }
@@ -78,7 +81,7 @@ static bool compile_shader(GLuint shader, const GLchar *source) {
         log.resize(log_length);
         glGetShaderInfoLog(shader, log_length, nullptr, &log.front());
 
-        std::cerr << &log.front() << std::endl;
+        LOG_ERROR("{}", log.front());
     }
 
     GLboolean is_compiled = GL_FALSE;
@@ -97,7 +100,7 @@ static bool compile_shader(GLuint shader, const SceGxmProgram *program, const ch
 
     std::ifstream is(path.str());
     if (is.fail()) {
-        std::cerr << "Couldn't open '" << path.str() << "' for reading." << std::endl;
+        LOG_ERROR("Couldn't open '{}' for reading.", path.str());
         return false;
     }
 
@@ -445,8 +448,8 @@ EXPORT(int, sceGxmCreateContext, const emu::SceGxmContextParams *params, Ptr<Sce
 #endif // MICROPROFILE_ENABLED
     setAfterCallback(after_callback);
 
-    std::cout << "GL_VERSION = " << glGetString(GL_VERSION) << std::endl;
-    std::cout << "GL_SHADING_LANGUAGE_VERSION = " << glGetString(GL_SHADING_LANGUAGE_VERSION) << std::endl;
+    LOG_INFO("GL_VERSION = {}", glGetString(GL_VERSION));
+	LOG_INFO("GL_SHADING_LANGUAGE_VERSION = {}", glGetString(GL_SHADING_LANGUAGE_VERSION));
 
     // TODO This is just for debugging.
     glClearColor(0.0625f, 0.125f, 0.25f, 0);
@@ -1453,7 +1456,7 @@ EXPORT(int, sceGxmShaderPatcherCreateFragmentProgram, SceGxmShaderPatcher *shade
         log.resize(log_length);
         glGetProgramInfoLog(fp->program.get(), log_length, nullptr, &log.front());
 
-        std::cerr << &log.front() << std::endl;
+		LOG_ERROR("{}", log.front());
     }
 
     GLboolean is_linked = GL_FALSE;

src/emulator/nids/CMakeLists.txt

@@ -7,3 +7,4 @@ add_library(
 )
 
 target_include_directories(nids PUBLIC include)
+target_link_libraries(cpu INTERFACE util spdlog)

src/emulator/relocation.cpp

@@ -16,6 +16,7 @@
 // 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
 
 #include "relocation.h"
+#include <util/log.h>
 
 #include <assert.h>
 #include <iostream>
@@ -192,7 +193,7 @@ static bool relocate(void *data, Code code, uint32_t s, uint32_t a, uint32_t p)
         return true;
     }
 
-    std::cerr << "Unhandled relocation code " << code << "." << std::endl;
+    LOG_WARN("Unhandled relocation code {}.", code);
 
     return true;
 }

src/emulator/util/CMakeLists.txt

@@ -5,7 +5,9 @@ add_library(
 	include/util/lock_and_find.h
 	include/util/resource.h
 	include/util/string_convert.h
+	include/util/log.h
 	src/util.cpp
 )
 
 target_include_directories(util PUBLIC include)
+target_link_libraries(util PUBLIC spdlog)

src/emulator/util/include/util/log.h

@@ -0,0 +1,21 @@
+#pragma once
+
+#include <spdlog/spdlog.h>
+
+extern std::shared_ptr<spdlog::logger> g_logger;
+
+void init_logging();
+
+#define LOG_TRACE(fmt, ...) g_logger->trace("[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_DEBUG(fmt, ...) g_logger->debug("[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_INFO(fmt, ...) g_logger->info("[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_WARN(fmt, ...) g_logger->warn("[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_ERROR(fmt, ...) g_logger->error("[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_CRITICAL(fmt, ...) g_logger->critical("[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+
+#define LOG_TRACE_IF(flag, fmt, ...) g_logger->trace_if(flag, "[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_DEBUG_IF(flag, fmt, ...) g_logger->debug_if(flag, "[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_INFO_IF(flag, fmt, ...) g_logger->info_if(flag, "[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_WARN_IF(flag, fmt, ...) g_logger->warn_if(flag, "[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_ERROR_IF(flag, fmt, ...) g_logger->error_if(flag, "[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)
+#define LOG_CRITICAL_IF(flag, fmt, ...) g_logger->critical_if(flag, "[ {:s} ]:    " fmt, __FUNCTION__, ## __VA_ARGS__)

src/emulator/util/src/util.cpp

@@ -1,14 +1,93 @@
+#include <util/log.h>
 #include <util/string_convert.h>
 
-#ifdef _WIN32
+#ifdef WIN32
 #include <windows.h>
 #include <processenv.h>
 #include <shellapi.h>
+#include <direct.h>
+#define getcwd _getcwd // stupid MSFT "deprecation" warning
+#else
+#include <unistd.h>
 #endif
 
+#ifdef _MSC_VER
+#include <spdlog/sinks/msvc_sink.h>
+#endif
+
+#include <iostream>
+#include <memory>
+#include <string>
 #include <codecvt>   // std::codecvt_utf8
 #include <locale>    // std::wstring_convert
-#include <iostream>
+
+std::shared_ptr<spdlog::logger> g_logger;
+
+static const
+#ifdef WIN32
+std::wstring& LOG_FILE_NAME = L"\\vita3k.log";
+#else
+std::string& LOG_FILE_NAME = "/vita3k.log";
+#endif
+
+void init_logging()
+{
+	static constexpr bool LOG_MSVC_OUTPUT = true;
+
+	std::vector<spdlog::sink_ptr> sinks;
+
+#ifdef WIN32
+	sinks.push_back(std::make_shared<spdlog::sinks::wincolor_stdout_sink_mt>());
+#else
+	sinks.push_back(std::make_shared<spdlog::sinks::ansicolor_stdout_sink_mt>());
+#endif
+	try
+	{
+        spdlog::filename_t s_cwd;
+
+#ifdef WIN32
+		wchar_t buffer[MAX_PATH];
+		GetModuleFileNameW(NULL, buffer, MAX_PATH);
+		std::string::size_type pos = std::wstring(buffer).find_last_of(L"\\\\");
+		std::wstring path = std::wstring(buffer).substr(0, pos);
+		if (!path.empty())
+			s_cwd = path;
+#else
+		char buffer[512];
+		char *path = getcwd(buffer, sizeof(buffer));
+		if (path)
+			s_cwd = path;
+#endif
+		else
+		{
+			std::cerr << "failed to get working directory" << std::endl;
+		}
+		sinks.push_back(std::make_shared<spdlog::sinks::simple_file_sink_mt>(s_cwd + LOG_FILE_NAME));
+	}
+	catch (const spdlog::spdlog_ex& ex)
+	{
+		std::cerr << "File log initialization failed: " << ex.what() << std::endl;
+	}
+
+#ifdef _MSC_VER
+	if (LOG_MSVC_OUTPUT)
+		sinks.push_back(std::make_shared<spdlog::sinks::msvc_sink_st>());
+#endif
+
+	g_logger = std::make_shared<spdlog::logger>("vita3k logger", begin(sinks), end(sinks));
+    spdlog::register_logger(g_logger);
+
+    spdlog::set_error_handler([](const std::string& msg)
+	{
+		std::cerr << "spdlog error: " << msg << std::endl;
+	});
+
+    spdlog::set_pattern("[%H:%M:%S.%e] [%l] %v");
+
+    spdlog::set_level(spdlog::level::trace);
+
+	g_logger->flush_on(spdlog::level::debug);
+}
 
 std::wstring utf_to_wide(const std::string& str)
 {
@@ -34,7 +113,7 @@ ProgramArgsWide process_args(int argc, char* argv[])
 
     if (nullptr == wide_arg_list)
     {
-        std::cerr << "CommandLineToArgvW failed\n";
+        LOG_ERROR("CommandLineToArgvW failed\n");
         return {};
     }
 
@@ -53,3 +132,4 @@ ProgramArgsWide process_args(int argc, char* argv[])
 
     return args;
 }
+

src/external/CMakeLists.txt

@@ -27,6 +27,10 @@ set(capstone_INCLUDE_DIRS "${CMAKE_CURRENT_SOURCE_DIR}/capstone/include" PARENT_
 add_library(elfio INTERFACE)
 target_include_directories(elfio INTERFACE "${CMAKE_CURRENT_SOURCE_DIR}/elfio")
 
+add_library(spdlog INTERFACE)
+target_include_directories(spdlog INTERFACE "${CMAKE_CURRENT_SOURCE_DIR}/spdlog/include")
+target_compile_definitions(spdlog INTERFACE SPDLOG_WCHAR_FILENAMES=1 SPDLOG_NO_THREAD_ID=1)
+
 option(BUILD_SHARED_LIBS "Build shared instead of static libraries." OFF)
 option(OPTION_BUILD_TESTS "Build tests." OFF)
 option(OPTION_BUILD_GPU_TESTS "Build tests that require an OpenGL context." OFF)

src/external/spdlog

@@ -0,0 +1 @@
+Subproject commit c336470320d2e7a3b70dca48bd822a0387d93a58