Why is my spring boot stateless filter being called twice?

Question

I'm trying to implement stateless token-based authentication on a rest api I've developed using Spring Boot. The idea is that the client includes a JWT token with any request, and a filter extracts this from the request, and sets up the SecurityContext with a relevant Authentication object based on the contents of the token. The request is then routed as normal, and secured using @PreAuthorize on the mapped method.

My security config is as follows :

@Configuration
@EnableWebSecurity
@EnableGlobalMethodSecurity(prePostEnabled = true)
public class SecurityConfig extends WebSecurityConfigurerAdapter {

@Autowired
private JWTTokenAuthenticationService authenticationService;

@Override
protected void configure(HttpSecurity http) throws Exception
{
    http
        .csrf().disable()
        .headers().addHeaderWriter(new XFrameOptionsHeaderWriter(XFrameOptionsMode.SAMEORIGIN))
        .and()
        .authorizeRequests()
            .antMatchers("/auth/**").permitAll()
            .antMatchers("/api/**").authenticated()
            .and()
        .addFilterBefore(new StatelessAuthenticationFilter(authenticationService), UsernamePasswordAuthenticationFilter.class);
}

With the stateless filter that extends GenericFilterBean defined as follows :

public class StatelessAuthenticationFilter extends GenericFilterBean {

    private static Logger logger = Logger.getLogger(StatelessAuthenticationFilter.class);

    private JWTTokenAuthenticationService authenticationservice;

    public StatelessAuthenticationFilter(JWTTokenAuthenticationService authenticationService)
    {
        this.authenticationservice = authenticationService;
    }

