Add more log messages

src/dllmain.cpp

@@ -13,25 +13,30 @@ namespace {
 bool Initialize() {
   logging::SetupLogger();
 
-  bool isError = false;
-
   if ( MH_Initialize() != MH_OK ) {
     spdlog::critical("Unable to initialize MinHook");
-    isError = true;
+    return false;
   }
+  spdlog::trace("Initialized MinHook");
 
   // CreateProcess needs to be hooked for both executables
   if ( MH_CreateHookApi(L"kernel32", "CreateProcessA", &hooks::CreateProcessA_Hook,
       reinterpret_cast<LPVOID*>(&hooks::CreateProcessA_Orig)) != MH_OK ) {
     spdlog::critical("Unable to hook CreateProcessA");
-    isError = true;
+    return false;
   }
+  spdlog::trace("Hooked CreateProcessA");
+
   if ( MH_CreateHookApi(L"kernel32", "CreateProcessW", &hooks::CreateProcessW_Hook,
       reinterpret_cast<LPVOID*>(&hooks::CreateProcessW_Orig)) != MH_OK ) {
     spdlog::critical("Unable to hook CreateProcessW");
-    isError = true;
+    return false;
+  }
+  spdlog::trace("Hooked CreateProcessW");
+
+  if ( MH_EnableHook(MH_ALL_HOOKS) != MH_OK ) {
+    spdlog::critical("Unable to enable CreateProcess hooks");
   }
-  MH_EnableHook(MH_ALL_HOOKS);
 
   char exeName[MAX_PATH];
   GetModuleFileNameA(nullptr, exeName, MAX_PATH);
@@ -47,18 +52,23 @@ bool Initialize() {
     /* DLL has been loaded into SafeDisc cleanup, need to relaunch main game
      * executable and inject into that instead */
     if ( !GetEnvironmentVariableW(L"SAFEDISCSHIM_INJECTED", nullptr, 0) ) {
+      spdlog::info("Cleanup.exe detected, relaunching game and injecting");
 
       /* PID of game executable is in command line as argument 1 */
       const wchar_t* cmdLine = GetCommandLineW();
       unsigned long pid = 0;
-      if ( swscanf_s(cmdLine, L"\"%*[^\"]\" %lu", &pid) != 1 || !pid )
+      if ( swscanf_s(cmdLine, L"\"%*[^\"]\" %lu", &pid) != 1 || !pid ) {
+        spdlog::error("Unable to get game PID");
         return false;
+      }
 
       HANDLE hGameProcess;
       if ( hGameProcess = OpenProcess(
         PROCESS_TERMINATE | PROCESS_QUERY_INFORMATION | PROCESS_VM_READ,
-        false, pid); !hGameProcess )
+        false, pid); !hGameProcess ) {
+        spdlog::error("Unable to open game process");
         return false;
+      }
 
       // for cleanup executable, log to game folder rather than %temp%
       GetModuleFileNameExA(hGameProcess, nullptr, exeName, MAX_PATH);
@@ -79,26 +89,24 @@ bool Initialize() {
       &hooks::NtDeviceIoControlFile_Hook,
       reinterpret_cast<LPVOID*>(&hooks::NtDeviceIoControlFile_Orig)) != MH_OK ) {
       spdlog::critical("Unable to hook NtDeviceIoControlFile");
-      isError = true;
+      return false;
     }
+    spdlog::trace("Hooked NtDeviceIoControlFile");
 
     if ( MH_CreateHookApi(L"kernel32", "CreateFileA", &hooks::CreateFileA_Hook,
       reinterpret_cast<LPVOID*>(&hooks::CreateFileA_Orig)) != MH_OK ) {
       spdlog::critical("Unable to hook CreateFileA");
-      isError = true;
+      return false;
     }
+    spdlog::trace("Hooked CreateFileA");
   }
 
   if ( MH_EnableHook(MH_ALL_HOOKS) != MH_OK ) {
-    spdlog::critical("Unable to enable hooks");
-    isError = true;
+    spdlog::critical("Unable to enable IOCTL hooks");
+    return false;
   }
 
   SetEvent(hInjectedEvent);
-
-  if ( isError ) {
-    return false;
-  }
   return true;
 }
 
