Use polling to watch certificate paths (#50251)

eng/test-configuration.json

@@ -22,6 +22,7 @@
     {"testName": {"contains": "HEADERS_Received_SecondRequest_ConnectProtocolReset"}},
     {"testName": {"contains": "ClientUsingOldCallWithNewProtocol"}},
     {"testName": {"contains": "CertificateChangedOnDisk"}},
+    {"testName": {"contains": "CertificateChangedOnDisk_Symlink"}},
     {"testAssembly": {"contains": "IIS"}},
     {"testAssembly": {"contains": "Template"}},
     {"failureMessage": {"contains":"(Site is started but no worker process found)"}},

src/Servers/Kestrel/Core/src/Internal/CertificatePathWatcher.cs

@@ -29,9 +29,17 @@ internal sealed partial class CertificatePathWatcher : IDisposable
 
     public CertificatePathWatcher(IHostEnvironment hostEnvironment, ILogger<CertificatePathWatcher> logger)
         : this(
-              hostEnvironment.ContentRootPath,
-              logger,
-              dir => Directory.Exists(dir) ? new PhysicalFileProvider(dir, ExclusionFilters.None) : null)
+            hostEnvironment.ContentRootPath,
+            logger,
+            dir => Directory.Exists(dir)
+                ? new PhysicalFileProvider(dir, ExclusionFilters.None)
+                {
+                    // Force polling because it monitors both symlinks and their targets,
+                    // whereas the non-polling watcher only monitors the symlinks themselves
+                    UseActivePolling = true,
+                    UsePollingFileWatcher = true,
+                }
+                : null)
     {
     }
 
@@ -138,9 +146,6 @@ internal sealed partial class CertificatePathWatcher : IDisposable
             _metadataForFile.Add(path, fileMetadata);
             dirMetadata.FileWatchCount++;
 
-            // We actually don't care if the file doesn't exist - we'll watch in case it is created
-            fileMetadata.LastModifiedTime = GetLastModifiedTimeOrMinimum(path, dirMetadata.FileProvider);
-
             _logger.CreatedFileWatcher(path);
         }
 
@@ -156,20 +161,6 @@ internal sealed partial class CertificatePathWatcher : IDisposable
         _logger.FileCount(dir, dirMetadata.FileWatchCount);
     }
 
-    private DateTimeOffset GetLastModifiedTimeOrMinimum(string path, IFileProvider fileProvider)
-    {
-        try
-        {
-            return fileProvider.GetFileInfo(Path.GetFileName(path)).LastModified;
-        }
-        catch (Exception e)
-        {
-            _logger.LastModifiedTimeError(path, e);
-        }
-
-        return DateTimeOffset.MinValue;
-    }
-
     private void OnChange(string path)
     {
         // Block until any in-progress updates are complete
@@ -184,33 +175,17 @@ internal sealed partial class CertificatePathWatcher : IDisposable
             // Existence implied by the fact that we're tracking the file
             var dirMetadata = _metadataForDirectory[Path.GetDirectoryName(path)!];
 
-            // We ignore file changes that don't advance the last modified time.
+            // We ignore file changes that result in a file becoming unavailable.
             // For example, if we lose access to the network share the file is
             // stored on, we don't notify our listeners because no one wants
             // their endpoint/server to shutdown when that happens.
             // We also anticipate that a cert file might be renamed to cert.bak
             // before a new cert is introduced with the old name.
-            // This also helps us in scenarios where the underlying file system
-            // reports more than one change for a single logical operation.
-            var lastModifiedTime = GetLastModifiedTimeOrMinimum(path, dirMetadata.FileProvider);
-            if (lastModifiedTime > fileMetadata.LastModifiedTime)
-            {
-                fileMetadata.LastModifiedTime = lastModifiedTime;
-            }
-            else
+
+            var fileInfo = dirMetadata.FileProvider.GetFileInfo(Path.GetFileName(path));
+            if (!fileInfo.Exists)
             {
-                if (lastModifiedTime == DateTimeOffset.MinValue)
-                {
-                    _logger.EventWithoutLastModifiedTime(path);
-                }
-                else if (lastModifiedTime == fileMetadata.LastModifiedTime)
-                {
-                    _logger.RedundantEvent(path);
-                }
-                else
-                {
-                    _logger.OutOfOrderEvent(path);
-                }
+                _logger.EventWithoutFile(path);
                 return;
             }
 
@@ -219,6 +194,8 @@ internal sealed partial class CertificatePathWatcher : IDisposable
             {
                 config.FileHasChanged = true;
             }
+
+            _logger.FlaggedObservers(path, configs.Count);
         }
 
         // AddWatch and RemoveWatch don't affect the token, so this doesn't need to be under the semaphore.
