RequestLoggingFilter: `afterRequest` is executed before Async servlet finishes

[svilen-ivanov-kubit]

Affects: 5.3.18 (via Spring Boot 2.6.6)

When I configure org.springframework.web.filter.CommonsRequestLoggingFilter I notice that servlet log messages appear after the lines from afterRequest:

2022-04-06 20:15:40,289 DEBUG [qtp2065957432-37] c.k.k.c.l.RequestLoggingFilter [73355343-b7fb-4e93-b82b-339009931d2c][]: Before request [POST /graphql, ....
2022-04-06 20:15:40,338 DEBUG [qtp2065957432-37] c.k.k.c.l.RequestLoggingFilter [73355343-b7fb-4e93-b82b-339009931d2c][]: After request [POST /graphql,  ...
2022-04-06 20:15:40,499 DEBUG [graphql-exec-1] o.a.i.l.j.BaseJdbcLogger [][]: ==>  Preparing: SELECT id, name, ....
2022-04-06 20:15:40,504 DEBUG [graphql-exec-1] o.a.i.l.j.BaseJdbcLogger [][]: ==> Parameters: ....
2022-04-06 20:15:40,513 DEBUG [graphql-exec-1] o.a.i.l.j.BaseJdbcLogger [][]: <==      Total: 1

I expect the After request ... to appear after the graphql-exec-1 thread which services the response.

I'm using GraphQL Java which processes requests asynchronously.

If I add javax.servlet.AsyncContext#addListener(javax.servlet.AsyncListener) and I hook on onComplete to call afterRequest, it is properly called at the end of the request.

Digging deeper, it seems this condition is true because there is no this.asyncWebRequest in here.

I think this out of order execution violates the contract of the CommonsRequestLoggingFilter.

[svilen-ivanov-kubit]

More details after investigation:

1. If I use simple rest controller with @Async annotation, the afterRequest is properly invoked after async action completes.
2. GraphQL (graphql-spring-boot-autoconfigure-12.0.0) registers its servlet using ServletRegistrationBean and properly sets that its servlet supports async operations.
3. GraphQL starts the async:

AsyncContext asyncContext =
        request.isAsyncStarted()
            ? request.getAsyncContext()
            : request.startAsync(request, response);

It looks like until GraphQL starts processing the request, it is not considered async by Spring.

[svilen-ivanov-kubit]

Perhaps a final comment. Spring servlets do not go over org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter#invokeHandlerMethod which initialises WebAsyncManager which CommonsRequestLoggingFilter uses to determine request lifecycle. The latter is not suited for hybrid environment: Spring bound controllers and plain Servlets. Perhaps resorting to pure servlet filter to log request start and end.