Request time is not measured correctly for async requests

[rpiotrow]

When request returns CompletableFuture or is asynchronous in some other way WebRequestTrackingFilter will measure only time until CompletableFuture is returned, but request is not completed after that. Additional work (defined in CompletableFuture) will be done to return response to client - this time won't be measured by WebRequestTrackingFilter.

[dhaval24]

@rpiotrow Thank you for letting us know the issue. Can you please provide us with additional steps to reproduce this issue?

[rpiotrow]

Sure, I'll prepare simple example and attach it here in a day or two.

[dhaval24]

@rpiotrow sure this would be great. By the way is this something like a new feature introduced in JDK 9?

[rpiotrow]

I'm attaching example application. To run it just unarchive it and invoke mvn spring-boot:run (assuming you have instaled Maven). To enable sending metrics to Application Insights you need to add APPLICATION_INSIGHTS_IKEY environment variable with instrumentation key from Azure (e.g. export APPLICATION_INSIGHTS_IKEY="xxxx-xxxx-xxxx-xxxx-xxxx")

sample-app.zip

When making request using curl in console:

time curl -s http://localhost:8080/
Hello World!
real    0m2.012s
user    0m0.000s
sys     0m0.004s

and in the Application Insights in Azure:

@dhaval24 asynchronous requests are part of Servlet 3.0 specification (not very new thing), CompletableFuture is from Java 8.

[dhaval24]

@rpiotrow thank you very much for submitting a repro. We will have a look and assign it to appropriate milestone.

[dhaval24]

@rpiotrow do you have a suggested fix for this issue? I know it has been hanging around here for a while and we haven't been able to catch up on this because of High P. issues. Let me know if there is a fix in your mind. We are also very open to accept contributions so please feel free to raise a PR if you wish to

[rpiotrow]

I would try to use Spring interceptors instead of filters, but I'm not sure if this will solve the isssue (it should be tested first) and I'm not sure if you have/consider dependency to Spring Framework.

[dhaval24]

@rpiotrow taking an explicit dependency on Spring is something I won't encourage unless there is no alternative way to do this. I fear by using Spring Interceptors, we might then well not be able to support J2EE and Standard Java Servelet Monitoring.

[mjrousos]

I'm seeing a similar issue. Let me know if you'd like it logged as a separate issue but I think it's the same root cause (WebRequestFilterTracking not handling async scenarios properly).

I noticed that when I have an async request handler (returning a CompletableFuture), there are two separate requests reported to AppInsights with different operation IDs for each request made by a user! It seems that one corresponds to the portion of the method before the CompletableFuture is returned (and it always has a status code of '200' according to App Insights, even if the eventual response has a different code) and another corresponding to the asynchronous portion of the request handler.

Having different operation IDs, potentially different returned status codes, and incorrect request times makes the resulting logs less useful.

Here's some repro code:

// Async request + logback logging
@RequestMapping(value="/{id}", method=RequestMethod.GET)
public @ResponseBody Future<PuzzleDto> findPuzzle(@PathVariable(name = "id", required = true) int id) {
    // One "request" is reported to App Insights for this portion of the request handling method
    return CompletableFuture.supplyAsync(() -> {
        // A second request is reported for this portion!
        PuzzleDto puzzle = puzzles.findOne(id);
        if (puzzle == null) {
            throw new PuzzleNotFoundException(id);
        }
        
        // The App Insights trace generated by this logging will have the same operation ID as the second request, but not the same as the first.
        logger.info("Retrieved puzzle {} with difficulty {}", puzzle.id, puzzle.difficulty);

        return puzzle;
    });
}

My request tracking filter is configured with the following code and config:

// Register filters so that we can add the App Insights filter
@Bean
public FilterRegistrationBean registerFilters() {
    FilterRegistrationBean registration = new FilterRegistrationBean();
    registration.setFilter(appInsightsWebRequestTrackingFilter());
    registration.addUrlPatterns("/*");
    registration.setName("webRequestTrackingFilter");
    registration.setOrder(1);
    return registration;
}

// Register App Insights filter
@Bean(name = "appInsightsWebRequestTrackingFilter")
public Filter appInsightsWebRequestTrackingFilter() {
    WebRequestTrackingFilter filter =  new WebRequestTrackingFilter(appName);
    return filter;
}

<?xml version="1.0" encoding="utf-8"?>
<ApplicationInsights xmlns="http://schemas.microsoft.com/ApplicationInsights/2013/Settings" schemaVersion="2014-05-30">

  <!-- Can also be set with env var APPLICATION_INSIGHTS_IKEY -->
  <InstrumentationKey>00000000-0000-0000-0000-000000000000</InstrumentationKey>

  <TelemetryModules>
    <Add type="com.microsoft.applicationinsights.web.extensibility.modules.WebRequestTrackingTelemetryModule"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.modules.WebSessionTrackingTelemetryModule"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.modules.WebUserTrackingTelemetryModule"/>
  </TelemetryModules>

  <!-- These initializers add context data to each event -->
  <TelemetryInitializers>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebOperationIdTelemetryInitializer"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebOperationNameTelemetryInitializer"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebSessionTelemetryInitializer"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebUserTelemetryInitializer"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebUserAgentTelemetryInitializer"/>
  </TelemetryInitializers>
</ApplicationInsights>

Relevant packages are Spring Boot 1.5.9 starters for web and logging along with 2.0.0-BETA AI pacakges:

<dependency>
  <groupId>com.microsoft.azure</groupId>
  <artifactId>applicationinsights-web</artifactId>
  <version>2.0.0-BETA</version>
</dependency>

<dependency>
  <groupId>com.microsoft.azure</groupId>
  <artifactId>applicationinsights-logging-logback</artifactId>
  <version>2.0.0-BETA</version>
</dependency>

[dhaval24]

@mjrousos thank you very much for the detailed explanation. I think there is no need for a separate issue. I think this would mostly be a feature request to support async request handling. We will investigate and triage this appropriately. Do you have any potential fix in your mind for this apart from Spring Interceptors, because then this would force us to take an explicit dependency on Spring Framework.

[dhaval24]

This should be fixed now with #830

[dhaval24]

@rpiotrow @mjrousos the fix should be available in the upcoming release. I will also publish code sample on how to propagate context for async requests.