From 2df1a629849e215fbf16754dd1ce294e2ed53c82 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 15 Sep 2021 11:04:50 -0700 Subject: [PATCH] Lost Baggage: Fix TelemetryHttpModule losing Baggage when switching from native to managed threads (#2314) * WIP working on reproducing and fixing lost baggage. * TelemetryHttpModule now restores Baggage. * Updated public api. * Unit tests. * Use SuppressFlow for more accurate test. * CHANGELOG update. * Attempting to fix unstable test. * Attempting to fix unstable test #2. --- .../Controllers/WeatherForecastController.cs | 53 +++++++ examples/AspNet/Web.config | 9 +- .../.publicApi/net461/PublicAPI.Shipped.txt | 2 - .../.publicApi/net461/PublicAPI.Unshipped.txt | 13 ++ .../netstandard2.0/PublicAPI.Shipped.txt | 2 - .../netstandard2.0/PublicAPI.Unshipped.txt | 11 ++ .../Context/AsyncLocalRuntimeContextSlot.cs | 9 +- .../IRuntimeContextSlotValueAccessor.cs | 29 ++++ .../Context/RemotingRuntimeContextSlot.cs | 24 +-- .../Context/RuntimeContext.cs | 73 +++++++-- .../Context/ThreadLocalRuntimeContextSlot.cs | 20 ++- .../ActivityHelper.cs | 62 ++++---- .../CHANGELOG.md | 4 + .../TelemetryHttpModule.cs | 51 ++----- .../HttpWebRequestActivitySource.netfx.cs | 5 +- .../ActivityHelperTest.cs | 141 +++++++++++------- 16 files changed, 355 insertions(+), 153 deletions(-) create mode 100644 src/OpenTelemetry.Api/Context/IRuntimeContextSlotValueAccessor.cs diff --git a/examples/AspNet/Controllers/WeatherForecastController.cs b/examples/AspNet/Controllers/WeatherForecastController.cs index 39bd26e23af..092bdf07104 100644 --- a/examples/AspNet/Controllers/WeatherForecastController.cs +++ b/examples/AspNet/Controllers/WeatherForecastController.cs @@ -20,9 +20,11 @@ using System.Linq; using System.Net; using System.Net.Http; +using System.Security.Cryptography; using System.Threading.Tasks; using System.Web.Http; using Examples.AspNet.Models; +using OpenTelemetry; namespace Examples.AspNet.Controllers { @@ -71,6 +73,57 @@ public async Task> Get(int customerId) return GetWeatherForecast(); } + /// + /// For testing large async operation which causes IIS to jump threads and results in lost AsyncLocals. + /// + [Route("data")] + [HttpGet] + public async Task GetData() + { + Baggage.SetBaggage("key1", "value1"); + + using var rng = RandomNumberGenerator.Create(); + + var requestData = new byte[1024 * 1024 * 100]; + rng.GetBytes(requestData); + + using var client = new HttpClient(); + + using var request = new HttpRequestMessage(HttpMethod.Post, this.Url.Content("~/data")); + + request.Content = new ByteArrayContent(requestData); + + using var response = await client.SendAsync(request).ConfigureAwait(false); + + response.EnsureSuccessStatusCode(); + + var responseData = await response.Content.ReadAsByteArrayAsync().ConfigureAwait(false); + + return responseData.SequenceEqual(responseData) ? "match" : "mismatch"; + } + + [Route("data")] + [HttpPost] + public async Task PostData() + { + string value1 = Baggage.GetBaggage("key1"); + if (string.IsNullOrEmpty(value1)) + { + throw new InvalidOperationException("Key1 was not found on Baggage."); + } + + var stream = await this.Request.Content.ReadAsStreamAsync().ConfigureAwait(false); + + var result = new HttpResponseMessage(HttpStatusCode.OK) + { + Content = new StreamContent(stream), + }; + + result.Content.Headers.ContentType = this.Request.Content.Headers.ContentType; + + return result; + } + private static IEnumerable GetWeatherForecast() { var rng = new Random(); diff --git a/examples/AspNet/Web.config b/examples/AspNet/Web.config index 0ee991a134e..c81722ba16a 100644 --- a/examples/AspNet/Web.config +++ b/examples/AspNet/Web.config @@ -13,7 +13,9 @@ - + @@ -26,6 +28,11 @@ + + + + + diff --git a/src/OpenTelemetry.Api/.publicApi/net461/PublicAPI.Shipped.txt b/src/OpenTelemetry.Api/.publicApi/net461/PublicAPI.Shipped.txt index afb32227a29..f213ac4c665 100644 --- a/src/OpenTelemetry.Api/.publicApi/net461/PublicAPI.Shipped.txt +++ b/src/OpenTelemetry.Api/.publicApi/net461/PublicAPI.Shipped.txt @@ -178,9 +178,7 @@ static OpenTelemetry.Context.Propagation.Propagators.DefaultTextMapPropagator.ge static OpenTelemetry.Context.RuntimeContext.ContextSlotType.get -> System.Type static OpenTelemetry.Context.RuntimeContext.ContextSlotType.set -> void static OpenTelemetry.Context.RuntimeContext.GetSlot(string slotName) -> OpenTelemetry.Context.RuntimeContextSlot -static OpenTelemetry.Context.RuntimeContext.GetValue(string name) -> T static OpenTelemetry.Context.RuntimeContext.RegisterSlot(string slotName) -> OpenTelemetry.Context.RuntimeContextSlot -static OpenTelemetry.Context.RuntimeContext.SetValue(string name, T value) -> void static OpenTelemetry.Trace.ActivityExtensions.GetStatus(this System.Diagnostics.Activity activity) -> OpenTelemetry.Trace.Status static OpenTelemetry.Trace.ActivityExtensions.RecordException(this System.Diagnostics.Activity activity, System.Exception ex) -> void static OpenTelemetry.Trace.ActivityExtensions.SetStatus(this System.Diagnostics.Activity activity, OpenTelemetry.Trace.Status status) -> void diff --git a/src/OpenTelemetry.Api/.publicApi/net461/PublicAPI.Unshipped.txt b/src/OpenTelemetry.Api/.publicApi/net461/PublicAPI.Unshipped.txt index edd1a3f6ec6..1c27b84e69a 100644 --- a/src/OpenTelemetry.Api/.publicApi/net461/PublicAPI.Unshipped.txt +++ b/src/OpenTelemetry.Api/.publicApi/net461/PublicAPI.Unshipped.txt @@ -1,4 +1,17 @@ +OpenTelemetry.Context.AsyncLocalRuntimeContextSlot.Value.get -> object +OpenTelemetry.Context.AsyncLocalRuntimeContextSlot.Value.set -> void +OpenTelemetry.Context.IRuntimeContextSlotValueAccessor +OpenTelemetry.Context.IRuntimeContextSlotValueAccessor.Value.get -> object +OpenTelemetry.Context.IRuntimeContextSlotValueAccessor.Value.set -> void +OpenTelemetry.Context.RemotingRuntimeContextSlot.Value.get -> object +OpenTelemetry.Context.RemotingRuntimeContextSlot.Value.set -> void +OpenTelemetry.Context.ThreadLocalRuntimeContextSlot.Value.get -> object +OpenTelemetry.Context.ThreadLocalRuntimeContextSlot.Value.set -> void override OpenTelemetry.Context.AsyncLocalRuntimeContextSlot.Get() -> T override OpenTelemetry.Context.AsyncLocalRuntimeContextSlot.Set(T value) -> void OpenTelemetry.Context.AsyncLocalRuntimeContextSlot OpenTelemetry.Context.AsyncLocalRuntimeContextSlot.AsyncLocalRuntimeContextSlot(string name) -> void +static OpenTelemetry.Context.RuntimeContext.GetValue(string slotName) -> object +static OpenTelemetry.Context.RuntimeContext.GetValue(string slotName) -> T +static OpenTelemetry.Context.RuntimeContext.SetValue(string slotName, object value) -> void +static OpenTelemetry.Context.RuntimeContext.SetValue(string slotName, T value) -> void diff --git a/src/OpenTelemetry.Api/.publicApi/netstandard2.0/PublicAPI.Shipped.txt b/src/OpenTelemetry.Api/.publicApi/netstandard2.0/PublicAPI.Shipped.txt index 3ebfa521557..ab7a66bc6fc 100644 --- a/src/OpenTelemetry.Api/.publicApi/netstandard2.0/PublicAPI.Shipped.txt +++ b/src/OpenTelemetry.Api/.publicApi/netstandard2.0/PublicAPI.Shipped.txt @@ -178,9 +178,7 @@ static OpenTelemetry.Context.Propagation.Propagators.DefaultTextMapPropagator.ge static OpenTelemetry.Context.RuntimeContext.ContextSlotType.get -> System.Type static OpenTelemetry.Context.RuntimeContext.ContextSlotType.set -> void static OpenTelemetry.Context.RuntimeContext.GetSlot(string slotName) -> OpenTelemetry.Context.RuntimeContextSlot -static OpenTelemetry.Context.RuntimeContext.GetValue(string name) -> T static OpenTelemetry.Context.RuntimeContext.RegisterSlot(string slotName) -> OpenTelemetry.Context.RuntimeContextSlot -static OpenTelemetry.Context.RuntimeContext.SetValue(string name, T value) -> void static OpenTelemetry.Trace.ActivityExtensions.GetStatus(this System.Diagnostics.Activity activity) -> OpenTelemetry.Trace.Status static OpenTelemetry.Trace.ActivityExtensions.RecordException(this System.Diagnostics.Activity activity, System.Exception ex) -> void static OpenTelemetry.Trace.ActivityExtensions.SetStatus(this System.Diagnostics.Activity activity, OpenTelemetry.Trace.Status status) -> void diff --git a/src/OpenTelemetry.Api/.publicApi/netstandard2.0/PublicAPI.Unshipped.txt b/src/OpenTelemetry.Api/.publicApi/netstandard2.0/PublicAPI.Unshipped.txt index e69de29bb2d..30e2441b221 100644 --- a/src/OpenTelemetry.Api/.publicApi/netstandard2.0/PublicAPI.Unshipped.txt +++ b/src/OpenTelemetry.Api/.publicApi/netstandard2.0/PublicAPI.Unshipped.txt @@ -0,0 +1,11 @@ +OpenTelemetry.Context.AsyncLocalRuntimeContextSlot.Value.get -> object +OpenTelemetry.Context.AsyncLocalRuntimeContextSlot.Value.set -> void +OpenTelemetry.Context.IRuntimeContextSlotValueAccessor +OpenTelemetry.Context.IRuntimeContextSlotValueAccessor.Value.get -> object +OpenTelemetry.Context.IRuntimeContextSlotValueAccessor.Value.set -> void +OpenTelemetry.Context.ThreadLocalRuntimeContextSlot.Value.get -> object +OpenTelemetry.Context.ThreadLocalRuntimeContextSlot.Value.set -> void +static OpenTelemetry.Context.RuntimeContext.GetValue(string slotName) -> object +static OpenTelemetry.Context.RuntimeContext.GetValue(string slotName) -> T +static OpenTelemetry.Context.RuntimeContext.SetValue(string slotName, object value) -> void +static OpenTelemetry.Context.RuntimeContext.SetValue(string slotName, T value) -> void \ No newline at end of file diff --git a/src/OpenTelemetry.Api/Context/AsyncLocalRuntimeContextSlot.cs b/src/OpenTelemetry.Api/Context/AsyncLocalRuntimeContextSlot.cs index de5c5083a13..f38af6d6cf5 100644 --- a/src/OpenTelemetry.Api/Context/AsyncLocalRuntimeContextSlot.cs +++ b/src/OpenTelemetry.Api/Context/AsyncLocalRuntimeContextSlot.cs @@ -23,7 +23,7 @@ namespace OpenTelemetry.Context /// The async local implementation of context slot. /// /// The type of the underlying value. - public class AsyncLocalRuntimeContextSlot : RuntimeContextSlot + public class AsyncLocalRuntimeContextSlot : RuntimeContextSlot, IRuntimeContextSlotValueAccessor { private readonly AsyncLocal slot; @@ -37,6 +37,13 @@ public AsyncLocalRuntimeContextSlot(string name) this.slot = new AsyncLocal(); } + /// + public object Value + { + get => this.slot.Value; + set => this.slot.Value = (T)value; + } + /// [MethodImpl(MethodImplOptions.AggressiveInlining)] public override T Get() diff --git a/src/OpenTelemetry.Api/Context/IRuntimeContextSlotValueAccessor.cs b/src/OpenTelemetry.Api/Context/IRuntimeContextSlotValueAccessor.cs new file mode 100644 index 00000000000..eab76adfca1 --- /dev/null +++ b/src/OpenTelemetry.Api/Context/IRuntimeContextSlotValueAccessor.cs @@ -0,0 +1,29 @@ +// +// Copyright The OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// + +namespace OpenTelemetry.Context +{ + /// + /// Describes a type of which can expose its value as an . + /// + public interface IRuntimeContextSlotValueAccessor + { + /// + /// Gets or sets the value of the slot as an . + /// + object Value { get; set; } + } +} diff --git a/src/OpenTelemetry.Api/Context/RemotingRuntimeContextSlot.cs b/src/OpenTelemetry.Api/Context/RemotingRuntimeContextSlot.cs index f589d9900bc..c40dae89356 100644 --- a/src/OpenTelemetry.Api/Context/RemotingRuntimeContextSlot.cs +++ b/src/OpenTelemetry.Api/Context/RemotingRuntimeContextSlot.cs @@ -26,7 +26,7 @@ namespace OpenTelemetry.Context /// The .NET Remoting implementation of context slot. /// /// The type of the underlying value. - public class RemotingRuntimeContextSlot : RuntimeContextSlot + public class RemotingRuntimeContextSlot : RuntimeContextSlot, IRuntimeContextSlotValueAccessor { // A special workaround to suppress context propagation cross AppDomains. // @@ -50,24 +50,26 @@ public RemotingRuntimeContextSlot(string name) { } + /// + public object Value + { + get => this.Get(); + set => this.Set((T)value); + } + /// [MethodImpl(MethodImplOptions.AggressiveInlining)] public override T Get() { - var wrapper = CallContext.LogicalGetData(this.Name) as BitArray; - - if (wrapper == null) + if (!(CallContext.LogicalGetData(this.Name) is BitArray wrapper)) { - return default(T); + return default; } var value = WrapperField.GetValue(wrapper); - if (value is T) - { - return (T)value; - } - - return default(T); + return value is T t + ? t + : default; } /// diff --git a/src/OpenTelemetry.Api/Context/RuntimeContext.cs b/src/OpenTelemetry.Api/Context/RuntimeContext.cs index b0110e5ac3c..3b7308adfca 100644 --- a/src/OpenTelemetry.Api/Context/RuntimeContext.cs +++ b/src/OpenTelemetry.Api/Context/RuntimeContext.cs @@ -73,8 +73,12 @@ public static RuntimeContextSlot GetSlot(string slotName) throw new ArgumentException($"{nameof(slotName)} cannot be null or empty string."); } - Slots.TryGetValue(slotName, out var slot); - return slot as RuntimeContextSlot ?? throw new ArgumentException($"The context slot {slotName} is not found."); + if (!Slots.TryGetValue(slotName, out var slot)) + { + throw new ArgumentException($"The context slot {slotName} could not be found."); + } + + return slot as RuntimeContextSlot ?? throw new ArgumentException($"The context slot {slotName} cannot be cast as {typeof(RuntimeContextSlot)}."); } /* @@ -104,27 +108,76 @@ public static IDictionary Snapshot() /// /// Sets the value to a registered slot. /// - /// The name of the context slot. + /// The name of the context slot. /// The value to be set. /// The type of the value. [MethodImpl(MethodImplOptions.AggressiveInlining)] - public static void SetValue(string name, T value) + public static void SetValue(string slotName, T value) { - var slot = (RuntimeContextSlot)Slots[name]; - slot.Set(value); + GetSlot(slotName).Set(value); } /// /// Gets the value from a registered slot. /// - /// The name of the context slot. + /// The name of the context slot. /// The type of the value. /// The value retrieved from the context slot. [MethodImpl(MethodImplOptions.AggressiveInlining)] - public static T GetValue(string name) + public static T GetValue(string slotName) + { + return GetSlot(slotName).Get(); + } + + /// + /// Sets the value to a registered slot. + /// + /// The name of the context slot. + /// The value to be set. + public static void SetValue(string slotName, object value) { - var slot = (RuntimeContextSlot)Slots[name]; - return slot.Get(); + if (string.IsNullOrEmpty(slotName)) + { + throw new ArgumentException($"{nameof(slotName)} cannot be null or empty string."); + } + + if (!Slots.TryGetValue(slotName, out var slot)) + { + throw new ArgumentException($"The context slot {slotName} could not be found."); + } + + if (slot is IRuntimeContextSlotValueAccessor runtimeContextSlotValueAccessor) + { + runtimeContextSlotValueAccessor.Value = value; + return; + } + + throw new NotSupportedException($"The context slot {slotName} value cannot be accessed as an object."); + } + + /// + /// Gets the value from a registered slot. + /// + /// The name of the context slot. + /// The value retrieved from the context slot. + public static object GetValue(string slotName) + { + if (string.IsNullOrEmpty(slotName)) + { + throw new ArgumentException($"{nameof(slotName)} cannot be null or empty string."); + } + + if (!Slots.TryGetValue(slotName, out var slot)) + { + throw new ArgumentException($"The context slot {slotName} could not be found."); + } + + if (slot is IRuntimeContextSlotValueAccessor runtimeContextSlotValueAccessor) + { + return runtimeContextSlotValueAccessor.Value; + } + + throw new NotSupportedException($"The context slot {slotName} value cannot be accessed as an object."); } // For testing purpose diff --git a/src/OpenTelemetry.Api/Context/ThreadLocalRuntimeContextSlot.cs b/src/OpenTelemetry.Api/Context/ThreadLocalRuntimeContextSlot.cs index efd06d31dae..87215c96d15 100644 --- a/src/OpenTelemetry.Api/Context/ThreadLocalRuntimeContextSlot.cs +++ b/src/OpenTelemetry.Api/Context/ThreadLocalRuntimeContextSlot.cs @@ -23,7 +23,7 @@ namespace OpenTelemetry.Context /// The thread local (TLS) implementation of context slot. /// /// The type of the underlying value. - public class ThreadLocalRuntimeContextSlot : RuntimeContextSlot + public class ThreadLocalRuntimeContextSlot : RuntimeContextSlot, IRuntimeContextSlotValueAccessor { private readonly ThreadLocal slot; private bool disposedValue; @@ -38,6 +38,13 @@ public ThreadLocalRuntimeContextSlot(string name) this.slot = new ThreadLocal(); } + /// + public object Value + { + get => this.slot.Value; + set => this.slot.Value = (T)value; + } + /// [MethodImpl(MethodImplOptions.AggressiveInlining)] public override T Get() @@ -55,14 +62,11 @@ public override void Set(T value) /// protected override void Dispose(bool disposing) { - base.Dispose(true); - if (!this.disposedValue) - { - if (disposing) - { - this.slot.Dispose(); - } + base.Dispose(disposing); + if (disposing && !this.disposedValue) + { + this.slot.Dispose(); this.disposedValue = true; } } diff --git a/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/ActivityHelper.cs b/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/ActivityHelper.cs index 0ad60496351..984f89dc21b 100644 --- a/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/ActivityHelper.cs +++ b/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/ActivityHelper.cs @@ -19,7 +19,9 @@ using System.Collections.Generic; using System.Diagnostics; using System.Runtime.CompilerServices; +using System.Threading; using System.Web; +using OpenTelemetry.Context; using OpenTelemetry.Context.Propagation; namespace OpenTelemetry.Instrumentation.AspNet @@ -30,11 +32,12 @@ namespace OpenTelemetry.Instrumentation.AspNet internal static class ActivityHelper { /// - /// Key to store the activity in HttpContext. + /// Key to store the state in HttpContext. /// - internal const string ActivityKey = "__AspnetActivity__"; - + internal const string ContextKey = "__AspnetInstrumentationContext__"; internal static readonly object StartedButNotSampledObj = new object(); + + private const string BaggageSlotName = "otel.baggage"; private static readonly Func> HttpRequestHeaderValuesGetter = (request, name) => request.Headers.GetValues(name); private static readonly ActivitySource AspNetSource = new ActivitySource( TelemetryHttpModule.AspNetSourceName, @@ -53,10 +56,10 @@ public static bool HasStarted(HttpContext context, out Activity aspNetActivity) { Debug.Assert(context != null, "Context is null."); - object itemValue = context.Items[ActivityKey]; - if (itemValue is Activity activity) + object itemValue = context.Items[ContextKey]; + if (itemValue is ContextHolder contextHolder) { - aspNetActivity = activity; + aspNetActivity = contextHolder.Activity; return true; } @@ -81,17 +84,15 @@ public static Activity StartAspNetActivity(TextMapPropagator textMapPropagator, if (activity != null) { - context.Items[ActivityKey] = activity; - if (!(textMapPropagator is TraceContextPropagator)) { - // todo: RestoreActivityIfNeeded below compensates for - // AsyncLocal Activity.Current being lost. Baggage - // potentially will suffer from the same issue, but we can't - // simply add it to context.Items because any change results - // in a new instance. Probably need to save it at the end of - // each OnExecuteRequestStep. Baggage.Current = propagationContext.Baggage; + + context.Items[ContextKey] = new ContextHolder { Activity = activity, Baggage = RuntimeContext.GetValue(BaggageSlotName) }; + } + else + { + context.Items[ContextKey] = new ContextHolder { Activity = activity }; } try @@ -107,7 +108,7 @@ public static Activity StartAspNetActivity(TextMapPropagator textMapPropagator, } else { - context.Items[ActivityKey] = StartedButNotSampledObj; + context.Items[ContextKey] = StartedButNotSampledObj; } return activity; @@ -127,20 +128,20 @@ public static void StopAspNetActivity(TextMapPropagator textMapPropagator, Activ if (aspNetActivity == null) { - Debug.Assert(context.Items[ActivityKey] == StartedButNotSampledObj, "Context item is not StartedButNotSampledObj."); + Debug.Assert(context.Items[ContextKey] == StartedButNotSampledObj, "Context item is not StartedButNotSampledObj."); // This is the case where a start was called but no activity was // created due to a sampling decision. - context.Items[ActivityKey] = null; + context.Items[ContextKey] = null; return; } - Debug.Assert(context.Items[ActivityKey] is Activity, "Context item is not an Activity instance."); + Debug.Assert(context.Items[ContextKey] is ContextHolder, "Context item is not an ContextHolder instance."); var currentActivity = Activity.Current; aspNetActivity.Stop(); - context.Items[ActivityKey] = null; + context.Items[ContextKey] = null; try { @@ -198,17 +199,28 @@ public static void WriteActivityException(Activity aspNetActivity, HttpContext c /// This method is intended to restore the current activity in order to correlate the child /// activities with the root activity of the request. /// - /// HttpContext.Items dictionary. + /// . [MethodImpl(MethodImplOptions.AggressiveInlining)] - internal static void RestoreActivityIfNeeded(IDictionary contextItems) + internal static void RestoreContextIfNeeded(HttpContext context) { - Debug.Assert(contextItems != null, "Context Items is null."); + Debug.Assert(context != null, "Context is null."); - if (Activity.Current == null && contextItems[ActivityKey] is Activity aspNetActivity) + if (context.Items[ContextKey] is ContextHolder contextHolder && Activity.Current != contextHolder.Activity) { - Activity.Current = aspNetActivity; - AspNetTelemetryEventSource.Log.ActivityRestored(aspNetActivity); + Activity.Current = contextHolder.Activity; + if (contextHolder.Baggage != null) + { + RuntimeContext.SetValue(BaggageSlotName, contextHolder.Baggage); + } + + AspNetTelemetryEventSource.Log.ActivityRestored(contextHolder.Activity); } } + + internal class ContextHolder + { + public Activity Activity; + public object Baggage; + } } } diff --git a/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/CHANGELOG.md index 3fc80c350f4..88682968e35 100644 --- a/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/CHANGELOG.md +++ b/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/CHANGELOG.md @@ -22,3 +22,7 @@ & OpenTelemetry.API ([#2249](https://github.com/open-telemetry/opentelemetry-dotnet/pull/2249) & follow-ups (linked to #2249)) + +* TelemetryHttpModule will now restore Baggage on .NET 4.7.1+ runtimes when IIS + switches threads + ([#2314](https://github.com/open-telemetry/opentelemetry-dotnet/pull/2314)) diff --git a/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/TelemetryHttpModule.cs b/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/TelemetryHttpModule.cs index e5684c4594f..64117bf6cea 100644 --- a/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/TelemetryHttpModule.cs +++ b/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/TelemetryHttpModule.cs @@ -42,7 +42,7 @@ public class TelemetryHttpModule : IHttpModule // ServerVariable set on every request if URL module is registered in HttpModule pipeline. private const string URLRewriteModuleVersion = "IIS_UrlRewriteModule"; - private static readonly MethodInfo OnStepMethodInfo = typeof(HttpApplication).GetMethod("OnExecuteRequestStep"); + private static readonly MethodInfo OnExecuteRequestStepMethodInfo = typeof(HttpApplication).GetMethod("OnExecuteRequestStep"); /// /// Gets the applied to requests processed by the handler. @@ -61,59 +61,36 @@ public void Init(HttpApplication context) context.EndRequest += this.Application_EndRequest; context.Error += this.Application_Error; - // OnExecuteRequestStep is availabile starting with 4.7.1 - // If this is executed in 4.7.1 runtime (regardless of targeted .NET version), - // we will use it to restore lost activity, otherwise keep PreRequestHandlerExecute - if (OnStepMethodInfo != null && HttpRuntime.UsingIntegratedPipeline) + if (HttpRuntime.UsingIntegratedPipeline && OnExecuteRequestStepMethodInfo != null) { + // OnExecuteRequestStep is availabile starting with 4.7.1 try { - OnStepMethodInfo.Invoke(context, new object[] { (Action)this.OnExecuteRequestStep }); + OnExecuteRequestStepMethodInfo.Invoke(context, new object[] { (Action)this.OnExecuteRequestStep }); } catch (Exception e) { AspNetTelemetryEventSource.Log.OnExecuteRequestStepInvokationError(e.Message); } } - else - { - context.PreRequestHandlerExecute += this.Application_PreRequestHandlerExecute; - } - } - - /// - /// Restores Activity before each pipeline step if it was lost. - /// - /// HttpContext instance. - /// Step to be executed. - internal void OnExecuteRequestStep(HttpContextBase context, Action step) - { - // Once we have public Activity.Current setter (https://github.com/dotnet/corefx/issues/29207) this method will be - // simplified to just assign Current if is was lost. - // In the mean time, we are creating child Activity to restore the context. We have to send - // event with this Activity to tracing system. It created a lot of issues for listeners as - // we may potentially have a lot of them for different stages. - // To reduce amount of events, we only care about ExecuteRequestHandler stage - restore activity here and - // stop/report it to tracing system in EndRequest. - if (context.CurrentNotification == RequestNotification.ExecuteRequestHandler && !context.IsPostNotification) - { - ActivityHelper.RestoreActivityIfNeeded(context.Items); - } - - step(); } private void Application_BeginRequest(object sender, EventArgs e) { - var context = ((HttpApplication)sender).Context; AspNetTelemetryEventSource.Log.TraceCallback("Application_BeginRequest"); - ActivityHelper.StartAspNetActivity(Options.TextMapPropagator, context, Options.OnRequestStartedCallback); + ActivityHelper.StartAspNetActivity(Options.TextMapPropagator, ((HttpApplication)sender).Context, Options.OnRequestStartedCallback); } - private void Application_PreRequestHandlerExecute(object sender, EventArgs e) + private void OnExecuteRequestStep(HttpContextBase context, Action step) { - AspNetTelemetryEventSource.Log.TraceCallback("Application_PreRequestHandlerExecute"); - ActivityHelper.RestoreActivityIfNeeded(((HttpApplication)sender).Context.Items); + // Called only on 4.7.1+ runtimes + + if (context.CurrentNotification == RequestNotification.ExecuteRequestHandler && !context.IsPostNotification) + { + ActivityHelper.RestoreContextIfNeeded(context.ApplicationInstance.Context); + } + + step(); } private void Application_EndRequest(object sender, EventArgs e) diff --git a/src/OpenTelemetry.Instrumentation.Http/Implementation/HttpWebRequestActivitySource.netfx.cs b/src/OpenTelemetry.Instrumentation.Http/Implementation/HttpWebRequestActivitySource.netfx.cs index a0dcd27815d..aab50d346b7 100644 --- a/src/OpenTelemetry.Instrumentation.Http/Implementation/HttpWebRequestActivitySource.netfx.cs +++ b/src/OpenTelemetry.Instrumentation.Http/Implementation/HttpWebRequestActivitySource.netfx.cs @@ -291,9 +291,8 @@ private static void HookOrProcessResult(HttpWebRequest request) private static void ProcessResult(IAsyncResult asyncResult, AsyncCallback asyncCallback, Activity activity, object result, bool forceResponseCopy) { - // We could be executing on a different thread now so set the activity. - Debug.Assert(Activity.Current == null || Activity.Current == activity, "There was an unexpected active Activity on the result thread."); - if (Activity.Current == null) + // We could be executing on a different thread now so restore the activity if needed. + if (Activity.Current != activity) { Activity.Current = activity; } diff --git a/test/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule.Tests/ActivityHelperTest.cs b/test/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule.Tests/ActivityHelperTest.cs index 04c0c3b4006..6f3d5330a3c 100644 --- a/test/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule.Tests/ActivityHelperTest.cs +++ b/test/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule.Tests/ActivityHelperTest.cs @@ -24,6 +24,7 @@ namespace OpenTelemetry.Instrumentation.AspNet.Tests using System.Threading; using System.Threading.Tasks; using System.Web; + using OpenTelemetry.Context; using OpenTelemetry.Context.Propagation; using Xunit; @@ -52,7 +53,7 @@ public void Has_Started_Returns_Correctly() Assert.False(result); Assert.Null(aspNetActivity); - context.Items[ActivityHelper.ActivityKey] = ActivityHelper.StartedButNotSampledObj; + context.Items[ActivityHelper.ContextKey] = ActivityHelper.StartedButNotSampledObj; result = ActivityHelper.HasStarted(context, out aspNetActivity); @@ -60,7 +61,7 @@ public void Has_Started_Returns_Correctly() Assert.Null(aspNetActivity); Activity activity = new Activity(TestActivityName); - context.Items[ActivityHelper.ActivityKey] = activity; + context.Items[ActivityHelper.ContextKey] = new ActivityHelper.ContextHolder { Activity = activity }; result = ActivityHelper.HasStarted(context, out aspNetActivity); @@ -70,19 +71,70 @@ public void Has_Started_Returns_Correctly() } [Fact] - public void Can_Restore_Activity() + public async Task Can_Restore_Activity() { this.EnableListener(); var context = HttpContextHelper.GetFakeHttpContext(); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); rootActivity.AddTag("k1", "v1"); rootActivity.AddTag("k2", "v2"); - Activity.Current = null; + Task testTask; + using (ExecutionContext.SuppressFlow()) + { + testTask = Task.Run(() => + { + Task.Yield(); + + Assert.Null(Activity.Current); + + ActivityHelper.RestoreContextIfNeeded(context); + + Assert.Same(Activity.Current, rootActivity); + }); + } + + await testTask.ConfigureAwait(false); + } + + [Fact] + public async Task Can_Restore_Baggage() + { + this.EnableListener(); + + var requestHeaders = new Dictionary + { + { BaggageHeaderName, BaggageInHeader }, + }; + + var context = HttpContextHelper.GetFakeHttpContext(headers: requestHeaders); + using var rootActivity = ActivityHelper.StartAspNetActivity(new CompositeTextMapPropagator(new TextMapPropagator[] { new TraceContextPropagator(), new BaggagePropagator() }), context, null); + + rootActivity.AddTag("k1", "v1"); + rootActivity.AddTag("k2", "v2"); + + Task testTask; + using (ExecutionContext.SuppressFlow()) + { + testTask = Task.Run(() => + { + Task.Yield(); + + Assert.Null(Activity.Current); + Assert.Equal(0, Baggage.Current.Count); + + ActivityHelper.RestoreContextIfNeeded(context); - ActivityHelper.RestoreActivityIfNeeded(context.Items); + Assert.Same(Activity.Current, rootActivity); + Assert.Empty(rootActivity.Baggage); - Assert.Same(Activity.Current, rootActivity); + Assert.Equal(2, Baggage.Current.Count); + Assert.Equal("789", Baggage.Current.GetBaggage("TestKey1")); + Assert.Equal("456", Baggage.Current.GetBaggage("TestKey2")); + }); + } + + await testTask.ConfigureAwait(false); } [Fact] @@ -95,7 +147,7 @@ public void Can_Stop_Lost_Activity() Assert.Equal(TelemetryHttpModule.AspNetActivityName, Activity.Current.OperationName); }); var context = HttpContextHelper.GetFakeHttpContext(); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); rootActivity.AddTag("k1", "v1"); rootActivity.AddTag("k2", "v2"); @@ -104,14 +156,14 @@ public void Can_Stop_Lost_Activity() ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, rootActivity, context, null); Assert.True(rootActivity.Duration != TimeSpan.Zero); Assert.Null(Activity.Current); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); } [Fact] public void Do_Not_Restore_Activity_When_There_Is_No_Activity_In_Context() { this.EnableListener(); - ActivityHelper.RestoreActivityIfNeeded(HttpContextHelper.GetFakeHttpContext().Items); + ActivityHelper.RestoreContextIfNeeded(HttpContextHelper.GetFakeHttpContext()); Assert.Null(Activity.Current); } @@ -123,9 +175,9 @@ public void Do_Not_Restore_Activity_When_It_Is_Not_Lost() var root = new Activity("root").Start(); var context = HttpContextHelper.GetFakeHttpContext(); - context.Items[ActivityHelper.ActivityKey] = root; + context.Items[ActivityHelper.ContextKey] = new ActivityHelper.ContextHolder { Activity = root }; - ActivityHelper.RestoreActivityIfNeeded(context.Items); + ActivityHelper.RestoreContextIfNeeded(context); Assert.Equal(root, Activity.Current); } @@ -136,13 +188,13 @@ public void Can_Stop_Activity_Without_AspNetListener_Enabled() var context = HttpContextHelper.GetFakeHttpContext(); var rootActivity = new Activity(TestActivityName); rootActivity.Start(); - context.Items[ActivityHelper.ActivityKey] = rootActivity; + context.Items[ActivityHelper.ContextKey] = new ActivityHelper.ContextHolder { Activity = rootActivity }; Thread.Sleep(100); ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, rootActivity, context, null); Assert.True(rootActivity.Duration != TimeSpan.Zero); Assert.Null(rootActivity.Parent); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); } [Fact] @@ -151,14 +203,14 @@ public void Can_Stop_Activity_With_AspNetListener_Enabled() var context = HttpContextHelper.GetFakeHttpContext(); var rootActivity = new Activity(TestActivityName); rootActivity.Start(); - context.Items[ActivityHelper.ActivityKey] = rootActivity; + context.Items[ActivityHelper.ContextKey] = new ActivityHelper.ContextHolder { Activity = rootActivity }; Thread.Sleep(100); this.EnableListener(); ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, rootActivity, context, null); Assert.True(rootActivity.Duration != TimeSpan.Zero); Assert.Null(rootActivity.Parent); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); } [Fact] @@ -166,7 +218,7 @@ public void Can_Stop_Root_Activity_With_All_Children() { this.EnableListener(); var context = HttpContextHelper.GetFakeHttpContext(); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); var child = new Activity("child").Start(); new Activity("grandchild").Start(); @@ -176,7 +228,7 @@ public void Can_Stop_Root_Activity_With_All_Children() Assert.True(rootActivity.Duration != TimeSpan.Zero); Assert.True(child.Duration == TimeSpan.Zero); Assert.Null(rootActivity.Parent); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); } [Fact] @@ -184,7 +236,7 @@ public void Can_Stop_Root_While_Child_Is_Current() { this.EnableListener(); var context = HttpContextHelper.GetFakeHttpContext(); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); var child = new Activity("child").Start(); ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, rootActivity, context, null); @@ -192,7 +244,7 @@ public void Can_Stop_Root_While_Child_Is_Current() Assert.True(child.Duration == TimeSpan.Zero); Assert.NotNull(Activity.Current); Assert.Equal(Activity.Current, child); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); } [Fact] @@ -200,7 +252,7 @@ public async Task Can_Stop_Root_Activity_If_It_Is_Broken() { this.EnableListener(); var context = HttpContextHelper.GetFakeHttpContext(); - var root = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var root = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); new Activity("child").Start(); for (int i = 0; i < 2; i++) @@ -221,7 +273,7 @@ await Task.Run(() => // not update Current ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, root, context, null); Assert.True(root.Duration != TimeSpan.Zero); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); Assert.Null(Activity.Current); } @@ -230,7 +282,7 @@ public void Stop_Root_Activity_With_129_Nesting_Depth() { this.EnableListener(); var context = HttpContextHelper.GetFakeHttpContext(); - var root = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var root = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); for (int i = 0; i < 129; i++) { @@ -241,7 +293,7 @@ public void Stop_Root_Activity_With_129_Nesting_Depth() ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, root, context, null); Assert.True(root.Duration != TimeSpan.Zero); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); Assert.NotNull(Activity.Current); } @@ -249,13 +301,13 @@ public void Stop_Root_Activity_With_129_Nesting_Depth() public void Should_Not_Create_RootActivity_If_AspNetListener_Not_Enabled() { var context = HttpContextHelper.GetFakeHttpContext(); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); Assert.Null(rootActivity); - Assert.Equal(ActivityHelper.StartedButNotSampledObj, context.Items[ActivityHelper.ActivityKey]); + Assert.Equal(ActivityHelper.StartedButNotSampledObj, context.Items[ActivityHelper.ContextKey]); ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, rootActivity, context, null); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); } [Fact] @@ -263,13 +315,13 @@ public void Should_Not_Create_RootActivity_If_AspNetActivity_Not_Enabled() { var context = HttpContextHelper.GetFakeHttpContext(); this.EnableListener(onSample: (context) => ActivitySamplingResult.None); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); Assert.Null(rootActivity); - Assert.Equal(ActivityHelper.StartedButNotSampledObj, context.Items[ActivityHelper.ActivityKey]); + Assert.Equal(ActivityHelper.StartedButNotSampledObj, context.Items[ActivityHelper.ContextKey]); ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, rootActivity, context, null); - Assert.Null(context.Items[ActivityHelper.ActivityKey]); + Assert.Null(context.Items[ActivityHelper.ContextKey]); } [Fact] @@ -282,7 +334,7 @@ public void Can_Create_RootActivity_From_W3C_Traceparent() }; var context = HttpContextHelper.GetFakeHttpContext(headers: requestHeaders); - var rootActivity = ActivityHelper.StartAspNetActivity(new TraceContextPropagator(), context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(new TraceContextPropagator(), context, null); Assert.NotNull(rootActivity); Assert.Equal(ActivityIdFormat.W3C, rootActivity.IdFormat); @@ -308,7 +360,7 @@ public void Can_Create_RootActivityWithTraceState_From_W3C_TraceContext() }; var context = HttpContextHelper.GetFakeHttpContext(headers: requestHeaders); - var rootActivity = ActivityHelper.StartAspNetActivity(new TraceContextPropagator(), context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(new TraceContextPropagator(), context, null); Assert.NotNull(rootActivity); Assert.Equal(ActivityIdFormat.W3C, rootActivity.IdFormat); @@ -334,7 +386,7 @@ public void Can_Create_RootActivity_From_W3C_Traceparent_With_Baggage() }; var context = HttpContextHelper.GetFakeHttpContext(headers: requestHeaders); - var rootActivity = ActivityHelper.StartAspNetActivity(new CompositeTextMapPropagator(new TextMapPropagator[] { new TraceContextPropagator(), new BaggagePropagator() }), context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(new CompositeTextMapPropagator(new TextMapPropagator[] { new TraceContextPropagator(), new BaggagePropagator() }), context, null); Assert.NotNull(rootActivity); Assert.Equal(ActivityIdFormat.W3C, rootActivity.IdFormat); @@ -355,29 +407,12 @@ public void Can_Create_RootActivity_From_W3C_Traceparent_With_Baggage() Assert.Equal(0, Baggage.Current.Count); } - [Fact] - public void Can_Create_RootActivity_And_Ignore_Info_From_Request_Header_If_ParseHeaders_Is_False() - { - this.EnableListener(); - var requestHeaders = new Dictionary - { - { TraceParentHeaderName, "00-0123456789abcdef0123456789abcdef-0123456789abcdef-01" }, - }; - - var context = HttpContextHelper.GetFakeHttpContext(headers: requestHeaders); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); - - Assert.NotNull(rootActivity); - Assert.Null(rootActivity.ParentId); - Assert.Empty(rootActivity.Baggage); - } - [Fact] public void Can_Create_RootActivity_And_Start_Activity() { this.EnableListener(); var context = HttpContextHelper.GetFakeHttpContext(); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); Assert.NotNull(rootActivity); Assert.True(!string.IsNullOrEmpty(rootActivity.Id)); @@ -388,10 +423,10 @@ public void Can_Create_RootActivity_And_Saved_In_HttContext() { this.EnableListener(); var context = HttpContextHelper.GetFakeHttpContext(); - var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); + using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, null); Assert.NotNull(rootActivity); - Assert.Same(rootActivity, context.Items[ActivityHelper.ActivityKey]); + Assert.Same(rootActivity, ((ActivityHelper.ContextHolder)context.Items[ActivityHelper.ContextKey])?.Activity); } [Fact]