Double request telemetry logging if rewrite rule is used

[rajkumar-rangaraj]

Describe your environment.
Two request telemetry are getting created for the requests which are processed with IIS UrlRewrite module

• SDK version: 2.13.1
• .NET runtime version (.NET or .NET Core, TargetFramework in the .csproj file): 4.7.2
• Hosting Info (IIS/Azure WebApps/etc): IIS / App Service with URL Rewrite module
• Platform and OS version: Windows 10 (IIS 10)

Steps to reproduce.
Describe exactly how to reproduce the error. Include a code sample if applicable.

1. Create default ASP.NET MVC app, install ApplicationInsights SDK, set up ikey to send data
2. Host it on IIS
3. Create rewrite rule as following:

<system.webServer>
    <validation validateIntegratedModeConfiguration="false" />
    <modules>
      <remove name="TelemetryCorrelationHttpModule" />
      <add name="TelemetryCorrelationHttpModule" type="Microsoft.AspNet.TelemetryCorrelation.TelemetryCorrelationHttpModule, Microsoft.AspNet.TelemetryCorrelation" preCondition="managedHandler" />
      <remove name="ApplicationInsightsWebTracking" />
      <add name="ApplicationInsightsWebTracking" type="Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule, Microsoft.AI.Web" preCondition="managedHandler" />
    </modules>
        <rewrite>
            <rules>
                <rule name="AboutRedirect" stopProcessing="true">
                    <match url="Home/About" />
                    <action type="Rewrite" url="home/index" />
                </rule>
            </rules>
        </rewrite>
  </system.webServer>
</configuration>

4. Hit the webpage “http://localhost/Home/About” – as expected the index page will be displayed.
5. Navigate to Application Insights resource and observe following:

What is the expected behavior?
What did you expect to see?
Only one entry should be displayed.

What is the actual behavior?
What did you see instead?
Right now this is a double logging for the same request.

Additional context.
Collected Perfview to investigate an issue. ASP.NET pipeline is considering it has two different request. Microsoft-Windows-ASPNET/Request/Start and Microsoft-Windows-ASPNET/Request/Stop are called for actual request and rewritten request.
Further investigation required to understand if this needs to be fixed in Application Insights SDK or at the ASP.NET framework.

Below snapshot are from Perfview trace collected on my machine.

[TimothyMothra]

This sounds identical to an issue I worked on 2 years ago. IIS will create "child" requests that lose the context of the original request.
From the SDK's perspective, it sees two unique requests.

I wrote the ChildRequestTrackingSuppressionModule to deal with this. Perhaps this can be expanded to support this.

ApplicationInsights-dotnet/WEB/Src/Web/Web.Shared.Net/RequestTrackingTelemetryModule.cs

Lines 321 to 339 in ce1473c

	/// <summary>
	/// <see cref="System.Web.Handlers.TransferRequestHandler"/> can create a Child request to route extension-less requests to a controller.
	/// (ex: site/home -> site/HomeController.cs)
	/// We do not want duplicate telemetry logged for both the Parent and Child requests, so the activeRequests will be created OnBeginRequest.
	/// When the child request OnEndRequest, the id will be removed from this dictionary and telemetry will not be logged for the parent.
	/// </summary>
	/// <remarks>
	/// Unit tests should disable the ChildRequestTrackingSuppressionModule.
	/// Unit test projects cannot create an [internal] IIS7WorkerRequest object.
	/// Without this object, we cannot modify the Request.Headers without throwing a PlatformNotSupportedException.
	/// Unit tests will have to initialize the RequestIdHeader.
	/// The second IF will ensure the id is added to the activeRequests.
	/// </remarks>
	/// <remarks>
	/// IIS Classic Pipeline should disable the ChildRequestTrackingSuppressionModule.
	/// Classic does not create IIS7WorkerRequest object and Headers will be read-only.
	/// (Exception System.PlatformNotSupportedException: This operation requires IIS integrated pipeline mode.)
	/// </remarks>
	private class ChildRequestTrackingSuppressionModule

[rajkumar-rangaraj]

More Information

Rewrite

In case of rewrite, a new request context is created, called the child request, and it goes through the entire IIS/ASP.NET integrated pipeline. The child request can be mapped to any of the handlers configured in IIS, and it's execution is no different than it would be if it was received via the HTTP stack. The parent request jumps ahead in the pipeline to the end request notification, and waits for the child request to complete. When the child request completes, the parent request executes the end request notifications and completes itself.

Original Request (Parent Request)	Rewritten Request (Child Request)

Reference: https://docs.microsoft.com/en-us/archive/msdn-magazine/2002/september/asp-net-request-processing-filtering-and-content-redirection

If a module aborts normal message handling during an event handler by calling CompleteRequest, the ASP.NET HTTP pipeline interrupts processing after that event completes. However, EndRequest and the events that follow are still fired. Thus, any modules that acquired valuable resources before processing was terminated have a chance to clean up those resources. For instance, if a module acquired a lock against shared state in its BeginRequest event handler, it can release the lock in its EndRequest event handler and be confident that the right thing will happen. The EndRequest event will fire even if some other module calls CompleteRequest and the HTTP message is never delivered to a handler.

What causes double telemetry issue?

• On rewrite, both parent and child request creates its own HttpContext. There are no ways to relate parent and child request context in managed modules (.NET Modules). But parent and child context can be very easily related in native modules (C++).
• As discussed above, parent request jumps directly to Endrequest without calling BeginRequest of TelemetryCorrelationHttpModule. As begin request is not called, TelemetryCorrelationHttpModule creates new activity for the parent request.
• Child request is considered as new request and it goes through normal request-response pipeline, this results in another activity
  • Activity1 - Original/Parent Request
  • Activity2 – Rewritten/Child Request

Why Endrequest of TelemetryCorrelationHttpModule creates new Activity when it does not have BeginRequest?

• If there is an exception before begin request, control gets directly transferred to end request
• To capture request telemetry on these errors, create new activity in end request (Begin request not called in this case) helps

Which Module requires a fix?

• A module in Microsoft.AspNet.TelemetryCorrelation repo need to be fixed to ignore activity on original(parent) request.

[rajkumar-rangaraj]

Moved issue to aspnet/Microsoft.AspNet.TelemetryCorrelation#73