Http request instrumentation with Activity (correlation part2)

src/System.Net.Http/src/HttpDiagnosticsGuide.md

@@ -0,0 +1,109 @@
+# HttpClient Diagnostic  Instrumentation Users Guide
+
+This document describes `HttpClientHandler` instrumentation with [DiagnosticSource](https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.DiagnosticSource/src/DiagnosticSourceUsersGuide.md).
+
+# Overview
+Applications typically log outgoing HTTP requests; typically it's done with DelegatingHandler implementation that logs every request. However in existing system it may require extensive code changes, since DelegatingHandler needs to be added to HttpClient pipeline every time when new client is created.
+DiagnosticListener instrumentation allows to enable outgoing request tracing with a few lines of code; it also provides context necessary to correlate logs.
+
+Context is represented as `System.Diagnostics.Activity` class. Activity may be started as a child of another Activity and the whole operation is represented with a tree of Activities. You can find more details in [Activity User Guide](https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.DiagnosticSource/src/ActivityUserGuide.md).
+
+Activity carries useful properties for logging such as Id, start time, Tags, Baggage and parent information. 
+
+Instrumentation ensures `Activity.Current` represents current outgoing request in Write event callbacks (if request is instrumented). Consumers **should not** assume `Activity.Current` is accurate in IsEnabled callbacks.
+
+In microservice environment some context should flow with outgoing requests to correlate telemtry from all services involved in operation processing.
+Instrumentation adds context into the request headers: 
+ * Request-Id header with `Activity.Id` value
+ * Correlation-Context header with `Activity.Baggage` key-value pair list in `k1=v1, k2=v2` format
+
+See [Http Protocol proposal](https://github.com/lmolkova/correlation/blob/master/http_protocol_proposal_v1.md) for more details
+[comment]: TODO: Update link once it's moved
+
+## Subscription
+Instrumentation is off by default; to enable it, consumer first needs to subscribe to DiagnosticListener called "HttpHandlerDiagnosticListener". 
+
+```C#
+var subscription = DiagnosticListener.AllListeners.Subscribe(delegate (DiagnosticListener listener)
+{
+    if (listener.Name == "HttpHandlerDiagnosticListener")
+    {
+        listener.Subscribe(delegate (KeyValuePair<string, object> value)
+        {
+            Console.WriteLine($"Event: {value.Key} ActivityName: {Activity.Current.OperationName} Id: {Activity.Current.Id} ");
+        });
+    }
+} );
+```
+
+## Events
+If there is a consumer, subscribed for "HttpHandlerDiagnosticListener" events, `HttpClientHandler` instruments outgoing request depending on subscription and request properties as well as request context.
+
+Instrumentation starts a new Activity for outgoing Http request as a child of some other Activity (e.g. incoming request Activity). If there is no parent Activity, outgoing request **will not** be instrumented. This is important for sampling scenarios to minimize instrumentation costs.
+
+Instrumentation also checks if user has enabled "System.Net.Http.Activity" event through the optional predicate provided in `DiagnosticListener.Subscribe`  method. 
+
+### Preconditions
+Summarizing preconditions for instrumentation:
+
+1. There must be **at least one consumer** for "HttpHandlerDiagnosticListener"(*)
+2. There must be **parent Activity** (Activity.Current must not be null)
+3. Consumer must enable **System.Net.Http.Activity** event 
+
+(*) Avoid having more than one consumer for DiagnosticListener. Note that DiagnosticListener best practice is to guard every `Write` method with `IsEnabled` check. In case there is more than one consumer, **each consumer** will receive Write event if **at least one** consumer returned true for `IsEnabled`.
+
+#### IsEnabled: System.Net.Http.Activity
+If instrumentation preconditions are met, there is another check to ensure consumer wants this particular request to be instrumented.
+It's done with `DiagnosticListener.IsEnabled("System.Net.Http.Activity", request)` call.
+Consumer may optionally provide predicate to DiagnosticListener to prevent some requests from being instrumented: e.g. if logging system has HTTP interface, it could be necessary to filter out requests to logging system itself.
+
+```C#
+    var predicate = (name, r, _) => 
+    {
+        var request = r as HttpRequestMessage;
+        if (request != null)
+        {
+           return !request.RequestUri.Equals(ElasticSearchUri);
+        }
+        return true;
+    }
+    listener.Subscribe(observer, predicate);
+```
+
+#### IsEnabled: System.Net.Http.Exception
+If request processing throws exception, instrumentation first checks if consumer wants to receive this event.
+
+### System.Net.Http.Activity.Start
+After initial instrumentation preconditions are met and `DiagnosticListener.IsEnabled("System.Net.Http.Activity", request)` check is passed, instrumentation starts a new Activity to represent outgoing request and writes  **"System.Net.Http.Activity.Start"** event.  Event payload has Request property with `HttpRequestMessage` object representing request.
+
+### System.Net.Http.Activity.Stop
+When request is completed (faulted with exception, cancelled or successfully completed), instrumentation stops activity and writes  **"System.Net.Http.Activity.Stop"** event.
+
+Event payload has following properties:
+* **Response**  with `HttpResponseMessage` object representing response, which could be null if request was failed or cancelled.  
+* **RequestTaskStatus** with `TaskStatus` enum value that describes status of the request task.
+
+This event is sent under the same conditions as "System.Net.Http.Activity.Start" event.
+
+### System.Net.Http.Exception
+If request throws an exception, instrumentation sends **"System.Net.Http.Exception"** event with payload containing `Exception` and `Request` properties.
+Exception event is sent if initial instrumentation preconditions are met and does not require current outgoing request to be instrumented.
+
+If current outgoing request is instrumented, `Activity.Current` represents it's context.
+Otherwise, `Activity.Current` represent some 'parent' activity (presumably incoming request).
+
+# Events Flow and Order
+
+1. `DiagnosticListener.IsEnabled()` - determines if there is a consumer
+2. `DiagnosticListener.IsEnabled("System.Net.Http.Activity")` - determines if consumer is interested in any Activity events
+3. `DiagnosticListener.IsEnabled("System.Net.Http.Activity", request)` - determines if this particular request should be instrumented
+4. `DiagnosticListener.Write("System.Net.Http.Activity.Start", new {Request})` - notifies that activity (outgoing request) was started
+5. `DiagnosticListener.IsEnabled("System.Net.Http.Exception")` - determines if exception event (if thrown) should be written
+6. `DiagnosticListener.Write("System.Net.Http.Activity.Exception", new {Exception, Request})` - notifies about exception during request processing (if thrown)
+7. `DiagnosticListener.Write("System.Net.Http.Activity.Stop", new {Response, RequestTaskStatus})` - notifies that activity (outgoing request) is stopping
+
+# Non-Activity events (deprecated)
+If there is a subscriber to "HttpHandlerDiagnosticListener", but Activity events are disabled, instrumentation attempts to send legacy "System.Net.Http.Request" and "System.Net.Http.Response" events if they are enabled.
+Consumers should consider migrating to Activity events instead of Request/Response events.
+
+

src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs

@@ -2,7 +2,9 @@
 // The .NET Foundation licenses this file to you under the MIT license.
 // See the LICENSE file in the project root for more information.
 
+using System.Collections.Generic;
 using System.Diagnostics;
+using System.Net.Http.Headers;
 using System.Threading;
 using System.Threading.Tasks;
 
@@ -36,12 +38,30 @@ protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessa
             //from DiagnosticListener right after the check. So some requests happening right after subscription starts
             //might not be instrumented. Similarly, when consumer unsubscribes, extra requests might be instumented
 
-            Guid loggingRequestId = Guid.NewGuid();
-            LogHttpRequest(request,  loggingRequestId);
+            Task<HttpResponseMessage> responseTask;
 
-            Task<HttpResponseMessage> responseTask = base.SendAsync(request, cancellationToken);
-
-            LogHttpResponse(responseTask, loggingRequestId);
+            //We need to know if activity events are enabled and send Request/Response events otherwise
+            if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityName))
+            {
+                if (Activity.Current != null)
+                {
+                    responseTask = SendInstrumentedAsync(request, cancellationToken);
+                }
+                else
+                {
+                    //null Activity.Current means that incoming request was not instrumented
+                    //and there is nothing we can do for outgoing request. 
+                    //Activity events are enabled so we don't send Request/Response events
+                    responseTask = base.SendAsync(request, cancellationToken);
+                }
+            }
+            else 
+            {
+                Guid loggingRequestId = Guid.NewGuid();
+                LogHttpRequestDeprecated(request, loggingRequestId);
+                responseTask = base.SendAsync(request, cancellationToken);
+                LogHttpResponseDeprecated(responseTask, loggingRequestId);
+            }
             return responseTask;
         }
 
