From 5cabf99881a22ca904da9805c0929c26f75327a7 Mon Sep 17 00:00:00 2001 From: jyh9521 Date: Fri, 7 Aug 2026 09:59:17 +0900 Subject: [PATCH] Log first-chance exceptions that RF's own SEH swallows --- game_patch/CMakeLists.txt | 1 + game_patch/debug/debug.h | 1 + game_patch/debug/exception_logger.cpp | 302 ++++++++++++++++++++++++++ game_patch/main/main.cpp | 1 + 4 files changed, 305 insertions(+) create mode 100644 game_patch/debug/exception_logger.cpp diff --git a/game_patch/CMakeLists.txt b/game_patch/CMakeLists.txt index aee8290b9..697b6b264 100644 --- a/game_patch/CMakeLists.txt +++ b/game_patch/CMakeLists.txt @@ -123,6 +123,7 @@ set(SRCS debug/debugwinmsg.cpp debug/debug_cmd.cpp debug/debug.cpp + debug/exception_logger.cpp debug/obj_debug.cpp debug/debug.h debug/debug_internal.h diff --git a/game_patch/debug/debug.h b/game_patch/debug/debug.h index 6fdd5ec22..5f3b065ac 100644 --- a/game_patch/debug/debug.h +++ b/game_patch/debug/debug.h @@ -2,6 +2,7 @@ void debug_apply_patches(); void debug_init(); +void exception_logger_init(); void debug_cleanup(); void debug_render(); void debug_render_ui(); diff --git a/game_patch/debug/exception_logger.cpp b/game_patch/debug/exception_logger.cpp new file mode 100644 index 000000000..0ee49977c --- /dev/null +++ b/game_patch/debug/exception_logger.cpp @@ -0,0 +1,302 @@ +#include +#include +#include +#include +#include +#include +#include "debug.h" + +// Logs first-chance C++ exceptions and access violations before any SEH frame can +// swallow them. +// +// Red Faction wraps large parts of the frame loop in its own __try/__except. When an +// exception is raised in there the process dies (or silently continues) with nothing in +// AlpineFaction.log: the log simply stops mid-frame. crash_handler_stub uses +// SetUnhandledExceptionFilter, which by definition only runs for exceptions nobody +// handled, so it never sees these either. +// +// A vectored exception handler runs ahead of every SEH frame, so it observes the throw +// before RF gets a chance to eat it. This one only logs and always returns +// EXCEPTION_CONTINUE_SEARCH, so exception handling behaviour is unchanged. +// +// These are *first-chance* exceptions: most are caught and handled a moment later, and +// seeing them in the log is normal. They are logged at warn level and capped, so a hot +// loop that throws cannot flood the file. + +static int g_num_logged = 0; +constexpr int max_logged = 40; + +static void copy_str(char* dst, int dst_size, const char* src) +{ + int i = 0; + if (!src) { + dst[0] = 0; + return; + } + while (i < dst_size - 1 && src[i]) { + dst[i] = src[i]; + ++i; + } + dst[i] = 0; +} + +// Reading the type name out of a C++ throw is MSVC-specific in two ways, so the whole +// probe is compiled only for MSVC: +// +// - The 0xE06D7363 exception code and the ThrowInfo structures below are the MSVC C++ +// ABI. A MinGW build uses a different mechanism entirely, so this parsing would be +// reading garbage. +// - Walking those structures means chasing pointers in a process that is already in +// trouble, so it needs SEH protection. __try/__except is MSVC syntax; GCC rejects it. +// +// Everything else in this file — access violations, the stack walk, symbol resolution — +// is plain Win32 and works the same either way. On MinGW a C++ throw is still logged, +// just without the type name. +#ifdef _MSC_VER + +// Layout of the MSVC throw metadata (x86: all pointers are absolute). +struct MsvcTypeDescriptor +{ + const void* vftable; + void* spare; + char name[1]; +}; +struct MsvcCatchableType +{ + unsigned properties; + MsvcTypeDescriptor* type_desc; +}; +struct MsvcCatchableTypeArray +{ + int count; + MsvcCatchableType* types[1]; +}; +struct MsvcThrowInfo +{ + unsigned attributes; + void* unwind; + void* forward_compat; + MsvcCatchableTypeArray* catchable; +}; + +// True for mangled names ending in "@std@@", i.e. types inside namespace std. +// Only those are safe to poke for what() through the vtable. +static bool name_is_std(const char* name) +{ + int len = 0; + while (name[len] && len < 240) { + ++len; + } + return len >= 6 && name[len - 6] == '@' && name[len - 5] == 's' && name[len - 4] == 't' + && name[len - 3] == 'd' && name[len - 2] == '@' && name[len - 1] == '@'; +} + +// Must stay free of objects with destructors, otherwise MSVC rejects __try (C2712). +static void probe_throw(const EXCEPTION_RECORD* rec, char* type_out, int type_size, + char* what_out, int what_size) +{ + copy_str(type_out, type_size, "?"); + copy_str(what_out, what_size, ""); + if (rec->NumberParameters < 3) { + return; + } + __try { + const MsvcThrowInfo* ti = reinterpret_cast(rec->ExceptionInformation[2]); + if (!ti || !ti->catchable || ti->catchable->count <= 0) { + return; + } + const char* name = ti->catchable->types[0]->type_desc->name; + copy_str(type_out, type_size, name); + if (name_is_std(name)) { + void* obj = reinterpret_cast(rec->ExceptionInformation[1]); + if (obj) { + // std::exception vtable: [0] destructor, [1] what() + typedef const char*(__thiscall* WhatFn)(void*); + WhatFn fn = reinterpret_cast((*reinterpret_cast(obj))[1]); + copy_str(what_out, what_size, fn(obj)); + } + } + } + __except (EXCEPTION_EXECUTE_HANDLER) { + copy_str(what_out, what_size, ""); + } +} + +#else // !_MSC_VER + +static void probe_throw(const EXCEPTION_RECORD*, char* type_out, int type_size, + char* what_out, int what_size) +{ + copy_str(type_out, type_size, ""); + copy_str(what_out, what_size, ""); +} + +#endif // _MSC_VER + +// dbghelp is loaded dynamically so the build system needs no extra link library. +typedef DWORD(WINAPI* SymSetOptionsFn)(DWORD); +typedef BOOL(WINAPI* SymInitializeFn)(HANDLE, PCSTR, BOOL); +typedef BOOL(WINAPI* SymFromAddrFn)(HANDLE, DWORD64, PDWORD64, PSYMBOL_INFO); +typedef BOOL(WINAPI* SymGetLineFn)(HANDLE, DWORD64, PDWORD, PIMAGEHLP_LINE64); +typedef BOOL(WINAPI* StackWalkFn)(DWORD, HANDLE, HANDLE, LPSTACKFRAME64, PVOID, + PREAD_PROCESS_MEMORY_ROUTINE64, PFUNCTION_TABLE_ACCESS_ROUTINE64, + PGET_MODULE_BASE_ROUTINE64, PTRANSLATE_ADDRESS_ROUTINE64); + +static SymFromAddrFn g_sym_from_addr = nullptr; +static SymGetLineFn g_sym_get_line = nullptr; +static StackWalkFn g_stack_walk = nullptr; +static PFUNCTION_TABLE_ACCESS_ROUTINE64 g_table_access = nullptr; +static PGET_MODULE_BASE_ROUTINE64 g_module_base = nullptr; + +static void sym_init() +{ + static bool tried = false; + if (tried) { + return; + } + tried = true; + HMODULE lib = LoadLibraryA("dbghelp.dll"); + if (!lib) { + return; + } + auto set_options = reinterpret_cast(GetProcAddress(lib, "SymSetOptions")); + auto initialize = reinterpret_cast(GetProcAddress(lib, "SymInitialize")); + g_sym_from_addr = reinterpret_cast(GetProcAddress(lib, "SymFromAddr")); + g_sym_get_line = reinterpret_cast(GetProcAddress(lib, "SymGetLineFromAddr64")); + g_stack_walk = reinterpret_cast(GetProcAddress(lib, "StackWalk64")); + g_table_access = reinterpret_cast( + GetProcAddress(lib, "SymFunctionTableAccess64")); + g_module_base = reinterpret_cast( + GetProcAddress(lib, "SymGetModuleBase64")); + if (set_options) { + set_options(SYMOPT_DEFERRED_LOADS | SYMOPT_UNDNAME | SYMOPT_LOAD_LINES); + } + if (initialize) { + // nullptr search path + invade: picks up the .pdb sitting next to each module + initialize(GetCurrentProcess(), nullptr, TRUE); + } + xlog::info("[exception-logger] dbghelp: sym={} line={} walk={} tbl={} base={}", + g_sym_from_addr != nullptr, g_sym_get_line != nullptr, g_stack_walk != nullptr, + g_table_access != nullptr, g_module_base != nullptr); +} + +// Resolve to "func+off [file:line]" when a PDB is available, else "module+RVA". +static std::string addr_str(void* addr) +{ + sym_init(); + if (g_sym_from_addr) { + char storage[sizeof(SYMBOL_INFO) + 256] = {}; + SYMBOL_INFO* sym = reinterpret_cast(storage); + sym->SizeOfStruct = sizeof(SYMBOL_INFO); + sym->MaxNameLen = 255; + DWORD64 sym_off = 0; + const DWORD64 addr64 = static_cast(reinterpret_cast(addr)); + if (g_sym_from_addr(GetCurrentProcess(), addr64, &sym_off, sym)) { + std::string out = std::format("{}+{:#x}", sym->Name, static_cast(sym_off)); + if (g_sym_get_line) { + IMAGEHLP_LINE64 line = {}; + line.SizeOfStruct = sizeof(line); + DWORD line_off = 0; + if (g_sym_get_line(GetCurrentProcess(), addr64, &line_off, &line)) { + out += std::format(" [{}:{}]", line.FileName, line.LineNumber); + } + } + return out; + } + } + HMODULE mod = nullptr; + if (GetModuleHandleExA(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS + | GET_MODULE_HANDLE_EX_FLAG_UNCHANGED_REFCOUNT, + reinterpret_cast(addr), &mod) + && mod) { + char path[MAX_PATH] = ""; + GetModuleFileNameA(mod, path, MAX_PATH); + const char* base = path; + for (const char* p = path; *p; ++p) { + if (*p == '\\') { + base = p + 1; + } + } + return std::format("{}+{:#x}", base, + reinterpret_cast(addr) - reinterpret_cast(mod)); + } + return std::format("{:#x}", reinterpret_cast(addr)); +} + +static LONG CALLBACK exception_logger(EXCEPTION_POINTERS* ep) +{ + const EXCEPTION_RECORD* rec = ep->ExceptionRecord; + const DWORD code = rec->ExceptionCode; + const bool is_cpp = code == 0xE06D7363u; + const bool is_av = code == 0xC0000005u; + if ((!is_cpp && !is_av) || g_num_logged >= max_logged) { + return EXCEPTION_CONTINUE_SEARCH; + } + ++g_num_logged; + // Load dbghelp now rather than lazily from addr_str(): the C++ throw branch below + // reaches the stack walk without ever calling addr_str(), and StackWalk64 would be + // skipped on the very first exception. + sym_init(); + + if (is_cpp) { + char type_name[192]; + char what_msg[256]; + probe_throw(rec, type_name, sizeof(type_name), what_msg, sizeof(what_msg)); + xlog::warn("[first-chance {}] C++ throw type={} what={}", g_num_logged, type_name, what_msg); + } + else { + const char* op = "read"; + if (rec->NumberParameters >= 1) { + if (rec->ExceptionInformation[0] == 1) { + op = "write"; + } + else if (rec->ExceptionInformation[0] == 8) { + op = "execute"; + } + } + const uintptr_t bad = rec->NumberParameters >= 2 ? rec->ExceptionInformation[1] : 0; + xlog::warn("[first-chance {}] access violation {} at {:#x}, pc={}", g_num_logged, op, bad, + addr_str(rec->ExceptionAddress)); + } + + // Release x86 omits frame pointers, so a naive EBP walk stops after a few frames. + // StackWalk64 uses the FPO/unwind data from the PDB and gets the whole chain. + std::string trace; + if (g_stack_walk && g_table_access && g_module_base) { + CONTEXT ctx = *ep->ContextRecord; // StackWalk64 modifies it, so work on a copy + STACKFRAME64 sf = {}; + sf.AddrPC.Offset = ctx.Eip; + sf.AddrPC.Mode = AddrModeFlat; + sf.AddrFrame.Offset = ctx.Ebp; + sf.AddrFrame.Mode = AddrModeFlat; + sf.AddrStack.Offset = ctx.Esp; + sf.AddrStack.Mode = AddrModeFlat; + for (int i = 0; i < 28; ++i) { + if (!g_stack_walk(IMAGE_FILE_MACHINE_I386, GetCurrentProcess(), GetCurrentThread(), + &sf, &ctx, nullptr, g_table_access, g_module_base, nullptr)) { + break; + } + if (sf.AddrPC.Offset == 0) { + break; + } + trace += "\n "; + trace += addr_str(reinterpret_cast(static_cast(sf.AddrPC.Offset))); + } + } + else { + void* frames[32] = {}; + USHORT n = RtlCaptureStackBackTrace(0, 32, frames, nullptr); + for (USHORT i = 0; i < n; ++i) { + trace += "\n "; + trace += addr_str(frames[i]); + } + } + xlog::warn("[first-chance {}] stack:{}", g_num_logged, trace); + + return EXCEPTION_CONTINUE_SEARCH; +} + +void exception_logger_init() +{ + AddVectoredExceptionHandler(1, exception_logger); +} diff --git a/game_patch/main/main.cpp b/game_patch/main/main.cpp index c3eae25d6..ff494c26c 100644 --- a/game_patch/main/main.cpp +++ b/game_patch/main/main.cpp @@ -578,6 +578,7 @@ extern "C" DWORD __declspec(dllexport) Init([[maybe_unused]] void* unused) level_init_post_hook.install(); // Init modules + exception_logger_init(); console_apply_patches(); gr_apply_patch(); bm_apply_patch();