Add more logging to understand host secrets regeneration

alrod · alrod · commit 7aa72290a0e3 · 2018-10-18T18:40:25.000-07:00
diff --git a/src/WebJobs.Script.WebHost/Controllers/KeysController.cs b/src/WebJobs.Script.WebHost/Controllers/KeysController.cs
@@ -182,8 +182,8 @@ private async Task<IHttpActionResult> AddOrUpdateSecretAsync(string keyName, str
             }
 
             string message = string.Format(Resources.TraceKeysApiSecretChange, keyName, keyScope ?? "host", operationResult.Result);
-            _traceWriter.Verbose(message);
-            _logger?.LogDebug(message);
+            _traceWriter.Info(message);
+            _logger?.LogInformation(message);
 
             switch (operationResult.Result)
             {
@@ -248,8 +248,8 @@ private async Task<IHttpActionResult> DeleteFunctionSecretAsync(string keyName,
             }
 
             string message = string.Format(Resources.TraceKeysApiSecretChange, keyName, keyScope ?? "host", "Deleted");
-            _traceWriter.VerboseFormat(message);
-            _logger?.LogDebug(message);
+            _traceWriter.Info(message);
+            _logger?.LogInformation(message);
 
             return StatusCode(HttpStatusCode.NoContent);
         }
diff --git a/src/WebJobs.Script.WebHost/Properties/Resources.Designer.cs b/src/WebJobs.Script.WebHost/Properties/Resources.Designer.cs
diff --git a/src/WebJobs.Script.WebHost/Properties/Resources.resx b/src/WebJobs.Script.WebHost/Properties/Resources.resx
@@ -286,6 +286,12 @@
   <data name="TraceFunctionSecretGeneration" xml:space="preserve">
     <value>Function ('{0}') secrets do not exist. Generating secrets.</value>
   </data>
+  <data name="TraceFunctionsKeysLoaded" xml:space="preserve">
+    <value>Function ('{0}') keys are loaded.</value>
+  </data>
+  <data name="TraceHostKeysLoaded" xml:space="preserve">
+    <value>Host keys are loaded.</value>
+  </data>
   <data name="TraceHostSecretGeneration" xml:space="preserve">
     <value>Host secrets do not exist. Generating secrets.</value>
   </data>
@@ -304,6 +310,9 @@
   <data name="TraceSecretDeleted" xml:space="preserve">
     <value>{0} secret '{1}' deleted.</value>
   </data>
+  <data name="TraceSecretsRepo" xml:space="preserve">
+    <value>Secrets manager initialized, repository type: {0}</value>
+  </data>
   <data name="TraceStaleFunctionSecretRefresh" xml:space="preserve">
     <value>Stale function ('{0}') secrets detected. Refreshing secrets.</value>
   </data>
diff --git a/src/WebJobs.Script.WebHost/Security/SecretManager.cs b/src/WebJobs.Script.WebHost/Security/SecretManager.cs
@@ -43,14 +43,17 @@ public SecretManager(ISecretsRepository repository, IKeyValueConverterFactory ke
             _keyValueConverterFactory = keyValueConverterFactory;
             _traceWriter = traceWriter;
             _repository.SecretsChanged += OnSecretsChanged;
-            _logger = loggerFactory?.CreateLogger(ScriptConstants.LogCategoryHostGeneral);
+            _logger = loggerFactory?.CreateLogger(ScriptConstants.LogCategoryKeys);
 
             if (createHostSecretsIfMissing)
             {
                 // The SecretManager implementation of GetHostSecrets will
                 // create a host secret if one is not present.
                 GetHostSecretsAsync().GetAwaiter().GetResult();
             }
+
+            _traceWriter.Info(Resources.TraceSecretsRepo, repository.ToString());
+            _logger?.LogInformation(Resources.TraceSecretsRepo, repository.ToString());
         }
 
         public void Dispose()
@@ -124,6 +127,9 @@ public async virtual Task<HostSecretsInfo> GetHostSecretsAsync()
                 }
             }
 
+            _traceWriter.Info(Resources.TraceHostKeysLoaded);
+            _logger?.LogInformation(Resources.TraceHostKeysLoaded);
+
             return _hostSecrets;
         }
 
