Spring Boot runs filter twice for requests returning a CompletionStage

Question

I was having an issue where my filter was running twice when methods were returning a CompletionStage. From the documentation on RequestMapping (here), it is a supported return value.

A CompletionStage (implemented by CompletableFuture for example) which the application uses to produce a return value in a separate thread of its own choosing, as an alternative to returning a Callable.

Since the project was pretty complex with a lot of concurrent code, I created a new simple spring-boot project. This is the (only) controller in it:

@Controller
public class BaseController {
    @RequestMapping("/hello")
    @ResponseBody
    public CompletionStage<String> world() {
        return CompletableFuture.supplyAsync(() -> "Hello World");
    }
}

And a filter:

@WebFilter
@Component
public class GenericLoggingFilter extends GenericFilterBean {
    @Override
    public void doFilter(ServletRequest request, ServletResponse response,
                         FilterChain chain) throws IOException, ServletException {
        HttpServletRequest httpServletRequest = (HttpServletRequest) request;

        System.out.println(httpServletRequest.getMethod() + " " +
                           httpServletRequest.getRequestURI());

        chain.doFilter(request, response);
    }
}

When I make a call curl http://localhost:8080/hello, it prints GET /hello twice on the console. When I change the controller method to return a String:

@RequestMapping("/hello")
@ResponseBody
public String world() {
    return "Hello World";
}

It prints it only once. This behavior is exhibited even if I change it to a Callable, which has no real concurrency significance (of course, spring itself might be treating this now as an Async request).

So, if spring is running the entire web-stack again to have a request context available, even that doesn't really make sense because the following:

@RequestMapping("/hello")
@ResponseBody
public CompletionStage<String> world() {
    return CompletableFuture.supplyAsync(() -> {
        System.out.println(RequestContextHolder.currentRequestAttributes());
        return "Hello World";
    });
}

throws an exception: IllegalStateException: No thread-bound request found...

What is surprising is, that the following works:

@RequestMapping("/hello")
@ResponseBody
public Callable<String> world() {
    return () -> {
        System.out.println(RequestContextHolder.currentRequestAttributes());
        return "Hello World";
    };
}

So, I am unsure about quite a few things.

1. It appears that Callable and CompletionStage is being treated differently in context of which thread it is executed in.
2. If that is the case, then why is my filter running twice in each case? If the job of a filter is to setup a certain request-specific context, it doesn't make sense to run it again for a CompletionStage if it anyways is not accessible.
3. Why exactly is the filter running twice either which ways?

Answer 1

Please replace GenericFilterBean with OncePerRequestFilter.