From 164626c31c76a6aed1311f125cb727bbdff39893 Mon Sep 17 00:00:00 2001 From: Miha Zupan Date: Fri, 18 Jun 2021 15:11:25 +0200 Subject: [PATCH 1/6] Add ActivitySource support to DiagnosticsHandler --- .../src/System.Net.Http.csproj | 3 +- .../src/System/Net/Http/DiagnosticsHandler.cs | 302 ++++++++---------- .../Http/DiagnosticsHandlerLoggingStrings.cs | 25 -- .../src/System/Net/Http/HttpClientHandler.cs | 26 +- .../tests/FunctionalTests/DiagnosticsTests.cs | 164 +++++++--- 5 files changed, 264 insertions(+), 256 deletions(-) delete mode 100644 src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs diff --git a/src/libraries/System.Net.Http/src/System.Net.Http.csproj b/src/libraries/System.Net.Http/src/System.Net.Http.csproj index 0ce5ec1aa171ef..a6034a21e0f5f8 100644 --- a/src/libraries/System.Net.Http/src/System.Net.Http.csproj +++ b/src/libraries/System.Net.Http/src/System.Net.Http.csproj @@ -1,4 +1,4 @@ - + win true @@ -494,7 +494,6 @@ - diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index 4e4d730c4c188a..ace67849cc9683 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -15,103 +15,129 @@ namespace System.Net.Http /// internal sealed class DiagnosticsHandler : DelegatingHandler { - /// - /// DiagnosticHandler constructor - /// - /// Inner handler: Windows or Unix implementation of HttpMessageHandler. - /// Note that DiagnosticHandler is the latest in the pipeline - public DiagnosticsHandler(HttpMessageHandler innerHandler) : base(innerHandler) - { - } + private const string Namespace = "System.Net.Http"; + private const string RequestWriteNameDeprecated = Namespace + ".Request"; + private const string ResponseWriteNameDeprecated = Namespace + ".Response"; + private const string ExceptionEventName = Namespace + ".Exception"; + private const string ActivityName = Namespace + ".HttpRequestOut"; + private const string ActivityStartName = ActivityName + ".Start"; + private const string ActivityStopName = ActivityName + ".Stop"; - internal static bool IsEnabled() + private static readonly DiagnosticListener s_diagnosticListener = new("HttpHandlerDiagnosticListener"); + private static readonly ActivitySource s_activitySource = new(Namespace); + + public static readonly bool IsGloballyEnabled = GetEnableActivityPropagationValue(); + + private static bool GetEnableActivityPropagationValue() { - // check if there is a parent Activity (and propagation is not suppressed) - // or if someone listens to HttpHandlerDiagnosticListener - return IsGloballyEnabled() && (Activity.Current != null || Settings.s_diagnosticListener.IsEnabled()); + // First check for the AppContext switch, giving it priority over the environment variable. + if (AppContext.TryGetSwitch(Namespace + ".EnableActivityPropagation", out bool enableActivityPropagation)) + { + return enableActivityPropagation; + } + + // AppContext switch wasn't used. Check the environment variable to determine which handler should be used. + string? envVar = Environment.GetEnvironmentVariable("DOTNET_SYSTEM_NET_HTTP_ENABLEACTIVITYPROPAGATION"); + if (envVar != null && (envVar.Equals("false", StringComparison.OrdinalIgnoreCase) || envVar.Equals("0"))) + { + // Suppress Activity propagation. + return false; + } + + // Defaults to enabling Activity propagation. + return true; } - internal static bool IsGloballyEnabled() + public DiagnosticsHandler(HttpMessageHandler innerHandler) : base(innerHandler) { - return Settings.s_activityPropagationEnabled; + Debug.Assert(IsGloballyEnabled); } - // SendAsyncCore returns already completed ValueTask for when async: false is passed. - // Internally, it calls the synchronous Send method of the base class. - protected internal override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken) => - SendAsyncCore(request, async: false, cancellationToken).AsTask().GetAwaiter().GetResult(); + private static bool ShouldLogDiagnostics(HttpRequestMessage request, out Activity? activity) + { + if (request is null) + { + throw new ArgumentNullException(nameof(request), SR.net_http_handler_norequest); + } - protected internal override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) => - SendAsyncCore(request, async: true, cancellationToken).AsTask(); + activity = null; - private async ValueTask SendAsyncCore(HttpRequestMessage request, bool async, - CancellationToken cancellationToken) - { - // HttpClientHandler is responsible to call static DiagnosticsHandler.IsEnabled() before forwarding request here. - // It will check if propagation is on (because parent Activity exists or there is a listener) or off (forcibly disabled) - // This code won't be called unless consumer unsubscribes from DiagnosticListener right after the check. - // So some requests happening right after subscription starts might not be instrumented. Similarly, - // when consumer unsubscribes, extra requests might be instrumented + bool currentActivitySet = Activity.Current is not null; + bool diagnosticListenerEnabled = s_diagnosticListener.IsEnabled(); - if (request == null) + if (!currentActivitySet && !diagnosticListenerEnabled) { - throw new ArgumentNullException(nameof(request), SR.net_http_handler_norequest); + return false; } - Activity? activity = null; - DiagnosticListener diagnosticListener = Settings.s_diagnosticListener; + bool diagnosticListenerActivityEnabled = diagnosticListenerEnabled && s_diagnosticListener.IsEnabled(ActivityName, request); - // if there is no listener, but propagation is enabled (with previous IsEnabled() check) - // do not write any events just start/stop Activity and propagate Ids - if (!diagnosticListener.IsEnabled()) + if (diagnosticListenerActivityEnabled || currentActivitySet) { - activity = new Activity(DiagnosticsHandlerLoggingStrings.ActivityName); - activity.Start(); - InjectHeaders(activity, request); + activity = s_activitySource.CreateActivity(ActivityName, ActivityKind.Client); - try + if (activity is null && (diagnosticListenerActivityEnabled || !s_activitySource.HasListeners())) { - return async ? - await base.SendAsync(request, cancellationToken).ConfigureAwait(false) : - base.Send(request, cancellationToken); - } - finally - { - activity.Stop(); + // ActivitySource decided not to create an Activity + // If that is because there were no listeners, manually create an Activity to maintain the behaviour before ActivitySource was introduced + // If a diagnostics listener is enabled for the Activity, always create one + activity = new Activity(ActivityName); } } - Guid loggingRequestId = Guid.Empty; + if (activity is null) + { + // There is no Activity, but we may still want to use the instrumented SendAsyncCore if diagnostic listeners are interested in other events + return diagnosticListenerEnabled; + } + + activity.Start(); - // There is a listener. Check if listener wants to be notified about HttpClient Activities - if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityName, request)) + if (diagnosticListenerActivityEnabled && s_diagnosticListener.IsEnabled(ActivityStartName)) { - activity = new Activity(DiagnosticsHandlerLoggingStrings.ActivityName); + Write(ActivityStartName, new ActivityStartData(request)); + } - // Only send start event to users who subscribed for it, but start activity anyway - if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ActivityStartName)) - { - StartActivity(diagnosticListener, activity, new ActivityStartData(request)); - } - else - { - activity.Start(); - } + InjectHeaders(activity, request); + + return true; + } + + protected internal override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken) + { + if (ShouldLogDiagnostics(request, out Activity? activity)) + { + ValueTask sendTask = SendAsyncCore(request, activity, async: false, cancellationToken); + return sendTask.IsCompleted ? + sendTask.Result : + sendTask.AsTask().GetAwaiter().GetResult(); } - // try to write System.Net.Http.Request event (deprecated) - if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated)) + else { - long timestamp = Stopwatch.GetTimestamp(); - loggingRequestId = Guid.NewGuid(); - Write(diagnosticListener, DiagnosticsHandlerLoggingStrings.RequestWriteNameDeprecated, - new RequestData(request, loggingRequestId, timestamp)); + return base.Send(request, cancellationToken); } + } - // If we are on at all, we propagate current activity information - Activity? currentActivity = Activity.Current; - if (currentActivity != null) + protected internal override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) + { + if (ShouldLogDiagnostics(request, out Activity? activity)) { - InjectHeaders(currentActivity, request); + return SendAsyncCore(request, activity, async: true, cancellationToken).AsTask(); + } + else + { + return base.SendAsync(request, cancellationToken); + } + } + + private async ValueTask SendAsyncCore(HttpRequestMessage request, Activity? activity, bool async, CancellationToken cancellationToken) + { + Guid loggingRequestId = default; + + if (s_diagnosticListener.IsEnabled(RequestWriteNameDeprecated)) + { + loggingRequestId = Guid.NewGuid(); + Write(RequestWriteNameDeprecated, new RequestData(request, loggingRequestId, Stopwatch.GetTimestamp())); } HttpResponseMessage? response = null; @@ -123,55 +149,50 @@ await base.SendAsync(request, cancellationToken).ConfigureAwait(false) : base.Send(request, cancellationToken); return response; } - catch (OperationCanceledException) + catch (Exception ex) when (LogException(ex, request, ref taskStatus)) { - taskStatus = TaskStatus.Canceled; - - // we'll report task status in HttpRequestOut.Stop throw; } - catch (Exception ex) + finally { - taskStatus = TaskStatus.Faulted; + if (activity is not null) + { + activity.SetEndTime(DateTime.UtcNow); + + if (s_diagnosticListener.IsEnabled(ActivityStopName)) + { + Write(ActivityStopName, new ActivityStopData(response, request, taskStatus)); + } + + activity.Stop(); + } - if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionEventName)) + if (s_diagnosticListener.IsEnabled(ResponseWriteNameDeprecated)) { - // If request was initially 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 - Write(diagnosticListener, DiagnosticsHandlerLoggingStrings.ExceptionEventName, new ExceptionData(ex, request)); + Write(ResponseWriteNameDeprecated, new ResponseData(response, loggingRequestId, Stopwatch.GetTimestamp(), taskStatus)); } - throw; } - finally + + static bool LogException(Exception ex, HttpRequestMessage request, ref TaskStatus taskStatus) { - // always stop activity if it was started - if (activity != null) + if (ex is OperationCanceledException) { - StopActivity(diagnosticListener, activity, new ActivityStopData( - response, - // If request is failed or cancelled, there is no response, therefore no information about request; - // pass the request in the payload, so consumers can have it in Stop for failed/canceled requests - // and not retain all requests in Start - request, - taskStatus)); + taskStatus = TaskStatus.Canceled; } - // Try to write System.Net.Http.Response event (deprecated) - if (diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated)) + else { - long timestamp = Stopwatch.GetTimestamp(); - Write(diagnosticListener, DiagnosticsHandlerLoggingStrings.ResponseWriteNameDeprecated, - new ResponseData( - response, - loggingRequestId, - timestamp, - taskStatus)); + taskStatus = TaskStatus.Faulted; + + if (s_diagnosticListener.IsEnabled(ExceptionEventName)) + { + Write(ExceptionEventName, new ExceptionData(ex, request)); + } } + + return false; } } - #region private - private sealed class ActivityStartData { // matches the properties selected in https://github.com/dotnet/diagnostics/blob/ffd0254da3bcc47847b1183fa5453c0877020abd/src/Microsoft.Diagnostics.Monitoring.EventPipe/Configuration/HttpRequestSourceConfiguration.cs#L36-L40 @@ -269,55 +290,29 @@ internal ResponseData(HttpResponseMessage? response, Guid loggingRequestId, long public override string ToString() => $"{{ {nameof(Response)} = {Response}, {nameof(LoggingRequestId)} = {LoggingRequestId}, {nameof(Timestamp)} = {Timestamp}, {nameof(RequestTaskStatus)} = {RequestTaskStatus} }}"; } - private static class Settings - { - private const string EnableActivityPropagationEnvironmentVariableSettingName = "DOTNET_SYSTEM_NET_HTTP_ENABLEACTIVITYPROPAGATION"; - private const string EnableActivityPropagationAppCtxSettingName = "System.Net.Http.EnableActivityPropagation"; - - public static readonly bool s_activityPropagationEnabled = GetEnableActivityPropagationValue(); - - private static bool GetEnableActivityPropagationValue() - { - // First check for the AppContext switch, giving it priority over the environment variable. - if (AppContext.TryGetSwitch(EnableActivityPropagationAppCtxSettingName, out bool enableActivityPropagation)) - { - return enableActivityPropagation; - } - - // AppContext switch wasn't used. Check the environment variable to determine which handler should be used. - string? envVar = Environment.GetEnvironmentVariable(EnableActivityPropagationEnvironmentVariableSettingName); - if (envVar != null && (envVar.Equals("false", StringComparison.OrdinalIgnoreCase) || envVar.Equals("0"))) - { - // Suppress Activity propagation. - return false; - } - - // Defaults to enabling Activity propagation. - return true; - } - - public static readonly DiagnosticListener s_diagnosticListener = - new DiagnosticListener(DiagnosticsHandlerLoggingStrings.DiagnosticListenerName); - } - private static void InjectHeaders(Activity currentActivity, HttpRequestMessage request) { + const string TraceParentHeaderName = "traceparent"; + const string TraceStateHeaderName = "tracestate"; + const string RequestIdHeaderName = "Request-Id"; + const string CorrelationContextHeaderName = "Correlation-Context"; + if (currentActivity.IdFormat == ActivityIdFormat.W3C) { - if (!request.Headers.Contains(DiagnosticsHandlerLoggingStrings.TraceParentHeaderName)) + if (!request.Headers.Contains(TraceParentHeaderName)) { - request.Headers.TryAddWithoutValidation(DiagnosticsHandlerLoggingStrings.TraceParentHeaderName, currentActivity.Id); + request.Headers.TryAddWithoutValidation(TraceParentHeaderName, currentActivity.Id); if (currentActivity.TraceStateString != null) { - request.Headers.TryAddWithoutValidation(DiagnosticsHandlerLoggingStrings.TraceStateHeaderName, currentActivity.TraceStateString); + request.Headers.TryAddWithoutValidation(TraceStateHeaderName, currentActivity.TraceStateString); } } } else { - if (!request.Headers.Contains(DiagnosticsHandlerLoggingStrings.RequestIdHeaderName)) + if (!request.Headers.Contains(RequestIdHeaderName)) { - request.Headers.TryAddWithoutValidation(DiagnosticsHandlerLoggingStrings.RequestIdHeaderName, currentActivity.Id); + request.Headers.TryAddWithoutValidation(RequestIdHeaderName, currentActivity.Id); } } @@ -333,41 +328,16 @@ private static void InjectHeaders(Activity currentActivity, HttpRequestMessage r baggage.Add(new NameValueHeaderValue(WebUtility.UrlEncode(item.Key), WebUtility.UrlEncode(item.Value)).ToString()); } while (e.MoveNext()); - request.Headers.TryAddWithoutValidation(DiagnosticsHandlerLoggingStrings.CorrelationContextHeaderName, baggage); + request.Headers.TryAddWithoutValidation(CorrelationContextHeaderName, baggage); } } } [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:UnrecognizedReflectionPattern", Justification = "The values being passed into Write have the commonly used properties being preserved with DynamicDependency.")] - private static void Write<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicProperties)] T>( - DiagnosticSource diagnosticSource, - string name, - T value) - { - diagnosticSource.Write(name, value); - } - - [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:UnrecognizedReflectionPattern", - Justification = "The args being passed into StartActivity have the commonly used properties being preserved with DynamicDependency.")] - private static Activity StartActivity<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicProperties)] T>( - DiagnosticSource diagnosticSource, - Activity activity, - T? args) + private static void Write<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicProperties)] T>(string name, T value) { - return diagnosticSource.StartActivity(activity, args); + s_diagnosticListener.Write(name, value); } - - [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026:UnrecognizedReflectionPattern", - Justification = "The args being passed into StopActivity have the commonly used properties being preserved with DynamicDependency.")] - private static void StopActivity<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicProperties)] T>( - DiagnosticSource diagnosticSource, - Activity activity, - T? args) - { - diagnosticSource.StopActivity(activity, args); - } - - #endregion } } diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs deleted file mode 100644 index 0fa57394c1cc32..00000000000000 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs +++ /dev/null @@ -1,25 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -namespace System.Net.Http -{ - /// - /// Defines names of DiagnosticListener and Write events for DiagnosticHandler - /// - internal static class DiagnosticsHandlerLoggingStrings - { - public const string DiagnosticListenerName = "HttpHandlerDiagnosticListener"; - 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.HttpRequestOut"; - public const string ActivityStartName = "System.Net.Http.HttpRequestOut.Start"; - - public const string RequestIdHeaderName = "Request-Id"; - public const string CorrelationContextHeaderName = "Correlation-Context"; - - public const string TraceParentHeaderName = "traceparent"; - public const string TraceStateHeaderName = "tracestate"; - } -} diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/HttpClientHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/HttpClientHandler.cs index 2e3289643cfbed..bfb8f6cae78348 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/HttpClientHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/HttpClientHandler.cs @@ -20,17 +20,17 @@ namespace System.Net.Http public partial class HttpClientHandler : HttpMessageHandler { private readonly HttpHandlerType _underlyingHandler; - private readonly DiagnosticsHandler? _diagnosticsHandler; + private readonly HttpMessageHandler _handler; private ClientCertificateOption _clientCertificateOptions; private volatile bool _disposed; public HttpClientHandler() { - _underlyingHandler = new HttpHandlerType(); - if (DiagnosticsHandler.IsGloballyEnabled()) + _handler = _underlyingHandler = new HttpHandlerType(); + if (DiagnosticsHandler.IsGloballyEnabled) { - _diagnosticsHandler = new DiagnosticsHandler(_underlyingHandler); + _handler = new DiagnosticsHandler(_handler); } ClientCertificateOptions = ClientCertificateOption.Manual; } @@ -288,21 +288,11 @@ public SslProtocols SslProtocols public IDictionary Properties => _underlyingHandler.Properties; [UnsupportedOSPlatform("browser")] - protected internal override HttpResponseMessage Send(HttpRequestMessage request, - CancellationToken cancellationToken) - { - return DiagnosticsHandler.IsEnabled() && _diagnosticsHandler != null ? - _diagnosticsHandler.Send(request, cancellationToken) : - _underlyingHandler.Send(request, cancellationToken); - } + protected internal override HttpResponseMessage Send(HttpRequestMessage request, CancellationToken cancellationToken) => + _handler.Send(request, cancellationToken); - protected internal override Task SendAsync(HttpRequestMessage request, - CancellationToken cancellationToken) - { - return DiagnosticsHandler.IsEnabled() && _diagnosticsHandler != null ? - _diagnosticsHandler.SendAsync(request, cancellationToken) : - _underlyingHandler.SendAsync(request, cancellationToken); - } + protected internal override Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) => + _handler.SendAsync(request, cancellationToken); // lazy-load the validator func so it can be trimmed by the ILLinker if it isn't used. private static Func? s_dangerousAcceptAnyServerCertificateValidator; diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index f11b84b34a72ed..4d77e310c2efa3 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -5,6 +5,7 @@ using System.Collections.Generic; using System.Diagnostics; using System.Diagnostics.Tracing; +using System.IO; using System.Linq; using System.Net.Http.Headers; using System.Net.Test.Common; @@ -273,7 +274,7 @@ public void SendAsync_ExpectedDiagnosticCancelledLogging() GetProperty(kvp.Value, "Request"); TaskStatus status = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.Canceled, status); - activityStopTcs.SetResult();; + activityStopTcs.SetResult(); } }); @@ -361,7 +362,7 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLogging(ActivityIdFormat i activityStopResponseLogged = GetProperty(kvp.Value, "Response"); TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.RanToCompletion, requestStatus); - activityStopTcs.SetResult();; + activityStopTcs.SetResult(); } }); @@ -426,7 +427,7 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLogging_InvalidBaggage() Assert.Contains("goodkey=bad%2Fvalue", correlationContext); TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.RanToCompletion, requestStatus); - activityStopTcs.SetResult();; + activityStopTcs.SetResult(); } else if (kvp.Key.Equals("System.Net.Http.Exception")) { @@ -484,7 +485,7 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLoggingDoesNotOverwriteHea Assert.False(request.Headers.TryGetValues("traceparent", out var _)); Assert.False(request.Headers.TryGetValues("tracestate", out var _)); - activityStopTcs.SetResult();; + activityStopTcs.SetResult(); } }); @@ -536,7 +537,7 @@ public void SendAsync_ExpectedDiagnosticSourceActivityLoggingDoesNotOverwriteW3C } else if (kvp.Key.Equals("System.Net.Http.HttpRequestOut.Stop")) { - activityStopTcs.SetResult();; + activityStopTcs.SetResult(); } }); @@ -625,7 +626,7 @@ public void SendAsync_ExpectedDiagnosticExceptionActivityLogging() GetProperty(kvp.Value, "Request"); TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.Faulted, requestStatus); - activityStopTcs.SetResult();; + activityStopTcs.SetResult(); } else if (kvp.Key.Equals("System.Net.Http.Exception")) { @@ -664,7 +665,7 @@ public void SendAsync_ExpectedDiagnosticSynchronousExceptionActivityLogging() GetProperty(kvp.Value, "Request"); TaskStatus requestStatus = GetProperty(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.Faulted, requestStatus); - activityStopTcs.SetResult();; + activityStopTcs.SetResult(); } else if (kvp.Key.Equals("System.Net.Http.Exception")) { @@ -813,44 +814,6 @@ public void SendAsync_ExpectedDiagnosticExceptionOnlyActivityLogging() }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); } - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void SendAsync_ExpectedActivityPropagationWithoutListener() - { - RemoteExecutor.Invoke(async (useVersion, testAsync) => - { - Activity parent = new Activity("parent").Start(); - - await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( - async uri => - { - await GetAsync(useVersion, testAsync, uri); - }, - async server => - { - HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(); - AssertHeadersAreInjected(requestData, parent); - }); - }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); - } - - [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - public void SendAsync_ExpectedActivityPropagationWithoutListenerOrParentActivity() - { - RemoteExecutor.Invoke(async (useVersion, testAsync) => - { - await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( - async uri => - { - await GetAsync(useVersion, testAsync, uri); - }, - async server => - { - HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(); - AssertNoHeadersAreInjected(requestData); - }); - }, UseVersion.ToString(), TestAsync.ToString()).Dispose(); - } - [ConditionalTheory(nameof(EnableActivityPropagationEnvironmentVariableIsNotSetAndRemoteExecutorSupported))] [InlineData("true")] [InlineData("1")] @@ -916,6 +879,117 @@ await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( }, UseVersion.ToString(), TestAsync.ToString(), switchValue.ToString()).Dispose(); } + [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] + [InlineData(true, true, true, true)] // Activity was set and ActivitySource created an Activity + [InlineData(true, false, true, true)] // Activity was set and ActivitySource created an Activity + [InlineData(true, null, true, true)] // Activity was set and ActivitySource created an Activity + [InlineData(true, true, false, true)] // Activity was set, ActivitySource chose not to create an Activity, but a DiagnosticListener requested one + [InlineData(true, false, false, false)] // Activity was set but ActivitySource chose not to create an Activity + [InlineData(true, null, false, false)] // Activity was set but ActivitySource chose not to create an Activity + [InlineData(true, true, null, true)] // Activity was set and there is no ActivitySource + [InlineData(true, false, null, true)] // Activity was set and there is no ActivitySource + [InlineData(true, null, null, true)] // Activity was set and there is no ActivitySource + [InlineData(false, true, true, true)] // DiagnosticListener requested an Activity and ActivitySource created an Activity + [InlineData(false, true, false, true)] // DiagnosticListener requested an Activity, ActivitySource chose not to create an Activity, so one was manually created + [InlineData(false, true, null, true)] // DiagnosticListener requested an Activity, there was no ActivitySource, so an Activity was manually created + [InlineData(false, false, true, false, false)] // No Activity is set and DiagnosticListener does not want one (ActivitySource does not come into play) + [InlineData(false, false, false, false, false)] // No Activity is set and DiagnosticListener does not want one (ActivitySource does not come into play) + [InlineData(false, false, null, false, false)] // No Activity is set and DiagnosticListener does not want one (ActivitySource does not come into play) + [InlineData(false, null, true, false, false)] // No Activity is set and there is no DiagnosticListener (ActivitySource does not come into play) + [InlineData(false, null, false, false, false)] // No Activity is set and there is no DiagnosticListener (ActivitySource does not come into play) + [InlineData(false, null, null, false, false)] // No Activity is set and there is no DiagnosticListener (ActivitySource does not come into play) + public void SendAsync_ActivityIsCreatedIfRequested(bool currentActivitySet, bool? diagnosticListenerActivityEnabled, bool? activitySourceCreatesActivity, bool shouldHaveActivity, bool activitySourceShouldMakeASamplingDecision = true) + { + string parameters = $"{currentActivitySet},{diagnosticListenerActivityEnabled},{activitySourceCreatesActivity},{shouldHaveActivity},{activitySourceShouldMakeASamplingDecision}"; + + RemoteExecutor.Invoke(async (useVersion, testAsync, parametersString) => + { + bool?[] parameters = parametersString.Split(',').Select(p => p.Length == 0 ? (bool?)null : bool.Parse(p)).ToArray(); + bool currentActivitySet = parameters[0].Value; + bool? diagnosticListenerActivityEnabled = parameters[1]; + bool? activitySourceCreatesActivity = parameters[2]; + bool shouldHaveActivity = parameters[3].Value; + bool activitySourceShouldMakeASamplingDecision = parameters[4].Value && activitySourceCreatesActivity.HasValue; + + bool madeASamplingDecision = false; + if (activitySourceCreatesActivity.HasValue) + { + var listener = new ActivityListener + { + ShouldListenTo = _ => true, + Sample = Sample + }; + + ActivitySamplingResult Sample(ref ActivityCreationOptions options) + { + madeASamplingDecision = true; + return activitySourceCreatesActivity.Value ? ActivitySamplingResult.AllData : ActivitySamplingResult.None; + } + + ActivitySource.AddActivityListener(listener); + } + + bool listenerCallbackWasCalled = false; + IDisposable listenerSubscription = new MemoryStream(); // Dummy disposable + if (diagnosticListenerActivityEnabled.HasValue) + { + var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(_ => listenerCallbackWasCalled = true); + + diagnosticListenerObserver.Enable(name => !name.Contains("HttpRequestOut") || diagnosticListenerActivityEnabled.Value); + + listenerSubscription = DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver); + } + + Activity activity = currentActivitySet ? new Activity("parent").Start() : null; + + if (!currentActivitySet) + { + // Listen to new activity creations if an Activity was created without a parent + // (when a DiagnosticListener forced one to be created) + ActivitySource.AddActivityListener(new ActivityListener + { + ShouldListenTo = _ => true, + ActivityStarted = created => + { + Assert.Null(activity); + activity = created; + } + }); + } + + using (listenerSubscription) + { + await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( + async uri => + { + await GetAsync(useVersion, testAsync, uri); + }, + async server => + { + HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(); + + if (shouldHaveActivity) + { + Assert.NotNull(activity); + AssertHeadersAreInjected(requestData, activity); + } + else + { + AssertNoHeadersAreInjected(requestData); + + if (!currentActivitySet) + { + Assert.Null(activity); + } + } + }); + } + + Assert.Equal(activitySourceShouldMakeASamplingDecision, madeASamplingDecision); + Assert.Equal(diagnosticListenerActivityEnabled.HasValue, listenerCallbackWasCalled); + }, UseVersion.ToString(), TestAsync.ToString(), parameters).Dispose(); + } + private static T GetProperty(object obj, string propertyName) { Type t = obj.GetType(); From 99fd03cb083c2f77262ca6ae855f0f8e45125ebc Mon Sep 17 00:00:00 2001 From: Miha Zupan Date: Tue, 22 Jun 2021 16:03:39 +0200 Subject: [PATCH 2/6] Use ActivitySource as another enabled condition --- .../src/System/Net/Http/DiagnosticsHandler.cs | 36 +++++------ .../tests/FunctionalTests/DiagnosticsTests.cs | 64 +++++++++---------- 2 files changed, 46 insertions(+), 54 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index ace67849cc9683..8746a44009ee0a 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -62,38 +62,36 @@ private static bool ShouldLogDiagnostics(HttpRequestMessage request, out Activit activity = null; - bool currentActivitySet = Activity.Current is not null; - bool diagnosticListenerEnabled = s_diagnosticListener.IsEnabled(); - - if (!currentActivitySet && !diagnosticListenerEnabled) + if (s_activitySource.HasListeners()) { - return false; + activity = s_activitySource.CreateActivity(ActivityName, ActivityKind.Client); } - bool diagnosticListenerActivityEnabled = diagnosticListenerEnabled && s_diagnosticListener.IsEnabled(ActivityName, request); - - if (diagnosticListenerActivityEnabled || currentActivitySet) + if (activity is null) { - activity = s_activitySource.CreateActivity(ActivityName, ActivityKind.Client); + bool currentActivitySet = Activity.Current is not null; + bool diagnosticListenerEnabled = s_diagnosticListener.IsEnabled(); + + if (!currentActivitySet && !diagnosticListenerEnabled) + { + return false; + } - if (activity is null && (diagnosticListenerActivityEnabled || !s_activitySource.HasListeners())) + if (currentActivitySet || (diagnosticListenerEnabled && s_diagnosticListener.IsEnabled(ActivityName, request))) { - // ActivitySource decided not to create an Activity - // If that is because there were no listeners, manually create an Activity to maintain the behaviour before ActivitySource was introduced // If a diagnostics listener is enabled for the Activity, always create one activity = new Activity(ActivityName); } - } - - if (activity is null) - { - // There is no Activity, but we may still want to use the instrumented SendAsyncCore if diagnostic listeners are interested in other events - return diagnosticListenerEnabled; + else + { + // There is no Activity, but we may still want to use the instrumented SendAsyncCore if diagnostic listeners are interested in other events + return diagnosticListenerEnabled; + } } activity.Start(); - if (diagnosticListenerActivityEnabled && s_diagnosticListener.IsEnabled(ActivityStartName)) + if (s_diagnosticListener.IsEnabled(ActivityStartName)) { Write(ActivityStartName, new ActivityStartData(request)); } diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index 4d77e310c2efa3..ab97d8a283107f 100644 --- a/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/src/libraries/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs @@ -880,27 +880,27 @@ await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( } [ConditionalTheory(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] - [InlineData(true, true, true, true)] // Activity was set and ActivitySource created an Activity - [InlineData(true, false, true, true)] // Activity was set and ActivitySource created an Activity - [InlineData(true, null, true, true)] // Activity was set and ActivitySource created an Activity - [InlineData(true, true, false, true)] // Activity was set, ActivitySource chose not to create an Activity, but a DiagnosticListener requested one - [InlineData(true, false, false, false)] // Activity was set but ActivitySource chose not to create an Activity - [InlineData(true, null, false, false)] // Activity was set but ActivitySource chose not to create an Activity - [InlineData(true, true, null, true)] // Activity was set and there is no ActivitySource - [InlineData(true, false, null, true)] // Activity was set and there is no ActivitySource - [InlineData(true, null, null, true)] // Activity was set and there is no ActivitySource - [InlineData(false, true, true, true)] // DiagnosticListener requested an Activity and ActivitySource created an Activity - [InlineData(false, true, false, true)] // DiagnosticListener requested an Activity, ActivitySource chose not to create an Activity, so one was manually created - [InlineData(false, true, null, true)] // DiagnosticListener requested an Activity, there was no ActivitySource, so an Activity was manually created - [InlineData(false, false, true, false, false)] // No Activity is set and DiagnosticListener does not want one (ActivitySource does not come into play) - [InlineData(false, false, false, false, false)] // No Activity is set and DiagnosticListener does not want one (ActivitySource does not come into play) - [InlineData(false, false, null, false, false)] // No Activity is set and DiagnosticListener does not want one (ActivitySource does not come into play) - [InlineData(false, null, true, false, false)] // No Activity is set and there is no DiagnosticListener (ActivitySource does not come into play) - [InlineData(false, null, false, false, false)] // No Activity is set and there is no DiagnosticListener (ActivitySource does not come into play) - [InlineData(false, null, null, false, false)] // No Activity is set and there is no DiagnosticListener (ActivitySource does not come into play) - public void SendAsync_ActivityIsCreatedIfRequested(bool currentActivitySet, bool? diagnosticListenerActivityEnabled, bool? activitySourceCreatesActivity, bool shouldHaveActivity, bool activitySourceShouldMakeASamplingDecision = true) + [InlineData(true, true, true)] // Activity was set and ActivitySource created an Activity + [InlineData(true, false, true)] // Activity was set and ActivitySource created an Activity + [InlineData(true, null, true)] // Activity was set and ActivitySource created an Activity + [InlineData(true, true, false)] // Activity was set, ActivitySource chose not to create an Activity, so one was manually created + [InlineData(true, false, false)] // Activity was set, ActivitySource chose not to create an Activity, so one was manually created + [InlineData(true, null, false)] // Activity was set, ActivitySource chose not to create an Activity, so one was manually created + [InlineData(true, true, null)] // Activity was set, ActivitySource had no listeners, so an Activity was manually created + [InlineData(true, false, null)] // Activity was set, ActivitySource had no listeners, so an Activity was manually created + [InlineData(true, null, null)] // Activity was set, ActivitySource had no listeners, so an Activity was manually created + [InlineData(false, true, true)] // DiagnosticListener requested an Activity and ActivitySource created an Activity + [InlineData(false, true, false)] // DiagnosticListener requested an Activity, ActivitySource chose not to create an Activity, so one was manually created + [InlineData(false, true, null)] // DiagnosticListener requested an Activity, ActivitySource had no listeners, so an Activity was manually created + [InlineData(false, false, true)] // No Activity is set, DiagnosticListener does not want one, but ActivitySource created an Activity + [InlineData(false, false, false)] // No Activity is set, DiagnosticListener does not want one and ActivitySource chose not to create an Activity + [InlineData(false, false, null)] // No Activity is set, DiagnosticListener does not want one and ActivitySource has no listeners + [InlineData(false, null, true)] // No Activity is set, there is no DiagnosticListener, but ActivitySource created an Activity + [InlineData(false, null, false)] // No Activity is set, there is no DiagnosticListener and ActivitySource chose not to create an Activity + [InlineData(false, null, null)] // No Activity is set, there is no DiagnosticListener and ActivitySource has no listeners + public void SendAsync_ActivityIsCreatedIfRequested(bool currentActivitySet, bool? diagnosticListenerActivityEnabled, bool? activitySourceCreatesActivity) { - string parameters = $"{currentActivitySet},{diagnosticListenerActivityEnabled},{activitySourceCreatesActivity},{shouldHaveActivity},{activitySourceShouldMakeASamplingDecision}"; + string parameters = $"{currentActivitySet},{diagnosticListenerActivityEnabled},{activitySourceCreatesActivity}"; RemoteExecutor.Invoke(async (useVersion, testAsync, parametersString) => { @@ -908,25 +908,19 @@ public void SendAsync_ActivityIsCreatedIfRequested(bool currentActivitySet, bool bool currentActivitySet = parameters[0].Value; bool? diagnosticListenerActivityEnabled = parameters[1]; bool? activitySourceCreatesActivity = parameters[2]; - bool shouldHaveActivity = parameters[3].Value; - bool activitySourceShouldMakeASamplingDecision = parameters[4].Value && activitySourceCreatesActivity.HasValue; bool madeASamplingDecision = false; if (activitySourceCreatesActivity.HasValue) { - var listener = new ActivityListener + ActivitySource.AddActivityListener(new ActivityListener { ShouldListenTo = _ => true, - Sample = Sample - }; - - ActivitySamplingResult Sample(ref ActivityCreationOptions options) - { - madeASamplingDecision = true; - return activitySourceCreatesActivity.Value ? ActivitySamplingResult.AllData : ActivitySamplingResult.None; - } - - ActivitySource.AddActivityListener(listener); + Sample = (ref ActivityCreationOptions _) => + { + madeASamplingDecision = true; + return activitySourceCreatesActivity.Value ? ActivitySamplingResult.AllData : ActivitySamplingResult.None; + } + }); } bool listenerCallbackWasCalled = false; @@ -968,7 +962,7 @@ await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( { HttpRequestData requestData = await server.AcceptConnectionSendResponseAndCloseAsync(); - if (shouldHaveActivity) + if (currentActivitySet || diagnosticListenerActivityEnabled == true || activitySourceCreatesActivity == true) { Assert.NotNull(activity); AssertHeadersAreInjected(requestData, activity); @@ -985,7 +979,7 @@ await GetFactoryForVersion(useVersion).CreateClientAndServerAsync( }); } - Assert.Equal(activitySourceShouldMakeASamplingDecision, madeASamplingDecision); + Assert.Equal(activitySourceCreatesActivity.HasValue, madeASamplingDecision); Assert.Equal(diagnosticListenerActivityEnabled.HasValue, listenerCallbackWasCalled); }, UseVersion.ToString(), TestAsync.ToString(), parameters).Dispose(); } From 214c726710eb2f4a7223ae1a1ead577dfe5030bf Mon Sep 17 00:00:00 2001 From: Miha Zupan Date: Tue, 22 Jun 2021 16:05:12 +0200 Subject: [PATCH 3/6] Make IsGloballyEnabled a property --- .../System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index 8746a44009ee0a..4fc32535ce53b5 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -26,7 +26,7 @@ internal sealed class DiagnosticsHandler : DelegatingHandler private static readonly DiagnosticListener s_diagnosticListener = new("HttpHandlerDiagnosticListener"); private static readonly ActivitySource s_activitySource = new(Namespace); - public static readonly bool IsGloballyEnabled = GetEnableActivityPropagationValue(); + public static bool IsGloballyEnabled { get; } = GetEnableActivityPropagationValue(); private static bool GetEnableActivityPropagationValue() { From 53c2c527128d0f8935ae42efa5f8d986dbc668d9 Mon Sep 17 00:00:00 2001 From: Miha Zupan Date: Tue, 22 Jun 2021 16:13:21 +0200 Subject: [PATCH 4/6] Simplify enabled check --- .../src/System/Net/Http/DiagnosticsHandler.cs | 8 +------- 1 file changed, 1 insertion(+), 7 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index 4fc32535ce53b5..6748c10f82dfe9 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -69,15 +69,9 @@ private static bool ShouldLogDiagnostics(HttpRequestMessage request, out Activit if (activity is null) { - bool currentActivitySet = Activity.Current is not null; bool diagnosticListenerEnabled = s_diagnosticListener.IsEnabled(); - if (!currentActivitySet && !diagnosticListenerEnabled) - { - return false; - } - - if (currentActivitySet || (diagnosticListenerEnabled && s_diagnosticListener.IsEnabled(ActivityName, request))) + if (Activity.Current is not null || (diagnosticListenerEnabled && s_diagnosticListener.IsEnabled(ActivityName, request))) { // If a diagnostics listener is enabled for the Activity, always create one activity = new Activity(ActivityName); From cd0529d95bce818bb7984c297b5ec57992972252 Mon Sep 17 00:00:00 2001 From: Miha Zupan Date: Wed, 23 Jun 2021 12:38:21 +0200 Subject: [PATCH 5/6] Revert using the exception filter --- .../src/System/Net/Http/DiagnosticsHandler.cs | 32 +++++++------------ 1 file changed, 12 insertions(+), 20 deletions(-) diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index 6748c10f82dfe9..14c1464e77a70a 100644 --- a/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/src/libraries/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs @@ -141,8 +141,19 @@ await base.SendAsync(request, cancellationToken).ConfigureAwait(false) : base.Send(request, cancellationToken); return response; } - catch (Exception ex) when (LogException(ex, request, ref taskStatus)) + catch (OperationCanceledException) { + taskStatus = TaskStatus.Canceled; + throw; + } + catch (Exception ex) + { + if (s_diagnosticListener.IsEnabled(ExceptionEventName)) + { + Write(ExceptionEventName, new ExceptionData(ex, request)); + } + + taskStatus = TaskStatus.Faulted; throw; } finally @@ -164,25 +175,6 @@ await base.SendAsync(request, cancellationToken).ConfigureAwait(false) : Write(ResponseWriteNameDeprecated, new ResponseData(response, loggingRequestId, Stopwatch.GetTimestamp(), taskStatus)); } } - - static bool LogException(Exception ex, HttpRequestMessage request, ref TaskStatus taskStatus) - { - if (ex is OperationCanceledException) - { - taskStatus = TaskStatus.Canceled; - } - else - { - taskStatus = TaskStatus.Faulted; - - if (s_diagnosticListener.IsEnabled(ExceptionEventName)) - { - Write(ExceptionEventName, new ExceptionData(ex, request)); - } - } - - return false; - } } private sealed class ActivityStartData From e8fa3a80c6566ef4ca8b04c226fea6ccf0534718 Mon Sep 17 00:00:00 2001 From: Miha Zupan Date: Wed, 23 Jun 2021 18:31:10 +0200 Subject: [PATCH 6/6] Update HTTP ILLink.Substitutions.xml --- .../System.Net.Http/src/ILLink/ILLink.Substitutions.xml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/libraries/System.Net.Http/src/ILLink/ILLink.Substitutions.xml b/src/libraries/System.Net.Http/src/ILLink/ILLink.Substitutions.xml index 314469c96d7775..d6aea3dbf37e46 100644 --- a/src/libraries/System.Net.Http/src/ILLink/ILLink.Substitutions.xml +++ b/src/libraries/System.Net.Http/src/ILLink/ILLink.Substitutions.xml @@ -1,7 +1,7 @@ - +