@@ -148,9 +154,9 @@ public async virtual Task<IDictionary<string, string>> GetFunctionSecretsAsync(s
                 {
                     // no secrets exist for this function so generate them
                     string message = string.Format(Resources.TraceFunctionSecretGeneration, functionName);
-                    _traceWriter.Verbose(message, traceProperties);
+                    _traceWriter.Info(message, traceProperties);
 
-                    _logger?.LogDebug(message);
+                    _logger?.LogInformation(message);
                     secrets = new FunctionSecrets
                     {
                         Keys = new List<Key>
@@ -170,17 +176,17 @@ public async virtual Task<IDictionary<string, string>> GetFunctionSecretsAsync(s
                 catch (CryptographicException)
                 {
                     string message = string.Format(Resources.TraceNonDecryptedFunctionSecretRefresh, functionName);
-                    _traceWriter.Verbose(message, traceProperties);
-                    _logger?.LogDebug(message);
+                    _traceWriter.Info(message, traceProperties);
+                    _logger?.LogInformation(message);
                     await PersistSecretsAsync(secrets, functionName, true);
                     await RefreshSecretsAsync(secrets, functionName);
                 }
 
                 if (secrets.HasStaleKeys)
                 {
                     string message = string.Format(Resources.TraceStaleFunctionSecretRefresh, functionName);
-                    _traceWriter.Verbose(message);
-                    _logger?.LogDebug(message);
+                    _traceWriter.Info(message);
+                    _logger?.LogInformation(message);
                     await RefreshSecretsAsync(secrets, functionName);
                 }
 
@@ -200,6 +206,9 @@ public async virtual Task<IDictionary<string, string>> GetFunctionSecretsAsync(s
                     .ToDictionary(kv => kv.Key, kv => kv.Value);
             }
 
+            _traceWriter.Info(Resources.TraceFunctionsKeysLoaded, functionName);
+            _logger?.LogInformation(Resources.TraceFunctionsKeysLoaded, functionName);
+
             return functionSecrets;
         }
 
@@ -426,8 +435,8 @@ private async Task PersistSecretsAsync<T>(T secrets, string keyScope = null, boo
                 {
                     string message = string.Format(Resources.ErrorTooManySecretBackups, ScriptConstants.MaximumSecretBackupCount, string.IsNullOrEmpty(keyScope) ? "host" : keyScope, await AnalizeSnapshots<T>(secretBackups));
                     TraceEvent traceEvent = new TraceEvent(TraceLevel.Verbose, message);
-                    _traceWriter.Verbose(message);
-                    _logger?.LogDebug(message);
+                    _traceWriter.Info(message);
+                    _logger?.LogInformation(message);
                     throw new InvalidOperationException(message);
                 }
                 await _repository.WriteSnapshotAsync(secretsType, keyScope, secretsContent);
diff --git a/src/WebJobs.Script/ScriptConstants.cs b/src/WebJobs.Script/ScriptConstants.cs
@@ -43,6 +43,7 @@ public static class ScriptConstants
         public const string LogCategoryAdminController = "Host.Controllers.Admin";
         public const string LogCategorySwaggerController = "Host.Controllers.Swagger";
         public const string LogCategoryKeysController = "Host.Controllers.Keys";
+        public const string LogCategoryKeys = "Host.Keys";
         public const string LogCategoryHostGeneral = "Host.General";
 
         // Define all system parameters we inject with a prefix to avoid collisions
diff --git a/test/WebJobs.Script.Tests.Integration/Host/StandbyManagerTests.cs b/test/WebJobs.Script.Tests.Integration/Host/StandbyManagerTests.cs
@@ -95,8 +95,8 @@ public async Task StandbyMode_EndToEnd()
                 TestHelpers.WaitForWebHost(httpClient);
 
                 var traces = traceWriter.GetTraces().ToArray();
-                Assert.Equal($"Creating StandbyMode placeholder function directory ({Path.GetTempPath()}Functions\\Standby\\WWWRoot)", traces[0].Message);
-                Assert.Equal("StandbyMode placeholder function directory created", traces[1].Message);
+                Assert.Equal($"Creating StandbyMode placeholder function directory ({Path.GetTempPath()}Functions\\Standby\\WWWRoot)", traces[1].Message);
+                Assert.Equal("StandbyMode placeholder function directory created", traces[2].Message);
 
                 // issue warmup request and verify
                 var request = new HttpRequestMessage(HttpMethod.Get, "api/warmup");
diff --git a/test/WebJobs.Script.Tests/Security/SecretManagerTests.cs b/test/WebJobs.Script.Tests/Security/SecretManagerTests.cs
@@ -121,7 +121,7 @@ public async Task GetFunctionSecrets_UpdatesStaleSecrets()
 
                 Assert.Equal(2, result.Keys.Count);
                 Assert.True(functionSecretsConverted, "Function secrets were not persisted");
-                Assert.True(traceWriter.GetTraces().Any(t => t.Level == TraceLevel.Verbose && t.Message.IndexOf(expectedTraceMessage) > -1));
+                Assert.True(traceWriter.GetTraces().Any(t => t.Level == TraceLevel.Info && t.Message.IndexOf(expectedTraceMessage) > -1));
             }
         }
 
@@ -245,7 +245,7 @@ public async Task GetFunctionSecrets_WhenNoSecretFileExists_CreatesDefaultSecret
                 Assert.Equal(1, functionSecrets.Count);
                 Assert.Equal(ScriptConstants.DefaultFunctionKeyName, functionSecrets.Keys.First());
                 Assert.True(traceWriter.GetTraces().Any(
-                    t => t.Level == TraceLevel.Verbose && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),
+                    t => t.Level == TraceLevel.Info && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),
                     "Expected Trace message not found");
             }
         }