@@ -321,7 +298,6 @@ internal sealed partial class CertificatePathWatcher : IDisposable
     {
         public readonly IDisposable Disposable = disposable;
         public readonly HashSet<CertificateConfig> Configs = new(ReferenceEqualityComparer.Instance);
-        public DateTimeOffset LastModifiedTime = DateTimeOffset.MinValue;
 
         public void Dispose() => Disposable.Dispose();
     }

src/Servers/Kestrel/Core/src/Internal/CertificatePathWatcherLoggerExtensions.cs

@@ -34,30 +34,24 @@ internal static partial class CertificatePathWatcherLoggerExtensions
     [LoggerMessage(9, LogLevel.Debug, "Ignored event for presently untracked file '{Path}'.", EventName = "UntrackedFileEvent")]
     public static partial void UntrackedFileEvent(this ILogger<CertificatePathWatcher> logger, string path);
 
-    [LoggerMessage(10, LogLevel.Debug, "Ignored out-of-order event for file '{Path}'.", EventName = "OutOfOrderEvent")]
-    public static partial void OutOfOrderEvent(this ILogger<CertificatePathWatcher> logger, string path);
-
-    [LoggerMessage(11, LogLevel.Trace, "Reused existing observer on file watcher for '{Path}'.", EventName = "ReusedObserver")]
+    [LoggerMessage(10, LogLevel.Trace, "Reused existing observer on file watcher for '{Path}'.", EventName = "ReusedObserver")]
     public static partial void ReusedObserver(this ILogger<CertificatePathWatcher> logger, string path);
 
-    [LoggerMessage(12, LogLevel.Trace, "Added observer to file watcher for '{Path}'.", EventName = "AddedObserver")]
+    [LoggerMessage(11, LogLevel.Trace, "Added observer to file watcher for '{Path}'.", EventName = "AddedObserver")]
     public static partial void AddedObserver(this ILogger<CertificatePathWatcher> logger, string path);
 
-    [LoggerMessage(13, LogLevel.Trace, "Removed observer from file watcher for '{Path}'.", EventName = "RemovedObserver")]
+    [LoggerMessage(12, LogLevel.Trace, "Removed observer from file watcher for '{Path}'.", EventName = "RemovedObserver")]
     public static partial void RemovedObserver(this ILogger<CertificatePathWatcher> logger, string path);
 
-    [LoggerMessage(14, LogLevel.Trace, "File '{Path}' now has {Count} observers.", EventName = "ObserverCount")]
+    [LoggerMessage(13, LogLevel.Trace, "File '{Path}' now has {Count} observers.", EventName = "ObserverCount")]
     public static partial void ObserverCount(this ILogger<CertificatePathWatcher> logger, string path, int count);
 
-    [LoggerMessage(15, LogLevel.Trace, "Directory '{Directory}' now has watchers on {Count} files.", EventName = "FileCount")]
+    [LoggerMessage(14, LogLevel.Trace, "Directory '{Directory}' now has watchers on {Count} files.", EventName = "FileCount")]
     public static partial void FileCount(this ILogger<CertificatePathWatcher> logger, string directory, int count);
 
-    [LoggerMessage(16, LogLevel.Trace, "Ignored event since last modified time for '{Path}' was unavailable.", EventName = "EventWithoutLastModifiedTime")]
-    public static partial void EventWithoutLastModifiedTime(this ILogger<CertificatePathWatcher> logger, string path);
-
-    [LoggerMessage(17, LogLevel.Trace, "Ignored redundant event for '{Path}'.", EventName = "RedundantEvent")]
-    public static partial void RedundantEvent(this ILogger<CertificatePathWatcher> logger, string path);
-
-    [LoggerMessage(18, LogLevel.Trace, "Flagged {Count} observers of '{Path}' as changed.", EventName = "FlaggedObservers")]
+    [LoggerMessage(15, LogLevel.Trace, "Flagged {Count} observers of '{Path}' as changed.", EventName = "FlaggedObservers")]
     public static partial void FlaggedObservers(this ILogger<CertificatePathWatcher> logger, string path, int count);
+
+    [LoggerMessage(16, LogLevel.Trace, "Ignored event since '{Path}' was unavailable.", EventName = "EventWithoutFile")]
+    public static partial void EventWithoutFile(this ILogger<CertificatePathWatcher> logger, string path);
 }

src/Servers/Kestrel/Core/test/CertificatePathWatcherTests.cs

