Spring Security 5.6.0 breaks multiple configurations in tests

[fast-reflexes]

Describe the bug
I use multiple security configurations with orders and requestMatchers to determine which requests end up where. After upgrading to Spring Boot 2.6.0 and Spring Security 5.6.0, tests that previously passed fail. Functionality when actually running the app is unaffected (which suggests an odd discrepancy between how security is handled when running tests and when running the application normally).

To Reproduce

Check repo: https://github.com/fast-reflexes/spring-boot-bug

Present there is a simple setup initialized via https://start.spring.io/ with minimal functionality added:

• Endpoint /api/bogus which returns text bogus
• Security config with 2 configurations ordered 1 and 2 where 2 is a catch-all that denies all access and 1 takes care of all the requests matching /api/** via requestMatchers call. Endpoint is protected with basic auth and requires role API_USER.
• 2 tests that test access to this api endpoint, first test logs in with correct user name and password and second test has the correct role set. Both should succeed.

Repo has Spring Boot 2.6.0 set initially (with Spring Security 5.6.0).

• Try to run the tests and verify that they fail: ./gradlew test
• Try to run the app and log in with user and password on localhost:8080/api/bogus and verify that you see the text bogus (e.g. access is granted, which was not the case when testing): ./gradlew bootRun

Now downgrade Spring Boot to 2.5.6 and do the same thing as above and verify that tests now pass (and like before, actually running the app works as expected too).

Back to version 2.6.0, if we remove the second configuration, tests work again, even if we add negative tests where we expect UNAUTHORIZED or FORBIDDEN (just to show that it is not the case that removal of the second config allows access to all).

Expected behavior

I expect the behaviour in Spring Boot 2.6.0 (and Spring Security 5.6.0) to be the same as in Spring Boot 2.5.6.

The above is a toy scenario and in the real use case, I have several configs to handle API access and UI login. There is no apparent reason to the behaviour observed with tests and two configs, which makes me believe that there is some bug introduced with the latest release of Spring Security.

I have done a lot of investigations myself and the only lead I could find was that before rejecting the valid login (when two configs are used), the following is logged (testing, version 2.6.0, two configs):

2021-11-23 10:24:42.450 TRACE 82423 --- [    Test worker] o.s.security.web.FilterChainProxy        : Invoking FilterSecurityInterceptor (12/12)
2021-11-23 10:24:42.450 TRACE 82423 --- [    Test worker] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not re-authenticate UsernamePasswordAuthenticationToken [Principal=org.springframework.security.core.userdetails.User [Username=user, Password=[PROTECTED], Enabled=true, AccountNonExpired=true, credentialsNonExpired=true, AccountNonLocked=true, Granted Authorities=[ROLE_API_USER]], Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=127.0.0.1, SessionId=null], Granted Authorities=[ROLE_API_USER]] before authorizing
2021-11-23 10:24:42.450 TRACE 82423 --- [    Test worker] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorizing filter invocation [GET /api/bogus] with attributes [hasAnyRole('ROLE_API_USER')]
2021-11-23 10:24:42.450 DEBUG 82423 --- [    Test worker] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorized filter invocation [GET /api/bogus] with attributes [hasAnyRole('ROLE_API_USER')]
2021-11-23 10:24:42.450 TRACE 82423 --- [    Test worker] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not switch RunAs authentication since RunAsManager returned null
2021-11-23 10:24:42.450 DEBUG 82423 --- [    Test worker] o.s.security.web.FilterChainProxy        : Secured GET /api/bogus
2021-11-23 10:24:42.450 TRACE 82423 --- [    Test worker] o.s.s.w.a.expression.WebExpressionVoter  : Voted to deny authorization
2021-11-23 10:24:42.455 DEBUG 82423 --- [    Test worker] a.DefaultWebInvocationPrivilegeEvaluator : filter invocation [/api/bogus] denied for UsernamePasswordAuthenticationToken [Principal=org.springframework.security.core.userdetails.User [Username=user, Password=[PROTECTED], Enabled=true, AccountNonExpired=true, credentialsNonExpired=true, AccountNonLocked=true, Granted Authorities=[ROLE_API_USER]], Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=127.0.0.1, SessionId=null], Granted Authorities=[ROLE_API_USER]]

    org.springframework.security.access.AccessDeniedException: Access is denied
        at org.springframework.security.access.vote.AffirmativeBased.decide(AffirmativeBased.java:73) ~[spring-security-core-5.6.0.jar:5.6.0]
        ...

2021-11-23 10:24:42.456 TRACE 82423 --- [    Test worker] o.s.s.w.header.writers.HstsHeaderWriter  : Not injecting HSTS header since it did not match request to [Is Secure]

The corresponding portion when the second config is disabled is (testing, version 2.6.0, one config):

2021-11-23 10:28:24.524 TRACE 82954 --- [    Test worker] o.s.security.web.FilterChainProxy        : Invoking FilterSecurityInterceptor (12/12)
2021-11-23 10:28:24.524 TRACE 82954 --- [    Test worker] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not re-authenticate UsernamePasswordAuthenticationToken [Principal=org.springframework.security.core.userdetails.User [Username=user, Password=[PROTECTED], Enabled=true, AccountNonExpired=true, credentialsNonExpired=true, AccountNonLocked=true, Granted Authorities=[ROLE_API_USER]], Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=127.0.0.1, SessionId=null], Granted Authorities=[ROLE_API_USER]] before authorizing
2021-11-23 10:28:24.524 TRACE 82954 --- [    Test worker] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorizing filter invocation [GET /api/bogus] with attributes [hasAnyRole('ROLE_API_USER')]
2021-11-23 10:28:24.524 DEBUG 82954 --- [    Test worker] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorized filter invocation [GET /api/bogus] with attributes [hasAnyRole('ROLE_API_USER')]
2021-11-23 10:28:24.525 TRACE 82954 --- [    Test worker] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not switch RunAs authentication since RunAsManager returned null
2021-11-23 10:28:24.525 DEBUG 82954 --- [    Test worker] o.s.security.web.FilterChainProxy        : Secured GET /api/bogus
2021-11-23 10:28:24.525 TRACE 82954 --- [    Test worker] o.s.t.web.servlet.TestDispatcherServlet  : GET "/api/bogus", parameters={}, headers={masked} in DispatcherServlet ''
2021-11-23 10:28:24.526 TRACE 82954 --- [    Test worker] o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'exampleEndpoint'
2021-11-23 10:28:24.526 TRACE 82954 --- [    Test worker] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.examplespringboot.ExampleEndpoint#bogus()
2021-11-23 10:28:24.526 TRACE 82954 --- [    Test worker] o.s.web.method.HandlerMethod             : Arguments: []
2021-11-23 10:28:24.527 DEBUG 82954 --- [    Test worker] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain', given [*/*] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
2021-11-23 10:28:24.527 TRACE 82954 --- [    Test worker] m.m.a.RequestResponseBodyMethodProcessor : Writing ["bogus"]
2021-11-23 10:28:24.528 TRACE 82954 --- [    Test worker] o.s.s.w.header.writers.HstsHeaderWriter  : Not injecting HSTS header since it did not match request to [Is Secure]

