Improve Managed Dependencies logs (#558) (#563)

Author: AnatoliB

src/DependencyManagement/BackgroundDependencySnapshotContentLogger.cs

@@ -0,0 +1,39 @@
+//
+// Copyright (c) Microsoft. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+//
+
+namespace Microsoft.Azure.Functions.PowerShellWorker.DependencyManagement
+{
+    using System;
+    using System.Threading;
+    using Microsoft.Azure.Functions.PowerShellWorker.Utility;
+
+    internal class BackgroundDependencySnapshotContentLogger : IBackgroundDependencySnapshotContentLogger, IDisposable
+    {
+        private readonly IDependencySnapshotContentLogger _snapshotContentLogger;
+
+        private Timer _timer;
+
+        public BackgroundDependencySnapshotContentLogger(IDependencySnapshotContentLogger snapshotContentLogger)
+        {
+            _snapshotContentLogger = snapshotContentLogger ?? throw new ArgumentNullException(nameof(snapshotContentLogger));
+        }
+
+        public void Start(string currentSnapshotPath, ILogger logger)
+        {
+            var period = PowerShellWorkerConfiguration.GetTimeSpan("MDCurrentSnapshotContentLogPeriod") ?? TimeSpan.FromDays(1);
+
+            _timer = new Timer(
+                _ => { _snapshotContentLogger.LogDependencySnapshotContent(currentSnapshotPath, logger); },
+                state: null,
+                dueTime: period,
+                period: period);
+        }
+
+        public void Dispose()
+        {
+            _timer?.Dispose();
+        }
+    }
+}

src/DependencyManagement/DependencyManager.cs

@@ -29,6 +29,8 @@ internal class DependencyManager : IDisposable
 
         private readonly IBackgroundDependencySnapshotMaintainer _backgroundSnapshotMaintainer;
 
+        private readonly IBackgroundDependencySnapshotContentLogger _currentSnapshotContentLogger;
+
         private DependencyManifestEntry[] _dependenciesFromManifest;
 
         private string _currentSnapshotPath;
@@ -48,21 +50,25 @@ public DependencyManager(
             IInstalledDependenciesLocator installedDependenciesLocator = null,
             IDependencySnapshotInstaller installer = null,
             INewerDependencySnapshotDetector newerSnapshotDetector = null,
-            IBackgroundDependencySnapshotMaintainer maintainer = null)
+            IBackgroundDependencySnapshotMaintainer maintainer = null,
+            IBackgroundDependencySnapshotContentLogger currentSnapshotContentLogger = null)
         {
             _storage = storage ?? new DependencyManagerStorage(GetFunctionAppRootPath(requestMetadataDirectory));
             _installedDependenciesLocator = installedDependenciesLocator ?? new InstalledDependenciesLocator(_storage);
+            var snapshotContentLogger = new PowerShellModuleSnapshotLogger();
             _installer = installer ?? new DependencySnapshotInstaller(
                                             moduleProvider ?? new PowerShellGalleryModuleProvider(),
                                             _storage,
                                             new PowerShellModuleSnapshotComparer(),
-                                            new PowerShellModuleSnapshotLogger());
+                                            snapshotContentLogger);
             _newerSnapshotDetector = newerSnapshotDetector ?? new NewerDependencySnapshotDetector(_storage, new WorkerRestarter());
             _backgroundSnapshotMaintainer =
                 maintainer ?? new BackgroundDependencySnapshotMaintainer(
                                     _storage,
                                     _installer,
                                     new DependencySnapshotPurger(_storage));
+            _currentSnapshotContentLogger =
+                currentSnapshotContentLogger ?? new BackgroundDependencySnapshotContentLogger(snapshotContentLogger);
         }
 
         /// <summary>
@@ -103,6 +109,7 @@ internal string Initialize(ILogger logger)
 
                 _backgroundSnapshotMaintainer.Start(_currentSnapshotPath, _dependenciesFromManifest, logger);
                 _newerSnapshotDetector.Start(_currentSnapshotPath, logger);
+                _currentSnapshotContentLogger.Start(_currentSnapshotPath, logger);
 
                 return _currentSnapshotPath;
             }
@@ -175,6 +182,7 @@ public void Dispose()
         {
             (_backgroundSnapshotMaintainer as IDisposable)?.Dispose();
             (_newerSnapshotDetector as IDisposable)?.Dispose();
+            (_currentSnapshotContentLogger as IDisposable)?.Dispose();
             _dependencyInstallationTask?.Dispose();
         }
 

src/DependencyManagement/DependencySnapshotInstaller.cs

@@ -60,6 +60,8 @@ public void InstallSnapshot(
                     InstallModule(module, installingPath, pwsh, logger);
                 }
 