@@ -187,17 +187,10 @@ public class CertificatePathWatcherTests : LoggedTest
 
         watcher.AddWatchUnsynchronized(certificateConfig);
 
-        var logTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
-
-        TestSink.MessageLogged += writeContext =>
-        {
-            if (writeContext.EventId.Name == "OutOfOrderEvent")
-            {
-                logTcs.SetResult();
-            }
-        };
+        var signalTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
 
         var oldChangeToken = watcher.GetChangeToken();
+        oldChangeToken.RegisterChangeCallback(_ => signalTcs.SetResult(), state: null);
 
         Assert.Equal(1, watcher.TestGetDirectoryWatchCountUnsynchronized());
         Assert.Equal(1, watcher.TestGetFileWatchCountUnsynchronized(dir));
@@ -207,9 +200,9 @@ public class CertificatePathWatcherTests : LoggedTest
         fileProvider.SetLastModifiedTime(fileName, fileLastModifiedTime.AddSeconds(-1));
         fileProvider.FireChangeToken(fileName);
 
-        await logTcs.Task.DefaultTimeout();
+        await signalTcs.Task.DefaultTimeout();
 
-        Assert.False(oldChangeToken.HasChanged);
+        Assert.True(oldChangeToken.HasChanged);
     }
 
     [Fact]
@@ -342,12 +335,10 @@ public class CertificatePathWatcherTests : LoggedTest
     }
 
     [Theory]
-    [InlineData(true, true)]
-    [InlineData(true, false)]
-    [InlineData(false, true)]
-    [InlineData(false, false)]
+    [InlineData(true)]
+    [InlineData(false)]
     [LogLevel(LogLevel.Trace)]
-    public async Task IgnoreDeletion(bool seeChangeForDeletion, bool restoredWithNewerLastModifiedTime)
+    public async Task IgnoreDeletion(bool restoredWithNewerLastModifiedTime)
     {
         var dir = Directory.GetCurrentDirectory();
         var fileName = Path.GetRandomFileName();
@@ -377,30 +368,21 @@ public class CertificatePathWatcherTests : LoggedTest
         watcher.GetChangeToken().RegisterChangeCallback(_ => changeTcs.SetResult(), state: null);
 
         var logNoLastModifiedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
-        var logSameLastModifiedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
 
         TestSink.MessageLogged += writeContext =>
         {
-            if (writeContext.EventId.Name == "EventWithoutLastModifiedTime")
+            if (writeContext.EventId.Name == "EventWithoutFile")
             {
                 logNoLastModifiedTcs.SetResult();
             }
-            else if (writeContext.EventId.Name == "RedundantEvent")
-            {
-                logSameLastModifiedTcs.SetResult();
-            }
         };
 
         // Simulate file deletion
         fileProvider.SetLastModifiedTime(fileName, null);
 
-        // In some file systems and watch modes, there's no event when (e.g.) the directory containing the watched file is deleted
-        if (seeChangeForDeletion)
-        {
-            fileProvider.FireChangeToken(fileName);
+        fileProvider.FireChangeToken(fileName);
 
-            await logNoLastModifiedTcs.Task.DefaultTimeout();
-        }
+        await logNoLastModifiedTcs.Task.DefaultTimeout();
 
         Assert.Equal(1, watcher.TestGetDirectoryWatchCountUnsynchronized());
         Assert.Equal(1, watcher.TestGetFileWatchCountUnsynchronized(dir));
@@ -412,16 +394,7 @@ public class CertificatePathWatcherTests : LoggedTest
         fileProvider.SetLastModifiedTime(fileName, restoredWithNewerLastModifiedTime ? fileLastModifiedTime.AddSeconds(1) : fileLastModifiedTime);
         fileProvider.FireChangeToken(fileName);
 
-        if (restoredWithNewerLastModifiedTime)
-        {
-            await changeTcs.Task.DefaultTimeout();
-            Assert.False(logSameLastModifiedTcs.Task.IsCompleted);
-        }
-        else
-        {
-            await logSameLastModifiedTcs.Task.DefaultTimeout();
-            Assert.False(changeTcs.Task.IsCompleted);
-        }
+        await changeTcs.Task.DefaultTimeout();
     }
 
     [Fact]

src/Servers/Kestrel/Kestrel/test/KestrelConfigurationLoaderTests.cs