    @Override
    public void doFilter(   ServletRequest request,
                            ServletResponse response,
                            FilterChain chain) throws IOException, ServletException {

        HttpServletRequest httpRequest = (HttpServletRequest) request;
        Authentication authentication = authenticationservice.getAuthentication(httpRequest);
        SecurityContextHolder.getContext().setAuthentication(authentication);

        logger.info("===== Security Context before request =====");
        logger.info("Request for: " + httpRequest.getRequestURI());
        logger.info(SecurityContextHolder.getContext().getAuthentication());
        logger.info("===========================================");

        chain.doFilter(request, response);

        SecurityContextHolder.getContext().setAuthentication(null);
        logger.info("===== Security Context after request =====");
        logger.info("Request for: " + httpRequest.getRequestURI());
         logger.info(SecurityContextHolder.getContext().getAuthentication());
        logger.info("===========================================");
    }

}

And the endpoint defined like this :

@PreAuthorize("hasAuthority('user')")
@RequestMapping (   value="/api/attachments/{attachmentId}/{fileName:.+}",
                    method = RequestMethod.GET)
public ResponseEntity<byte[]> getAttachedDocumentEndpoint(@PathVariable String attachmentId, @PathVariable String fileName)
{
    logger.info("GET called for /attachments/" + attachmentId + "/" + fileName);

    // do something to get the file, and return ResponseEntity<byte[]> object
}

When doing a GET on /api/attachments/someattachment/somefilename, including the token, I can see that the filter is being invoked twice, once apparently with the token, and once without. But the restcontroller mapped to the request is only called once.

[INFO] [06-04-2015 12:26:44,465] [JWTTokenAuthenticationService] getAuthentication - Getting authentication based on token supplied in HTTP Header
[INFO] [06-04-2015 12:26:44,473] [StatelessAuthenticationFilter] doFilter - ===== Security Context before request =====
[INFO] [06-04-2015 12:26:44,473] [StatelessAuthenticationFilter] doFilter - Request for: /api/attachments/1674b08b6bbd54a6efaff4a780001a9e/jpg.png
[INFO] [06-04-2015 12:26:44,474] [StatelessAuthenticationFilter] doFilter - Name:iser, Principal:user, isAuthenticated:true, grantedAuthorites:[user]
[INFO] [06-04-2015 12:26:44,474] [StatelessAuthenticationFilter] doFilter - ===========================================
[INFO] [06-04-2015 12:26:44,476] [AttachmentRESTController] getAttachedDocumentEndpoint - GET called for /api/attachments/1674b08b6bbd54a6efaff4a780001a9e/jpg.png
[INFO] [06-04-2015 12:26:44,477] [AttachmentDBController] getAttachment - getAttachment method called with attachmentId:1674b08b6bbd54a6efaff4a780001a9e , and fileName:jpg.png
[INFO] [06-04-2015 12:26:44,483] [StatelessAuthenticationFilter] doFilter - ===== Security Context after request =====
[INFO] [06-04-2015 12:26:44,484] [StatelessAuthenticationFilter] doFilter - Request for: /api/attachments/1674b08b6bbd54a6efaff4a780001a9e/jpg.png
[INFO] [06-04-2015 12:26:44,484] [StatelessAuthenticationFilter] doFilter - 
[INFO] [06-04-2015 12:26:44,484] [StatelessAuthenticationFilter] doFilter - ===========================================
[INFO] [06-04-2015 12:26:44,507] [JWTTokenAuthenticationService] getAuthentication - No token supplied in HTTP Header
[INFO] [06-04-2015 12:26:44,507] [StatelessAuthenticationFilter] doFilter - ===== Security Context before request =====
[INFO] [06-04-2015 12:26:44,507] [StatelessAuthenticationFilter] doFilter - Request for: /api/attachments/1674b08b6bbd54a6efaff4a780001a9e/jpg.png
[INFO] [06-04-2015 12:26:44,507] [StatelessAuthenticationFilter] doFilter - 
[INFO] [06-04-2015 12:26:44,508] [StatelessAuthenticationFilter] doFilter - ===========================================
[INFO] [06-04-2015 12:26:44,508] [StatelessAuthenticationFilter] doFilter - ===== Security Context after request =====
[INFO] [06-04-2015 12:26:44,508] [StatelessAuthenticationFilter] doFilter - Request for: /api/attachments/1674b08b6bbd54a6efaff4a780001a9e/jpg.png
[INFO] [06-04-2015 12:26:44,508] [StatelessAuthenticationFilter] doFilter - 
[INFO] [06-04-2015 12:26:44,508] [StatelessAuthenticationFilter] doFilter - ===========================================

What's going on here ?

Edit :

It's even stranger than I first thought - implementing a simple endpoint that just returns a simple message displays the expected behaviour - it's seems like only when I try to return data as a ResponseEntity as above does this problem occur.

Endpoint :

@PreAuthorize("hasAuthority('user')")
@RequestMapping("/api/userHelloWorld")
public String userHelloWorld()
{
    return "Hello Secure User World";
}

Output, showing single call to filter (with extra debug on):

[INFO] [06-04-2015 19:43:25,831] [JWTTokenAuthenticationService] getAuthentication - Getting authentication based on token supplied in HTTP Header
[INFO] [06-04-2015 19:43:25,844] [StatelessAuthenticationFilter] doFilterInternal - ===== Security Context before request =====
[INFO] [06-04-2015 19:43:25,844] [StatelessAuthenticationFilter] doFilterInternal - Request for: /api/userHelloWorld
[INFO] [06-04-2015 19:43:25,844] [StatelessAuthenticationFilter] doFilterInternal - Response = null 200
[INFO] [06-04-2015 19:43:25,844] [StatelessAuthenticationFilter] doFilterInternal - Name:user, Principal:user, isAuthenticated:true, grantedAuthorites:[user]
[INFO] [06-04-2015 19:43:25,845] [StatelessAuthenticationFilter] doFilterInternal - ===========================================
[DEBUG] [06-04-2015 19:43:25,845] [DispatcherServlet] doService - DispatcherServlet with name 'dispatcherServlet' processing GET request for [/api/userHelloWorld]
[DEBUG] [06-04-2015 19:43:25,847] [AbstractHandlerMethodMapping] getHandlerInternal - Looking up handler method for path /api/userHelloWorld
[DEBUG] [06-04-2015 19:43:25,848] [AbstractHandlerMethodMapping] getHandlerInternal - Returning handler method [public java.lang.String RESTController.userHelloWorld()]
[DEBUG] [06-04-2015 19:43:25,849] [DispatcherServlet] doDispatch - Last-Modified value for [/api/userHelloWorld] is: -1
[DEBUG] [06-04-2015 19:43:25,851] [AbstractMessageConverterMethodProcessor] writeWithMessageConverters - Written [Hello Secure User World] as "text/plain;charset=UTF-8" using [org.springframework.http.converter.StringHttpMessageConverter@3eaf6fe7]
[DEBUG] [06-04-2015 19:43:25,852] [DispatcherServlet] processDispatchResult - Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling
[DEBUG] [06-04-2015 19:43:25,852] [FrameworkServlet] processRequest - Successfully completed request
[INFO] [06-04-2015 19:43:25,852] [StatelessAuthenticationFilter] doFilterInternal - ===== Security Context after request =====
[INFO] [06-04-2015 19:43:25,853] [StatelessAuthenticationFilter] doFilterInternal - Request for: /api/userHelloWorld
[INFO] [06-04-2015 19:43:25,853] [StatelessAuthenticationFilter] doFilterInternal - Response = text/plain;charset=UTF-8 200
[INFO] [06-04-2015 19:43:25,853] [StatelessAuthenticationFilter] doFilterInternal - 
[INFO] [06-04-2015 19:43:25,853] [StatelessAuthenticationFilter] doFilterInternal - ===========================================

Answer 1

It is a part of filters that has still some black magic for me (*), but I know that this is a common problem, and Spring has a subclass of GenericFilterBean specially for dealing with it : just use OncePerRequestFilter as base class and your filter should be called only once.

(*) I've read it could be caused by the request being dispatched multiple times via the request dispatcher

Answer 2

Okay - so this is pretty ridiculous, but it seems like it's an issue with the way I was invoking the request (via the POSTMAN Chrome Extension)

Postman seems to fire in 2 requests, one with headers, one without. There's an open bug report describing this here : https://github.com/a85/POSTMan-Chrome-Extension/issues/615

The behaviour is not seen if the request is invoked using curl, or just straight from the browser.