Disable tx timeouts, add tx debug logging, static DLL pattern, fix docs

Core/CkanTransaction.cs

@@ -1,23 +1,103 @@
+using System;
 using System.Transactions;
+using System.Reflection;
+using log4net;
 
 namespace CKAN
 {
 
     public static class CkanTransaction
     {
-
         // as per http://blogs.msdn.com/b/dbrowne/archive/2010/05/21/using-new-transactionscope-considered-harmful.aspx
 
+        static CkanTransaction()
+        {
+            // ChinhDo is incompatible with transaction timeouts on Windows; it can't
+            // be aborted by another thread while the main thread is still working.
+            // Disable transaction timeouts by maximizing the MaximumTimeout (49 days).
+            SetMaxTimeout(maxCoretimeout);
+        }
+
         public static TransactionScope CreateTransactionScope()
         {
+            log.DebugFormat("Starting transaction with timeout {0:g}", transOpts.Timeout);
             return new TransactionScope(TransactionScopeOption.Required, transOpts);
         }
 
+        // System.ArgumentOutOfRangeException : Time-out interval must be less than 2^32-2. (Parameter 'dueTime')
+        private const double timeoutMs = 4294967294d;
+        private static readonly TimeSpan maxCoretimeout = TimeSpan.FromMilliseconds(timeoutMs);
+
         private static TransactionOptions transOpts = new TransactionOptions()
         {
             IsolationLevel = IsolationLevel.ReadCommitted,
-            Timeout        = TransactionManager.MaximumTimeout
+            Timeout        = maxCoretimeout
         };
 
+        /// <summary>
+        /// Set TransactionManager.MaximumTimeout with reflection
+        /// </summary>
+        /// <param name="timeout">New maximum transaction timeout</param>
+        private static void SetMaxTimeout(TimeSpan timeout)
+        {
+            log.DebugFormat("Trying to set max timeout to {0:g}", timeout);
+            if (TransactionManager.MaximumTimeout < timeout)
+            {
+                // TransactionManager.MaximumTimeout should not exist; if
+                // app code tells TransactionScope's constructor that it needs
+                // 2 hours to run a transaction, it's probably not wrong, and
+                // the framework should listen and obey.  Instead,
+                // TransactionManager reduces the requested span to 10 minutes.
+                // But even worse, this limit can't be publicly changed!
+                // Someone at Microsoft has arbitrarily decided that 10 minutes
+                // is the maximum time for any transaction ever, without knowing
+                // what those transactions need to do, and app programmers who do
+                // know what they need to do can't override it no matter how dire
+                // the need.
+                // It can only be overridden by the end user, at the machine level,
+                // and we can't ask every CKAN user to add a bunch of XML to some
+                // random system file to ensure that core functionality works.
+                // TransactionManager is unsuitable for use as-is, since it has
+                // a built in time bomb ready to sabotage your application once you
+                // hit that arbitrary limit, and you can't do anything about it.
+
+                // To work around this design disaster, we commit our own
+                // cardinal sin by using reflection to set private properties.
+                // I wish TransactionManager did not force us to do this by
+                // imposing incorrect behavior with no escape hatch.
+
+                var t = typeof(TransactionManager);
+                if (Platform.IsMono)
+                {
+                    // Mono
+                    SetField(t, "machineSettings", null);
+                    SetField(t, "maxTimeout",      timeout);
+                }
+                else
+                {
+                    // Framework
+                    SetField(t, "_cachedMaxTimeout", true);
+                    SetField(t, "_maximumTimeout",   timeout);
+                    // Core
+                    SetField(t, "s_cachedMaxTimeout", true);
+                    SetField(t, "s_maximumTimeout",   timeout);
+                }
+            }            
+        }
+
+        private static void SetField(Type T, string fieldName, object value)
+        {
+            try
+            {
+                T.GetField(fieldName, BindingFlags.NonPublic | BindingFlags.Static)
+                    .SetValue(null, value);
+            }
+            catch
+            {
+                log.DebugFormat("Failed to set {0}", fieldName);
+            }
+        }
+
+        private static readonly ILog log = LogManager.GetLogger(typeof(CkanTransaction));
     }
 }

Core/GameInstance.cs

@@ -10,6 +10,7 @@
 using Newtonsoft.Json;
 
 using CKAN.Games;
+using CKAN.Extensions;
 using CKAN.Versioning;
 
 namespace CKAN
