Duplicate call of FilterChainProxy with SpringSecurity, MVC and

I encounter a strange behaviour in my Spring-Boot project (v4.0.6):

When I execute a Controller which returns ResponseEntity<StraingResponseBody> for writing NDJSON-Lines the FilterChainProxy of SpringSecurity will get invoked twice. In the second invocation it looses the previous resolved Authentication object and throws an error.

The Controller is defined as such:

@RestController
public class AsyncController {
    private Logger logger = LoggerFactory.getLogger(AsyncController.class);
    
    @GetMapping("/tests/async/run")
    public ResponseEntity<StreamingResponseBody> run() {
    List<String> data = new ArrayList<>();
        Random random = new Random();
    for (int i = 0; i < 50; i++) {
        data.add(random.nextInt() + "");
    }
        
    StreamingResponseBody responseBody = os -> {
            final AtomicLong i = new AtomicLong();
            try (Stream<String> s = data.stream()) {
        s.forEach(e -> {
                    try {
                        os.write(e.getBytes());
                        os.write('n');
                    } catch (Exception ex) {
                        logger.error("Could not send bytes!", ex);
            }
                });
             }
    };
        
         return ResponseEntity
            .status(HttpStatus.OK)
            .contentType(MediaType.APPLICATION_NDJSON)
            .body(responseBody);    
    }
}

The configured HttpSecurity-Object does - from my point of view - nothing fancy. Except: I use a custom AuthenticationFilterfor populating the Authentication object. This AuthenticationFilter is not managed by Spring - instead it is directly instantiated when configuring the "http"-instance of Spring-Security:

http
    .csrf(CsrfConfigurer::disable)
    .httpBasic(AbstractHttpConfigurer::disable)
    .sessionManagement(session -> session.sessionCreationPolicy(SessionCreationPolicy.STATELESS))
        .headers(HeadersConfigurer::disable)
        .exceptionHandling(ehc ->
            ehc.authenticationEntryPoint(new NoOpAuthenticationEntryPoint() {

                @Override
                public void commence(HttpServletRequest req, HttpServletResponse res,
                        AuthenticationException e) 
                throws IOException, ServletException {
                    res.setStatus(HttpStatus.FORBIDDEN_403);
                    
                    res.getWriter().println(
                            mapper.writeValueAsString(
                                ResponseDTO.of(e)));
                    
                    res.getWriter().flush();
                    res.getWriter().close();
                }
            })
        )
        .addFilterBefore(
            new AuthenticationFilter(authService), 
            AnonymousAuthenticationFilter.class)

.authorizeHttpRequests(auth -> auth
                .requestMatchers("/").permitAll()
                .requestMatchers("/favicon.ico").permitAll()
                .requestMatchers("/_stylesheet.css").permitAll()
                .requestMatchers("/*.html").permitAll()
                .anyRequest().hasAnyAuthority("ROLE_AUTHENTICATED")
            );

And finally the custom AuthenticationFilter-Object:

// This is NOT controlled by the Spring-Container
public class AuthenticationFilter extends OncePerRequestFilter {
    AuthService authService;
    
    public AuthenticationFilter(AuthService authService) {
        this.authService = authService;
    }
    
    @Override
    public void doFilterInternal(HttpServletRequest req, HttpServletResponse res, FilterChain chain)
    throws IOException, ServletException {
        try {
// Reads a "token" from the request and tries to find 
// a corresponding user in a DB. This is then returned as a Auth-Object.
            Authentication authentication = 
                authService.getAuthentication((HttpServletRequest)req);
            
            SecurityContextHolder.getContext()
                .setAuthentication(authentication);
            
            chain.doFilter(req, res);
        } catch (AccessDeniedException ade) {
            throw ade;
        } catch (Exception exp) {
            throw new ServletException(exp);
        }
    }
}

When ruing a request against the specified Controller I see the follwing output:

