SyncTriggers improvements #4401

Author: mathewc

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

@@ -413,15 +413,17 @@ internal static HttpRequestMessage BuildSetTriggersRequest()
                 sanitizedContent.Remove("secrets");
                 sanitizedContentString = sanitizedContent.ToString();
             }
-            _logger.LogDebug($"SyncTriggers content: {sanitizedContentString}");
 
             using (var request = BuildSetTriggersRequest())
             {
-                // This has to start with Mozilla because the frontEnd checks for it.
-                request.Headers.Add("User-Agent", "Mozilla/5.0");
+                var requestId = Guid.NewGuid().ToString();
+                request.Headers.Add(ScriptConstants.AntaresLogIdHeaderName, requestId);
+                request.Headers.Add("User-Agent", ScriptConstants.FunctionsUserAgent);
                 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}).");
+
                 var response = await _httpClient.SendAsync(request);
                 if (response.IsSuccessStatusCode)
                 {
@@ -430,7 +432,7 @@ internal static HttpRequestMessage BuildSetTriggersRequest()
                 }
                 else
                 {
-                    string message = $"SyncTriggers call failed. StatusCode={response.StatusCode}";
+                    string message = $"SyncTriggers call failed (StatusCode={response.StatusCode}).";
                     _logger.LogDebug(message);
                     return (false, message);
                 }

src/WebJobs.Script/ScriptConstants.cs

@@ -71,6 +71,7 @@ public static class ScriptConstants
         public const string DynamicSku = "Dynamic";
         public const string DefaultProductionSlotName = "production";
 
+        public const string FunctionsUserAgent = "AzureFunctionsRuntime";
         public const string AntaresDefaultHostNameHeader = "WAS-DEFAULT-HOSTNAME";
         public const string AzureProxyFunctionLocalRedirectHeaderName = "X-PROXY-LOCAL-REDIRECT-COUNT";
         public const int AzureProxyFunctionMaxLocalRedirects = 10;

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

@@ -209,6 +209,10 @@ public async Task TrySyncTriggers_PostsExpectedContent(bool cacheEnabled)
                 Assert.True(syncResult.Success, "SyncTriggers should return success true");
                 Assert.True(string.IsNullOrEmpty(syncResult.Error), "Error should be null or empty");
 
+                // verify expected headers
+                Assert.Equal(ScriptConstants.FunctionsUserAgent, _mockHttpHandler.LastRequest.Headers.UserAgent.ToString());
+                Assert.True(_mockHttpHandler.LastRequest.Headers.Contains(ScriptConstants.AntaresLogIdHeaderName));
+
                 if (cacheEnabled)
                 {
                     // verify triggers
@@ -253,8 +257,9 @@ public async Task TrySyncTriggers_PostsExpectedContent(bool cacheEnabled)
 
                     var logs = _loggerProvider.GetAllLogMessages();
                     var log = logs.First();
-                    int idx = log.FormattedMessage.IndexOf(':');
-                    var triggersLog = log.FormattedMessage.Substring(idx + 1).Trim();
+                    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);
 
                     Assert.Equal(_expectedSyncTriggersPayload, logObject["triggers"].ToString(Formatting.None));
@@ -267,8 +272,9 @@ public async Task TrySyncTriggers_PostsExpectedContent(bool cacheEnabled)
 
                     var logs = _loggerProvider.GetAllLogMessages();
                     var log = logs.First();
-                    int idx = log.FormattedMessage.IndexOf(':');
-                    var triggersLog = log.FormattedMessage.Substring(idx + 1).Trim();
+                    int startIdx = log.FormattedMessage.IndexOf("Content=") + 8;
+                    int endIdx = log.FormattedMessage.LastIndexOf(')');
+                    var triggersLog = log.FormattedMessage.Substring(startIdx, endIdx - startIdx).Trim();
                     Assert.Equal(_expectedSyncTriggersPayload, triggersLog);
                 }
             }
@@ -294,9 +300,10 @@ public async Task TrySyncTriggers_CheckHash_PostsExpectedContent()
 
                 // verify log statements
                 var logMessages = _loggerProvider.GetAllLogMessages().Select(p => p.FormattedMessage).ToArray();
-                Assert.True(logMessages[0].StartsWith("SyncTriggers content: {"));
-                var idx = logMessages[0].IndexOf('{');
-                var sanitizedContent = logMessages[0].Substring(idx);
+                Assert.True(logMessages[0].StartsWith("Making SyncTriggers request"));
+                var startIdx = logMessages[0].IndexOf("Content=") + 8;
+                var endIdx = logMessages[0].LastIndexOf(')');
+                var sanitizedContent = logMessages[0].Substring(startIdx, endIdx - startIdx);
                 var sanitizedObject = JObject.Parse(sanitizedContent);
                 JToken value = null;
                 var secretsLogged = sanitizedObject.TryGetValue("secrets", out value);
@@ -339,7 +346,7 @@ public async Task TrySyncTriggers_CheckHash_SetTriggersFailure_HashNotUpdated()
                 _mockHttpHandler.MockStatusCode = HttpStatusCode.InternalServerError;
                 var syncResult = await _functionsSyncManager.TrySyncTriggersAsync(checkHash: true);
                 Assert.False(syncResult.Success);
-                string expectedErrorMessage = "SyncTriggers call failed. StatusCode=InternalServerError";
+                string expectedErrorMessage = "SyncTriggers call failed (StatusCode=InternalServerError).";
                 Assert.Equal(expectedErrorMessage, syncResult.Error);
                 Assert.Equal(1, _mockHttpHandler.RequestCount);
                 var result = JObject.Parse(_contentBuilder.ToString());
@@ -350,7 +357,7 @@ public async Task TrySyncTriggers_CheckHash_SetTriggersFailure_HashNotUpdated()
 
                 // verify log statements
                 var logMessages = _loggerProvider.GetAllLogMessages().Select(p => p.FormattedMessage).ToArray();
-                Assert.True(logMessages[0].StartsWith("SyncTriggers content: {"));
+                Assert.True(logMessages[0].Contains("Content="));
                 Assert.Equal(expectedErrorMessage, logMessages[1]);
             }
         }
@@ -553,15 +560,19 @@ public MockHttpHandler(StringBuilder content)
 
             public HttpStatusCode MockStatusCode { get; set; }
 
+            public HttpRequestMessage LastRequest { get; set; }
+
             protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
             {
+                LastRequest = request;
                 RequestCount++;
                 _content.Append(await request.Content.ReadAsStringAsync());
                 return new HttpResponseMessage(MockStatusCode);
             }
 
             public void Reset()
             {
+                LastRequest = null;
                 _content.Clear();
                 RequestCount = 0;
             }