Filter out late file system events caused by API push (#72)

Un-suppress file system events before releasing the lock.
Add two configuration values which allow control of automatic cache rebuild.
Add a concurrency integration test to ensure cache rebuilds don't occur from concurrent pushes.
Address NuGet/NuGetGallery#6960.

Author: joelverhagen

samples/NuGet.Server.V2.Samples.OwinHost/DictionarySettingsProvider.cs

@@ -8,19 +8,21 @@ namespace NuGet.Server.V2.Samples.OwinHost
 {
     public class DictionarySettingsProvider : ISettingsProvider
     {
-        readonly Dictionary<string, object> _settings;
+        private readonly Dictionary<string, object> _settings;
 
         public DictionarySettingsProvider(Dictionary<string, object> settings)
         {
             _settings = settings;
         }
 
-
         public bool GetBoolSetting(string key, bool defaultValue)
         {
-            System.Diagnostics.Debug.WriteLine("getSetting: " + key);
             return _settings.ContainsKey(key) ? Convert.ToBoolean(_settings[key]) : defaultValue;
+        }
 
+        public int GetIntSetting(string key, int defaultValue)
+        {
+            return _settings.ContainsKey(key) ? Convert.ToInt32(_settings[key]) : defaultValue;
         }
 
         public string GetStringSetting(string key, string defaultValue)

src/NuGet.Server.Core/Infrastructure/DefaultSettingsProvider.cs

@@ -9,6 +9,11 @@ public bool GetBoolSetting(string key, bool defaultValue)
             return defaultValue;
         }
 
+        public int GetIntSetting(string key, int defaultValue)
+        {
+            return defaultValue;
+        }
+
         public string GetStringSetting(string key, string defaultValue)
         {
             return defaultValue;

src/NuGet.Server.Core/Infrastructure/ISettingsProvider.cs

@@ -6,5 +6,6 @@ public interface ISettingsProvider
     {
         bool GetBoolSetting(string key, bool defaultValue);
         string GetStringSetting(string key, string defaultValue);
+        int GetIntSetting(string key, int defaultValue);
     }
 }

src/NuGet.Server.Core/Infrastructure/KnownPathUtility.cs

@@ -0,0 +1,65 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System.IO;
+
+namespace NuGet.Server.Core.Infrastructure
+{
+    public static class KnownPathUtility
+    {
+        /// <summary>
+        /// Determines if a relative file path could have been generated by <see cref="ExpandedPackageRepository"/>.
+        /// The path is assumed to be relative to the base of the package directory.
+        /// </summary>
+        /// <param name="path">The file path to parse.</param>
+        /// <param name="id">The package ID found.</param>
+        /// <param name="version">The package version found.</param>
+        /// <returns>True if the file name is known.</returns>
+        public static bool TryParseFileName(string path, out string id, out SemanticVersion version)
+        {
+            id = null;
+            version = null;
+
+            if (path == null || Path.IsPathRooted(path))
+            {
+                return false;
+            }
+
+            var pathPieces = path.Split(Path.DirectorySeparatorChar);
+            if (pathPieces.Length != 3) // {id}\{version}\{file name}
+            {
+                return false;
+            }
+
+            id = pathPieces[pathPieces.Length - 3];
+            var unparsedVersion = pathPieces[pathPieces.Length - 2];
+            var fileName = pathPieces[pathPieces.Length - 1];
+
+            if (!SemanticVersion.TryParse(unparsedVersion, out version)
+                || version.ToNormalizedString() != unparsedVersion)
+            {
+                return false;
+            }
+
+            string expectedFileName;
+            if (fileName.EndsWith(NuGet.Constants.PackageExtension))
+            {
+                expectedFileName = $"{id}.{version}{NuGet.Constants.PackageExtension}";
+            }
+            else if (fileName.EndsWith(NuGet.Constants.HashFileExtension))
+            {
+                expectedFileName = $"{id}.{version}{NuGet.Constants.HashFileExtension}";
+            }
+            else if (fileName.EndsWith(NuGet.Constants.ManifestExtension))
+            {
+                expectedFileName = $"{id}{NuGet.Constants.ManifestExtension}";
+            }
+            else
+            {
+                return false;
+            }
+
+            return expectedFileName == fileName;
+        }
+    }
+}

src/NuGet.Server.Core/Infrastructure/ServerPackageRepository.cs

@@ -108,6 +108,35 @@ internal ServerPackageRepository(
 
         private string CacheFileName => _settingsProvider.GetStringSetting("cacheFileName", null);
 
+        private TimeSpan InitialCacheRebuildAfter
+        {
+            get
+            {
+                var value = GetPositiveIntSetting("initialCacheRebuildAfterSeconds", 15);
+                return TimeSpan.FromSeconds(value);
+            }
+        }
+
+        private TimeSpan CacheRebuildFrequency
+        {
+            get
+            {
+                int value = GetPositiveIntSetting("cacheRebuildFrequencyInMinutes", 60);
+                return TimeSpan.FromMinutes(value);
+            }
+        }
+
+        private int GetPositiveIntSetting(string name, int defaultValue)
+        {
+            var value = _settingsProvider.GetIntSetting(name, defaultValue);
+            if (value <= 0)
+            {
+                value = defaultValue;
+            }
+
+            return value;
+        }
+
         private ServerPackageCache InitializeServerPackageCache()
         {
             return new ServerPackageCache(_fileSystem, ResolveCacheFileName());
@@ -529,18 +558,21 @@ private void SetupBackgroundJobs()
             _logger.Log(LogLevel.Info, "Registering background jobs...");
 
             // Persist to package store at given interval (when dirty)
+            _logger.Log(LogLevel.Info, "Persisting the cache file every 1 minute.");
             _persistenceTimer = new Timer(
                 callback: state => _serverPackageCache.PersistIfDirty(),
                 state: null,
                 dueTime: TimeSpan.FromMinutes(1),
                 period: TimeSpan.FromMinutes(1));
 
-            // Rebuild the package store in the background (every hour)
+            // Rebuild the package store in the background
+            _logger.Log(LogLevel.Info, "Rebuilding the cache file for the first time after {0} second(s).", InitialCacheRebuildAfter.TotalSeconds);
+            _logger.Log(LogLevel.Info, "Rebuilding the cache file every {0} hour(s).", CacheRebuildFrequency.TotalHours);
             _rebuildTimer = new Timer(
                 callback: state => RebuildPackageStoreAsync(CancellationToken.None),
                 state: null,
-                dueTime: TimeSpan.FromSeconds(15),
-                period: TimeSpan.FromHours(1));
+                dueTime: InitialCacheRebuildAfter,
+                period: CacheRebuildFrequency);
 
             _logger.Log(LogLevel.Info, "Finished registering background jobs.");
         }
@@ -595,7 +627,6 @@ private void UnregisterFileSystemWatcher()
             _watchDirectory = null;
         }
 
-
         /// <summary>
         /// This is an event handler for background work. Therefore, it should never throw exceptions.
         /// </summary>
@@ -608,6 +639,12 @@ private async void FileSystemChangedAsync(object sender, FileSystemEventArgs e)
                     return;
                 }
 
