ServerHttpObservationFilter does not register against new async operations

[hanson76]

Affects: Spring Framework 6.1.9 - current

The change introduced to ServerHttpObservationFilter in 6.1.9 causes requests that executes multiple asynchronous cycles to not get any observations and the observation will never be closed, the listener will not receive any callbacks.

The listener in ServerHttpObservationFilter need to add itself to the AsyncContext provided in the AsyncEvent provide when onStartAsync(AsyncEvent event) is being called. The listener will not receive any other callbacks unless this is done.

This happens if there is a servlet filter with lower priority in the filter chain that do asynchronous work (calls startAsync() on the request) before dispatching the request to further filters or Spring handlers, that in turn calls startAsync() on the request.

[bclozel]

This sounds very specific. We're going to need a minimal sample application to reproduce the case and properly test it.

[hanson76]

We did some further investigation while creating a minimal Spring Boot demo application showing this error.
We can reproduce it with Spring Boot 3.3.1 but not with Spring Boot 3.3.2 or 3.3.3
We have no other dependencies.

The difference is that ServerHttpObservationFilter.doFilterInternal is not called after dispatch() with Spring Boot 3.3.1, but is with 3.3.2 and 3.3.3.
Not sure if this is the correct behavour yet,

The first call will create an observation that is never "stopped", the listener added here will not be called.
The second call to doFilterInternal creates a new observation and the listener added is being called correctly.

Attached is a small zip file containing a very simple example.
We verify it by calling the only endpoint exposed, and then calling actuator/metrics/http.server.requests afterwards.

time curl http://localhost:8080/ : should take ~2seconds (2 times 1 second async delays)

curl http://localhost:8080/actuator/metrics/http.server.requests|jq should output json document

The outcome when this works is that we get json data from the actuator endpoint.
The outcome when this is not working is that we do not get any data from the actuator endpoint.

demo.zip

[bclozel]

Project seems empty with no controller endpoint nor custom filter. Am I missing something?

[hanson76]

THe zip file indeed look to be broken! attached a new one.

The application.properties is bit different, ran it on a custom port 10000 locally not 8080

demo.zip

[bclozel]

Thanks for the update.

public class AsyncFilter extends OncePerRequestFilter {

  private final TaskScheduler scheduler;

  public AsyncFilter(TaskScheduler scheduler) {
    this.scheduler = scheduler;
  }

  @Override
  protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) {

    final AsyncContext asyncContext = request.startAsync(request, response);

    scheduler.schedule(() -> later(asyncContext), Instant.now().plusSeconds(1));
  }

  private void later(AsyncContext asyncContext) {
    asyncContext.dispatch();
  }
}

I know that coming up with a minimal sample can be hard, but here the Async filter looks invalid for several reasons:

1. the doFilterInternal never calls the filter chain so filters are not executed or not in the order they should
2. the scheduled work calls asyncContext.dispatch(); which... dispatches the exchange back to the container but the async context is never completed. Maybe explain what is the goal of this filter?
3. it seems the filter is competing with the actual controller for the response. Trying to fix one of the problems listed above results in exceptions thrown by the Servlet container or an invalid HTTP response.