Describe the bug
Spring Cloud microservice, with spring-security-oauth2-jose:6.0.8 with nimbus-jose-jwt:9.24.4
Sometimes (i.e. in the last 12 hours it happened 7 times), we are experiencing an increment of the java thread in state blocked, with the following stacktrace, taken from a thread dump generated during the issue:
"qtp1120531149-1608" - Thread t@1608
java.lang.Thread.State: BLOCKED
at app//com.nimbusds.jose.jwk.source.RemoteJWKSet.get(RemoteJWKSet.java:433)
- waiting to lock <2e2f22fa> (a com.nimbusds.jose.jwk.source.RemoteJWKSet) owned by "qtp1120531149-1460" t@1460
at app//com.nimbusds.jose.proc.JWSVerificationKeySelector.selectJWSKeys(JWSVerificationKeySelector.java:157)
at app//com.nimbusds.jwt.proc.DefaultJWTProcessor.selectKeys(DefaultJWTProcessor.java:283)
at app//com.nimbusds.jwt.proc.DefaultJWTProcessor.process(DefaultJWTProcessor.java:354)
at app//com.nimbusds.jwt.proc.DefaultJWTProcessor.process(DefaultJWTProcessor.java:303)
at app//org.springframework.security.oauth2.jwt.NimbusJwtDecoder.createJwt(NimbusJwtDecoder.java:154)
at app//org.springframework.security.oauth2.jwt.NimbusJwtDecoder.decode(NimbusJwtDecoder.java:137)
at app//it.eutelsat.mcm.spring.security.SwitchClientIdAuthenticationProvider.getJwt(SwitchClientIdAuthenticationProvider.java:70)
at app//it.eutelsat.mcm.spring.security.SwitchClientIdAuthenticationProvider.authenticate(SwitchClientIdAuthenticationProvider.java:44)
at app//org.springframework.security.authentication.ProviderManager.authenticate(ProviderManager.java:182)
at app//org.springframework.security.oauth2.server.resource.web.authentication.BearerTokenAuthenticationFilter.doFilterInternal(BearerTokenAuthenticationFilter.java:137)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:187)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:174)
at app//org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:135)
at app//org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:107)
at app//org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:93)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:187)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:174)
at app//org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:135)
at app//org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90)
at app//org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:187)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:174)
at app//org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:135)
at app//org.springframework.security.web.context.SecurityContextHolderFilter.doFilter(SecurityContextHolderFilter.java:82)
at app//org.springframework.security.web.context.SecurityContextHolderFilter.doFilter(SecurityContextHolderFilter.java:69)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:187)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:174)
at app//org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:135)
at app//org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:62)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:187)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:174)
at app//org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:135)
at app//org.springframework.security.web.session.DisableEncodeUrlFilter.doFilterInternal(DisableEncodeUrlFilter.java:42)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.wrapFilter(ObservationFilterChainDecorator.java:187)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter$$Lambda/0x00007f303757b560.doFilter(Unknown Source)
at app//org.springframework.security.web.ObservationFilterChainDecorator$AroundFilterObservation$SimpleAroundFilterObservation.lambda$wrap$0(ObservationFilterChainDecorator.java:270)
at app//org.springframework.security.web.ObservationFilterChainDecorator$AroundFilterObservation$SimpleAroundFilterObservation$$Lambda/0x00007f303757b7a0.doFilter(Unknown Source)
at app//org.springframework.security.web.ObservationFilterChainDecorator$ObservationFilter.doFilter(ObservationFilterChainDecorator.java:171)
at app//org.springframework.security.web.ObservationFilterChainDecorator$VirtualFilterChain.doFilter(ObservationFilterChainDecorator.java:135)
at app//org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:233)
at app//org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:191)
at app//org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:362)
at app//org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:278)
at app//org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at app//org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1586)
at app//org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at app//org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1586)
at app//org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at app//org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1586)
at app//org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:113)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at app//org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1586)
at app//org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at app//org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1586)
at app//org.springframework.web.filter.ForwardedHeaderFilter.doFilterInternal(ForwardedHeaderFilter.java:173)
at app//org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at app//org.eclipse.jetty.ee10.servlet.FilterHolder.doFilter(FilterHolder.java:205)
at app//org.eclipse.jetty.ee10.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1586)
at app//org.eclipse.jetty.ee10.servlet.ServletHandler$MappedServlet.handle(ServletHandler.java:1547)
at app//org.eclipse.jetty.ee10.servlet.ServletChannel.dispatch(ServletChannel.java:819)
at app//org.eclipse.jetty.ee10.servlet.ServletChannel.handle(ServletChannel.java:436)
at app//org.eclipse.jetty.ee10.servlet.ServletHandler.handle(ServletHandler.java:464)
at app//org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:575)
at app//org.eclipse.jetty.ee10.servlet.SessionHandler.handle(SessionHandler.java:717)
at app//org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1060)
at app//org.eclipse.jetty.server.Server.handle(Server.java:182)
at app//org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:662)
at app//org.eclipse.jetty.util.thread.Invocable$ReadyTask.run(Invocable.java:168)
at app//org.eclipse.jetty.http2.server.internal.HttpStreamOverHTTP2$1.run(HttpStreamOverHTTP2.java:135)
at app//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
at app//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
at app//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
at app//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:195)
at app//org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:210)
at app//org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:157)
at app//org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:442)
at app//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
at app//org.eclipse.jetty.io.ssl.SslConnection$SslEndPoint.onFillable(SslConnection.java:575)
at app//org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:390)
at app//org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:150)
at app//org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
at app//org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
at app//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
at app//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
at app//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
at app//org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
at app//org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
at app//org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
at app//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
at app//org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
at java.base@21.0.6/java.lang.Thread.runWith(Thread.java:1596)
at java.base@21.0.6/java.lang.Thread.run(Thread.java:1583)
The problem last 3-4 minutes, and during this period all the autenticated API calls received are stuck.
This is a graph of the jetty thread when the problem happens:
Honestly I'm not able to reproduce it systematically, but I'm pretty sure (after further analisys) that the problem occurs when there are a considerable number of bearers cached.
Comment From: mertmr
The same is also happening to our service on Openshift, it is intermittent and we couldn't come up with a way to reproduce it. Thread dump states the same, just for now we had to increase the thread count to meet the requests. I hope there is a workaround to this.
Comment From: giuliodema-eut
The same is also happening to our service on Openshift, it is intermittent and we couldn't come up with a way to reproduce it. Thread dump states the same, just for now we had to increase the thread count to meet the requests. I hope there is a workaround to this.
Hi, the problem on our side seems solved, I will explain how, maybe could be helpfull for you and others:
we analyzed the thread dump with an analyzer, and we noticed that all blocked threads were waiting for a single thread
qtp1927960180-2289
Stack Trace is:
java.lang.Thread.State: RUNNABLE
at java.base@21.0.6/sun.nio.ch.Net.connect0(Native Method)
Then we checked the net ACL for microsoft azure configured in our systems, and we realized that we were missing some.
After that we insert the missing ACL, the problem has not happened again for 12 days so far.
Hope that helps.
Comment From: mertmr
What I don't understand is this only happens like once a week, sometimes even once a month. do you still think ACL might cause this issue? I thought in the case of ACL, the connection should be blocked all the time, not intermittent like this.
Also why this thread is waiting on this connection this much time, why is it not getting a connection timeout? At least a default connection timeout value should be there for this. Or I am missing something, I am really confused about this :(
Thanks for the reply :)
Comment From: giuliodema-eut
What I don't understand is this only happens like once a week, sometimes even once a month. do you still think ACL might cause this issue? I thought in the case of ACL, the connection should be blocked all the time, not intermittent like this.
In our case only some subnets were missing, 2 out of 5, if I remember well. This explains the intermittent issue
Comment From: mertmr
Ok, I will investigate with them, thanks for the reply again.
Comment From: tshe-te
@mertmr We are experiencing a similar issue where a thread is blocking all other threads. This thread utilizes RestTemplate for HTTP client operations. We identified that the timeout was not configured in the following code section: [JdkClientHttpRequest.java](https://github.com/spring-projects/spring-framework/blob/5dc7425a8f3a0c15a270719b82bd24a37f9a9f70/spring-web/src/main/java/org/springframework/http/client/JdkClientHttpRequest.java#L105).
It should be updated:
HttpResponse<InputStream> response = responseFuture.get(this.timeout.toMillis(), TimeUnit.MILLISECONDS);
How do you think about?
Comment From: mertmr
For the default timeout, I am not sure where it should get implemented, spring security team might have a better idea. For Azure timeout implementation, I am checking out the timeout properties here, I am planning to use these properties to set a timeout value so we can fail fast, at least that is the idea:
https://learn.microsoft.com/en-us/azure/developer/java/spring-framework/spring-security-support?tabs=SpringCloudAzure5x
These are the properties I am planning to set:
spring.cloud.azure.active-directory.jwt-connect-timeout spring.cloud.azure.active-directory.jwt-read-timeout
But still, this is not the answer, I am going to explore the path that @giuliodema-eut mentioned, there is something else in play here.