@@ -578,7 +578,7 @@ public async Task GetFunctiontSecrets_WhenNonDecryptedSecrets_SavesAndRefreshes(
                 Assert.Equal(1, Directory.GetFiles(directory.Path, $"{functionName}.{ScriptConstants.Snapshot}*").Length);
 
                 Assert.True(traceWriter.GetTraces().Any(
-                    t => t.Level == TraceLevel.Verbose && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),
+                    t => t.Level == TraceLevel.Info && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),
                     "Expected Trace message not found");
             }
         }
@@ -645,7 +645,7 @@ public async Task GetHostSecrets_WhenTooManyBackups_ThrowsException()
 
                 Assert.True(Directory.GetFiles(directory.Path, $"{functionName}.{ScriptConstants.Snapshot}*").Length >= ScriptConstants.MaximumSecretBackupCount);
                 Assert.True(traceWriter.GetTraces().Any(
-                    t => t.Level == TraceLevel.Verbose && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),
+                    t => t.Level == TraceLevel.Info && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),
                     "Expected Trace message not found");
             }
         }

Original file line number	Diff line number	Diff line change
`@@ -182,8 +182,8 @@ private async Task<IHttpActionResult> AddOrUpdateSecretAsync(string keyName, str`
`182`	`182`	`}`
`183`	`183`
`184`	`184`	`string message = string.Format(Resources.TraceKeysApiSecretChange, keyName, keyScope ?? "host", operationResult.Result);`
`185`		`- _traceWriter.Verbose(message);`
`186`		`- _logger?.LogDebug(message);`
	`185`	`+ _traceWriter.Info(message);`
	`186`	`+ _logger?.LogInformation(message);`
`187`	`187`
`188`	`188`	`switch (operationResult.Result)`
`189`	`189`	`{`
`@@ -248,8 +248,8 @@ private async Task<IHttpActionResult> DeleteFunctionSecretAsync(string keyName,`
`248`	`248`	`}`
`249`	`249`
`250`	`250`	`string message = string.Format(Resources.TraceKeysApiSecretChange, keyName, keyScope ?? "host", "Deleted");`
`251`		`- _traceWriter.VerboseFormat(message);`
`252`		`- _logger?.LogDebug(message);`
	`251`	`+ _traceWriter.Info(message);`
	`252`	`+ _logger?.LogInformation(message);`
