[Instrumentation.AspNet] Fix activity being closed before processing …

…completes (#1388)
open-telemetry · Oct 12, 2023 · 2fd5e52 · 2fd5e52
1 parent 66c74ac
commit 2fd5e52
Show file tree

Hide file tree

Showing 4 changed files with 49 additions and 2 deletions.
diff --git a/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/ActivityHelper.cs b/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/ActivityHelper.cs
@@ -131,8 +131,6 @@ public static void StopAspNetActivity(TextMapPropagator textMapPropagator, Activ
         Debug.Assert(context.Items[ContextKey] is ContextHolder, "Context item is not an ContextHolder instance.");
 
         var currentActivity = Activity.Current;
-
-        aspNetActivity.Stop();
         context.Items[ContextKey] = null;
 
         try
@@ -144,6 +142,7 @@ public static void StopAspNetActivity(TextMapPropagator textMapPropagator, Activ
             AspNetTelemetryEventSource.Log.CallbackException(aspNetActivity, "OnStopped", callbackEx);
         }
 
+        aspNetActivity.Stop();
         AspNetTelemetryEventSource.Log.ActivityStopped(aspNetActivity);
 
         if (textMapPropagator is not TraceContextPropagator)

diff --git a/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule/CHANGELOG.md
@@ -2,6 +2,10 @@
 
 ## Unreleased
 
+* Fixed an issue where activities were stopped incorrectly before processing completed.
+  Activity processor's `OnEnd` will now happen after `AspNetInstrumentationOptions.Enrich`.
+  ([#1388](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/1388))
+
 * Update `OpenTelemetry.Api` to `1.6.0`.
   ([#1344](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/1344))
 

diff --git a/src/OpenTelemetry.Instrumentation.AspNet/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.AspNet/CHANGELOG.md
@@ -2,6 +2,11 @@
 
 ## Unreleased
 
+* Release together with `OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule`.
+  Fixed an issue where activities were stopped incorrectly before processing completed.
+  Activity processor's `OnEnd` will now happen after `AspNetInstrumentationOptions.Enrich`.
+  ([#1388](https://github.com/open-telemetry/opentelemetry-dotnet-contrib/pull/1388))
+
 ## 1.0.0-rc9.9
 
 Released 2023-Jun-09

diff --git a/test/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule.Tests/ActivityHelperTest.cs b/test/OpenTelemetry.Instrumentation.AspNet.TelemetryHttpModule.Tests/ActivityHelperTest.cs
@@ -447,6 +447,45 @@ public void Fire_Exception_Events()
         Assert.Equal(1, callbacksFired);
     }
 
+    [Fact]
+    public void Should_Handle_Activity_Events_In_Correct_Order()
+    {
+        var eventOrder = new List<string>();
+        const string ActivityOnStarted = "ActivityOnStarted";
+        const string ActivityOnStopped = "ActivityOnStarted";
+        const string OnStartCallback = "OnStartCallback";
+        const string OnStopCallback = "OnStopCallback";
+
+        this.EnableListener(_ => eventOrder.Add(ActivityOnStarted), _ => eventOrder.Add(ActivityOnStopped));
+
+        var context = HttpContextHelper.GetFakeHttpContext();
+        using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, (_, _) => eventOrder.Add(OnStartCallback));
+        ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, rootActivity, context, (_, _) => eventOrder.Add(OnStopCallback));
+
+        var expectedOrder = new List<string>()
+        {
+            ActivityOnStarted,
+            OnStartCallback,
+            OnStopCallback,
+            ActivityOnStopped,
+        };
+
+        Assert.Equal(expectedOrder, eventOrder);
+    }
+
+    [Fact]
+    public void Should_Not_Pass_Stopped_Activity_To_Callbacks()
+    {
+        this.EnableListener();
+
+        var wasStopped = false;
+        var context = HttpContextHelper.GetFakeHttpContext();
+        using var rootActivity = ActivityHelper.StartAspNetActivity(this.noopTextMapPropagator, context, (activity, _) => wasStopped = activity.IsStopped || wasStopped);
+        ActivityHelper.StopAspNetActivity(this.noopTextMapPropagator, rootActivity, context, (activity, _) => wasStopped = activity.IsStopped || wasStopped);
+
+        Assert.False(wasStopped);
+    }
+
     private void EnableListener(Action<Activity>? onStarted = null, Action<Activity>? onStopped = null, Func<ActivityContext, ActivitySamplingResult>? onSample = null)
     {
         Debug.Assert(this.activitySourceListener == null, "Cannot attach multiple listeners in tests.");