From 7a5d2f3362610be3c4da2ff08a9000cf4d993317 Mon Sep 17 00:00:00 2001 From: Anairkoen Schno Date: Tue, 1 Jun 2021 00:59:36 -0500 Subject: [PATCH] Add trace logging to new loader for debugging issues --- IPA.Injector/PermissionFix.cs | 134 +++++++++++++++--------------- IPA.Loader/Loader/PluginLoader.cs | 26 +++++- IPA.Loader/Loader/manifest.json | 4 +- 3 files changed, 92 insertions(+), 72 deletions(-) diff --git a/IPA.Injector/PermissionFix.cs b/IPA.Injector/PermissionFix.cs index 7b531e52..2cd891b2 100644 --- a/IPA.Injector/PermissionFix.cs +++ b/IPA.Injector/PermissionFix.cs @@ -1,73 +1,73 @@ using IPA.Logging; -using System; +using System; using System.Diagnostics; using System.Diagnostics.CodeAnalysis; -using System.IO; -using System.Security.AccessControl; -using System.Security.Principal; -using System.Threading.Tasks; -#if NET3 -using Net3_Proxy; -#endif - -namespace IPA.Injector -{ - internal static class PermissionFix +using System.IO; +using System.Security.AccessControl; +using System.Security.Principal; +using System.Threading.Tasks; +#if NET3 +using Net3_Proxy; +#endif + +namespace IPA.Injector +{ + internal static class PermissionFix { [SuppressMessage("Reliability", "CA2008:Do not create tasks without passing a TaskScheduler", Justification = "I very explicitly want the default scheduler")] - public static Task FixPermissions(DirectoryInfo root) - { - if (!root.Exists) return new Task(() => { }); - - return Task.Factory.StartNew(() => - { - var sw = Stopwatch.StartNew(); - try - { - var acl = root.GetAccessControl(); - - var rules = acl.GetAccessRules(true, true, typeof(SecurityIdentifier)); - - var requestedRights = FileSystemRights.Modify; - var requestedInheritance = InheritanceFlags.ContainerInherit | InheritanceFlags.ObjectInherit; - var requestedPropagation = PropagationFlags.InheritOnly; - - bool hasRule = false; - for (var i = 0; i < rules.Count; i++) - { - var rule = rules[i]; - - if (rule is FileSystemAccessRule fsrule - && fsrule.AccessControlType == AccessControlType.Allow - && fsrule.InheritanceFlags.HasFlag(requestedInheritance) - && fsrule.PropagationFlags == requestedPropagation - && fsrule.FileSystemRights.HasFlag(requestedRights)) - { hasRule = true; break; } - } - - if (!hasRule) - { // this is *sooo* fucking slow on first run - acl.AddAccessRule( - new FileSystemAccessRule( - new SecurityIdentifier(WellKnownSidType.WorldSid, null), - requestedRights, - requestedInheritance, - requestedPropagation, - AccessControlType.Allow - ) - ); - root.SetAccessControl(acl); - } - } - catch (Exception e) - { - Logger.log.Warn("Error configuring permissions in the game install dir"); - Logger.log.Warn(e); - } - sw.Stop(); - Logger.log.Info($"Configuring permissions took {sw.Elapsed}"); - }); - } - } -} + public static Task FixPermissions(DirectoryInfo root) + { + if (!root.Exists) return new Task(() => { }); + + return Task.Factory.StartNew(() => + { + var sw = Stopwatch.StartNew(); + try + { + var acl = root.GetAccessControl(); + + var rules = acl.GetAccessRules(true, true, typeof(SecurityIdentifier)); + + var requestedRights = FileSystemRights.Modify; + var requestedInheritance = InheritanceFlags.ContainerInherit | InheritanceFlags.ObjectInherit; + var requestedPropagation = PropagationFlags.InheritOnly; + + bool hasRule = false; + for (var i = 0; i < rules.Count; i++) + { + var rule = rules[i]; + + if (rule is FileSystemAccessRule fsrule + && fsrule.AccessControlType == AccessControlType.Allow + && fsrule.InheritanceFlags.HasFlag(requestedInheritance) + && fsrule.PropagationFlags == requestedPropagation + && fsrule.FileSystemRights.HasFlag(requestedRights)) + { hasRule = true; break; } + } + + if (!hasRule) + { // this is *sooo* fucking slow on first run + acl.AddAccessRule( + new FileSystemAccessRule( + new SecurityIdentifier(WellKnownSidType.WorldSid, null), + requestedRights, + requestedInheritance, + requestedPropagation, + AccessControlType.Allow + ) + ); + root.SetAccessControl(acl); + } + } + catch (Exception e) + { + Logger.log.Warn("Error configuring permissions in the game install dir"); + Logger.log.Warn(e); + } + sw.Stop(); + Logger.log.Info($"Configuring permissions took {sw.Elapsed}"); + }); + } + } +} diff --git a/IPA.Loader/Loader/PluginLoader.cs b/IPA.Loader/Loader/PluginLoader.cs index 3b93e48c..e34bcb00 100644 --- a/IPA.Loader/Loader/PluginLoader.cs +++ b/IPA.Loader/Loader/PluginLoader.cs @@ -765,7 +765,17 @@ namespace IPA.Loader internal static void DoOrderResolution() { - PluginsMetadata.Sort((a, b) => a.Version.CompareTo(b.Version)); +#if DEBUG + // print starting order + Logger.loader.Debug(string.Join(", ", PluginsMetadata.StrJP())); +#endif + + PluginsMetadata.Sort((a, b) => b.Version.CompareTo(a.Version)); + +#if DEBUG + // print base resolution order + Logger.loader.Debug(string.Join(", ", PluginsMetadata.StrJP())); +#endif var metadataCache = new Dictionary(PluginsMetadata.Count); var pluginsToProcess = new List(PluginsMetadata.Count); @@ -824,33 +834,40 @@ namespace IPA.Loader meta = null; disabled = false; ignored = true; + Logger.loader.Trace($"Trying to resolve plugin '{id}'"); if (loadedPlugins.TryGetValue(id, out var foundMeta)) { meta = foundMeta.Meta; disabled = foundMeta.Disabled; ignored = foundMeta.Ignored; + Logger.loader.Trace($"- Found already processed"); return true; } if (metadataCache!.TryGetValue(id, out var plugin)) { + Logger.loader.Trace($"- In metadata cache"); disabled = !plugin.Enabled; meta = plugin.Meta; if (!disabled) { Resolve(plugin.Meta, ref disabled, out ignored); } + Logger.loader.Trace($"- '{id}' resolved as ignored:{ignored},disabled:{disabled}"); loadedPlugins.Add(id, (plugin.Meta, disabled, ignored)); return true; } + Logger.loader.Trace($"- Not found"); return false; } void Resolve(PluginMetadata plugin, ref bool disabled, out bool ignored) { + Logger.loader.Trace($">Resolving '{plugin.Name}'"); + // first we need to check for loops in the resolution graph to prevent stack overflows if (isProcessing.Contains(plugin)) { - Logger.loader.Error($"Loop detected while processing {plugin.Name}; flagging as ignored"); + Logger.loader.Error($"Loop detected while processing '{plugin.Name}'; flagging as ignored"); // we can't safely add it to ignoredPlugins, because then when the ignore propagates up the stack, // we may end up ignoring outselves again ignored = true; @@ -873,7 +890,7 @@ namespace IPA.Loader ReasonText = $"File {Utils.GetRelativePath(file.FullName, UnityGame.InstallPath)} does not exist" }); Logger.loader.Warn($"File {Utils.GetRelativePath(file.FullName, UnityGame.InstallPath)}" + - $" (declared by {plugin.Name}) does not exist! Mod installation is incomplete, not loading it."); + $" (declared by '{plugin.Name}') does not exist! Mod installation is incomplete, not loading it."); ignored = true; return; } @@ -960,6 +977,7 @@ namespace IPA.Loader // after we handle dependencies and loadafters, then check conflicts foreach (var conflict in plugin.Manifest.Conflicts) { + Logger.loader.Trace($">- Checking conflict '{conflict.Key}' {conflict.Value}"); if (TryResolveId(conflict.Key, out var meta, out var conflDisabled, out var conflIgnored) && !conflIgnored && !conflDisabled) { // the conflict is only *actually* a problem if it is both not ignored and not disabled @@ -978,6 +996,8 @@ namespace IPA.Loader outputOrder!.Add(plugin); // loadbefores have already been preprocessed into loadafters + + Logger.loader.Trace($">Processed '{plugin.Name}'"); } // run TryResolveId over every plugin, which recursively calculates load order diff --git a/IPA.Loader/Loader/manifest.json b/IPA.Loader/Loader/manifest.json index a864f713..d438446e 100644 --- a/IPA.Loader/Loader/manifest.json +++ b/IPA.Loader/Loader/manifest.json @@ -5,10 +5,10 @@ "#![IPA.Loader.description.md]", "A mod loader specifically for Beat Saber." ], - "gameVersion": "1.14.0", + "gameVersion": "1.16.1", "id": "BSIPA", "name": "Beat Saber IPA", - "version": "4.1.7-pre.2", + "version": "4.1.7-pre.3", "icon": "IPA.icon_white.png", "features": { "IPA.DefineFeature": {