`253`	`253`
`254`	`254`	`return StatusCode(HttpStatusCode.NoContent);`
`255`	`255`	`}`
Original file line number	Diff line number	Diff line change
`@@ -43,14 +43,17 @@ public SecretManager(ISecretsRepository repository, IKeyValueConverterFactory ke`
`43`	`43`	`_keyValueConverterFactory = keyValueConverterFactory;`
`44`	`44`	`_traceWriter = traceWriter;`
`45`	`45`	`_repository.SecretsChanged += OnSecretsChanged;`
`46`		`- _logger = loggerFactory?.CreateLogger(ScriptConstants.LogCategoryHostGeneral);`
	`46`	`+ _logger = loggerFactory?.CreateLogger(ScriptConstants.LogCategoryKeys);`
`47`	`47`
`48`	`48`	`if (createHostSecretsIfMissing)`
`49`	`49`	`{`
`50`	`50`	`// The SecretManager implementation of GetHostSecrets will`
`51`	`51`	`// create a host secret if one is not present.`
`52`	`52`	`GetHostSecretsAsync().GetAwaiter().GetResult();`
`53`	`53`	`}`
	`54`	`+`
	`55`	`+ _traceWriter.Info(Resources.TraceSecretsRepo, repository.ToString());`
	`56`	`+ _logger?.LogInformation(Resources.TraceSecretsRepo, repository.ToString());`
`54`	`57`	`}`
`55`	`58`
`56`	`59`	`public void Dispose()`
`@@ -124,6 +127,9 @@ public async virtual Task<HostSecretsInfo> GetHostSecretsAsync()`
`124`	`127`	`}`
`125`	`128`	`}`
`126`	`129`
	`130`	`+ _traceWriter.Info(Resources.TraceHostKeysLoaded);`
	`131`	`+ _logger?.LogInformation(Resources.TraceHostKeysLoaded);`
	`132`	`+`
`127`	`133`	`return _hostSecrets;`
`128`	`134`	`}`
`129`	`135`
`@@ -148,9 +154,9 @@ public async virtual Task<IDictionary<string, string>> GetFunctionSecretsAsync(s`
`148`	`154`	`{`
`149`	`155`	`// no secrets exist for this function so generate them`
`150`	`156`	`string message = string.Format(Resources.TraceFunctionSecretGeneration, functionName);`
`151`		`- _traceWriter.Verbose(message, traceProperties);`
	`157`	`+ _traceWriter.Info(message, traceProperties);`
`152`	`158`
`153`		`- _logger?.LogDebug(message);`
	`159`	`+ _logger?.LogInformation(message);`
`154`	`160`	`secrets = new FunctionSecrets`
`155`	`161`	`{`
`156`	`162`	`Keys = new List<Key>`
`@@ -170,17 +176,17 @@ public async virtual Task<IDictionary<string, string>> GetFunctionSecretsAsync(s`
`170`	`176`	`catch (CryptographicException)`
`171`	`177`	`{`
`172`	`178`	`string message = string.Format(Resources.TraceNonDecryptedFunctionSecretRefresh, functionName);`
`173`		`- _traceWriter.Verbose(message, traceProperties);`
`174`		`- _logger?.LogDebug(message);`
	`179`	`+ _traceWriter.Info(message, traceProperties);`
	`180`	`+ _logger?.LogInformation(message);`
`175`	`181`	`await PersistSecretsAsync(secrets, functionName, true);`
`176`	`182`	`await RefreshSecretsAsync(secrets, functionName);`
`177`	`183`	`}`
`178`	`184`
`179`	`185`	`if (secrets.HasStaleKeys)`
`180`	`186`	`{`
`181`	`187`	`string message = string.Format(Resources.TraceStaleFunctionSecretRefresh, functionName);`
`182`		`- _traceWriter.Verbose(message);`
`183`		`- _logger?.LogDebug(message);`
	`188`	`+ _traceWriter.Info(message);`
	`189`	`+ _logger?.LogInformation(message);`
`184`	`190`	`await RefreshSecretsAsync(secrets, functionName);`
`185`	`191`	`}`
`186`	`192`
`@@ -200,6 +206,9 @@ public async virtual Task<IDictionary<string, string>> GetFunctionSecretsAsync(s`
`200`	`206`	`.ToDictionary(kv => kv.Key, kv => kv.Value);`
`201`	`207`	`}`
`202`	`208`
	`209`	`+ _traceWriter.Info(Resources.TraceFunctionsKeysLoaded, functionName);`
	`210`	`+ _logger?.LogInformation(Resources.TraceFunctionsKeysLoaded, functionName);`
	`211`	`+`