@@ -128,7 +136,7 @@ BOOL WINAPI DllMain(HINSTANCE /*hinstDLL*/, DWORD fdwReason, LPVOID /*lpvReserve
 
 // Exported functions from the original drvmgt.dll. 100 = success
 extern "C" __declspec(dllexport) int Setup(LPCSTR /*lpSubKey*/, char* /*FullPath*/) {
-  // don't continue unless hooks are installed
+  // wait for hooks to be installed to continue
   WaitForSingleObject(hInjectedEvent, INFINITE);
   CloseHandle(hInjectedEvent);
   return 100;

src/hooks.cpp

@@ -120,6 +120,7 @@ BOOL WINAPI hooks::CreateProcessA_Hook(LPCSTR lpApplicationName,
     lpEnvironment, lpCurrentDirectory, lpStartupInfo, lpProcessInformation) )
     return FALSE;
 
+  spdlog::info("Injecting into executable {}", lpApplicationName);
   InjectIntoExecutable(lpProcessInformation->hProcess,
     lpProcessInformation->hThread, !isCreateSuspended);
 
@@ -145,6 +146,7 @@ BOOL WINAPI hooks::CreateProcessW_Hook(LPCWSTR lpApplicationName,
     lpEnvironment, lpCurrentDirectory, lpStartupInfo, lpProcessInformation) )
     return FALSE;
 
+  spdlog::info(L"Injecting into executable {}", lpApplicationName);
   InjectIntoExecutable(lpProcessInformation->hProcess,
      lpProcessInformation->hThread, !isCreateSuspended);
 

src/logging.cpp

@@ -16,7 +16,7 @@ void logging::SetupLogger() {
   GetEnvironmentVariable("SAFEDISCSHIM_LOGLEVEL", envLogLevel, sizeof(envLogLevel));
   if ( GetLastError() == ERROR_ENVVAR_NOT_FOUND ) {
 #ifdef _DEBUG
-    spdlog::set_level(spdlog::level::debug);
+    spdlog::set_level(spdlog::level::trace);
 #else
     // don't output logs if envvar is not defined
     return;

src/process.cpp

@@ -1,11 +1,10 @@
 #include <winternl.h>
-
-#include "process.h"
-
-#include <istream>
 #include <string>
 #include <vector>
 
+#include "process.h"
+#include "logging.h"
+
 namespace {
   /* the definition in winternl.h is missing quite a bit, including, for our
    * purposes, the current directory, so we redefine it here */
@@ -31,38 +30,50 @@ namespace {
     PROCESS_BASIC_INFORMATION pbi;
     NTSTATUS status = NtQueryInformationProcess(hProcess, ProcessBasicInformation,
       &pbi, sizeof(pbi), nullptr);
-    if ( !NT_SUCCESS(status) || !pbi.PebBaseAddress )
+    if ( !NT_SUCCESS(status) || !pbi.PebBaseAddress ) {
+      spdlog::critical("Unable to get PEB address");
       return false;
+    }
 
     PEB peb {};
     if ( !ReadProcessMemory(hProcess, pbi.PebBaseAddress,
-      &peb, sizeof(peb), nullptr) )
+      &peb, sizeof(peb), nullptr) ) {
+      spdlog::critical("Unable to read PEB");
       return false;
+    }
 
     RTL_USER_PROCESS_PARAMETERS processParameters {};
     if ( !ReadProcessMemory(hProcess, peb.ProcessParameters,
-      &processParameters, sizeof(processParameters), nullptr) )
+      &processParameters, sizeof(processParameters), nullptr) ) {
+      spdlog::critical("Unable to read ProcessParameters");
       return false;
+    }
 
     UNICODE_STRING &cmdLine = processParameters.CommandLine;
     std::vector<wchar_t> cmdLineBuf(cmdLine.Length / sizeof(wchar_t));
     if ( !ReadProcessMemory(hProcess, cmdLine.Buffer, cmdLineBuf.data(),
-      cmdLine.Length, nullptr) )
+      cmdLine.Length, nullptr) ) {
+      spdlog::critical("Unable to read process command line");
       return false;
+    }
     commandLine.assign(cmdLineBuf.data(), cmdLineBuf.size());
 
     UNICODE_STRING &curDir = processParameters.CurrentDirectoryPath;
     std::vector<wchar_t> curDirBuf(curDir.Length / sizeof(wchar_t));
     if ( !ReadProcessMemory(hProcess, curDir.Buffer, curDirBuf.data(),
-      curDir.Length, nullptr) )
+      curDir.Length, nullptr) ) {
+      spdlog::critical("Unable to read process current directory");
       return false;
+    }
     directory.assign(curDirBuf.data(), curDirBuf.size());
 
     return true;
   }
 }
 
 void process::RelaunchGame(HANDLE hGameProcess) {
+  spdlog::info("Relaunching main game process");
+
   SetEnvironmentVariableW(L"SAFEDISCSHIM_INJECTED", L"1");
 
   std::wstring commandLine;
@@ -82,5 +93,6 @@ void process::RelaunchGame(HANDLE hGameProcess) {
     nullptr, nullptr, false, 0,nullptr,
     workingDirectory.c_str(), &si, &pi);
 
+  spdlog::info("Main game process relaunched; exiting cleanup.exe");
   ExitProcess(0);
 }

