Spring Security 过滤器链为什么会在每个请求中执行两次？

Question

我有一个基于Spring Boot 2.1的项目，使用了Spring Security。它包含API和Spring Security链，只需要验证JWT令牌并检查不同端点的权限。这是我的配置：

@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();
    }
}

我的自定义JwtAuthenticationFilter正确验证了JWT令牌，且端点只被调用了一次。但是我注意到Spring安全链的所有过滤器都会被调用两次：

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

到这里，我的JWT令牌已经得到验证，API端点已被调用，然后出现以下日志：

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

为什么在控制器方法执行后，整个Spring Security过滤器链会再次被调用？

- codependent

---

正如您在第二个日志中所看到的那样，您的JwtAuthenticationFilter没有再次被调用。第二个日志未经过身份验证，用户是匿名的。您确定两个日志都是针对同一请求的吗？间隔超过一秒钟。 - dur

这个间隔是由于调试断点引起的。JwtAuthFilter不会被调用两次，因为它继承了OncePerRequestFilter。我想知道的是为什么链被调用两次。 - codependent

你调用哪种HTTP方法？GET还是POST？ - dur

Answer 1

我的控制器端点使用异步方式响应（Callable，DeferredResult）。显然，Spring会将整个Spring Security链的异步处理线程传递。由于在我的情况下这不是必要的，只需使用以下配置即可使异步线程不再调用该链：

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

- codependent

---

这项工作也适用于Spring 3和使用Kotlin的暂停控制器。 - z0mb1ek

Answer 2

这是一个老问题，但我遇到了类似的问题。虽然这可能不是最终答案，但这部分内容如下：

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

可能是罪魁祸首。像这样替换它：

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

（注意使用setStatus而不是sendError）可能会解决问题。我有一个类似的AuthenticationEntrypoint实现，当我使用它时，我遇到了ProxyFilterChain两次工作的相同问题，并且一次没有使用它。将sendError更改为setStatus解决了我的问题。

这很可能是因为setStatus仅设置响应状态，而sendError还调用错误页面机制，导致服务器重新迭代整个过滤器链。这可以在两种方法的Javadoc中看到：

/**
 * 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);

并且

/**
 * 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;

- berserk81