CCrashHandler and logging improvements

* CCrashHandler now calls the crashmsg executable to display the error to the user.
* Logs are now placed into directories named to the current time to avoid overwriting them or having 2 instances of the game writing to the same logs.
This commit is contained in:
Kawe Mazidjatari 2022-12-27 02:28:43 +01:00
parent 5502dcb8f1
commit 7dfef9c9c8
6 changed files with 145 additions and 50 deletions

View File

@ -14,6 +14,7 @@ void SpdLog_Init(void)
return;
}
g_svLogSessionDirectory = fmt::format("platform\\logs\\{:s}\\", CreateTimedFileName());
/************************
* IMGUI LOGGER SETUP *
************************/
@ -45,17 +46,17 @@ void SpdLog_Init(void)
* ROTATE LOGGER SETUP *
************************/
{
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sqvm_warn" , "platform\\logs\\sqvm_warn.log" , SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sqvm_info" , "platform\\logs\\sqvm_info.log" , SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sdk_info" , "platform\\logs\\sdk_info.log" , SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sdk_warn" , "platform\\logs\\sdk_warn.log" , SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sdk_error" , "platform\\logs\\sdk_error.log" , SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("qhull_info", "platform\\logs\\qhull_info.log" , SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("net_trace" , "platform\\logs\\net_trace.log" , SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sqvm_warn" , fmt::format("{:s}sqvm_warn.log" , g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sqvm_info" , fmt::format("{:s}sqvm_info.log" , g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sdk_info" , fmt::format("{:s}sdk_info.log" , g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sdk_warn" , fmt::format("{:s}sdk_warn.log" , g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("sdk_error" , fmt::format("{:s}sdk_error.log" , g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("qhull_info", fmt::format("{:s}qhull_info.log" , g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("net_trace" , fmt::format("{:s}net_trace.log" , g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
#ifndef DEDICATED
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("net_con" , "platform\\logs\\net_console.log", SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("net_con" , fmt::format("{:s}net_console.log", g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
#endif // !DEDICATED
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("fs_warn" , "platform\\logs\\fs_warn.log" , SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
spdlog::rotating_logger_mt<spdlog::synchronous_factory>("fs_warn" , fmt::format("{:s}fs_warn.log" ,g_svLogSessionDirectory), SPDLOG_MAX_SIZE, SPDLOG_NUM_FILE)->set_pattern("[%Y-%m-%d %H:%M:%S.%e] %v");
}
spdlog::set_level(spdlog::level::trace);

View File

@ -6,6 +6,8 @@ constexpr int SPDLOG_NUM_FILE = 0; // Sets number of files to rotate to.
inline bool g_bSpdLog_UseAnsiClr = false;
inline bool g_bSpdLog_PostInit = false;
inline string g_svLogSessionDirectory;
//-------------------------------------------------------------------------
// IMGUI CONSOLE SINK |
inline std::ostringstream g_spd_sys_w_oss;

View File

@ -4,18 +4,10 @@
//
//=============================================================================//
#include "core/stdafx.h"
#include "core/logdef.h"
#include "tier0/cpu.h"
#include "public/utility/binstream.h"
#ifndef _DEBUG
#include "crashhandler.h"
#include "engine/cmodel_bsp.h"
//#include "materialsystem/cmaterialglue.h"
//#include "materialsystem/cmaterialsystem.h"
#include "bsplib/bsplib.h"
#include <tier0/cpu.h>
CCrashHandler* g_CrashHandler = new CCrashHandler();
#include "public/utility/crashhandler.h"
//-----------------------------------------------------------------------------
// Purpose: formats the crasher (module, address and exception)
@ -153,6 +145,7 @@ void CCrashHandler::FormatExceptionAddress(LPCSTR pExceptionAddress)
if (!GetModuleHandleExA(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS | GET_MODULE_HANDLE_EX_FLAG_UNCHANGED_REFCOUNT, pExceptionAddress, &hCrashedModule))
{
m_svBuffer.append(fmt::format("\t!!!unknown-module!!!: 0x{:016X}\n", reinterpret_cast<uintptr_t>(pExceptionAddress)));
m_nCrashMsgFlags = 0; // Display the "unknown DLL or EXE" message.
return;
}
@ -162,12 +155,19 @@ void CCrashHandler::FormatExceptionAddress(LPCSTR pExceptionAddress)
if (GetModuleFileNameExA(GetCurrentProcess(), hCrashedModule, szCrashedModuleFullName, sizeof(szCrashedModuleFullName)) - 1 > 0x1FE)
{
m_svBuffer.append(fmt::format("\tmodule@{:016X}: 0x{:016X}\n", (void*)hCrashedModule, reinterpret_cast<uintptr_t>(pModuleBase)));
m_nCrashMsgFlags = 0; // Display the "Apex crashed" message without additional information regarding the module.
return;
}
// TODO: REMOVE EXT.
const char* szCrashedModuleName = strrchr(szCrashedModuleFullName, '\\') + 1;
m_svBuffer.append(fmt::format("\t{:s}: 0x{:016X}\n", szCrashedModuleName, reinterpret_cast<uintptr_t>(pModuleBase)));
m_svBuffer.append(fmt::format("\t{:15s}: 0x{:016X}\n", szCrashedModuleName, reinterpret_cast<uintptr_t>(pModuleBase)));
m_nCrashMsgFlags = 1; // Display the "Apex crashed in <module>" message.
if (m_svCrashMsgInfo.empty()) // Only set it once to the crashing module.
{
m_svCrashMsgInfo = szCrashedModuleName;
}
}
//-----------------------------------------------------------------------------
@ -288,9 +288,9 @@ void CCrashHandler::FormatFPU(const char* pszRegister, M128A* pxContent)
//-----------------------------------------------------------------------------
// Purpose: returns the current exception code as string
//-----------------------------------------------------------------------------
const char* CCrashHandler::ExceptionToString() const
const char* CCrashHandler::ExceptionToString(DWORD nExceptionCode) const
{
switch (m_pExceptionPointers->ExceptionRecord->ExceptionCode)
switch (nExceptionCode)
{
case EXCEPTION_GUARD_PAGE: { return "\tEXCEPTION_GUARD_PAGE" ": 0x{:08X}\n"; };
case EXCEPTION_BREAKPOINT: { return "\tEXCEPTION_BREAKPOINT" ": 0x{:08X}\n"; };
@ -318,6 +318,14 @@ const char* CCrashHandler::ExceptionToString() const
}
}
//-----------------------------------------------------------------------------
// Purpose: returns the current exception code as string
//-----------------------------------------------------------------------------
const char* CCrashHandler::ExceptionToString() const
{
return ExceptionToString(m_pExceptionPointers->ExceptionRecord->ExceptionCode);
}
//-----------------------------------------------------------------------------
// Purpose: tests if memory page is accessible
//-----------------------------------------------------------------------------
@ -352,13 +360,50 @@ void CCrashHandler::GetCallStack()
//-----------------------------------------------------------------------------
void CCrashHandler::WriteFile()
{
std::time_t time = std::time(nullptr);
stringstream ss; ss << "platform\\logs\\" << "apex_crash_" << std::put_time(std::localtime(&time), "%Y-%m-%d %H-%M-%S.txt");
string svLogDirectory = fmt::format("{:s}{:s}", g_svLogSessionDirectory, "apex_crash.txt");
CIOStream ioLogFile(svLogDirectory, CIOStream::Mode_t::WRITE);
CIOStream ioLogFile = CIOStream(ss.str(), CIOStream::Mode_t::WRITE);
ioLogFile.WriteString(m_svBuffer);
}
//-----------------------------------------------------------------------------
// Purpose: creates the crashmsg process displaying the error to the user
// the process has to be separate as the current process is getting killed
//-----------------------------------------------------------------------------
void CCrashHandler::CreateMessageProcess()
{
if (m_bCrashMsgCreated)
{
return; // CrashMsg already displayed.
}
m_bCrashMsgCreated = true;
PEXCEPTION_RECORD pExceptionRecord = m_pExceptionPointers->ExceptionRecord;
PCONTEXT pContextRecord = m_pExceptionPointers->ContextRecord;
if (pExceptionRecord->ExceptionCode == 0xC0000005 &&
pExceptionRecord->ExceptionInformation[0] == 8 &&
pExceptionRecord->ExceptionInformation[1] != pContextRecord->Rip)
{
m_svCrashMsgInfo = "bin\\crashmsg.exe overclock";
}
else
{
m_svCrashMsgInfo = fmt::format("bin\\crashmsg.exe crash {:d} \"{:s}\"", m_nCrashMsgFlags, m_svCrashMsgInfo);
}
PROCESS_INFORMATION processInfo;
STARTUPINFOA startupInfo = { 0 };
startupInfo.cb = sizeof(STARTUPINFOA);
if (CreateProcessA(NULL, (LPSTR)m_svCrashMsgInfo.c_str(), NULL, NULL, TRUE, CREATE_NO_WINDOW, NULL, NULL, &startupInfo, &processInfo))
{
CloseHandle(processInfo.hProcess);
CloseHandle(processInfo.hThread);
}
}
//-----------------------------------------------------------------------------
// Purpose:
//-----------------------------------------------------------------------------
@ -366,14 +411,25 @@ long __stdcall ExceptionFilter(EXCEPTION_POINTERS* exceptionInfo)
{
g_CrashHandler->Lock();
g_CrashHandler->SetExceptionPointers(exceptionInfo);
if (g_CrashHandler->ExceptionToString() == g_CrashHandler->ExceptionToString(-1))
{
g_CrashHandler->Unlock();
return EXCEPTION_CONTINUE_SEARCH;
}
if (IsDebuggerPresent())
{
g_CrashHandler->Unlock();
return EXCEPTION_CONTINUE_SEARCH;
}
// Kill on recursive call.
static bool bLogged = false;
if (bLogged)
if (g_CrashHandler->GetState())
ExitProcess(1u);
bLogged = true;
g_CrashHandler->SetState(true);
g_CrashHandler->GetCallStack();
g_CrashHandler->SetExceptionPointers(exceptionInfo);
g_CrashHandler->FormatCrash();
g_CrashHandler->FormatCallstack();
@ -382,24 +438,10 @@ long __stdcall ExceptionFilter(EXCEPTION_POINTERS* exceptionInfo)
g_CrashHandler->FormatBuildInfo();
g_CrashHandler->WriteFile();
g_CrashHandler->CreateMessageProcess();
g_CrashHandler->Unlock();
//#ifndef _DEBUG
// // THIS WONT WORK ON DEBUG!!!
// // THIS IS DUE TO A JMP TABLE CREATED BY MSVC!!
// static auto find_IMI_ref = CMemory(IsMaterialInternal).FindAllCallReferences(reinterpret_cast<uintptr_t>(BuildPropStaticFrustumCullMap), 1000);
// if (!find_IMI_ref.empty())
// {
// const void* imiRetAddr = find_IMI_ref.at(0).Offset(0x5).RCast<void*>();
// for (WORD i = 0; i < 7; i++)
// {
// if (imiRetAddr == pStackTrace[i])
// return EXCEPTION_CONTINUE_SEARCH;
// }
// }
//#endif // _DEBUG
return EXCEPTION_EXECUTE_HANDLER;
}
@ -408,8 +450,11 @@ long __stdcall ExceptionFilter(EXCEPTION_POINTERS* exceptionInfo)
//-----------------------------------------------------------------------------
CCrashHandler::CCrashHandler()
: m_ppStackTrace()
, m_pExceptionPointers(nullptr)
, m_nCapturedFrames(0)
, m_nCrashMsgFlags(0)
, m_bCallState(false)
, m_bCrashMsgCreated(false)
{
m_hExceptionHandler = AddVectoredExceptionHandler(TRUE, ExceptionFilter);
}
@ -422,4 +467,4 @@ CCrashHandler::~CCrashHandler()
RemoveVectoredExceptionHandler(m_hExceptionHandler);
}
#endif // _DEBUG
CCrashHandler* g_CrashHandler = new CCrashHandler();

View File

@ -10,24 +10,40 @@ public:
CCrashHandler();
~CCrashHandler();
//-------------------------------------------------------------------------
// Inlines:
//-------------------------------------------------------------------------
void Lock() const { m_Mutex.lock(); };
void Unlock() const { m_Mutex.unlock(); };
bool GetState() const { return m_bCallState; };
void SetState(bool bState) { m_bCallState = bState; };
//-------------------------------------------------------------------------
// Formatters:
//-------------------------------------------------------------------------
void FormatCrash();
void FormatCallstack();
void FormatRegisters();
void FormatSystemInfo();
void FormatBuildInfo();
//-------------------------------------------------------------------------
// Utility:
//-------------------------------------------------------------------------
const char* ExceptionToString() const;
const char* ExceptionToString(DWORD nExceptionCode) const;
void SetExceptionPointers(EXCEPTION_POINTERS* pExceptionPointers) { m_pExceptionPointers = pExceptionPointers; };
void WriteFile();
void GetCallStack();
void CreateMessageProcess();
private:
//-------------------------------------------------------------------------
// Internals:
//-------------------------------------------------------------------------
void FormatExceptionAddress(LPCSTR pExceptionAddress = nullptr);
void FormatExceptionCode();
@ -42,12 +58,20 @@ private:
NUM_FRAMES_TO_CAPTURE = 60
};
void* m_hExceptionHandler;
PVOID m_hExceptionHandler;
PVOID m_ppStackTrace[NUM_FRAMES_TO_CAPTURE];
EXCEPTION_POINTERS* m_pExceptionPointers;
WORD m_nCapturedFrames;
string m_svBuffer;
string m_svBuffer; // Buffer containing the entire crash log.
string m_svCrashMsgInfo;
uint8_t m_nCrashMsgFlags;
bool m_bCallState; // Set when called to prevent recursive calls.
bool m_bCrashMsgCreated; // Set when crashmsg.exe is created to prevent recursive messages.
mutable std::mutex m_Mutex;
};
extern CCrashHandler* g_CrashHandler;
#endif // CRASHHANDLER_H

View File

@ -351,6 +351,27 @@ string RemoveFileName(const string& svInput, bool bWindows)
return svInput.substr(0, nPos);
}
///////////////////////////////////////////////////////////////////////////////
// For creating a file name with the current (now) date and time
string CreateTimedFileName()
{
auto now = std::chrono::system_clock::now();
// Get number of milliseconds for the current second (remainder after division into seconds).
auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000;
// Convert to std::time_t in order to convert to std::tm (broken time).
auto timer = std::chrono::system_clock::to_time_t(now);
std::tm bt = *std::localtime(&timer);
ostringstream oss;
oss << std::put_time(&bt, "%Y-%m-%d_%H-%M-%S");
oss << '.' << std::setfill('0') << std::setw(3) << ms.count();
return oss.str(); // 'YY-MM-DD_HH-MM-SS.MMM'.
}
///////////////////////////////////////////////////////////////////////////////
// For creating directories for output streams.
string CreateDirectories(string svInput, bool bWindows)

View File

@ -29,7 +29,9 @@ bool HasFileName(const string& svInput, const string& svFileName);
string GetFileName(const string& svInput, bool bRemoveExtension = false, bool bWindows = false);
string RemoveFileName(const string& svInput, bool bWindows = false);
string CreateTimedFileName();
string CreateDirectories(string svInput, bool bWindows = false);
string ConvertToWinPath(const string& svInput);
string ConvertToUnixPath(const string& svInput);