@@ -894,7 +894,7 @@ public class KestrelConfigurationLoaderTests
 
             if (reloadOnChange)
             {
-                await fileTcs.Task.DefaultTimeout();
+                await fileTcs.Task.TimeoutAfter(TimeSpan.FromSeconds(10)); // Needs to be meaningfully longer than the polling period - 4 seconds
             }
             else
             {
@@ -922,6 +922,94 @@ public class KestrelConfigurationLoaderTests
         }
     }
 
+    [ConditionalFact]
+    [OSSkipCondition(OperatingSystems.Windows)] // Windows has poor support for directory symlinks (e.g. https://github.com/dotnet/runtime/issues/27826)
+    public async Task CertificateChangedOnDisk_Symlink()
+    {
+        var tempDir = Directory.CreateTempSubdirectory().FullName;
+
+        try
+        {
+            // temp/
+            //     tls.key -> link/tls.key
+            //     link/ -> old/
+            //     old/
+            //         tls.key
+            //     new/
+            //         tls.key
+
+            var oldDir = Directory.CreateDirectory(Path.Combine(tempDir, "old"));
+            var newDir = Directory.CreateDirectory(Path.Combine(tempDir, "new"));
+            var oldCertPath = Path.Combine(oldDir.FullName, "tls.key");
+            var newCertPath = Path.Combine(newDir.FullName, "tls.key");
+
+            var dirLink = Directory.CreateSymbolicLink(Path.Combine(tempDir, "link"), "./old");
+            var fileLink = File.CreateSymbolicLink(Path.Combine(tempDir, "tls.key"), "./link/tls.key");
+
+            var serverOptions = CreateServerOptions();
+
+            var certificatePassword = "1234";
+
+            var oldCertificate = new X509Certificate2(TestResources.GetCertPath("aspnetdevcert.pfx"), "testPassword", X509KeyStorageFlags.Exportable);
+            var oldCertificateBytes = oldCertificate.Export(X509ContentType.Pkcs12, certificatePassword);
+
+            File.WriteAllBytes(oldCertPath, oldCertificateBytes);
+
+            var newCertificate = new X509Certificate2(TestResources.TestCertificatePath, "testPassword", X509KeyStorageFlags.Exportable);
+            var newCertificateBytes = newCertificate.Export(X509ContentType.Pkcs12, certificatePassword);
+
+            File.WriteAllBytes(newCertPath, newCertificateBytes);
+
+            var endpointConfigurationCallCount = 0;
+            var config = new ConfigurationBuilder().AddInMemoryCollection(new[]
+            {
+                new KeyValuePair<string, string>("Endpoints:End1:Url", "https://*:5001"),
+                new KeyValuePair<string, string>("Endpoints:End1:Certificate:Path", fileLink.FullName),
+                new KeyValuePair<string, string>("Endpoints:End1:Certificate:Password", certificatePassword),
+            }).Build();
+
+            var configLoader = serverOptions
+                .Configure(config, reloadOnChange: true)
+                .Endpoint("End1", opt =>
+                {
+                    Assert.True(opt.IsHttps);
+                    var expectedSerialNumber = endpointConfigurationCallCount == 0
+                        ? oldCertificate.SerialNumber
+                        : newCertificate.SerialNumber;
+                    Assert.Equal(opt.HttpsOptions.ServerCertificate.SerialNumber, expectedSerialNumber);
+                    endpointConfigurationCallCount++;
+                });
+
+            configLoader.Load();
+
+            var fileTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously);
+
+            configLoader.GetReloadToken().RegisterChangeCallback(_ => fileTcs.SetResult(), state: null);
+
+            // Clobber link/ directory symlink - this will effectively cause the cert to be updated.
+            // Unfortunately, it throws (file exists) if we don't delete the old one first so it's not a single, clean FS operation.
+            dirLink.Delete();
+            dirLink = Directory.CreateSymbolicLink(Path.Combine(tempDir, "link"), "./new");
+
+            // This can fail in local runs where the timeout is 5 seconds and polling period is 4 seconds - just re-run
+            await fileTcs.Task.DefaultTimeout();
+
+            Assert.Equal(1, endpointConfigurationCallCount);
+
+            configLoader.Reload();
+
+            Assert.Equal(2, endpointConfigurationCallCount);
+        }
+        finally
+        {
+            if (Directory.Exists(tempDir))
+            {
+                // Note: the watcher will see this event, but we ignore deletions, so it shouldn't matter
+                Directory.Delete(tempDir, recursive: true);
+            }
+        }
+    }
+
     [ConditionalTheory]
     [InlineData("http1", HttpProtocols.Http1)]
     // [InlineData("http2", HttpProtocols.Http2)] // Not supported due to missing ALPN support. https://github.com/dotnet/corefx/issues/33016