Skip to content

Commit 91cfab4

Browse files
AnatoliBAnatoliB
authored
Improve dependency management logs (#354)
Improve dependency management logs: - For every dependency snapshot installation start, success, or failure event, log the installation mode as well ("Required" vs. "Optional"). - Log AcceptableFunctionAppDependenciesAlreadyInstalled just once on worker start, no need to repeat it later.
1 parent 4f48c19 commit 91cfab4

10 files changed

+123
-90
lines changed

‎src/DependencyManagement/BackgroundDependencySnapshotMaintainer.cs

Lines changed: 4 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -56,11 +56,6 @@ public string InstallAndPurgeSnapshots(Func<PowerShell> pwshFactory, ILogger log
5656
{
5757
try
5858
{
59-
logger.Log(
60-
isUserOnlyLog: false,
61-
RpcLog.Types.Level.Trace,
62-
PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled);
63-
6459
// Purge before installing a new snapshot, as we may be able to free some space.
6560
_purger.Purge(logger);
6661

@@ -77,12 +72,11 @@ public string InstallAndPurgeSnapshots(Func<PowerShell> pwshFactory, ILogger log
7772
_dependencyManifest,
7873
nextSnapshotPath,
7974
pwsh,
80-
// If the new snapshot turns out to be equivalent to the latest one,
81-
// removing it helps us save storage space and avoid unnecessary worker restarts.
82-
// It is ok to do that during background upgrade because the current
75+
// Background dependency upgrades are optional because the current
8376
// worker already has a good enough snapshot, and nothing depends on
84-
// the new snapshot yet.
85-
removeIfEquivalentToLatest: true,
77+
// the new snapshot yet, so installation failures will not affect
78+
// function invocations.
79+
DependencySnapshotInstallationMode.Optional,
8680
logger);
8781
}
8882

‎src/DependencyManagement/DependencyManager.cs

Lines changed: 8 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -185,6 +185,11 @@ internal Exception InstallFunctionAppDependencies(PowerShell firstPwsh, Func<Pow
185185
{
186186
if (AreAcceptableDependenciesAlreadyInstalled())
187187
{
188+
logger.Log(
189+
isUserOnlyLog: false,
190+
RpcLog.Types.Level.Trace,
191+
PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled);
192+
188193
// Background installation: can't use the firstPwsh runspace because it belongs
189194
// to the pool used to run functions code, so create a new runspace.
190195
_nextSnapshotPath = _backgroundSnapshotMaintainer.InstallAndPurgeSnapshots(pwshFactory, logger);
@@ -210,13 +215,9 @@ private void InstallSnapshotInForeground(PowerShell pwsh, ILogger logger)
210215
_dependenciesFromManifest,
211216
_currentSnapshotPath,
212217
pwsh,
213-
// Even if the new snapshot turns out to be equivalent to the latest one,
214-
// removing it would not be safe because the current worker already depends
215-
// on it, as it has the path to this snapshot already added to PSModulePath.
216-
// As opposed to the background upgrade case, this snapshot is *required* for
217-
// this worker to run, even though it occupies some space (until the workers
218-
// restart and the redundant snapshots are purged).
219-
removeIfEquivalentToLatest: false,
218+
// As opposed to the background upgrade case, the worker does not have an acceptable
219+
// snapshot to use yet, so the initial snapshot is *required* for this worker to run.
220+
DependencySnapshotInstallationMode.Required,
220221
logger);
221222
}
222223
catch (Exception e)

‎src/DependencyManagement/DependencySnapshotInstallationMode.cs

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
//
2+
// Copyright (c) Microsoft. All rights reserved.
3+
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
4+
//
5+
6+
#pragma warning disable 1591 // "Mixing XML comments for publicly visible type"
7+
8+
namespace Microsoft.Azure.Functions.PowerShellWorker.DependencyManagement
9+
{
10+
public enum DependencySnapshotInstallationMode
11+
{
12+
Required,
13+
Optional
14+
}
15+
}

‎src/DependencyManagement/DependencySnapshotInstaller.cs

Lines changed: 44 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -40,15 +40,18 @@ public void InstallSnapshot(
4040
IEnumerable<DependencyManifestEntry> dependencies,
4141
string targetPath,
4242
PowerShell pwsh,
43-
bool removeIfEquivalentToLatest,
43+
DependencySnapshotInstallationMode installationMode,
4444
ILogger logger)
4545
{
4646
var installingPath = CreateInstallingSnapshot(targetPath);
4747

4848
logger.Log(
4949
isUserOnlyLog: false,
5050
LogLevel.Trace,
51-
string.Format(PowerShellWorkerStrings.InstallingFunctionAppRequiredModules, installingPath));
51+
string.Format(
52+
PowerShellWorkerStrings.InstallingFunctionAppRequiredModules,
53+
installingPath,
54+
installationMode));
5255

5356
try
5457
{
@@ -57,18 +60,38 @@ public void InstallSnapshot(
5760
InstallModule(module, installingPath, pwsh, logger);
5861
}
5962

60-
if (removeIfEquivalentToLatest)
63+
switch (installationMode)
6164
{
62-
PromoteToInstalledOrRemove(installingPath, targetPath, logger);
63-
}
64-
else
65-
{
66-
PromoteToInstalled(installingPath, targetPath, logger);
65+
case DependencySnapshotInstallationMode.Optional:
66+
// If the new snapshot turns out to be equivalent to the latest one,
67+
// removing it helps us save storage space and avoid unnecessary worker restarts.
68+
// It is ok to do that during background upgrade because the current
69+
// worker already has a good enough snapshot, and nothing depends on
70+
// the new snapshot yet.
71+
PromoteToInstalledOrRemove(installingPath, targetPath, installationMode, logger);
72+
break;
73+
74+
case DependencySnapshotInstallationMode.Required:
75+
// Even if the new snapshot turns out to be equivalent to the latest one,
76+
// removing it would not be safe because the current worker already depends
77+
// on it, as it has the path to this snapshot already added to PSModulePath.
78+
// As opposed to the background upgrade case, this snapshot is *required* for
79+
// this worker to run, even though it occupies some space (until the workers
80+
// restart and the redundant snapshots are purged).
81+
PromoteToInstalled(installingPath, targetPath, installationMode, logger);
82+
break;
83+
84+
default:
85+
throw new ArgumentException($"Unexpected installation mode: {installationMode}", nameof(installationMode));
6786
}
6887
}
6988
catch (Exception e)
7089
{
71-
var message = string.Format(PowerShellWorkerStrings.FailedToInstallDependenciesSnapshot, targetPath);
90+
var message = string.Format(
91+
PowerShellWorkerStrings.FailedToInstallDependenciesSnapshot,
92+
targetPath,
93+
installationMode);
94+
7295
logger.Log(isUserOnlyLog: false, LogLevel.Warning, message, e);
7396
_storage.RemoveSnapshot(installingPath);
7497
throw;
@@ -130,7 +153,11 @@ private void InstallModule(DependencyInfo module, string installingPath, PowerSh
130153
}
131154
}
132155

133-
private void PromoteToInstalledOrRemove(string installingPath, string installedPath, ILogger logger)
156+
private void PromoteToInstalledOrRemove(
157+
string installingPath,
158+
string installedPath,
159+
DependencySnapshotInstallationMode installationMode,
160+
ILogger logger)
134161
{
135162
var latestSnapshot = _storage.GetLatestInstalledSnapshot();
136163
if (latestSnapshot != null && _snapshotComparer.AreEquivalent(installingPath, latestSnapshot, logger))
@@ -148,18 +175,22 @@ private void PromoteToInstalledOrRemove(string installingPath, string installedP
148175
}
149176
else
150177
{
151-
PromoteToInstalled(installingPath, installedPath, logger);
178+
PromoteToInstalled(installingPath, installedPath, installationMode, logger);
152179
}
153180
}
154181

155-
private void PromoteToInstalled(string installingPath, string installedPath, ILogger logger)
182+
private void PromoteToInstalled(
183+
string installingPath,
184+
string installedPath,
185+
DependencySnapshotInstallationMode installationMode,
186+
ILogger logger)
156187
{
157188
_storage.PromoteInstallingSnapshotToInstalledAtomically(installedPath);
158189

159190
logger.Log(
160191
isUserOnlyLog: false,
161192
LogLevel.Trace,
162-
string.Format(PowerShellWorkerStrings.PromotedDependencySnapshot, installingPath, installedPath));
193+
string.Format(PowerShellWorkerStrings.PromotedDependencySnapshot, installingPath, installedPath, installationMode));
163194

164195
_snapshotContentLogger.LogDependencySnapshotContent(installedPath, logger);
165196
}

‎src/DependencyManagement/IDependencySnapshotInstaller.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,7 @@ void InstallSnapshot(
1515
IEnumerable<DependencyManifestEntry> dependencies,
1616
string targetPath,
1717
PowerShell pwsh,
18-
bool removeIfEquivalentToLatest,
18+
DependencySnapshotInstallationMode installationMode,
1919
ILogger logger);
2020
}
2121
}

‎src/resources/PowerShellWorkerStrings.resx

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -200,7 +200,7 @@
200200
<value>Failed to resolve '{0}' path in App Service.</value>
201201
</data>
202202
<data name="InstallingFunctionAppRequiredModules" xml:space="preserve">
203-
<value>Installing function app required modules to '{0}'.</value>
203+
<value>Installing function app required modules to '{0}' (installation mode: {1}).</value>
204204
</data>
205205
<data name="LogConcurrencyUpperBound" xml:space="preserve">
206206
<value>The enforced concurrency level (pool size limit) is '{0}'.</value>
@@ -257,7 +257,7 @@
257257
<value>Updating dependencies folder heartbeat for '{0}''.</value>
258258
</data>
259259
<data name="FailedToInstallDependenciesSnapshot" xml:space="preserve">
260-
<value>Failed to install dependencies into '{0}', removing the folder.</value>
260+
<value>Failed to install dependencies into '{0}' (installation mode: {1}), removing the folder.</value>
261261
</data>
262262
<data name="TooManyDependencies" xml:space="preserve">
263263
<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 @@
269269
<value>Removing dependency snapshot '{0}' because it is equivalent to '{1}'.</value>
270270
</data>
271271
<data name="PromotedDependencySnapshot" xml:space="preserve">
272-
<value>Promoted dependency snapshot '{0}' to '{1}'.</value>
272+
<value>Promoted dependency snapshot '{0}' to '{1}' (installation mode: {2}).</value>
273273
</data>
274274
<data name="LookingForNewerDependencySnapshot" xml:space="preserve">
275275
<value>Looking for a dependency snapshot newer than {0}.</value>

‎test/Unit/DependencyManagement/BackgroundDependencySnapshotMaintainerTests.cs

Lines changed: 3 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -52,7 +52,7 @@ public void InstallsSnapshotIfNoRecentlyInstalledSnapshotFound()
5252
It.IsAny<DependencyManifestEntry[]>(),
5353
It.IsAny<string>(),
5454
It.IsAny<PowerShell>(),
55-
It.IsAny<bool>(),
55+
It.IsAny<DependencySnapshotInstallationMode>(),
5656
It.IsAny<ILogger>()));
5757