32561 12:09:16 [main] DEBUG o.s.s.w.DefaultSecurityFilterChain : Will secure any request with filters: DisableEncodeUrlFilter, WebAsyncManagerIntegrationFilter, SecurityContextHolderFilter, LogoutFilter, RequestCacheAwareFilter, SecurityContextHolderAwareRequestFilter, AuthenticationFilter, AnonymousAuthenticationFilter, SessionManagementFilter, ExceptionTranslationFilter, AuthorizationFilter
32561 12:09:17 [main] INFO  o.h.v.i.u.Version         : HV000001: Hibernate Validator 9.0.1.Final
32561 12:09:17 [main] INFO  o.s.b.w.a.WelcomePageHandlerMapping : Adding welcome page: class path resource [static/index.html]
32561 12:09:18 [main] INFO  o.s.b.StartupInfoLogger   : Started AsyncControllerTest in 9.736 seconds (process ruing for 12.461)
OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended
32561 12:09:19 [main] INFO  o.s.m.w.MockServletContext : Initializing Spring TestDispatcherServlet ''
32561 12:09:19 [main] INFO  o.s.w.s.FrameworkServlet  : Initializing Servlet ''
32561 12:09:19 [main] INFO  o.s.w.s.FrameworkServlet  : Completed initialization in 3 ms
32561 12:09:19 [main] INFO  c.z.h.HikariDataSource    : main - Starting...
32561 12:09:19 [main] INFO  c.z.h.p.HikariPool        : main - Added coection com.mysql.cj.jdbc.CoectionImpl@2a1fce44
32561 12:09:19 [main] INFO  c.z.h.HikariDataSource    : main - Start completed.
32561 12:09:19 [main] DEBUG o.s.s.w.FilterChainProxy  : Securing GET /tests/async/run
32561 12:09:19 [main] DEBUG o.s.s.w.FilterChainProxy  : Secured GET /tests/async/run
32561 12:09:19 [main] INFO  w.r.a.a.RequestLoggingInterceptor : tester@/tests/async/run
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 10
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 20
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 30
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 40
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 50
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 60
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 70
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 80
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 90
32561 12:09:20 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 100
32561 12:09:20 [main] DEBUG o.s.s.w.FilterChainProxy  : Securing GET /tests/async/run
32561 12:09:20 [main] DEBUG o.s.s.w.a.AnonymousAuthenticationFilter : Set SecurityContextHolder to anonymous SecurityContext
[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 12.87 s <<< FAILURE! -- in wdc.rest.api.test.AsyncControllerTest
[ERROR] wdc.rest.api.test.AsyncControllerTest.run -- Time elapsed: 1.504 s <<< ERROR!
org.springframework.web.reactive.function.client.WebClientRequestException: Unable to handle the Spring Security Exception because the response is already committed.
        at org.springframework.web.reactive.function.client.ExchangeFunctions$DefaultExchangeFunction.lambda$wrapException$0(ExchangeFunctions.java:139)
        at reactor.core.publisher.MonoErrorSupplied.subscribe(MonoErrorSupplied.java:56)
        at reactor.core.publisher.Mono.subscribe(Mono.java:4569)
        at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:104)
        at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:225)
        at reactor.core.publisher.FluxPeek$PeekSubscriber.onError(FluxPeek.java:225)
        at reactor.core.publisher.FluxMap$MapSubscriber.onError(FluxMap.java:134)
        at reactor.core.publisher.Operators.error(Operators.java:198)
        at reactor.core.publisher.MonoError.subscribe(MonoError.java:54)
        at reactor.core.publisher.Mono.subscribe(Mono.java:4569)
        at reactor.core.publisher.Mono.block(Mono.java:1799)
        at org.springframework.test.web.reactive.server.DefaultWebTestClient$DefaultRequestBodyUriSpec.exchange(DefaultWebTestClient.java:375)
        at wdc.rest.api.test.AsyncControllerTest.run(AsyncControllerTest.java:24)
        Suppressed: java.lang.Exception: #block terminated with an error
                at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:145)
                at reactor.core.publisher.Mono.block(Mono.java:1800)
                ... 2 more
Caused by: jakarta.servlet.ServletException: Unable to handle the Spring Security Exception because the response is already committed.

The main problem I see here is that after all objects have been streamed the FilterChainProxy seems to Secure the same request again - but seems to have lost the information of the Authentication-Object. When calling a 'normal' synchronous method such behaviour caot be observed. Any ideas what causes the second call of the FilterChainProxy or what I am doing wrong here?

-- Edit I still have not found a solution. Yet, I could narrow it someway down. If I modify the AuthenticationFilter as such:

public class AuthenticationFilter extends OncePerRequestFilter {
    
    //...

    protected boolean shouldNotFilterAsyncDispatch() {
    return false;
    }
}

The resulting second call to the FilterChainProxy picks up the correct Authentication-Object:

