spring-projects / spring-projects/spring-security

Possible StackOverflowError with io.micrometer:context-propagation and Lettuce Redis backend and Web Session in Redis

Open
#18,059 0 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

in: core type: bug
Dominant language
Java
Stars
9.6k
Forks
6.3k
Avg merge
2d 11h
Merged PRs (30d)
52

Description

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:

  1. It is necessary to have io.micrometer:context-propagation in dependencies, we got it when using micrometer-tracing.
  2. Use Lettuce Redis backend to store the web session for the user.
  3. Have Redis disconnected.
  4. New user request comes in, web session is set.
  5. 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:

  1. Redis client tries to connect: RedisClient.connect
  2. Mono calls onSubscribe: FluxContextWriteRestoringThreadLocalsFuseable$FuseableContextWriteRestoringThreadLocalsSubscriber.onSubscribe
  3. Context propagation takes place: ContextPropagation.setThreadLocals
  4. io.micrometer:context-propagation handles the context propagation in DefaultContextSnapshotFactory.setAllThreadLocalsFrom and DefaultContextSnapshot.clearThreadLocal.
  5. io.micrometer:context-propagation calls all registered ThreadLocalAccessor, including SecurityContextHolderThreadLocalAccessor.
  6. The accessor's getter getValue is called in preparation to be forwarded into the new context.
  7. The actual SecurityContext value (not the deferred value) is being retrieved with ThreadLocalSecurityContextHolderStrategy.getContext.
  8. The SecurityContext is being created in SupplierDeferredSecurityContext.init.
  9. Because the session is stored in Redis, the call to RedisSessionRepository.findById wants to get a Redis connection.
  10. 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:

  1. Fix setDeferredContext in ThreadLocalSecurityContextHolderStrategy and InheritableThreadLocalSecurityContextHolderStrategy to check if the object has been wrapped already to prevent creating a get-wrapper every time the setDeferredContext is being made (and a chain of get-get-get-get-get methods for a call to setDeferredContext(getDeferredContext())).
  2. Use getDeferredContext call in SecurityContextHolderThreadLocalAccessor.getValue() instead of calling getContext and use setDeferredContext call (the updated one) in SecurityContextHolderThreadLocalAccessor.setValue() instead of setContext.

That should prevent premature materialization of the SecurityContext and would fix the Redis loop.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with ThreadLocalSecurityContextHolderStrategy, InheritableThreadLocalSecurityContextHolderStrategy, and SecurityContextHolderThreadLocalAccessor, then inspect the Micrometer ThreadLocalAccessor services registration. Reproduce with a disconnected Redis instance and a new web-session request; done means context propagation no longer recursively triggers Redis session lookup or a StackOverflowError.

Written by the indexing model from the issue text.

Assessment

Tech stack
java, redis, spring
Domain
authentication, databases, security
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
38/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.