Spring Security permitAll() matcher being ignored

Question

This is based on Spring Security 5.x (latest), being used in a Spring Webflux environment.

I've got a very basic config, attempting to get JWT bearer tokens working.

Config in its entirety:

package domain.test.platformapi.config;

import lombok.val;
import domain.test.platformapi.lib.auth.JWTAuthenticationManager;
import domain.test.platformapi.lib.auth.JWTAuthenticationConverter;
import domain.test.platformapi.lib.auth.JWTAuthenticationEntryPoint;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.security.config.annotation.web.reactive.EnableWebFluxSecurity;
import org.springframework.security.config.web.server.SecurityWebFiltersOrder;
import org.springframework.security.config.web.server.ServerHttpSecurity;
import org.springframework.security.web.server.SecurityWebFilterChain;
import org.springframework.security.web.server.authentication.AuthenticationWebFilter;
import org.springframework.security.web.server.authentication.ServerAuthenticationEntryPointFailureHandler;
import org.springframework.security.web.server.context.ServerSecurityContextRepository;
import org.springframework.security.web.server.context.WebSessionServerSecurityContextRepository;
import org.springframework.security.web.server.util.matcher.PathPatternParserServerWebExchangeMatcher;

@EnableWebFluxSecurity
@Configuration
public class SecurityConfig
{
    @Autowired
    private JWTAuthenticationManager authenticationManager;

    @Autowired
    private JWTAuthenticationConverter authenticationConverter;

    private final ServerSecurityContextRepository securityContextRepository = new WebSessionServerSecurityContextRepository();

    @Bean
    SecurityWebFilterChain configure (ServerHttpSecurity httpSecurity)
    {
        return
                httpSecurity
                        .httpBasic().disable()
                        .formLogin().disable()
                        .csrf().disable()
                        .logout().disable()
                        .authenticationManager(authenticationManager)
                        .securityContextRepository(securityContextRepository)
                        .authorizeExchange()
                            .pathMatchers("v1/auth")
                                .permitAll()
                        .anyExchange()
                            .authenticated()
                        .and().addFilterAt(configureWebFilter(), SecurityWebFiltersOrder.AUTHENTICATION)
                .build();
    }

    private AuthenticationWebFilter configureWebFilter ()
    {
        val f = new AuthenticationWebFilter(authenticationManager);

        f.setAuthenticationFailureHandler(new ServerAuthenticationEntryPointFailureHandler(new JWTAuthenticationEntryPoint()));
        f.setAuthenticationConverter(authenticationConverter);

        // Issue is here
        // f.setRequiresAuthenticationMatcher(new PathPatternParserServerWebExchangeMatcher("v1/user"));

        f.setSecurityContextRepository(securityContextRepository);

        return f;
    }

}

Idea is very simple, aside from v1/auth and v1/info, everything else should require authentication and pass through the AuthenticationWebFilter. Authentication itself works fine.

Problem is, if f.setRequiresAuthenticationMatcher(new PathPatternParserServerWebExchangeMatcher("v1/user")); (just a test value for now) is omitted, my 'permitAll()` calls above are completely ignored.

EVERYTHING seems to require authentication. I'm likely missing something obvious, anyone have pointers?

I tried to turn on Spring Security debug logging with logging.level.org.springframework.security=DEBUG in my application.properties file, but it doesn't seem to generate any real debug logs either.

Runtime std{out | err}:

