Improve dependency management logs

src/DependencyManagement/BackgroundDependencySnapshotMaintainer.cs

@@ -56,11 +56,6 @@ public string InstallAndPurgeSnapshots(Func<PowerShell> pwshFactory, ILogger log
         {
             try
             {
-                logger.Log(
-                    isUserOnlyLog: false,
-                    RpcLog.Types.Level.Trace,
-                    PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled);
-
                 // Purge before installing a new snapshot, as we may be able to free some space.
                 _purger.Purge(logger);
 
@@ -77,12 +72,11 @@ public string InstallAndPurgeSnapshots(Func<PowerShell> pwshFactory, ILogger log
                         _dependencyManifest,
                         nextSnapshotPath,
                         pwsh,
-                        // If the new snapshot turns out to be equivalent to the latest one,
-                        // removing it helps us save storage space and avoid unnecessary worker restarts.
-                        // It is ok to do that during background upgrade because the current
+                        // Background dependency upgrades are optional because the current
                         // worker already has a good enough snapshot, and nothing depends on
-                        // the new snapshot yet.
-                        removeIfEquivalentToLatest: true,
+                        // the new snapshot yet, so installation failures will not affect
+                        // function invocations.
+                        DependencySnapshotInstallationMode.Optional,
                         logger);
                 }
 

src/DependencyManagement/DependencyManager.cs

@@ -185,6 +185,11 @@ internal Exception InstallFunctionAppDependencies(PowerShell firstPwsh, Func<Pow
         {
             if (AreAcceptableDependenciesAlreadyInstalled())
             {
+                logger.Log(
+                    isUserOnlyLog: false,
+                    RpcLog.Types.Level.Trace,
+                    PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled);
+
                 // Background installation: can't use the firstPwsh runspace because it belongs
                 // to the pool used to run functions code, so create a new runspace.
                 _nextSnapshotPath = _backgroundSnapshotMaintainer.InstallAndPurgeSnapshots(pwshFactory, logger);
@@ -210,13 +215,9 @@ private void InstallSnapshotInForeground(PowerShell pwsh, ILogger logger)
                     _dependenciesFromManifest,
                     _currentSnapshotPath,
                     pwsh,
-                    // Even if the new snapshot turns out to be equivalent to the latest one,
-                    // removing it would not be safe because the current worker already depends
-                    // on it, as it has the path to this snapshot already added to PSModulePath.
-                    // As opposed to the background upgrade case, this snapshot is *required* for
-                    // this worker to run, even though it occupies some space (until the workers
-                    // restart and the redundant snapshots are purged).
-                    removeIfEquivalentToLatest: false,
+                    // As opposed to the background upgrade case, the worker does not have an acceptable
+                    // snapshot to use yet, so the initial snapshot is *required* for this worker to run.
+                    DependencySnapshotInstallationMode.Required,
                     logger);
             }
             catch (Exception e)

src/DependencyManagement/DependencySnapshotInstallationMode.cs

@@ -0,0 +1,15 @@
+//
+// Copyright (c) Microsoft. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+//
+
+#pragma warning disable 1591 // "Mixing XML comments for publicly visible type"
+
+namespace Microsoft.Azure.Functions.PowerShellWorker.DependencyManagement
+{
+    public enum DependencySnapshotInstallationMode
+    {
+        Required,
+        Optional
+    }
+}

src/DependencyManagement/DependencySnapshotInstaller.cs

@@ -40,15 +40,18 @@ public void InstallSnapshot(
             IEnumerable<DependencyManifestEntry> dependencies,
             string targetPath,
             PowerShell pwsh,
-            bool removeIfEquivalentToLatest,
+            DependencySnapshotInstallationMode installationMode,
             ILogger logger)
         {
             var installingPath = CreateInstallingSnapshot(targetPath);
 
             logger.Log(
                 isUserOnlyLog: false,
                 LogLevel.Trace,
-                string.Format(PowerShellWorkerStrings.InstallingFunctionAppRequiredModules, installingPath));
+                string.Format(
+                    PowerShellWorkerStrings.InstallingFunctionAppRequiredModules,
+                    installingPath,
+                    installationMode));
 
             try
             {
@@ -57,18 +60,38 @@ public void InstallSnapshot(
                     InstallModule(module, installingPath, pwsh, logger);
                 }
 
-                if (removeIfEquivalentToLatest)
+                switch (installationMode)
                 {
-                    PromoteToInstalledOrRemove(installingPath, targetPath, logger);
-                }
-                else
-                {
-                    PromoteToInstalled(installingPath, targetPath, logger);
+                    case DependencySnapshotInstallationMode.Optional:
+                        // If the new snapshot turns out to be equivalent to the latest one,
+                        // removing it helps us save storage space and avoid unnecessary worker restarts.
+                        // It is ok to do that during background upgrade because the current
+                        // worker already has a good enough snapshot, and nothing depends on
+                        // the new snapshot yet.
+                        PromoteToInstalledOrRemove(installingPath, targetPath, installationMode, logger);
+                        break;
+
+                    case DependencySnapshotInstallationMode.Required:
+                        // Even if the new snapshot turns out to be equivalent to the latest one,
+                        // removing it would not be safe because the current worker already depends
+                        // on it, as it has the path to this snapshot already added to PSModulePath.
+                        // As opposed to the background upgrade case, this snapshot is *required* for
+                        // this worker to run, even though it occupies some space (until the workers
+                        // restart and the redundant snapshots are purged).
+                        PromoteToInstalled(installingPath, targetPath, installationMode, logger);
+                        break;
+
+                    default:
+                        throw new ArgumentException($"Unexpected installation mode: {installationMode}", nameof(installationMode));
                 }
             }
             catch (Exception e)
             {
-                var message = string.Format(PowerShellWorkerStrings.FailedToInstallDependenciesSnapshot, targetPath);
+                var message = string.Format(
+                                PowerShellWorkerStrings.FailedToInstallDependenciesSnapshot,
+                                targetPath,
+                                installationMode);
+
                 logger.Log(isUserOnlyLog: false, LogLevel.Warning, message, e);
                 _storage.RemoveSnapshot(installingPath);
                 throw;
@@ -130,7 +153,11 @@ private void InstallModule(DependencyInfo module, string installingPath, PowerSh
             }
         }
 
-        private void PromoteToInstalledOrRemove(string installingPath, string installedPath, ILogger logger)
+        private void PromoteToInstalledOrRemove(
+            string installingPath,
+            string installedPath,
+            DependencySnapshotInstallationMode installationMode,
+            ILogger logger)
         {
             var latestSnapshot = _storage.GetLatestInstalledSnapshot();
             if (latestSnapshot != null && _snapshotComparer.AreEquivalent(installingPath, latestSnapshot, logger))
@@ -148,18 +175,22 @@ private void PromoteToInstalledOrRemove(string installingPath, string installedP
             }
             else
             {
-                PromoteToInstalled(installingPath, installedPath, logger);
+                PromoteToInstalled(installingPath, installedPath, installationMode, logger);
             }
         }
 
-        private void PromoteToInstalled(string installingPath, string installedPath, ILogger logger)
+        private void PromoteToInstalled(
+            string installingPath,
+            string installedPath,
+            DependencySnapshotInstallationMode installationMode,
+            ILogger logger)
         {
             _storage.PromoteInstallingSnapshotToInstalledAtomically(installedPath);
 
             logger.Log(
                 isUserOnlyLog: false,
                 LogLevel.Trace,
-                string.Format(PowerShellWorkerStrings.PromotedDependencySnapshot, installingPath, installedPath));
+                string.Format(PowerShellWorkerStrings.PromotedDependencySnapshot, installingPath, installedPath, installationMode));
 
             _snapshotContentLogger.LogDependencySnapshotContent(installedPath, logger);
         }

src/DependencyManagement/IDependencySnapshotInstaller.cs

@@ -15,7 +15,7 @@ void InstallSnapshot(
             IEnumerable<DependencyManifestEntry> dependencies,
             string targetPath,
             PowerShell pwsh,
-            bool removeIfEquivalentToLatest,
+            DependencySnapshotInstallationMode installationMode,
             ILogger logger);
     }
 }

