Spring Security Filter chain executed twice per request. Why?

Question

I have a Spring Boot 2.1 project with Spring Security. It consists of an API and the Spring Security chain only has to validate a JWT token and check the permission of the different endpoints. This is my configuration:

@EnableWebSecurity
public class SecurityConfiguration extends WebSecurityConfigurerAdapter {

    @Bean
    public AuthenticationManager authenticationManager() {
        return new JwtAuthenticationManager();
    }

    @Override
    protected void configure(HttpSecurity http) throws Exception {
        http.httpBasic().disable()
                .csrf().disable()
                .sessionManagement().sessionCreationPolicy(SessionCreationPolicy.STATELESS)
                .and()
                .exceptionHandling().authenticationEntryPoint(
                (req, rsp, e) -> rsp.sendError(HttpServletResponse.SC_UNAUTHORIZED)
        )
                .and()
                .addFilterBefore(new JwtAuthenticationFilter(authenticationManager()), UsernamePasswordAuthenticationFilter.class)
                .authorizeRequests()
                .antMatchers(HttpMethod.GET, "/api/**").hasRole("USER")
                .anyRequest().permitAll();
    }
}

The JWT token is correctly validated in my custom JwtAuthenticationFilter and the endpoint is called only once. However I have noticed that all filters of the Spring Security chain are called twice:

2018-12-19 01:27:21.331 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 1 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 2 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : Trying to match using Ant [pattern='/logout', GET]
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Checking match of request : '/api/v1/customers'; against '/logout'
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : Trying to match using Ant [pattern='/logout', POST]
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Request 'GET /api/v1/customers' doesn't match 'POST /logout'
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : Trying to match using Ant [pattern='/logout', PUT]
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Request 'GET /api/v1/customers' doesn't match 'PUT /logout'
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : Trying to match using Ant [pattern='/logout', DELETE]
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Request 'GET /api/v1/customers' doesn't match 'DELETE /logout'
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : No matches found
2018-12-19 01:27:21.332 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 5 of 11 in additional filter chain; firing Filter: 'JwtAuthenticationFilter'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 6 of 11 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 7 of 11 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 8 of 11 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.a.AnonymousAuthenticationFilter  : SecurityContextHolder not populated with anonymous token, as it already contained: 'JwtAuthentication(credentials=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJlbnZpcm9ubWVudCI6eyJwcm9maWxlcyI6WyJkZXYiXX0sImF1dGgiOnsicm9sZXMiOlsiVVNFUiIsIkFETUlOIl19LCJ1c2VyX25hbWUiOiIwMDAwMDA5OSIsInNjb3BlIjpbIm9wZXJhdGUiXSwiZXhwIjoxNTQ1MTgzODc5LCJnZW5lcmF0ZWRCeSI6IlBBUyIsImp0aSI6IjllNWQxOWMwLTY0ZTYtNGIzYy1hNWQzLWEwYTQ4Mzk1MzhjOCIsImNsaWVudF9pZCI6ImZyb250LXBvbGl6YXMifQ.MoOXLj7dQ5ei4kJVA9wsar8VL1M4y6XxE4uw6-GHW0JwgSYTrUJkeU_H9iaT4X2JXo9vfSXJPAVQHGzCm7wHCeJdyUTJT_Du1nu6vSrezNQRqVBt1m1MxiE46omsTkBEqbtkxeVnx2CEBxGnGeyyaM1qLKrg2BilwwSy0xQ58O32zp3z_d_wUNy8q-9ki5Dxz3ja9YiKn-AgRDZHiBvKVciR3GtowVTMvfmBDMo4p6Ivj3GVHphyc0Czgqp5G1hgFg53C21K5axanBvO7yj0DqM8MdMhivUDICjnZ6OTUWv2JI99rG5ks_BxF7Vp7k_RXzGhklK55GKf-iuLwdyJ7w, authorities=[ROLE_USER, ROLE_ADMIN], username=00000099, authenticated=true)'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 9 of 11 in additional filter chain; firing Filter: 'SessionManagementFilter'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] s.CompositeSessionAuthenticationStrategy : Delegating to org.springframework.security.web.authentication.session.ChangeSessionIdAuthenticationStrategy@1958b360
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 10 of 11 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 11 of 11 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Checking match of request : '/api/v1/customers'; against '/api/**'
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.a.i.FilterSecurityInterceptor    : Secure object: FilterInvocation: URL: /api/v1/customers; Attributes: [hasRole('ROLE_USER')]
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.a.i.FilterSecurityInterceptor    : Previously Authenticated: JwtAuthentication(credentials=eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJlbnZpcm9ubWVudCI6eyJwcm9maWxlcyI6WyJkZXYiXX0sImF1dGgiOnsicm9sZXMiOlsiVVNFUiIsIkFETUlOIl19LCJ1c2VyX25hbWUiOiIwMDAwMDA5OSIsInNjb3BlIjpbIm9wZXJhdGUiXSwiZXhwIjoxNTQ1MTgzODc5LCJnZW5lcmF0ZWRCeSI6IlBBUyIsImp0aSI6IjllNWQxOWMwLTY0ZTYtNGIzYy1hNWQzLWEwYTQ4Mzk1MzhjOCIsImNsaWVudF9pZCI6ImZyb250LXBvbGl6YXMifQ.MoOXLj7dQ5ei4kJVA9wsar8VL1M4y6XxE4uw6-GHW0JwgSYTrUJkeU_H9iaT4X2JXo9vfSXJPAVQHGzCm7wHCeJdyUTJT_Du1nu6vSrezNQRqVBt1m1MxiE46omsTkBEqbtkxeVnx2CEBxGnGeyyaM1qLKrg2BilwwSy0xQ58O32zp3z_d_wUNy8q-9ki5Dxz3ja9YiKn-AgRDZHiBvKVciR3GtowVTMvfmBDMo4p6Ivj3GVHphyc0Czgqp5G1hgFg53C21K5axanBvO7yj0DqM8MdMhivUDICjnZ6OTUWv2JI99rG5ks_BxF7Vp7k_RXzGhklK55GKf-iuLwdyJ7w, authorities=[ROLE_USER, ROLE_ADMIN], username=00000099, authenticated=true)
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.access.vote.AffirmativeBased       : Voter: org.springframework.security.web.access.expression.WebExpressionVoter@177b76b1, returned: 1
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorization successful
2018-12-19 01:27:24.117 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.a.i.FilterSecurityInterceptor    : RunAsManager did not change Authentication object
2018-12-19 01:27:24.118 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers reached end of additional filter chain; proceeding with original chain

