From 99c042d76730a9fef2e756b3b509d361bc159ab7 Mon Sep 17 00:00:00 2001 From: SokyranTheDragon <36712560+SokyranTheDragon@users.noreply.github.com> Date: Wed, 4 Sep 2024 09:49:09 +0200 Subject: [PATCH] Update debug action related to desync source searching (#469) I've made some changes to the debug tool back when 1.5 originally released, but haven't bothered finishing it up. I've decided to also include a special window for it, which allows to configure the search tool. Anyway, included changes: The debug tool option now opens a window where you can configure desync source search options. It allows you to select specific elements you want to search, if you want to search mods and/or vanilla types, as well as select if you want to log all checked types. There's also 2 buttons to select 2 presets, basic and full, and the dialog by default selects the basic preset. The basic preset was tailored towards a player who may not fully understand what to look for in the other options, especially since the majority of what they'll report will be false positives. Since the selection of logging of all classes is now inside the dialog, one of the 2 debug actions was removed as it was pointless. Added `NonBasicAttribute` and applied it to all options in the enum that are, as the name suggests, non-basic. It's used for the selection of basic options in the dialog, as those options in particular will be skipped. Added a `LongEvents` options, which will log every single long event. Majority of them will be false positives, but may be worth investigating. They can cause issues if they are asynchronous or if they are queued during the game loading (hosting the server), as they end up being queued twice for host. Removed all references of Biomes Core special terrain in non-ticking updates, as those were removed some time ago (back in 1.4). Removed the check to `MaxFoundStuff` that would end checking a method early, as it was extremely unlikely that a single method would have all the elements in it. It was just a waste of computational power, even if a minor one. (Also it stopped working since addition of `PatchedSyncMethods`, as that one was checked in a different place, so the max value would have to be lowered by 1 to compensate). The `LogUnpatchedStuff` now accepts more arguments that determine what it should do. It also has a few extra checks early if the input data is correct, even if the window should already provide correct data (just in case of some weird shenanigans). Renamed `unsupportedTypes` to `unsupportedNamespaces`, as that name is more correct. `Prepatcher` and `Prestarter` namespaces were included, as Prepatcher is going to be commonly used with MP and causes a few false positives. `FisheryLib` and `PerformanceFish` were also included, as operating on those crashes RimWorld. Also removed the note about RW namespaces, as RW itself can now be checked as well. The dictionary containing the lists of all found issues now only include entries for stuff that can be found, so all operations performed on it generally use `TryGetValue` for safety. Added a few calls to `Enumerable.Distinct()` to make sure we don't have duplicates and don't operate on duplicates. --- Source/DebugActions.cs | 287 +++++++++++++++++++++++++++++++---------- 1 file changed, 220 insertions(+), 67 deletions(-) diff --git a/Source/DebugActions.cs b/Source/DebugActions.cs index f55d21b..69ad43d 100644 --- a/Source/DebugActions.cs +++ b/Source/DebugActions.cs @@ -37,6 +37,115 @@ private static void BuildDllReferences() #endregion #region DesyncSourceSearch + + private class DesyncSourceSearchWindow : Window + { + private HashSet selectedOptions; + private bool checkedTypes = false; + private bool doModded = true; + private bool doVanilla = false; + + public override bool IsDebug => true; + public override Vector2 InitialSize => new(525f, 615f); + public override float Margin => 32f; + + public DesyncSourceSearchWindow() + { + doCloseX = true; + SetDefault(); + } + + private void SetDefault() + => selectedOptions = ((StuffToSearch[])Enum.GetValues(typeof(StuffToSearch))) + .Where(s => !typeof(StuffToSearch).GetField(s.ToString()).IsDefined(typeof(NonBasicAttribute))) + .ToHashSet(); + + private void SetAll() + => selectedOptions = ((StuffToSearch[])Enum.GetValues(typeof(StuffToSearch))) + .ToHashSet(); + + public override void OnAcceptKeyPressed() + { + if (Accept()) + Event.current.Use(); + } + + // Not sure how to split it into multiple lines while also making it look nice... + private bool CanAccept() + => (doModded || (doVanilla && (selectedOptions.Count != 1 || selectedOptions.Single() != StuffToSearch.PatchedSyncMethods))) && + selectedOptions.Any() && + !Log.ReachedMaxMessagesLimit; + + private bool Accept() + { + if (!CanAccept()) + return false; + + LogUnpatchedStuff(selectedOptions, checkedTypes, doModded, doVanilla); + Close(); + // Open the log window, as that's where the results are displayed + Find.WindowStack.Add(new EditWindow_Log()); + + return true; + } + + public override void DoWindowContents(Rect inRect) + { + var listing = new Listing_Standard(); + listing.Begin(inRect); + + foreach (StuffToSearch e in Enum.GetValues(typeof(StuffToSearch))) + { + var check = selectedOptions.Contains(e); + var prev = check; + listing.CheckboxLabeled(e.ToString(), ref check); + if (check != prev) + { + if (check) + selectedOptions.Add(e); + else + selectedOptions.Remove(e); + } + } + + listing.GapLine(); + + listing.CheckboxLabeled("Check mods", ref doModded); + listing.CheckboxLabeled("Check vanilla (only relevant for MP devs)", ref doVanilla); + + listing.GapLine(); + + listing.CheckboxLabeled("Log all checked types (do not use unless specifically told to do so)", ref checkedTypes); + + listing.GapLine(); + + if (listing.ButtonText("Default (basic)")) + SetDefault(); + if (listing.ButtonText("Default (all)")) + SetAll(); + + listing.GapLine(); + + var buttonActive = CanAccept(); + var text = (Log.ReachedMaxMessagesLimit, Log.messageCount, buttonActive) switch + { + (true, _, _) => "Cannot run, message log full - clear your message log", + // If I counted correctly, there can be 48 calls to log at most + (_, >= 950, _) => "Cannot run, message log almost full - clear your message log", + // Not bothering making an explanation for every single possible reason + (_, _, false) => "Cannot run, incorrect option(s)", + _ => "Run" + }; + if (listing.ButtonText(text)) + Accept(); + + listing.Gap(listing.verticalSpacing); + + listing.End(); + } + } + + private class NonBasicAttribute : Attribute; internal enum StuffToSearch { @@ -45,18 +154,17 @@ internal enum StuffToSearch GenView, Coroutines, Multithreading, - CameraDriver, - CurrentMap, - Selector, + [NonBasic] CameraDriver, + [NonBasic] CurrentMap, + [NonBasic] Selector, Stopwatch, - NonTickingUpdate, + [NonBasic] NonTickingUpdate, TimeManager, - GetHashCode, - PatchedSyncMethods, + [NonBasic] GetHashCode, + [NonBasic] PatchedSyncMethods, + [NonBasic] LongEvents, } - private static readonly int MaxFoundStuff = Enum.GetNames(typeof(StuffToSearch)).Length; - private static readonly MethodInfo FindCurrentMap = AccessTools.DeclaredPropertyGetter(typeof(Find), nameof(Find.CurrentMap)); private static readonly MethodInfo GameCurrentMap = AccessTools.DeclaredPropertyGetter(typeof(Game), nameof(Game.CurrentMap)); private static readonly MethodInfo GetHashCodeMethod = AccessTools.DeclaredMethod(typeof(object), nameof(GetHashCode)); @@ -69,12 +177,9 @@ internal enum StuffToSearch AccessTools.DeclaredMethod("HugsLib.ModBase:Update"), AccessTools.DeclaredMethod("HugsLib.ModBase:FixedUpdate"), AccessTools.DeclaredMethod("HugsLib.ModBase:OnGUI"), - AccessTools.DeclaredMethod("BiomesCore.TerrainInstance:Update"), - AccessTools.DeclaredMethod("BiomesCore.TerrainComp:CompUpdate"), - AccessTools.DeclaredMethod("BiomesCore.DefExtensionActive:DoWork", new [] { AccessTools.TypeByName("Verse.TerrainDef") }), AccessTools.DeclaredMethod("VFECore.TerrainInstance:Update"), AccessTools.DeclaredMethod("VFECore.TerrainComp:CompUpdate"), - AccessTools.DeclaredMethod("VFECore.DefExtensionActive:DoWork", new [] { AccessTools.TypeByName("Verse.TerrainDef") }), + AccessTools.DeclaredMethod("VFECore.DefExtensionActive:DoWork", [AccessTools.TypeByName("Verse.TerrainDef")]), }.Where(x => x != null).ToHashSet(); private static readonly HashSet NonTickingUpdateMethodCalls = new[] @@ -83,18 +188,38 @@ internal enum StuffToSearch AccessTools.DeclaredMethod("HugsLib.Utils.DoLaterScheduler:DoNextOnGUI"), }.Where(x => x != null).ToHashSet(); - [DebugAction(CategoryName, "Log unsafe stuff", allowedGameStates = AllowedGameStates.Entry)] - public static void LogUnpatchedStuff() => LogUnpatchedStuff(false); + private static readonly HashSet LongEventMethods = new[] + { + AccessTools.DeclaredMethod(typeof(LongEventHandler), nameof(LongEventHandler.QueueLongEvent), + [typeof(Action), typeof(string), typeof(bool), typeof(Action), typeof(bool), typeof(Action)]), + AccessTools.DeclaredMethod(typeof(LongEventHandler), nameof(LongEventHandler.QueueLongEvent), + [typeof(IEnumerable), typeof(string), typeof(Action), typeof(bool)]), + AccessTools.DeclaredMethod(typeof(LongEventHandler), nameof(LongEventHandler.QueueLongEvent), + [typeof(Action), typeof(string), typeof(string), typeof(bool), typeof(Action), typeof(bool)]), + }.Where(x => x != null).ToHashSet(); - // Having the same name could be confusing, so people would potentially use it since it "logs more", - // but this stuff is more useful for checking if too much (like RimWorld itself) is getting checked. - // Also, name didn't fit in fully. - [DebugAction(CategoryName, "Test checked types", allowedGameStates = AllowedGameStates.Entry)] - public static void LogUnpatchedRngLogAll() => LogUnpatchedStuff(true); + [DebugAction(CategoryName, "Unsafe stuff logger", allowedGameStates = AllowedGameStates.Entry)] + public static void OpenDesyncSourceSearchWindow() => Find.WindowStack.Add(new DesyncSourceSearchWindow()); - public static void LogUnpatchedStuff(bool logAllCheckedClasses) + public static void LogUnpatchedStuff(HashSet selectedStuff, bool logAllCheckedClasses, bool doModded = true, bool doVanilla = false) { - var unsupportedTypes = new[] + if (!doModded && !doVanilla) + { + Log.Error("Trying to search for potential desync sources with both vanilla and modded disabled."); + return; + } + if (!selectedStuff.Any()) + { + Log.Error("Trying to search for potential desync sources but nothing was selected for searching."); + return; + } + if (!doVanilla && selectedStuff.Count == 1 && selectedStuff.Single() == StuffToSearch.PatchedSyncMethods) + { + Log.Error("Trying to search for potential desync sources for vanilla only but the only option was patched sync methods."); + return; + } + + var unsupportedNamespaces = new[] { nameof(System), nameof(Unity), @@ -124,27 +249,43 @@ public static void LogUnpatchedStuff(bool logAllCheckedClasses) "RestSharp", "YamlDotNet", "SemVer", - - // Used by some mods, don't include - //nameof(RimWorld), - //nameof(Verse), + // Exclude prepatcher and prestarter, as they give off a few false positives. + "Prepatcher", + "Prestarter", + // Exclude Fishery and Performance Fish they crash the game when checking them. + "FisheryLib", + "PerformanceFish", }; - var types = LoadedModManager.RunningMods - .Where(x => x.PackageId.ToLower() != "rwmt.multiplayer" && x.PackageId.ToLower() != "rwmt.multiplayercompatibility") - .SelectMany(x => x.assemblies.loadedAssemblies) - .SelectMany(x => x.GetTypes()); + IEnumerable types = []; + if (doModded) + { + types = types.Concat(LoadedModManager.RunningMods + .Where(x => x.PackageId.ToLower() != "rwmt.multiplayer" && x.PackageId.ToLower() != "rwmt.multiplayercompatibility") + .SelectMany(x => x.assemblies.loadedAssemblies) + .SelectMany(x => x.GetTypes())); + } + if (doVanilla) + { + types = types.Concat(typeof(Def).Assembly.GetTypes()); + } + // Just in case + types = types.Distinct(); - var log = Enum.GetValues(typeof(StuffToSearch)) - .Cast() - .ToDictionary(x => x, _ => new List()); + var log = selectedStuff.ToDictionary(x => x, _ => new List()); List logAllClasses = null; if (logAllCheckedClasses) - logAllClasses = new List(); + logAllClasses = []; - Parallel.ForEach(types, t => FindUnpatchedInType(t, unsupportedTypes, log, logAllClasses)); - FindPatchedSyncMethods(log); + // Make sure that we have something to do that requires going through the IL + // instructions of each method + if (selectedStuff.Any(x => x != StuffToSearch.PatchedSyncMethods)) + Parallel.ForEach(types, t => FindUnpatchedInType(t, unsupportedNamespaces, log, logAllClasses)); + // Make sure that the option for looking for patched sync method was enabled, + // and that we're checking mods (as vanilla won't have Harmony patches) + if (doModded && selectedStuff.Contains(StuffToSearch.PatchedSyncMethods)) + FindPatchedSyncMethods(log); if (log.Any(x => x.Value.Any())) { @@ -152,96 +293,103 @@ public static void LogUnpatchedStuff(bool logAllCheckedClasses) Log.Warning("Please note, it doesn't always need syncing, or might even break if synced, depending on how the mod uses it. It could also be patched in an alternative way."); Log.Warning("Things that are already patched or don't need patching are not listed here, if possible to (easily) check for that."); - if (log[StuffToSearch.SystemRng].Any()) + if (log.TryGetValue(StuffToSearch.SystemRng, out var found) && found.Any()) { Log.Warning("== Unpatched System RNG: =="); Log.Warning("== Unless it's deterministically seeded or unused, it'll cause issues. =="); - Log.Message(log[StuffToSearch.SystemRng].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.UnityRng].Any()) + if (log.TryGetValue(StuffToSearch.UnityRng, out found) && found.Any()) { Log.Warning("== Unpatched Unity RNG: =="); Log.Warning("== Unless it's deterministically seeded or unused, it'll cause issues. =="); - Log.Message(log[StuffToSearch.UnityRng].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.GenView].Any()) + if (log.TryGetValue(StuffToSearch.GenView, out found) && found.Any()) { Log.Warning("== GenView usage found: =="); Log.Warning("== Usage of GenView means the mod is doing something based on if something is (not) visible for the user. Can cause issues as players tend to have different camera positions, or be on different maps. =="); - Log.Message(log[StuffToSearch.GenView].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.Coroutines].Any()) + if (log.TryGetValue(StuffToSearch.Coroutines, out found) && found.Any()) { Log.Warning("== Coroutine usage found: =="); Log.Warning("== Coroutine are not supported by MP as they are not deterministic. Unless they were patched, or are used on game startup, expect issues. =="); - Log.Message(log[StuffToSearch.Coroutines].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.Multithreading].Any()) + if (log.TryGetValue(StuffToSearch.Multithreading, out found) && found.Any()) { Log.Warning("== Multithreading usage found: =="); Log.Warning("== Please note, the detection may not be perfect and miss some some multithreading usage! =="); Log.Warning("== Multithreading is not supported by MP as they are not deterministic. Unless they were patched, or are used on game startup, expect issues. =="); - Log.Message(log[StuffToSearch.Multithreading].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.CameraDriver].Any()) + if (log.TryGetValue(StuffToSearch.CameraDriver, out found) && found.Any()) { Log.Warning("== CameraDriver usage found: =="); Log.Warning("== Usage of CameraDriver may cause issues if used for things like checking if something is (not) visible on the screen. Can cause issues as players tend to have different camera positions, or be on different maps. Mods moving camera around, etc. are generally fine. =="); - Log.Message(log[StuffToSearch.CameraDriver].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.CurrentMap].Any()) + if (log.TryGetValue(StuffToSearch.CurrentMap, out found) && found.Any()) { Log.Warning("== Current map usage found: =="); Log.Warning("== Mods basing code on current map for things like spawning events may cause issues, as players can be on different maps. =="); - Log.Message(log[StuffToSearch.CurrentMap].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.Selector].Any()) + if (log.TryGetValue(StuffToSearch.Selector, out found) && found.Any()) { Log.Warning("== Selector usage found: =="); Log.Warning("== Usage of selector could cause issues when mod needs to check what the player has selected, but for obvious reason in MP there's more than 1 player. Using it for displaying overlays, etc. is fine. =="); - Log.Message(log[StuffToSearch.Selector].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.Stopwatch].Any()) + if (log.TryGetValue(StuffToSearch.Stopwatch, out found) && found.Any()) { Log.Warning("== Stopwatch usage found: =="); Log.Warning("== Potential issues from it arise when mod try to make a mod more performant by limiting how long some code can run. Using it to measure performance is safe. =="); - Log.Message(log[StuffToSearch.Stopwatch].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.NonTickingUpdate].Any()) + if (log.TryGetValue(StuffToSearch.NonTickingUpdate, out found) && found.Any()) { Log.Warning("== Non-ticking update call usage found: =="); Log.Warning("== Those can be called while the game is paused, and are not called once per tick (instead can be called once per frame, etc.). Depending on what it's used for, it may cause issues. =="); - Log.Message(log[StuffToSearch.NonTickingUpdate].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.TimeManager].Any()) + if (log.TryGetValue(StuffToSearch.TimeManager, out found) && found.Any()) { Log.Warning("== TimeManager usage found: =="); Log.Warning("== TimeManager uses timing functions that won't be synced across players. Unless used for UI, sounds, etc. then it will cause desyncs. =="); - Log.Message(log[StuffToSearch.TimeManager].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.GetHashCode].Any()) + if (log.TryGetValue(StuffToSearch.GetHashCode, out found) && found.Any()) { Log.Warning("== GetHashCode usage found: =="); Log.Warning("== A lot of those will likely be false positives. However, depending on what the mod does with it - it can cause issues. Especially if the object has not implemented, or has non-deterministic .GetHashCode() implementation. =="); - Log.Message(log[StuffToSearch.GetHashCode].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } - if (log[StuffToSearch.PatchedSyncMethods].Any()) + if (log.TryGetValue(StuffToSearch.PatchedSyncMethods, out found) && found.Any()) { Log.Warning("== Harmony patched SyncMethods found: =="); Log.Warning("== SyncMethod normally is synchronized to all players and called only then - however, if it contains any Harmony patches (skipping transpilers, as those are likely least disruptive) then they still run before the method is synchronized, which may cause issues. =="); - Log.Message(log[StuffToSearch.PatchedSyncMethods].Append("\n").Join(delimiter: "\n")); + Log.Message(found.Append("\n").Join(delimiter: "\n")); + } + + if (log.TryGetValue(StuffToSearch.LongEvents, out found) && found.Any()) + { + Log.Warning("== Long events found: =="); + Log.Warning("== In majority of cases, long events are completely safe. However, there are 2 potential situations that can cause issues with them. The first is asynchronous long events, and the second is long events queued during game startup. =="); + Log.Message(found.Append("\n").Join(delimiter: "\n")); } } else Log.Warning("== No unpatched RNG or potentially unsafe methods found =="); @@ -253,12 +401,12 @@ public static void LogUnpatchedStuff(bool logAllCheckedClasses) } } - internal static void FindUnpatchedInType(Type type, string[] unsupportedTypes, Dictionary> log, List logAllClasses = null) + internal static void FindUnpatchedInType(Type type, string[] unsupportedNamespaces, Dictionary> log, List logAllClasses = null) { // Don't mind all the try/catch blocks, I went for maximum safety try { - if (unsupportedTypes.Any(t => type.Namespace != null && (type.Namespace == t || type.Namespace.StartsWith($"{t}.")))) return; + if (unsupportedNamespaces.Any(t => type.Namespace != null && (type.Namespace == t || type.Namespace.StartsWith($"{t}.")))) return; } catch (Exception) { @@ -282,6 +430,7 @@ internal static void FindUnpatchedInType(Type type, string[] unsupportedTypes, D .Concat(AccessTools.GetDeclaredProperties(type) .SelectMany(p => new[] { p.GetGetMethod(true), p.GetSetMethod(true) }) .Where(p => p != null && p.ReturnType.FullName != monoFunctionPointerClass)) + .Distinct() .Where(m => m.HasMethodBody()); foreach (var method in methods) @@ -290,8 +439,11 @@ internal static void FindUnpatchedInType(Type type, string[] unsupportedTypes, D { foreach (var found in FindRng(method)) { - lock (log[found]) - log[found].Add($"{type.FullName}:{method.Name} ({type.Assembly.GetName().Name})"); + if (log.TryGetValue(found, out var list)) + { + lock (list) + log[found].Add($"{type.FullName}:{method.Name} ({type.Assembly.GetName().Name})"); + } } } catch (Exception) @@ -363,9 +515,10 @@ internal static HashSet FindRng(MethodBase baseMethod) case MethodInfo method when IsOverrideOfAny(method, NonTickingUpdateMethodCalls): foundStuff.Add(StuffToSearch.NonTickingUpdate); break; + case MethodInfo method when LongEventMethods.Contains(method): + foundStuff.Add(StuffToSearch.LongEvents); + break; } - - if (foundStuff.Count == MaxFoundStuff) break; } return foundStuff;