Spring Security Filter chain executed twice per request. Why?

6
votes

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?

2
springspring-bootspring-security
As you could see in the second log, your JwtAuthenticationFilter isn't called again. The second log didn't authenticate, the user is anonymous. Are you sure, both logs are for the same request? There is a gap of more than on second. – dur
The gap is because of the debug breakpoint. The JwtAuthFilter isn't called twice because it extends OncePerRequestFilter. What I want to know is why the chain is invoked twice. – codependent
What HTTP method do you call? GET or POST? – dur

2 Answers

3
votes

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
0
votes

This is an old question, but I had a similar problem. It may not be the definitive answer however this part:

(req, rsp, e) -> rsp.sendError(HttpServletResponse.SC_UNAUTHORIZED)

may be the culprit. Replacing it like this:

(req, rsp, e) -> rsp.setStatus(HttpServletResponse.SC_UNAUTHORIZED)

(notice setStatus instead of sendError) may solve the problem. I had a similar AuthenticationEntrypoint implementation and when using it I had the same problem of ProxyFilterChain working twice, and once without it. Changing sendError to setStatus solved my problem.

This is most probably due to the fact that setStatus merely sets the response status whereas sendError also invokes the error-page mechanism, causing the server to re-iterate the whole filter chain. This can be seen on the Javadoc of the two methods:

/**
 * Sets the status code for this response. This method is used to set the
 * return status code when there is no error (for example, for the status
 * codes SC_OK or SC_MOVED_TEMPORARILY). If there is an error, and the
 * caller wishes to invoke an error-page defined in the web application, the
 * <code>sendError</code> method should be used instead.
 * <p>
 * The container clears the buffer and sets the Location header, preserving
 * cookies and other headers.
 *
 * @param sc
 *            the status code
 * @see #sendError
 */
public void setStatus(int sc);

and

/**
 * Sends an error response to the client using the specified status code and
 * clears the output buffer. The server defaults to creating the response to
 * look like an HTML-formatted server error page containing the specified
 * message, setting the content type to "text/html", leaving cookies and
 * other headers unmodified. If an error-page declaration has been made for
 * the web application corresponding to the status code passed in, it will
 * be served back in preference to the suggested msg parameter.
 * <p>
 * If the response has already been committed, this method throws an
 * IllegalStateException. After using this method, the response should be
 * considered to be committed and should not be written to.
 *
 * @param sc
 *            the error status code
 * @param msg
 *            the descriptive message
 * @exception IOException
 *                If an input or output exception occurs
 * @exception IllegalStateException
 *                If the response was committed
 */
public void sendError(int sc, String msg) throws IOException;