Search code examples
spring-securityspring-security-oauth2

Spring Authorization Server - Client Credentials flow - no session created on POST to /oauth2/token

I am testing spring-authorization-server 0.2.1 with a simple application with a REST Controller to return a String on GET ("/message").

POST to "/oauth2/token" with BASIC Auth Header will successfully retrieve JWT token, but when client use the token, application will reply with 403 Forbidden.

The flow looks like this:

  1. POST /oauth2/token
  2. Response 200 OK with access_token_a
  3. GET /message with Authorization: "Bearer account_token_a"
  4. Response 403 Forbidden
  5. POST /oauth2/token
  6. Response 200 OK with access_token_b
  7. GET /message with Authorization: "Bearer account_token_b"
  8. Response 200 OK with Body Hello There

Checking the logs I can see that in the first POST to get access_token (1), no HTTP session is created and thus the SecurityContext is not stored in the session.

2022-01-10 15:27:53.971 DEBUG 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Securing POST /oauth2/token
2022-01-10 15:27:53.973 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking WebAsyncManagerIntegrationFilter (1/20)
2022-01-10 15:27:53.979 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking SecurityContextPersistenceFilter (2/20)
2022-01-10 15:27:53.980 TRACE 25384 --- [nio-8080-exec-1] w.c.HttpSessionSecurityContextRepository : No HttpSession currently exists
2022-01-10 15:27:53.981 TRACE 25384 --- [nio-8080-exec-1] w.c.HttpSessionSecurityContextRepository : Created SecurityContextImpl [Null authentication]
2022-01-10 15:27:53.983 DEBUG 25384 --- [nio-8080-exec-1] s.s.w.c.SecurityContextPersistenceFilter : Set SecurityContextHolder to empty SecurityContext
2022-01-10 15:27:53.984 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking HeaderWriterFilter (3/20)
2022-01-10 15:27:53.984 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking CsrfFilter (4/20)
2022-01-10 15:27:53.986 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.csrf.CsrfFilter         : Did not protect against CSRF since request did not match And [CsrfNotRequired [TRACE, HEAD, GET, OPTIONS], Not [Or [org.springframework.security.config.annotation.web.configurers.oauth2.server.authorization.OAuth2AuthorizationServerConfigurer$$Lambda$603/0x000000080043d040@3811510]]]
2022-01-10 15:27:53.986 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking LogoutFilter (5/20)
2022-01-10 15:27:53.987 TRACE 25384 --- [nio-8080-exec-1] o.s.s.w.a.logout.LogoutFilter            : Did not match request to Ant [pattern='/logout', POST]
2022-01-10 15:27:53.987 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking OAuth2AuthorizationEndpointFilter (6/20)
2022-01-10 15:27:53.987 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking OidcProviderConfigurationEndpointFilter (7/20)
2022-01-10 15:27:53.987 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking NimbusJwkSetEndpointFilter (8/20)
2022-01-10 15:27:53.987 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking OAuth2AuthorizationServerMetadataEndpointFilter (9/20)
2022-01-10 15:27:53.988 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking OAuth2ClientAuthenticationFilter (10/20)
2022-01-10 15:27:53.991 TRACE 25384 --- [nio-8080-exec-1] o.s.s.authentication.ProviderManager     : Authenticating request with OAuth2ClientAuthenticationProvider (1/9)
2022-01-10 15:27:53.991 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking RequestCacheAwareFilter (11/20)
2022-01-10 15:27:53.991 TRACE 25384 --- [nio-8080-exec-1] o.s.s.w.s.HttpSessionRequestCache        : No saved request
2022-01-10 15:27:53.991 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking SecurityContextHolderAwareRequestFilter (12/20)
2022-01-10 15:27:53.993 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking AnonymousAuthenticationFilter (13/20)
2022-01-10 15:27:53.993 TRACE 25384 --- [nio-8080-exec-1] o.s.s.w.a.AnonymousAuthenticationFilter  : Did not set SecurityContextHolder since already authenticated OAuth2ClientAuthenticationToken [Principal=prometheus-client, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=null], Granted Authorities=[]]
2022-01-10 15:27:53.993 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking SessionManagementFilter (14/20)
2022-01-10 15:27:53.993 TRACE 25384 --- [nio-8080-exec-1] s.CompositeSessionAuthenticationStrategy : Preparing session with ChangeSessionIdAuthenticationStrategy (1/2)
2022-01-10 15:27:53.994 TRACE 25384 --- [nio-8080-exec-1] s.CompositeSessionAuthenticationStrategy : Preparing session with CsrfAuthenticationStrategy (2/2)
2022-01-10 15:27:53.997 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking ExceptionTranslationFilter (15/20)
2022-01-10 15:27:53.997 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking FilterSecurityInterceptor (16/20)
2022-01-10 15:27:53.997 TRACE 25384 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not re-authenticate OAuth2ClientAuthenticationToken [Principal=prometheus-client, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=null], Granted Authorities=[]] before authorizing
2022-01-10 15:27:53.998 TRACE 25384 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorizing filter invocation [POST /oauth2/token] with attributes [authenticated]
2022-01-10 15:27:54.003 DEBUG 25384 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorized filter invocation [POST /oauth2/token] with attributes [authenticated]
2022-01-10 15:27:54.004 TRACE 25384 --- [nio-8080-exec-1] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not switch RunAs authentication since RunAsManager returned null
2022-01-10 15:27:54.004 TRACE 25384 --- [nio-8080-exec-1] o.s.security.web.FilterChainProxy        : Invoking OAuth2TokenEndpointFilter (17/20)
2022-01-10 15:27:54.010 TRACE 25384 --- [nio-8080-exec-1] o.s.s.authentication.ProviderManager     : Authenticating request with OAuth2ClientCredentialsAuthenticationProvider (1/9)
2022-01-10 15:27:54.147 TRACE 25384 --- [nio-8080-exec-1] o.s.s.w.header.writers.HstsHeaderWriter  : Not injecting HSTS header since it did not match request to [Is Secure]
2022-01-10 15:27:54.152 DEBUG 25384 --- [nio-8080-exec-1] s.s.w.c.SecurityContextPersistenceFilter : Cleared SecurityContextHolder to complete request