src/resources/PowerShellWorkerStrings.resx

@@ -200,7 +200,7 @@
     <value>Failed to resolve '{0}' path in App Service.</value>
   </data>
   <data name="InstallingFunctionAppRequiredModules" xml:space="preserve">
-    <value>Installing function app required modules to '{0}'.</value>
+    <value>Installing function app required modules to '{0}' (installation mode: {1}).</value>
   </data>
   <data name="LogConcurrencyUpperBound" xml:space="preserve">
     <value>The enforced concurrency level (pool size limit) is '{0}'.</value>
@@ -257,7 +257,7 @@
     <value>Updating dependencies folder heartbeat for '{0}''.</value>
   </data>
   <data name="FailedToInstallDependenciesSnapshot" xml:space="preserve">
-    <value>Failed to install dependencies into '{0}', removing the folder.</value>
+    <value>Failed to install dependencies into '{0}' (installation mode: {1}), removing the folder.</value>
   </data>
   <data name="TooManyDependencies" xml:space="preserve">
     <value>The number of entries in the '{0}' file is {1}, which exceeds the maximum supported number of entries ({2}).</value>
@@ -269,7 +269,7 @@
     <value>Removing dependency snapshot '{0}' because it is equivalent to '{1}'.</value>
   </data>
   <data name="PromotedDependencySnapshot" xml:space="preserve">
