Fixing broken logging

Author: mathewc

src/WebJobs.Script.WebHost/Management/FunctionsSyncManager.cs

@@ -38,13 +38,15 @@ public sealed class FunctionsSyncManager : IFunctionsSyncManager, IDisposable
         private readonly bool _ownsHttpClient;
         private readonly ScriptSettingsManager _settings;
         private readonly SemaphoreSlim _syncSemaphore = new SemaphoreSlim(1, 1);
+        private readonly TraceWriter _traceWriter;
 
         private CloudBlockBlob _hashBlob;
 
         public FunctionsSyncManager(ScriptHostConfiguration hostConfig, ILoggerFactory loggerFactory, ISecretManager secretManager, ScriptSettingsManager settings, HttpClient httpClient = null)
         {
             _hostConfig = hostConfig;
-            _logger = loggerFactory.CreateLogger(ScriptConstants.LogCategoryHostGeneral);
+            _logger = loggerFactory.CreateLogger<FunctionsSyncManager>();
+            _traceWriter = hostConfig.TraceWriter.WithDefaults(typeof(FunctionsSyncManager).FullName);
             _secretManager = secretManager;
             _settings = settings;
 
@@ -76,6 +78,7 @@ public async Task<SyncTriggersResult> TrySyncTriggersAsync(bool checkHash = fals
                 result.Success = false;
                 result.Error = "Invalid environment for SyncTriggers operation.";
                 _logger.LogWarning(result.Error);
+                _traceWriter.Warning(result.Error);
                 return result;
             }
 
@@ -119,6 +122,7 @@ public async Task<SyncTriggersResult> TrySyncTriggersAsync(bool checkHash = fals
                 result.Success = false;
                 result.Error = "SyncTriggers operation failed.";
                 _logger.LogError(0, ex, result.Error);
+                _traceWriter.Error(result.Error, ex);
             }
             finally
             {
@@ -171,7 +175,9 @@ internal async Task<string> CheckHashAsync(CloudBlockBlob hashBlob, string conte
                 if (await hashBlob.ExistsAsync())
                 {
                     lastHash = await hashBlob.DownloadTextAsync();
-                    _logger.LogDebug($"SyncTriggers hash (Last='{lastHash}', Current='{currentHash}')");
+                    string message = $"SyncTriggers hash (Last='{lastHash}', Current='{currentHash}')";
+                    _logger.LogDebug(message);
+                    _traceWriter.Verbose(message);
                 }
 
                 if (string.Compare(currentHash, lastHash) != 0)
@@ -184,7 +190,9 @@ internal async Task<string> CheckHashAsync(CloudBlockBlob hashBlob, string conte
             catch (Exception ex)
             {
                 // best effort
-                _logger.LogError(0, ex, "Error checking SyncTriggers hash");
+                string error = "Error checking SyncTriggers hash";
+                _logger.LogError(0, ex, error);
+                _traceWriter.Error(error, ex);
             }
 
             // if the last and current hash values are the same,
@@ -199,12 +207,16 @@ internal async Task UpdateHashAsync(CloudBlockBlob hashBlob, string hash)
                 // hash value has changed or was not yet stored
                 // update the last hash value in storage
                 await hashBlob.UploadTextAsync(hash);
-                _logger.LogDebug($"SyncTriggers hash updated to '{hash}'");
+                string message = $"SyncTriggers hash updated to '{hash}'";
+                _logger.LogDebug(message);
+                _traceWriter.Verbose(message);
             }
             catch (Exception ex)
             {
                 // best effort
-                _logger.LogError(0, ex, "Error updating SyncTriggers hash");
+                string error = "Error updating SyncTriggers hash";
+                _logger.LogError(0, ex, error);
+                _traceWriter.Error(error, ex);
             }
         }
 
@@ -298,7 +310,9 @@ public async Task<string> GetSyncTriggersPayload()
                 // The settriggers call to the FE enforces a max request size
                 // limit. If we're over limit, revert to the minimal triggers
                 // format.
-                _logger.LogWarning($"SyncTriggers payload of length '{json.Length}' exceeds max length of '{ScriptConstants.MaxTriggersStringLength}'. Reverting to minimal format.");
+                string warning = $"SyncTriggers payload of length '{json.Length}' exceeds max length of '{ScriptConstants.MaxTriggersStringLength}'. Reverting to minimal format.";
+                _logger.LogWarning(warning);
+                _traceWriter.Warning(warning);
                 return JsonConvert.SerializeObject(triggersArray);
             }
 
@@ -428,18 +442,23 @@ internal static HttpRequestMessage BuildSetTriggersRequest()
                 request.Headers.Add("x-ms-site-restricted-token", token);
                 request.Content = new StringContent(content, Encoding.UTF8, "application/json");
 
-                _logger.LogDebug($"Making SyncTriggers request (RequestId={requestId}, Uri={request.RequestUri.ToString()}, Content={sanitizedContentString}).");
+                string message = $"Making SyncTriggers request (RequestId={requestId}, Uri={request.RequestUri.ToString()}, Content={sanitizedContentString}).";
+                _logger.LogDebug(message);
+                _traceWriter.Verbose(message);
 
                 var response = await _httpClient.SendAsync(request);
                 if (response.IsSuccessStatusCode)
                 {
-                    _logger.LogDebug($"SyncTriggers call succeeded.");
+                    message = $"SyncTriggers call succeeded.";
+                    _logger.LogDebug(message);
+                    _traceWriter.Verbose(message);
                     return (true, null);
                 }
                 else
                 {
-                    string message = $"SyncTriggers call failed (StatusCode={response.StatusCode}).";
+                    message = $"SyncTriggers call failed (StatusCode={response.StatusCode}).";
                     _logger.LogDebug(message);
+                    _traceWriter.Verbose(message);
                     return (false, message);
                 }
             }

