Chain logger call stack (#7)

.vscode/settings.json

@@ -64,7 +64,8 @@
         "xstring": "cpp",
         "xtr1common": "cpp",
         "xtree": "cpp",
-        "xutility": "cpp"
+        "xutility": "cpp",
+        "mutex": "cpp"
     },
     "cmake.preferredGenerators": [
         "Visual Studio 17 2022"

src/CMakeLists.txt

@@ -3,6 +3,7 @@ add_library(TOFInternal SHARED
     globals.cpp
     hooks.cpp
     logger/logger.cpp
+    logger/chain/chain.cpp
     menu/menu.cpp
     menu/layout/layout.cpp
     menu/dx12_impl.cpp
@@ -15,6 +16,7 @@ add_library(TOFInternal SHARED
     feats/teleport_nucleus.cpp
     feats/quest.cpp
     feats/teleport_anywhere.cpp
+    feats/chain_logging.cpp
 )
 target_precompile_headers(TOFInternal PRIVATE pch.hpp)
 add_subdirectory(ext/imgui)

src/feats/chain_logging.cpp

@@ -0,0 +1,128 @@
+#include "chain_logging.hpp"
+#include "../hooks.hpp"
+#include "../logger/chain/chain.hpp"
+
+namespace Feats {
+    namespace ChainLogging {
+        bool enabled = false;
+        int callStackSize = 3;
+        bool showObjFullName = false;
+
+        constexpr ImVec4 red = ImVec4(0xf3 / 255.0, 0x12 / 255.0, 0x60 / 255.0, 1.0f);
+        constexpr ImVec4 green = ImVec4(0x17 / 255.0, 0xc9 / 255.0, 0x64 / 255.0, 1.0f);
+        constexpr ImVec4 blue = ImVec4(0.0f, 0x6f / 255.0, 0xee / 255.0, 1.0f);
+
+        void init() {
+            Hooks::registerHook(
+                "*",
+                [](SDK::UObject *pObject, SDK::UFunction *pFunction, void *pParams) -> uint8_t {
+                    const auto functionName = pFunction->GetFullName().substr(9);
+                    Logger::Chain::startCallLog(functionName, {{"objFullName", pObject->GetFullName()}});
+                    return Hooks::ExecutionFlag::CONTINUE_EXECUTION;
+                },
+                Hooks::Type::PRE);
+
+            Hooks::registerHook(
+                "*",
+                [](SDK::UObject *pObject, SDK::UFunction *pFunction, void *pParams) -> uint8_t {
+                    const auto functionName = pFunction->GetFullName().substr(9);
+                    Logger::Chain::endCallLog(functionName);
+                    return Hooks::ExecutionFlag::CONTINUE_EXECUTION;
+                },
+                Hooks::Type::POST);
+        }
+
+        void tick() { return; }
+
+        void renderStack(Logger::Chain::Call &call, bool isRoot = false) {
+            const auto childCount = std::get<uint64_t>(call.attributes["childCount"]);
+            std::string header = call.funcName + " (" + std::to_string(childCount + 1) + " calls)";
+
+            bool shouldRender = true;
+
+            if (childCount > 0) {
+                if (isRoot) {
+                    shouldRender = ImGui::CollapsingHeader(header.c_str());
+                } else {
+                    shouldRender = ImGui::TreeNode(header.c_str());
+                }
+            }
+
+            if (shouldRender) {
+                ImGui::Indent();
+                auto entry = call.funcName;
+
+                if (showObjFullName) {
+                    const auto index = std::get<std::string>(call.attributes["objFullName"]).find_first_of(" ");
+                    const auto type = std::get<std::string>(call.attributes["objFullName"]).substr(0, index);
+
+                    ImGui::PushStyleColor(ImGuiCol_Text, red);
+                    ImGui::Text(type.c_str());
+                    ImGui::PopStyleColor();
+                    ImGui::SameLine();
+
+                    if (index != std::string::npos) {
+                        const auto path = std::get<std::string>(call.attributes["objFullName"]).substr(index);
+
+                        ImGui::PushStyleColor(ImGuiCol_Text, green);
+                        ImGui::Text(path.c_str());
+                        ImGui::PopStyleColor();
+                        ImGui::SameLine();
+                    }
+                }
+
+                ImGui::PushStyleColor(ImGuiCol_Text, blue);
+                ImGui::Text(call.funcName.c_str());
+                ImGui::PopStyleColor();
+
+                for (auto &child : call.children) {
+                    renderStack(child);
+                }
+
+                ImGui::Unindent();
+
+                if (childCount > 0 && !isRoot) {
+                    ImGui::TreePop();
+                }
+            }
+        }
+
+        void menu() {
+            if (ImGui::Checkbox("Chain Logging", &enabled)) {
+                if (enabled) {
+                    Logger::Chain::enable();
+                } else {
+                    Logger::Chain::disable();
+                }
+            }
+
+            ImGui::SameLine();
+
+            ImGui::PushItemWidth(100.0);
+            if (ImGui::InputInt("Min Call Stack Size", &callStackSize)) {
+                Logger::Chain::setMinCallStackSize((uint16_t)callStackSize);
+            }
+            ImGui::PopItemWidth();
+
+            ImGui::SameLine();
+
+            ImGui::Checkbox("Show Object Full Name", &showObjFullName);
+
+            ImGui::SameLine();
+
+            if (ImGui::Button("Clear Logs")) {
+                Logger::Chain::clearLogs();
+            }
+
+            auto logs = Logger::Chain::getLogs();
+
+            if (logs.empty()) {
+                return;
+            }
+
+            for (auto &log : logs) {
+                renderStack(log, true);
+            }
+        }
+    } // namespace ChainLogging
+} // namespace Feats

src/feats/chain_logging.hpp

@@ -0,0 +1,7 @@
+namespace Feats {
+    namespace ChainLogging {
+        void init();
+        void tick();
+        void menu();
+    } // namespace ChainLogging
+} // namespace Feats

src/hooks.cpp

@@ -2,31 +2,60 @@
 #include "logger/logger.hpp"
 #include "minhook/include/MinHook.h"
 
+#define RETURN_IF_STOPPING(result, message)                                                                            \
+    if (result == STOP_EXECUTION) {                                                                                    \
+        Logger::warning(message);                                                                                      \
+        return;                                                                                                        \
+    }
+
 namespace Hooks {
-    std::map<std::string, std::vector<Callback>> handlers;
+    std::map<Type, std::map<std::string, std::vector<Callback>>> handlers = {
+        {Type::PRE, std::map<std::string, std::vector<Callback>>()},
+        {Type::POST, std::map<std::string, std::vector<Callback>>()},
+    };
 
     typedef void(WINAPI *ProcessEvent)(SDK::UObject *pObject, SDK::UFunction *pFunction, void *pParams, void *pResult);
     ProcessEvent oProcessEvent = nullptr;
 
+    ExecutionFlag runHooks(Type type, const std::string &functionName, SDK::UObject *pObject, SDK::UFunction *pFunction,
+                           void *pParams) {
+        if (handlers[type].find(functionName) != handlers[type].end()) {
+            for (auto &handler : handlers[type][functionName]) {
+                const auto result = handler(pObject, pFunction, pParams);
+
+                if (result == STOP_EXECUTION) {
+                    return STOP_EXECUTION;
+                }
+            }
+        }
+
+        return CONTINUE_EXECUTION;
+    }
+
     void WINAPI myProcessEvent(SDK::UObject *pObject, SDK::UFunction *pFunction, void *pParams, void *pResult) {
         if (!pObject || !pFunction) {
             return oProcessEvent(pObject, pFunction, pParams, pResult);
         }
 
         const std::string functionName = pFunction->GetFullName().substr(9);
 
-        if (handlers.find(functionName) != handlers.end()) {
-            for (auto &handler : handlers[functionName]) {
-                const auto result = handler(pObject, pFunction, pParams);
+        const auto preResult = runHooks(Type::PRE, functionName, pObject, pFunction, pParams);
 
-                if (result == STOP_EXECUTION) {
-                    Logger::warning("Execution for " + functionName + " was stopped");
-                    return;
-                }
-            }
-        }
+        RETURN_IF_STOPPING(preResult, "Pre-hooks: Execution for " + functionName + " was stopped");
+
+        const auto preWildResult = runHooks(Type::PRE, "*", pObject, pFunction, pParams);
+
+        RETURN_IF_STOPPING(preWildResult, "Pre-hooks (Wildcard): Execution for " + functionName + " was stopped");
+
+        oProcessEvent(pObject, pFunction, pParams, pResult);
+
+        const auto postResult = runHooks(Type::POST, functionName, pObject, pFunction, pParams);
+
+        RETURN_IF_STOPPING(postResult, "Post-hooks: Execution for " + functionName + " was stopped");
+
+        const auto postWildResult = runHooks(Type::POST, "*", pObject, pFunction, pParams);
 
-        return oProcessEvent(pObject, pFunction, pParams, pResult);
+        RETURN_IF_STOPPING(postWildResult, "Post-hooks (Wildcard): Execution for " + functionName + " was stopped");
     }
 
     void init() {
@@ -45,11 +74,11 @@ namespace Hooks {
         MH_Uninitialize();
     }
 
-    void registerHook(std::string functionName, Callback handler) {
-        if (handlers.find(functionName) == handlers.end()) {
-            handlers[functionName] = std::vector<Callback>();
+    void registerHook(std::string functionName, Callback handler, Type type) {
+        if (handlers[type].find(functionName) == handlers[type].end()) {
+            handlers[type][functionName] = std::vector<Callback>();
         }
 
-        handlers[functionName].push_back(handler);
+        handlers[type][functionName].push_back(handler);
     }
 } // namespace Hooks

src/hooks.hpp

@@ -1,12 +1,17 @@
 namespace Hooks {
-    enum {
+    enum ExecutionFlag {
         CONTINUE_EXECUTION = 0,
         STOP_EXECUTION = 1,
     };
 
+    enum Type {
+        PRE,
+        POST,
+    };
+
     typedef uint8_t (*Callback)(SDK::UObject *, SDK::UFunction *, void *);
 
     void init();
     void shutdown();
-    void registerHook(std::string functionName, Callback handler);
+    void registerHook(std::string functionName, Callback handler, Type type = Type::PRE);
 } // namespace Hooks

src/logger/chain/chain.cpp

@@ -0,0 +1,114 @@
+#include "chain.hpp"
+#include "../logger.hpp"
+
+namespace Logger {
+    namespace Chain {
+        bool enabled = false;
+        uint16_t minCallStackSize = 3;
+
+        std::vector<Call> logs;
+        std::map<uintptr_t, Call> threadedCallStacks;
+
+        void enable() { enabled = true; }
+        void disable() { enabled = false; }
+        bool isEnabled() { return enabled; }
+
+        void commit(Call *callStack) {
+            if (std::get<uint64_t>(callStack->attributes["childCount"]) + 1 >= minCallStackSize) {
+                logs.push_back(*callStack);
+            }
+        }
+
+        void setMinCallStackSize(uint16_t size) { minCallStackSize = size; }
+
+        void clearLogs() { logs.clear(); }
+
+        void appendChild(Call *parent, Call child) {
+            parent->attributes["childCount"] = std::get<uint64_t>(parent->attributes["childCount"]) + 1;
+
+            for (auto &c : parent->children) {
+                if (c.status == STARTED) {
+                    appendChild(&c, child);
+                    return;
+                }
+            }
+
+            parent->children.push_back(child);
+        }
+
+        void startCallLog(const std::string funcName,
+                          std::map<std::string, std::variant<uint64_t, std::string>> attributes) {
+            if (!enabled) {
+                return;
+            }
+
+            attributes["childCount"] = (uint64_t)0;
+
+            Call call = {funcName, STARTED, std::vector<Call>{}, attributes};
+
+            const auto callStackIt = threadedCallStacks.find(GetCurrentThreadId());
+
+            if (callStackIt == threadedCallStacks.end()) {
+                threadedCallStacks[GetCurrentThreadId()] = call;
+            } else {
+                const auto callStack = &(*callStackIt).second;
+                if (callStack->status == COMPLETED) {
+                    threadedCallStacks[GetCurrentThreadId()] = call;
+                } else {
+                    appendChild(callStack, call);
+                }
+            }
+        }
+
+        bool markCompleted(Call *callStack, const std::string &funcName,
+                           std::map<std::string, std::variant<uint64_t, std::string>> *attributes) {
+            for (auto &call : callStack->children) {
+                if (call.status == STARTED) {
+                    const auto result = markCompleted(&call, funcName, attributes);
+                    if (result) {
+                        return result;
+                    }
+                }
+            }
+
+            if (callStack->funcName == funcName && callStack->status == STARTED) {
+                callStack->status = COMPLETED;
+
+                for (const auto &attribute : *attributes) {
+                    callStack->attributes[attribute.first] = attribute.second;
+                }
+
+                return true;
+            }
+
+            return false;
+        }
+
+        void endCallLog(const std::string funcName,
+                        std::map<std::string, std::variant<uint64_t, std::string>> attributes) {
+            if (!enabled) {
+                return;
+            }
+
+            auto callStackIt = threadedCallStacks.find(GetCurrentThreadId());
+
+            if (callStackIt != threadedCallStacks.end()) {
+                auto callStack = &(*callStackIt).second;
+                const auto markResult = markCompleted(callStack, funcName, &attributes);
+
+                if (markResult) {
+                    if (callStack->status == COMPLETED) {
+                        commit(callStack);
+                    }
+                } else {
+                    Logger::error("Could not find " + funcName + " in call stack.");
+                    commit(callStack);
+                }
+            } else {
+                Logger::error("Could not find call stack for thread " + std::to_string(GetCurrentThreadId()));
+            }
+        }
+
+        std::vector<Call> getLogs() { return logs; }
+    } // namespace Chain
+} // namespace Logger