Up to here my JWT token has been validated, and the api endpoint is called, then the following log shows up:

2018-12-19 01:28:29.220 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.a.ExceptionTranslationFilter     : Chain processed normally
2018-12-19 01:28:29.220 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.header.writers.HstsHeaderWriter  : Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@2451b217
2018-12-19 01:28:29.220 DEBUG 1677 --- [nio-8080-exec-4] s.s.w.c.SecurityContextPersistenceFilter : SecurityContextHolder now cleared, as request processing completed
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 1 of 11 in additional filter chain; firing Filter: 'WebAsyncManagerIntegrationFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 2 of 11 in additional filter chain; firing Filter: 'SecurityContextPersistenceFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 3 of 11 in additional filter chain; firing Filter: 'HeaderWriterFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 4 of 11 in additional filter chain; firing Filter: 'LogoutFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : Trying to match using Ant [pattern='/logout', GET]
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Checking match of request : '/api/v1/customers'; against '/logout'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : Trying to match using Ant [pattern='/logout', POST]
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Request 'GET /api/v1/customers' doesn't match 'POST /logout'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : Trying to match using Ant [pattern='/logout', PUT]
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Request 'GET /api/v1/customers' doesn't match 'PUT /logout'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : Trying to match using Ant [pattern='/logout', DELETE]
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.u.matcher.AntPathRequestMatcher  : Request 'GET /api/v1/customers' doesn't match 'DELETE /logout'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.web.util.matcher.OrRequestMatcher  : No matches found
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 5 of 11 in additional filter chain; firing Filter: 'JwtAuthenticationFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 6 of 11 in additional filter chain; firing Filter: 'RequestCacheAwareFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 7 of 11 in additional filter chain; firing Filter: 'SecurityContextHolderAwareRequestFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 8 of 11 in additional filter chain; firing Filter: 'AnonymousAuthenticationFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.a.AnonymousAuthenticationFilter  : Populated SecurityContextHolder with anonymous token: 'org.springframework.security.authentication.AnonymousAuthenticationToken@cd4b591e: Principal: anonymousUser; Credentials: [PROTECTED]; Authenticated: true; Details: org.springframework.security.web.authentication.WebAuthenticationDetails@b364: RemoteIpAddress: 0:0:0:0:0:0:0:1; SessionId: null; Granted Authorities: ROLE_ANONYMOUS'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 9 of 11 in additional filter chain; firing Filter: 'SessionManagementFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 10 of 11 in additional filter chain; firing Filter: 'ExceptionTranslationFilter'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers at position 11 of 11 in additional filter chain; firing Filter: 'FilterSecurityInterceptor'
2018-12-19 01:28:29.221 DEBUG 1677 --- [nio-8080-exec-4] o.s.security.web.FilterChainProxy        : /api/v1/customers reached end of additional filter chain; proceeding with original chain
2018-12-19 01:28:29.223 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.header.writers.HstsHeaderWriter  : Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@2451b217
2018-12-19 01:28:29.224 DEBUG 1677 --- [nio-8080-exec-4] o.s.s.w.a.ExceptionTranslationFilter     : Chain processed normally
2018-12-19 01:28:29.224 DEBUG 1677 --- [nio-8080-exec-4] s.s.w.c.SecurityContextPersistenceFilter : SecurityContextHolder now cleared, as request processing completed

Why is the whole Spring Security filter chain being invoked again after the controller method has executed?

Answer 1

My controller endpoints respond asynchronously (Callable, DeferredResult). Apparently Spring passes the async processing thread for the whole Spring Security chain. Since in my case that's not necessary simply using the following configuration the chain is not invoked in the async thread anymore:

spring:
  security:
    filter:
      dispatcher-types:
        - request
        - error