Application Insights logs double request telemetry with rewrite rule

[rajkumar-rangaraj]

Describe your environment.

Application Insights creates two request telemetry for ASP.NET requests which are processed with IIS UrlRewrite module

• Application Insights .NET SDK: 2.14.0
• Microsoft.AspNet.TelemetryCorrelation: 1.0.7
• .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.

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

Proposal

• For parent request, ignore creating activity in EndRequest
• Modify end request to create new activity only when below conditions are met
  • Begin Request is not fired – there is already a logic to identify this case
  • Create new activity in EndRequest only when HttpContext.Error is not null. If an exception is thrown before begin request, Error property of HttpContext will have exception details.