9765 13:10:39 [main] INFO  c.z.h.HikariDataSource    : main - Start completed.
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy  : Trying to match request against DefaultSecurityFilterChain defined as 'filterChain' in [class path resource [wdc/rest/api/RestServiceConf.class]] matching [any request] and having filters [DisableEncodeUrl, WebAsyncManagerIntegration, SecurityContextHolder, RequestCacheAware, SecurityContextHolderAwareRequest, Authentication, AnonymousAuthentication, SessionManagement, ExceptionTranslation, Authorization] (1/1)
9765 13:10:39 [main] DEBUG o.s.s.w.FilterChainProxy  : Securing GET /tests/async/run
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking DisableEncodeUrlFilter (1/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking WebAsyncManagerIntegrationFilter (2/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking SecurityContextHolderFilter (3/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking RequestCacheAwareFilter (4/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking SecurityContextHolderAwareRequestFilter (5/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking AuthenticationFilter (6/10)
9765 13:10:39 [main] TRACE o.s.s.w.c.SupplierDeferredSecurityContext : Created SecurityContextImpl [Null authentication]
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking AnonymousAuthenticationFilter (7/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking SessionManagementFilter (8/10)
9765 13:10:39 [main] TRACE o.s.s.w.a.AnonymousAuthenticationFilter : Did not set SecurityContextHolder since already authenticated ApiKeyAuthentication [Principal=tester, Credentials=[PROTECTED], Authenticated=true, Details=AppUser[id=3, login=tester, token=thetoken, permissions=[PermissionEntry[objects=selection:createWithSelection, read=true, write=true], PermissionEntry[objects=snapshot:%, read=true, write=false]]], Granted Authorities=[ROLE_AUTHENTICATED]]
9765 13:10:39 [main] TRACE o.s.s.w.a.s.CompositeSessionAuthenticationStrategy : Preparing session with ChangeSessionIdAuthenticationStrategy (1/1)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking ExceptionTranslationFilter (9/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking AuthorizationFilter (10/10)
9765 13:10:39 [main] TRACE o.s.s.w.a.i.RequestMatcherDelegatingAuthorizationManager : Authorizing GET /tests/async/run
9765 13:10:39 [main] TRACE o.s.s.w.a.i.RequestMatcherDelegatingAuthorizationManager : Checking authorization on GET /tests/async/run using AuthorityAuthorizationManager[authorities=[ROLE_AUTHENTICATED]]
9765 13:10:39 [main] DEBUG o.s.s.w.FilterChainProxy  : Secured GET /tests/async/run
9765 13:10:39 [main] INFO  w.r.a.a.RequestLoggingInterceptor : started: tester@/tests/async/run
9765 13:10:39 [main] INFO  w.r.a.a.RequestLoggingInterceptor :   log.id: 12534
9765 13:10:39 [main] INFO  w.r.a.c.AsyncController   : run!
9765 13:10:39 [main] WARN  w.r.a.a.RequestLoggingInterceptor : START async
9765 13:10:39 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 10
9765 13:10:39 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 20
9765 13:10:39 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 30
9765 13:10:39 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 40
9765 13:10:39 [asyncThread-1] INFO  w.r.a.c.AsyncController   : Objects streamed: 50
9765 13:10:39 [asyncThread-1] INFO  w.r.a.c.AsyncController   : finished!
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy  : Trying to match request against DefaultSecurityFilterChain defined as 'filterChain' in [class path resource [wdc/rest/api/RestServiceConf.class]] matching [any request] and having filters [DisableEncodeUrl, WebAsyncManagerIntegration, SecurityContextHolder, RequestCacheAware, SecurityContextHolderAwareRequest, Authentication, AnonymousAuthentication, SessionManagement, ExceptionTranslation, Authorization] (1/1)
9765 13:10:39 [main] DEBUG o.s.s.w.FilterChainProxy  : Securing GET /tests/async/run
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking DisableEncodeUrlFilter (1/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking WebAsyncManagerIntegrationFilter (2/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking SecurityContextHolderFilter (3/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking RequestCacheAwareFilter (4/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking SecurityContextHolderAwareRequestFilter (5/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking AuthenticationFilter (6/10)
9765 13:10:39 [main] TRACE o.s.s.w.c.SupplierDeferredSecurityContext : Created SecurityContextImpl [Null authentication]
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking AnonymousAuthenticationFilter (7/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking SessionManagementFilter (8/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking ExceptionTranslationFilter (9/10)
9765 13:10:39 [main] TRACE o.s.s.w.FilterChainProxy$VirtualFilterChain : Invoking AuthorizationFilter (10/10)
9765 13:10:39 [main] TRACE o.s.s.w.a.i.RequestMatcherDelegatingAuthorizationManager : Authorizing GET /tests/async/run
9765 13:10:39 [main] TRACE o.s.s.w.a.i.RequestMatcherDelegatingAuthorizationManager : Checking authorization on GET /tests/async/run using org.springframework.security.authorization.SingleResultAuthorizationManager@1934a7c1
9765 13:10:39 [main] DEBUG o.s.s.w.FilterChainProxy  : Secured GET /tests/async/run
9765 13:10:39 [main] TRACE o.s.s.w.a.AnonymousAuthenticationFilter : Did not set SecurityContextHolder since already authenticated ApiKeyAuthentication [Principal=tester, Credentials=[PROTECTED], Authenticated=true, Details=AppUser[id=3, login=tester, token=thetoken, permissions=[PermissionEntry[objects=selection:createWithSelection, read=true, write=true], PermissionEntry[objects=snapshot:%, read=true, write=false]]], Granted Authorities=[ROLE_AUTHENTICATED]]

But still I wonder, why the FilterChainProxy is called again after the original request has been secured.

Any further ideas?

سوالات متداول

چرا Duplicate call of FilterChainProxy with SpringSecurity, MVC and StringResponseBody اهمیت دارد؟

این موضوع به دلیل اطلاعات و کاربردهای مرتبط، مورد توجه کاربران قرار گرفته است.