-    <value>Promoted dependency snapshot '{0}' to '{1}'.</value>
+    <value>Promoted dependency snapshot '{0}' to '{1}' (installation mode: {2}).</value>
   </data>
   <data name="LookingForNewerDependencySnapshot" xml:space="preserve">
     <value>Looking for a dependency snapshot newer than {0}.</value>

test/Unit/DependencyManagement/BackgroundDependencySnapshotMaintainerTests.cs

@@ -52,7 +52,7 @@ public void InstallsSnapshotIfNoRecentlyInstalledSnapshotFound()
                         It.IsAny<DependencyManifestEntry[]>(),
                         It.IsAny<string>(),
                         It.IsAny<PowerShell>(),
-                        It.IsAny<bool>(),
+                        It.IsAny<DependencySnapshotInstallationMode>(),
                         It.IsAny<ILogger>()));
 
             using (var dummyPowerShell = PowerShell.Create())
@@ -66,19 +66,11 @@ public void InstallsSnapshotIfNoRecentlyInstalledSnapshotFound()
 
                 // ReSharper disable once AccessToDisposedClosure
                 _mockInstaller.Verify(
-                    _ => _.InstallSnapshot(_dependencyManifest, "new snapshot path", dummyPowerShell, true, _mockLogger.Object),
+                    _ => _.InstallSnapshot(_dependencyManifest, "new snapshot path", dummyPowerShell, DependencySnapshotInstallationMode.Optional, _mockLogger.Object),
                     Times.Once);
 
                 _mockPurger.Verify(_ => _.Purge(_mockLogger.Object), Times.Exactly(2));
             }
-
-            _mockLogger.Verify(
-                _ => _.Log(
-                    false,
-                    LogLevel.Trace,
-                    It.Is<string>(message => message.Contains(PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled)),
-                    It.IsAny<Exception>()),
-                Times.Once);
         }
 
         [Fact]
@@ -97,14 +89,6 @@ public void DoesNotInstallSnapshotIfRecentlyInstalledSnapshotFound()
 
                 _mockPurger.Verify(_ => _.Purge(_mockLogger.Object), Times.Once);
             }
