Describe the bug
We encountered repeating, but not easily reproducible bug ending with StackOverflowError
caught and logged in Reactor:
java.lang.StackOverflowError
at java.base/sun.util.locale.provider.CalendarProviderImpl.getInstance(CalendarProviderImpl.java:87)
at java.base/java.util.Calendar.createCalendar(Calendar.java:1700)
at java.base/java.util.Calendar.getInstance(Calendar.java:1679)
at net.logstash.logback.encoder.org.apache.commons.lang3.time.FastDatePrinter.newCalendar(FastDatePrinter.java:463)
at net.logstash.logback.encoder.org.apache.commons.lang3.time.FastDatePrinter.format(FastDatePrinter.java:444)
at net.logstash.logback.encoder.org.apache.commons.lang3.time.FastDateFormat.format(FastDateFormat.java:428)
at net.logstash.logback.composite.FormattedTimestampJsonProvider$PatternTimestampWriter.getTimestampAsString(FormattedTimestampJsonProvider.java:101)
at net.logstash.logback.composite.FormattedTimestampJsonProvider$PatternTimestampWriter.writeTo(FormattedTimestampJsonProvider.java:96)
at net.logstash.logback.composite.FormattedTimestampJsonProvider.writeTo(FormattedTimestampJsonProvider.java:149)
at net.logstash.logback.composite.JsonProviders.writeTo(JsonProviders.java:77)
at net.logstash.logback.composite.CompositeJsonFormatter.writeEventToGenerator(CompositeJsonFormatter.java:195)
at net.logstash.logback.composite.CompositeJsonFormatter.writeEventAsString(CompositeJsonFormatter.java:184)
at net.logstash.logback.layout.CompositeJsonLayout.doLayout(CompositeJsonLayout.java:58)
at net.logstash.logback.layout.CompositeJsonLayout.doLayout(CompositeJsonLayout.java:30)
at net.logstash.logback.appender.AbstractLogstashUdpSocketAppender.append(AbstractLogstashUdpSocketAppender.java:85)
at net.logstash.logback.appender.AbstractLogstashUdpSocketAppender.append(AbstractLogstashUdpSocketAppender.java:32)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:426)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:386)
at ch.qos.logback.classic.Logger.warn(Logger.java:697)
at reactor.util.Loggers$Slf4JLogger.warn(Loggers.java:304)
at reactor.core.Exceptions.throwIfFatal(Exceptions.java:513)
at reactor.core.publisher.Operators.reportThrowInSubscribe(Operators.java:229)
at reactor.core.publisher.Mono.subscribe(Mono.java:4579)
at reactor.core.publisher.Mono.subscribeWith(Mono.java:4641)
at reactor.core.publisher.Mono.subscribe(Mono.java:4542)
at reactor.core.publisher.Mono.subscribe(Mono.java:4478)
at reactor.core.publisher.Mono.subscribe(Mono.java:4450)
at io.lettuce.core.AbstractRedisClient.initializeChannelAsync(AbstractRedisClient.java:411)
at io.lettuce.core.RedisClient.connectStatefulAsync(RedisClient.java:331)
at io.lettuce.core.RedisClient.connectStandaloneAsync(RedisClient.java:292)
at io.lettuce.core.RedisClient.connect(RedisClient.java:220)
at org.springframework.data.redis.connection.lettuce.StandaloneConnectionProvider.lambda$getConnection$1(StandaloneConnectionProvider.java:112)
at java.base/java.util.Optional.orElseGet(Optional.java:364)
at org.springframework.data.redis.connection.lettuce.StandaloneConnectionProvider.getConnection(StandaloneConnectionProvider.java:112)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$ExceptionTranslatingConnectionProvider.getConnection(LettuceConnectionFactory.java:1795)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$SharedConnection.getNativeConnection(LettuceConnectionFactory.java:1594)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$SharedConnection.lambda$getConnection$0(LettuceConnectionFactory.java:1574)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory.doInLock(LettuceConnectionFactory.java:1535)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$SharedConnection.getConnection(LettuceConnectionFactory.java:1571)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory.getSharedConnection(LettuceConnectionFactory.java:1257)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory.getConnection(LettuceConnectionFactory.java:1063)
at org.springframework.data.redis.core.RedisConnectionUtils.fetchConnection(RedisConnectionUtils.java:195)
at org.springframework.data.redis.core.RedisConnectionUtils.doGetConnection(RedisConnectionUtils.java:144)
at org.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:105)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:400)
at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:380)
at org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:117)
at org.springframework.data.redis.core.DefaultHashOperations.entries(DefaultHashOperations.java:323)
at org.springframework.session.data.redis.RedisSessionRepository.findById(RedisSessionRepository.java:138)
at org.springframework.session.data.redis.RedisSessionRepository.findById(RedisSessionRepository.java:45)
at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.getRequestedSession(SessionRepositoryFilter.java:352)
at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.getSession(SessionRepositoryFilter.java:286)
at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.getSession(SessionRepositoryFilter.java:193)
at jakarta.servlet.http.HttpServletRequestWrapper.getSession(HttpServletRequestWrapper.java:221)
at org.springframework.security.web.context.HttpSessionSecurityContextRepository.lambda$loadDeferredContext$0(HttpSessionSecurityContextRepository.java:145)
at org.springframework.security.web.context.SupplierDeferredSecurityContext.init(SupplierDeferredSecurityContext.java:67)
at org.springframework.security.web.context.SupplierDeferredSecurityContext.get(SupplierDeferredSecurityContext.java:52)
at org.springframework.security.web.context.SupplierDeferredSecurityContext.get(SupplierDeferredSecurityContext.java:33)
at org.springframework.security.core.context.ThreadLocalSecurityContextHolderStrategy.lambda$setDeferredContext$2(ThreadLocalSecurityContextHolderStrategy.java:67)
at org.springframework.security.core.context.ThreadLocalSecurityContextHolderStrategy.getContext(ThreadLocalSecurityContextHolderStrategy.java:43)
at org.springframework.security.core.context.SecurityContextHolder.getContext(SecurityContextHolder.java:125)
at org.springframework.security.core.context.SecurityContextHolderThreadLocalAccessor.getValue(SecurityContextHolderThreadLocalAccessor.java:46)
at org.springframework.security.core.context.SecurityContextHolderThreadLocalAccessor.getValue(SecurityContextHolderThreadLocalAccessor.java:37)
at io.micrometer.context.DefaultContextSnapshot.clearThreadLocal(DefaultContextSnapshot.java:110)
at io.micrometer.context.DefaultContextSnapshotFactory.setAllThreadLocalsFrom(DefaultContextSnapshotFactory.java:128)
at io.micrometer.context.DefaultContextSnapshotFactory.setThreadLocalsFrom(DefaultContextSnapshotFactory.java:109)
at reactor.core.publisher.ContextPropagation.setThreadLocals(ContextPropagation.java:84)
at reactor.core.publisher.FluxContextWriteRestoringThreadLocals$ContextWriteRestoringThreadLocalsSubscriber.onSubscribe(FluxContextWriteRestoringThreadLocals.java:101)
at io.opentelemetry.javaagent.shaded.instrumentation.reactor.v3_1.TracingSubscriber.onSubscribe(TracingSubscriber.java:61)
at reactor.core.publisher.Operators.reportThrowInSubscribe(Operators.java:226)
... (repeated, reactor.core.publisher.Mono.subscribe(Mono.java:4579) and so on)
To Reproduce Not easily reproducible. My investigation led to the following conclusion:
- It is necessary to have
io.micrometer:context-propagation
in dependencies, we got it when usingmicrometer-tracing
. - Use Lettuce Redis backend to store the web session for the user.
- Have Redis disconnected.
- New user request comes in, web session is set.
- Redis connection is being established.
Expected behavior No StackOverflowError happens.
What happened?
I do not know why the Redis connection was disconnected, possibly by some other handling error. We cannot find this in our traces. Anyway, the stack trace shows the following:
- Redis client tries to connect:
RedisClient.connect
- Mono calls onSubscribe:
FluxContextWriteRestoringThreadLocalsFuseable$FuseableContextWriteRestoringThreadLocalsSubscriber.onSubscribe
- Context propagation takes place:
ContextPropagation.setThreadLocals
io.micrometer:context-propagation
handles the context propagation inDefaultContextSnapshotFactory.setAllThreadLocalsFrom
andDefaultContextSnapshot.clearThreadLocal
.io.micrometer:context-propagation
calls all registeredThreadLocalAccessor
, includingSecurityContextHolderThreadLocalAccessor
.- The accessor's getter
getValue
is called in preparation to be forwarded into the new context. - The actual
SecurityContext
value (not the deferred value) is being retrieved withThreadLocalSecurityContextHolderStrategy.getContext
. - The
SecurityContext
is being created inSupplierDeferredSecurityContext.init
. - Because the session is stored in Redis, the call to
RedisSessionRepository.findById
wants to get a Redis connection. - Redis client tries to connect... Loop repeats.Unfortunately, it is not possible to prevent
SecurityContextHolderThreadLocalAccessor
from being called this way, it is registered in services file), and there is no way to prevent it being registered. So, with this setup the SecurityContext is being created prematurely.
There is a functionality to work with deferred security contexts in SecurityContextHolder
- methods getDeferredContext
and setDeferredContext
. Those methods are not called when the value is transferred into a new Reactor/Mono context. The fix would be the following:
- Fix
setDeferredContext
inThreadLocalSecurityContextHolderStrategy
andInheritableThreadLocalSecurityContextHolderStrategy
to check if the object has been wrapped already to prevent creating a get-wrapper every time thesetDeferredContext
is being made (and a chain of get-get-get-get-get methods for a call tosetDeferredContext(getDeferredContext())
). - Use
getDeferredContext
call inSecurityContextHolderThreadLocalAccessor.getValue()
instead of callinggetContext
and usesetDeferredContext
call (the updated one) inSecurityContextHolderThreadLocalAccessor.setValue()
instead ofsetContext
.
That should prevent premature materialization of the SecurityContext
and would fix the Redis loop.