From 76dabc67a537be2401e1e0db0dceae9acd652c9c Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Wed, 15 Feb 2017 18:48:58 -0800 Subject: [PATCH 1/9] Add Activity instrumentation --- .../HttpKnownHeaderNames.TryGetHeaderName.cs | 10 +- .../src/System/Net/HttpKnownHeaderNames.cs | 2 + .../src/HttpDiagnosticsGuide.md | 118 +++++ .../src/System/Net/Http/DiagnosticsHandler.cs | 111 ++++- .../Http/DiagnosticsHandlerLoggingStrings.cs | 5 +- .../tests/FunctionalTests/DiagnosticsTests.cs | 402 +++++++++++++++++- .../FakeDiagnosticSourceListenerObserver.cs | 20 +- 7 files changed, 645 insertions(+), 23 deletions(-) create mode 100644 src/System.Net.Http/src/HttpDiagnosticsGuide.md diff --git a/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs b/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs index e3c6a1346c8a..c78d52c38b22 100644 --- a/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs +++ b/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs @@ -155,6 +155,7 @@ private static bool TryGetHeaderName( case 'K': potentialHeader = KeepAlive; goto TryMatch; // [K]eep-Alive case 'S': potentialHeader = SetCookie; goto TryMatch; // [S]et-Cookie case 'U': potentialHeader = UserAgent; goto TryMatch; // [U]ser-Agent + case 'R': potentialHeader = RequestId; goto TryMatch; // [R]equest-Id } break; @@ -240,11 +241,12 @@ private static bool TryGetHeaderName( break; case 19: - switch (charAt(key, startIndex)) + switch (charAt(key, startIndex + 2)) { - case 'C': potentialHeader = ContentDisposition; goto TryMatch; // [C]ontent-Disposition - case 'I': potentialHeader = IfUnmodifiedSince; goto TryMatch; // [I]f-Unmodified-Since - case 'P': potentialHeader = ProxyAuthorization; goto TryMatch; // [P]roxy-Authorization + case 'n': potentialHeader = ContentDisposition; goto TryMatch; // Co[n]tent-Disposition + case 'r': potentialHeader = CorrelationContext; goto TryMatch; // Co[r]relation-Context + case '-': potentialHeader = IfUnmodifiedSince; goto TryMatch; // If[-]Unmodified-Since + case 'o': potentialHeader = ProxyAuthorization; goto TryMatch; // Pr[o]xy-Authorization } break; diff --git a/src/Common/src/System/Net/HttpKnownHeaderNames.cs b/src/Common/src/System/Net/HttpKnownHeaderNames.cs index 874c8d06951c..658c67bb971c 100644 --- a/src/Common/src/System/Net/HttpKnownHeaderNames.cs +++ b/src/Common/src/System/Net/HttpKnownHeaderNames.cs @@ -37,6 +37,7 @@ internal static partial class HttpKnownHeaderNames public const string ContentType = "Content-Type"; public const string Cookie = "Cookie"; public const string Cookie2 = "Cookie2"; + public const string CorrelationContext = "Correlation-Context"; public const string Date = "Date"; public const string ETag = "ETag"; public const string Expect = "Expect"; @@ -61,6 +62,7 @@ internal static partial class HttpKnownHeaderNames public const string ProxyConnection = "Proxy-Connection"; public const string PublicKeyPins = "Public-Key-Pins"; public const string Range = "Range"; + public const string RequestId = "Request-Id"; public const string Referer = "Referer"; // NB: The spelling-mistake "Referer" for "Referrer" must be matched. public const string RetryAfter = "Retry-After"; public const string SecWebSocketAccept = "Sec-WebSocket-Accept"; diff --git a/src/System.Net.Http/src/HttpDiagnosticsGuide.md b/src/System.Net.Http/src/HttpDiagnosticsGuide.md new file mode 100644 index 000000000000..4a0c9d99b64e --- /dev/null +++ b/src/System.Net.Http/src/HttpDiagnosticsGuide.md @@ -0,0 +1,118 @@ +# 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. + +## 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 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. + +Request context is represented as `System.Diagnostics.Activity` class. Activity describes context for logical piece of work. 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. + +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.Activity.Propagate +In order to correlate logs in distributed systems, 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 + +Instrumentation will call `DiagnosticListener.IsEnabled("System.Net.Http.Activity.Propagate")` method, so consumer may enable or disable headers injection. + +```C# + listener.Subscribe(observer, name != "System.Net.Http.Activity.Propagate"); +``` + +Above example demonstrates predicate that allows to instrument the request, but does not allow context propagation through headers. Note that in this case telemetry from downstream services cannot be correlated with telemetry from current and upstream services. + +#### 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` property. +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})` - 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. + + diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index 322484d5ede3..a71555f8c8ac 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/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,19 +38,107 @@ protected internal override Task 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 responseTask; - Task 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(); + LogHttpRequest(request, loggingRequestId); + responseTask = base.SendAsync(request, cancellationToken); + LogHttpResponse(responseTask, loggingRequestId); + } return responseTask; } #region private - private static readonly DiagnosticListener s_diagnosticListener = - new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); + private async Task 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 }); + + //inject headers unless user does not want it to happen + //we may pass request to IsEnabled, but not clear how useful it is + if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityPropagateName)) + { + request.Headers.Add(HttpKnownHeaderNames.RequestId, activity.Id); + + //we expect baggage to be empty or contain a few items + bool baggageIsEmpty = true; + foreach (var _ in activity.Baggage) + { + baggageIsEmpty = false; + break; + } + + if (!baggageIsEmpty) + { + List baggage = new List(); + foreach (KeyValuePair baggageItem in activity.Baggage) + { + baggage.Add(new NameValueHeaderValue(baggageItem.Key, baggageItem.Value).ToString()); + } + request.Headers.Add(HttpKnownHeaderNames.CorrelationContext, baggage); + } + } + } + + Task 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 + if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionEventName)) + { + s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.ExceptionEventName, new {Exception = ex}); + } + 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 LogHttpRequest(HttpRequestMessage request, Guid loggingRequestId) { @@ -75,10 +165,10 @@ private static void LogHttpResponse(Task responseTask, Guid { 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, @@ -104,6 +194,9 @@ private static void LogHttpResponse(Task responseTask, Guid }, loggingRequestId, CancellationToken.None, TaskContinuationOptions.None, TaskScheduler.Default); } + private static readonly DiagnosticListener s_diagnosticListener = + new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); + #endregion } } diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs index 0b0dc0bda48d..186ce7aee572 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs @@ -12,6 +12,9 @@ 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 ExceptionEventName = "System.Net.Http.Exception"; + public const string ActivityName = "System.Net.Http.Activity"; + public const string ActivityPropagateName = "System.Net.Http.Activity.Propagate"; } } diff --git a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 1c59c9c3e82e..10053a3eb168 100644 --- a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -8,6 +8,7 @@ using System.Diagnostics.Tracing; using System.IO; using System.Linq; +using System.Net.Http.Headers; using System.Net.Test.Common; using System.Reflection; using System.Threading; @@ -51,8 +52,9 @@ public void SendAsync_ExpectedDiagnosticSourceLogging() Guid requestGuid = Guid.Empty; bool responseLogged = false; Guid responseGuid = Guid.Empty; - bool exceptionLogged = false; + bool activityLogged = false; + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.Request")) @@ -77,11 +79,15 @@ public void SendAsync_ExpectedDiagnosticSourceLogging() { exceptionLogged = true; } + else if (kvp.Key.StartsWith("System.Net.Http.Activity")) + { + activityLogged = true; + } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { - diagnosticListenerObserver.Enable(); + diagnosticListenerObserver.Enable( s => !s.Contains("Activity")); using (var client = new HttpClient()) { var response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; @@ -92,6 +98,7 @@ public void SendAsync_ExpectedDiagnosticSourceLogging() WaitForTrue(() => responseLogged, TimeSpan.FromSeconds(1), "Response was not logged within 1 second timeout."); Assert.Equal(requestGuid, responseGuid); Assert.False(exceptionLogged, "Exception was logged for successful request"); + Assert.False(activityLogged, "Activity was logged while Activity logging was disabled"); diagnosticListenerObserver.Disable(); } @@ -111,6 +118,14 @@ public void SendAsync_ExpectedDiagnosticSourceNoLogging() { bool requestLogged = false; bool responseLogged = false; + bool activityStartLogged = false; + bool activityStopLogged = false; + + //start parent activity + Activity parentActivity = new Activity("parent"); + parentActivity.AddBaggage("correlationId", Guid.NewGuid().ToString()); + parentActivity.Start(); + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { @@ -122,17 +137,35 @@ public void SendAsync_ExpectedDiagnosticSourceNoLogging() { responseLogged = true; } + else if (kvp.Key.Equals("System.Net.Http.Activity.Start")) + { + activityStartLogged = true; + } + else if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) + { + activityStopLogged = true; + } }); using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { using (var client = new HttpClient()) { - var response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; + LoopbackServer.CreateServerAsync(async (server, url) => + { + Task> requestLines = LoopbackServer.AcceptSocketAsync(server, + (s, stream, reader, writer) => LoopbackServer.ReadWriteAcceptedAsync(s, reader, writer)); + Task response = client.GetAsync(url); + await Task.WhenAll(response, requestLines); + + AssertNoHeadersAreInjected(requestLines.Result); + }).Wait(); } Assert.False(requestLogged, "Request was logged while logging disabled."); + Assert.False(activityStartLogged, "Activity.Start was logged while logging disabled."); WaitForFalse(() => responseLogged, TimeSpan.FromSeconds(1), "Response was logged while logging disabled."); + Assert.False(activityStopLogged, "Activity.Stop was logged while logging disabled."); } return SuccessExitCode; }).Dispose(); @@ -211,7 +244,7 @@ public void SendAsync_ExpectedDiagnosticExceptionLogging() using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { - diagnosticListenerObserver.Enable(); + diagnosticListenerObserver.Enable(s => !s.Contains("Activity")); using (var client = new HttpClient()) { Assert.ThrowsAsync(() => client.GetAsync($"http://{Guid.NewGuid()}.com")).Wait(); @@ -245,6 +278,324 @@ public void SendAsync_ExpectedDiagnosticCancelledLogging() } }); + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + diagnosticListenerObserver.Enable(s => !s.Contains("Activity")); + using (var client = new HttpClient()) + { + LoopbackServer.CreateServerAsync(async (server, url) => + { + CancellationTokenSource tcs = new CancellationTokenSource(); + Task request = LoopbackServer.AcceptSocketAsync(server, + (s, stream, reader, writer) => + { + tcs.Cancel(); + return LoopbackServer.ReadWriteAcceptedAsync(s, reader, writer); + }); + Task response = client.GetAsync(url, tcs.Token); + await Assert.ThrowsAnyAsync(() => Task.WhenAll(response, request)); + }).Wait(); + } + } + // Poll with a timeout since logging response is not synchronized with returning a response. + WaitForTrue(() => cancelLogged, TimeSpan.FromSeconds(1), + "Cancellation was not logged within 1 second timeout."); + diagnosticListenerObserver.Disable(); + + return SuccessExitCode; + }).Dispose(); + } + + [OuterLoop] // TODO: Issue #11345 + [Fact] + public void SendAsync_ExpectedDiagnosticSourceActivityLogging() + { + RemoteInvoke(() => + { + bool requestLogged = false; + bool responseLogged = false; + bool activityStartLogged = false; + bool activityStopLogged = false; + bool exceptionLogged = false; + + Activity parentActivity = new Activity("parent"); + parentActivity.AddBaggage("correlationId", Guid.NewGuid().ToString()); + parentActivity.AddBaggage("moreBaggage", Guid.NewGuid().ToString()); + parentActivity.AddTag("tag", "tag"); //add tag to ensure it is not injected into request + parentActivity.Start(); + + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + if (kvp.Key.Equals("System.Net.Http.Request")) { requestLogged = true; } + else if (kvp.Key.Equals("System.Net.Http.Response")) { responseLogged = true;} + else if (kvp.Key.Equals("System.Net.Http.Exception")) { exceptionLogged = true; } + else if (kvp.Key.Equals("System.Net.Http.Activity.Start")) + { + Assert.NotNull(kvp.Value); + Assert.NotNull(Activity.Current); + Assert.Equal(parentActivity, Activity.Current.Parent); + GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); + + activityStartLogged = true; + } + else if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) + { + Assert.NotNull(kvp.Value); + Assert.NotNull(Activity.Current); + Assert.Equal(parentActivity, Activity.Current.Parent); + GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Response"); + + activityStopLogged = true; + } + }); + + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + diagnosticListenerObserver.Enable(); + using (var client = new HttpClient()) + { + LoopbackServer.CreateServerAsync(async (server, url) => + { + Task> requestLines = LoopbackServer.AcceptSocketAsync(server, + (s, stream, reader, writer) => LoopbackServer.ReadWriteAcceptedAsync(s, reader, writer)); + Task response = client.GetAsync(url); + await Task.WhenAll(response, requestLines); + + AssertHeadersAreInjected(requestLines.Result, parentActivity); + }).Wait(); + } + + Assert.True(activityStartLogged, "Activity.Start was not logged."); + Assert.False(requestLogged, "Request was logged when Activity logging was enabled."); + // Poll with a timeout since logging response is not synchronized with returning a response. + WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), "Activity.Stop was not logged within 1 second timeout."); + Assert.False(exceptionLogged, "Exception was logged for successful request"); + Assert.False(responseLogged, "Response was logged when Activity logging was enabled."); + diagnosticListenerObserver.Disable(); + } + + return SuccessExitCode; + }).Dispose(); + } + + [OuterLoop] // TODO: Issue #11345 + [Fact] + public void SendAsync_ExpectedDiagnosticSourceActivityLoggingNoPropagation() + { + RemoteInvoke(() => + { + bool activityStartLogged = false; + bool activityStopLogged = false; + + Activity parentActivity = new Activity("parent"); + parentActivity.Start(); + + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + if (kvp.Key.Equals("System.Net.Http.Activity.Start")) + { + Assert.NotNull(kvp.Value); + Assert.NotNull(Activity.Current); + Assert.Equal(parentActivity, Activity.Current.Parent); + GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); + + activityStartLogged = true; + } + else if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) + { + Assert.NotNull(kvp.Value); + Assert.NotNull(Activity.Current); + Assert.Equal(parentActivity, Activity.Current.Parent); + GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Response"); + + activityStopLogged = true; + } + }); + + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + diagnosticListenerObserver.Enable(s => s != "System.Net.Http.Activity.Propagate"); + using (var client = new HttpClient()) + { + LoopbackServer.CreateServerAsync(async (server, url) => + { + Task> requestLines = LoopbackServer.AcceptSocketAsync(server, + (s, stream, reader, writer) => LoopbackServer.ReadWriteAcceptedAsync(s, reader, writer)); + Task response = client.GetAsync(url); + await Task.WhenAll(response, requestLines); + + AssertNoHeadersAreInjected(requestLines.Result); + }).Wait(); + } + + Assert.True(activityStartLogged, "Activity.Start was not logged."); + // Poll with a timeout since logging response is not synchronized with returning a response. + WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), "Activity.Stop was not logged within 1 second timeout."); + diagnosticListenerObserver.Disable(); + } + + return SuccessExitCode; + }).Dispose(); + } + + [OuterLoop] // TODO: Issue #11345 + [Fact] + public void SendAsync_ExpectedDiagnosticSourceUrlFilteredActivityLogging() + { + RemoteInvoke(() => + { + bool activityStartLogged = false; + bool activityStopLogged = false; + + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + if (kvp.Key.Equals("System.Net.Http.Activity.Start")){activityStartLogged = true;} + else if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) {activityStopLogged = true;} + }); + + Activity parentActivity = new Activity("parent"); + parentActivity.Start(); + + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + diagnosticListenerObserver.Enable((s, r, _) => + { + if (s.StartsWith("System.Net.Http.Activity")) + { + var request = r as HttpRequestMessage; + if (request != null) + return !request.RequestUri.Equals(Configuration.Http.RemoteEchoServer); + } + return true; + }); + using (var client = new HttpClient()) + { + var response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; + } + Assert.False(activityStartLogged, "Activity.Start was logged while URL disabled."); + // Poll with a timeout since logging response is not synchronized with returning a response. + Assert.False(activityStopLogged, "Activity.Stop was logged while URL disabled."); + diagnosticListenerObserver.Disable(); + } + + return SuccessExitCode; + }).Dispose(); + } + + [OuterLoop] // TODO: Issue #11345 + [Fact] + public void SendAsync_ExpectedDiagnosticNoParentActivityLogging() + { + RemoteInvoke(() => + { + bool activityLogged = false; + bool requestLogged = false; + bool responseLogged = false; + + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + if (kvp.Key.StartsWith("System.Net.Http.Activity")) + { + activityLogged = true; + } + else if (kvp.Key.Equals("System.Net.Http.Request")) + { + requestLogged = true; + } + else if (kvp.Key.Equals("System.Net.Http.Response")) + { + responseLogged = true; + } + }); + + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + diagnosticListenerObserver.Enable(); + using (var client = new HttpClient()) + { + var response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; + } + + Assert.False(requestLogged, "Request was logged when activity events were enabled."); + // Poll with a timeout since logging response is not synchronized with returning a response. + WaitForFalse(() => responseLogged, TimeSpan.FromSeconds(1), "Response was logged when activity events were enabled."); + Assert.False(activityLogged, "Activity was logged, when there was no parent activity."); + diagnosticListenerObserver.Disable(); + } + + return SuccessExitCode; + }).Dispose(); + } + + [OuterLoop] // TODO: Issue #11345 + [Fact] + public void SendAsync_ExpectedDiagnosticExceptionActivityLogging() + { + RemoteInvoke(() => + { + bool exceptionLogged = false; + bool activityStopLogged = false; + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) + { + Assert.NotNull(kvp.Value); + var requestStatus = GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + Assert.Equal(TaskStatus.Faulted, requestStatus); + + activityStopLogged = true; + } + else if (kvp.Key.Equals("System.Net.Http.Exception")) + { + Assert.NotNull(kvp.Value); + GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Exception"); + + exceptionLogged = true; + } + }); + + Activity parentActivity = new Activity("parent"); + parentActivity.Start(); + + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + diagnosticListenerObserver.Enable(); + using (var client = new HttpClient()) + { + Assert.ThrowsAsync(() => client.GetAsync($"http://{Guid.NewGuid()}.com")).Wait(); + } + // Poll with a timeout since logging response is not synchronized with returning a response. + WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), + "Response with exception was not logged within 1 second timeout."); + Assert.True(exceptionLogged, "Exception was not logged"); + diagnosticListenerObserver.Disable(); + } + + return SuccessExitCode; + }).Dispose(); + } + + [OuterLoop] // TODO: Issue #11345 + [Fact] + public void SendAsync_ExpectedDiagnosticCancelledActivityLogging() + { + RemoteInvoke(() => + { + bool cancelLogged = false; + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + if (kvp.Key == "System.Net.Http.Activity.Stop") + { + Assert.NotNull(kvp.Value); + var status = GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); + Assert.Equal(TaskStatus.Canceled, status); + cancelLogged = true; + } + }); + + Activity parentActivity = new Activity("parent"); + parentActivity.Start(); + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); @@ -297,5 +648,48 @@ private static void WaitForFalse(Func p, TimeSpan timeout, string message) // Assert that spin times out. Assert.False(SpinWait.SpinUntil(p, timeout), message); } + + private void AssertHeadersAreInjected(List requestLines, Activity parent) + { + string requestId = null; + var correlationContext = new List(); + + foreach (var line in requestLines) + { + if (line.StartsWith("Request-Id")) + { + requestId = line.Substring("Request-Id".Length).Trim(' ', ':'); + } + if (line.StartsWith("Correlation-Context")) + { + var corrCtxString = line.Substring("Correlation-Context".Length).Trim(' ', ':'); + foreach (var kvp in corrCtxString.Split(',')) + { + correlationContext.Add(NameValueHeaderValue.Parse(kvp)); + } + } + } + Assert.True(requestId != null, "Request-Id was not injected when instrumentation was enabled"); + Assert.True(requestId.StartsWith(parent.Id)); + Assert.NotEqual(parent.Id, requestId); + + List> baggage = parent.Baggage.ToList(); + Assert.Equal(baggage.Count, correlationContext.Count); + foreach (var kvp in baggage) + { + Assert.Contains(new NameValueHeaderValue(kvp.Key, kvp.Value), correlationContext); + } + } + + private void AssertNoHeadersAreInjected(List requestLines) + { + foreach (var line in requestLines) + { + Assert.False(line.StartsWith("Request-Id"), + "Request-Id header was injected when instrumentation was disabled"); + Assert.False(line.StartsWith("Correlation-Context"), + "Correlation-Context header was injected when instrumentation was disabled"); + } + } } } diff --git a/src/System.Net.Http/tests/FunctionalTests/FakeDiagnosticSourceListenerObserver.cs b/src/System.Net.Http/tests/FunctionalTests/FakeDiagnosticSourceListenerObserver.cs index 07c09d249a5b..175e6f98a84a 100644 --- a/src/System.Net.Http/tests/FunctionalTests/FakeDiagnosticSourceListenerObserver.cs +++ b/src/System.Net.Http/tests/FunctionalTests/FakeDiagnosticSourceListenerObserver.cs @@ -34,7 +34,7 @@ public void OnNext(KeyValuePair value) private readonly Action> _writeCallback; - private bool _writeObserverEnabled; + private Func _writeObserverEnabled = (name, arg1, arg2) => false; public FakeDiagnosticListenerObserver(Action> writeCallback) { @@ -59,17 +59,27 @@ public void OnNext(DiagnosticListener value) public void Enable() { - _writeObserverEnabled = true; + _writeObserverEnabled = (name, arg1, arg2) => true; + } + + public void Enable(Func writeObserverEnabled) + { + _writeObserverEnabled = (name, arg1, arg2) => writeObserverEnabled(name); + } + + public void Enable(Func writeObserverEnabled) + { + _writeObserverEnabled = writeObserverEnabled; } public void Disable() { - _writeObserverEnabled = false; + _writeObserverEnabled = (name, arg1, arg2) => false; } - private bool IsEnabled(string s) + private bool IsEnabled(string s, object arg1, object arg2) { - return _writeObserverEnabled; + return _writeObserverEnabled.Invoke(s, arg1, arg2); } } } From 707fa0d2bfef2a12d8385f2973b01b83dbf8b2eb Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Thu, 23 Feb 2017 13:59:11 -0800 Subject: [PATCH 2/9] review comments --- .../HttpKnownHeaderNames.TryGetHeaderName.cs | 10 +++--- .../src/HttpDiagnosticsGuide.md | 4 +-- .../src/System/Net/Http/DiagnosticsHandler.cs | 34 +++++++++---------- 3 files changed, 23 insertions(+), 25 deletions(-) diff --git a/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs b/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs index c78d52c38b22..e3c6a1346c8a 100644 --- a/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs +++ b/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs @@ -155,7 +155,6 @@ private static bool TryGetHeaderName( case 'K': potentialHeader = KeepAlive; goto TryMatch; // [K]eep-Alive case 'S': potentialHeader = SetCookie; goto TryMatch; // [S]et-Cookie case 'U': potentialHeader = UserAgent; goto TryMatch; // [U]ser-Agent - case 'R': potentialHeader = RequestId; goto TryMatch; // [R]equest-Id } break; @@ -241,12 +240,11 @@ private static bool TryGetHeaderName( break; case 19: - switch (charAt(key, startIndex + 2)) + switch (charAt(key, startIndex)) { - case 'n': potentialHeader = ContentDisposition; goto TryMatch; // Co[n]tent-Disposition - case 'r': potentialHeader = CorrelationContext; goto TryMatch; // Co[r]relation-Context - case '-': potentialHeader = IfUnmodifiedSince; goto TryMatch; // If[-]Unmodified-Since - case 'o': potentialHeader = ProxyAuthorization; goto TryMatch; // Pr[o]xy-Authorization + case 'C': potentialHeader = ContentDisposition; goto TryMatch; // [C]ontent-Disposition + case 'I': potentialHeader = IfUnmodifiedSince; goto TryMatch; // [I]f-Unmodified-Since + case 'P': potentialHeader = ProxyAuthorization; goto TryMatch; // [P]roxy-Authorization } break; diff --git a/src/System.Net.Http/src/HttpDiagnosticsGuide.md b/src/System.Net.Http/src/HttpDiagnosticsGuide.md index 4a0c9d99b64e..cf971837e94d 100644 --- a/src/System.Net.Http/src/HttpDiagnosticsGuide.md +++ b/src/System.Net.Http/src/HttpDiagnosticsGuide.md @@ -95,7 +95,7 @@ Event payload has following properties: 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` property. +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. @@ -108,7 +108,7 @@ Otherwise, `Activity.Current` represent some 'parent' activity (presumably incom 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})` - notifies about exception during request processing (if thrown) +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) diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index a71555f8c8ac..e9fd7d522887 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -67,6 +67,9 @@ protected internal override Task SendAsync(HttpRequestMessa #region private + private static readonly DiagnosticListener s_diagnosticListener = + new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); + private async Task SendInstrumentedAsync(HttpRequestMessage request, CancellationToken cancellationToken) { Activity activity = null; @@ -82,23 +85,21 @@ private async Task SendInstrumentedAsync(HttpRequestMessage if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityPropagateName)) { request.Headers.Add(HttpKnownHeaderNames.RequestId, activity.Id); - - //we expect baggage to be empty or contain a few items - bool baggageIsEmpty = true; - foreach (var _ in activity.Baggage) - { - baggageIsEmpty = false; - break; - } - if (!baggageIsEmpty) + //we expect baggage to be empty or contain a few items + using (IEnumerator> e = activity.Baggage.GetEnumerator()) { - List baggage = new List(); - foreach (KeyValuePair baggageItem in activity.Baggage) + if (e.MoveNext()) { - baggage.Add(new NameValueHeaderValue(baggageItem.Key, baggageItem.Value).ToString()); + var baggage = new List(); + do + { + KeyValuePair item = e.Current; + baggage.Add(new NameValueHeaderValue(item.Key, item.Value).ToString()); + } + while (e.MoveNext()); + request.Headers.Add(HttpKnownHeaderNames.CorrelationContext, baggage); } - request.Headers.Add(HttpKnownHeaderNames.CorrelationContext, baggage); } } } @@ -119,9 +120,11 @@ private async Task SendInstrumentedAsync(HttpRequestMessage //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}); + s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.ExceptionEventName, new {Exception = ex, Request = request}); } throw; } @@ -194,9 +197,6 @@ private static void LogHttpResponse(Task responseTask, Guid }, loggingRequestId, CancellationToken.None, TaskContinuationOptions.None, TaskScheduler.Default); } - private static readonly DiagnosticListener s_diagnosticListener = - new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); - #endregion } } From 8dcc776aca7e0b347b9711f6721547fa6e79cbdd Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Thu, 23 Feb 2017 16:01:45 -0800 Subject: [PATCH 3/9] return TryGetHeaderName back --- .../Net/HttpKnownHeaderNames.TryGetHeaderName.cs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs b/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs index e3c6a1346c8a..c78d52c38b22 100644 --- a/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs +++ b/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs @@ -155,6 +155,7 @@ private static bool TryGetHeaderName( case 'K': potentialHeader = KeepAlive; goto TryMatch; // [K]eep-Alive case 'S': potentialHeader = SetCookie; goto TryMatch; // [S]et-Cookie case 'U': potentialHeader = UserAgent; goto TryMatch; // [U]ser-Agent + case 'R': potentialHeader = RequestId; goto TryMatch; // [R]equest-Id } break; @@ -240,11 +241,12 @@ private static bool TryGetHeaderName( break; case 19: - switch (charAt(key, startIndex)) + switch (charAt(key, startIndex + 2)) { - case 'C': potentialHeader = ContentDisposition; goto TryMatch; // [C]ontent-Disposition - case 'I': potentialHeader = IfUnmodifiedSince; goto TryMatch; // [I]f-Unmodified-Since - case 'P': potentialHeader = ProxyAuthorization; goto TryMatch; // [P]roxy-Authorization + case 'n': potentialHeader = ContentDisposition; goto TryMatch; // Co[n]tent-Disposition + case 'r': potentialHeader = CorrelationContext; goto TryMatch; // Co[r]relation-Context + case '-': potentialHeader = IfUnmodifiedSince; goto TryMatch; // If[-]Unmodified-Since + case 'o': potentialHeader = ProxyAuthorization; goto TryMatch; // Pr[o]xy-Authorization } break; From 573530cd049602f801d22f2b8abe8e72aee6a7c2 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Thu, 23 Feb 2017 17:15:14 -0800 Subject: [PATCH 4/9] mark Request/Respose events as deprecated, remove Propagate check --- .../src/HttpDiagnosticsGuide.md | 37 +++++------- .../src/System/Net/Http/DiagnosticsHandler.cs | 43 ++++++------- .../Http/DiagnosticsHandlerLoggingStrings.cs | 4 +- .../tests/FunctionalTests/DiagnosticsTests.cs | 60 ------------------- 4 files changed, 35 insertions(+), 109 deletions(-) diff --git a/src/System.Net.Http/src/HttpDiagnosticsGuide.md b/src/System.Net.Http/src/HttpDiagnosticsGuide.md index cf971837e94d..b9145d988fe9 100644 --- a/src/System.Net.Http/src/HttpDiagnosticsGuide.md +++ b/src/System.Net.Http/src/HttpDiagnosticsGuide.md @@ -6,6 +6,20 @@ This document describes `HttpClientHandler` instrumentation with [DiagnosticSour 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". @@ -25,12 +39,6 @@ var subscription = DiagnosticListener.AllListeners.Subscribe(delegate (Diagnosti ## 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. -Request context is represented as `System.Diagnostics.Activity` class. Activity describes context for logical piece of work. 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. - 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. @@ -62,23 +70,6 @@ Consumer may optionally provide predicate to DiagnosticListener to prevent some listener.Subscribe(observer, predicate); ``` -#### IsEnabled: System.Net.Http.Activity.Propagate -In order to correlate logs in distributed systems, 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 - -Instrumentation will call `DiagnosticListener.IsEnabled("System.Net.Http.Activity.Propagate")` method, so consumer may enable or disable headers injection. - -```C# - listener.Subscribe(observer, name != "System.Net.Http.Activity.Propagate"); -``` - -Above example demonstrates predicate that allows to instrument the request, but does not allow context propagation through headers. Note that in this case telemetry from downstream services cannot be correlated with telemetry from current and upstream services. - #### IsEnabled: System.Net.Http.Exception If request processing throws exception, instrumentation first checks if consumer wants to receive this event. diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index e9fd7d522887..83619b960186 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -58,9 +58,9 @@ protected internal override Task SendAsync(HttpRequestMessa else { Guid loggingRequestId = Guid.NewGuid(); - LogHttpRequest(request, loggingRequestId); + LogHttpRequestDeprecated(request, loggingRequestId); responseTask = base.SendAsync(request, cancellationToken); - LogHttpResponse(responseTask, loggingRequestId); + LogHttpResponseDeprecated(responseTask, loggingRequestId); } return responseTask; } @@ -80,26 +80,21 @@ private async Task SendInstrumentedAsync(HttpRequestMessage s_diagnosticListener.StartActivity(activity, new { Request = request }); - //inject headers unless user does not want it to happen - //we may pass request to IsEnabled, but not clear how useful it is - if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityPropagateName)) - { - request.Headers.Add(HttpKnownHeaderNames.RequestId, activity.Id); + request.Headers.Add(HttpKnownHeaderNames.RequestId, activity.Id); - //we expect baggage to be empty or contain a few items - using (IEnumerator> e = activity.Baggage.GetEnumerator()) + //we expect baggage to be empty or contain a few items + using (IEnumerator> e = activity.Baggage.GetEnumerator()) + { + if (e.MoveNext()) { - if (e.MoveNext()) + var baggage = new List(); + do { - var baggage = new List(); - do - { - KeyValuePair item = e.Current; - baggage.Add(new NameValueHeaderValue(item.Key, item.Value).ToString()); - } - while (e.MoveNext()); - request.Headers.Add(HttpKnownHeaderNames.CorrelationContext, baggage); + KeyValuePair item = e.Current; + baggage.Add(new NameValueHeaderValue(item.Key, item.Value).ToString()); } + while (e.MoveNext()); + request.Headers.Add(HttpKnownHeaderNames.CorrelationContext, baggage); } } } @@ -143,14 +138,14 @@ private async Task SendInstrumentedAsync(HttpRequestMessage return responseTask.Result; } - private static void LogHttpRequest(HttpRequestMessage request, Guid loggingRequestId) + 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, @@ -161,7 +156,7 @@ private static void LogHttpRequest(HttpRequestMessage request, Guid loggingReque } } - private static void LogHttpResponse(Task responseTask, Guid loggingRequestId) + private static void LogHttpResponseDeprecated(Task responseTask, Guid loggingRequestId) { responseTask.ContinueWith( (t, s) => @@ -181,10 +176,10 @@ private static void LogHttpResponse(Task 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, diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs index 186ce7aee572..43ec1ab359b8 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs @@ -10,8 +10,8 @@ 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 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"; diff --git a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 10053a3eb168..0a1f254e2660 100644 --- a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -378,66 +378,6 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLogging() }).Dispose(); } - [OuterLoop] // TODO: Issue #11345 - [Fact] - public void SendAsync_ExpectedDiagnosticSourceActivityLoggingNoPropagation() - { - RemoteInvoke(() => - { - bool activityStartLogged = false; - bool activityStopLogged = false; - - Activity parentActivity = new Activity("parent"); - parentActivity.Start(); - - var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => - { - if (kvp.Key.Equals("System.Net.Http.Activity.Start")) - { - Assert.NotNull(kvp.Value); - Assert.NotNull(Activity.Current); - Assert.Equal(parentActivity, Activity.Current.Parent); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Request"); - - activityStartLogged = true; - } - else if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) - { - Assert.NotNull(kvp.Value); - Assert.NotNull(Activity.Current); - Assert.Equal(parentActivity, Activity.Current.Parent); - GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Response"); - - activityStopLogged = true; - } - }); - - using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) - { - diagnosticListenerObserver.Enable(s => s != "System.Net.Http.Activity.Propagate"); - using (var client = new HttpClient()) - { - LoopbackServer.CreateServerAsync(async (server, url) => - { - Task> requestLines = LoopbackServer.AcceptSocketAsync(server, - (s, stream, reader, writer) => LoopbackServer.ReadWriteAcceptedAsync(s, reader, writer)); - Task response = client.GetAsync(url); - await Task.WhenAll(response, requestLines); - - AssertNoHeadersAreInjected(requestLines.Result); - }).Wait(); - } - - Assert.True(activityStartLogged, "Activity.Start was not logged."); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), "Activity.Stop was not logged within 1 second timeout."); - diagnosticListenerObserver.Disable(); - } - - return SuccessExitCode; - }).Dispose(); - } - [OuterLoop] // TODO: Issue #11345 [Fact] public void SendAsync_ExpectedDiagnosticSourceUrlFilteredActivityLogging() From dcf640948be054dbb54810f04b7e8d5142be59b8 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Thu, 23 Feb 2017 18:49:02 -0800 Subject: [PATCH 5/9] remove Request-Id and Correlation-Context from HttpKnownHeaderNames --- .../Net/HttpKnownHeaderNames.TryGetHeaderName.cs | 10 ++++------ src/Common/src/System/Net/HttpKnownHeaderNames.cs | 2 -- .../src/System/Net/Http/DiagnosticsHandler.cs | 4 ++-- .../Net/Http/DiagnosticsHandlerLoggingStrings.cs | 3 +++ 4 files changed, 9 insertions(+), 10 deletions(-) diff --git a/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs b/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs index c78d52c38b22..e3c6a1346c8a 100644 --- a/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs +++ b/src/Common/src/System/Net/HttpKnownHeaderNames.TryGetHeaderName.cs @@ -155,7 +155,6 @@ private static bool TryGetHeaderName( case 'K': potentialHeader = KeepAlive; goto TryMatch; // [K]eep-Alive case 'S': potentialHeader = SetCookie; goto TryMatch; // [S]et-Cookie case 'U': potentialHeader = UserAgent; goto TryMatch; // [U]ser-Agent - case 'R': potentialHeader = RequestId; goto TryMatch; // [R]equest-Id } break; @@ -241,12 +240,11 @@ private static bool TryGetHeaderName( break; case 19: - switch (charAt(key, startIndex + 2)) + switch (charAt(key, startIndex)) { - case 'n': potentialHeader = ContentDisposition; goto TryMatch; // Co[n]tent-Disposition - case 'r': potentialHeader = CorrelationContext; goto TryMatch; // Co[r]relation-Context - case '-': potentialHeader = IfUnmodifiedSince; goto TryMatch; // If[-]Unmodified-Since - case 'o': potentialHeader = ProxyAuthorization; goto TryMatch; // Pr[o]xy-Authorization + case 'C': potentialHeader = ContentDisposition; goto TryMatch; // [C]ontent-Disposition + case 'I': potentialHeader = IfUnmodifiedSince; goto TryMatch; // [I]f-Unmodified-Since + case 'P': potentialHeader = ProxyAuthorization; goto TryMatch; // [P]roxy-Authorization } break; diff --git a/src/Common/src/System/Net/HttpKnownHeaderNames.cs b/src/Common/src/System/Net/HttpKnownHeaderNames.cs index 658c67bb971c..874c8d06951c 100644 --- a/src/Common/src/System/Net/HttpKnownHeaderNames.cs +++ b/src/Common/src/System/Net/HttpKnownHeaderNames.cs @@ -37,7 +37,6 @@ internal static partial class HttpKnownHeaderNames public const string ContentType = "Content-Type"; public const string Cookie = "Cookie"; public const string Cookie2 = "Cookie2"; - public const string CorrelationContext = "Correlation-Context"; public const string Date = "Date"; public const string ETag = "ETag"; public const string Expect = "Expect"; @@ -62,7 +61,6 @@ internal static partial class HttpKnownHeaderNames public const string ProxyConnection = "Proxy-Connection"; public const string PublicKeyPins = "Public-Key-Pins"; public const string Range = "Range"; - public const string RequestId = "Request-Id"; public const string Referer = "Referer"; // NB: The spelling-mistake "Referer" for "Referrer" must be matched. public const string RetryAfter = "Retry-After"; public const string SecWebSocketAccept = "Sec-WebSocket-Accept"; diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index 83619b960186..ecccfb385500 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -80,7 +80,7 @@ private async Task SendInstrumentedAsync(HttpRequestMessage s_diagnosticListener.StartActivity(activity, new { Request = request }); - request.Headers.Add(HttpKnownHeaderNames.RequestId, activity.Id); + request.Headers.Add(DiagnosticsHandlerLoggingStrings.RequestIdHeaderName, activity.Id); //we expect baggage to be empty or contain a few items using (IEnumerator> e = activity.Baggage.GetEnumerator()) @@ -94,7 +94,7 @@ private async Task SendInstrumentedAsync(HttpRequestMessage baggage.Add(new NameValueHeaderValue(item.Key, item.Value).ToString()); } while (e.MoveNext()); - request.Headers.Add(HttpKnownHeaderNames.CorrelationContext, baggage); + request.Headers.Add(DiagnosticsHandlerLoggingStrings.CorrelationContextHeaderName, baggage); } } } diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs index 43ec1ab359b8..6dc2ead2f65b 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs @@ -16,5 +16,8 @@ internal static class DiagnosticsHandlerLoggingStrings 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"; } } From 0916191040adee4a5183b0ae4978e9f66764a5c8 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Mon, 27 Feb 2017 14:51:41 -0800 Subject: [PATCH 6/9] remove propagate event --- .../src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs index 6dc2ead2f65b..cee6974a8c1f 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs @@ -15,7 +15,6 @@ internal static class DiagnosticsHandlerLoggingStrings 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"; From 9815a34bdc5b1ec3d8add193736fc5c4419b4c32 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Tue, 28 Feb 2017 11:20:53 -0800 Subject: [PATCH 7/9] refactor DiagnosticsListener: enable Exceptions only and Stop only scenarios --- .../src/HttpDiagnosticsGuide.md | 12 +- .../src/System/Net/Http/DiagnosticsHandler.cs | 150 +++++++----------- .../Http/DiagnosticsHandlerLoggingStrings.cs | 1 + .../tests/FunctionalTests/DiagnosticsTests.cs | 78 +++++++++ 4 files changed, 141 insertions(+), 100 deletions(-) diff --git a/src/System.Net.Http/src/HttpDiagnosticsGuide.md b/src/System.Net.Http/src/HttpDiagnosticsGuide.md index b9145d988fe9..26e787105e17 100644 --- a/src/System.Net.Http/src/HttpDiagnosticsGuide.md +++ b/src/System.Net.Http/src/HttpDiagnosticsGuide.md @@ -74,7 +74,8 @@ Consumer may optionally provide predicate to DiagnosticListener to prevent some 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. +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. @@ -97,10 +98,11 @@ Otherwise, `Activity.Current` represent some 'parent' activity (presumably incom 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 +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. diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index ecccfb385500..c3896b9ae1fc 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -30,7 +30,7 @@ internal static bool IsEnabled() return s_diagnosticListener.IsEnabled(); } - protected internal override Task SendAsync(HttpRequestMessage request, + protected internal override async Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) { //HttpClientHandler is responsible to call DiagnosticsHandler.IsEnabled() before forwarding request here. @@ -38,50 +38,32 @@ protected internal override Task 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 - Task responseTask; + 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; + } - //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 && //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 { - if (Activity.Current != null) + 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)) { - responseTask = SendInstrumentedAsync(request, cancellationToken); + s_diagnosticListener.StartActivity(activity, new { Request = request }); } 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); + activity.Start(); } - } - else - { - Guid loggingRequestId = Guid.NewGuid(); - LogHttpRequestDeprecated(request, loggingRequestId); - responseTask = base.SendAsync(request, cancellationToken); - LogHttpResponseDeprecated(responseTask, loggingRequestId); - } - return responseTask; - } - - #region private - - private static readonly DiagnosticListener s_diagnosticListener = - new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); - - private async Task 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> e = activity.Baggage.GetEnumerator()) { @@ -98,6 +80,20 @@ private async Task SendInstrumentedAsync(HttpRequestMessage } } } + //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(); + loggingRequestId = Guid.NewGuid(); + s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated, + new + { + Request = request, + LoggingRequestId = loggingRequestId, + Timestamp = timestamp + } + ); + } Task responseTask = base.SendAsync(request, cancellationToken); try @@ -111,15 +107,12 @@ private async Task SendInstrumentedAsync(HttpRequestMessage } 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}); + //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; } @@ -134,63 +127,30 @@ private async Task SendInstrumentedAsync(HttpRequestMessage 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; } - private static void LogHttpRequestDeprecated(HttpRequestMessage request, Guid loggingRequestId) - { - if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated)) - { - long timestamp = Stopwatch.GetTimestamp(); - - s_diagnosticListener.Write( - DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated, - new - { - Request = request, - LoggingRequestId = loggingRequestId, - Timestamp = timestamp - } - ); - } - } - - private static void LogHttpResponseDeprecated(Task responseTask, Guid loggingRequestId) - { - responseTask.ContinueWith( - (t, s) => - { - long timestamp = Stopwatch.GetTimestamp(); - - if (t.IsFaulted && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionEventName)) - { - s_diagnosticListener.Write( - DiagnosticsHandlerLoggingStrings.ExceptionEventName, - new - { - LoggingRequestId = (Guid) s, - Timestamp = timestamp, - Exception = t.Exception, - } - ); - } + #region private - if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated)) - { - s_diagnosticListener.Write( - DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated, - 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 } diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs index cee6974a8c1f..4cc2a8ec7227 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs @@ -15,6 +15,7 @@ internal static class DiagnosticsHandlerLoggingStrings 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"; diff --git a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 0a1f254e2660..945e74a5c403 100644 --- a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -515,6 +515,84 @@ public void SendAsync_ExpectedDiagnosticExceptionActivityLogging() }).Dispose(); } + [OuterLoop] // TODO: Issue #11345 + [Fact] + public void SendAsync_ExpectedDiagnosticExceptionOnlyActivityLogging() + { + RemoteInvoke(() => + { + bool exceptionLogged = false; + bool activityLogged = false; + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) { activityLogged = true; } + else if (kvp.Key.Equals("System.Net.Http.Exception")) + { + Assert.NotNull(kvp.Value); + GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Exception"); + + exceptionLogged = true; + } + }); + + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + diagnosticListenerObserver.Enable(s => s.Equals("System.Net.Http.Exception")); + using (var client = new HttpClient()) + { + Assert.ThrowsAsync(() => client.GetAsync($"http://{Guid.NewGuid()}.com")).Wait(); + } + // Poll with a timeout since logging response is not synchronized with returning a response. + WaitForTrue(() => exceptionLogged, TimeSpan.FromSeconds(1), + "Exception was not logged within 1 second timeout."); + Assert.False(activityLogged, "Activity was logged when logging was disabled"); + diagnosticListenerObserver.Disable(); + } + + return SuccessExitCode; + }).Dispose(); + } + + [OuterLoop] // TODO: Issue #11345 + [Fact] + public void SendAsync_ExpectedDiagnosticStopOnlyActivityLogging() + { + RemoteInvoke(() => + { + bool activityStartLogged = false; + bool activityStopLogged = false; + + Activity parentActivity = new Activity("parent"); + parentActivity.Start(); + + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => + { + if (kvp.Key.Equals("System.Net.Http.Activity.Start")) { activityStartLogged = true; } + else if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) + { + Assert.Equal(parentActivity, Activity.Current.Parent); + activityStopLogged = true; + } + }); + + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) + { + diagnosticListenerObserver.Enable(s => s.Equals("System.Net.Http.Activity")); + using (var client = new HttpClient()) + { + var response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; + } + // Poll with a timeout since logging response is not synchronized with returning a response. + WaitForTrue(() => activityStopLogged, TimeSpan.FromSeconds(1), + "Activity.Stop was not logged within 1 second timeout."); + Assert.False(activityStartLogged, "Activity Start was logged when start logging was disabled"); + diagnosticListenerObserver.Disable(); + } + + return SuccessExitCode; + }).Dispose(); + } + [OuterLoop] // TODO: Issue #11345 [Fact] public void SendAsync_ExpectedDiagnosticCancelledActivityLogging() From 1ee9ac6e4c76324cb191769c2e369abe4ea08f00 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Wed, 1 Mar 2017 13:38:50 -0800 Subject: [PATCH 8/9] enabling Activity for outgoing request if there is no parent activiy, always propagate if there is any activity --- .../src/HttpDiagnosticsGuide.md | 47 +++++--------- .../src/System/Net/Http/DiagnosticsHandler.cs | 55 +++++++--------- .../tests/FunctionalTests/DiagnosticsTests.cs | 65 +------------------ 3 files changed, 41 insertions(+), 126 deletions(-) diff --git a/src/System.Net.Http/src/HttpDiagnosticsGuide.md b/src/System.Net.Http/src/HttpDiagnosticsGuide.md index 26e787105e17..77f24f0495e6 100644 --- a/src/System.Net.Http/src/HttpDiagnosticsGuide.md +++ b/src/System.Net.Http/src/HttpDiagnosticsGuide.md @@ -37,24 +37,12 @@ var subscription = DiagnosticListener.AllListeners.Subscribe(delegate (Diagnosti ``` ## 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. +If there is **at least one consumer**, subscribed for "HttpHandlerDiagnosticListener" events, `HttpClientHandler` instruments outgoing request depending on subscription and request properties. -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`. +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. +If there is a consumer, instrumentation calls `DiagnosticListener.IsEnabled("System.Net.Http.Activity", request)` to check if particular request needs to be instrumented. 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# @@ -69,13 +57,9 @@ Consumer may optionally provide predicate to DiagnosticListener to prevent some } 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. +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. @@ -86,9 +70,11 @@ Event payload has following properties: This event is sent under the same conditions as "System.Net.Http.Activity.Start" event. +#### IsEnabled: System.Net.Http.Exception +If request processing causes an exception, instrumentation first checks if consumer wants to receive Exception 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). @@ -96,16 +82,13 @@ Otherwise, `Activity.Current` represent some 'parent' activity (presumably incom # 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 +2. `DiagnosticListener.IsEnabled("System.Net.Http.Activity", request)` - determines if this particular request should be instrumented +3. `DiagnosticListener.IsEnabled("System.Net.Http.Activity.Start")` - determines if Start event should be written +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. - - +If there is a subscriber to "HttpHandlerDiagnosticListener", but Activity events are disabled (`DiagnosticListener.IsEnabled("System.Net.Http.Activity", request)` returns false), 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. \ No newline at end of file diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index c3896b9ae1fc..b7db836f9cd3 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -40,17 +40,9 @@ protected internal override async Task SendAsync(HttpReques 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; - } - 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 + // If System.Net.Http.Activity is on see if we should log the start (or just log the activity) + if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityName, request)) { activity = new Activity(DiagnosticsHandlerLoggingStrings.ActivityName); //Only send start event to users who subscribed for it, but start activity anyway @@ -62,10 +54,29 @@ protected internal override async Task SendAsync(HttpReques { activity.Start(); } + } + //if Activity events are disabled, try to write System.Net.Http.Request event (deprecated) + else if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated)) + { + long timestamp = Stopwatch.GetTimestamp(); + loggingRequestId = Guid.NewGuid(); + s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated, + new + { + Request = request, + LoggingRequestId = loggingRequestId, + Timestamp = timestamp + } + ); + } - request.Headers.Add(DiagnosticsHandlerLoggingStrings.RequestIdHeaderName, activity.Id); + // If we are on at all, we propagate any activity information. + Activity currentActivity = Activity.Current; + if (currentActivity != null) + { + request.Headers.Add(DiagnosticsHandlerLoggingStrings.RequestIdHeaderName, currentActivity.Id); //we expect baggage to be empty or contain a few items - using (IEnumerator> e = activity.Baggage.GetEnumerator()) + using (IEnumerator> e = currentActivity.Baggage.GetEnumerator()) { if (e.MoveNext()) { @@ -80,20 +91,6 @@ protected internal override async Task SendAsync(HttpReques } } } - //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(); - loggingRequestId = Guid.NewGuid(); - s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated, - new - { - Request = request, - LoggingRequestId = loggingRequestId, - Timestamp = timestamp - } - ); - } Task responseTask = base.SendAsync(request, cancellationToken); try @@ -128,7 +125,7 @@ protected internal override async Task SendAsync(HttpReques }); } //if Activity events are disabled, try to write System.Net.Http.Response event (deprecated) - else if (!s_activityIsEnabled && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated)) + else if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated)) { long timestamp = Stopwatch.GetTimestamp(); s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated, @@ -147,11 +144,9 @@ protected internal override async Task SendAsync(HttpReques #region private - private static bool s_activityIsEnabled = false; - private static bool s_activityEventIsChecked = false; private static readonly DiagnosticListener s_diagnosticListener = new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); #endregion } -} +} \ No newline at end of file diff --git a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 945e74a5c403..7a6cab8a9547 100644 --- a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -121,12 +121,6 @@ public void SendAsync_ExpectedDiagnosticSourceNoLogging() bool activityStartLogged = false; bool activityStopLogged = false; - //start parent activity - Activity parentActivity = new Activity("parent"); - parentActivity.AddBaggage("correlationId", Guid.NewGuid().ToString()); - parentActivity.Start(); - - var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.Request")) @@ -393,9 +387,6 @@ public void SendAsync_ExpectedDiagnosticSourceUrlFilteredActivityLogging() else if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) {activityStopLogged = true;} }); - Activity parentActivity = new Activity("parent"); - parentActivity.Start(); - using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable((s, r, _) => @@ -422,51 +413,6 @@ public void SendAsync_ExpectedDiagnosticSourceUrlFilteredActivityLogging() }).Dispose(); } - [OuterLoop] // TODO: Issue #11345 - [Fact] - public void SendAsync_ExpectedDiagnosticNoParentActivityLogging() - { - RemoteInvoke(() => - { - bool activityLogged = false; - bool requestLogged = false; - bool responseLogged = false; - - var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => - { - if (kvp.Key.StartsWith("System.Net.Http.Activity")) - { - activityLogged = true; - } - else if (kvp.Key.Equals("System.Net.Http.Request")) - { - requestLogged = true; - } - else if (kvp.Key.Equals("System.Net.Http.Response")) - { - responseLogged = true; - } - }); - - using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) - { - diagnosticListenerObserver.Enable(); - using (var client = new HttpClient()) - { - var response = client.GetAsync(Configuration.Http.RemoteEchoServer).Result; - } - - Assert.False(requestLogged, "Request was logged when activity events were enabled."); - // Poll with a timeout since logging response is not synchronized with returning a response. - WaitForFalse(() => responseLogged, TimeSpan.FromSeconds(1), "Response was logged when activity events were enabled."); - Assert.False(activityLogged, "Activity was logged, when there was no parent activity."); - diagnosticListenerObserver.Disable(); - } - - return SuccessExitCode; - }).Dispose(); - } - [OuterLoop] // TODO: Issue #11345 [Fact] public void SendAsync_ExpectedDiagnosticExceptionActivityLogging() @@ -494,9 +440,6 @@ public void SendAsync_ExpectedDiagnosticExceptionActivityLogging() } }); - Activity parentActivity = new Activity("parent"); - parentActivity.Start(); - using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); @@ -562,15 +505,12 @@ public void SendAsync_ExpectedDiagnosticStopOnlyActivityLogging() bool activityStartLogged = false; bool activityStopLogged = false; - Activity parentActivity = new Activity("parent"); - parentActivity.Start(); - var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { if (kvp.Key.Equals("System.Net.Http.Activity.Start")) { activityStartLogged = true; } else if (kvp.Key.Equals("System.Net.Http.Activity.Stop")) { - Assert.Equal(parentActivity, Activity.Current.Parent); + Assert.NotNull(Activity.Current); activityStopLogged = true; } }); @@ -611,9 +551,6 @@ public void SendAsync_ExpectedDiagnosticCancelledActivityLogging() } }); - Activity parentActivity = new Activity("parent"); - parentActivity.Start(); - using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); From 0706536c55c8d5bc3daaf37dc4441ccc90063fdc Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Wed, 1 Mar 2017 13:47:17 -0800 Subject: [PATCH 9/9] call SetEndTime before stopping activity --- src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs | 1 + src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs | 1 + 2 files changed, 2 insertions(+) diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index b7db836f9cd3..ac2df0e0d844 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -118,6 +118,7 @@ protected internal override async Task SendAsync(HttpReques //always stop activity if it was started if (activity != null) { + activity.SetEndTime(DateTime.UtcNow); s_diagnosticListener.StopActivity(activity, new { Response = responseTask.Status == TaskStatus.RanToCompletion ? responseTask.Result : null, diff --git a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 7a6cab8a9547..095317db458c 100644 --- a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -337,6 +337,7 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLogging() Assert.NotNull(kvp.Value); Assert.NotNull(Activity.Current); Assert.Equal(parentActivity, Activity.Current.Parent); + Assert.True(Activity.Current.Duration != TimeSpan.Zero); GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Response"); activityStopLogged = true;