`203`	`212`	`return functionSecrets;`
`204`	`213`	`}`
`205`	`214`
`@@ -426,8 +435,8 @@ private async Task PersistSecretsAsync<T>(T secrets, string keyScope = null, boo`
`426`	`435`	`{`
`427`	`436`	`string message = string.Format(Resources.ErrorTooManySecretBackups, ScriptConstants.MaximumSecretBackupCount, string.IsNullOrEmpty(keyScope) ? "host" : keyScope, await AnalizeSnapshots<T>(secretBackups));`
`428`	`437`	`TraceEvent traceEvent = new TraceEvent(TraceLevel.Verbose, message);`
`429`		`- _traceWriter.Verbose(message);`
`430`		`- _logger?.LogDebug(message);`
	`438`	`+ _traceWriter.Info(message);`
	`439`	`+ _logger?.LogInformation(message);`
`431`	`440`	`throw new InvalidOperationException(message);`
`432`	`441`	`}`
`433`	`442`	`await _repository.WriteSnapshotAsync(secretsType, keyScope, secretsContent);`
Original file line number	Diff line number	Diff line change
`@@ -121,7 +121,7 @@ public async Task GetFunctionSecrets_UpdatesStaleSecrets()`
`121`	`121`
`122`	`122`	`Assert.Equal(2, result.Keys.Count);`
`123`	`123`	`Assert.True(functionSecretsConverted, "Function secrets were not persisted");`
`124`		`- Assert.True(traceWriter.GetTraces().Any(t => t.Level == TraceLevel.Verbose && t.Message.IndexOf(expectedTraceMessage) > -1));`
	`124`	`+ Assert.True(traceWriter.GetTraces().Any(t => t.Level == TraceLevel.Info && t.Message.IndexOf(expectedTraceMessage) > -1));`
`125`	`125`	`}`
`126`	`126`	`}`
`127`	`127`
`@@ -245,7 +245,7 @@ public async Task GetFunctionSecrets_WhenNoSecretFileExists_CreatesDefaultSecret`
`245`	`245`	`Assert.Equal(1, functionSecrets.Count);`
`246`	`246`	`Assert.Equal(ScriptConstants.DefaultFunctionKeyName, functionSecrets.Keys.First());`
`247`	`247`	`Assert.True(traceWriter.GetTraces().Any(`
`248`		`- t => t.Level == TraceLevel.Verbose && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),`
	`248`	`+ t => t.Level == TraceLevel.Info && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),`
`249`	`249`	`"Expected Trace message not found");`
`250`	`250`	`}`
`251`	`251`	`}`
`@@ -578,7 +578,7 @@ public async Task GetFunctiontSecrets_WhenNonDecryptedSecrets_SavesAndRefreshes(`
`578`	`578`	`Assert.Equal(1, Directory.GetFiles(directory.Path, $"{functionName}.{ScriptConstants.Snapshot}*").Length);`
`579`	`579`
`580`	`580`	`Assert.True(traceWriter.GetTraces().Any(`
`581`		`- t => t.Level == TraceLevel.Verbose && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),`
	`581`	`+ t => t.Level == TraceLevel.Info && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),`
`582`	`582`	`"Expected Trace message not found");`
`583`	`583`	`}`
`584`	`584`	`}`
`@@ -645,7 +645,7 @@ public async Task GetHostSecrets_WhenTooManyBackups_ThrowsException()`
`645`	`645`
`646`	`646`	`Assert.True(Directory.GetFiles(directory.Path, $"{functionName}.{ScriptConstants.Snapshot}*").Length >= ScriptConstants.MaximumSecretBackupCount);`
`647`	`647`	`Assert.True(traceWriter.GetTraces().Any(`
`648`		`- t => t.Level == TraceLevel.Verbose && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),`
	`648`	`+ t => t.Level == TraceLevel.Info && t.Message.IndexOf(expectedTraceMessage, StringComparison.OrdinalIgnoreCase) > -1),`
`649`	`649`	`"Expected Trace message not found");`
`650`	`650`	`}`
`651`	`651`	`}`