From 27afb0ba38dcf0e74a4d09ba43e73261542b8e96 Mon Sep 17 00:00:00 2001 From: Emma Miler Date: Mon, 19 Dec 2022 19:32:16 +0100 Subject: Restructuring (#365) * Remove launcher proxy * Restructuring * More restructuring * Fix include dirs * Fix merge * Remove clang thing * Filters * Oops --- NorthstarDLL/logging/crashhandler.cpp | 376 +++++++++++++++++++++++++++++++++ NorthstarDLL/logging/crashhandler.h | 26 +++ NorthstarDLL/logging/logging.cpp | 205 ++++++++++++++++++ NorthstarDLL/logging/logging.h | 130 ++++++++++++ NorthstarDLL/logging/loghooks.cpp | 262 +++++++++++++++++++++++ NorthstarDLL/logging/loghooks.h | 1 + NorthstarDLL/logging/sourceconsole.cpp | 92 ++++++++ NorthstarDLL/logging/sourceconsole.h | 86 ++++++++ 8 files changed, 1178 insertions(+) create mode 100644 NorthstarDLL/logging/crashhandler.cpp create mode 100644 NorthstarDLL/logging/crashhandler.h create mode 100644 NorthstarDLL/logging/logging.cpp create mode 100644 NorthstarDLL/logging/logging.h create mode 100644 NorthstarDLL/logging/loghooks.cpp create mode 100644 NorthstarDLL/logging/loghooks.h create mode 100644 NorthstarDLL/logging/sourceconsole.cpp create mode 100644 NorthstarDLL/logging/sourceconsole.h (limited to 'NorthstarDLL/logging') diff --git a/NorthstarDLL/logging/crashhandler.cpp b/NorthstarDLL/logging/crashhandler.cpp new file mode 100644 index 00000000..d4a54169 --- /dev/null +++ b/NorthstarDLL/logging/crashhandler.cpp @@ -0,0 +1,376 @@ +#include "pch.h" +#include "crashhandler.h" +#include "dedicated/dedicated.h" +#include "config/profile.h" +#include "util/version.h" +#include "mods/modmanager.h" + +#include + +HANDLE hExceptionFilter; + +std::shared_ptr storedException {}; + +#define RUNTIME_EXCEPTION 3765269347 +// clang format did this :/ +std::map ExceptionNames = { + {EXCEPTION_ACCESS_VIOLATION, "Access Violation"}, {EXCEPTION_IN_PAGE_ERROR, "Access Violation"}, + {EXCEPTION_ARRAY_BOUNDS_EXCEEDED, "Array bounds exceeded"}, {EXCEPTION_DATATYPE_MISALIGNMENT, "Datatype misalignment"}, + {EXCEPTION_FLT_DENORMAL_OPERAND, "Denormal operand"}, {EXCEPTION_FLT_DIVIDE_BY_ZERO, "Divide by zero (float)"}, + {EXCEPTION_FLT_INEXACT_RESULT, "Inexact float result"}, {EXCEPTION_FLT_INVALID_OPERATION, "Invalid operation"}, + {EXCEPTION_FLT_OVERFLOW, "Numeric overflow (float)"}, {EXCEPTION_FLT_STACK_CHECK, "Stack check"}, + {EXCEPTION_FLT_UNDERFLOW, "Numeric underflow (float)"}, {EXCEPTION_ILLEGAL_INSTRUCTION, "Illegal instruction"}, + {EXCEPTION_INT_DIVIDE_BY_ZERO, "Divide by zero (int)"}, {EXCEPTION_INT_OVERFLOW, "Numeric overfloat (int)"}, + {EXCEPTION_INVALID_DISPOSITION, "Invalid disposition"}, {EXCEPTION_NONCONTINUABLE_EXCEPTION, "Non-continuable exception"}, + {EXCEPTION_PRIV_INSTRUCTION, "Priviledged instruction"}, {EXCEPTION_STACK_OVERFLOW, "Stack overflow"}, + {RUNTIME_EXCEPTION, "Uncaught runtime exception:"}, +}; + +void PrintExceptionLog(ExceptionLog& exc) +{ + // General crash message + spdlog::error("Northstar version: {}", version); + spdlog::error("Northstar has crashed! a minidump has been written and exception info is available below:"); + if (g_pModManager) + { + spdlog::error("Loaded mods: "); + for (const auto& mod : g_pModManager->m_LoadedMods) + { + if (mod.m_bEnabled) + { + spdlog::error("{} {}", mod.Name, mod.Version); + } + } + } + spdlog::error(exc.cause); + // If this was a runtime error, print the message + if (exc.runtimeInfo.length() != 0) + spdlog::error("\"{}\"", exc.runtimeInfo); + spdlog::error("At: {} + {}", exc.trace[0].name, exc.trace[0].relativeAddress); + spdlog::error(""); + spdlog::error("Stack trace:"); + + // Generate format string for stack trace + std::stringstream formatString; + formatString << " {:<" << exc.longestModuleNameLength + 2 << "} {:<" << exc.longestRelativeAddressLength << "} {}"; + std::string guide = fmt::format(formatString.str(), "Module Name", "Offset", "Full Address"); + std::string line(guide.length() + 2, '-'); + spdlog::error(guide); + spdlog::error(line); + + for (const auto& module : exc.trace) + spdlog::error(formatString.str(), module.name, module.relativeAddress, module.address); + + // Print dump of most CPU registers + spdlog::error(""); + for (const auto& reg : exc.registerDump) + spdlog::error(reg); + + if (!IsDedicatedServer()) + MessageBoxA( + 0, + "Northstar has crashed! Crash info can be found in R2Northstar/logs", + "Northstar has crashed!", + MB_ICONERROR | MB_OK | MB_SYSTEMMODAL); +} + +std::string GetExceptionName(ExceptionLog& exc) +{ + const DWORD exceptionCode = exc.exceptionRecord.ExceptionCode; + auto name = ExceptionNames[exceptionCode]; + if (exceptionCode == EXCEPTION_ACCESS_VIOLATION || exceptionCode == EXCEPTION_IN_PAGE_ERROR) + { + std::stringstream returnString; + returnString << name << ": "; + + auto exceptionInfo0 = exc.exceptionRecord.ExceptionInformation[0]; + auto exceptionInfo1 = exc.exceptionRecord.ExceptionInformation[1]; + + if (!exceptionInfo0) + returnString << "Attempted to read from: 0x" << (void*)exceptionInfo1; + else if (exceptionInfo0 == 1) + returnString << "Attempted to write to: 0x" << (void*)exceptionInfo1; + else if (exceptionInfo0 == 8) + returnString << "Data Execution Prevention (DEP) at: 0x" << (void*)std::hex << exceptionInfo1; + else + returnString << "Unknown access violation at: 0x" << (void*)exceptionInfo1; + return returnString.str(); + } + return name; +} + +// Custom formatter for the Xmm registers +template <> struct fmt::formatter : fmt::formatter +{ + template auto format(const M128A& obj, FormatContext& ctx) + { + // Masking the top and bottom half of the long long + int v1 = obj.Low & INT_MAX; + int v2 = obj.Low >> 32; + int v3 = obj.High & INT_MAX; + int v4 = obj.High >> 32; + return fmt::format_to( + ctx.out(), + "[ {:G}, {:G}, {:G}, {:G}], [ 0x{:x}, 0x{:x}, 0x{:x}, 0x{:x} ]", + *reinterpret_cast(&v1), + *reinterpret_cast(&v2), + *reinterpret_cast(&v3), + *reinterpret_cast(&v4), + v1, + v2, + v3, + v4); + } +}; + +void GenerateTrace(ExceptionLog& exc, bool skipErrorHandlingFrames = true, int numSkipFrames = 0) +{ + + MODULEINFO crashedModuleInfo; + GetModuleInformation(GetCurrentProcess(), exc.crashedModule, &crashedModuleInfo, sizeof(crashedModuleInfo)); + + char crashedModuleFullName[MAX_PATH]; + GetModuleFileNameExA(GetCurrentProcess(), exc.crashedModule, crashedModuleFullName, MAX_PATH); + char* crashedModuleName = strrchr(crashedModuleFullName, '\\') + 1; + + DWORD64 crashedModuleOffset = ((DWORD64)exc.exceptionRecord.ExceptionAddress) - ((DWORD64)crashedModuleInfo.lpBaseOfDll); + + PVOID framesToCapture[62]; + int frames = RtlCaptureStackBackTrace(0, 62, framesToCapture, NULL); + bool haveSkippedErrorHandlingFrames = false; + + for (int i = 0; i < frames; i++) + { + + HMODULE backtraceModuleHandle; + GetModuleHandleExA(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS, static_cast(framesToCapture[i]), &backtraceModuleHandle); + + char backtraceModuleFullName[MAX_PATH]; + GetModuleFileNameExA(GetCurrentProcess(), backtraceModuleHandle, backtraceModuleFullName, MAX_PATH); + char* backtraceModuleName = strrchr(backtraceModuleFullName, '\\') + 1; + + if (!haveSkippedErrorHandlingFrames) + { + if (!strncmp(backtraceModuleFullName, crashedModuleFullName, MAX_PATH) && + !strncmp(backtraceModuleName, crashedModuleName, MAX_PATH)) + { + haveSkippedErrorHandlingFrames = true; + } + else + { + continue; + } + } + + if (numSkipFrames > 0) + { + numSkipFrames--; + continue; + } + + void* actualAddress = (void*)framesToCapture[i]; + void* relativeAddress = (void*)(uintptr_t(actualAddress) - uintptr_t(backtraceModuleHandle)); + std::string s_moduleName {backtraceModuleName}; + std::string s_relativeAddress {fmt::format("{}", relativeAddress)}; + // These are used for formatting later on + if (s_moduleName.length() > exc.longestModuleNameLength) + { + exc.longestModuleNameLength = s_moduleName.length(); + } + if (s_relativeAddress.length() > exc.longestRelativeAddressLength) + { + exc.longestRelativeAddressLength = s_relativeAddress.length(); + } + + exc.trace.push_back(BacktraceModule {s_moduleName, s_relativeAddress, fmt::format("{}", actualAddress)}); + } + + CONTEXT* exceptionContext = &exc.contextRecord; + + exc.registerDump.push_back(fmt::format("Flags: 0b{0:b}", exceptionContext->ContextFlags)); + exc.registerDump.push_back(fmt::format("RIP: 0x{0:x}", exceptionContext->Rip)); + exc.registerDump.push_back(fmt::format("CS : 0x{0:x}", exceptionContext->SegCs)); + exc.registerDump.push_back(fmt::format("DS : 0x{0:x}", exceptionContext->SegDs)); + exc.registerDump.push_back(fmt::format("ES : 0x{0:x}", exceptionContext->SegEs)); + exc.registerDump.push_back(fmt::format("SS : 0x{0:x}", exceptionContext->SegSs)); + exc.registerDump.push_back(fmt::format("FS : 0x{0:x}", exceptionContext->SegFs)); + exc.registerDump.push_back(fmt::format("GS : 0x{0:x}", exceptionContext->SegGs)); + + exc.registerDump.push_back(fmt::format("RAX: 0x{0:x}", exceptionContext->Rax)); + exc.registerDump.push_back(fmt::format("RBX: 0x{0:x}", exceptionContext->Rbx)); + exc.registerDump.push_back(fmt::format("RCX: 0x{0:x}", exceptionContext->Rcx)); + exc.registerDump.push_back(fmt::format("RDX: 0x{0:x}", exceptionContext->Rdx)); + exc.registerDump.push_back(fmt::format("RSI: 0x{0:x}", exceptionContext->Rsi)); + exc.registerDump.push_back(fmt::format("RDI: 0x{0:x}", exceptionContext->Rdi)); + exc.registerDump.push_back(fmt::format("RBP: 0x{0:x}", exceptionContext->Rbp)); + exc.registerDump.push_back(fmt::format("RSP: 0x{0:x}", exceptionContext->Rsp)); + exc.registerDump.push_back(fmt::format("R8 : 0x{0:x}", exceptionContext->R8)); + exc.registerDump.push_back(fmt::format("R9 : 0x{0:x}", exceptionContext->R9)); + exc.registerDump.push_back(fmt::format("R10: 0x{0:x}", exceptionContext->R10)); + exc.registerDump.push_back(fmt::format("R11: 0x{0:x}", exceptionContext->R11)); + exc.registerDump.push_back(fmt::format("R12: 0x{0:x}", exceptionContext->R12)); + exc.registerDump.push_back(fmt::format("R13: 0x{0:x}", exceptionContext->R13)); + exc.registerDump.push_back(fmt::format("R14: 0x{0:x}", exceptionContext->R14)); + exc.registerDump.push_back(fmt::format("R15: 0x{0:x}", exceptionContext->R15)); + + exc.registerDump.push_back(fmt::format("Xmm0 : {}", exceptionContext->Xmm0)); + exc.registerDump.push_back(fmt::format("Xmm1 : {}", exceptionContext->Xmm1)); + exc.registerDump.push_back(fmt::format("Xmm2 : {}", exceptionContext->Xmm2)); + exc.registerDump.push_back(fmt::format("Xmm3 : {}", exceptionContext->Xmm3)); + exc.registerDump.push_back(fmt::format("Xmm4 : {}", exceptionContext->Xmm4)); + exc.registerDump.push_back(fmt::format("Xmm5 : {}", exceptionContext->Xmm5)); + exc.registerDump.push_back(fmt::format("Xmm6 : {}", exceptionContext->Xmm6)); + exc.registerDump.push_back(fmt::format("Xmm7 : {}", exceptionContext->Xmm7)); + exc.registerDump.push_back(fmt::format("Xmm8 : {}", exceptionContext->Xmm8)); + exc.registerDump.push_back(fmt::format("Xmm9 : {}", exceptionContext->Xmm9)); + exc.registerDump.push_back(fmt::format("Xmm10: {}", exceptionContext->Xmm10)); + exc.registerDump.push_back(fmt::format("Xmm11: {}", exceptionContext->Xmm11)); + exc.registerDump.push_back(fmt::format("Xmm12: {}", exceptionContext->Xmm12)); + exc.registerDump.push_back(fmt::format("Xmm13: {}", exceptionContext->Xmm13)); + exc.registerDump.push_back(fmt::format("Xmm14: {}", exceptionContext->Xmm14)); + exc.registerDump.push_back(fmt::format("Xmm15: {}", exceptionContext->Xmm15)); +} + +void CreateMiniDump(EXCEPTION_POINTERS* exceptionInfo) +{ + time_t time = std::time(nullptr); + tm currentTime = *std::localtime(&time); + std::stringstream stream; + stream << std::put_time(¤tTime, (GetNorthstarPrefix() + "/logs/nsdump%Y-%m-%d %H-%M-%S.dmp").c_str()); + + auto hMinidumpFile = CreateFileA(stream.str().c_str(), GENERIC_WRITE, FILE_SHARE_READ, 0, CREATE_ALWAYS, FILE_ATTRIBUTE_NORMAL, 0); + if (hMinidumpFile) + { + MINIDUMP_EXCEPTION_INFORMATION dumpExceptionInfo; + dumpExceptionInfo.ThreadId = GetCurrentThreadId(); + dumpExceptionInfo.ExceptionPointers = exceptionInfo; + dumpExceptionInfo.ClientPointers = false; + + MiniDumpWriteDump( + GetCurrentProcess(), + GetCurrentProcessId(), + hMinidumpFile, + MINIDUMP_TYPE(MiniDumpWithIndirectlyReferencedMemory | MiniDumpScanMemory), + &dumpExceptionInfo, + nullptr, + nullptr); + CloseHandle(hMinidumpFile); + } + else + spdlog::error("Failed to write minidump file {}!", stream.str()); +} + +long GenerateExceptionLog(EXCEPTION_POINTERS* exceptionInfo) +{ + storedException->exceptionRecord = *exceptionInfo->ExceptionRecord; + storedException->contextRecord = *exceptionInfo->ContextRecord; + const DWORD exceptionCode = exceptionInfo->ExceptionRecord->ExceptionCode; + + void* exceptionAddress = exceptionInfo->ExceptionRecord->ExceptionAddress; + + storedException->cause = GetExceptionName(*storedException); + + HMODULE crashedModuleHandle; + GetModuleHandleExA(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS, static_cast(exceptionAddress), &crashedModuleHandle); + + storedException->crashedModule = crashedModuleHandle; + + // When encountering a runtime exception, we store the exception to be displayed later + // We then have to return EXCEPTION_CONTINUE_SEARCH so that our runtime handler may be called + // This might possibly cause some issues if client and server are crashing at the same time, but honestly i don't care + if (exceptionCode == RUNTIME_EXCEPTION) + { + GenerateTrace(*storedException, false, 2); + storedException = storedException; + return EXCEPTION_CONTINUE_SEARCH; + } + + GenerateTrace(*storedException, true, 0); + CreateMiniDump(exceptionInfo); + PrintExceptionLog(*storedException); + return EXCEPTION_EXECUTE_HANDLER; +} + +long __stdcall ExceptionFilter(EXCEPTION_POINTERS* exceptionInfo) +{ + if (!IsDebuggerPresent()) + { + // Check if we are capable of handling this type of exception + if (ExceptionNames.find(exceptionInfo->ExceptionRecord->ExceptionCode) == ExceptionNames.end()) + return EXCEPTION_CONTINUE_SEARCH; + if (exceptionInfo->ExceptionRecord->ExceptionCode == RUNTIME_EXCEPTION) + { + storedException = std::make_shared(); + storedException->exceptionRecord = *exceptionInfo->ExceptionRecord; + storedException->contextRecord = *exceptionInfo->ContextRecord; + } + else + { + CreateMiniDump(exceptionInfo); + return GenerateExceptionLog(exceptionInfo); + } + } + + return EXCEPTION_EXECUTE_HANDLER; +} + +void RuntimeExceptionHandler() +{ + auto ptr = std::current_exception(); + if (ptr) + { + try + { + // This is to generate an actual std::exception object that we can then inspect + std::rethrow_exception(ptr); + } + catch (std::exception& e) + { + storedException->runtimeInfo = e.what(); + } + catch (...) + { + storedException->runtimeInfo = "Unknown runtime exception type"; + } + EXCEPTION_POINTERS test {}; + test.ContextRecord = &storedException->contextRecord; + test.ExceptionRecord = &storedException->exceptionRecord; + CreateMiniDump(&test); + GenerateExceptionLog(&test); + PrintExceptionLog(*storedException); + exit(-1); + } + else + { + spdlog::error( + "std::current_exception() returned nullptr while being handled by RuntimeExceptionHandler. This should never happen!"); + std::abort(); + } +} + +BOOL WINAPI ConsoleHandlerRoutine(DWORD eventCode) +{ + switch (eventCode) + { + case CTRL_CLOSE_EVENT: + // User closed console, shut everything down + spdlog::info("Exiting due to console close..."); + RemoveCrashHandler(); + exit(EXIT_SUCCESS); + return FALSE; + } + + return TRUE; +} + +void InitialiseCrashHandler() +{ + hExceptionFilter = AddVectoredExceptionHandler(TRUE, ExceptionFilter); + SetConsoleCtrlHandler(ConsoleHandlerRoutine, true); + std::set_terminate(RuntimeExceptionHandler); +} + +void RemoveCrashHandler() +{ + RemoveVectoredExceptionHandler(hExceptionFilter); +} diff --git a/NorthstarDLL/logging/crashhandler.h b/NorthstarDLL/logging/crashhandler.h new file mode 100644 index 00000000..4d8a59ce --- /dev/null +++ b/NorthstarDLL/logging/crashhandler.h @@ -0,0 +1,26 @@ +#pragma once + +void InitialiseCrashHandler(); +void RemoveCrashHandler(); + +struct BacktraceModule +{ + std::string name; + std::string relativeAddress; + std::string address; +}; + +struct ExceptionLog +{ + std::string cause; + HMODULE crashedModule; + EXCEPTION_RECORD exceptionRecord; + CONTEXT contextRecord; + std::vector trace; + std::vector registerDump; + + std::string runtimeInfo; + + int longestModuleNameLength; + int longestRelativeAddressLength; +}; diff --git a/NorthstarDLL/logging/logging.cpp b/NorthstarDLL/logging/logging.cpp new file mode 100644 index 00000000..6bb57170 --- /dev/null +++ b/NorthstarDLL/logging/logging.cpp @@ -0,0 +1,205 @@ +#include "pch.h" +#include "logging.h" +#include "core/convar/convar.h" +#include "core/convar/concommand.h" +#include "config/profile.h" +#include "core/tier0.h" +#include "spdlog/sinks/basic_file_sink.h" + +#include +#include + +AUTOHOOK_INIT() + +std::vector> loggers {}; + +namespace NS::log +{ + std::shared_ptr SCRIPT_UI; + std::shared_ptr SCRIPT_CL; + std::shared_ptr SCRIPT_SV; + + std::shared_ptr NATIVE_UI; + std::shared_ptr NATIVE_CL; + std::shared_ptr NATIVE_SV; + std::shared_ptr NATIVE_EN; + + std::shared_ptr fs; + std::shared_ptr rpak; + std::shared_ptr echo; + + std::shared_ptr NORTHSTAR; +}; // namespace NS::log + +// This needs to be called after hooks are loaded so we can access the command line args +void CreateLogFiles() +{ + if (strstr(GetCommandLineA(), "-disablelogs")) + { + spdlog::default_logger()->set_level(spdlog::level::off); + } + else + { + try + { + // todo: might be good to delete logs that are too old + time_t time = std::time(nullptr); + tm currentTime = *std::localtime(&time); + std::stringstream stream; + + stream << std::put_time(¤tTime, (GetNorthstarPrefix() + "/logs/nslog%Y-%m-%d %H-%M-%S.txt").c_str()); + auto sink = std::make_shared(stream.str(), false); + sink->set_pattern("[%H:%M:%S] [%n] [%l] %v"); + for (auto& logger : loggers) + { + logger->sinks().push_back(sink); + } + spdlog::flush_on(spdlog::level::info); + } + catch (...) + { + spdlog::error("Failed creating log file!"); + MessageBoxA( + 0, "Failed creating log file! Make sure the profile directory is writable.", "Northstar Warning", MB_ICONWARNING | MB_OK); + } + } +} + +void ExternalConsoleSink::sink_it_(const spdlog::details::log_msg& msg) +{ + throw std::runtime_error("sink_it_ called on SourceConsoleSink with pure log_msg. This is an error!"); +} + +void ExternalConsoleSink::custom_sink_it_(const custom_log_msg& msg) +{ + spdlog::memory_buf_t formatted; + spdlog::sinks::base_sink::formatter_->format(msg, formatted); + + std::string out = ""; + // if ansi colour is turned off, just use WriteConsoleA and return + if (!g_bSpdLog_UseAnsiColor) + { + out += fmt::to_string(formatted); + } + + // print to the console with colours + else + { + // get message string + std::string str = fmt::to_string(formatted); + + std::string levelColor = m_LogColours[msg.level]; + std::string name {msg.logger_name.begin(), msg.logger_name.end()}; + + std::string name_str = "[NAME]"; + int name_pos = str.find(name_str); + str.replace(name_pos, name_str.length(), msg.origin->ANSIColor + "[" + name + "]" + default_color); + + std::string level_str = "[LVL]"; + int level_pos = str.find(level_str); + str.replace(level_pos, level_str.length(), levelColor + "[" + std::string(level_names[msg.level]) + "]" + default_color); + + out += str; + } + // print the string to the console - this is definitely bad i think + HANDLE handle = GetStdHandle(STD_OUTPUT_HANDLE); + auto ignored = WriteConsoleA(handle, out.c_str(), std::strlen(out.c_str()), nullptr, nullptr); + (void)ignored; +} + +void ExternalConsoleSink::flush_() +{ + std::cout << std::flush; +} + +void CustomSink::custom_log(const custom_log_msg& msg) +{ + std::lock_guard lock(mutex_); + custom_sink_it_(msg); +} + +void InitialiseConsole() +{ + if (AllocConsole() == FALSE) + { + std::cout << "[*] Failed to create a console window, maybe a console already exists?" << std::endl; + } + else + { + freopen("CONOUT$", "w", stdout); + freopen("CONOUT$", "w", stderr); + } + + // this if statement is adapted from r5sdk + if (!strstr(GetCommandLineA(), "-noansiclr")) + { + g_bSpdLog_UseAnsiColor = true; + DWORD dwMode = NULL; + HANDLE hOutput = GetStdHandle(STD_OUTPUT_HANDLE); + + GetConsoleMode(hOutput, &dwMode); + dwMode |= ENABLE_PROCESSED_OUTPUT | ENABLE_VIRTUAL_TERMINAL_PROCESSING; + + if (!SetConsoleMode(hOutput, dwMode)) // Some editions of Windows have 'VirtualTerminalLevel' disabled by default. + { + // If 'VirtualTerminalLevel' can't be set, just disable ANSI color, since it wouldnt work anyway. + spdlog::warn("could not set VirtualTerminalLevel. Disabling color output"); + g_bSpdLog_UseAnsiColor = false; + } + } +} + +void RegisterCustomSink(std::shared_ptr sink) +{ + for (auto& logger : loggers) + { + logger->custom_sinks_.push_back(sink); + } +}; + +void InitialiseLogging() +{ + // create a logger, and set it to default + NS::log::NORTHSTAR = std::make_shared("NORTHSTAR", NS::Colors::NORTHSTAR, true); + NS::log::NORTHSTAR->sinks().clear(); + loggers.push_back(NS::log::NORTHSTAR); + spdlog::set_default_logger(NS::log::NORTHSTAR); + + // create our console sink + auto sink = std::make_shared(); + // set the pattern + if (g_bSpdLog_UseAnsiColor) + // dont put the log level in the pattern if we are using colours, as the colour will show the log level + sink->set_pattern("[%H:%M:%S] [NAME] [LVL] %v"); + else + sink->set_pattern("[%H:%M:%S] [%n] [%l] %v"); + + // add our sink to the logger + NS::log::NORTHSTAR->custom_sinks_.push_back(sink); + + NS::log::SCRIPT_UI = std::make_shared("SCRIPT UI", NS::Colors::SCRIPT_UI); + NS::log::SCRIPT_CL = std::make_shared("SCRIPT CL", NS::Colors::SCRIPT_CL); + NS::log::SCRIPT_SV = std::make_shared("SCRIPT SV", NS::Colors::SCRIPT_SV); + + NS::log::NATIVE_UI = std::make_shared("NATIVE UI", NS::Colors::NATIVE_UI); + NS::log::NATIVE_CL = std::make_shared("NATIVE CL", NS::Colors::NATIVE_CL); + NS::log::NATIVE_SV = std::make_shared("NATIVE SV", NS::Colors::NATIVE_SV); + NS::log::NATIVE_EN = std::make_shared("NATIVE EN", NS::Colors::NATIVE_ENGINE); + + NS::log::fs = std::make_shared("FILESYSTM", NS::Colors::FILESYSTEM); + NS::log::rpak = std::make_shared("RPAK_FSYS", NS::Colors::RPAK); + NS::log::echo = std::make_shared("ECHO", NS::Colors::ECHO); + + loggers.push_back(NS::log::SCRIPT_UI); + loggers.push_back(NS::log::SCRIPT_CL); + loggers.push_back(NS::log::SCRIPT_SV); + + loggers.push_back(NS::log::NATIVE_UI); + loggers.push_back(NS::log::NATIVE_CL); + loggers.push_back(NS::log::NATIVE_SV); + loggers.push_back(NS::log::NATIVE_EN); + + loggers.push_back(NS::log::fs); + loggers.push_back(NS::log::rpak); + loggers.push_back(NS::log::echo); +} diff --git a/NorthstarDLL/logging/logging.h b/NorthstarDLL/logging/logging.h new file mode 100644 index 00000000..af20c3e8 --- /dev/null +++ b/NorthstarDLL/logging/logging.h @@ -0,0 +1,130 @@ +#pragma once +#include "pch.h" +#include "spdlog/sinks/base_sink.h" +#include "spdlog/logger.h" +#include "core/math/color.h" + +void CreateLogFiles(); +void InitialiseLogging(); +void InitialiseConsole(); + +class ColoredLogger; + +struct custom_log_msg : spdlog::details::log_msg +{ + public: + custom_log_msg(ColoredLogger* origin, spdlog::details::log_msg msg) : origin(origin), spdlog::details::log_msg(msg) {} + + ColoredLogger* origin; +}; + +class CustomSink : public spdlog::sinks::base_sink +{ + public: + void custom_log(const custom_log_msg& msg); + virtual void custom_sink_it_(const custom_log_msg& msg) + { + throw std::runtime_error("Pure virtual call to CustomSink::custom_sink_it_"); + } +}; + +class ColoredLogger : public spdlog::logger +{ + public: + std::string ANSIColor; + SourceColor SRCColor; + + std::vector> custom_sinks_; + + ColoredLogger(std::string name, Color color, bool first = false) : spdlog::logger(*spdlog::default_logger()) + { + name_ = std::move(name); + if (!first) + { + custom_sinks_ = dynamic_pointer_cast(spdlog::default_logger())->custom_sinks_; + } + + ANSIColor = color.ToANSIColor(); + SRCColor = color.ToSourceColor(); + } + + void sink_it_(const spdlog::details::log_msg& msg) + { + custom_log_msg custom_msg {this, msg}; + + // Ugh + for (auto& sink : sinks_) + { + SPDLOG_TRY + { + sink->log(custom_msg); + } + SPDLOG_LOGGER_CATCH() + } + + for (auto& sink : custom_sinks_) + { + SPDLOG_TRY + { + sink->custom_log(custom_msg); + } + SPDLOG_LOGGER_CATCH() + } + + if (should_flush_(custom_msg)) + { + flush_(); + } + } +}; + +namespace NS::log +{ + // Squirrel + extern std::shared_ptr SCRIPT_UI; + extern std::shared_ptr SCRIPT_CL; + extern std::shared_ptr SCRIPT_SV; + + // Native code + extern std::shared_ptr NATIVE_UI; + extern std::shared_ptr NATIVE_CL; + extern std::shared_ptr NATIVE_SV; + extern std::shared_ptr NATIVE_EN; + + // File system + extern std::shared_ptr fs; + // RPak + extern std::shared_ptr rpak; + // Echo + extern std::shared_ptr echo; + + extern std::shared_ptr NORTHSTAR; +}; // namespace NS::log + +void RegisterCustomSink(std::shared_ptr sink); + +inline bool g_bSpdLog_UseAnsiColor = true; + +// Could maybe use some different names here, idk +static const char* level_names[] {"trac", "dbug", "info", "warn", "errr", "crit", "off"}; + +// spdlog logger, for cool colour things +class ExternalConsoleSink : public CustomSink +{ + private: + std::map m_LogColours = { + {spdlog::level::trace, NS::Colors::TRACE.ToANSIColor()}, + {spdlog::level::debug, NS::Colors::DEBUG.ToANSIColor()}, + {spdlog::level::info, NS::Colors::INFO.ToANSIColor()}, + {spdlog::level::warn, NS::Colors::WARN.ToANSIColor()}, + {spdlog::level::err, NS::Colors::ERR.ToANSIColor()}, + {spdlog::level::critical, NS::Colors::CRIT.ToANSIColor()}, + {spdlog::level::off, NS::Colors::OFF.ToANSIColor()}}; + + std::string default_color = "\033[39;49m"; + + protected: + void sink_it_(const spdlog::details::log_msg& msg) override; + void custom_sink_it_(const custom_log_msg& msg); + void flush_() override; +}; diff --git a/NorthstarDLL/logging/loghooks.cpp b/NorthstarDLL/logging/loghooks.cpp new file mode 100644 index 00000000..d09f23cc --- /dev/null +++ b/NorthstarDLL/logging/loghooks.cpp @@ -0,0 +1,262 @@ +#include "pch.h" +#include "logging.h" +#include "loghooks.h" +#include "core/convar/convar.h" +#include "core/convar/concommand.h" +#include "core/math/bitbuf.h" +#include "config/profile.h" +#include "core/tier0.h" +#include "squirrel/squirrel.h" +#include +#include + +AUTOHOOK_INIT() + +ConVar* Cvar_spewlog_enable; +ConVar* Cvar_cl_showtextmsg; + +enum class TextMsgPrintType_t +{ + HUD_PRINTNOTIFY = 1, + HUD_PRINTCONSOLE, + HUD_PRINTTALK, + HUD_PRINTCENTER +}; + +class ICenterPrint +{ + public: + virtual void ctor() = 0; + virtual void Clear(void) = 0; + virtual void ColorPrint(int r, int g, int b, int a, wchar_t* text) = 0; + virtual void ColorPrint(int r, int g, int b, int a, char* text) = 0; + virtual void Print(wchar_t* text) = 0; + virtual void Print(char* text) = 0; + virtual void SetTextColor(int r, int g, int b, int a) = 0; +}; + +enum class SpewType_t +{ + SPEW_MESSAGE = 0, + + SPEW_WARNING, + SPEW_ASSERT, + SPEW_ERROR, + SPEW_LOG, + + SPEW_TYPE_COUNT +}; + +const std::unordered_map PrintSpewTypes = { + {SpewType_t::SPEW_MESSAGE, "SPEW_MESSAGE"}, + {SpewType_t::SPEW_WARNING, "SPEW_WARNING"}, + {SpewType_t::SPEW_ASSERT, "SPEW_ASSERT"}, + {SpewType_t::SPEW_ERROR, "SPEW_ERROR"}, + {SpewType_t::SPEW_LOG, "SPEW_LOG"}}; + +// these are used to define the base text colour for these things +const std::unordered_map PrintSpewLevels = { + {SpewType_t::SPEW_MESSAGE, spdlog::level::level_enum::info}, + {SpewType_t::SPEW_WARNING, spdlog::level::level_enum::warn}, + {SpewType_t::SPEW_ASSERT, spdlog::level::level_enum::err}, + {SpewType_t::SPEW_ERROR, spdlog::level::level_enum::err}, + {SpewType_t::SPEW_LOG, spdlog::level::level_enum::info}}; + +const std::unordered_map PrintSpewTypes_Short = { + {SpewType_t::SPEW_MESSAGE, 'M'}, + {SpewType_t::SPEW_WARNING, 'W'}, + {SpewType_t::SPEW_ASSERT, 'A'}, + {SpewType_t::SPEW_ERROR, 'E'}, + {SpewType_t::SPEW_LOG, 'L'}}; + +ICenterPrint* pInternalCenterPrint = NULL; + +// clang-format off +AUTOHOOK(TextMsg, client.dll + 0x198710, +void,, (BFRead* msg)) +// clang-format on +{ + TextMsgPrintType_t msg_dest = (TextMsgPrintType_t)msg->ReadByte(); + + char text[256]; + msg->ReadString(text, sizeof(text)); + + if (!Cvar_cl_showtextmsg->GetBool()) + return; + + switch (msg_dest) + { + case TextMsgPrintType_t::HUD_PRINTCENTER: + pInternalCenterPrint->Print(text); + break; + + default: + spdlog::warn("Unimplemented TextMsg type {}! printing to console", msg_dest); + [[fallthrough]]; + + case TextMsgPrintType_t::HUD_PRINTCONSOLE: + auto endpos = strlen(text); + if (text[endpos - 1] == '\n') + text[endpos - 1] = '\0'; // cut off repeated newline + + spdlog::info(text); + break; + } +} + +// clang-format off +AUTOHOOK(Hook_fprintf, engine.dll + 0x51B1F0, +int,, (void* const stream, const char* const format, ...)) +// clang-format on +{ + va_list va; + va_start(va, format); + + SQChar buf[1024]; + int charsWritten = vsnprintf_s(buf, _TRUNCATE, format, va); + + if (charsWritten > 0) + { + if (buf[charsWritten - 1] == '\n') + buf[charsWritten - 1] = '\0'; + NS::log::NATIVE_EN->info("{}", buf); + } + + va_end(va); + return 0; +} + +// clang-format off +AUTOHOOK(ConCommand_echo, engine.dll + 0x123680, +void,, (const CCommand& arg)) +// clang-format on +{ + if (arg.ArgC() >= 2) + NS::log::echo->info("{}", arg.ArgS()); +} + +// clang-format off +AUTOHOOK(EngineSpewFunc, engine.dll + 0x11CA80, +void, __fastcall, (void* pEngineServer, SpewType_t type, const char* format, va_list args)) +// clang-format on +{ + if (!Cvar_spewlog_enable->GetBool()) + return; + + const char* typeStr = PrintSpewTypes.at(type); + char formatted[2048] = {0}; + bool bShouldFormat = true; + + // because titanfall 2 is quite possibly the worst thing to yet exist, it sometimes gives invalid specifiers which will crash + // ttf2sdk had a way to prevent them from crashing but it doesnt work in debug builds + // so we use this instead + for (int i = 0; format[i]; i++) + { + if (format[i] == '%') + { + switch (format[i + 1]) + { + // this is fucking awful lol + case 'd': + case 'i': + case 'u': + case 'x': + case 'X': + case 'f': + case 'F': + case 'g': + case 'G': + case 'a': + case 'A': + case 'c': + case 's': + case 'p': + case 'n': + case '%': + case '-': + case '+': + case ' ': + case '#': + case '*': + case '0': + case '1': + case '2': + case '3': + case '4': + case '5': + case '6': + case '7': + case '8': + case '9': + break; + + default: + { + bShouldFormat = false; + break; + } + } + } + } + + if (bShouldFormat) + vsnprintf(formatted, sizeof(formatted), format, args); + else + spdlog::warn("Failed to format {} \"{}\"", typeStr, format); + + auto endpos = strlen(formatted); + if (formatted[endpos - 1] == '\n') + formatted[endpos - 1] = '\0'; // cut off repeated newline + + NS::log::NATIVE_SV->log(PrintSpewLevels.at(type), "{}", formatted); +} + +// used for printing the output of status +// clang-format off +AUTOHOOK(Status_ConMsg, engine.dll + 0x15ABD0, +void,, (const char* text, ...)) +// clang-format on +{ + char formatted[2048]; + va_list list; + + va_start(list, text); + vsprintf_s(formatted, text, list); + va_end(list); + + auto endpos = strlen(formatted); + if (formatted[endpos - 1] == '\n') + formatted[endpos - 1] = '\0'; // cut off repeated newline + + spdlog::info(formatted); +} + +// clang-format off +AUTOHOOK(CClientState_ProcessPrint, engine.dll + 0x1A1530, +bool,, (void* thisptr, uintptr_t msg)) +// clang-format on +{ + char* text = *(char**)(msg + 0x20); + + auto endpos = strlen(text); + if (text[endpos - 1] == '\n') + text[endpos - 1] = '\0'; // cut off repeated newline + + spdlog::info(text); + return true; +} + +ON_DLL_LOAD_RELIESON("engine.dll", EngineSpewFuncHooks, ConVar, (CModule module)) +{ + AUTOHOOK_DISPATCH_MODULE(engine.dll) + + Cvar_spewlog_enable = new ConVar("spewlog_enable", "1", FCVAR_NONE, "Enables/disables whether the engine spewfunc should be logged"); +} + +ON_DLL_LOAD_CLIENT_RELIESON("client.dll", ClientPrintHooks, ConVar, (CModule module)) +{ + AUTOHOOK_DISPATCH_MODULE(client.dll) + + Cvar_cl_showtextmsg = new ConVar("cl_showtextmsg", "1", FCVAR_NONE, "Enable/disable text messages printing on the screen."); + pInternalCenterPrint = module.Offset(0x216E940).As(); +} diff --git a/NorthstarDLL/logging/loghooks.h b/NorthstarDLL/logging/loghooks.h new file mode 100644 index 00000000..6f70f09b --- /dev/null +++ b/NorthstarDLL/logging/loghooks.h @@ -0,0 +1 @@ +#pragma once diff --git a/NorthstarDLL/logging/sourceconsole.cpp b/NorthstarDLL/logging/sourceconsole.cpp new file mode 100644 index 00000000..62b41e1a --- /dev/null +++ b/NorthstarDLL/logging/sourceconsole.cpp @@ -0,0 +1,92 @@ +#include "pch.h" +#include "core/convar/convar.h" +#include "sourceconsole.h" +#include "shared/sourceinterface.h" +#include "core/convar/concommand.h" +#include "util/printcommands.h" + +SourceInterface* g_pSourceGameConsole; + +void ConCommand_toggleconsole(const CCommand& arg) +{ + if ((*g_pSourceGameConsole)->IsConsoleVisible()) + (*g_pSourceGameConsole)->Hide(); + else + (*g_pSourceGameConsole)->Activate(); +} + +void ConCommand_showconsole(const CCommand& arg) +{ + (*g_pSourceGameConsole)->Activate(); +} + +void ConCommand_hideconsole(const CCommand& arg) +{ + (*g_pSourceGameConsole)->Hide(); +} + +void SourceConsoleSink::custom_sink_it_(const custom_log_msg& msg) +{ + if (!(*g_pSourceGameConsole)->m_bInitialized) + return; + + spdlog::memory_buf_t formatted; + spdlog::sinks::base_sink::formatter_->format(msg, formatted); + + // get message string + std::string str = fmt::to_string(formatted); + + SourceColor levelColor = m_LogColours[msg.level]; + std::string name {msg.logger_name.begin(), msg.logger_name.end()}; + + (*g_pSourceGameConsole)->m_pConsole->m_pConsolePanel->ColorPrint(msg.origin->SRCColor, ("[" + name + "]").c_str()); + (*g_pSourceGameConsole)->m_pConsole->m_pConsolePanel->Print(" "); + (*g_pSourceGameConsole)->m_pConsole->m_pConsolePanel->ColorPrint(levelColor, ("[" + std::string(level_names[msg.level]) + "]").c_str()); + (*g_pSourceGameConsole)->m_pConsole->m_pConsolePanel->Print(" "); + (*g_pSourceGameConsole)->m_pConsole->m_pConsolePanel->Print(fmt::to_string(formatted).c_str()); +} + +void SourceConsoleSink::sink_it_(const spdlog::details::log_msg& msg) +{ + throw std::runtime_error("sink_it_ called on SourceConsoleSink with pure log_msg. This is an error!"); +} + +void SourceConsoleSink::flush_() {} + +// clang-format off +HOOK(OnCommandSubmittedHook, OnCommandSubmitted, +void, __fastcall, (CConsoleDialog* consoleDialog, const char* pCommand)) +// clang-format on +{ + consoleDialog->m_pConsolePanel->Print("] "); + consoleDialog->m_pConsolePanel->Print(pCommand); + consoleDialog->m_pConsolePanel->Print("\n"); + + TryPrintCvarHelpForCommand(pCommand); + + OnCommandSubmitted(consoleDialog, pCommand); +} + +// called from sourceinterface.cpp in client createinterface hooks, on GameClientExports001 +void InitialiseConsoleOnInterfaceCreation() +{ + (*g_pSourceGameConsole)->Initialize(); + // hook OnCommandSubmitted so we print inputted commands + OnCommandSubmittedHook.Dispatch((*g_pSourceGameConsole)->m_pConsole->m_vtable->OnCommandSubmitted); + + auto consoleSink = std::make_shared(); + if (g_bSpdLog_UseAnsiColor) + consoleSink->set_pattern("%v"); // no need to include the level in the game console, the text colour signifies it anyway + else + consoleSink->set_pattern("[%n] [%l] %v"); // no colour, so we should show the level for colourblind people + RegisterCustomSink(consoleSink); +} + +ON_DLL_LOAD_CLIENT_RELIESON("client.dll", SourceConsole, ConCommand, (CModule module)) +{ + g_pSourceGameConsole = new SourceInterface("client.dll", "GameConsole004"); + + RegisterConCommand("toggleconsole", ConCommand_toggleconsole, "Show/hide the console.", FCVAR_DONTRECORD); + RegisterConCommand("showconsole", ConCommand_showconsole, "Show the console.", FCVAR_DONTRECORD); + RegisterConCommand("hideconsole", ConCommand_hideconsole, "Hide the console.", FCVAR_DONTRECORD); +} diff --git a/NorthstarDLL/logging/sourceconsole.h b/NorthstarDLL/logging/sourceconsole.h new file mode 100644 index 00000000..00498054 --- /dev/null +++ b/NorthstarDLL/logging/sourceconsole.h @@ -0,0 +1,86 @@ +#pragma once +#include "pch.h" +#include "shared/sourceinterface.h" +#include "spdlog/sinks/base_sink.h" +#include + +class EditablePanel +{ + public: + virtual ~EditablePanel() = 0; + unsigned char unknown[0x2B0]; +}; + +class IConsoleDisplayFunc +{ + public: + virtual void ColorPrint(const SourceColor& clr, const char* pMessage) = 0; + virtual void Print(const char* pMessage) = 0; + virtual void DPrint(const char* pMessage) = 0; +}; + +class CConsolePanel : public EditablePanel, public IConsoleDisplayFunc +{ +}; + +class CConsoleDialog +{ + public: + struct VTable + { + void* unknown[298]; + void (*OnCommandSubmitted)(CConsoleDialog* consoleDialog, const char* pCommand); + }; + + VTable* m_vtable; + unsigned char unknown[0x398]; + CConsolePanel* m_pConsolePanel; +}; + +class CGameConsole +{ + public: + virtual ~CGameConsole() = 0; + + // activates the console, makes it visible and brings it to the foreground + virtual void Activate() = 0; + + virtual void Initialize() = 0; + + // hides the console + virtual void Hide() = 0; + + // clears the console + virtual void Clear() = 0; + + // return true if the console has focus + virtual bool IsConsoleVisible() = 0; + + virtual void SetParent(int parent) = 0; + + bool m_bInitialized; + CConsoleDialog* m_pConsole; +}; + +extern SourceInterface* g_pSourceGameConsole; + +// spdlog logger +class SourceConsoleSink : public CustomSink +{ + private: + std::map m_LogColours = { + {spdlog::level::trace, NS::Colors::TRACE.ToSourceColor()}, + {spdlog::level::debug, NS::Colors::DEBUG.ToSourceColor()}, + {spdlog::level::info, NS::Colors::INFO.ToSourceColor()}, + {spdlog::level::warn, NS::Colors::WARN.ToSourceColor()}, + {spdlog::level::err, NS::Colors::ERR.ToSourceColor()}, + {spdlog::level::critical, NS::Colors::CRIT.ToSourceColor()}, + {spdlog::level::off, NS::Colors::OFF.ToSourceColor()}}; + + protected: + void custom_sink_it_(const custom_log_msg& msg); + void sink_it_(const spdlog::details::log_msg& msg) override; + void flush_() override; +}; + +void InitialiseConsoleOnInterfaceCreation(); -- cgit v1.2.3