@@ -357,7 +358,9 @@ public bool Scan()
                 var manager = RegistryManager.Instance(this);
                 using (TransactionScope tx = CkanTransaction.CreateTransactionScope())
                 {
-                    var oldDlls = new HashSet<string>(manager.registry.InstalledDlls);
+                    log.DebugFormat("Scanning for DLLs in {0}",
+                        game.PrimaryModDirectory(this));
+                    var oldDlls = manager.registry.InstalledDlls.ToHashSet();
                     manager.registry.ClearDlls();
 
                     // TODO: It would be great to optimise this to skip .git directories and the like.
@@ -379,7 +382,7 @@ public bool Scan()
                     {
                         manager.registry.RegisterDll(this, dll);
                     }
-                    var newDlls = new HashSet<string>(manager.registry.InstalledDlls);
+                    var newDlls = manager.registry.InstalledDlls.ToHashSet();
                     bool dllChanged = !oldDlls.SetEquals(newDlls);
                     bool dlcChanged = manager.ScanDlc();
 
@@ -388,6 +391,7 @@ public bool Scan()
                         manager.Save(false);
                     }
 
+                    log.Debug("Scan completed, committing transaction");
                     tx.Complete();
 
                     return dllChanged || dlcChanged;
@@ -415,6 +419,39 @@ public string ToAbsoluteGameDir(string path)
             return CKANPathUtils.ToAbsolute(path, GameDir());
         }
 
+        /// <summary>
+        /// https://xkcd.com/208/
+        /// This regex matches things like GameData/Foo/Foo.1.2.dll
+        /// </summary>
+        private static readonly Regex dllPattern = new Regex(
+            @"
+                ^(?:.*/)?             # Directories (ending with /)
+                (?<identifier>[^.]+)  # Our DLL name, up until the first dot.
+                .*\.dll$              # Everything else, ending in dll
+            ",
+            RegexOptions.IgnoreCase | RegexOptions.IgnorePatternWhitespace | RegexOptions.Compiled
+        );
+
+        /// <summary>
+        /// Find the identifier associated with a manually installed DLL
+        /// </summary>
+        /// <param name="relative_path">Path of the DLL relative to game root</param>
+        /// <returns>
+        /// Identifier if found otherwise null
+        /// </returns>
+        public string DllPathToIdentifier(string relative_path)
+        {
+            if (!relative_path.StartsWith($"{game.PrimaryModDirectoryRelative}/", StringComparison.CurrentCultureIgnoreCase))
+            {
+                // DLLs only live in the primary mod directory
+                return null;
+            }
+            Match match = dllPattern.Match(relative_path);
+            return match.Success
+                ? Identifier.Sanitize(match.Groups["identifier"].Value)
+                : null;
+        }
+
         public override string ToString()
         {
             return $"{game.ShortName} Install: {gameDir}";

Core/ModuleInstaller.cs

@@ -209,6 +209,7 @@ public void InstallList(ICollection<CkanModule> modules, RelationshipResolverOpt
                 // leaves everything consistent, and this is just gravy. (And ScanGameData
                 // acts as a Tx, anyway, so we don't need to provide our own.)
                 User.RaiseProgress("Rescanning GameData", 90);
+                log.Debug("Scanning after install");
                 ksp.Scan();
             }
 

Core/Registry/Registry.cs

@@ -427,9 +427,12 @@ private void EnlistWithTransaction()
                         throw new TransactionalKraken(
                             $"Registry already enlisted with tx {enlisted_tx}, can't enlist with tx {current_tx}");
                     }
-
-                    // If we're here, it's a transaction we're already participating in,
-                    // so do nothing.
+                    else
+                    {
+                        // If we're here, it's a transaction we're already participating in,
+                        // so do nothing.
+                        log.DebugFormat("Already enlisted with tx {0}", current_tx);
+                    }
                 }
             }
         }