5858
using (var dummyPowerShell = PowerShell.Create())
@@ -66,19 +66,11 @@ public void InstallsSnapshotIfNoRecentlyInstalledSnapshotFound()
6666

6767
// ReSharper disable once AccessToDisposedClosure
6868
_mockInstaller.Verify(
69-
_ => _.InstallSnapshot(_dependencyManifest, "new snapshot path", dummyPowerShell, true, _mockLogger.Object),
69+
_ => _.InstallSnapshot(_dependencyManifest, "new snapshot path", dummyPowerShell, DependencySnapshotInstallationMode.Optional, _mockLogger.Object),
7070
Times.Once);
7171

7272
_mockPurger.Verify(_ => _.Purge(_mockLogger.Object), Times.Exactly(2));
7373
}
74-
75-
_mockLogger.Verify(
76-
_ => _.Log(
77-
false,
78-
LogLevel.Trace,
79-
It.Is<string>(message => message.Contains(PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled)),
80-
It.IsAny<Exception>()),
81-
Times.Once);
8274
}
8375

8476
[Fact]
@@ -97,14 +89,6 @@ public void DoesNotInstallSnapshotIfRecentlyInstalledSnapshotFound()
9789

9890
_mockPurger.Verify(_ => _.Purge(_mockLogger.Object), Times.Once);
9991
}
100-
101-
_mockLogger.Verify(
102-
_ => _.Log(
103-
false,
104-
LogLevel.Trace,
105-
It.Is<string>(message => message.Contains(PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled)),
106-
It.IsAny<Exception>()),
107-
Times.Once);
10892
}
10993

