Http request instrumentation with Activity (correlation part2)

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

@@ -0,0 +1,111 @@
+# 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.
+If **"System.Net.Http.Activity.Start"** is enabled, instrumentation writes  it. 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.IsEnabled("System.Net.Http.Activity.Start")` - determines if Start event should be written
+5. `DiagnosticListener.Write("System.Net.Http.Activity.Start", new {Request})` - notifies that activity (outgoing request) was started
+6. `DiagnosticListener.IsEnabled("System.Net.Http.Exception")` - determines if exception event (if thrown) should be written
+7. `DiagnosticListener.Write("System.Net.Http.Activity.Exception", new {Exception, Request})` - notifies about exception during request processing (if thrown)
+8. `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;
 
@@ -28,36 +30,62 @@ internal static bool IsEnabled()
             return s_diagnosticListener.IsEnabled();
         }
 
-        protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
+        protected internal override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
             CancellationToken cancellationToken)
         {
             //HttpClientHandler is responsible to call DiagnosticsHandler.IsEnabled() before forwarding request here.
             //This code will not be reached if no one listens to 'HttpHandlerDiagnosticListener', unless consumer unsubscribes
             //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 = base.SendAsync(request, cancellationToken);
-
-            LogHttpResponse(responseTask, loggingRequestId);
-            return responseTask;
-        }
-
-        #region private
+            Activity activity = null;
+            Guid loggingRequestId = Guid.Empty;
+
+            //cache IsEnabled result for Activity name
+            if (!s_activityEventIsChecked)
+            {
+                s_activityIsEnabled = s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityName);
+                s_activityEventIsChecked = true;
+            }
 
-        private static readonly DiagnosticListener s_diagnosticListener =
-            new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName);
+            if (Activity.Current != null && //without parent activity, we cannot instrument the request
+                s_activityIsEnabled &&  //Activity events are enabled
+                s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityName, request)) //user wants THIS request to be instumented
+            {
+                activity = new Activity(DiagnosticsHandlerLoggingStrings.ActivityName);
+                //Only send start event to users who subscribed for it, but start activity anyway
+                if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityStartName))
+                {
+                    s_diagnosticListener.StartActivity(activity, new { Request = request });
+                }
+                else
+                {
+                    activity.Start();
+                }
 
-        private static void LogHttpRequest(HttpRequestMessage request, Guid loggingRequestId)
-        {
-            if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteName))
+                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);
+                    }
+                }
+            }
+            //if Activity events are disabled, try to write System.Net.Http.Request event (deprecated)
+            else if (!s_activityIsEnabled && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated))
             {
                 long timestamp = Stopwatch.GetTimestamp();
-
-                s_diagnosticListener.Write(
-                    DiagnosticsHandlerLoggingStrings.RequestWriteName,
+                loggingRequestId = Guid.NewGuid();
+                s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated,
                     new
                     {
                         Request = request,
@@ -66,43 +94,63 @@ private static void LogHttpRequest(HttpRequestMessage request, Guid loggingReque
                     }
                 );
             }
-        }
 
-        private static void LogHttpResponse(Task<HttpResponseMessage> responseTask, Guid loggingRequestId)
-        {
-            responseTask.ContinueWith(
-                (t, s) =>
+            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 (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionEventName))
+                {
+                    //If request was initialy instrumented, Activity.Current has all necessary context for logging
+                    //Request is passed to provide some context if instrumentation was disabled and to avoid
+                    //extensive Activity.Tags usage to tunnel request properties
+                    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
+                    });
+                }
+                //if Activity events are disabled, try to write System.Net.Http.Response event (deprecated)
+                else if (!s_activityIsEnabled && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated))
                 {
                     long timestamp = Stopwatch.GetTimestamp();
+                    s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated,
+                        new
+                        {
+                            Response = responseTask.Status == TaskStatus.RanToCompletion ? responseTask.Result : null,
+                            LoggingRequestId = loggingRequestId,
+                            TimeStamp = timestamp,
+                            RequestTaskStatus = responseTask.Status
+                        }
+                    );
+                }
+            }
+            return responseTask.Result;
+        }
 
-                    if (t.IsFaulted && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionWriteName))
-                    {
-                        s_diagnosticListener.Write(
-                            DiagnosticsHandlerLoggingStrings.ExceptionWriteName,
-                            new
-                            {
-                                LoggingRequestId = (Guid) s,
-                                Timestamp = timestamp,
-                                Exception = t.Exception,
-                            }
-                        );
-                    }
+        #region private
 
-                    if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteName))
-                    {
-                        s_diagnosticListener.Write(
-                            DiagnosticsHandlerLoggingStrings.ResponseWriteName,
-                            new
-                            {
-                                Response = t.Status == TaskStatus.RanToCompletion ? t.Result : null,
-                                LoggingRequestId = (Guid) s,
-                                TimeStamp = timestamp,
-                                RequestTaskStatus = t.Status
-                            }
-                        );
-                    }
-                }, loggingRequestId, CancellationToken.None, TaskContinuationOptions.None, TaskScheduler.Default);
-        }
+        private static bool s_activityIsEnabled = false;
+        private static bool s_activityEventIsChecked = false;
+        private static readonly DiagnosticListener s_diagnosticListener =
+            new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName);
 
         #endregion
     }

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 ActivityStartName = "System.Net.Http.Activity.Start";
+
+        public const string RequestIdHeaderName = "Request-Id";
+        public const string CorrelationContextHeaderName = "Correlation-Context";
     }
 }