@@ -50,14 +70,82 @@ protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessa
         private static readonly DiagnosticListener s_diagnosticListener =
             new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName);
 
-        private static void LogHttpRequest(HttpRequestMessage request, Guid loggingRequestId)
+        private async Task<HttpResponseMessage> SendInstrumentedAsync(HttpRequestMessage request, CancellationToken cancellationToken)
+        {
+            Activity activity = null;
+            //check if user wants THIS request to be instrumented
+            if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityName, request))
+            {
+                activity = new Activity(DiagnosticsHandlerLoggingStrings.ActivityName);
+
+                s_diagnosticListener.StartActivity(activity, new { Request = request });
+
+                request.Headers.Add(DiagnosticsHandlerLoggingStrings.RequestIdHeaderName, activity.Id);
+
+                //we expect baggage to be empty or contain a few items
+                using (IEnumerator<KeyValuePair<string, string>> e = activity.Baggage.GetEnumerator())
+                {
+                    if (e.MoveNext())
+                    {
+                        var baggage = new List<string>();
+                        do
+                        {
+                            KeyValuePair<string, string> item = e.Current;
+                            baggage.Add(new NameValueHeaderValue(item.Key, item.Value).ToString());
+                        }
+                        while (e.MoveNext());
+                        request.Headers.Add(DiagnosticsHandlerLoggingStrings.CorrelationContextHeaderName, baggage);
+                    }
+                }
+            }
+
+            Task<HttpResponseMessage> responseTask = base.SendAsync(request, cancellationToken);
+            try
+            {
+                await responseTask.ConfigureAwait(false);
+            }
+            catch (TaskCanceledException)
+            {
+                //we'll report task status in Activity.Stop
+                throw;
+            }
+            catch (Exception ex)
+            {
+                //If request was initialy instrumented, Activity.Current has all necessary context for logging
+                //If user decided to NOT instrument this request AND it threw an exception then:
+                //Activity.Current represents 'parent' Activity (presumably incoming request)
+                //So we let user log it as exception happened in this 'parent' activity
+                //Request is passed to provide some context if instrumentation was disabled and to avoid
+                //extensive Activity.Tags usage to tunnel request properties
+                if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionEventName))
+                {
+                    s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.ExceptionEventName, new {Exception = ex, Request = request});
+                }
+                throw;
+            }
+            finally
+            {
+                //always stop activity if it was started
+                if (activity != null)
+                {
+                    s_diagnosticListener.StopActivity(activity, new
+                    {
+                        Response = responseTask.Status == TaskStatus.RanToCompletion ? responseTask.Result : null,
+                        RequestTaskStatus = responseTask.Status
+                    });
+                }
+            }
+            return responseTask.Result;
+        }
+
+        private static void LogHttpRequestDeprecated(HttpRequestMessage request, Guid loggingRequestId)
         {
-            if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteName))
+            if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated))
             {
                 long timestamp = Stopwatch.GetTimestamp();
 
                 s_diagnosticListener.Write(
-                    DiagnosticsHandlerLoggingStrings.RequestWriteName,
+                    DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated,
                     new
                     {
                         Request = request,
@@ -68,17 +156,17 @@ private static void LogHttpRequest(HttpRequestMessage request, Guid loggingReque
             }
         }
 
-        private static void LogHttpResponse(Task<HttpResponseMessage> responseTask, Guid loggingRequestId)
+        private static void LogHttpResponseDeprecated(Task<HttpResponseMessage> responseTask, Guid loggingRequestId)
         {
             responseTask.ContinueWith(
                 (t, s) =>
                 {
                     long timestamp = Stopwatch.GetTimestamp();
 
-                    if (t.IsFaulted && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionWriteName))
+                    if (t.IsFaulted && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionEventName))
                     {
                         s_diagnosticListener.Write(
-                            DiagnosticsHandlerLoggingStrings.ExceptionWriteName,
+                            DiagnosticsHandlerLoggingStrings.ExceptionEventName,
                             new
                             {
                                 LoggingRequestId = (Guid) s,
@@ -88,10 +176,10 @@ private static void LogHttpResponse(Task<HttpResponseMessage> responseTask, Guid
                         );
                     }
 
-                    if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteName))
+                    if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated))
                     {
                         s_diagnosticListener.Write(
-                            DiagnosticsHandlerLoggingStrings.ResponseWriteName,
+                            DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated,
                             new
                             {
                                 Response = t.Status == TaskStatus.RanToCompletion ? t.Result : null,

src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs

@@ -10,8 +10,14 @@ namespace System.Net.Http
     internal static class DiagnosticsHandlerLoggingStrings
     {
         public const string DiagnosticListenerName = "HttpHandlerDiagnosticListener";
-        public const string RequestWriteName = "System.Net.Http.Request";
-        public const string ResponseWriteName = "System.Net.Http.Response";
-        public const string ExceptionWriteName = "System.Net.Http.Exception";
+        public const string RequestWriteNameDeprecated = "System.Net.Http.Request";
+        public const string ResponseWriteNameDeprecated = "System.Net.Http.Response";
+
+        public const string ExceptionEventName = "System.Net.Http.Exception";
+        public const string ActivityName = "System.Net.Http.Activity";
+        public const string ActivityPropagateName = "System.Net.Http.Activity.Propagate";
+
+        public const string RequestIdHeaderName = "Request-Id";
+        public const string CorrelationContextHeaderName = "Correlation-Context";
     }
 }