HTTP Session will be created on the GET request (3), but no SecurityContext will be found thus the request will fail with 403 Forbidden

2022-01-10 15:27:59.854 DEBUG 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Securing GET /message
2022-01-10 15:27:59.855 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking WebAsyncManagerIntegrationFilter (1/11)
2022-01-10 15:27:59.855 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking SecurityContextPersistenceFilter (2/11)
2022-01-10 15:27:59.876 DEBUG 25384 --- [nio-8080-exec-2] s.s.w.c.SecurityContextPersistenceFilter : Created session FC68E4563F8E775A591D1632F2C7456E eagerly
2022-01-10 15:27:59.876 TRACE 25384 --- [nio-8080-exec-2] w.c.HttpSessionSecurityContextRepository : Did not find SecurityContext in HttpSession FC68E4563F8E775A591D1632F2C7456E using the SPRING_SECURITY_CONTEXT session attribute
2022-01-10 15:27:59.876 TRACE 25384 --- [nio-8080-exec-2] w.c.HttpSessionSecurityContextRepository : Created SecurityContextImpl [Null authentication]
2022-01-10 15:27:59.876 DEBUG 25384 --- [nio-8080-exec-2] s.s.w.c.SecurityContextPersistenceFilter : Set SecurityContextHolder to empty SecurityContext
2022-01-10 15:27:59.876 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking HeaderWriterFilter (3/11)
2022-01-10 15:27:59.876 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking CsrfFilter (4/11)
2022-01-10 15:27:59.876 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.csrf.CsrfFilter         : Did not protect against CSRF since request did not match CsrfNotRequired [TRACE, HEAD, GET, OPTIONS]
2022-01-10 15:27:59.877 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking LogoutFilter (5/11)
2022-01-10 15:27:59.877 TRACE 25384 --- [nio-8080-exec-2] o.s.s.w.a.logout.LogoutFilter            : Did not match request to Ant [pattern='/logout', POST]
2022-01-10 15:27:59.877 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking RequestCacheAwareFilter (6/11)
2022-01-10 15:27:59.877 TRACE 25384 --- [nio-8080-exec-2] o.s.s.w.s.HttpSessionRequestCache        : No saved request
2022-01-10 15:27:59.877 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking SecurityContextHolderAwareRequestFilter (7/11)
2022-01-10 15:27:59.877 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking AnonymousAuthenticationFilter (8/11)
2022-01-10 15:27:59.877 TRACE 25384 --- [nio-8080-exec-2] o.s.s.w.a.AnonymousAuthenticationFilter  : Set SecurityContextHolder to AnonymousAuthenticationToken [Principal=anonymousUser, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=FC68E4563F8E775A591D1632F2C7456E], Granted Authorities=[ROLE_ANONYMOUS]]
2022-01-10 15:27:59.878 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking SessionManagementFilter (9/11)
2022-01-10 15:27:59.878 DEBUG 25384 --- [nio-8080-exec-2] o.s.s.w.session.SessionManagementFilter  : Request requested invalid session id A75734F37AD5AA7C76AA39F041B1C505
2022-01-10 15:27:59.878 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking ExceptionTranslationFilter (10/11)
2022-01-10 15:27:59.878 TRACE 25384 --- [nio-8080-exec-2] o.s.security.web.FilterChainProxy        : Invoking AuthorizationFilter (11/11)
2022-01-10 15:27:59.880 TRACE 25384 --- [nio-8080-exec-2] estMatcherDelegatingAuthorizationManager : Authorizing SecurityContextHolderAwareRequestWrapper[ org.springframework.security.web.header.HeaderWriterFilter$HeaderWriterRequest@764a97f0]
2022-01-10 15:27:59.880 TRACE 25384 --- [nio-8080-exec-2] estMatcherDelegatingAuthorizationManager : Checking authorization on SecurityContextHolderAwareRequestWrapper[ org.springframework.security.web.header.HeaderWriterFilter$HeaderWriterRequest@764a97f0] using org.springframework.security.authorization.AuthenticatedAuthorizationManager@a2fdca
2022-01-10 15:27:59.889 TRACE 25384 --- [nio-8080-exec-2] o.s.s.w.a.ExceptionTranslationFilter     : Sending AnonymousAuthenticationToken [Principal=anonymousUser, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=FC68E4563F8E775A591D1632F2C7456E], Granted Authorities=[ROLE_ANONYMOUS]] to authentication entry point since access is denied

