Report intermediate requests for lost and restored Activity

CHANGELOG.md

@@ -2,6 +2,7 @@
 
 ## Version 2.7.0-beta1
 - [Added support to collect Perf Counters for .NET Core Apps if running inside Azure WebApps] (https://github.com/Microsoft/ApplicationInsights-dotnet-server/issues/889)
+- [Fix: Correlation is not working for POST requests](https://github.com/Microsoft/ApplicationInsights-dotnet-server/pull/898) when .NET 4.7.1 runtime is installed.
 
 ## Version 2.6.0-beta4
 - [Remove CorrelationIdLookupHelper. Use TelemetryConfiguration.ApplicationIdProvider instead.](https://github.com/Microsoft/ApplicationInsights-dotnet-server/pull/880) With this change you can update URL to query application ID from which enables environments with reverse proxy configuration to access Application Insights ednpoints.

Src/Common/Common.projitems

@@ -14,6 +14,7 @@
     <Compile Include="$(MSBuildThisFileDirectory)ExceptionUtilities.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)HeadersUtilities.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)InjectionGuardConstants.cs" />
+    <Compile Include="$(MSBuildThisFileDirectory)PropertyFetcher.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)RequestResponseHeaders.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)SdkVersionUtils.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)StringUtilities.cs" />

Src/DependencyCollector/Shared/PropertyFetcher.cs → Src/Common/PropertyFetcher.cs

@@ -1,4 +1,4 @@
-namespace Microsoft.ApplicationInsights.DependencyCollector.Implementation
+namespace Microsoft.ApplicationInsights.Common
 {
     using System;
     using System.Reflection;

Src/DependencyCollector/Shared/DependencyCollector.Shared.projitems

@@ -42,7 +42,6 @@
     <Compile Include="$(MSBuildThisFileDirectory)Implementation\SqlClientDiagnostics\SqlClientDiagnosticFetcherTypes.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)Implementation\SqlClientDiagnostics\SqlClientDiagnosticSourceListener.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)Properties\AssemblyInfo.cs" />
-    <Compile Include="$(MSBuildThisFileDirectory)PropertyFetcher.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)SanitizedHostList.cs" />
     <Compile Include="$(MSBuildThisFileDirectory)TelemetryDiagnosticSourceListener.cs" />
   </ItemGroup>

Src/DependencyCollector/Shared/Implementation/EventHandlers/DiagnosticsEventHandlerBase.cs

@@ -5,6 +5,7 @@
     using System.Collections.Generic;
     using System.Diagnostics;
     using System.Threading.Tasks;
+    using Microsoft.ApplicationInsights.Common;
     using Microsoft.ApplicationInsights.Extensibility;
     using Microsoft.ApplicationInsights.Extensibility.Implementation;
 

Src/DependencyCollector/Shared/Implementation/HttpDesktopDiagnosticSourceListener.cs

@@ -4,6 +4,7 @@ namespace Microsoft.ApplicationInsights.DependencyCollector.Implementation
     using System;
     using System.Collections.Generic;
     using System.Net;
+    using Microsoft.ApplicationInsights.Common;
     using Microsoft.ApplicationInsights.Extensibility.Implementation.Tracing;
 
     /// <summary>

Src/DependencyCollector/Shared/Implementation/SqlClientDiagnostics/SqlClientDiagnosticFetcherTypes.cs

@@ -1,5 +1,7 @@
 namespace Microsoft.ApplicationInsights.DependencyCollector.Implementation.SqlClientDiagnostics
 {
+    using Microsoft.ApplicationInsights.Common;
+
     internal static class SqlClientDiagnosticFetcherTypes
     {
         //// These types map to the anonymous types defined here: System.Data.SqlClient.SqlClientDiagnosticListenerExtensions. 

Src/Web/Web.Net45.Tests/AspNetDiagnosticTelemetryModuleTest.cs

@@ -113,12 +113,21 @@ public void GrandChildTelemetryIsReportedProperlyBetweenBeginEndRequestWhenActiv
             var client = new TelemetryClient(this.configuration);
             client.TrackTrace(trace);
 
-            this.aspNetDiagnosticsSource.StopActivity();
+            this.aspNetDiagnosticsSource.ReportRestoredActivity(restoredActivity);
             Assert.AreEqual(2, this.sendItems.Count);
+            var requestRestoredTelemetry = (RequestTelemetry)this.sendItems.SingleOrDefault(i => i is RequestTelemetry);
+            Assert.IsNotNull(requestRestoredTelemetry);
 
-            var requestTelemetry = this.sendItems[0] as RequestTelemetry ?? this.sendItems[1] as RequestTelemetry;
+            this.aspNetDiagnosticsSource.StopActivity();
+            Assert.AreEqual(3, this.sendItems.Count);
+
+            var requestTelemetry = (RequestTelemetry)this.sendItems[2];
             Assert.IsNotNull(requestTelemetry);
 
+            Assert.AreEqual(requestTelemetry.Id, requestRestoredTelemetry.Context.Operation.ParentId);
+            Assert.AreEqual(restoredActivity.Id, requestRestoredTelemetry.Id);
+            Assert.AreEqual(requestTelemetry.Context.Operation.Id, requestRestoredTelemetry.Context.Operation.Id);
+
             Assert.AreEqual(restoredActivity.ParentId, requestTelemetry.Id);
             Assert.AreEqual(restoredActivity.Id, trace.Context.Operation.ParentId);
             Assert.AreEqual(requestTelemetry.Context.Operation.Id, trace.Context.Operation.Id);
@@ -345,6 +354,7 @@ private class FakeAspNetDiagnosticSource : IDisposable
             public const string IncomingRequestEventName = "Microsoft.AspNet.HttpReqIn";
             private const string AspNetListenerName = "Microsoft.AspNet.TelemetryCorrelation";
             private const string IncomingRequestStopLostActivity = "Microsoft.AspNet.HttpReqIn.ActivityLost.Stop";
+            private const string IncomingRequestStopRestoredActivity = "Microsoft.AspNet.HttpReqIn.ActivityRestored.Stop";
 
             private readonly DiagnosticListener listener;
 
@@ -433,6 +443,13 @@ public void StopLostActivity(Activity activity)
                 this.listener.Write(IncomingRequestStopLostActivity, new { activity });
             }
 
+            public void ReportRestoredActivity(Activity activity)
+            {
+                Debug.Assert(activity != null, "Activity is null");
+
+                this.listener.Write(IncomingRequestStopRestoredActivity, new { Activity = activity });
+            }
+
             public void Dispose()
             {
                 this.Dispose(true);

Src/Web/Web.Net45.Tests/RequestTrackingTelemetryModuleTest.Net45.cs

@@ -3,6 +3,7 @@
     using System;
     using System.Collections.Generic;
     using System.Diagnostics;
+    using System.Threading.Tasks;
     using System.Web;
 
     using Microsoft.ApplicationInsights.DataContracts;
@@ -193,7 +194,7 @@ public void OnBeginTelemetryCreatedWithinRequestScopeIsRequestChild()
         }
 
         [TestMethod]
-        public void OnPreHandlerTelemetryCreatedWithinRequestScopeIsRequestChild()
+        public async Task OnPreHandlerTelemetryCreatedWithinRequestScopeIsRequestChild()
         {
             var context = HttpModuleHelper.GetFakeHttpContext(new Dictionary<string, string>
             {
@@ -215,9 +216,16 @@ public void OnPreHandlerTelemetryCreatedWithinRequestScopeIsRequestChild()
             // CallContext was lost after OnBegin, so Asp.NET Http Module will restore it in OnPreRequestHandlerExecute
             new Activity("restored").SetParentId(activity.Id).AddBaggage("k", "v").Start();
 
-            // if OnPreRequestHandlerExecute set a CallContext, child telemetry will be properly filled
             var trace = new TraceTelemetry();
-            telemetryClient.TrackTrace(trace);
+
+            // run track trace in the async task, so that HttpContext.Current is not available and we could be sure
+            // telemetry is not initialized from it.
+            await Task.Run(() =>
+            {
+                // if OnPreRequestHandlerExecute set a CallContext, child telemetry will be properly filled
+                telemetryClient.TrackTrace(trace);
+            });
+
             var requestTelemetry = context.GetRequestTelemetry();
 
             Assert.Equal(requestTelemetry.Context.Operation.Id, trace.Context.Operation.Id);

Src/Web/Web.Net45/AspNetDiagnosticTelemetryModule.cs

@@ -21,6 +21,7 @@ public class AspNetDiagnosticTelemetryModule : IObserver<DiagnosticListener>, ID
         private const string IncomingRequestStartEventName = "Microsoft.AspNet.HttpReqIn.Start";
         private const string IncomingRequestStopEventName = "Microsoft.AspNet.HttpReqIn.Stop";
         private const string IncomingRequestStopLostActivity = "Microsoft.AspNet.HttpReqIn.ActivityLost.Stop";
+        private const string IncomingRequestStopRestoredActivity = "Microsoft.AspNet.HttpReqIn.ActivityRestored.Stop";
 
         private IDisposable allListenerSubscription;
         private RequestTrackingTelemetryModule requestModule;
@@ -117,6 +118,7 @@ private class AspNetEventObserver : IObserver<KeyValuePair<string, object>>
             private const string FirstRequestFlag = "Microsoft.ApplicationInsights.FirstRequestFlag";
             private readonly RequestTrackingTelemetryModule requestModule;
             private readonly ExceptionTrackingTelemetryModule exceptionModule;
+            private readonly PropertyFetcher activityFetcher = new PropertyFetcher(nameof(Activity));
 
             public AspNetEventObserver(RequestTrackingTelemetryModule requestModule, ExceptionTrackingTelemetryModule exceptionModule)
             {
@@ -182,6 +184,17 @@ public void OnNext(KeyValuePair<string, object> value)
                         this.requestModule?.OnEndRequest(context);
                     }
                 }
+                else if (value.Key == IncomingRequestStopRestoredActivity)
+                {
+                    var activity = (Activity)this.activityFetcher.Fetch(value.Value);
+                    if (activity == null)
+                    {
+                        WebEventSource.Log.ActivityIsNull(IncomingRequestStopRestoredActivity);
+                        return;
+                    }
+
+                    this.requestModule.TrackIntermediateRequest(context, activity);
+                }
             }
 
             #region IObserver

Src/Web/Web.Net45/Web.Net45.csproj

@@ -26,8 +26,8 @@
     <Reference Include="Microsoft.ApplicationInsights, Version=2.6.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35, processorArchitecture=MSIL">
       <HintPath>..\..\..\..\packages\Microsoft.ApplicationInsights.2.6.0-beta4\lib\net45\Microsoft.ApplicationInsights.dll</HintPath>
     </Reference>
-    <Reference Include="Microsoft.AspNet.TelemetryCorrelation, Version=1.0.1.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35, processorArchitecture=MSIL">
-      <HintPath>..\..\..\..\packages\Microsoft.AspNet.TelemetryCorrelation.1.0.1\lib\net45\Microsoft.AspNet.TelemetryCorrelation.dll</HintPath>
+    <Reference Include="Microsoft.AspNet.TelemetryCorrelation, Version=1.0.3.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35, processorArchitecture=MSIL">
+      <HintPath>..\..\..\..\packages\Microsoft.AspNet.TelemetryCorrelation.1.0.3\lib\net45\Microsoft.AspNet.TelemetryCorrelation.dll</HintPath>
     </Reference>
     <Reference Include="Microsoft.CSharp" />
     <Reference Include="System" />

Src/Web/Web.Net45/packages.config

@@ -3,7 +3,7 @@
   <package id="Desktop.Analyzers" version="1.1.0" targetFramework="net45" />
   <package id="MicroBuild.Core" version="0.3.0" targetFramework="net45" developmentDependency="true" />
   <package id="Microsoft.ApplicationInsights" version="2.6.0-beta4" targetFramework="net45" />
-  <package id="Microsoft.AspNet.TelemetryCorrelation" version="1.0.1" targetFramework="net45" />
+  <package id="Microsoft.AspNet.TelemetryCorrelation" version="1.0.3" targetFramework="net45" />
   <package id="StyleCop.Analyzers" version="1.0.2" targetFramework="net45" developmentDependency="true" />
   <package id="System.Diagnostics.DiagnosticSource" version="4.4.0" targetFramework="net45" />
 </packages>

Src/Web/Web.Nuget/Package.nuspec

@@ -19,7 +19,7 @@
       <group targetFramework="net45">
         <dependency id="Microsoft.ApplicationInsights" version="[$coresdkversion$]" />
         <dependency id="Microsoft.ApplicationInsights.WindowsServer" version="$version$" />
-        <dependency id="Microsoft.AspNet.TelemetryCorrelation" version="1.0.1" />
+        <dependency id="Microsoft.AspNet.TelemetryCorrelation" version="1.0.3" />
         <dependency id="System.Diagnostics.DiagnosticSource" version="4.4.0" />
       </group>
     </dependencies>

Src/Web/Web.Shared.Net.Tests/RequestTrackingTelemetryModuleTest.cs

@@ -1,13 +1,15 @@
 namespace Microsoft.ApplicationInsights.Web
 {
     using System;
+    using System.Collections.Concurrent;
     using System.Collections.Generic;
     using System.Diagnostics;
     using System.Globalization;
     using System.Web;
 
     using Microsoft.ApplicationInsights.Channel;
     using Microsoft.ApplicationInsights.Common;
+    using Microsoft.ApplicationInsights.DataContracts;
     using Microsoft.ApplicationInsights.Extensibility;
     using Microsoft.ApplicationInsights.Extensibility.Implementation;
     using Microsoft.ApplicationInsights.TestFramework;
@@ -28,10 +30,15 @@ public partial class RequestTrackingTelemetryModuleTest
         private const string TestInstrumentationKey2 = nameof(TestInstrumentationKey2);
         private const string TestApplicationId1 = nameof(TestApplicationId1);
         private const string TestApplicationId2 = nameof(TestApplicationId2);
-
+        private readonly ConcurrentQueue<RequestTelemetry> sentTelemetry = new ConcurrentQueue<RequestTelemetry>();
+
         [TestCleanup]
         public void Cleanup()
         {
+            while (this.sentTelemetry.TryDequeue(out _))
+            {
+            }
+
 #if NET45
             while (Activity.Current != null)
             {
@@ -404,9 +411,57 @@ public void OnEndDoesNotOverrideSourceField()
             Assert.Equal(TestApplicationId2, context.GetRequestTelemetry().Source);
         }
 
+        [TestMethod]
+        public void TrackIntermediateRequestSetsProperties()
+        {
+            string requestId = "|standard-id.";
+            var context = HttpModuleHelper.GetFakeHttpContext(new Dictionary<string, string>
+            {
+                ["Request-Id"] = requestId
+            });
+
+            var module = this.RequestTrackingTelemetryModuleFactory(this.CreateDefaultConfig(context));
+            module.OnBeginRequest(context);
+
+            var originalRequest = context.GetRequestTelemetry();
+            originalRequest.Start(Stopwatch.GetTimestamp() - (1 * Stopwatch.Frequency));
+
+            var restoredActivity = new Activity("dummy").SetParentId(originalRequest.Id).Start();
+
+            module.TrackIntermediateRequest(context, restoredActivity);
+
+            Assert.Equal(1, this.sentTelemetry.Count);
+            Assert.True(this.sentTelemetry.TryDequeue(out RequestTelemetry intermediateRequest));
+
+            Assert.Equal(originalRequest.Id, intermediateRequest.Context.Operation.ParentId);
+            Assert.Equal(originalRequest.Context.Operation.Id, intermediateRequest.Context.Operation.Id);
+            Assert.Equal(restoredActivity.StartTimeUtc, intermediateRequest.Timestamp);
+            Assert.Equal(restoredActivity.Duration, intermediateRequest.Duration);
+            Assert.True(intermediateRequest.Properties.ContainsKey("AI internal"));
+        }
+
         private TelemetryConfiguration CreateDefaultConfig(HttpContext fakeContext, string rootIdHeaderName = null, string parentIdHeaderName = null, string instrumentationKey = null)
         {
-            var config = TelemetryConfiguration.CreateDefault();
+            var telemetryChannel = new StubTelemetryChannel()
+            {
+                EndpointAddress = "https://endpointaddress",
+                OnSend = item =>
+                {
+                    if (item is RequestTelemetry request)
+                    {
+                        this.sentTelemetry.Enqueue(request);
+                    }
+                }
+            };
+
+            var configuration = new TelemetryConfiguration
+            {
+                TelemetryChannel = telemetryChannel,
+                InstrumentationKey = TestInstrumentationKey1,
+                ApplicationIdProvider = new MockApplicationIdProvider(TestInstrumentationKey1, TestApplicationId1)
+            };
+            configuration.TelemetryInitializers.Add(new Extensibility.OperationCorrelationTelemetryInitializer());
+
             var telemetryInitializer = new TestableOperationCorrelationTelemetryInitializer(fakeContext);
 
             if (rootIdHeaderName != null)
@@ -419,9 +474,9 @@ private TelemetryConfiguration CreateDefaultConfig(HttpContext fakeContext, stri
                 telemetryInitializer.ParentOperationIdHeaderName = parentIdHeaderName;
             }
 
-            config.TelemetryInitializers.Add(telemetryInitializer);
-            config.InstrumentationKey = instrumentationKey ?? Guid.NewGuid().ToString();
-            return config;
+            configuration.TelemetryInitializers.Add(telemetryInitializer);
+
+            return configuration;
         }
 
         private string GetActivityRootId(string telemetryId)

Src/Web/Web.Shared.Net/Implementation/WebEventSource.cs

@@ -467,6 +467,15 @@ public void InjectionCompleted(string appDomainName = "Incorrect")
             this.WriteEvent(47, this.ApplicationName);
         }
 
+        [Event(48,
+            Keywords = Keywords.Diagnostics,
+            Message = "Activity is null for event = '{0}'",
+            Level = EventLevel.Error)]
+        public void ActivityIsNull(string diagnosticsSourceEventName, string appDomainName = "Incorrect")
+        {
+            this.WriteEvent(48, diagnosticsSourceEventName, this.ApplicationName);
+        }
+
         [NonEvent]
         private string GetApplicationName()
         {