Search: Extend telemetry information (#6967)

Extend the telemetry information

Author: cristinamanum

src/NuGetGallery/Infrastructure/Lucene/HttpClientWrapper.cs

@@ -4,6 +4,8 @@
 using System;
 using System.Net.Http;
 using System.Threading.Tasks;
+using NuGetGallery.Infrastructure.Search;
+using Polly;
 
 namespace NuGetGallery.Infrastructure
 {
@@ -18,9 +20,18 @@ public HttpClientWrapper(HttpClient httpClient)
 
         public Uri BaseAddress => _httpClient.BaseAddress;
 
-        public Task<HttpResponseMessage> GetAsync(Uri uri)
+        public async Task<HttpResponseMessage> GetAsync(Uri uri)
         {
-            return _httpClient.GetAsync(uri);
+            // Add the request Uri to the  Polly context to be used for logging.
+            // https://docs.microsoft.com/en-us/dotnet/api/polly.httprequestmessageextensions.setpolicyexecutioncontext?view=aspnetcore-2.2
+            // http://www.thepollyproject.org/2017/05/04/putting-the-context-into-polly/ 
+            using (var request = new HttpRequestMessage(HttpMethod.Get, uri))
+            {
+                var context = new Context();
+                context.Add(SearchClientPolicies.ContextKey_RequestUri, uri.AbsoluteUri);
+                request.SetPolicyExecutionContext(context);
+                return await _httpClient.SendAsync(request);
+            }
         }
     }
 }

src/NuGetGallery/Infrastructure/Lucene/SearchClientPolicies.cs

@@ -9,16 +9,20 @@
 using Polly;
 using Polly.CircuitBreaker;
 using Polly.Extensions.Http;
-using NuGetGallery;
 
 namespace NuGetGallery.Infrastructure.Search
 {
     // Implements Polly policies 
     // Samples at https://github.com/App-vNext/Polly-Samples
+    // Docs: https://github.com/App-vNext/Polly/wiki/Circuit-Breaker
     public class SearchClientPolicies
     {
+        internal const string ContextKey_RequestUri = "RequestUri";
+        internal const string ContextKey_CircuitBreakerStatus = "CircuitBreakerStatus";
+
         /// <summary>
-        /// Builds the CircuitBreakerPolicy. Through this policy a request will be retried for <paramref name="breakAfterCount"/> and break after. This will move the circuit breaker into Open state. 
+        /// Builds the CircuitBreakerPolicy. Through this policy if <paramref name="breakAfterCount"/> consecutive requests will fail with transient HttpErrors
+        /// the circuit breaker will move into Open state. 
         /// It will stay in this state(Open) for the <paramref name="breakDuration"/>. This means that requests made while the circuit is in this state will fail fast.
         /// When the timeout expires trial requsts are allowed. The state will be changed to a Close state if they succeed.
         /// If they do not succeed the circuit will be moved back in the Open state for another <paramref name="breakDuration"/>. 
@@ -35,17 +39,18 @@ public static IAsyncPolicy<HttpResponseMessage> SearchClientCircuitBreakerPolicy
                 .HandleTransientHttpError()
                 .CircuitBreakerAsync(breakAfterCount,
                 breakDuration,
-                onBreak: (delegateResult, breakDelay, context) =>
+                onBreak: (delegateResult, circuitBreakerStatus, breakDelay, context) =>
                 {
-                    telemetryService.TrackMetricForSearchCircuitBreakerOnBreak(searchName, delegateResult.Exception, delegateResult.Result);
+                    context.Add(ContextKey_CircuitBreakerStatus, circuitBreakerStatus);
+                    telemetryService.TrackMetricForSearchCircuitBreakerOnBreak(searchName, delegateResult.Exception, delegateResult.Result, context.CorrelationId.ToString(), GetValueFromContext("RequestUri",context));
                     logger.LogWarning("SearchCircuitBreaker logging: Breaking the circuit for {BreakDelayInMilliseconds} milliseconds due to {Exception} {SearchName}.",
                         breakDelay.TotalMilliseconds,
                         delegateResult.Exception,
                         searchName);
                 },
                 onReset: (context) =>
                 {
-                    telemetryService.TrackMetricForSearchCircuitBreakerOnReset(searchName);
+                    telemetryService.TrackMetricForSearchCircuitBreakerOnReset(searchName, context.CorrelationId.ToString(), GetValueFromContext("RequestUri", context));
                     logger.LogInformation("SearchCircuitBreaker logging: Call ok! Closed the circuit again! {SearchName}", searchName);
                 },
                 onHalfOpen: () => logger.LogInformation("SearchCircuitBreaker logging: Half-open: Next call is a trial! {SearchName}", searchName));
@@ -69,10 +74,14 @@ public static IAsyncPolicy<HttpResponseMessage> SearchClientWaitAndRetryForeverP
                                 return false;
                             }).
                         WaitAndRetryForeverAsync(
-                            sleepDurationProvider: retryAttempt => TimeSpan.FromMilliseconds(SearchClientConfiguration.WaitAndRetryDefaultIntervalInMilliseconds), 
-                            onRetry: (delegateResult, waitDuration) =>
+                            sleepDurationProvider: (retryAttempt, context) => TimeSpan.FromMilliseconds(SearchClientConfiguration.WaitAndRetryDefaultIntervalInMilliseconds),
+                            onRetry: (delegateResult, waitDuration, context) =>
                                     {
-                                        telemetryService.TrackMetricForSearchOnRetry(searchName, delegateResult.Exception);
+                                        telemetryService.TrackMetricForSearchOnRetry(searchName,
+                                            delegateResult.Exception,
+                                            context.CorrelationId.ToString(),
+                                            GetValueFromContext(ContextKey_RequestUri, context),
+                                            GetValueFromContext(ContextKey_CircuitBreakerStatus, context));
                                         logger.LogInformation("Policy retry - it will retry after {RetryMilliseconds} milliseconds. {Exception} {SearchName}", waitDuration.TotalMilliseconds, delegateResult.Exception, searchName);
                                     });
         }
