From 3863d5a4ed233794fa5210223a422d22ef766dcc Mon Sep 17 00:00:00 2001 From: bicarus <202771338+bicarus-dev@users.noreply.github.com> Date: Mon, 17 Aug 2026 22:41:07 -0700 Subject: [PATCH] misc: various clean up for diagnosing launch failures (#872) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Link to GitHub Issue or related Pull Request, if one exists #345 ## Description of change **IIDX TDJ rom probe no longer touches removable media** — `C:\000rom.txt` and `D:\001rom.txt` are not emulated paths; they hit whatever is actually mounted on the user's machine. `D:` is commonly an optical drive or card reader, and the launcher clears `SEM_FAILCRITICALERRORS` process-wide before attach, so an empty drive raises the modal *"insert a disk"* dialog and blocks the attaching thread. The probe now checks `GetDriveTypeW` and only reads fixed and RAM disks. **`iat_find` no longer calls `log_fatal` on an unparseable module** — `iat_try(nullptr)` walks every loaded module, including foreign ones (injected, manually mapped, header wiped by AV/EDR/overlays). A non-`MZ` DOS header called `log_fatal`. There is nothing to hook in such a module, so it is skipped. **`logger::stop()` can no longer hang forever** — hook installation suspends every other thread, including the logging thread. `stop()` unconditionally joined that thread, so `log_fatal` and the 30-second `show_popup` watchdog both wedged instead of terminating, and logging is asynchronous so nothing reached log.txt either. It now waits with a timeout, then detaches and flushes synchronously. **`GetFileSizeEx` was never hooked** — the hook was registered under the name `"GetFileSize"`, so it re-patched that slot instead. **Warn when `-modules` is set** — it changes where the game is run from, and is usually set accidentally. ## Testing *how was the code tested?* --- src/spice2x/games/iidx/iidx.cpp | 26 ++++++++++- src/spice2x/hooks/devicehook.cpp | 2 +- src/spice2x/launcher/launcher.cpp | 20 ++++++++ src/spice2x/launcher/logger.cpp | 78 +++++++++++++++++++++++++------ src/spice2x/util/detour.cpp | 39 +++++++++++----- 5 files changed, 136 insertions(+), 29 deletions(-) diff --git a/src/spice2x/games/iidx/iidx.cpp b/src/spice2x/games/iidx/iidx.cpp index 36c73c3..d165da8 100644 --- a/src/spice2x/games/iidx/iidx.cpp +++ b/src/spice2x/games/iidx/iidx.cpp @@ -279,6 +279,26 @@ namespace games::iidx { return nullptr; } + // best-effort read of a TDJ ROM file to determine if the game is running in TDJ mode + // + // these paths are not emulated - they hit whatever is actually mounted at that drive letter. + // an empty optical or removable drive raises the modal "insert a disk" error (the launcher + // clears SEM_FAILCRITICALERRORS process-wide) and a downed network drive stalls on redirector + // timeouts, so only probe what a TDJ cabinet would actually be laid out on. + // drive_path must be absolute and start with a drive letter. + static bool tdj_rom_matches(const char *drive_path, const char *expected) { + const wchar_t root[] = { (wchar_t) drive_path[0], L':', L'\\', L'\0' }; + const auto drive_type = GetDriveTypeW(root); + + if (drive_type != DRIVE_FIXED && drive_type != DRIVE_RAMDISK) { + log_misc("iidx", "not probing '{}' for TDJ, not a local disk (drive type {})", + drive_path, drive_type); + return false; + } + + return fileutils::text_read(drive_path) == expected; + } + #endif IIDXGame::IIDXGame() : Game("Beatmania IIDX") { @@ -339,8 +359,10 @@ namespace games::iidx { HAS_LIBAIO = true; // check TDJ mode - TDJ_MODE |= fileutils::text_read("C:\\000rom.txt") == "TDJ-JA"; - TDJ_MODE |= fileutils::text_read("D:\\001rom.txt") == "TDJ"; + if (!TDJ_MODE) { + TDJ_MODE = tdj_rom_matches("C:\\000rom.txt", "TDJ-JA") + || tdj_rom_matches("D:\\001rom.txt", "TDJ"); + } // force TDJ mode if (TDJ_MODE) { diff --git a/src/spice2x/hooks/devicehook.cpp b/src/spice2x/hooks/devicehook.cpp index 9f47b0a..038c35b 100644 --- a/src/spice2x/hooks/devicehook.cpp +++ b/src/spice2x/hooks/devicehook.cpp @@ -574,7 +574,7 @@ void devicehook_init(HMODULE module) { STORE(EscapeCommFunction_orig, detour::iat_try("EscapeCommFunction", EscapeCommFunction_hook, module)); STORE(GetCommState_orig, detour::iat_try("GetCommState", GetCommState_hook, module)); STORE(GetFileSize_orig, detour::iat_try("GetFileSize", GetFileSize_hook, module)); - STORE(GetFileSizeEx_orig, detour::iat_try("GetFileSize", GetFileSizeEx_hook, module)); + STORE(GetFileSizeEx_orig, detour::iat_try("GetFileSizeEx", GetFileSizeEx_hook, module)); STORE(GetFileInformationByHandle_orig, detour::iat_try( "GetFileInformationByHandle", GetFileInformationByHandle_hook, module)); STORE(PurgeComm_orig, detour::iat_try("PurgeComm", PurgeComm_hook, module)); diff --git a/src/spice2x/launcher/launcher.cpp b/src/spice2x/launcher/launcher.cpp index 9917f67..e47809e 100644 --- a/src/spice2x/launcher/launcher.cpp +++ b/src/spice2x/launcher/launcher.cpp @@ -1683,6 +1683,26 @@ int main_implementation(int argc, char *argv[]) { }); } + if (options[launcher::Options::PathToModules].is_active() && !cfg::CONFIGURATOR_STANDALONE) { + log_warning( + "launcher", + "WARNING - user specified -modules option\n\n\n" + "!!! !!!\n" + "!!! Using -modules changes which game DLLs get loaded! !!!\n" + "!!! Unless you know exactly what you are doing, clear -modules !!!\n" + "!!! and try again; usually this is accidentally set by users !!!\n" + "!!! without understanding the implications. !!!\n" + "!!! !!!\n" + ); + deferredlogs::defer_error_messages({ + "-modules option specified by user", + " game DLLs and patches are loaded from that folder instead of the spice folder,", + " and it is also prepended to the DLL search path, so dependencies may resolve to", + " unexpected copies; instead, clear -modules option and place spice binaries in", + " the intended game directory", + }); + } + if (launcher::signal::DISABLE && !cfg::CONFIGURATOR_STANDALONE) { log_warning( "launcher", diff --git a/src/spice2x/launcher/logger.cpp b/src/spice2x/launcher/logger.cpp index 8c5ad67..aad50af 100644 --- a/src/spice2x/launcher/logger.cpp +++ b/src/spice2x/launcher/logger.cpp @@ -1,6 +1,7 @@ #include "logger.h" #include +#include #include #include #include @@ -25,13 +26,16 @@ namespace logger { bool COLOR = true; // state - static bool RUNNING = false; + static std::atomic RUNNING = false; static WORD DEFAULT_ATTRIBUTES = 0; static std::mutex EVENT_MUTEX; static std::condition_variable EVENT_CV; static std::thread *THREAD = nullptr; + static HANDLE THREAD_FINISHED = nullptr; + static std::atomic THREAD_ABANDONED = false; static std::mutex OUTPUT_MUTEX; - static bool OUTPUT_BUFFER_HOT = false; + static std::mutex FLUSH_MUTEX; + static std::atomic OUTPUT_BUFFER_HOT = false; static std::vector> OUTPUT_BUFFER1; static std::vector> OUTPUT_BUFFER2; static std::vector> *OUTPUT_BUFFER = &OUTPUT_BUFFER1; @@ -71,7 +75,9 @@ namespace logger { SetConsoleTextAttribute(hTerminal, info.wAttributes); } - static void output_buffer_flush() { + // the buffer is swapped under OUTPUT_MUTEX but drained outside of it, so two concurrent + // drains would leave one of them iterating a buffer that push() has started appending to + static void output_buffer_flush_locked() { // get buffer and swap auto buffer = output_buffer_swap(); @@ -142,6 +148,23 @@ namespace logger { } } + static void output_buffer_flush() { + + // a detached logging thread can hold FLUSH_MUTEX forever, so never wait on it + if (THREAD_ABANDONED) { + std::unique_lock guard(FLUSH_MUTEX, std::try_to_lock); + if (guard.owns_lock()) { + output_buffer_flush_locked(); + } + + return; + } + + std::lock_guard guard(FLUSH_MUTEX); + + output_buffer_flush_locked(); + } + void start() { // don't start if blocking @@ -151,6 +174,7 @@ namespace logger { // start logging thread RUNNING = true; + THREAD_FINISHED = CreateEvent(nullptr, TRUE, FALSE, nullptr); THREAD = new std::thread([] { std::unique_lock lock(EVENT_MUTEX); @@ -160,7 +184,7 @@ namespace logger { while (RUNNING) { // wait for hot buffer - EVENT_CV.wait(lock, [] { return OUTPUT_BUFFER_HOT; }); + EVENT_CV.wait(lock, [] { return OUTPUT_BUFFER_HOT.load(); }); OUTPUT_BUFFER_HOT = false; // flush buffer @@ -180,22 +204,51 @@ namespace logger { HANDLE hTerminal = GetStdHandle(STD_OUTPUT_HANDLE); SetConsoleTextAttribute(hTerminal, DEFAULT_ATTRIBUTES); } + + if (THREAD_FINISHED) { + SetEvent(THREAD_FINISHED); + } }); } void stop() { - log_info("logger", "stop"); + + // NOTE: don't log to the logger here! + + RUNNING = false; // clean up thread if required - RUNNING = false; if (THREAD) { // fake notify to exit wait loop OUTPUT_BUFFER_HOT = true; EVENT_CV.notify_all(); - // join and clean up - THREAD->join(); + // never block forever - this also runs on the fatal/crash path, where the logging + // thread may be suspended or wedged and would take the whole process down with it + const bool finished = THREAD_FINISHED != nullptr && + WaitForSingleObject(THREAD_FINISHED, 1000) == WAIT_OBJECT_0; + + if (finished) { + THREAD->join(); + + CloseHandle(THREAD_FINISHED); + THREAD_FINISHED = nullptr; + } else { + THREAD->detach(); + THREAD_ABANDONED = true; + + // THREAD_FINISHED is leaked on purpose: the detached thread can still wake up and + // signal it, and closing it here risks signaling an unrelated recycled handle + + // write out whatever the logging thread never got to + output_buffer_flush(); + + if (LOG_FILE && LOG_FILE != INVALID_HANDLE_VALUE) { + FlushFileBuffers(LOG_FILE); + } + } + delete THREAD; THREAD = nullptr; } @@ -229,17 +282,14 @@ namespace logger { // check if blocking or the logging thread is not running if (BLOCKING || !RUNNING) { - // blocking guard - static std::mutex blocking_lock; - std::lock_guard blocking_guard(blocking_lock); - // immediately process logs output_buffer_flush(); } else { - // mark buffer as hot - std::unique_lock lock(EVENT_MUTEX); + // never block here - the logging thread can be suspended while holding EVENT_MUTEX, + // and it re-checks OUTPUT_BUFFER_HOT before waiting again + std::unique_lock lock(EVENT_MUTEX, std::try_to_lock); OUTPUT_BUFFER_HOT = true; EVENT_CV.notify_one(); } diff --git a/src/spice2x/util/detour.cpp b/src/spice2x/util/detour.cpp index 4a91820..791ff3b 100644 --- a/src/spice2x/util/detour.cpp +++ b/src/spice2x/util/detour.cpp @@ -119,6 +119,14 @@ static void *pe_offset(void *ptr, size_t offset) { return reinterpret_cast(ptr) + offset; } +// foreign modules (injected, manually mapped) have no import table to patch - skip them +// instead of taking the process down +static bool has_pe_header(HMODULE module) { + const auto dos_headers = reinterpret_cast(module); + + return dos_headers->e_magic == IMAGE_DOS_SIGNATURE; +} + void **detour::iat_find(const char *function, HMODULE module, const char *iid_name) { // check module @@ -127,11 +135,13 @@ void **detour::iat_find(const char *function, HMODULE module, const char *iid_na } // check signature - const IMAGE_DOS_HEADER *pImgDosHeaders = (IMAGE_DOS_HEADER *) module; - if (pImgDosHeaders->e_magic != IMAGE_DOS_SIGNATURE) { - log_fatal("detour", "signature mismatch ({} != {})", pImgDosHeaders->e_magic, IMAGE_DOS_SIGNATURE); + if (!has_pe_header(module)) { + log_misc("detour", "no PE header in {}, not looking for {}", fmt::ptr(module), function); + return nullptr; } + const IMAGE_DOS_HEADER *pImgDosHeaders = (IMAGE_DOS_HEADER *) module; + // get import table const auto nt_headers = reinterpret_cast(pe_offset(module, pImgDosHeaders->e_lfanew)); const auto data_dir = &nt_headers->OptionalHeader.DataDirectory[IMAGE_DIRECTORY_ENTRY_IMPORT]; @@ -191,11 +201,13 @@ void **detour::iat_find_ordinal(const char *iid_name, DWORD ordinal, HMODULE mod } // check signature - const auto pImgDosHeaders = reinterpret_cast(module); - if (pImgDosHeaders->e_magic != IMAGE_DOS_SIGNATURE) { - log_fatal("detour", "signature error"); + if (!has_pe_header(module)) { + log_misc("detour", "no PE header in {}, not looking for {}:{}", fmt::ptr(module), iid_name, ordinal); + return nullptr; } + const auto pImgDosHeaders = reinterpret_cast(module); + // get import table const auto nt_headers = reinterpret_cast(pe_offset(module, pImgDosHeaders->e_lfanew)); const auto data_dir = &nt_headers->OptionalHeader.DataDirectory[IMAGE_DIRECTORY_ENTRY_IMPORT]; @@ -246,11 +258,13 @@ void **detour::iat_find_proc(const char *iid_name, void *proc, HMODULE module) { } // check signature - const auto pImgDosHeaders = reinterpret_cast(module); - if (pImgDosHeaders->e_magic != IMAGE_DOS_SIGNATURE) { - log_fatal("detour", "signature error"); + if (!has_pe_header(module)) { + log_misc("detour", "no PE header in {}, not looking for {}", fmt::ptr(module), iid_name); + return nullptr; } + const auto pImgDosHeaders = reinterpret_cast(module); + // get import table const auto nt_headers = reinterpret_cast(pe_offset(module, pImgDosHeaders->e_lfanew)); const auto data_dir = &nt_headers->OptionalHeader.DataDirectory[IMAGE_DIRECTORY_ENTRY_IMPORT]; @@ -298,7 +312,9 @@ void *detour::iat_try(const char *function, void *new_func, HMODULE module, cons while (cur_entry != nullptr) { module = reinterpret_cast(cur_entry->DllBase); - if (module) { + // walking the PEB turns up foreign modules too, and those are expected to have + // nothing to patch - filter them here so iat_find only complains about real callers + if (module && has_pe_header(module)) { auto old_func = iat_try(function, new_func, module, iid_name); ret = ret != nullptr ? ret : old_func; } @@ -328,7 +344,6 @@ void *detour::iat_try(const char *function, void *new_func, HMODULE module, cons } void *detour::iat_try_ordinal(const char *iid_name, DWORD ordinal, void *new_func, HMODULE module) { - // fail when no module was specified if (module == nullptr) { return nullptr; @@ -367,7 +382,7 @@ void *detour::iat_try_proc(const char *iid_name, void *proc, void *new_func, HMO while (cur_entry != nullptr) { module = reinterpret_cast(cur_entry->DllBase); - if (module) { + if (module && has_pe_header(module)) { auto old_func = iat_try_proc(iid_name, proc, new_func, module); ret = ret != nullptr ? ret : old_func; }