+                if (ShouldIgnoreFileSystemEvent(e))
+                {
+                    _logger.Log(LogLevel.Verbose, "File system event ignored. File: {0} - Change: {1}", e.Name, e.ChangeType);
+                    return;
+                }
+
                 _logger.Log(LogLevel.Verbose, "File system changed. File: {0} - Change: {1}", e.Name, e.ChangeType);
 
                 var changedDirectory = Path.GetDirectoryName(e.FullPath);
@@ -642,6 +679,59 @@ private async void FileSystemChangedAsync(object sender, FileSystemEventArgs e)
             }
         }
 
+        private bool ShouldIgnoreFileSystemEvent(FileSystemEventArgs e)
+        {
+            // We can only ignore Created or Changed events. All other types are always processed. Eventually we could
+            // try to ignore some Deleted events in the case of API package delete, but this is harder.
+            if (e.ChangeType != WatcherChangeTypes.Created
+                && e.ChangeType != WatcherChangeTypes.Changed)
+            {
+                _logger.Log(LogLevel.Verbose, "The file system event change type is not ignorable.");
+                return false;
+            }
+
+            /// We can only ignore events related to file paths changed by the
+            /// <see cref="ExpandedPackageRepository"/>. If the file system event is representing a known file path
+            /// extracted during package push, we can ignore the event. File system events are supressed during package
+            /// push but this is still necessary since file system events can come some time after the suppression
+            /// window has ended.
+            if (!KnownPathUtility.TryParseFileName(e.Name, out var id, out var version))
+            {
+                _logger.Log(LogLevel.Verbose, "The file system event is not related to a known package path.");
+                return false;
+            }
+
+            /// The file path could have been generated by <see cref="ExpandedPackageRepository"/>. Now
+            /// determine if the package is in the cache.
+            var matchingPackage = _serverPackageCache
+                .GetAll()
+                .Where(p => StringComparer.OrdinalIgnoreCase.Equals(p.Id, id))
+                .Where(p => version.Equals(p.Version))
+                .FirstOrDefault();
+
+            if (matchingPackage == null)
+            {
+                _logger.Log(LogLevel.Verbose, "The file system event is not related to a known package.");
+                return false;
+            }
+
+            var fileInfo = new FileInfo(e.FullPath);
+            if (!fileInfo.Exists)
+            {
+                _logger.Log(LogLevel.Verbose, "The package file is missing.");
+                return false;
+            }
+
+            var minimumCreationTime = DateTimeOffset.UtcNow.AddMinutes(-1);
+            if (fileInfo.CreationTimeUtc < minimumCreationTime)
+            {
+                _logger.Log(LogLevel.Verbose, "The package file was not created recently.");
+                return false;
+            }
+
+            return true;
+        }
+
         private async Task<Lock> LockAsync(CancellationToken token)
         {
             var handle = new Lock(_syncLock);
@@ -710,8 +800,8 @@ public void Dispose()
             {
                 if (_lockHandle != null && _lockHandle.LockTaken)
                 {
-                    _lockHandle.Dispose();
                     _repository._isFileSystemWatcherSuppressed = false;
+                    _lockHandle.Dispose();
                 }
             }
         }

