Add trace logging to new loader for debugging issues

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}");
+            });
+        }
+    }
+}

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<string, (PluginMetadata Meta, bool Enabled)>(PluginsMetadata.Count);
             var pluginsToProcess = new List<PluginMetadata>(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

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": {