diff options
author | Jack <66967891+ASpoonPlaysGames@users.noreply.github.com> | 2023-07-07 16:11:43 +0100 |
---|---|---|
committer | GitHub <noreply@github.com> | 2023-07-07 17:11:43 +0200 |
commit | 9f9e3a906f2792ee518c7d9910d70607469f80ae (patch) | |
tree | 0716bc0639a181c1a390eb3ca3d3e54a8c8bbf9d | |
parent | 513705e33f59273c5b463c0da874a0066e8d0589 (diff) | |
download | NorthstarLauncher-1.16.3-rc1.tar.gz NorthstarLauncher-1.16.3-rc1.zip |
Improve logging for mods (#445)v1.16.3-rc2v1.16.3-rc1v1.16.3v1.16.2-rc1v1.16.2v1.16.1-rc1v1.16.11.16.X
- Removes the log spam of "changing mod search path"
- Logs mods as they are loaded, alongside their ConVars, Scripts, ConCommands, etc.
- Warns in the console about errors in the mod.json instead of silently skipping things
-rw-r--r-- | NorthstarDLL/core/filesystem/filesystem.cpp | 2 | ||||
-rw-r--r-- | NorthstarDLL/mods/modmanager.cpp | 458 | ||||
-rw-r--r-- | NorthstarDLL/mods/modmanager.h | 8 |
3 files changed, 343 insertions, 125 deletions
diff --git a/NorthstarDLL/core/filesystem/filesystem.cpp b/NorthstarDLL/core/filesystem/filesystem.cpp index d9c70476..e4da647f 100644 --- a/NorthstarDLL/core/filesystem/filesystem.cpp +++ b/NorthstarDLL/core/filesystem/filesystem.cpp @@ -73,8 +73,6 @@ void SetNewModSearchPaths(Mod* mod) { if ((fs::absolute(mod->m_ModDirectory) / MOD_OVERRIDE_DIR).string().compare(sCurrentModPath)) { - NS::log::fs->info("Changing mod search path from {} to {}", sCurrentModPath, mod->m_ModDirectory.string()); - AddSearchPath( &*(*g_pFilesystem), (fs::absolute(mod->m_ModDirectory) / MOD_OVERRIDE_DIR).string().c_str(), "GAME", PATH_ADD_TO_HEAD); sCurrentModPath = (fs::absolute(mod->m_ModDirectory) / MOD_OVERRIDE_DIR).string(); diff --git a/NorthstarDLL/mods/modmanager.cpp b/NorthstarDLL/mods/modmanager.cpp index cdfe5384..d2cc8eb8 100644 --- a/NorthstarDLL/mods/modmanager.cpp +++ b/NorthstarDLL/mods/modmanager.cpp @@ -28,6 +28,8 @@ Mod::Mod(fs::path modDir, char* jsonBuf) rapidjson_document modJson; modJson.Parse<rapidjson::ParseFlag::kParseCommentsFlag | rapidjson::ParseFlag::kParseTrailingCommasFlag>(jsonBuf); + spdlog::info("Loading mod file at path '{}'", modDir.string()); + // fail if parse error if (modJson.HasParseError()) { @@ -55,6 +57,7 @@ Mod::Mod(fs::path modDir, char* jsonBuf) } Name = modJson["Name"].GetString(); + spdlog::info("Loading mod '{}'", Name); // Don't load blacklisted mods if (!strstr(GetCommandLineA(), "-nomodblacklist") && MODS_BLACKLIST.find(Name) != std::end(MODS_BLACKLIST)) @@ -94,197 +97,400 @@ Mod::Mod(fs::path modDir, char* jsonBuf) LoadPriority = 0; } - // mod convars - if (modJson.HasMember("ConVars") && modJson["ConVars"].IsArray()) + // Parse all array fields + ParseConVars(modJson); + ParseConCommands(modJson); + ParseScripts(modJson); + ParseLocalization(modJson); + ParseDependencies(modJson); + ParseInitScript(modJson); + + m_bWasReadSuccessfully = true; +} + +void Mod::ParseConVars(rapidjson_document& json) +{ + if (!json.HasMember("ConVars")) + return; + + if (!json["ConVars"].IsArray()) + { + spdlog::warn("'ConVars' field is not an array, skipping..."); + return; + } + + for (auto& convarObj : json["ConVars"].GetArray()) { - for (auto& convarObj : modJson["ConVars"].GetArray()) + if (!convarObj.IsObject()) { - if (!convarObj.IsObject() || !convarObj.HasMember("Name") || !convarObj.HasMember("DefaultValue")) - continue; + spdlog::warn("ConVar is not an object, skipping..."); + continue; + } + if (!convarObj.HasMember("Name")) + { + spdlog::warn("ConVar does not have a Name, skipping..."); + continue; + } + // from here on, the ConVar can be referenced by name in logs + if (!convarObj.HasMember("DefaultValue")) + { + spdlog::warn("ConVar '{}' does not have a DefaultValue, skipping...", convarObj["Name"].GetString()); + continue; + } - // have to allocate this manually, otherwise convar registration will break - // unfortunately this causes us to leak memory on reload, unsure of a way around this rn - ModConVar* convar = new ModConVar; - convar->Name = convarObj["Name"].GetString(); - convar->DefaultValue = convarObj["DefaultValue"].GetString(); + // have to allocate this manually, otherwise convar registration will break + // unfortunately this causes us to leak memory on reload, unsure of a way around this rn + ModConVar* convar = new ModConVar; + convar->Name = convarObj["Name"].GetString(); + convar->DefaultValue = convarObj["DefaultValue"].GetString(); - if (convarObj.HasMember("HelpString")) - convar->HelpString = convarObj["HelpString"].GetString(); - else - convar->HelpString = ""; + if (convarObj.HasMember("HelpString")) + convar->HelpString = convarObj["HelpString"].GetString(); + else + convar->HelpString = ""; - convar->Flags = FCVAR_NONE; + convar->Flags = FCVAR_NONE; - if (convarObj.HasMember("Flags")) + if (convarObj.HasMember("Flags")) + { + // read raw integer flags + if (convarObj["Flags"].IsInt()) + convar->Flags = convarObj["Flags"].GetInt(); + else if (convarObj["Flags"].IsString()) { - // read raw integer flags - if (convarObj["Flags"].IsInt()) - convar->Flags = convarObj["Flags"].GetInt(); - else if (convarObj["Flags"].IsString()) - { - // parse cvar flags from string - // example string: ARCHIVE_PLAYERPROFILE | GAMEDLL - convar->Flags |= ParseConVarFlagsString(convar->Name, convarObj["Flags"].GetString()); - } + // parse cvar flags from string + // example string: ARCHIVE_PLAYERPROFILE | GAMEDLL + convar->Flags |= ParseConVarFlagsString(convar->Name, convarObj["Flags"].GetString()); } - - ConVars.push_back(convar); } + + ConVars.push_back(convar); + + spdlog::info("'{}' contains ConVar '{}'", Name, convar->Name); + } +} + +void Mod::ParseConCommands(rapidjson_document& json) +{ + if (!json.HasMember("ConCommands")) + return; + + if (!json["ConCommands"].IsArray()) + { + spdlog::warn("'ConCommands' field is not an array, skipping..."); + return; } - if (modJson.HasMember("ConCommands") && modJson["ConCommands"].IsArray()) + for (auto& concommandObj : json["ConCommands"].GetArray()) { - for (auto& concommandObj : modJson["ConCommands"].GetArray()) + if (!concommandObj.IsObject()) + { + spdlog::warn("ConCommand is not an object, skipping..."); + continue; + } + if (!concommandObj.HasMember("Name")) { - if (!concommandObj.IsObject() || !concommandObj.HasMember("Name") || !concommandObj.HasMember("Function") || - !concommandObj.HasMember("Context")) + spdlog::warn("ConCommand does not have a Name, skipping..."); + continue; + } + // from here on, the ConCommand can be referenced by name in logs + if (!concommandObj.HasMember("Function")) + { + spdlog::warn("ConCommand '{}' does not have a Function, skipping...", concommandObj["Name"].GetString()); + continue; + } + if (!concommandObj.HasMember("Context")) + { + spdlog::warn("ConCommand '{}' does not have a Context, skipping...", concommandObj["Name"].GetString()); + continue; + } + + // have to allocate this manually, otherwise concommand registration will break + // unfortunately this causes us to leak memory on reload, unsure of a way around this rn + ModConCommand* concommand = new ModConCommand; + concommand->Name = concommandObj["Name"].GetString(); + concommand->Function = concommandObj["Function"].GetString(); + concommand->Context = ScriptContextFromString(concommandObj["Context"].GetString()); + if (concommand->Context == ScriptContext::INVALID) + { + spdlog::warn("ConCommand '{}' has invalid context '{}', skipping...", concommand->Name, concommandObj["Context"].GetString()); + continue; + } + + if (concommandObj.HasMember("HelpString")) + concommand->HelpString = concommandObj["HelpString"].GetString(); + else + concommand->HelpString = ""; + + concommand->Flags = FCVAR_NONE; + + if (concommandObj.HasMember("Flags")) + { + // read raw integer flags + if (concommandObj["Flags"].IsInt()) { - continue; + concommand->Flags = concommandObj["Flags"].GetInt(); } - - // have to allocate this manually, otherwise concommand registration will break - // unfortunately this causes us to leak memory on reload, unsure of a way around this rn - ModConCommand* concommand = new ModConCommand; - concommand->Name = concommandObj["Name"].GetString(); - concommand->Function = concommandObj["Function"].GetString(); - concommand->Context = ScriptContextFromString(concommandObj["Context"].GetString()); - if (concommand->Context == ScriptContext::INVALID) + else if (concommandObj["Flags"].IsString()) { - spdlog::warn("Mod ConCommand {} has invalid context {}", concommand->Name, concommandObj["Context"].GetString()); - continue; + // parse cvar flags from string + // example string: ARCHIVE_PLAYERPROFILE | GAMEDLL + concommand->Flags |= ParseConVarFlagsString(concommand->Name, concommandObj["Flags"].GetString()); } + } - if (concommandObj.HasMember("HelpString")) - concommand->HelpString = concommandObj["HelpString"].GetString(); - else - concommand->HelpString = ""; + ConCommands.push_back(concommand); - concommand->Flags = FCVAR_NONE; + spdlog::info("'{}' contains ConCommand '{}'", Name, concommand->Name); + } +} - if (concommandObj.HasMember("Flags")) - { - // read raw integer flags - if (concommandObj["Flags"].IsInt()) - { - concommand->Flags = concommandObj["Flags"].GetInt(); - } - else if (concommandObj["Flags"].IsString()) - { - // parse cvar flags from string - // example string: ARCHIVE_PLAYERPROFILE | GAMEDLL - concommand->Flags |= ParseConVarFlagsString(concommand->Name, concommandObj["Flags"].GetString()); - } - } +void Mod::ParseScripts(rapidjson_document& json) +{ + if (!json.HasMember("Scripts")) + return; - ConCommands.push_back(concommand); - } + if (!json["Scripts"].IsArray()) + { + spdlog::warn("'Scripts' field is not an array, skipping..."); + return; } - // mod scripts - if (modJson.HasMember("Scripts") && modJson["Scripts"].IsArray()) + for (auto& scriptObj : json["Scripts"].GetArray()) { - for (auto& scriptObj : modJson["Scripts"].GetArray()) + if (!scriptObj.IsObject()) { - if (!scriptObj.IsObject() || !scriptObj.HasMember("Path") || !scriptObj.HasMember("RunOn")) - continue; + spdlog::warn("Script is not an object, skipping..."); + continue; + } + if (!scriptObj.HasMember("Path")) + { + spdlog::warn("Script does not have a Path, skipping..."); + continue; + } + // from here on, the Path for a script is used as it's name in logs + if (!scriptObj.HasMember("RunOn")) + { + // "a RunOn" sounds dumb but anything else doesn't match the format of the warnings... + // this is the best i could think of within 20 seconds + spdlog::warn("Script '{}' does not have a RunOn field, skipping...", scriptObj["Path"].GetString()); + continue; + } - ModScript script; + ModScript script; - script.Path = scriptObj["Path"].GetString(); - script.RunOn = scriptObj["RunOn"].GetString(); + script.Path = scriptObj["Path"].GetString(); + script.RunOn = scriptObj["RunOn"].GetString(); - if (scriptObj.HasMember("ServerCallback") && scriptObj["ServerCallback"].IsObject()) + if (scriptObj.HasMember("ServerCallback")) + { + if (scriptObj["ServerCallback"].IsObject()) { ModScriptCallback callback; callback.Context = ScriptContext::SERVER; - if (scriptObj["ServerCallback"].HasMember("Before") && scriptObj["ServerCallback"]["Before"].IsString()) - callback.BeforeCallback = scriptObj["ServerCallback"]["Before"].GetString(); + if (scriptObj["ServerCallback"].HasMember("Before")) + { + if (scriptObj["ServerCallback"]["Before"].IsString()) + callback.BeforeCallback = scriptObj["ServerCallback"]["Before"].GetString(); + else + spdlog::warn("'Before' ServerCallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } - if (scriptObj["ServerCallback"].HasMember("After") && scriptObj["ServerCallback"]["After"].IsString()) - callback.AfterCallback = scriptObj["ServerCallback"]["After"].GetString(); + if (scriptObj["ServerCallback"].HasMember("After")) + { + if (scriptObj["ServerCallback"]["After"].IsString()) + callback.AfterCallback = scriptObj["ServerCallback"]["After"].GetString(); + else + spdlog::warn("'After' ServerCallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } - if (scriptObj["ServerCallback"].HasMember("Destroy") && scriptObj["ServerCallback"]["Destroy"].IsString()) - callback.DestroyCallback = scriptObj["ServerCallback"]["Destroy"].GetString(); + if (scriptObj["ServerCallback"].HasMember("Destroy")) + { + if (scriptObj["ServerCallback"]["Destroy"].IsString()) + callback.DestroyCallback = scriptObj["ServerCallback"]["Destroy"].GetString(); + else + spdlog::warn( + "'Destroy' ServerCallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } script.Callbacks.push_back(callback); } + else + { + spdlog::warn("ServerCallback for script '{}' is not an object, skipping...", scriptObj["Path"].GetString()); + } + } - if (scriptObj.HasMember("ClientCallback") && scriptObj["ClientCallback"].IsObject()) + if (scriptObj.HasMember("ClientCallback")) + { + if (scriptObj["ClientCallback"].IsObject()) { ModScriptCallback callback; callback.Context = ScriptContext::CLIENT; - if (scriptObj["ClientCallback"].HasMember("Before") && scriptObj["ClientCallback"]["Before"].IsString()) - callback.BeforeCallback = scriptObj["ClientCallback"]["Before"].GetString(); + if (scriptObj["ClientCallback"].HasMember("Before")) + { + if (scriptObj["ClientCallback"]["Before"].IsString()) + callback.BeforeCallback = scriptObj["ClientCallback"]["Before"].GetString(); + else + spdlog::warn("'Before' ClientCallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } - if (scriptObj["ClientCallback"].HasMember("After") && scriptObj["ClientCallback"]["After"].IsString()) - callback.AfterCallback = scriptObj["ClientCallback"]["After"].GetString(); + if (scriptObj["ClientCallback"].HasMember("After")) + { + if (scriptObj["ClientCallback"]["After"].IsString()) + callback.AfterCallback = scriptObj["ClientCallback"]["After"].GetString(); + else + spdlog::warn("'After' ClientCallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } - if (scriptObj["ClientCallback"].HasMember("Destroy") && scriptObj["ClientCallback"]["Destroy"].IsString()) - callback.DestroyCallback = scriptObj["ClientCallback"]["Destroy"].GetString(); + if (scriptObj["ClientCallback"].HasMember("Destroy")) + { + if (scriptObj["ClientCallback"]["Destroy"].IsString()) + callback.DestroyCallback = scriptObj["ClientCallback"]["Destroy"].GetString(); + else + spdlog::warn( + "'Destroy' ClientCallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } script.Callbacks.push_back(callback); } + else + { + spdlog::warn("ClientCallback for script '{}' is not an object, skipping...", scriptObj["Path"].GetString()); + } + } - if (scriptObj.HasMember("UICallback") && scriptObj["UICallback"].IsObject()) + if (scriptObj.HasMember("UICallback")) + { + if (scriptObj["UICallback"].IsObject()) { ModScriptCallback callback; callback.Context = ScriptContext::UI; - if (scriptObj["UICallback"].HasMember("Before") && scriptObj["UICallback"]["Before"].IsString()) - callback.BeforeCallback = scriptObj["UICallback"]["Before"].GetString(); + if (scriptObj["UICallback"].HasMember("Before")) + { + if (scriptObj["UICallback"]["Before"].IsString()) + callback.BeforeCallback = scriptObj["UICallback"]["Before"].GetString(); + else + spdlog::warn("'Before' UICallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } - if (scriptObj["UICallback"].HasMember("After") && scriptObj["UICallback"]["After"].IsString()) - callback.AfterCallback = scriptObj["UICallback"]["After"].GetString(); + if (scriptObj["UICallback"].HasMember("After")) + { + if (scriptObj["UICallback"]["After"].IsString()) + callback.AfterCallback = scriptObj["UICallback"]["After"].GetString(); + else + spdlog::warn("'After' UICallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } - if (scriptObj["UICallback"].HasMember("Destroy") && scriptObj["UICallback"]["Destroy"].IsString()) - callback.DestroyCallback = scriptObj["UICallback"]["Destroy"].GetString(); + if (scriptObj["UICallback"].HasMember("Destroy")) + { + if (scriptObj["UICallback"]["Destroy"].IsString()) + callback.DestroyCallback = scriptObj["UICallback"]["Destroy"].GetString(); + else + spdlog::warn("'Destroy' UICallback for script '{}' is not a string, skipping...", scriptObj["Path"].GetString()); + } script.Callbacks.push_back(callback); } - - Scripts.push_back(script); + else + { + spdlog::warn("UICallback for script '{}' is not an object, skipping...", scriptObj["Path"].GetString()); + } } + + Scripts.push_back(script); + + spdlog::info("'{}' contains Script '{}'", Name, script.Path); } +} - if (modJson.HasMember("InitScript") && modJson["InitScript"].IsString()) +void Mod::ParseLocalization(rapidjson_document& json) +{ + if (!json.HasMember("Localisation")) + return; + + if (!json["Localisation"].IsArray()) { - initScript = modJson["InitScript"].GetString(); + spdlog::warn("'Localisation' field is not an array, skipping..."); + return; } - if (modJson.HasMember("Localisation") && modJson["Localisation"].IsArray()) + for (auto& localisationStr : json["Localisation"].GetArray()) { - for (auto& localisationStr : modJson["Localisation"].GetArray()) + if (!localisationStr.IsString()) { - if (!localisationStr.IsString()) - continue; - - LocalisationFiles.push_back(localisationStr.GetString()); + // not a string but we still GetString() to log it :trol: + spdlog::warn("Localisation '{}' is not a string, skipping...", localisationStr.GetString()); + continue; } + + LocalisationFiles.push_back(localisationStr.GetString()); + + spdlog::info("'{}' registered Localisation '{}'", Name, localisationStr.GetString()); } +} - if (modJson.HasMember("Dependencies") && modJson["Dependencies"].IsObject()) +void Mod::ParseDependencies(rapidjson_document& json) +{ + if (!json.HasMember("Dependencies")) + return; + + if (!json["Dependencies"].IsObject()) { - for (auto v = modJson["Dependencies"].MemberBegin(); v != modJson["Dependencies"].MemberEnd(); v++) - { - if (!v->name.IsString() || !v->value.IsString()) - continue; + spdlog::warn("'Dependencies' field is not an object, skipping..."); + return; + } - spdlog::info("Constant {} defined by {} for mod {}", v->name.GetString(), Name, v->value.GetString()); - if (DependencyConstants.find(v->name.GetString()) != DependencyConstants.end() && - v->value.GetString() != DependencyConstants[v->name.GetString()]) - { - spdlog::error("A dependency constant with the same name already exists for another mod. Change the constant name."); - return; - } + for (auto v = json["Dependencies"].MemberBegin(); v != json["Dependencies"].MemberEnd(); v++) + { + if (!v->name.IsString()) + { + spdlog::warn("Dependency constant '{}' is not a string, skipping...", v->name.GetString()); + continue; + } + if (!v->value.IsString()) + { + spdlog::warn("Dependency constant '{}' is not a string, skipping...", v->value.GetString()); + continue; + } - if (DependencyConstants.find(v->name.GetString()) == DependencyConstants.end()) - DependencyConstants.emplace(v->name.GetString(), v->value.GetString()); + if (DependencyConstants.find(v->name.GetString()) != DependencyConstants.end() && + v->value.GetString() != DependencyConstants[v->name.GetString()]) + { + // this is fatal because otherwise the mod will probably try to use functions that dont exist, + // which will cause errors further down the line that are harder to debug + spdlog::error( + "'{}' attempted to register a dependency constant '{}' for '{}' that already exists for '{}'. " + "Change the constant name.", + Name, + v->name.GetString(), + v->value.GetString(), + DependencyConstants[v->name.GetString()]); + return; } + + if (DependencyConstants.find(v->name.GetString()) == DependencyConstants.end()) + DependencyConstants.emplace(v->name.GetString(), v->value.GetString()); + + spdlog::info("'{}' registered dependency constant '{}' for mod '{}'", Name, v->name.GetString(), v->value.GetString()); } +} - m_bWasReadSuccessfully = true; +void Mod::ParseInitScript(rapidjson_document& json) +{ + if (!json.HasMember("InitScript")) + return; + + if (!json["InitScript"].IsString()) + { + spdlog::warn("'InitScript' field is not a string, skipping..."); + return; + } + + initScript = json["InitScript"].GetString(); } ModManager::ModManager() @@ -419,7 +625,8 @@ void ModManager::LoadMods() // fail if no mod json if (jsonStream.fail()) { - spdlog::warn("Mod {} has a directory but no mod.json", modDir.string()); + spdlog::warn( + "Mod file at '{}' does not exist or could not be read, is it installed correctly?", (modDir / "mod.json").string()); continue; } @@ -434,7 +641,13 @@ void ModManager::LoadMods() { if (m_DependencyConstants.find(pair.first) != m_DependencyConstants.end() && m_DependencyConstants[pair.first] != pair.second) { - spdlog::error("Constant {} in mod {} already exists in another mod.", pair.first, mod.Name); + spdlog::error( + "'{}' attempted to register a dependency constant '{}' for '{}' that already exists for '{}'. " + "Change the constant name.", + mod.Name, + pair.first, + pair.second, + m_DependencyConstants[pair.first]); mod.m_bWasReadSuccessfully = false; break; } @@ -449,16 +662,15 @@ void ModManager::LoadMods() if (mod.m_bWasReadSuccessfully) { - spdlog::info("Loaded mod {} successfully", mod.Name); if (mod.m_bEnabled) - spdlog::info("Mod {} is enabled", mod.Name); + spdlog::info("'{}' loaded successfully", mod.Name); else - spdlog::info("Mod {} is disabled", mod.Name); + spdlog::info("'{}' loaded successfully (DISABLED)", mod.Name); m_LoadedMods.push_back(mod); } else - spdlog::warn("Skipping loading mod file {}", (modDir / "mod.json").string()); + spdlog::warn("Mod file at '{}' failed to load", (modDir / "mod.json").string()); } // sort by load prio, lowest-highest diff --git a/NorthstarDLL/mods/modmanager.h b/NorthstarDLL/mods/modmanager.h index c25c95ba..33f4ceac 100644 --- a/NorthstarDLL/mods/modmanager.h +++ b/NorthstarDLL/mods/modmanager.h @@ -126,6 +126,14 @@ class Mod public: Mod(fs::path modPath, char* jsonBuf); + + private: + void ParseConVars(rapidjson_document& json); + void ParseConCommands(rapidjson_document& json); + void ParseScripts(rapidjson_document& json); + void ParseLocalization(rapidjson_document& json); + void ParseDependencies(rapidjson_document& json); + void ParseInitScript(rapidjson_document& json); }; struct ModOverrideFile |