11094
[Fact]
@@ -123,7 +107,7 @@ public void LogsWarningIfCannotInstallSnapshot()
123107
It.IsAny<DependencyManifestEntry[]>(),
124108
It.IsAny<string>(),
125109
It.IsAny<PowerShell>(),
126-
It.IsAny<bool>(),
110+
It.IsAny<DependencySnapshotInstallationMode>(),
127111
It.IsAny<ILogger>()))
128112
.Throws(injectedException);
129113

‎test/Unit/DependencyManagement/DependencyManagementTests.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -352,7 +352,7 @@ public void TestManagedDependencyRetryLogicMaxNumberOfTries()
352352
Assert.Contains(currentAttempt, relevantLogs[index]);
353353
}
354354

355-
Assert.Matches("Warning: Failed to install dependencies into '(.+?)', removing the folder", relevantLogs[4]);
355+
Assert.Matches("Warning: Failed to install dependencies into '(.+?)'", relevantLogs[4]);
356356

357357
// Lastly, DependencyError should get set after unsuccessfully retrying 3 times.
358358
Assert.NotNull(dependencyError);

‎test/Unit/DependencyManagement/DependencyManagerTests.cs

Lines changed: 12 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -137,7 +137,7 @@ public void StartDependencyInstallationIfNeeded_InstallsSnapshotInForeground_Whe
137137
"NewSnapshot",
138138
// Must run on the same runspace
139139
It.Is<PowerShell>(powerShell => ReferenceEquals(firstPowerShellRunspace, powerShell)),
140-
false, // removeIfEquivalentToLatest
140+
DependencySnapshotInstallationMode.Required,
141141
_mockLogger.Object));
142142