@@ -101,5 +110,11 @@ public static IAsyncPolicy<HttpResponseMessage> SearchClientFallBackCircuitBreak
                                     logger.LogInformation("On circuit breaker fallback. {SearchName} {Exception} {Result}", searchName, delegateResult.Exception, delegateResult.Result);
                                 });
         }
+
+        private static string GetValueFromContext(string contextKey, Context context)
+        {
+            object objValue = null;
+            return context.TryGetValue(contextKey, out objValue) ? objValue.ToString() : string.Empty;
+        }
     }
 }

src/NuGetGallery/Services/ITelemetryService.cs

@@ -272,20 +272,26 @@ void TrackMetricForTyposquattingCheckResultAndTotalTime(
         /// <param name="searchName">A name to identify the search instance.</param>
         /// <param name="exception">The exception if any.</param>
         /// <param name="responseMessage">The response message.</param>
-        void TrackMetricForSearchCircuitBreakerOnBreak(string searchName, Exception exception, HttpResponseMessage responseMessage);
+        /// <param name="correlationId">CorrelationId set by Polly context.</param>
+        /// <param name="uri">The request uri.</param>
+        void TrackMetricForSearchCircuitBreakerOnBreak(string searchName, Exception exception, HttpResponseMessage responseMessage, string correlationId, string uri);
 
         /// <summary>
         /// Tracks the OnReset for the search circuit breaker.
         /// </summary>
         /// <param name="searchName">A name to identify the search instance.</param>
-        void TrackMetricForSearchCircuitBreakerOnReset(string searchName);
+        /// <param name="correlationId">CorrelationId set by Polly context.</param>
+        /// <param name="uri">The request uri.</param>
+        void TrackMetricForSearchCircuitBreakerOnReset(string searchName, string correlationId, string uri);
 
         /// <summary>
         /// Tracks the OnRetry for the search retry policy.
         /// </summary>
         /// <param name="searchName">A name to identify the search instance.</param>
         /// <param name="exception">The exception.</param>
-        /// <param name=""></param>
-        void TrackMetricForSearchOnRetry(string searchName, Exception exception);
+        /// <param name="correlationId">CorrelationId set by Polly context.</param>
+        /// <param name="uri">The request uri.</param>
+        /// <param name="circuitBreakerStatus">The CircuitBreakerStatus at the time of the Retry action.</param>
+        void TrackMetricForSearchOnRetry(string searchName, Exception exception, string correlationId, string uri, string circuitBreakerStatus);
     }
 }

