From 0f10c14fe51c8069699901fe61bcbd1dd40d5af4 Mon Sep 17 00:00:00 2001 From: Sourabh Shirhatti Date: Wed, 10 Feb 2021 23:44:06 -0800 Subject: [PATCH 1/7] WIP: Migrate to ActivitySource --- .../Internal/HostingApplicationDiagnostics.cs | 116 +++++++++--------- .../HostingApplicationDiagnosticsTests.cs | 6 +- 2 files changed, 60 insertions(+), 62 deletions(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index f7735093d20d..38d85cb632df 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -24,6 +24,10 @@ internal class HostingApplicationDiagnostics private const string DeprecatedDiagnosticsEndRequestKey = "Microsoft.AspNetCore.Hosting.EndRequest"; private const string DiagnosticsUnhandledExceptionKey = "Microsoft.AspNetCore.Hosting.UnhandledException"; + private const string ActivitySourceName = "Microsoft.AspNetCore.Hosting"; + private static readonly ActivitySource _activitySource = new ActivitySource(ActivitySourceName); + private ActivityListener? _dummyListener; + private readonly DiagnosticListener _diagnosticListener; private readonly ILogger _logger; @@ -48,11 +52,19 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con var diagnosticListenerEnabled = _diagnosticListener.IsEnabled(); var loggingEnabled = _logger.IsEnabled(LogLevel.Critical); + // TODO: If loggingEnabled check to change to if ActivityPropogation options are enabled if (loggingEnabled || (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext))) { - context.Activity = StartActivity(httpContext, out var hasDiagnosticListener); - context.HasDiagnosticListener = hasDiagnosticListener; + // Review: Force creation of Activity by creating dummy listener + _dummyListener = new ActivityListener() + { + ShouldListenTo = activitySource => activitySource.Name.Equals(ActivitySourceName), + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.PropagationData + }; + ActivitySource.AddActivityListener(_dummyListener); } + context.Activity = StartActivity(httpContext, out var hasDiagnosticListener); + context.HasDiagnosticListener = hasDiagnosticListener; if (diagnosticListenerEnabled) { @@ -63,6 +75,10 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con } } + // Dispose dummy listener + // TODO: How do we avoid allocating a new listener on each request + _dummyListener?.Dispose(); + // To avoid allocation, return a null scope if the logger is not on at least to some degree. if (loggingEnabled) { @@ -245,56 +261,53 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) } [MethodImpl(MethodImplOptions.NoInlining)] - private Activity StartActivity(HttpContext httpContext, out bool hasDiagnosticListener) + private Activity? StartActivity(HttpContext httpContext, out bool hasDiagnosticListener) { - var activity = new Activity(ActivityName); hasDiagnosticListener = false; + if (_diagnosticListener.IsEnabled(ActivityStartKey)) + { + hasDiagnosticListener = true; + } + // TODO: Don't look at headers if there no listeners var headers = httpContext.Request.Headers; if (!headers.TryGetValue(HeaderNames.TraceParent, out var requestId)) { headers.TryGetValue(HeaderNames.RequestId, out requestId); } - - if (!StringValues.IsNullOrEmpty(requestId)) + var activity = _activitySource.StartActivity(ActivityName, ActivityKind.Server, requestId); + if (activity is not null) { - activity.SetParentId(requestId); - if (headers.TryGetValue(HeaderNames.TraceState, out var traceState)) + if (!StringValues.IsNullOrEmpty(requestId)) { - activity.TraceStateString = traceState; - } + // activity.SetParentId(requestId); + if (headers.TryGetValue(HeaderNames.TraceState, out var traceState)) + { + activity.TraceStateString = traceState; + } - // We expect baggage to be empty by default - // Only very advanced users will be using it in near future, we encourage them to keep baggage small (few items) - var baggage = headers.GetCommaSeparatedValues(HeaderNames.Baggage); - if (baggage.Length == 0) - { - baggage = headers.GetCommaSeparatedValues(HeaderNames.CorrelationContext); - } + // We expect baggage to be empty by default + // Only very advanced users will be using it in near future, we encourage them to keep baggage small (few items) + var baggage = headers.GetCommaSeparatedValues(HeaderNames.Baggage); + if (baggage.Length == 0) + { + baggage = headers.GetCommaSeparatedValues(HeaderNames.CorrelationContext); + } - // AddBaggage adds items at the beginning of the list, so we need to add them in reverse to keep the same order as the client - // An order could be important if baggage has two items with the same key (that is allowed by the contract) - for (var i = baggage.Length - 1; i >= 0; i--) - { - if (NameValueHeaderValue.TryParse(baggage[i], out var baggageItem)) + // AddBaggage adds items at the beginning of the list, so we need to add them in reverse to keep the same order as the client + // An order could be important if baggage has two items with the same key (that is allowed by the contract) + for (var i = baggage.Length - 1; i >= 0; i--) { - activity.AddBaggage(baggageItem.Name.ToString(), HttpUtility.UrlDecode(baggageItem.Value.ToString())); + if (NameValueHeaderValue.TryParse(baggage[i], out var baggageItem)) + { + activity.AddBaggage(baggageItem.Name.ToString(), HttpUtility.UrlDecode(baggageItem.Value.ToString())); + } } } - } - _diagnosticListener.OnActivityImport(activity, httpContext); - - if (_diagnosticListener.IsEnabled(ActivityStartKey)) - { - hasDiagnosticListener = true; - StartActivity(activity, httpContext); + // Review: Breaking change: We will no longer fire OnActivityImport before Activity.Start() + _diagnosticListener.OnActivityImport(activity, httpContext); } - else - { - activity.Start(); - } - return activity; } @@ -303,32 +316,15 @@ private void StopActivity(HttpContext httpContext, Activity activity, bool hasDi { if (hasDiagnosticListener) { - StopActivity(activity, httpContext); - } - else - { - activity.Stop(); - } - } - - // These are versions of DiagnosticSource.Start/StopActivity that don't allocate strings per call (see https://github.com/dotnet/corefx/issues/37055) - private Activity StartActivity(Activity activity, HttpContext httpContext) - { - activity.Start(); - _diagnosticListener.Write(ActivityStartKey, httpContext); - return activity; - } - - private void StopActivity(Activity activity, HttpContext httpContext) - { - // Stop sets the end time if it was unset, but we want it set before we issue the write - // so we do it now. - if (activity.Duration == TimeSpan.Zero) - { - activity.SetEndTime(DateTime.UtcNow); + // Stop sets the end time if it was unset, but we want it set before we issue the write + // so we do it now. + if (activity.Duration == TimeSpan.Zero) + { + activity.SetEndTime(DateTime.UtcNow); + } + _diagnosticListener.Write(ActivityStopKey, httpContext); } - _diagnosticListener.Write(ActivityStopKey, httpContext); - activity.Stop(); // Resets Activity.Current (we want this after the Write) + activity.Dispose(); } } } diff --git a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs index 92f1f2f9286c..f7e652fb31c4 100644 --- a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs +++ b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs @@ -465,7 +465,7 @@ public void ActivityTraceParentAndTraceStateFromHeaders() } [Fact] - public void ActivityOnExportHookIsCalled() + public void ActivityOnImportHookIsCalled() { var diagnosticListener = new DiagnosticListener("DummySource"); var hostingApplication = CreateApplication(out var features, diagnosticListener: diagnosticListener); @@ -477,7 +477,9 @@ public void ActivityOnExportHookIsCalled() onActivityImport: (activity, context) => { onActivityImportCalled = true; - Assert.Null(Activity.Current); + // Review: Breaking change + // Since we fire OnActivityImport after Activity.Start(), it will no longer be not null + //Assert.Null(Activity.Current); Assert.Equal("Microsoft.AspNetCore.Hosting.HttpRequestIn", activity.OperationName); Assert.NotNull(context); Assert.IsAssignableFrom(context); From 8ce84111be3a999b07d66f1a19c19fa8ed8f4454 Mon Sep 17 00:00:00 2001 From: Sourabh Shirhatti Date: Thu, 11 Feb 2021 00:55:45 -0800 Subject: [PATCH 2/7] Add ActivityListener test --- .../Internal/HostingApplicationDiagnostics.cs | 36 +++++++++++++------ .../HostingApplicationDiagnosticsTests.cs | 30 ++++++++++++++++ 2 files changed, 56 insertions(+), 10 deletions(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index 38d85cb632df..73f753deeb77 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -55,7 +55,6 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con // TODO: If loggingEnabled check to change to if ActivityPropogation options are enabled if (loggingEnabled || (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext))) { - // Review: Force creation of Activity by creating dummy listener _dummyListener = new ActivityListener() { ShouldListenTo = activitySource => activitySource.Name.Equals(ActivitySourceName), @@ -63,6 +62,7 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con }; ActivitySource.AddActivityListener(_dummyListener); } + context.Activity = StartActivity(httpContext, out var hasDiagnosticListener); context.HasDiagnosticListener = hasDiagnosticListener; @@ -269,7 +269,12 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) hasDiagnosticListener = true; } - // TODO: Don't look at headers if there no listeners + // Short-circuit to avoid doing an expensive header lookup + if (!(hasDiagnosticListener || _activitySource.HasListeners())) + { + return null; + } + var headers = httpContext.Request.Headers; if (!headers.TryGetValue(HeaderNames.TraceParent, out var requestId)) { @@ -307,6 +312,12 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) // Review: Breaking change: We will no longer fire OnActivityImport before Activity.Start() _diagnosticListener.OnActivityImport(activity, httpContext); + + if (hasDiagnosticListener) + { + //Review: Do we need to explicity call this? + _diagnosticListener.Write(ActivityStartKey, httpContext); + } } return activity; } @@ -316,15 +327,20 @@ private void StopActivity(HttpContext httpContext, Activity activity, bool hasDi { if (hasDiagnosticListener) { - // Stop sets the end time if it was unset, but we want it set before we issue the write - // so we do it now. - if (activity.Duration == TimeSpan.Zero) - { - activity.SetEndTime(DateTime.UtcNow); - } - _diagnosticListener.Write(ActivityStopKey, httpContext); + StopActivity(activity, httpContext); + } + activity.Stop(); + } + + private void StopActivity(Activity activity, HttpContext httpContext) + { + // Stop sets the end time if it was unset, but we want it set before we issue the write + // so we do it now. + if (activity.Duration == TimeSpan.Zero) + { + activity.SetEndTime(DateTime.UtcNow); } - activity.Dispose(); + _diagnosticListener.Write(ActivityStopKey, httpContext); } } } diff --git a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs index f7e652fb31c4..5129d983e394 100644 --- a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs +++ b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs @@ -362,6 +362,7 @@ public void ActivityBaggagePrefersW3CBaggageHeaderName() Assert.Contains(Activity.Current.Baggage, pair => pair.Key == "Key2" && pair.Value == "value4"); } + [Fact] public void ActivityBaggagePreservesItemsOrder() { @@ -494,6 +495,35 @@ public void ActivityOnImportHookIsCalled() Assert.True(Activity.Current.Recorded); } + [Fact] + public void ActivityListenersAreCalled() + { + var hostingApplication = CreateApplication(out var features); + using var listener = new ActivityListener + { + ShouldListenTo = activitySource => true, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllData, + ActivityStarted = activity => + { + Assert.Equal("0123456789abcdef", Activity.Current.ParentSpanId.ToHexString()); + }, + //ActivityStopped = activity => Assert.. + }; + + ActivitySource.AddActivityListener(listener); + + features.Set(new HttpRequestFeature() + { + Headers = new HeaderDictionary() + { + {"traceparent", "00-0123456789abcdef0123456789abcdef-0123456789abcdef-01"}, + {"tracestate", "TraceState1"}, + {"baggage", "Key1=value1, Key2=value2"} + } + }); + hostingApplication.CreateContext(features); + } + private static void AssertProperty(object o, string name) { From d3ff48149fbbfb04a82bc5b98b59e3856eca84c4 Mon Sep 17 00:00:00 2001 From: Sourabh Shirhatti Date: Fri, 12 Feb 2021 10:56:06 -0800 Subject: [PATCH 3/7] Fix remaining tests --- .../Internal/HostingApplicationDiagnostics.cs | 34 ++++++++++++------- .../HostingApplicationDiagnosticsTests.cs | 3 +- 2 files changed, 22 insertions(+), 15 deletions(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index 73f753deeb77..eb40bd7f8901 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -50,20 +50,22 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con } var diagnosticListenerEnabled = _diagnosticListener.IsEnabled(); + var diagnosticListenerActivityCreationEnabled = (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext)); var loggingEnabled = _logger.IsEnabled(LogLevel.Critical); // TODO: If loggingEnabled check to change to if ActivityPropogation options are enabled - if (loggingEnabled || (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext))) + if (loggingEnabled || diagnosticListenerActivityCreationEnabled) { _dummyListener = new ActivityListener() { - ShouldListenTo = activitySource => activitySource.Name.Equals(ActivitySourceName), - Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.PropagationData + ShouldListenTo = activitySource => ReferenceEquals(activitySource, _activitySource), + Sample = (ref ActivityCreationOptions options) => ActivitySamplingResult.PropagationData, + SampleUsingParentId = (ref ActivityCreationOptions options) => ActivitySamplingResult.PropagationData }; ActivitySource.AddActivityListener(_dummyListener); } - context.Activity = StartActivity(httpContext, out var hasDiagnosticListener); + context.Activity = StartActivity(httpContext, diagnosticListenerActivityCreationEnabled, out var hasDiagnosticListener); context.HasDiagnosticListener = hasDiagnosticListener; if (diagnosticListenerEnabled) @@ -261,12 +263,15 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) } [MethodImpl(MethodImplOptions.NoInlining)] - private Activity? StartActivity(HttpContext httpContext, out bool hasDiagnosticListener) + private Activity? StartActivity(HttpContext httpContext, bool diagnosticListenerActivityCreationEnabled, out bool hasDiagnosticListener) { hasDiagnosticListener = false; - if (_diagnosticListener.IsEnabled(ActivityStartKey)) + if (diagnosticListenerActivityCreationEnabled) { - hasDiagnosticListener = true; + if (_diagnosticListener.IsEnabled(ActivityStartKey)) + { + hasDiagnosticListener = true; + } } // Short-circuit to avoid doing an expensive header lookup @@ -310,13 +315,16 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) } } - // Review: Breaking change: We will no longer fire OnActivityImport before Activity.Start() - _diagnosticListener.OnActivityImport(activity, httpContext); - - if (hasDiagnosticListener) + if (diagnosticListenerActivityCreationEnabled) { - //Review: Do we need to explicity call this? - _diagnosticListener.Write(ActivityStartKey, httpContext); + // Review: Breaking change: We will no longer fire OnActivityImport before Activity.Start() + _diagnosticListener.OnActivityImport(activity, httpContext); + + if (hasDiagnosticListener) + { + //Review: Do we need to explicity call this? + _diagnosticListener.Write(ActivityStartKey, httpContext); + } } } return activity; diff --git a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs index 5129d983e394..c90dc44fb5cb 100644 --- a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs +++ b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs @@ -506,8 +506,7 @@ public void ActivityListenersAreCalled() ActivityStarted = activity => { Assert.Equal("0123456789abcdef", Activity.Current.ParentSpanId.ToHexString()); - }, - //ActivityStopped = activity => Assert.. + } }; ActivitySource.AddActivityListener(listener); From 224912bd1dd9b0c62c726e39daae78021324ad3f Mon Sep 17 00:00:00 2001 From: Sourabh Shirhatti Date: Mon, 22 Feb 2021 21:20:18 -0800 Subject: [PATCH 4/7] Remove dummy listener --- .../Internal/HostingApplicationDiagnostics.cs | 99 +++++++++---------- 1 file changed, 45 insertions(+), 54 deletions(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index eb40bd7f8901..84af2fa2f2c4 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -26,7 +26,6 @@ internal class HostingApplicationDiagnostics private const string ActivitySourceName = "Microsoft.AspNetCore.Hosting"; private static readonly ActivitySource _activitySource = new ActivitySource(ActivitySourceName); - private ActivityListener? _dummyListener; private readonly DiagnosticListener _diagnosticListener; private readonly ILogger _logger; @@ -53,19 +52,7 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con var diagnosticListenerActivityCreationEnabled = (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext)); var loggingEnabled = _logger.IsEnabled(LogLevel.Critical); - // TODO: If loggingEnabled check to change to if ActivityPropogation options are enabled - if (loggingEnabled || diagnosticListenerActivityCreationEnabled) - { - _dummyListener = new ActivityListener() - { - ShouldListenTo = activitySource => ReferenceEquals(activitySource, _activitySource), - Sample = (ref ActivityCreationOptions options) => ActivitySamplingResult.PropagationData, - SampleUsingParentId = (ref ActivityCreationOptions options) => ActivitySamplingResult.PropagationData - }; - ActivitySource.AddActivityListener(_dummyListener); - } - - context.Activity = StartActivity(httpContext, diagnosticListenerActivityCreationEnabled, out var hasDiagnosticListener); + context.Activity = StartActivity(httpContext, loggingEnabled, diagnosticListenerActivityCreationEnabled, out var hasDiagnosticListener); context.HasDiagnosticListener = hasDiagnosticListener; if (diagnosticListenerEnabled) @@ -77,10 +64,6 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con } } - // Dispose dummy listener - // TODO: How do we avoid allocating a new listener on each request - _dummyListener?.Dispose(); - // To avoid allocation, return a null scope if the logger is not on at least to some degree. if (loggingEnabled) { @@ -263,19 +246,18 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) } [MethodImpl(MethodImplOptions.NoInlining)] - private Activity? StartActivity(HttpContext httpContext, bool diagnosticListenerActivityCreationEnabled, out bool hasDiagnosticListener) + private Activity? StartActivity(HttpContext httpContext, bool loggingEnabled, bool diagnosticListenerActivityCreationEnabled, out bool hasActivityStartDiagnosticListener) { - hasDiagnosticListener = false; + hasActivityStartDiagnosticListener = false; if (diagnosticListenerActivityCreationEnabled) { if (_diagnosticListener.IsEnabled(ActivityStartKey)) { - hasDiagnosticListener = true; + hasActivityStartDiagnosticListener = true; } } - // Short-circuit to avoid doing an expensive header lookup - if (!(hasDiagnosticListener || _activitySource.HasListeners())) + if (!(diagnosticListenerActivityCreationEnabled || _activitySource.HasListeners() || loggingEnabled)) { return null; } @@ -285,48 +267,57 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) { headers.TryGetValue(HeaderNames.RequestId, out requestId); } + var activity = _activitySource.StartActivity(ActivityName, ActivityKind.Server, requestId); - if (activity is not null) + bool ActivityStarted = true; + if (activity is null) { - if (!StringValues.IsNullOrEmpty(requestId)) - { - // activity.SetParentId(requestId); - if (headers.TryGetValue(HeaderNames.TraceState, out var traceState)) - { - activity.TraceStateString = traceState; - } - - // We expect baggage to be empty by default - // Only very advanced users will be using it in near future, we encourage them to keep baggage small (few items) - var baggage = headers.GetCommaSeparatedValues(HeaderNames.Baggage); - if (baggage.Length == 0) - { - baggage = headers.GetCommaSeparatedValues(HeaderNames.CorrelationContext); - } + ActivityStarted = false; + activity = new Activity(ActivityName); + } - // AddBaggage adds items at the beginning of the list, so we need to add them in reverse to keep the same order as the client - // An order could be important if baggage has two items with the same key (that is allowed by the contract) - for (var i = baggage.Length - 1; i >= 0; i--) - { - if (NameValueHeaderValue.TryParse(baggage[i], out var baggageItem)) - { - activity.AddBaggage(baggageItem.Name.ToString(), HttpUtility.UrlDecode(baggageItem.Value.ToString())); - } - } + if (!StringValues.IsNullOrEmpty(requestId)) + { + activity.SetParentId(requestId); + if (headers.TryGetValue(HeaderNames.TraceState, out var traceState)) + { + activity.TraceStateString = traceState; } - if (diagnosticListenerActivityCreationEnabled) + // We expect baggage to be empty by default + // Only very advanced users will be using it in near future, we encourage them to keep baggage small (few items) + var baggage = headers.GetCommaSeparatedValues(HeaderNames.Baggage); + if (baggage.Length == 0) { - // Review: Breaking change: We will no longer fire OnActivityImport before Activity.Start() - _diagnosticListener.OnActivityImport(activity, httpContext); + baggage = headers.GetCommaSeparatedValues(HeaderNames.CorrelationContext); + } - if (hasDiagnosticListener) + // AddBaggage adds items at the beginning of the list, so we need to add them in reverse to keep the same order as the client + // An order could be important if baggage has two items with the same key (that is allowed by the contract) + for (var i = baggage.Length - 1; i >= 0; i--) + { + if (NameValueHeaderValue.TryParse(baggage[i], out var baggageItem)) { - //Review: Do we need to explicity call this? - _diagnosticListener.Write(ActivityStartKey, httpContext); + activity.AddBaggage(baggageItem.Name.ToString(), HttpUtility.UrlDecode(baggageItem.Value.ToString())); } } } + + if (diagnosticListenerActivityCreationEnabled) + { + _diagnosticListener.OnActivityImport(activity, httpContext); + } + + if (!ActivityStarted) + { + activity.Start(); + } + + if (hasActivityStartDiagnosticListener) + { + _diagnosticListener.Write(ActivityStartKey, httpContext); + } + return activity; } From fe50c4b4926ca166cf31477f470c241519270097 Mon Sep 17 00:00:00 2001 From: Sourabh Shirhatti Date: Tue, 23 Feb 2021 14:04:19 -0800 Subject: [PATCH 5/7] Use ActivitySource.CreateActivity APIs --- .../Internal/HostingApplicationDiagnostics.cs | 55 +++++++++---------- 1 file changed, 27 insertions(+), 28 deletions(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index 84af2fa2f2c4..5bbf0dcbe6da 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -52,8 +52,12 @@ public void BeginRequest(HttpContext httpContext, HostingApplication.Context con var diagnosticListenerActivityCreationEnabled = (diagnosticListenerEnabled && _diagnosticListener.IsEnabled(ActivityName, httpContext)); var loggingEnabled = _logger.IsEnabled(LogLevel.Critical); - context.Activity = StartActivity(httpContext, loggingEnabled, diagnosticListenerActivityCreationEnabled, out var hasDiagnosticListener); - context.HasDiagnosticListener = hasDiagnosticListener; + + if (loggingEnabled || diagnosticListenerActivityCreationEnabled || _activitySource.HasListeners()) + { + context.Activity = StartActivity(httpContext, loggingEnabled, diagnosticListenerActivityCreationEnabled, out var hasDiagnosticListener); + context.HasDiagnosticListener = hasDiagnosticListener; + } if (diagnosticListenerEnabled) { @@ -246,18 +250,16 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) } [MethodImpl(MethodImplOptions.NoInlining)] - private Activity? StartActivity(HttpContext httpContext, bool loggingEnabled, bool diagnosticListenerActivityCreationEnabled, out bool hasActivityStartDiagnosticListener) + private Activity? StartActivity(HttpContext httpContext, bool loggingEnabled, bool diagnosticListenerActivityCreationEnabled, out bool hasDiagnosticListener) { - hasActivityStartDiagnosticListener = false; - if (diagnosticListenerActivityCreationEnabled) + var activity = _activitySource.CreateActivity(ActivityName, ActivityKind.Server); + if (activity is null && (loggingEnabled || diagnosticListenerActivityCreationEnabled)) { - if (_diagnosticListener.IsEnabled(ActivityStartKey)) - { - hasActivityStartDiagnosticListener = true; - } + activity = new Activity(ActivityName); } - // Short-circuit to avoid doing an expensive header lookup - if (!(diagnosticListenerActivityCreationEnabled || _activitySource.HasListeners() || loggingEnabled)) + hasDiagnosticListener = false; + + if (activity is null) { return null; } @@ -268,14 +270,6 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) headers.TryGetValue(HeaderNames.RequestId, out requestId); } - var activity = _activitySource.StartActivity(ActivityName, ActivityKind.Server, requestId); - bool ActivityStarted = true; - if (activity is null) - { - ActivityStarted = false; - activity = new Activity(ActivityName); - } - if (!StringValues.IsNullOrEmpty(requestId)) { activity.SetParentId(requestId); @@ -303,19 +297,16 @@ private static void RecordRequestStartEventLog(HttpContext httpContext) } } - if (diagnosticListenerActivityCreationEnabled) - { - _diagnosticListener.OnActivityImport(activity, httpContext); - } + _diagnosticListener.OnActivityImport(activity, httpContext); - if (!ActivityStarted) + if (_diagnosticListener.IsEnabled(ActivityStartKey)) { - activity.Start(); + hasDiagnosticListener = true; + StartActivity(activity, httpContext); } - - if (hasActivityStartDiagnosticListener) + else { - _diagnosticListener.Write(ActivityStartKey, httpContext); + activity.Start(); } return activity; @@ -331,6 +322,14 @@ private void StopActivity(HttpContext httpContext, Activity activity, bool hasDi activity.Stop(); } + // These are versions of DiagnosticSource.Start/StopActivity that don't allocate strings per call (see https://github.com/dotnet/corefx/issues/37055) + private Activity StartActivity(Activity activity, HttpContext httpContext) + { + activity.Start(); + _diagnosticListener.Write(ActivityStartKey, httpContext); + return activity; + } + private void StopActivity(Activity activity, HttpContext httpContext) { // Stop sets the end time if it was unset, but we want it set before we issue the write From b2b8ee6a06ebda3057e95c30b2ad336eddce5c5d Mon Sep 17 00:00:00 2001 From: Sourabh Shirhatti Date: Tue, 23 Feb 2021 14:08:49 -0800 Subject: [PATCH 6/7] Undo changes to Activity.Stop --- .../Hosting/src/Internal/HostingApplicationDiagnostics.cs | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs index 5bbf0dcbe6da..5b4f058d6515 100644 --- a/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs +++ b/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs @@ -319,7 +319,10 @@ private void StopActivity(HttpContext httpContext, Activity activity, bool hasDi { StopActivity(activity, httpContext); } - activity.Stop(); + else + { + activity.Stop(); + } } // These are versions of DiagnosticSource.Start/StopActivity that don't allocate strings per call (see https://github.com/dotnet/corefx/issues/37055) @@ -339,6 +342,7 @@ private void StopActivity(Activity activity, HttpContext httpContext) activity.SetEndTime(DateTime.UtcNow); } _diagnosticListener.Write(ActivityStopKey, httpContext); + activity.Stop(); // Resets Activity.Current (we want this after the Write) } } } From 606da28771ec6ed195039676ed0b6bdc8810bd6c Mon Sep 17 00:00:00 2001 From: Sourabh Shirhatti Date: Tue, 23 Feb 2021 14:10:38 -0800 Subject: [PATCH 7/7] Undo test change --- .../Hosting/test/HostingApplicationDiagnosticsTests.cs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs index c90dc44fb5cb..6fc75016976d 100644 --- a/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs +++ b/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs @@ -478,9 +478,7 @@ public void ActivityOnImportHookIsCalled() onActivityImport: (activity, context) => { onActivityImportCalled = true; - // Review: Breaking change - // Since we fire OnActivityImport after Activity.Start(), it will no longer be not null - //Assert.Null(Activity.Current); + Assert.Null(Activity.Current); Assert.Equal("Microsoft.AspNetCore.Hosting.HttpRequestIn", activity.OperationName); Assert.NotNull(context); Assert.IsAssignableFrom(context);