src/WebJobs.Script/ScriptConstants.cs

@@ -108,6 +108,6 @@ public static class ScriptConstants
         /// This constant is also defined in Antares, where the limit is ultimately enforced
         /// for settriggers calls. If we raise that limit there, we should raise here as well.
         /// </summary>
-        public const int MaxTriggersStringLength = 102400;
+        public const int MaxTriggersStringLength = 204800;
     }
 }

test/WebJobs.Script.Tests/Management/FunctionsSyncManagerTests.cs

@@ -3,6 +3,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.IO;
 using System.IO.Abstractions;
 using System.Linq;
@@ -29,6 +30,7 @@ public class FunctionsSyncManagerTests : IDisposable
         private readonly string _testRootScriptPath;
         private readonly string _testHostConfigFilePath;
         private readonly ScriptHostConfiguration _hostConfig;
+        private readonly TestTraceWriter _traceWriter;
         private readonly FunctionsSyncManager _functionsSyncManager;
         private readonly Dictionary<string, string> _vars;
         private readonly StringBuilder _contentBuilder;
@@ -40,6 +42,7 @@ public class FunctionsSyncManagerTests : IDisposable
 
         public FunctionsSyncManagerTests()
         {
+            _traceWriter = new TestTraceWriter(TraceLevel.Verbose);
             _testRootScriptPath = Path.GetTempPath();
             _testHostConfigFilePath = Path.Combine(_testRootScriptPath, ScriptConstants.HostMetadataFileName);
             FileUtility.DeleteFileSafe(_testHostConfigFilePath);
@@ -49,7 +52,8 @@ public FunctionsSyncManagerTests()
                 RootScriptPath = @"x:\root\site\wwwroot",
                 IsSelfHost = false,
                 RootLogPath = @"x:\root\LogFiles\Application\Functions",
-                TestDataPath = @"x:\root\data\functions\sampledata"
+                TestDataPath = @"x:\root\data\functions\sampledata",
+                TraceWriter = _traceWriter
             };
             _hostConfig.HostConfig.HostId = "testhostid123";
 
@@ -438,6 +442,31 @@ public void Use_Website_Name_If_Website_Hostname_Is_Not_Available(string envKey,
             }
         }
 
+        [Fact]
+        public async Task Logging_ConfiguredCorrectly()
+        {
+            _scriptSettingsManagerMock.Setup(p => p.GetSetting(EnvironmentSettingNames.AzureWebsiteArmCacheEnabled)).Returns("1");
+
+            using (var env = new TestScopedEnvironmentVariable(_vars))
+            {
+                var syncResult = await _functionsSyncManager.TrySyncTriggersAsync();
+                Assert.True(syncResult.Success, "SyncTriggers should return success true");
+
+                var logs = _loggerProvider.GetAllLogMessages();
+                var log = logs.First();
+                int startIdx = log.FormattedMessage.IndexOf("Content=") + 8;
+                int endIdx = log.FormattedMessage.LastIndexOf(')');
+                var triggersLog = log.FormattedMessage.Substring(startIdx, endIdx - startIdx).Trim();
+                var logObject = JObject.Parse(triggersLog);
+
+                // just verifying here that we're logging to both loggers, to ensure
+                // we're writing system logs
+                var trace = _traceWriter.GetTraces().First();
+                Assert.Equal(log.FormattedMessage, trace.Message);
+                Assert.Equal(log.Category, trace.Source);
+            }
+        }
+
         private static HttpClient CreateHttpClient(MockHttpHandler httpHandler)
         {
             return new HttpClient(httpHandler);