+                _snapshotContentLogger.LogDependencySnapshotContent(installingPath, logger);
+
                 switch (installationMode)
                 {
                     case DependencySnapshotInstallationMode.Optional:

src/DependencyManagement/IBackgroundDependencySnapshotContentLogger.cs

@@ -0,0 +1,14 @@
+//
+// Copyright (c) Microsoft. All rights reserved.
+// Licensed under the MIT license. See LICENSE file in the project root for full license information.
+//
+
+namespace Microsoft.Azure.Functions.PowerShellWorker.DependencyManagement
+{
+    using Utility;
+
+    internal interface IBackgroundDependencySnapshotContentLogger
+    {
+        void Start(string currentSnapshotPath, ILogger logger);
+    }
+}

test/Unit/DependencyManagement/DependencyManagerTests.cs

@@ -24,6 +24,7 @@ public class DependencyManagerTests
         private readonly Mock<IDependencySnapshotInstaller> _mockInstaller = new Mock<IDependencySnapshotInstaller>(MockBehavior.Strict);
         private readonly Mock<INewerDependencySnapshotDetector> _mockNewerDependencySnapshotDetector = new Mock<INewerDependencySnapshotDetector>();
         private readonly Mock<IBackgroundDependencySnapshotMaintainer> _mockBackgroundDependencySnapshotMaintainer = new Mock<IBackgroundDependencySnapshotMaintainer>();
+        private readonly Mock<IBackgroundDependencySnapshotContentLogger> _mockBackgroundDependencySnapshotContentLogger = new Mock<IBackgroundDependencySnapshotContentLogger>();
         private readonly Mock<ILogger> _mockLogger = new Mock<ILogger>();
 
         [Fact]
@@ -82,7 +83,7 @@ public void Initialize_DoesNotTryToCheckOrMaintainDependencies_WhenNoDependencie
         }
 
         [Fact]
-        public void Initialize_StartsBackgroundSnapshotMaintainerAndNewerSnapshotDetector()
+        public void Initialize_StartsBackgroundActivities()
         {
             var dependencyManifest = GetAnyNonEmptyDependencyManifestEntries();
             _mockStorage.Setup(_ => _.GetDependencies()).Returns(dependencyManifest);
@@ -100,6 +101,10 @@ public void Initialize_StartsBackgroundSnapshotMaintainerAndNewerSnapshotDetecto
                 _mockNewerDependencySnapshotDetector.Verify(
                     _ => _.Start("InstalledSnapshot", _mockLogger.Object),
                     Times.Once);
+
+                _mockBackgroundDependencySnapshotContentLogger.Verify(
+                    _ => _.Start("InstalledSnapshot", _mockLogger.Object),
+                    Times.Once);
             }
         }
 
@@ -307,7 +312,8 @@ private DependencyManager CreateDependencyManagerWithMocks()
                 installedDependenciesLocator: _mockInstalledDependenciesLocator.Object,
                 installer: _mockInstaller.Object,
                 newerSnapshotDetector: _mockNewerDependencySnapshotDetector.Object,
-                maintainer: _mockBackgroundDependencySnapshotMaintainer.Object);
+                maintainer: _mockBackgroundDependencySnapshotMaintainer.Object,
+                currentSnapshotContentLogger: _mockBackgroundDependencySnapshotContentLogger.Object);
         }
     }
 }

test/Unit/DependencyManagement/DependencySnapshotInstallerTests.cs

@@ -118,6 +118,8 @@ public void PromotesInstallingSnapshotToInstalledIfNotEquivalentToLatest()
 
             _mockStorage.Verify(_ => _.CreateInstallingSnapshot(_targetPathInstalled), Times.Once);
             _mockStorage.Verify(_ => _.PromoteInstallingSnapshotToInstalledAtomically(_targetPathInstalled), Times.Once);
+
+            _mockSnapshotContentLogger.Verify(_ => _.LogDependencySnapshotContent(_targetPathInstalling, _mockLogger.Object), Times.Once);
             _mockSnapshotContentLogger.Verify(_ => _.LogDependencySnapshotContent(_targetPathInstalled, _mockLogger.Object), Times.Once);
         }
 
@@ -260,6 +262,9 @@ public void DoesNotPromoteSnapshotIfItIsEquivalentToLatest()
             _mockStorage.Verify(_ => _.PromoteInstallingSnapshotToInstalledAtomically(It.IsAny<string>()), Times.Never);
             _mockStorage.Verify(_ => _.RemoveSnapshot(_targetPathInstalling), Times.Once);
             _mockStorage.Verify(_ => _.SetSnapshotCreationTimeToUtcNow("snapshot"), Times.Once);
+
+            _mockSnapshotContentLogger.Verify(_ => _.LogDependencySnapshotContent(_targetPathInstalling, _mockLogger.Object), Times.Once);
+            _mockSnapshotContentLogger.Verify(_ => _.LogDependencySnapshotContent(_targetPathInstalled, _mockLogger.Object), Times.Never);
         }
 
         private DependencySnapshotInstaller CreateDependenciesSnapshotInstallerWithMocks()