The corresponding portion when the second config is active but when the app is running like normal and we log in via the browser is (running app, version 2.6.0, two configs):

2021-11-23 10:38:37.466 TRACE 84274 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking FilterSecurityInterceptor (12/12)
2021-11-23 10:38:37.467 TRACE 84274 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not re-authenticate UsernamePasswordAuthenticationToken [Principal=org.springframework.security.core.userdetails.User [Username=user, Password=[PROTECTED], Enabled=true, AccountNonExpired=true, credentialsNonExpired=true, AccountNonLocked=true, Granted Authorities=[ROLE_API_USER]], Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=0:0:0:0:0:0:0:1, SessionId=null], Granted Authorities=[ROLE_API_USER]] before authorizing
2021-11-23 10:38:37.471 TRACE 84274 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorizing filter invocation [GET /api/bogus] with attributes [hasAnyRole('ROLE_API_USER')]
2021-11-23 10:38:37.513 DEBUG 84274 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorized filter invocation [GET /api/bogus] with attributes [hasAnyRole('ROLE_API_USER')]
2021-11-23 10:38:37.513 TRACE 84274 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not switch RunAs authentication since RunAsManager returned null
2021-11-23 10:38:37.514 DEBUG 84274 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Secured GET /api/bogus
2021-11-23 10:38:37.518 DEBUG 84274 --- [nio-8080-exec-1] org.apache.tomcat.util.http.Parameters   : Set encoding to UTF-8
2021-11-23 10:38:37.519 TRACE 84274 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/api/bogus", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
2021-11-23 10:38:37.550 TRACE 84274 --- [nio-8080-exec-1] o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'exampleEndpoint'
2021-11-23 10:38:37.552 TRACE 84274 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.examplespringboot.ExampleEndpoint#bogus()
2021-11-23 10:38:37.623 TRACE 84274 --- [nio-8080-exec-1] o.s.web.method.HandlerMethod             : Arguments: []
2021-11-23 10:38:37.825 DEBUG 84274 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/html', given [text/html, application/xhtml+xml, image/avif, image/webp, image/apng, application/xml;q=0.9, application/signed-exchange;v=b3;q=0.9, */*;q=0.8] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
2021-11-23 10:38:37.830 TRACE 84274 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Writing ["bogus"]
2021-11-23 10:38:37.887 TRACE 84274 --- [nio-8080-exec-1] o.s.s.w.header.writers.HstsHeaderWriter  : Not injecting HSTS header since it did not match request to [Is Secure]

... which is more or less identical to the previous (except for the UTF-8 part)

Sample

See above

Reports that include a sample will take priority over reports that do not.
At times, we may require a sample, so it is good to try and include a sample up front.

[marcusdacoregio]

Hi @fast-reflexes, thanks for reaching out.

This is related to spring-projects/spring-boot#28759. A newly added filter, ErrorPageSecurityFilter, is being invoked for every dispatch due to a limitation in MockMvc. You can have more details on the thread.

As a workaround, you can remove this filter from your application for the time being, like so:

@Bean
fun removeErrorSecurityFilter(): BeanFactoryPostProcessor? {
    return BeanFactoryPostProcessor {beanFactory: ConfigurableListableBeanFactory -> (beanFactory as DefaultListableBeanFactory)
                .removeBeanDefinition("errorPageSecurityInterceptor") }
}

The fix is scheduled for Spring Boot 2.6.1. Keep an eye on the release and make sure you remove the workaround.
Please, feel free to discuss further if you want.

[steklopod]

@Bean
fun removeErrorSecurityFilter(): BeanFactoryPostProcessor? {
    return BeanFactoryPostProcessor {beanFactory: ConfigurableListableBeanFactory -> (beanFactory as DefaultListableBeanFactory)
                .removeBeanDefinition("errorPageSecurityInterceptor") }
}

It solved my problem too

[fast-reflexes]

Thanks for fast feedback! Delighted to solve this so fast! <3