org.springframework.security.access.AccessDeniedException: Access Denied
    at org.springframework.security.authorization.AuthorizationManager.verify(AuthorizationManager.java:44) ~[spring-security-core-5.6.1.jar:5.6.1]
    at org.springframework.security.web.access.intercept.AuthorizationFilter.doFilterInternal(AuthorizationFilter.java:57) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.14.jar:5.3.14]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:122) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:116) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:109) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.csrf.CsrfFilter.doFilterInternal(CsrfFilter.java:117) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.14.jar:5.3.14]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.14.jar:5.3.14]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:110) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:80) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.14.jar:5.3.14]
    at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183) ~[spring-security-web-5.6.1.jar:5.6.1]
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354) ~[spring-web-5.3.14.jar:5.3.14]
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267) ~[spring-web-5.3.14.jar:5.3.14]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.14.jar:5.3.14]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.14.jar:5.3.14]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.14.jar:5.3.14]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.14.jar:5.3.14]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.14.jar:5.3.14]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.14.jar:5.3.14]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1732) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.56.jar:9.0.56]
    at java.base/java.lang.Thread.run(Thread.java:829) ~[na:na]

2022-01-10 15:27:59.898 DEBUG 25384 --- [nio-8080-exec-2] o.s.s.w.s.HttpSessionRequestCache        : Saved request http://10.20.1.192:8080/message to session
2022-01-10 15:27:59.898 DEBUG 25384 --- [nio-8080-exec-2] o.s.s.w.a.Http403ForbiddenEntryPoint     : Pre-authenticated entry point called. Rejecting access
2022-01-10 15:27:59.898 TRACE 25384 --- [nio-8080-exec-2] o.s.s.w.header.writers.HstsHeaderWriter  : Not injecting HSTS header since it did not match request to [Is Secure]
2022-01-10 15:27:59.898 DEBUG 25384 --- [nio-8080-exec-2] w.c.HttpSessionSecurityContextRepository : Did not store empty SecurityContext
2022-01-10 15:27:59.898 DEBUG 25384 --- [nio-8080-exec-2] w.c.HttpSessionSecurityContextRepository : Did not store empty SecurityContext
2022-01-10 15:27:59.898 DEBUG 25384 --- [nio-8080-exec-2] s.s.w.c.SecurityContextPersistenceFilter : Cleared SecurityContextHolder to complete request

