Apparent Spring Boot race condition causing duplicate springSecurityFilterChain registration

Question

I have a REST-full web service implemented with Spring Boot 1.2.0-RELEASE that occasionally throws the following exception on startup.

03-Feb-2015 11:42:23.697 SEVERE [localhost-startStop-1] org.apache.catalina.core.ContainerBase.addChildInternal ContainerBase.addChild: start: 
 org.apache.catalina.LifecycleException: Failed to start component [StandardEngine[Catalina].StandardHost[localhost].StandardContext[]]
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:154)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:725)
...
Caused by: java.lang.IllegalStateException: Duplicate Filter registration for 'springSecurityFilterChain'. Check to ensure the Filter is only configured once.
        at org.springframework.security.web.context.AbstractSecurityWebApplicationInitializer.registerFilter(AbstractSecurityWebApplicationInitializer.java:215)
        at org.springframework.security.web.context.AbstractSecurityWebApplicationInitializer.insertSpringSecurityFilterChain(AbstractSecurityWebApplicationInitializer.java:147)
...

When I say "occasionally", I mean simply restarting the Tomcat server (version 8.0.17) will yield either this exception or will successfully load without issue.

This is a Servlet 3.0 application built on Spring Boot, so we don't have a traditional web.xml file. Instead, we initialize our servlet using Java.

package com.v.dw.webservice;

import org.springframework.boot.builder.SpringApplicationBuilder;
import org.springframework.boot.context.web.SpringBootServletInitializer;

public class WebXml extends SpringBootServletInitializer {

    @Override
    protected SpringApplicationBuilder configure(SpringApplicationBuilder application) {
        return application.sources(ApplicationConfig.class);
    }
}

We also leverage the mvn spring-boot:run command during development, and this race condition has yet to appear when run in this way. The "root" of our configuration and the main method used by maven are in the same class:

package com.v.dw.webservice;

import javax.sql.DataSource;

import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.actuate.autoconfigure.ManagementSecurityAutoConfiguration;
import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.autoconfigure.jdbc.DataSourceBuilder;
import org.springframework.boot.autoconfigure.security.SecurityAutoConfiguration;
import org.springframework.boot.context.properties.ConfigurationProperties;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Primary;

@SpringBootApplication
@EnableAutoConfiguration(exclude = {ManagementSecurityAutoConfiguration.class, SecurityAutoConfiguration.class})
public class ApplicationConfig {

    public static void main(String[] args) {
        SpringApplication.run(ApplicationConfig.class, args);
    }

    @Value("${info.build.version}")
    private String apiVersion;

    @Bean
    @Primary
    @ConfigurationProperties(prefix="datasource.primary")
    public DataSource primaryDataSource() {
        return DataSourceBuilder.create().build();
    }

}

I've tried simplifying our authentication logic to use a custom in-memory authentication provider for testing. As far as I can tell, this is the only custom authentication provider on the classpath, and we do not import any configuration classes outside of the application root package.

Unfortunately the logging output provided by Spring and Tomcat does not help provide any context around the error, so I tried grabbing the AbstractSecurityWebApplictionInitializer source from here:

https://raw.githubusercontent.com/spring-projects/spring-security/rb3.2.5.RELEASE/web/src/main/java/org/springframework/security/web/context/AbstractSecurityWebApplicationInitializer.java

And I modified the registerFilter(...) method in an attempt to generate some useful debug output by adding System.out calls.

private final void registerFilter(ServletContext servletContext, boolean insertBeforeOtherFilters, String filterName, Filter filter) {
    System.out.println(">>>>>> Registering filter '" + filterName + "' with: " + filter.getClass().toString());
    Dynamic registration = servletContext.addFilter(filterName, filter);
    if(registration == null) {
        System.out.println(">>>>>> Existing filter '" + filterName + "' as: " + servletContext.getFilterRegistration(filterName).getClassName());
        throw new IllegalStateException("Duplicate Filter registration for '" + filterName +"'. Check to ensure the Filter is only configured once.");
    }
    registration.setAsyncSupported(isAsyncSecuritySupported());
    EnumSet<DispatcherType> dispatcherTypes = getSecurityDispatcherTypes();
    registration.addMappingForUrlPatterns(dispatcherTypes, !insertBeforeOtherFilters, "/*");
}

When it fails, the debug output is generated only once right before the exception. This indicates the registerFilter(...) method is called only once and relatively late in the Spring loading process:

>>>>>> Registering filter 'springSecurityFilterChain' with: class org.springframework.web.filter.DelegatingFilterProxy
>>>>>> Existing filter 'springSecurityFilterChain' as: org.springframework.security.web.FilterChainProxy

When it works, the debug output looks like this:

>>>>>> Registering filter 'springSecurityFilterChain' with: class org.springframework.web.filter.DelegatingFilterProxy

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v1.2.0.RELEASE)

This suggests the security configuration is happening much earlier in the loading process when it works vs. when it fails.

Answer 1

I think you must have a concrete subclass of AbstractSecurityWebApplicationInitializer in your application. Spring's Servlet 3.0 support will find this WebApplicationInitializer implementation and call it when Tomcat starts your app. This triggers an attempt to register Spring Security's filter. You also have your WebXml class that extends SpringBootServletInitializer. This too is a WebApplicationInitializer that will be getting called when Tomcat starts your app. Due to Spring Boot's auto-configuration support this also triggers an attempt to register Spring Security's filter.

Your WebXml class does not declare an order (it doesn't implement Spring's Ordered interface and it isn't annotated with @Order). I would guess that the same is true of your AbstractSecurityWebApplicationInitializer subclass. This means that they both have the same order (the default) so Spring is free to call them in any order. Your application works when your AbstractSecurityWebApplicationInitializer subclass goes first as Spring Boot is tolerant of the filter already being there. If fails when Spring Boot goes first as AbstractSecurityWebApplicationInitializer is not so tolerant.

Having said all of this, as you're using Spring Boot you may not even need your AbstractSecurityWebApplicationInitializer so the simplest solution is probably to delete it. If you do need it, then you should assign both it and WebXml an order (annotate with @Order or implement Ordered) so that WebXml is guaranteed to always be called after your AbstractSecurityWebApplicationInitializer subclass.