@@ -438,6 +441,8 @@ private void EnlistWithTransaction()
 
         public void SetAllAvailable(IEnumerable<CkanModule> newAvail)
         {
+            log.DebugFormat(
+                "Setting all available modules, count {0}", newAvail);
             EnlistWithTransaction();
             // Clear current modules
             available_modules = new Dictionary<string, AvailableModule>();
@@ -465,6 +470,7 @@ public bool HasAnyAvailable()
         /// </summary>
         public void AddAvailable(CkanModule module)
         {
+            log.DebugFormat("Adding available module {0}", module);
             EnlistWithTransaction();
 
             var identifier = module.identifier;
@@ -493,6 +499,8 @@ public void RemoveAvailable(string identifier, ModuleVersion version)
             AvailableModule availableModule;
             if (available_modules.TryGetValue(identifier, out availableModule))
             {
+                log.DebugFormat("Removing available module {0} {1}",
+                    identifier, version);
                 EnlistWithTransaction();
                 availableModule.Remove(version);
             }
@@ -732,6 +740,7 @@ public CkanModule GetModuleByVersion(string ident, ModuleVersion version)
         /// </summary>
         public void RegisterModule(CkanModule mod, IEnumerable<string> absolute_files, GameInstance ksp, bool autoInstalled)
         {
+            log.DebugFormat("Registering module {0}", mod);
             EnlistWithTransaction();
 
             sorter = null;
@@ -794,6 +803,7 @@ public void RegisterModule(CkanModule mod, IEnumerable<string> absolute_files, G
         /// </summary>
         public void DeregisterModule(GameInstance ksp, string module)
         {
+            log.DebugFormat("Deregistering module {0}", module);
             EnlistWithTransaction();
 
             sorter = null;
@@ -828,24 +838,6 @@ public void DeregisterModule(GameInstance ksp, string module)
             installed_modules.Remove(module);
         }
 
-        /// <summary>
-        /// http://xkcd.com/208/
-        /// This regex works great for things like GameData/Foo/Foo-1.2.dll
-        /// Would be nice to make it persistent, but it depends on the game
-        /// </summary>
-        public static Regex DllPattern(IGame game)
-        {
-            return new Regex(
-                // DLLs only live in the primary mod directory
-                $"^{game.PrimaryModDirectoryRelative}/" + @"
-                    (?:.*/)?              # Intermediate paths (ending with /)
-                    (?<modname>[^.]+)     # Our DLL name, up until the first dot.
-                    .*\.dll$              # Everything else, ending in dll
-                ",
-                RegexOptions.IgnoreCase | RegexOptions.IgnorePatternWhitespace | RegexOptions.Compiled
-            );
-        }
-
         /// <summary>
         /// Registers the given DLL as having been installed. This provides some support
         /// for pre-CKAN modules.
@@ -854,10 +846,16 @@ public static Regex DllPattern(IGame game)
         /// </summary>
         public void RegisterDll(GameInstance ksp, string absolute_path)
         {
-            EnlistWithTransaction();
-
+            log.DebugFormat("Registering DLL {0}", absolute_path);
             string relative_path = ksp.ToRelativeGameDir(absolute_path);
 
+            string dllIdentifier = ksp.DllPathToIdentifier(relative_path);
+            if (dllIdentifier == null)
+            {
+                log.WarnFormat("Attempted to index {0} which is not a DLL", relative_path);
+                return;
+            }
+
             string owner;
             if (installed_files.TryGetValue(relative_path, out owner))
             {
@@ -869,25 +867,20 @@ public void RegisterDll(GameInstance ksp, string absolute_path)
                 return;
             }
 
-            Match match = DllPattern(ksp.game).Match(relative_path);
-            if (!match.Success)
-            {
-                log.WarnFormat("Attempted to index {0} which is not a DLL", relative_path);
-                return;
-            }
-            string modName = match.Groups["modname"].Value.Replace("_", "-");
+            EnlistWithTransaction();
 
-            log.InfoFormat("Registering {0} from {1}", modName, relative_path);
+            log.InfoFormat("Registering {0} from {1}", dllIdentifier, relative_path);
 
             // We're fine if we overwrite an existing key.
-            installed_dlls[modName] = relative_path;
+            installed_dlls[dllIdentifier] = relative_path;
         }
 
         /// <summary>
         /// Clears knowledge of all DLLs from the registry.
         /// </summary>
         public void ClearDlls()
         {
+            log.Debug("Clearing DLLs");
             EnlistWithTransaction();
             installed_dlls = new Dictionary<string, string>();
         }

GUI/Main/Main.cs

@@ -239,6 +239,7 @@ private void manageGameInstancesMenuItem_Click(object sender, EventArgs e)
         /// <param name="allowRepoUpdate">true if a repo update is allowed if needed (e.g. on initial load), false otherwise</param>
         private void CurrentInstanceUpdated(bool allowRepoUpdate)
         {
+            log.Debug("Current instance updated, scanning");
             CurrentInstance.Scan();
             Util.Invoke(this, () =>
             {

GUI/Main/MainRepo.cs

@@ -65,6 +65,7 @@ private void UpdateRepo(object sender, DoWorkEventArgs e)
             try
             {
                 AddStatusMessage(Properties.Resources.MainRepoScanning);
+                log.Debug("Scanning before repo update");
                 bool scanChanged = CurrentInstance.Scan();
 
                 AddStatusMessage(Properties.Resources.MainRepoUpdating);

Netkan/Validators/PluginsValidator.cs

@@ -41,12 +41,10 @@ public void Validate(Metadata metadata)
                             .Select(f => inst.ToRelativeGameDir(f.destination))
                             .OrderBy(f => f)
                             .ToList();
-                        var pattern = Registry.DllPattern(inst.game);
                         var dllIdentifiers = dllPaths
-                            .Select(p => pattern.Match(p))
-                            .Where(m => m.Success)
-                            .Select(m => m.Groups["modname"].Value.Replace("_", "-"))
-                            .Where(ident => !identifiersToIgnore.Contains(ident))
+                            .Select(p => inst.DllPathToIdentifier(p))
+                            .Where(ident => !string.IsNullOrEmpty(ident)
+                                && !identifiersToIgnore.Contains(ident))
                             .ToHashSet();
                         if (dllIdentifiers.Any() && !dllIdentifiers.Contains(metadata.Identifier))
                         {