src/secdrv_ioctl.cpp

@@ -67,17 +67,19 @@ BOOL secdrvIoctl::ProcessMainIoctl(LPVOID lpInBuffer,
   }
 
   if ( nInBufferSize != sizeof(MainIoctlInBuffer) ) {
-    spdlog::error("invalid ioctl in-buffer size: {:x}", nInBufferSize);
+    spdlog::error("invalid ioctl in-buffer size: {:#x}", nInBufferSize);
     return FALSE;
   }
+  spdlog::trace("ioctl in-buffer size: {:#x}", nInBufferSize);
 
   /* later versions report a buffer size of 0xC18 for some reason, though it is
    * never read from or written to outside of the normal size */
   if ( nOutBufferSize != sizeof(MainIoctlOutBuffer)
     && nOutBufferSize != 0xC18 ) {
-    spdlog::error("invalid ioctl out-buffer size: {:x}", nOutBufferSize);
+    spdlog::error("invalid ioctl out-buffer size: {:#x}", nOutBufferSize);
     return FALSE;
   }
+  spdlog::trace("ioctl out-buffer size: {:#x}", nOutBufferSize);
 
   auto* inBuffer = static_cast<MainIoctlInBuffer *>(lpInBuffer);
   auto* outBuffer = static_cast<MainIoctlOutBuffer *>(lpOutBuffer);
@@ -100,24 +102,29 @@ BOOL secdrvIoctl::ProcessMainIoctl(LPVOID lpInBuffer,
    * perform more checks */
   switch ( inBuffer->Command ) {
   case GetDebugRegisterInfo:
+    spdlog::trace("command GetDebugRegisterInfo called");
     outBuffer->ExtraDataSize = 4;
     outBuffer->ExtraData[0] = 0x400;
     break;
   case GetIdtInfo:
+    spdlog::trace("command GetIdtInfo called");
     outBuffer->ExtraDataSize = 4;
     outBuffer->ExtraData[0] = 0x2C8;
     break;
   case SetupVerification:
+    spdlog::trace("command SetupVerification called");
     outBuffer->ExtraDataSize = 4;
     outBuffer->ExtraData[0] = 0x5278d11b;
     break;
   case Command3Fh:
+    spdlog::trace("command 3Fh called");
     if ( nOutBufferSize != 0xC18 ||
       inBuffer->ExtraData[0] > 0x60 ) return FALSE;
     outBuffer->ExtraDataSize = 4;
     outBuffer->ExtraData[0] = 0;
     break;
   case Command40h:
+    spdlog::trace("command 40h called");
     if ( nOutBufferSize != 0xC18 ||
       !inBuffer->ExtraData[0] ||
       !inBuffer->ExtraData[1] ) return FALSE;
@@ -128,11 +135,13 @@ BOOL secdrvIoctl::ProcessMainIoctl(LPVOID lpInBuffer,
       outBuffer->ExtraData[0] = 0x587C1284;
     break;
   case Command41h:
+    spdlog::trace("command 41h called");
     if ( nOutBufferSize != 0xC18 ||
       !LOBYTE(inBuffer->ExtraData[0]) ) return FALSE;
     outBuffer->ExtraDataSize = 4;
     break;
   case Command42h:
+    spdlog::trace("command 42h called");
     return FALSE;
   case Command43h:
     if ( inBuffer->ExtraData[0] != 0x98A64100 ||
@@ -142,7 +151,7 @@ BOOL secdrvIoctl::ProcessMainIoctl(LPVOID lpInBuffer,
     outBuffer->ExtraData[0] = 0;
     break;
   default:
-    spdlog::error("unhandled ioctl command: {:x}",
+    spdlog::error("unhandled ioctl command: {:#x}",
       static_cast<DWORD>(inBuffer->Command));
     return FALSE;
   }