On the second POST to get a new JWT token (5), HTTP Session is present, thus the SecurityContext will be saved there and reused for later. And as a result, GET request (7) will succeed.

2022-01-10 15:28:08.152 DEBUG 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Securing POST /oauth2/token
2022-01-10 15:28:08.152 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking WebAsyncManagerIntegrationFilter (1/20)
2022-01-10 15:28:08.152 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking SecurityContextPersistenceFilter (2/20)
2022-01-10 15:28:08.153 TRACE 25384 --- [nio-8080-exec-3] w.c.HttpSessionSecurityContextRepository : Did not find SecurityContext in HttpSession FC68E4563F8E775A591D1632F2C7456E using the SPRING_SECURITY_CONTEXT session attribute
2022-01-10 15:28:08.153 TRACE 25384 --- [nio-8080-exec-3] w.c.HttpSessionSecurityContextRepository : Created SecurityContextImpl [Null authentication]
2022-01-10 15:28:08.153 DEBUG 25384 --- [nio-8080-exec-3] s.s.w.c.SecurityContextPersistenceFilter : Set SecurityContextHolder to empty SecurityContext
2022-01-10 15:28:08.153 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking HeaderWriterFilter (3/20)
2022-01-10 15:28:08.153 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking CsrfFilter (4/20)
2022-01-10 15:28:08.153 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.csrf.CsrfFilter         : Did not protect against CSRF since request did not match And [CsrfNotRequired [TRACE, HEAD, GET, OPTIONS], Not [Or [org.springframework.security.config.annotation.web.configurers.oauth2.server.authorization.OAuth2AuthorizationServerConfigurer$$Lambda$603/0x000000080043d040@3811510]]]
2022-01-10 15:28:08.153 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking LogoutFilter (5/20)
2022-01-10 15:28:08.153 TRACE 25384 --- [nio-8080-exec-3] o.s.s.w.a.logout.LogoutFilter            : Did not match request to Ant [pattern='/logout', POST]
2022-01-10 15:28:08.154 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking OAuth2AuthorizationEndpointFilter (6/20)
2022-01-10 15:28:08.154 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking OidcProviderConfigurationEndpointFilter (7/20)
2022-01-10 15:28:08.154 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking NimbusJwkSetEndpointFilter (8/20)
2022-01-10 15:28:08.154 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking OAuth2AuthorizationServerMetadataEndpointFilter (9/20)
2022-01-10 15:28:08.154 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking OAuth2ClientAuthenticationFilter (10/20)
2022-01-10 15:28:08.155 TRACE 25384 --- [nio-8080-exec-3] o.s.s.authentication.ProviderManager     : Authenticating request with OAuth2ClientAuthenticationProvider (1/9)
2022-01-10 15:28:08.155 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking RequestCacheAwareFilter (11/20)
2022-01-10 15:28:08.155 TRACE 25384 --- [nio-8080-exec-3] o.s.s.w.s.HttpSessionRequestCache        : Did not match request /oauth2/token to the saved one DefaultSavedRequest [http://10.20.1.192:8080/message]
2022-01-10 15:28:08.155 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking SecurityContextHolderAwareRequestFilter (12/20)
2022-01-10 15:28:08.155 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking AnonymousAuthenticationFilter (13/20)
2022-01-10 15:28:08.155 TRACE 25384 --- [nio-8080-exec-3] o.s.s.w.a.AnonymousAuthenticationFilter  : Did not set SecurityContextHolder since already authenticated OAuth2ClientAuthenticationToken [Principal=prometheus-client, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=FC68E4563F8E775A591D1632F2C7456E], Granted Authorities=[]]
2022-01-10 15:28:08.155 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking SessionManagementFilter (14/20)
2022-01-10 15:28:08.155 TRACE 25384 --- [nio-8080-exec-3] s.CompositeSessionAuthenticationStrategy : Preparing session with ChangeSessionIdAuthenticationStrategy (1/2)
2022-01-10 15:28:08.156 DEBUG 25384 --- [nio-8080-exec-3] .s.ChangeSessionIdAuthenticationStrategy : Changed session id from FC68E4563F8E775A591D1632F2C7456E
2022-01-10 15:28:08.158 TRACE 25384 --- [nio-8080-exec-3] s.CompositeSessionAuthenticationStrategy : Preparing session with CsrfAuthenticationStrategy (2/2)
2022-01-10 15:28:08.159 DEBUG 25384 --- [nio-8080-exec-3] w.c.HttpSessionSecurityContextRepository : Stored SecurityContextImpl [Authentication=OAuth2ClientAuthenticationToken [Principal=prometheus-client, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=FC68E4563F8E775A591D1632F2C7456E], Granted Authorities=[]]] to HttpSession [org.apache.catalina.session.StandardSessionFacade@7f25256d]
2022-01-10 15:28:08.159 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking ExceptionTranslationFilter (15/20)
2022-01-10 15:28:08.159 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking FilterSecurityInterceptor (16/20)
2022-01-10 15:28:08.159 TRACE 25384 --- [nio-8080-exec-3] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not re-authenticate OAuth2ClientAuthenticationToken [Principal=prometheus-client, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=FC68E4563F8E775A591D1632F2C7456E], Granted Authorities=[]] before authorizing
2022-01-10 15:28:08.159 TRACE 25384 --- [nio-8080-exec-3] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorizing filter invocation [POST /oauth2/token] with attributes [authenticated]
2022-01-10 15:28:08.160 DEBUG 25384 --- [nio-8080-exec-3] o.s.s.w.a.i.FilterSecurityInterceptor    : Authorized filter invocation [POST /oauth2/token] with attributes [authenticated]
2022-01-10 15:28:08.160 TRACE 25384 --- [nio-8080-exec-3] o.s.s.w.a.i.FilterSecurityInterceptor    : Did not switch RunAs authentication since RunAsManager returned null
2022-01-10 15:28:08.160 TRACE 25384 --- [nio-8080-exec-3] o.s.security.web.FilterChainProxy        : Invoking OAuth2TokenEndpointFilter (17/20)
2022-01-10 15:28:08.160 TRACE 25384 --- [nio-8080-exec-3] o.s.s.authentication.ProviderManager     : Authenticating request with OAuth2ClientCredentialsAuthenticationProvider (1/9)
2022-01-10 15:28:08.181 TRACE 25384 --- [nio-8080-exec-3] o.s.s.w.header.writers.HstsHeaderWriter  : Not injecting HSTS header since it did not match request to [Is Secure]
2022-01-10 15:28:08.182 DEBUG 25384 --- [nio-8080-exec-3] w.c.HttpSessionSecurityContextRepository : Stored SecurityContextImpl [Authentication=OAuth2ClientAuthenticationToken [Principal=prometheus-client, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=FC68E4563F8E775A591D1632F2C7456E], Granted Authorities=[]]] to HttpSession [org.apache.catalina.session.StandardSessionFacade@7f25256d]
2022-01-10 15:28:08.182 DEBUG 25384 --- [nio-8080-exec-3] w.c.HttpSessionSecurityContextRepository : Stored SecurityContextImpl [Authentication=OAuth2ClientAuthenticationToken [Principal=prometheus-client, Credentials=[PROTECTED], Authenticated=true, Details=WebAuthenticationDetails [RemoteIpAddress=10.20.1.192, SessionId=FC68E4563F8E775A591D1632F2C7456E], Granted Authorities=[]]] to HttpSession [org.apache.catalina.session.StandardSessionFacade@7f25256d]
2022-01-10 15:28:08.182 DEBUG 25384 --- [nio-8080-exec-3] s.s.w.c.SecurityContextPersistenceFilter : Cleared SecurityContextHolder to complete request

I am using configuration https://github.com/spring-projects/spring-security-samples/blob/main/servlet/spring-boot/java/oauth2/authorization-server/src/main/java/example/OAuth2AuthorizationServerSecurityConfiguration.java but with login page disabled.

Is this a bug or something wrong in the configuration?

Thanks

Solution

  • Since you're using client_credentials, you shouldn't be relying on a session. You also don't need a second filter chain with formLogin() disabled.

    Upon investigating your sample, it looks as though you're attempting to include a resource server (the Simple controller) in your authorization server. This is an incorrect setup. It should be a separately deployed application and properly configured as a resource server, as in the samples provided in the project.