improve logging + minor refactors

loader/include/Geode/loader/Loader.hpp

@@ -63,6 +63,7 @@ namespace geode {
 
     public:
         // TODO: do we want to expose all of these functions?
+
         static Loader* get();
 
         enum class LoadingState : uint8_t {
@@ -76,6 +77,7 @@ namespace geode {
             Done
         };
 
+        // TODO: return void
         Result<> saveData();
         Result<> loadData();
 

loader/src/hooks/save.cpp

@@ -6,14 +6,18 @@ using namespace geode::prelude;
 
 struct SaveLoader : Modify<SaveLoader, AppDelegate> {
     void trySaveGame() {
-        log::info("Saving...");
+        log::info("Saving mod data...");
+        log::pushNest();
 
-        auto r = Loader::get()->saveData();
-        if (!r) {
-            log::info("{}", r.unwrapErr());
-        }
+        auto begin = std::chrono::high_resolution_clock::now();
 
-        log::info("Saved");
+        (void)Loader::get()->saveData();
+
+        auto end = std::chrono::high_resolution_clock::now();
+        auto time = std::chrono::duration_cast<std::chrono::milliseconds>(end - begin).count();
+        log::info("Took {}s", static_cast<float>(time) / 1000.f);
+
+        log::popNest();
 
         return AppDelegate::trySaveGame();
     }

loader/src/load.cpp

@@ -58,8 +58,17 @@ $execute {
 }
 
 int geodeEntry(void* platformData) {
+    log::Logger::setup();
+
+    log::info("Entry");
+
+    auto begin = std::chrono::high_resolution_clock::now();
+
     // set up internal mod, settings and data
+    log::info("Setting up internal mod");
+    log::pushNest();
     auto internalSetupRes = LoaderImpl::get()->setupInternalMod();
+    log::popNest();
     if (!internalSetupRes) {
         LoaderImpl::get()->platformMessageBox(
             "Unable to Load Geode!",
@@ -72,30 +81,38 @@ int geodeEntry(void* platformData) {
 
     // open console
     if (Mod::get()->getSettingValue<bool>("show-platform-console")) {
+        log::debug("Opening console");
         Loader::get()->openPlatformConsole();
     }
 
     // set up loader, load mods, etc.
+    log::info("Setting up loader");
+    log::pushNest();
     auto setupRes = LoaderImpl::get()->setup();
+    log::popNest();
     if (!setupRes) {
         LoaderImpl::get()->platformMessageBox(
             "Unable to Load Geode!",
             "There was an unknown fatal error setting up "
-            "the loader and Geode can not be loaded. " 
+            "the loader and Geode can not be loaded. "
             "(" + setupRes.unwrapErr() + ")"
         );
         LoaderImpl::get()->forceReset();
         return 1;
     }
 
-    log::info("Set up loader");
-
     // download and install new loader update in the background
     if (Mod::get()->getSettingValue<bool>("auto-check-updates")) {
+        log::info("Starting loader update check");
         LoaderImpl::get()->checkForLoaderUpdates();
     }
+    else {
+        log::info("Skipped loader update check");
+    }
 
-    log::debug("Entry done.");
+    auto end = std::chrono::high_resolution_clock::now();
+    auto time = std::chrono::duration_cast<std::chrono::milliseconds>(end - begin).count();
+    log::info("Entry took {}s", static_cast<float>(time) / 1000.f);
 
     return 0;
 }

loader/src/loader/HookImpl.cpp

@@ -44,28 +44,35 @@ tulip::hook::HookMetadata Hook::Impl::getHookMetadata() const {
 }
 
 Result<> Hook::Impl::enable() {
-    if (!m_enabled) {
-        if (!LoaderImpl::get()->hasHandler(m_address)) {
-            GEODE_UNWRAP(LoaderImpl::get()->createHandler(m_address, m_handlerMetadata));
-        }
-        GEODE_UNWRAP_INTO(auto handler, LoaderImpl::get()->getHandler(m_address));
+    if (m_enabled)
+        return Ok();
 
-        m_handle = tulip::hook::createHook(handler, m_detour, m_hookMetadata);
-        log::debug("Enabling hook at function {} with address {}", m_displayName, m_address);
-        m_enabled = true;
+    if (!LoaderImpl::get()->hasHandler(m_address)) {
+        GEODE_UNWRAP(LoaderImpl::get()->createHandler(m_address, m_handlerMetadata));
     }
+    GEODE_UNWRAP_INTO(auto handler, LoaderImpl::get()->getHandler(m_address));
+
+    m_handle = tulip::hook::createHook(handler, m_detour, m_hookMetadata);
+    if (m_owner)
+        log::debug("Enabled {} hook at {} for {}", m_displayName, m_address, m_owner->getID());
+    else
+        log::debug("Enabled {} hook at {}", m_displayName, m_address);
+
+    m_enabled = true;
     return Ok();
 }
 
 Result<> Hook::Impl::disable() {
-    if (m_enabled) {
-        GEODE_UNWRAP_INTO(auto handler, LoaderImpl::get()->getHandler(m_address));
+    if (!m_enabled)
+        return Ok();
 
-        tulip::hook::removeHook(handler, m_handle);
+    GEODE_UNWRAP_INTO(auto handler, LoaderImpl::get()->getHandler(m_address));
 
-        log::debug("Disabling hook at function {}", m_displayName);
-        m_enabled = false;
-    }
+    tulip::hook::removeHook(handler, m_handle);
+
+    log::debug("Disabled {} hook", m_displayName);
+
+    m_enabled = false;
     return Ok();
 }
 
@@ -101,4 +108,4 @@ bool Hook::Impl::getAutoEnable() const {
 
 void Hook::Impl::setAutoEnable(bool autoEnable) {
     m_autoEnable = autoEnable;
-}
+}

loader/src/loader/Index.cpp

@@ -403,6 +403,8 @@ void Index::Impl::checkForUpdates() {
 
 void Index::Impl::updateFromLocalTree() {
     log::debug("Updating local index cache");
+    log::pushNest();
+
     IndexUpdateEvent(UpdateProgress(100, "Updating local cache")).post();
     // delete old items
     m_items.clear();
@@ -442,6 +444,8 @@ void Index::Impl::updateFromLocalTree() {
     // mark source as finished
     m_isUpToDate = true;
     IndexUpdateEvent(UpdateFinished()).post();
+
+    log::popNest();
 }
 
 void Index::update(bool force) {

loader/src/loader/LoaderImpl.cpp

@@ -61,33 +61,30 @@ Result<> Loader::Impl::setup() {
         return Ok();
     }
 
-    log::Logger::setup();
-
-    if (crashlog::setupPlatformHandler()) {
-        log::debug("Set up platform crash logger");
-    }
-    else {
-        log::debug("Unable to set up platform crash logger");
+    log::debug("Setting up crash handler");
+    log::pushNest();
+    if (!crashlog::setupPlatformHandler()) {
+        log::debug("Failed to set up crash handler");
     }
+    log::popNest();
 
-    log::debug("Setting up Loader...");
-
-    log::debug("Set up internal mod representation");
-    log::debug("Loading hooks... ");
-
+    log::debug("Loading hooks");
+    log::pushNest();
     if (!this->loadHooks()) {
         return Err("There were errors loading some hooks, see console for details");
     }
+    log::popNest();
 
-    log::debug("Loaded hooks");
-
-    log::debug("Setting up IPC...");
-
+    log::debug("Setting up IPC");
+    log::pushNest();
     this->setupIPC();
+    log::popNest();
 
+    log::debug("Setting up directories");
+    log::pushNest();
     this->createDirectories();
-
     this->addSearchPaths();
+    log::popNest();
 
     this->refreshModGraph();
 
@@ -107,14 +104,14 @@ void Loader::Impl::updateResources() {
 
 void Loader::Impl::updateResources(bool forceReload) {
     log::debug("Adding resources");
-
-    // add mods' spritesheets
+    log::pushNest();
     for (auto const& [_, mod] : m_mods) {
-        if (forceReload || !ModImpl::getImpl(mod)->m_resourcesLoaded) {
-            this->updateModResources(mod);
-            ModImpl::getImpl(mod)->m_resourcesLoaded = true;
-        }
+        if (!forceReload && ModImpl::getImpl(mod)->m_resourcesLoaded)
+            continue;
+        this->updateModResources(mod);
+        ModImpl::getImpl(mod)->m_resourcesLoaded = true;
     }
+    log::popNest();
 }
 
 std::vector<Mod*> Loader::Impl::getAllMods() {
@@ -164,25 +161,27 @@ bool Loader::Impl::isModVersionSupported(VersionInfo const& version) {
 // Data saving
 
 Result<> Loader::Impl::saveData() {
-    // save mods' data
     for (auto& [id, mod] : m_mods) {
+        log::debug("{}", mod->getID());
+        log::pushNest();
         auto r = mod->saveData();
         if (!r) {
             log::warn("Unable to save data for mod \"{}\": {}", mod->getID(), r.unwrapErr());
         }
+        log::popNest();
     }
-    // save loader data
-    GEODE_UNWRAP(Mod::get()->saveData());
-
     return Ok();
 }
 
 Result<> Loader::Impl::loadData() {
     for (auto& [_, mod] : m_mods) {
+        log::debug("{}", mod->getID());
+        log::pushNest();
         auto r = mod->loadData();
         if (!r) {
             log::warn("Unable to load data for mod \"{}\": {}", mod->getID(), r.unwrapErr());
         }
+        log::popNest();
     }
     return Ok();
 }
@@ -225,9 +224,9 @@ void Loader::Impl::updateModResources(Mod* mod) {
     if (mod->getMetadata().getSpritesheets().empty())
         return;
 
-    log::debug("Adding resources for {}", mod->getID());
+    log::debug("{}", mod->getID());
+    log::pushNest();
 
-    // add spritesheets
     for (auto const& sheet : mod->getMetadata().getSpritesheets()) {
         log::debug("Adding sheet {}", sheet);
         auto png = sheet + ".png";
@@ -246,6 +245,8 @@ void Loader::Impl::updateModResources(Mod* mod) {
             CCSpriteFrameCache::get()->addSpriteFramesWithFile(plist.c_str());
         }
     }
+
+    log::popNest();
 }
 
 // Dependencies and refreshing
@@ -422,6 +423,9 @@ void Loader::Impl::loadModGraph(Mod* node, bool early) {
             return;
         }
 
+        if (node->getID() == "absolllute.megahack")
+            log::debug("megahack creepypasta");
+
         for (auto const& dep : node->m_impl->m_dependants) {
             this->loadModGraph(dep, early);
         }
@@ -512,17 +516,17 @@ void Loader::Impl::findProblems() {
 }
 
 void Loader::Impl::refreshModGraph() {
-    log::info("Refreshing mod graph...");
+    log::info("Refreshing mod graph");
     log::pushNest();
 
-    auto begin = std::chrono::high_resolution_clock::now();
-
     if (m_isSetup) {
         log::error("Cannot refresh mod graph after startup");
         log::popNest();
         return;
     }
 
+    auto begin = std::chrono::high_resolution_clock::now();
+
     m_problems.clear();
 
     m_loadingState = LoadingState::Queue;
@@ -641,23 +645,22 @@ bool Loader::Impl::isReadyToHook() const {
     return m_readyToHook;
 }
 
-void Loader::Impl::addInternalHook(Hook* hook, Mod* mod) {
-    m_internalHooks.emplace_back(hook, mod);
+void Loader::Impl::addUninitializedHook(Hook* hook, Mod* mod) {
+    m_uninitializedHooks.emplace_back(hook, mod);
 }
 
 bool Loader::Impl::loadHooks() {
     m_readyToHook = true;
-    auto thereWereErrors = false;
-    for (auto const& hook : m_internalHooks) {
+    bool hadErrors = false;
+    for (auto const& hook : m_uninitializedHooks) {
         auto res = hook.second->addHook(hook.first);
         if (!res) {
             log::internalLog(Severity::Error, hook.second, "{}", res.unwrapErr());
-            thereWereErrors = true;
+            hadErrors = true;
         }
     }
-    // free up memory
-    m_internalHooks.clear();
-    return !thereWereErrors;
+    m_uninitializedHooks.clear();
+    return !hadErrors;
 }
 
 void Loader::Impl::queueInMainThread(ScheduledFunction func) {
@@ -1037,21 +1040,16 @@ void Loader::Impl::provideNextMod(Mod* mod) {
 }
 
 Mod* Loader::Impl::takeNextMod() {
-    if (!m_nextMod) {
-        m_nextMod = this->createInternalMod();
-        log::debug("Created internal mod {}", m_nextMod->getName());
-    }
-    auto ret = m_nextMod;
-    return ret;
+    if (!m_nextMod)
+        m_nextMod = this->getInternalMod();
+    return m_nextMod;
 }
 
 void Loader::Impl::releaseNextMod() {
     m_nextMod = nullptr;
-
     m_nextModLock.unlock();
 }
 
-
 Result<> Loader::Impl::createHandler(void* address, tulip::hook::HandlerMetadata const& metadata) {
     if (m_handlerHandles.count(address)) {
         return Err("Handler already exists at address");

loader/src/loader/LoaderImpl.hpp

@@ -72,7 +72,7 @@ namespace geode {
         std::vector<utils::MiniFunction<void(void)>> m_gdThreadQueue;
         mutable std::mutex m_gdThreadMutex;
         bool m_platformConsoleOpen = false;
-        std::vector<std::pair<Hook*, Mod*>> m_internalHooks;
+        std::vector<std::pair<Hook*, Mod*>> m_uninitializedHooks;
         bool m_readyToHook = false;
 
         std::mutex m_nextModMutex;
@@ -173,9 +173,9 @@ namespace geode {
         bool isNewUpdateDownloaded() const;
 
         bool isReadyToHook() const;
-        void addInternalHook(Hook* hook, Mod* mod);
+        void addUninitializedHook(Hook* hook, Mod* mod);
 
-        Mod* createInternalMod();
+        Mod* getInternalMod();
         Result<> setupInternalMod();
 
         bool userTriedToLoadDLLs() const;

loader/src/loader/Log.cpp

@@ -113,6 +113,36 @@ std::string Log::toString(bool logTime, uint32_t nestLevel) const {
         res += fmt::format("{:%H:%M:%S}", m_time);
     }
 
+    switch (m_severity.m_value) {
+        case Severity::Debug:
+            res += " DBG";
+            break;
+        case Severity::Info:
+            res += " INF";
+            break;
+        case Severity::Notice:
+            res += " NTC";
+            break;
+        case Severity::Warning:
+            res += " WRN";
+            break;
+        case Severity::Error:
+            res += " ERR";
+            break;
+        case Severity::Critical:
+            res += " CRT";
+            break;
+        case Severity::Alert:
+            res += " ALR";
+            break;
+        case Severity::Emergency:
+            res += " FAT";
+            break;
+        default:
+            res += " UNK";
+            break;
+    }
+
     res += fmt::format(" [{}]: ", m_sender ? m_sender->getName() : "Geode?");
 
     for (uint32_t i = 0; i < nestLevel; i++) {

loader/src/loader/ModImpl.cpp

@@ -224,7 +224,7 @@ Result<> Mod::Impl::saveData() {
         log::debug("Check covered");
         for (auto& [key, value] : m_savedSettingsData.as_object()) {
             log::debug("Check if {} is saved", key);
-            if (!coveredSettings.count(key)) {
+            if (!coveredSettings.contains(key)) {
                 json[key] = value;
             }
         }
@@ -465,18 +465,21 @@ Result<> Mod::Impl::disableHook(Hook* hook) {
 }
 
 Result<Hook*> Mod::Impl::addHook(Hook* hook) {
-    m_hooks.push_back(hook);
-    if (LoaderImpl::get()->isReadyToHook()) {
-        if (this->isEnabled() && hook->getAutoEnable()) {
-            auto res = this->enableHook(hook);
-            if (!res) {
-                delete hook;
-                return Err("Can't create hook: "+ res.unwrapErr());
-            }
-        }
+    if (!ranges::contains(m_hooks, [&](auto const& h) { return h != hook; }))
+        m_hooks.push_back(hook);
+
+    if (!LoaderImpl::get()->isReadyToHook()) {
+        LoaderImpl::get()->addUninitializedHook(hook, m_self);
+        return Ok(hook);
     }
-    else {
-        LoaderImpl::get()->addInternalHook(hook, m_self);
+
+    if (!this->isEnabled() || !hook->getAutoEnable())
+        return Ok(hook);
+
+    auto res = this->enableHook(hook);
+    if (!res) {
+        delete hook;
+        return Err("Can't create hook: " + res.unwrapErr());
     }
 
     return Ok(hook);
@@ -620,9 +623,10 @@ static Result<ModMetadata> getModImplInfo() {
     return Ok(info);
 }
 
-Mod* Loader::Impl::createInternalMod() {
+Mod* Loader::Impl::getInternalMod() {
     auto& mod = Mod::sharedMod<>;
-    if (mod) return mod;
+    if (mod)
+        return mod;
     auto infoRes = getModImplInfo();
     if (!infoRes) {
         LoaderImpl::get()->platformMessageBox(
@@ -639,6 +643,7 @@ Mod* Loader::Impl::createInternalMod() {
     }
     mod->m_impl->m_enabled = true;
     m_mods.insert({ mod->getID(), mod });
+    log::debug("Created internal mod {}", mod->getName());
     return mod;
 }
 

loader/src/platform/windows/LoaderImpl.cpp

@@ -20,24 +20,37 @@ void Loader::Impl::platformMessageBox(char const* title, std::string const& info
 bool hasAnsiColorSupport = false;
 
 void Loader::Impl::logConsoleMessageWithSeverity(std::string const& msg, Severity severity) {
-    if (m_platformConsoleOpen) {
-        if (hasAnsiColorSupport) {
-            int color = 0;
-            switch (severity) {
-                case Severity::Debug: color = 243; break;
-                case Severity::Info: color = 33; break;
-                case Severity::Warning: color = 229; break;
-                case Severity::Error: color = 9; break;
-                default: color = 7; break;
-            }
-            auto const colorStr = fmt::format("\x1b[38;5;{}m", color);
-            auto const newMsg = fmt::format("{}{}\x1b[0m{}", colorStr, msg.substr(0, 8), msg.substr(8));
+    if (!m_platformConsoleOpen)
+        return;
 
-            std::cout << newMsg << "\n" << std::flush;
-        } else {
-            std::cout << msg << "\n" << std::flush;
-        }
+    if (!hasAnsiColorSupport) {
+        std::cout << msg << "\n" << std::flush;
+        return;
     }
+
+    int color = 0;
+    switch (severity) {
+        case Severity::Debug:
+            color = 243;
+            break;
+        case Severity::Info:
+            color = 33;
+            break;
+        case Severity::Warning:
+            color = 229;
+            break;
+        case Severity::Error:
+            color = 9;
+            break;
+        default:
+            color = 7;
+            break;
+    }
+    auto const colorStr = fmt::format("\x1b[38;5;{}m", color);
+    auto const newMsg = fmt::format("{}{}\x1b[0m{}", colorStr, msg.substr(0, 12),
+        msg.substr(12));
+
+    std::cout << newMsg << "\n" << std::flush;
 }
 
 void Loader::Impl::openPlatformConsole() {