Spring DefaultWebFilterChain is called twice by a long http request

Hello everyone,

we have a reactive spring boot application (2.7.0). We have a HTTP POST Request which upload up to 5 GB of data. We are seeing that AuthorizationWebFilter.java is called twice. First call before the request reaches our controller which seems correct, the second call ist just after the request leaves our controller. Which is bad as our oauth token is only 1h and the request can take 1h and 10 minutes to upload. Further debugging showed that DefaultWebFilterChain.java uses:

@Override
public Mono<Void> filter(ServerWebExchange exchange) {
   return Mono.defer(() ->
         this.currentFilter != null && this.chain != null ?
               invokeFilter(this.currentFilter, this.chain, exchange) :
               this.handler.handle(exchange));
}

Could it be that we are just executing the filters at the end and this is why we call it twice?

Error has been observed at the following site(s):
    *__checkpoint ⇢ org.springframework.security.web.server.authorization.AuthorizationWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.web.server.authorization.ExceptionTranslationWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.web.server.authentication.logout.LogoutWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.web.server.savedrequest.ServerRequestCacheWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.web.server.context.SecurityContextServerWebExchangeWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.web.server.context.ReactorContextWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.web.server.header.HttpHeaderWriterWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.config.web.server.ServerHttpSecurity$ServerWebExchangeReactorContextWebFilter [DefaultWebFilterChain]
    *__checkpoint ⇢ org.springframework.security.web.server.WebFilterChainProxy [DefaultWebFilterChain]
    *__checkpoint ⇢ HTTP POST \"/api/v1/datasets/3ceebdac-4070-4fc2-a4d4-1d10c679aade/entries?filename=Archive.zip\" [ExceptionHandlingWebHandler]

Comment From: bclozel

Using a vanilla WebFlux application and a custom filter registered, I'm seeing that the filter is called once and its lifecycle seems right:

2022-06-22 11:43:57.524  INFO 39456 --- [ctor-http-nio-2] com.example.webfilter.MyWebFilter        : filter subscribe
2022-06-22 11:43:57.546  INFO 39456 --- [ctor-http-nio-2] com.example.webfilter.MyController       : controller subscribe
2022-06-22 11:44:07.548  INFO 39456 --- [     parallel-1] com.example.webfilter.MyController       : controller on success
2022-06-22 11:44:07.571  INFO 39456 --- [ctor-http-nio-2] com.example.webfilter.MyWebFilter        : filter on success

Could you share a sample application that demonstrates the problem? You can simulate a long-running controller method with something like:

    @GetMapping("/")
    public Mono<String> some() {
        return Mono.delay(Duration.ofSeconds(10))
                .thenReturn("Hello delayed")
                .doOnSubscribe(sub -> logger.info("controller on subscribe"))
                .doOnSuccess(message -> logger.info("controller on success"));
    }

As for the authentication filter, you can turn on debug logging to show when it's being called and configure a simpler authentication mechanism for demo purposes. I'm moving this issue to Spring Framework for now until we understand the issue here.

Comment From: jomach

Ok, I think my assumption is wrong. After activating the logs I see:

2022-06-22 12:16:30.020 DEBUG 95413 --- [     parallel-5] a.DelegatingReactiveAuthorizationManager : Checking authorization on '/api/v1/datasets/24ad64a6-1fca-4534-8ffd-80ef4544a170/entries' using org.springframework.security.authorization.AuthorityReactiveAuthorizationManager@3ee7da5d
2022-06-22 12:16:30.022 DEBUG 95413 --- [     parallel-5] o.s.s.w.s.a.AuthorizationWebFilter       : Authorization successful

I guess it is something else. I will close this for now and reopen if I have more feedback