Version
- Spring Boot Version: 2.6.5
- Spring Cloud Version: 2021.0.0
The application built has the following characteristics:
- It is a reactive application (Reactor + WebFlux)
- It is an Oauth2 Client Application that uses Grant Type = Authorization Code.
- It uses Spring Cloud Gateway to proxy Oauth2 Resources.
- It uses Spring Session (Redis) to be able to accomplish transparent horizontal scaling.
Problem:
Requesting a resource that goes through the Spring Cloud Gateway to a downstream service returns a correct 200, but after the application is restarted while there is an active session saved in Redis it will return a 302. I find this to be a huge problem because it basically prevents horizontal scaling, which is my whole reason to implement Spring Session in Redis.
Steps to reproduce:
- Start Application.
- User requests loading application in the browser: https://localhost:9093/hello.html
- Session is successfully created in Redis.
- User redirected to the Oauth2 Server for Authentication
- User Authenticates
- User redirected to application after successful login.
- Application loads in browser without a problem.
- User requests a gateway resource: https://localhost:9093/entries
- Resources loads fine with a 200.
- Everything great so far.
- Restart the server.
- (Session still active, saved on Redis)
- User requests the gateway resource (https://localhost:9093/entries).
- Resources returns 302 and redirected to the Ouath Server (BAD)
Logs
The difference in logs when the resource loads vs does not load is the following:
Correct Loading
2022-03-30 18:25:06.655 [lettuce-kqueueEventLoop-5-1] DEBUG 90299 --- [PathPatternParserServerWebExchangeMatcher PathPatternParserServerWebExchangeMatcher.java:95->matches] : Checking match of request : '/wasd/selfservice/api/ccbConfiguration'; against '/wasd/**'
2022-03-30 18:25:06.655 [lettuce-kqueueEventLoop-5-1] DEBUG 90299 --- [OrServerWebExchangeMatcher OrServerWebExchangeMatcher.java:60->lambda$matches$2] : matched
2022-03-30 18:25:06.655 [lettuce-kqueueEventLoop-5-1] DEBUG 90299 --- [DelegatingReactiveAuthorizationManager DelegatingReactiveAuthorizationManager.java:55->lambda$check$1] : Checking authorization on '/wasd/selfservice/api/ccbConfiguration' using org.springframework.security.config.web.server.ServerHttpSecurity$AuthorizeExchangeSpec$Access$$Lambda$1069/0x0000000800995840@7ffc1fdb
2022-03-30 18:25:06.656 [lettuce-kqueueEventLoop-5-1] DEBUG 90299 --- [AuthorizationWebFilter AuthorizationWebFilter.java:52->lambda$filter$2] : Authorization successful
2022-03-30 18:25:06.656 [lettuce-kqueueEventLoop-5-1] DEBUG 90299 --- [RoutePredicateHandlerMapping RoutePredicateHandlerMapping.java:142->lambda$lookupRoute$6] : Route matched: ssa-resources
2022-03-30 18:25:06.656 [lettuce-kqueueEventLoop-5-1] DEBUG 90299 --- [RoutePredicateHandlerMapping RoutePredicateHandlerMapping.java:90->lambda$getHandlerInternal$0] : Mapping [Exchange: GET https://localhost:9093/wasdservice/wasd/selfservice/api/ccbConfiguration] to Route{id='ssa-resources', uri=https://wasd-api-int.company.com:443, order=0, predicate=Paths: [/wasdservice/wasd/**], match trailing slash: true, gatewayFilters=[[gov.miamidade.wasd.client.gateway.StripBasePathGatewayFilterFactory$$Lambda$1563/0x0000000800b4f040@4d05f800, order = 1], [org.springframework.cloud.gateway.filter.factory.TokenRelayGatewayFilterFactory$$Lambda$1564/0x0000000800b4f440@46c35be4, order = 2]], metadata={}}
2022-03-30 18:25:06.657 [lettuce-kqueueEventLoop-5-1] DEBUG 90299 --- [RoutePredicateHandlerMapping AbstractHandlerMapping.java:189->lambda$getHandler$1] : [cb1dc8d7-90] Mapped to org.springframework.cloud.gateway.handler.FilteringWebHandler@546da583
2022-03-30 18:25:06.657 [lettuce-kqueueEventLoop-5-1] DEBUG 90299 --- [FilteringWebHandler FilteringWebHandler.java:85->handle] : Sorted gatewayFilterFactories: [[GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.RemoveCachedBodyFilter@86e7c7a}, order = -2147483648], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.AdaptCachedBodyGlobalFilter@29617475}, order = -2147482648], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.NettyWriteResponseFilter@271df4c0}, order = -1], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.ForwardPathFilter@22edca96}, order = 0], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.GatewayMetricsFilter@6e1bd2b}, order = 0], [gov.miamidade.wasd.client.gateway.StripBasePathGatewayFilterFactory$$Lambda$1563/0x0000000800b4f040@4d05f800, order = 1], [org.springframework.cloud.gateway.filter.factory.TokenRelayGatewayFilterFactory$$Lambda$1564/0x0000000800b4f440@46c35be4, order = 2], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.RouteToRequestUrlFilter@6e863469}, order = 10000], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.config.GatewayNoLoadBalancerClientAutoConfiguration$NoLoadBalancerClientFilter@18a66406}, order = 10150], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.WebsocketRoutingFilter@591bff1d}, order = 2147483646], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.NettyRoutingFilter@38379575}, order = 2147483647], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.ForwardRoutingFilter@6a9e88f1}, order = 2147483647]]
.]]]' in WebSession: 'org.springframework.session.web.server.session.SpringSessionWebSessionStore$SpringSessionWebSession@118f2254'
2022-03-30 18:25:06.658 [reactor-http-kqueue-2] DEBUG 90299 --- [PooledConnectionProvider Loggers.java:250->debug] : [1bea583a, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443] Channel acquired, now: 1 active connections, 0 inactive connections and 0 pending acquire requests.
2022-03-30 18:25:06.659 [reactor-http-kqueue-2] DEBUG 90299 --- [HttpClientConnect Loggers.java:250->debug] : [1bea583a-5, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443] Handler is being applied: {uri=https://wasd-api-int.company.com/wasd/selfservice/api/ccbConfiguration, method=GET}
2022-03-30 18:25:06.659 [reactor-http-kqueue-2] DEBUG 90299 --- [DefaultPooledConnectionProvider Loggers.java:250->debug] : [1bea583a-5, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443] onStateChange(GET{uri=/wasd/selfservice/api/ccbConfiguration, connection=PooledConnection{channel=[id: 0x1bea583a, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443]}}, [request_prepared])
2022-03-30 18:25:06.659 [reactor-http-kqueue-4] DEBUG 90299 --- [FluxReceive Loggers.java:250->debug] : [cb1dc8d7-16, L:/0:0:0:0:0:0:0:1%0:9093 - R:/0:0:0:0:0:0:0:1%0:56346] FluxReceive{pending=0, cancelled=false, inboundDone=true, inboundError=null}: subscribing inbound receiver
2022-03-30 18:25:06.660 [reactor-http-kqueue-2] DEBUG 90299 --- [DefaultPooledConnectionProvider Loggers.java:250->debug] : [1bea583a-5, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443] onStateChange(GET{uri=/wasd/selfservice/api/ccbConfiguration, connection=PooledConnection{channel=[id: 0x1bea583a, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443]}}, [request_sent])
2022-03-30 18:25:06.779 [reactor-http-kqueue-2] DEBUG 90299 --- [HttpClientOperations Loggers.java:250->debug] : [1bea583a-5, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443] Received response (auto-read:false) : [Cache-Control=no-cache, no-store, max-age=0, must-revalidate, Pragma=no-cache, Transfer-Encoding=chunked, Content-Type=application/json, Expires=0, Vary=Access-Control-Request-Headers, Request-Context=appId=e6c5278f-0ac3-4701-9647-f98e97152b1f, X-Content-Type-Options=nosniff, X-XSS-Protection=1; mode=block, Strict-Transport-Security=max-age=31536000 ; includeSubDomains, X-Frame-Options=DENY, Set-Cookie=ARRAffinity=64fcec8b11e29841b77fe53d1af49439c9f64a9de8bd5c352f6db54bf06a60d1;Path=/;HttpOnly;Secure;Domain=wasd-api-int.company.com, Set-Cookie=ARRAffinitySameSite=64fcec8b11e29841b77fe53d1af49439c9f64a9de8bd5c352f6db54bf06a60d1;Path=/;HttpOnly;SameSite=None;Secure;Domain=wasd-api-int.company.com, Date=Wed, 30 Mar 2022 22:25:05 GMT]
2022-03-30 18:25:06.779 [reactor-http-kqueue-2] DEBUG 90299 --- [DefaultPooledConnectionProvider Loggers.java:250->debug] : [1bea583a-5, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443] onStateChange(GET{uri=/wasd/selfservice/api/ccbConfiguration, connection=PooledConnection{channel=[id: 0x1bea583a, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443]}}, [response_received])
2022-03-30 18:25:06.780 [reactor-http-kqueue-2] DEBUG 90299 --- [FluxReceive Loggers.java:250->debug] : [1bea583a-5, L:/192.168.1.11:56359 - R:wasd-api-int.company.com/10.82.52.4:443] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
Incorrect Loading
2022-03-30 18:31:56.074 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [PathPatternParserServerWebExchangeMatcher PathPatternParserServerWebExchangeMatcher.java:95->matches] : Checking match of request : '/wasd/selfservice/api/ccbConfiguration'; against '/wasd/**'
2022-03-30 18:31:56.075 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [OrServerWebExchangeMatcher OrServerWebExchangeMatcher.java:60->lambda$matches$2] : matched
2022-03-30 18:31:56.075 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [DelegatingReactiveAuthorizationManager DelegatingReactiveAuthorizationManager.java:55->lambda$check$1] : Checking authorization on '/wasd/selfservice/api/ccbConfiguration' using org.springframework.security.config.web.server.ServerHttpSecurity$AuthorizeExchangeSpec$Access$$Lambda$1070/0x000000080099e840@1107fca4
2022-03-30 18:31:56.075 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [AuthorizationWebFilter AuthorizationWebFilter.java:52->lambda$filter$2] : Authorization successful
2022-03-30 18:31:56.105 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [RoutePredicateHandlerMapping RoutePredicateHandlerMapping.java:142->lambda$lookupRoute$6] : Route matched: ssa-resources
2022-03-30 18:31:56.105 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [RoutePredicateHandlerMapping RoutePredicateHandlerMapping.java:90->lambda$getHandlerInternal$0] : Mapping [Exchange: GET https://localhost:9093/wasdservice/wasd/selfservice/api/ccbConfiguration] to Route{id='ssa-resources', uri=https://wasd-api-int.company.com:443, order=0, predicate=Paths: [/wasdservice/wasd/**], match trailing slash: true, gatewayFilters=[[com.mycompany.wasd.client.gateway.StripBasePathGatewayFilterFactory$$Lambda$1543/0x0000000800b38440@2f286cb, order = 1], [org.springframework.cloud.gateway.filter.factory.TokenRelayGatewayFilterFactory$$Lambda$1544/0x0000000800b38840@19401a72, order = 2]], metadata={}}
2022-03-30 18:31:56.106 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [RoutePredicateHandlerMapping AbstractHandlerMapping.java:189->lambda$getHandler$1] : [cc95c8f2-1] Mapped to org.springframework.cloud.gateway.handler.FilteringWebHandler@addc61b
2022-03-30 18:31:56.107 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [FilteringWebHandler FilteringWebHandler.java:85->handle] : Sorted gatewayFilterFactories: [[GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.RemoveCachedBodyFilter@142f0ac1}, order = -2147483648], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.AdaptCachedBodyGlobalFilter@11544ddd}, order = -2147482648], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.NettyWriteResponseFilter@3f7d20c5}, order = -1], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.ForwardPathFilter@f4a21cb}, order = 0], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.GatewayMetricsFilter@456d3914}, order = 0], [com.mycompany.wasd.client.gateway.StripBasePathGatewayFilterFactory$$Lambda$1543/0x0000000800b38440@2f286cb, order = 1], [org.springframework.cloud.gateway.filter.factory.TokenRelayGatewayFilterFactory$$Lambda$1544/0x0000000800b38840@19401a72, order = 2], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.RouteToRequestUrlFilter@1847da64}, order = 10000], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.config.GatewayNoLoadBalancerClientAutoConfiguration$NoLoadBalancerClientFilter@26a0068a}, order = 10150], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.WebsocketRoutingFilter@635f4be1}, order = 2147483646], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.NettyRoutingFilter@27acd9a7}, order = 2147483647], [GatewayFilterAdapter{delegate=org.springframework.cloud.gateway.filter.ForwardRoutingFilter@5967492a}, order = 2147483647]]
.]]]' in WebSession: 'org.springframework.session.web.server.session.SpringSessionWebSessionStore$SpringSessionWebSession@3d103de5'
2022-03-30 18:31:56.144 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [AndServerWebExchangeMatcher AndServerWebExchangeMatcher.java:61->lambda$matches$0] : Trying to match using OrServerWebExchangeMatcher{matchers=[PathMatcherServerWebExchangeMatcher{pattern='/**', method=GET}]}
2022-03-30 18:31:56.144 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [OrServerWebExchangeMatcher OrServerWebExchangeMatcher.java:57->lambda$matches$0] : Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/**', method=GET}
2022-03-30 18:31:56.145 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [PathPatternParserServerWebExchangeMatcher PathPatternParserServerWebExchangeMatcher.java:95->matches] : Checking match of request : '/wasd/selfservice/api/ccbConfiguration'; against '/**'
2022-03-30 18:31:56.145 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [OrServerWebExchangeMatcher OrServerWebExchangeMatcher.java:60->lambda$matches$2] : matched
2022-03-30 18:31:56.146 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [AndServerWebExchangeMatcher AndServerWebExchangeMatcher.java:61->lambda$matches$0] : Trying to match using NegatedServerWebExchangeMatcher{matcher=OrServerWebExchangeMatcher{matchers=[PathMatcherServerWebExchangeMatcher{pattern='/favicon.*', method=null}]}}
2022-03-30 18:31:56.147 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [OrServerWebExchangeMatcher OrServerWebExchangeMatcher.java:57->lambda$matches$0] : Trying to match using PathMatcherServerWebExchangeMatcher{pattern='/favicon.*', method=null}
2022-03-30 18:31:56.148 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [PathPatternParserServerWebExchangeMatcher PathPatternParserServerWebExchangeMatcher.java:87->lambda$matches$1] : Request 'GET /wasd/selfservice/api/ccbConfiguration' doesn't match 'null /favicon.*'
2022-03-30 18:31:56.148 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [OrServerWebExchangeMatcher OrServerWebExchangeMatcher.java:60->lambda$matches$2] : No matches found
2022-03-30 18:31:56.149 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [NegatedServerWebExchangeMatcher NegatedServerWebExchangeMatcher.java:49->lambda$matches$0] : matches = true
2022-03-30 18:31:56.149 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [AndServerWebExchangeMatcher AndServerWebExchangeMatcher.java:61->lambda$matches$0] : Trying to match using MediaTypeRequestMatcher [matchingMediaTypes=[text/html], useEquals=false, ignoredMediaTypes=[*/*]]
2022-03-30 18:31:56.150 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [MediaTypeServerWebExchangeMatcher MediaTypeServerWebExchangeMatcher.java:84->matches] : httpRequestMediaTypes=[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]
2022-03-30 18:31:56.150 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [MediaTypeServerWebExchangeMatcher MediaTypeServerWebExchangeMatcher.java:86->matches] : Processing text/html
2022-03-30 18:31:56.151 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [MediaTypeServerWebExchangeMatcher MediaTypeServerWebExchangeMatcher.java:98->matches] : text/html .isCompatibleWith text/html = true
2022-03-30 18:31:56.152 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [AndServerWebExchangeMatcher AndServerWebExchangeMatcher.java:66->lambda$matches$4] : All requestMatchers returned true
2022-03-30 18:31:56.152 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [WebSessionServerRequestCache WebSessionServerRequestCache.java:76->lambda$saveRequest$1] : Request added to WebSession: '/wasd/selfservice/api/ccbConfiguration'
2022-03-30 18:31:56.163 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [DefaultServerRedirectStrategy DefaultServerRedirectStrategy.java:54->lambda$sendRedirect$0] : Redirecting to 'https://s0144821.company.com:9999/uaa/oauth/authorize?response_type=code&client_id=wasdssa&state=CPaWn5UE9oBzjPm-efV2mlONTXbNrLz5i_DZAy9KrS4%3D&redirect_uri=https://localhost:9093/wasdservice/login/oauth2/code/mdc'
2022-03-30 18:31:56.166 [lettuce-kqueueEventLoop-5-1] DEBUG 90357 --- [HttpWebHandlerAdapter LogFormatUtils.java:119->traceDebug] : [cc95c8f2-1] Completed 302 FOUND
Sample Application
I created a minimalistic project where you can see all the details of the configuration and execute it so that you can verify for yourself that indeed this is happening. (you are going to need a Redis instance and an Oauth server)
https://github.com/fiallega/spring-session-oauth-gateway
Configuration
The WebSecurity Configuration is as follows:
@Bean
public SecurityWebFilterChain springSecurityFilterChain(ServerHttpSecurity http) {
http.csrf().disable();
http.headers()
.referrerPolicy(ReferrerPolicyServerHttpHeadersWriter.ReferrerPolicy.NO_REFERRER_WHEN_DOWNGRADE);
http.authorizeExchange()
.pathMatchers("/login**","/entries/**").permitAll()
.anyExchange()
.authenticated()
.and()
.oauth2Login();
return http.build();
}
and the gateway configuration is
cloud:
gateway:
routes:
- id: ssa-resources
uri: https://api.publicapis.org
predicates:
- Path=/entries
filters:
- TokenRelay=
What I see is that after reloading the application for some reason instead of making calls to the downstream servers, checks on mediatype happens and ends up with a 302 redirect when it should get a 200.
So why is it that a reload of an application that is using spring session is not able to "pickup" where it left, and this weird redirect happening after reloading the application if an active session exists in Redis?
Thanks