src/NuGetGallery/Services/TelemetryService.cs

@@ -173,6 +173,8 @@ internal class Events
         public const string SearchSuccessExecutionStatus = "SearchSuccessExecutionStatus";
         public const string SearchException = "SearchException";
         public const string SearchName = "SearchName";
+        public const string SearchPollyCorrelationId = "SearchPollyCorrelationId";
+        public const string SearchCircuitBreakerStatus = "SearchCircuitBreakerStatus";
 
         public TelemetryService(IDiagnosticsService diagnosticsService, ITelemetryClient telemetryClient = null)
         {
@@ -803,27 +805,34 @@ public void TrackMetricForSearchExecutionDuration(string url, TimeSpan duration,
             });
         }
 
-        public void TrackMetricForSearchCircuitBreakerOnBreak(string searchName, Exception exception, HttpResponseMessage responseMessage)
+        public void TrackMetricForSearchCircuitBreakerOnBreak(string searchName, Exception exception, HttpResponseMessage responseMessage, string correlationId, string uri)
         {
             TrackMetric(Events.SearchCircuitBreakerOnBreak, 1, properties => {
                 properties.Add(SearchName, searchName);
                 properties.Add(SearchException, exception?.ToString() ?? string.Empty);
                 properties.Add(SearchHttpResponseCode, responseMessage?.StatusCode.ToString() ?? string.Empty);
+                properties.Add(SearchPollyCorrelationId, correlationId);
+                properties.Add(SearchUrl, uri);
             });
         }
 
-        public void TrackMetricForSearchCircuitBreakerOnReset(string searchName)
+        public void TrackMetricForSearchCircuitBreakerOnReset(string searchName, string correlationId, string uri)
         {
             TrackMetric(Events.SearchCircuitBreakerOnReset, 1, properties => {
                 properties.Add(SearchName, searchName);
+                properties.Add(SearchPollyCorrelationId, correlationId);
+                properties.Add(SearchUrl, uri);
             });
         }
 
-        public void TrackMetricForSearchOnRetry(string searchName, Exception exception)
+        public void TrackMetricForSearchOnRetry(string searchName, Exception exception, string correlationId, string uri, string circuitBreakerStatus)
         {
             TrackMetric(Events.SearchOnRetry, 1, properties => {
                 properties.Add(SearchName, searchName);
                 properties.Add(SearchException, exception?.ToString() ?? string.Empty);
+                properties.Add(SearchPollyCorrelationId, correlationId);
+                properties.Add(SearchUrl, uri);
+                properties.Add(SearchCircuitBreakerStatus, circuitBreakerStatus);
             });
         }
         /// <summary>

tests/NuGetGallery.Facts/Services/TelemetryServiceFacts.cs

@@ -259,15 +259,15 @@ public static IEnumerable<object[]> TrackMetricNames_Data
                     };
 
                     yield return new object[] { "SearchCircuitBreakerOnBreak",
-                        (TrackAction)(s => s.TrackMetricForSearchCircuitBreakerOnBreak("SomeName", exception: null, responseMessage: null))
+                        (TrackAction)(s => s.TrackMetricForSearchCircuitBreakerOnBreak("SomeName", exception: null, responseMessage: null, correlationId: string.Empty, uri: string.Empty))
                     };
 
                     yield return new object[] { "SearchCircuitBreakerOnReset",
-                        (TrackAction)(s => s.TrackMetricForSearchCircuitBreakerOnReset("SomeName"))
+                        (TrackAction)(s => s.TrackMetricForSearchCircuitBreakerOnReset("SomeName", correlationId: string.Empty, uri: string.Empty))
                     };
 
                     yield return new object[] { "SearchOnRetry",
-                        (TrackAction)(s => s.TrackMetricForSearchOnRetry("SomeName", exception: null))
+                        (TrackAction)(s => s.TrackMetricForSearchOnRetry("SomeName", exception: null, correlationId: string.Empty, uri: string.Empty, circuitBreakerStatus: string.Empty))
                     };
                 }
             }