diff --git a/src/System.Net.Http/src/HttpDiagnosticsGuide.md b/src/System.Net.Http/src/HttpDiagnosticsGuide.md new file mode 100644 index 000000000000..77f24f0495e6 --- /dev/null +++ b/src/System.Net.Http/src/HttpDiagnosticsGuide.md @@ -0,0 +1,94 @@ +# HttpClient Diagnostic Instrumentation Users Guide + +This document describes `HttpClientHandler` instrumentation with [DiagnosticSource](https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.DiagnosticSource/src/DiagnosticSourceUsersGuide.md). + +# Overview +Applications typically log outgoing HTTP requests; typically it's done with DelegatingHandler implementation that logs every request. However in existing system it may require extensive code changes, since DelegatingHandler needs to be added to HttpClient pipeline every time when new client is created. +DiagnosticListener instrumentation allows to enable outgoing request tracing with a few lines of code; it also provides context necessary to correlate logs. + +Context is represented as `System.Diagnostics.Activity` class. Activity may be started as a child of another Activity and the whole operation is represented with a tree of Activities. You can find more details in [Activity User Guide](https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.DiagnosticSource/src/ActivityUserGuide.md). + +Activity carries useful properties for logging such as Id, start time, Tags, Baggage and parent information. + +Instrumentation ensures `Activity.Current` represents current outgoing request in Write event callbacks (if request is instrumented). Consumers **should not** assume `Activity.Current` is accurate in IsEnabled callbacks. + +In microservice environment some context should flow with outgoing requests to correlate telemtry from all services involved in operation processing. +Instrumentation adds context into the request headers: + * Request-Id header with `Activity.Id` value + * Correlation-Context header with `Activity.Baggage` key-value pair list in `k1=v1, k2=v2` format + +See [Http Protocol proposal](https://github.com/lmolkova/correlation/blob/master/http_protocol_proposal_v1.md) for more details +[comment]: TODO: Update link once it's moved + +## Subscription +Instrumentation is off by default; to enable it, consumer first needs to subscribe to DiagnosticListener called "HttpHandlerDiagnosticListener". + +```C# +var subscription = DiagnosticListener.AllListeners.Subscribe(delegate (DiagnosticListener listener) +{ + if (listener.Name == "HttpHandlerDiagnosticListener") + { + listener.Subscribe(delegate (KeyValuePair value) + { + Console.WriteLine($"Event: {value.Key} ActivityName: {Activity.Current.OperationName} Id: {Activity.Current.Id} "); + }); + } +} ); +``` + +## Events +If there is **at least one consumer**, subscribed for "HttpHandlerDiagnosticListener" events, `HttpClientHandler` instruments outgoing request depending on subscription and request properties. + +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 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# + var predicate = (name, r, _) => + { + var request = r as HttpRequestMessage; + if (request != null) + { + return !request.RequestUri.Equals(ElasticSearchUri); + } + return true; + } + listener.Subscribe(observer, predicate); +``` +### System.Net.Http.Activity.Start +After initial instrumentation preconditions are met and `DiagnosticListener.IsEnabled("System.Net.Http.Activity", request)` check is passed, instrumentation starts a new Activity to represent outgoing request. +If **"System.Net.Http.Activity.Start"** is enabled, instrumentation writes it. Event payload has Request property with `HttpRequestMessage` object representing request. + +### System.Net.Http.Activity.Stop +When request is completed (faulted with exception, cancelled or successfully completed), instrumentation stops activity and writes **"System.Net.Http.Activity.Stop"** event. + +Event payload has following properties: +* **Response** with `HttpResponseMessage` object representing response, which could be null if request was failed or cancelled. +* **RequestTaskStatus** with `TaskStatus` enum value that describes status of the request task. + +This event is sent under the same conditions as "System.Net.Http.Activity.Start" event. + +#### 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. + +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", 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 (`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 322484d5ede3..ac2df0e0d844 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; @@ -28,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. @@ -36,28 +38,29 @@ 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); + Activity activity = null; + Guid loggingRequestId = Guid.Empty; - Task responseTask = base.SendAsync(request, cancellationToken); - - LogHttpResponse(responseTask, loggingRequestId); - return responseTask; - } - - #region private - - private static readonly DiagnosticListener s_diagnosticListener = - new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); - - private static void LogHttpRequest(HttpRequestMessage request, Guid loggingRequestId) - { - if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteName)) + // 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 + if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityStartName)) + { + s_diagnosticListener.StartActivity(activity, new { Request = request }); + } + else + { + 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(); - - s_diagnosticListener.Write( - DiagnosticsHandlerLoggingStrings.RequestWriteName, + loggingRequestId = Guid.NewGuid(); + s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated, new { Request = request, @@ -66,44 +69,85 @@ private static void LogHttpRequest(HttpRequestMessage request, Guid loggingReque } ); } - } - private static void LogHttpResponse(Task responseTask, Guid loggingRequestId) - { - responseTask.ContinueWith( - (t, s) => + // 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 = currentActivity.Baggage.GetEnumerator()) { - long timestamp = Stopwatch.GetTimestamp(); - - if (t.IsFaulted && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionWriteName)) + if (e.MoveNext()) { - s_diagnosticListener.Write( - DiagnosticsHandlerLoggingStrings.ExceptionWriteName, - new - { - LoggingRequestId = (Guid) s, - Timestamp = timestamp, - Exception = t.Exception, - } - ); + var baggage = new List(); + do + { + KeyValuePair item = e.Current; + baggage.Add(new NameValueHeaderValue(item.Key, item.Value).ToString()); + } + while (e.MoveNext()); + request.Headers.Add(DiagnosticsHandlerLoggingStrings.CorrelationContextHeaderName, baggage); } + } + } - if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteName)) + 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 (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionEventName)) + { + //If request was initialy instrumented, Activity.Current has all necessary context for logging + //Request is passed to provide some context if instrumentation was disabled and to avoid + //extensive Activity.Tags usage to tunnel request properties + s_diagnosticListener.Write(DiagnosticsHandlerLoggingStrings.ExceptionEventName, new { Exception = ex, Request = request }); + } + throw; + } + finally + { + //always stop activity if it was started + if (activity != null) + { + activity.SetEndTime(DateTime.UtcNow); + s_diagnosticListener.StopActivity(activity, new { - s_diagnosticListener.Write( - DiagnosticsHandlerLoggingStrings.ResponseWriteName, - new - { - Response = t.Status == TaskStatus.RanToCompletion ? t.Result : null, - LoggingRequestId = (Guid) s, - TimeStamp = timestamp, - RequestTaskStatus = t.Status - } - ); - } - }, loggingRequestId, CancellationToken.None, TaskContinuationOptions.None, TaskScheduler.Default); + Response = responseTask.Status == TaskStatus.RanToCompletion ? responseTask.Result : null, + RequestTaskStatus = responseTask.Status + }); + } + //if Activity events are disabled, try to write System.Net.Http.Response event (deprecated) + else if (s_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; } + #region private + + private static readonly DiagnosticListener s_diagnosticListener = + new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); + #endregion } -} +} \ No newline at end of file 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..4cc2a8ec7227 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,14 @@ namespace System.Net.Http internal static class DiagnosticsHandlerLoggingStrings { public const string DiagnosticListenerName = "HttpHandlerDiagnosticListener"; - public const string RequestWriteName = "System.Net.Http.Request"; - public const string ResponseWriteName = "System.Net.Http.Response"; - public const string ExceptionWriteName = "System.Net.Http.Exception"; + public const string RequestWriteNameDeprecated = "System.Net.Http.Request"; + public const string ResponseWriteNameDeprecated = "System.Net.Http.Response"; + + public const string ExceptionEventName = "System.Net.Http.Exception"; + public const string ActivityName = "System.Net.Http.Activity"; + public const string ActivityStartName = "System.Net.Http.Activity.Start"; + + public const string RequestIdHeaderName = "Request-Id"; + public const string CorrelationContextHeaderName = "Correlation-Context"; } } diff --git a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 1c59c9c3e82e..095317db458c 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,8 @@ public void SendAsync_ExpectedDiagnosticSourceNoLogging() { bool requestLogged = false; bool responseLogged = false; + bool activityStartLogged = false; + bool activityStopLogged = false; var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp => { @@ -122,17 +131,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 +238,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 +272,286 @@ 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); + Assert.True(Activity.Current.Duration != TimeSpan.Zero); + 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_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;} + }); + + 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_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; + } + }); + + 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_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; + + 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.NotNull(Activity.Current); + 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() + { + 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; + } + }); + using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver)) { diagnosticListenerObserver.Enable(); @@ -297,5 +604,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); } } }