143143
_mockStorage.Setup(_ => _.SnapshotExists("NewSnapshot")).Returns(false);
@@ -184,6 +184,14 @@ public void StartDependencyInstallationIfNeeded_InvokesBackgroundMaintainer_When
184184
_ => _.InstallAndPurgeSnapshots(powerShellFactory, _mockLogger.Object),
185185
Times.Once);
186186
}
187+
188+
_mockLogger.Verify(
189+
_ => _.Log(
190+
false,
191+
LogLevel.Trace,
192+
It.Is<string>(message => message.Contains(PowerShellWorkerStrings.AcceptableFunctionAppDependenciesAlreadyInstalled)),
193+
It.IsAny<Exception>()),
194+
Times.Once);
187195
}
188196

189197
[Fact]
@@ -202,7 +210,7 @@ public void StartDependencyInstallationIfNeeded_InstallsSnapshotInForeground_Whe
202210
"NewSnapshot",
203211
// Must run on the same runspace
204212
It.Is<PowerShell>(powerShell => ReferenceEquals(firstPowerShellRunspace, powerShell)),
205-
false, // removeIfEquivalentToLatest
213+
DependencySnapshotInstallationMode.Required,
206214
_mockLogger.Object));
207215

208216
_mockStorage.Setup(_ => _.SnapshotExists("NewSnapshot")).Returns(false);
@@ -244,7 +252,7 @@ public void StartDependencyInstallationIfNeeded_HandlesExceptionThrownBy_Install
244252
It.IsAny<IEnumerable<DependencyManifestEntry>>(),
245253
It.IsAny<string>(),
246254
It.IsAny<PowerShell>(),
247-
It.IsAny<bool>(),
255+
It.IsAny<DependencySnapshotInstallationMode>(),
248256
It.IsAny<ILogger>()))
249257
.Throws(injectedException);
250258

@@ -273,7 +281,7 @@ private void VerifyExactlyOneSnapshotInstalled()
273281
It.IsAny<IEnumerable<DependencyManifestEntry>>(),
274282
It.IsAny<string>(),
275283
It.IsAny<PowerShell>(),
276-
It.IsAny<bool>(),
284+
It.IsAny<DependencySnapshotInstallationMode>(),
277285
It.IsAny<ILogger>()),
278286
Times.Once());
279287

0 commit comments

Comments
 (0)