-
-            _mockLogger.Verify(
-                _ => _.Log(
-                    false,
-                    LogLevel.Trace,
-                    It.Is<string>(message => message.Contains(PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled)),
-                    It.IsAny<Exception>()),
-                Times.Once);
         }
 
         [Fact]
@@ -123,7 +107,7 @@ public void LogsWarningIfCannotInstallSnapshot()
                         It.IsAny<DependencyManifestEntry[]>(),
                         It.IsAny<string>(),
                         It.IsAny<PowerShell>(),
-                        It.IsAny<bool>(),
+                        It.IsAny<DependencySnapshotInstallationMode>(),
                         It.IsAny<ILogger>()))
                 .Throws(injectedException);
 

test/Unit/DependencyManagement/DependencyManagementTests.cs

@@ -352,7 +352,7 @@ public void TestManagedDependencyRetryLogicMaxNumberOfTries()
                         Assert.Contains(currentAttempt, relevantLogs[index]);
                     }
 
-                    Assert.Matches("Warning: Failed to install dependencies into '(.+?)', removing the folder", relevantLogs[4]);
+                    Assert.Matches("Warning: Failed to install dependencies into '(.+?)'", relevantLogs[4]);
 
                     // Lastly, DependencyError should get set after unsuccessfully retrying 3 times.
                     Assert.NotNull(dependencyError);

test/Unit/DependencyManagement/DependencyManagerTests.cs

@@ -137,7 +137,7 @@ public void StartDependencyInstallationIfNeeded_InstallsSnapshotInForeground_Whe
                         "NewSnapshot",
                         // Must run on the same runspace
                         It.Is<PowerShell>(powerShell => ReferenceEquals(firstPowerShellRunspace, powerShell)),
-                        false, // removeIfEquivalentToLatest
+                        DependencySnapshotInstallationMode.Required,
                         _mockLogger.Object));
 
             _mockStorage.Setup(_ => _.SnapshotExists("NewSnapshot")).Returns(false);
@@ -184,6 +184,14 @@ public void StartDependencyInstallationIfNeeded_InvokesBackgroundMaintainer_When
                     _ => _.InstallAndPurgeSnapshots(powerShellFactory, _mockLogger.Object),
                     Times.Once);
             }
+
+            _mockLogger.Verify(
+                _ => _.Log(
+                    false,
+                    LogLevel.Trace,
+                    It.Is<string>(message => message.Contains(PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled)),
+                    It.IsAny<Exception>()),
+                Times.Once);
         }
 
         [Fact]
@@ -202,7 +210,7 @@ public void StartDependencyInstallationIfNeeded_InstallsSnapshotInForeground_Whe
                         "NewSnapshot",
                         // Must run on the same runspace
                         It.Is<PowerShell>(powerShell => ReferenceEquals(firstPowerShellRunspace, powerShell)),
-                        false, // removeIfEquivalentToLatest
+                        DependencySnapshotInstallationMode.Required,
                         _mockLogger.Object));
 
             _mockStorage.Setup(_ => _.SnapshotExists("NewSnapshot")).Returns(false);
@@ -244,7 +252,7 @@ public void StartDependencyInstallationIfNeeded_HandlesExceptionThrownBy_Install
                             It.IsAny<IEnumerable<DependencyManifestEntry>>(),
                             It.IsAny<string>(),
                             It.IsAny<PowerShell>(),
-                            It.IsAny<bool>(),
+                            It.IsAny<DependencySnapshotInstallationMode>(),
                             It.IsAny<ILogger>()))
                     .Throws(injectedException);
 
@@ -273,7 +281,7 @@ private void VerifyExactlyOneSnapshotInstalled()
                     It.IsAny<IEnumerable<DependencyManifestEntry>>(),
                     It.IsAny<string>(),
                     It.IsAny<PowerShell>(),
-                    It.IsAny<bool>(),
+                    It.IsAny<DependencySnapshotInstallationMode>(),
                     It.IsAny<ILogger>()),
                 Times.Once());