src/NuGet.Server.Core/NuGet.Server.Core.csproj

@@ -75,6 +75,7 @@
     <Compile Include="Infrastructure\ClientCompatibility.cs" />
     <Compile Include="Infrastructure\ClientCompatibilityFactory.cs" />
     <Compile Include="Infrastructure\DefaultSettingsProvider.cs" />
+    <Compile Include="Infrastructure\KnownPathUtility.cs" />
     <Compile Include="Infrastructure\SerializedServerPackages.cs" />
     <Compile Include="Infrastructure\ServerPackageStore.cs" />
     <Compile Include="Infrastructure\IServerPackageStore.cs" />

src/NuGet.Server/Core/DefaultServiceResolver.cs

@@ -13,6 +13,7 @@ namespace NuGet.Server
     public sealed class DefaultServiceResolver
         : IServiceResolver, IDisposable
     {
+        private readonly Core.Logging.ILogger _logger;
         private readonly CryptoHashProvider _hashProvider;
         private readonly ServerPackageRepository _packageRepository;
         private readonly PackageAuthenticationService _packageAuthenticationService;
@@ -24,20 +25,33 @@ public DefaultServiceResolver() : this(
         {
         }
 
-        public DefaultServiceResolver(string packagePath, NameValueCollection settings)
+        public DefaultServiceResolver(string packagePath, NameValueCollection settings) : this(
+            packagePath,
+            settings,
+            new TraceLogger())
         {
+        }
+
+        public DefaultServiceResolver(string packagePath, NameValueCollection settings, Core.Logging.ILogger logger)
+        {
+            _logger = logger;
+
             _hashProvider = new CryptoHashProvider(Core.Constants.HashAlgorithm);
 
             _settingsProvider = new WebConfigSettingsProvider(settings);
 
-            _packageRepository = new ServerPackageRepository(packagePath, _hashProvider, _settingsProvider, new TraceLogger());
+            _packageRepository = new ServerPackageRepository(packagePath, _hashProvider, _settingsProvider, _logger);
 
             _packageAuthenticationService = new PackageAuthenticationService(settings);
-
         }
 
         public object Resolve(Type type)
         {
+            if (type == typeof(Core.Logging.ILogger))
+            {
+                return _logger;
+            }
+
             if (type == typeof(IHashProvider))
             {
                 return _hashProvider;

src/NuGet.Server/Infrastructure/WebConfigSettingsProvider.cs

@@ -29,6 +29,13 @@ public bool GetBoolSetting(string key, bool defaultValue)
             return !bool.TryParse(settings[key], out value) ? defaultValue : value;
         }
 
+        public int GetIntSetting(string key, int defaultValue)
+        {
+            var settings = _getSettings();
+            int value;
+            return !int.TryParse(settings[key], out value) ? defaultValue : value;
+        }
+
         public string GetStringSetting(string key, string defaultValue)
         {
             var settings = _getSettings();

src/NuGet.Server/Web.config

@@ -62,15 +62,31 @@
     Uncomment the following configuration entry to enable NAT support.
     -->
     <!-- <add key="aspnet:UseHostHeaderForRequestUrl" value="true" /> -->
+    
     <!--
     Set enableFileSystemMonitoring to true (default) to enable file system monitoring (which will update the package cache appropriately on file system changes).
     Set it to false to disable file system monitoring.
     NOTE: Disabling file system monitoring may result in increased storage capacity requirements as package cache may only be purged by a background job running 
     on a fixed 1-hour interval.
     -->
     <add key="enableFileSystemMonitoring" value="true" />
-    <!--Set allowRemoteCacheManagement to true to enable the "clear cache" and other cache operations initiated via requests originating from remote hosts.-->
+    
+    <!--
+    Set allowRemoteCacheManagement to true to enable the "clear cache" and other cache operations initiated via requests originating from remote hosts.
+    -->
     <add key="allowRemoteCacheManagement" value="false" />
+    
+    <!--
+    Set initialCacheRebuildAfterSeconds to the number of seconds to wait before starting the cache rebuild timer.
+    Defaults to 15 seconds if excluded or an invalid value.
+    -->
+    <add key="initialCacheRebuildAfterSeconds" value="15" />
+
+    <!--
+    Set cacheRebuildFrequencyInMinutes to the frequency in minutes to rebuild the cache. Defaults to 60 minutes if
+    excluded or an invalid value.
+    -->
+    <add key="cacheRebuildFrequencyInMinutes" value="60" />
   </appSettings>
   <!--
     For a description of web.config changes see http://go.microsoft.com/fwlink/?LinkId=235367.

test/NuGet.Server.Core.Tests/Infrastructure/FuncSettingsProvider.cs

@@ -23,6 +23,11 @@ public bool GetBoolSetting(string key, bool defaultValue)
             return Convert.ToBoolean(_getSetting(key, defaultValue));
         }
 
+        public int GetIntSetting(string key, int defaultValue)
+        {
+            return Convert.ToInt32(_getSetting(key, defaultValue));
+        }
+
         public string GetStringSetting(string key, string defaultValue)
         {
             return Convert.ToString(_getSetting(key, defaultValue));