Tolerate read-only managed dependencies files (#409)

Tolerate read-only managed dependencies files:
- When updating the heartbeat (the timestamp on the .used file under a snapshot) fails because the file is read-only, log a warning but proceed.
- Make sure the worker does not purge the currently used snapshot even if the heartbeat has not been updated for long time.

Author: AnatoliB

src/DependencyManagement/DependencySnapshotPurger.cs

@@ -21,6 +21,7 @@ internal class DependencySnapshotPurger : IDependencySnapshotPurger, IDisposable
         private readonly TimeSpan _oldHeartbeatAgeMargin;
         private readonly int _minNumberOfSnapshotsToKeep;
 
+        private string _currentlyUsedSnapshotPath;
         private Timer _heartbeat;
 
         public DependencySnapshotPurger(
@@ -42,6 +43,8 @@ public DependencySnapshotPurger(
         /// </summary>
         public void SetCurrentlyUsedSnapshot(string path, ILogger logger)
         {
+            _currentlyUsedSnapshotPath = path;
+
             Heartbeat(path, logger);
 
             _heartbeat = new Timer(
@@ -65,6 +68,7 @@ public void Purge(ILogger logger)
             var threshold = DateTime.UtcNow - _heartbeatPeriod - _oldHeartbeatAgeMargin;
 
             var pathSortedByAccessTime = allSnapshotPaths
+                                            .Where(path => string.CompareOrdinal(path, _currentlyUsedSnapshotPath) != 0)
                                             .Select(path => Tuple.Create(path, GetSnapshotAccessTimeUtc(path, logger)))
                                             .OrderBy(entry => entry.Item2)
                                             .ToArray();
@@ -108,7 +112,22 @@ internal void Heartbeat(string path, ILogger logger)
 
             if (_storage.SnapshotExists(path))
             {
-                _storage.SetSnapshotAccessTimeToUtcNow(path);
+                try
+                {
+                    _storage.SetSnapshotAccessTimeToUtcNow(path);
+                }
+                // The files in the snapshot may be read-only in some scenarios, so updating
+                // the timestamp may fail. However, the snapshot can still be used, and
+                // we should not prevent function executions because of that.
+                // So, just log and move on.
+                catch (IOException e)
+                {
+                    LogHeartbeatUpdateFailure(logger, path, e);
+                }
+                catch (UnauthorizedAccessException e)
+                {
+                    LogHeartbeatUpdateFailure(logger, path, e);
+                }
             }
         }
 
@@ -140,5 +159,16 @@ private static int GetMinNumberOfSnapshotsToKeep()
         {
             return PowerShellWorkerConfiguration.GetInt("MDMinNumberOfSnapshotsToKeep") ?? 1;
         }
+
+        private static void LogHeartbeatUpdateFailure(ILogger logger, string path, Exception exception)
+        {
+            var message = string.Format(
+                                PowerShellWorkerStrings.FailedToUpdateManagedDependencySnapshotHeartbeat,
+                                path,
+                                exception.GetType().FullName,
+                                exception.Message);
+
+            logger.Log(isUserOnlyLog: false, LogLevel.Warning, message);
+        }
     }
 }

src/resources/PowerShellWorkerStrings.resx

@@ -256,6 +256,9 @@
   <data name="UpdatingManagedDependencySnapshotHeartbeat" xml:space="preserve">
     <value>Updating dependencies folder heartbeat for '{0}''.</value>
   </data>
+  <data name="FailedToUpdateManagedDependencySnapshotHeartbeat" xml:space="preserve">
+    <value>Failed to update dependencies folder heartbeat for '{0}'. Exception {1}: '{2}'.</value>
+  </data>
   <data name="FailedToInstallDependenciesSnapshot" xml:space="preserve">
     <value>Failed to install dependencies into '{0}' (installation mode: {1}), removing the folder.</value>
   </data>

test/Unit/DependencyManagement/DependencySnapshotPurgerTests.cs

@@ -71,6 +71,28 @@ public void DoesNotRemoveRecentlyUsedSnapshot()
             _mockStorage.Verify(_ => _.RemoveSnapshot(It.IsAny<string>()), Times.Never);
         }
 
+        [Fact]
+        public void DoesNotRemoveCurrentlyUsedSnapshotEvenIfNotAccessedForLongTime()
+        {
+            _mockStorage.Setup(_ => _.GetInstalledAndInstallingSnapshots()).Returns(new[] { "snapshot" });
+            _mockStorage.Setup(_ => _.SnapshotExists("snapshot")).Returns(true);
+            _mockStorage.Setup(_ => _.GetSnapshotAccessTimeUtc("snapshot")).Returns(DateTime.UtcNow - TimeSpan.FromMinutes(300));
+            _mockStorage.Setup(_ => _.SetSnapshotAccessTimeToUtcNow("snapshot"));
+
+            using (var purger = new DependencySnapshotPurger(
+                                        _mockStorage.Object,
+                                        heartbeatPeriod: TimeSpan.FromMinutes(10),
+                                        oldHeartbeatAgeMargin: TimeSpan.FromMinutes(5),
+                                        minNumberOfSnapshotsToKeep: 0))
+            {
+                purger.SetCurrentlyUsedSnapshot("snapshot",  _mockLogger.Object);
+
+                purger.Purge(_mockLogger.Object);
+            }
+
+            _mockStorage.Verify(_ => _.RemoveSnapshot(It.IsAny<string>()), Times.Never);
+        }
+
         [Fact]
         public void RemovesMultipleSnapshotNotUsedForLongTime()
         {
@@ -258,6 +280,32 @@ public void Heartbeat_DoesNotUpdateCurrentSnapshotAccessTime_WhenSnapshotDoesNot
             _mockStorage.Verify(_ => _.SetSnapshotAccessTimeToUtcNow(It.IsAny<string>()), Times.Never);
         }
 
+        [Theory]
+        [MemberData(nameof(GetNonFatalFileSystemExceptions))]
+        public void Heartbeat_Tolerates_FileAccessFailures(Exception exception)
+        {
+            const string snapshotPath = "FakeSnapshotPath";
+            _mockStorage.Setup(_ => _.SnapshotExists(snapshotPath)).Returns(true);
+            _mockStorage.Setup(_ => _.SetSnapshotAccessTimeToUtcNow(snapshotPath))
+                .Throws(exception);
+
+            using (var purger = new DependencySnapshotPurger(_mockStorage.Object))
+            {
+                purger.Heartbeat(snapshotPath, _mockLogger.Object);
+            }
+
+            _mockLogger.Verify(
+                _ => _.Log(
+                    false,
+                    LogLevel.Warning,
+                    It.Is<string>(
+                        message => message.Contains(exception.GetType().FullName)
+                                    && message.Contains(exception.Message)
+                                    && message.Contains(snapshotPath)),
+                    null),
+                Times.AtLeastOnce);
+        }
+
         [Fact]
         public void SetCurrentlyUsedSnapshot_UpdatesCurrentSnapshotAccessTimeImmediately()
         {