2018-03-06 19:51:11.458  INFO 41896 --- [           main] n.s.p.PlatformApiApplication             : Starting PlatformApiApplication on Bleu with PID 41896 (G:\StudyExpress\platform-api\out\production\classes started by reise in G:\StudyExpress\platform-api)
2018-03-06 19:51:11.460  INFO 41896 --- [           main] n.s.p.PlatformApiApplication             : No active profile set, falling back to default profiles: default
2018-03-06 19:51:11.527  INFO 41896 --- [           main] onfigReactiveWebServerApplicationContext : Refreshing org.springframework.boot.web.reactive.context.AnnotationConfigReactiveWebServerApplicationContext@e24ddd0: startup date [Tue Mar 06 19:51:11 JST 2018]; root of context hierarchy
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.springframework.cglib.core.ReflectUtils$1 (file:/C:/Users/reise/.gradle/caches/modules-2/files-2.1/org.springframework/spring-core/5.0.2.RELEASE/45b2958ab3fb022dd29f8b1c553ebf1c75a144aa/spring-core-5.0.2.RELEASE.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
WARNING: Please consider reporting this to the maintainers of org.springframework.cglib.core.ReflectUtils$1
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
2018-03-06 19:51:12.659  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'arangoDBConfig' of type [domain.test.platformapi.config.ArangoDBConfig$$EnhancerBySpringCGLIB$$6e4eb669] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.711  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'arango' of type [com.arangodb.ArangoDB$Builder] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.719  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'database' of type [java.lang.String] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.755  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'customConversions' of type [com.arangodb.springframework.core.convert.ArangoCustomConversions] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.773  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'arangoMappingContext' of type [com.arangodb.springframework.core.mapping.ArangoMappingContext] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.786  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'arangoConverter' of type [com.arangodb.springframework.core.convert.DefaultArangoConverter] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.816  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'arangoTemplate' of type [com.arangodb.springframework.core.template.ArangoTemplate] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.869  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.cache.annotation.ProxyCachingConfiguration' of type [org.springframework.cache.annotation.ProxyCachingConfiguration$$EnhancerBySpringCGLIB$$141d066d] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.893  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.autoconfigure.cache.CacheAutoConfiguration' of type [org.springframework.boot.autoconfigure.cache.CacheAutoConfiguration$$EnhancerBySpringCGLIB$$890cb11] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:12.911  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.context.properties.ConfigurationPropertiesBinderBuilder$ConversionServiceFactory' of type [org.springframework.boot.context.properties.ConfigurationPropertiesBinderBuilder$ConversionServiceFactory] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:13.057  INFO 41896 --- [           main] o.h.v.i.e.ValidatorFactoryImpl           : HV000238: Temporal validation tolerance set to 0.
2018-03-06 19:51:13.079  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'spring.cache-org.springframework.boot.autoconfigure.cache.CacheProperties' of type [org.springframework.boot.autoconfigure.cache.CacheProperties] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:13.087  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'cacheManagerCustomizers' of type [org.springframework.boot.autoconfigure.cache.CacheManagerCustomizers] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:13.090  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.autoconfigure.cache.HazelcastCacheConfiguration' of type [org.springframework.boot.autoconfigure.cache.HazelcastCacheConfiguration$$EnhancerBySpringCGLIB$$cb0fc2b7] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:13.094  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.boot.autoconfigure.hazelcast.HazelcastServerConfiguration$HazelcastServerConfigConfiguration' of type [org.springframework.boot.autoconfigure.hazelcast.HazelcastServerConfiguration$HazelcastServerConfigConfiguration$$EnhancerBySpringCGLIB$$8f7600e3] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:13.098  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'hazelcastConfig' of type [domain.test.platformapi.config.HazelcastConfig$$EnhancerBySpringCGLIB$$b16afb0e] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:13.148  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'config' of type [com.hazelcast.config.Config] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:13.176  INFO 41896 --- [           main] c.h.i.AddressPicker                      : [LOCAL] [dev] [3.9] Prefer IPv4 stack is true.
2018-03-06 19:51:13.478  INFO 41896 --- [           main] c.h.i.AddressPicker                      : [LOCAL] [dev] [3.9] Picked [192.168.81.1]:5701, using socket ServerSocket[addr=/0:0:0:0:0:0:0:0,localport=5701], bind any local is true
2018-03-06 19:51:13.486  INFO 41896 --- [           main] c.h.system                               : [192.168.81.1]:5701 [dev] [3.9] Hazelcast 3.9 (20171023 - b29f549) starting at [192.168.81.1]:5701
2018-03-06 19:51:13.486  INFO 41896 --- [           main] c.h.system                               : [192.168.81.1]:5701 [dev] [3.9] Copyright (c) 2008-2017, Hazelcast, Inc. All Rights Reserved.
2018-03-06 19:51:13.486  INFO 41896 --- [           main] c.h.system                               : [192.168.81.1]:5701 [dev] [3.9] Configured Hazelcast Serialization version: 1
2018-03-06 19:51:13.656  INFO 41896 --- [           main] c.h.s.i.o.i.BackpressureRegulator        : [192.168.81.1]:5701 [dev] [3.9] Backpressure is disabled
2018-03-06 19:51:14.640  INFO 41896 --- [           main] c.h.i.Node                               : [192.168.81.1]:5701 [dev] [3.9] Creating MulticastJoiner
2018-03-06 19:51:14.730  INFO 41896 --- [           main] c.h.s.i.o.i.OperationExecutorImpl        : [192.168.81.1]:5701 [dev] [3.9] Starting 8 partition threads and 5 generic threads (1 dedicated for priority tasks)
2018-03-06 19:51:14.732  INFO 41896 --- [           main] c.h.i.d.Diagnostics                      : [192.168.81.1]:5701 [dev] [3.9] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
2018-03-06 19:51:14.740  INFO 41896 --- [           main] c.h.c.LifecycleService                   : [192.168.81.1]:5701 [dev] [3.9] [192.168.81.1]:5701 is STARTING
2018-03-06 19:51:16.897  INFO 41896 --- [           main] c.h.system                               : [192.168.81.1]:5701 [dev] [3.9] Cluster version set to 3.9
2018-03-06 19:51:16.898  INFO 41896 --- [           main] c.h.i.c.ClusterService                   : [192.168.81.1]:5701 [dev] [3.9] 

Members {size:1, ver:1} [
    Member [192.168.81.1]:5701 - b70f5ec9-47fb-4ba2-b2bd-511404f44c58 this
]

2018-03-06 19:51:16.916  INFO 41896 --- [           main] c.h.c.LifecycleService                   : [192.168.81.1]:5701 [dev] [3.9] [192.168.81.1]:5701 is STARTED
2018-03-06 19:51:16.930  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'hazelcastInstance' of type [com.hazelcast.instance.HazelcastInstanceProxy] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:16.935  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'cacheManager' of type [com.hazelcast.spring.cache.HazelcastCacheManager] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:16.936  INFO 41896 --- [           main] trationDelegate$BeanPostProcessorChecker : Bean 'cacheAutoConfigurationValidator' of type [org.springframework.boot.autoconfigure.cache.CacheAutoConfiguration$CacheManagerValidator] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
2018-03-06 19:51:17.098  INFO 41896 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/v1/auth],methods=[POST]}" onto public reactor.core.publisher.Mono<domain.test.platformapi.model.opaque.APIResponse> domain.test.platformapi.controller.v1.AuthController.authenticate(domain.test.platformapi.model.Tenant,domain.test.platformapi.model.opaque.AuthRequest)
2018-03-06 19:51:17.102  INFO 41896 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/v1/info],methods=[GET]}" onto public reactor.core.publisher.Mono<domain.test.platformapi.model.opaque.APIResponse> domain.test.platformapi.controller.v1.InformationController.resolveAnonymous(org.springframework.http.server.reactive.ServerHttpRequest,domain.test.platformapi.model.Tenant)
2018-03-06 19:51:17.108  INFO 41896 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/v1/student],methods=[GET]}" onto public reactor.core.publisher.Mono<domain.test.platformapi.model.opaque.APIResponse> domain.test.platformapi.controller.v1.StudentController.index()
2018-03-06 19:51:17.109  INFO 41896 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/v1/student/test],methods=[GET]}" onto public reactor.core.publisher.Mono<domain.test.platformapi.model.opaque.APIResponse> domain.test.platformapi.controller.v1.StudentController.test(domain.test.platformapi.model.User)
2018-03-06 19:51:17.110  INFO 41896 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/v1/student],methods=[POST]}" onto public reactor.core.publisher.Mono<domain.test.platformapi.model.opaque.APIResponse> domain.test.platformapi.controller.v1.StudentController.create(domain.test.platformapi.model.Student)
2018-03-06 19:51:17.111  INFO 41896 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/v1/student/{id}],methods=[GET]}" onto public reactor.core.publisher.Mono<domain.test.platformapi.model.opaque.APIResponse> domain.test.platformapi.controller.v1.StudentController.getStudent(java.lang.Long)
2018-03-06 19:51:17.113  INFO 41896 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/v1/user],methods=[GET]}" onto public reactor.core.publisher.Mono<domain.test.platformapi.model.opaque.APIResponse> domain.test.platformapi.controller.v1.UserController.index()
2018-03-06 19:51:17.114  INFO 41896 --- [           main] s.w.r.r.m.a.RequestMappingHandlerMapping : Mapped "{[/v1/user/{id}],methods=[GET]}" onto public reactor.core.publisher.Mono<domain.test.platformapi.model.opaque.APIResponse> domain.test.platformapi.controller.v1.UserController.getUser(java.lang.Long)
2018-03-06 19:51:17.478  INFO 41896 --- [           main] .b.a.e.w.r.WebFluxEndpointHandlerMapping : Mapped "{[/actuator/health],methods=[GET],produces=[application/vnd.spring-boot.actuator.v2+json || application/json]}" onto public org.reactivestreams.Publisher<org.springframework.http.ResponseEntity<java.lang.Object>> org.springframework.boot.actuate.endpoint.web.reactive.WebFluxEndpointHandlerMapping$ReadOperationHandler.handle(org.springframework.web.server.ServerWebExchange)
2018-03-06 19:51:17.479  INFO 41896 --- [           main] .b.a.e.w.r.WebFluxEndpointHandlerMapping : Mapped "{[/actuator/info],methods=[GET],produces=[application/vnd.spring-boot.actuator.v2+json || application/json]}" onto public org.reactivestreams.Publisher<org.springframework.http.ResponseEntity<java.lang.Object>> org.springframework.boot.actuate.endpoint.web.reactive.WebFluxEndpointHandlerMapping$ReadOperationHandler.handle(org.springframework.web.server.ServerWebExchange)
2018-03-06 19:51:17.479  INFO 41896 --- [           main] .b.a.e.w.r.WebFluxEndpointHandlerMapping : Mapped "{[/actuator],methods=[GET],produces=[application/vnd.spring-boot.actuator.v2+json || application/json]}" onto private java.util.Map<java.lang.String, java.util.Map<java.lang.String, org.springframework.boot.actuate.endpoint.web.Link>> org.springframework.boot.actuate.endpoint.web.reactive.WebFluxEndpointHandlerMapping.links(org.springframework.http.server.reactive.ServerHttpRequest)
2018-03-06 19:51:17.510  INFO 41896 --- [           main] o.h.v.i.e.ValidatorFactoryImpl           : HV000238: Temporal validation tolerance set to 0.
2018-03-06 19:51:17.532  INFO 41896 --- [           main] o.s.w.r.r.m.a.ControllerMethodResolver   : Looking for @ControllerAdvice: org.springframework.boot.web.reactive.context.AnnotationConfigReactiveWebServerApplicationContext@e24ddd0: startup date [Tue Mar 06 19:51:11 JST 2018]; root of context hierarchy
2018-03-06 19:51:17.542  INFO 41896 --- [           main] o.s.w.r.r.m.a.ControllerMethodResolver   : Detected @ExceptionHandler methods in validationErrorHandler
2018-03-06 19:51:17.542  INFO 41896 --- [           main] o.s.w.r.r.m.a.ControllerMethodResolver   : Detected @ExceptionHandler methods in genericInputErrorHandler
2018-03-06 19:51:17.543  INFO 41896 --- [           main] o.s.w.r.r.m.a.ControllerMethodResolver   : Detected @ExceptionHandler methods in baseErrorHandler
2018-03-06 19:51:17.543  INFO 41896 --- [           main] o.s.w.r.r.m.a.ControllerMethodResolver   : Detected @ExceptionHandler methods in rootExceptionHandler
2018-03-06 19:51:18.416  INFO 41896 --- [           main] o.h.v.i.e.ValidatorFactoryImpl           : HV000238: Temporal validation tolerance set to 0.
2018-03-06 19:51:18.756  INFO 41896 --- [           main] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-03-06 19:51:18.791  INFO 41896 --- [           main] o.xnio                                   : XNIO version 3.3.8.Final
2018-03-06 19:51:18.797  INFO 41896 --- [           main] o.x.nio                                  : XNIO NIO Implementation Version 3.3.8.Final
2018-03-06 19:51:18.847  INFO 41896 --- [           main] o.s.b.w.e.u.UndertowServletWebServer     : Undertow started on port(s) 8443 (https)
2018-03-06 19:51:18.850  INFO 41896 --- [           main] n.s.p.PlatformApiApplication             : Started PlatformApiApplication in 8.424 seconds (JVM running for 9.8)
2018-03-06 19:51:24.993  WARN 41896 --- [   XNIO-1 I/O-8] n.s.p.l.a.JWTAuthenticationConverter     : couldn't find bearer string, will ignore the header
2018-03-06 19:51:24.994  INFO 41896 --- [   XNIO-1 I/O-8] n.s.p.l.a.JWTAuthenticationConverter     : checking authentication for user null
2018-03-06 19:51:25.016 ERROR 41896 --- [   XNIO-1 I/O-8] .a.w.r.e.DefaultErrorWebExceptionHandler : Failed to handle request [POST https://127.0.0.1:8443/v1/auth]

org.springframework.security.authentication.BadCredentialsException: Invalid token...
    at domain.test.platformapi.lib.auth.JWTAuthenticationConverter.apply(JWTAuthenticationConverter.java:98) ~[classes/:?]
    at domain.test.platformapi.lib.auth.JWTAuthenticationConverter.apply(JWTAuthenticationConverter.java:19) ~[classes/:?]
    at org.springframework.security.web.server.authentication.AuthenticationWebFilter.lambda$filter$1(AuthenticationWebFilter.java:66) ~[spring-security-web-5.0.0.RELEASE.jar:5.0.0.RELEASE]
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:118) ~[reactor-core-3.1.2.RELEASE.jar:3.1.2.RELEASE]
    at reactor.core.publisher.FluxFilterFuseable$FilterFuseableSubscriber.onNext(FluxFilterFuseable.java:104) ~[reactor-core-3.1.2.RELEASE.jar:3.1.2.RELEASE]
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:1649) ~[reactor-core-3.1.2.RELEASE.jar:3.1.2.RELEASE]...

Answer 1

This was because my AuthenticationConverter would actually throw an exception on invalid token (which I have an ExceptionHandler for, that's fine).

This would halt processing of the security flow. SecurityWebFiltersOrder.AUTHENTICATION comes BEFORE the permitAll calls are taken into account, so if the flow is terminated at that filter, nothing further gets done.

This is now resolved. Many thanks to @MateuszMrozewski for the assist.