Spring-session: ERR no such key when RedisOperationsSessionRepository.saveChangeSessionId called

[wangzw]

Hi all

I got the following exception and seems the session is already gone before rename. Should we ignore such exception?

Version: spring-session-data-redis-2.1.2.RELEASE

I guess that #1137 d3134ad065af9e8bf10906c6e82710236be3691d did not fix all issues.

org.springframework.data.redis.RedisSystemException: Error in execution; nested exception is io.lettuce.core.RedisCommandExecutionException: ERR no such key
    at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:54) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:52) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:268) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.connection.lettuce.LettuceKeyCommands.convertLettuceAccessException(LettuceKeyCommands.java:817) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.connection.lettuce.LettuceKeyCommands.rename(LettuceKeyCommands.java:325) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.connection.DefaultedRedisConnection.rename(DefaultedRedisConnection.java:118) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.core.RedisTemplate.lambda$rename$16(RedisTemplate.java:932) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:224) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:184) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.data.redis.core.RedisTemplate.rename(RedisTemplate.java:931) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
    at org.springframework.session.data.redis.RedisOperationsSessionRepository$RedisSession.saveChangeSessionId(RedisOperationsSessionRepository.java:867) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.springframework.session.data.redis.RedisOperationsSessionRepository$RedisSession.saveDelta(RedisOperationsSessionRepository.java:826) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.springframework.session.data.redis.RedisOperationsSessionRepository$RedisSession.access$000(RedisOperationsSessionRepository.java:703) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.springframework.session.data.redis.RedisOperationsSessionRepository.save(RedisOperationsSessionRepository.java:421) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.springframework.session.data.redis.RedisOperationsSessionRepository.save(RedisOperationsSessionRepository.java:247) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(SessionRepositoryFilter.java:240) ~[spring-session-core-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter.java:201) ~[spring-session-core-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:154) ~[spring-session-core-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:81) ~[spring-session-core-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:117) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
    at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:106) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:490) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:791) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1417) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_191]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_191]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_191]
Caused by: io.lettuce.core.RedisCommandExecutionException: ERR no such key
    at io.lettuce.core.ExceptionFactory.createExecutionException(ExceptionFactory.java:135) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
    at io.lettuce.core.ExceptionFactory.createExecutionException(ExceptionFactory.java:108) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
    at io.lettuce.core.protocol.AsyncCommand.completeResult(AsyncCommand.java:120) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
    at io.lettuce.core.protocol.AsyncCommand.complete(AsyncCommand.java:111) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
    at io.lettuce.core.protocol.CommandWrapper.complete(CommandWrapper.java:59) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
    at io.lettuce.core.protocol.CommandHandler.complete(CommandHandler.java:646) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
    at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:604) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
    at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:556) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:648) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:583) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:500) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:462) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) ~[netty-common-4.1.31.Final.jar!/:4.1.31.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.31.Final.jar!/:4.1.31.Final]
    ... 1 common frames omitted

[vpavic]

Thanks for the report @wangzw - can you describe how to reproduce this? A minimal sample would be the most helpful.

[wangzw]

It is hard to reproduce since it happened on our online production. Customer reported a 500 error and from the logs, we found above exception.

From #1137 , there are two rename operations and only one ignore "ERR no such key" exception. Is it intentional？The exception we got was thrown from the other one, just as I commented in d3134ad065af9e8bf10906c6e82710236be3691d.

[vpavic]

Thanks for following up. Yes, at the time it was intentional to only handle _ERR no such key_ for expiration key. However, the session key itself should be there 5 minutes after the session was deleted (see reference manual section on handling expirations) so this truly looks like an exceptional situation.

Therefore I think it's important to understand under which circumstances the error occurs.

[wangzw]

Thanks for your feedback, I'm currently working on the investigation. The session is definitely not expired in 5 minutes. It happened just after I login.

It is a restful api, and I set session policy to SessionCreationPolicy.STATELESS. I do not know if it is related.

[wangzw]

If SessionCreationPolicy.STATELESS is set in HttpSecurity, session will be eagerly destroyed and "rename" will throw "ERR no such key".

That is the case we should catch when rename a session.

Temporary workaround is to change session policy to NEVER.

[wangzw]

@vpavic What is your opinion to fix this issue?

[vpavic]

It's still not clear to me how to reproduce the problem @wangzw. Can you provide a minimal sample application that reproduces the problem? It's unclear to me what's your use case with Spring Session and SessionCreationPolicy.STATELESS.

[wangzw]

I have a project to manage user account, it handle user authentication with spring-security (endpoint /login), user authorization with oauth2 (endpoint /token)and several restful API to do user management such as add/delete user (endpoint /users).

The project should support HA some two instances is running at the same time. So I use redis based distributed session for spring-security to handle login process.

User management API is restful, so it is configured as SessionCreationPolicy.STATELESS.

I do not know if there is a simply way to reproduce this issue. From my investigation, there is a race condition between session clean and session rename if SessionCreationPolicy.STATELESS is set.

In the previous comments you mentioned that the session key itself should be there 5 minutes after the session was deleted, but it is not true from my investigation.

[vpavic]

In the previous comments you mentioned that the session key itself should be there 5 minutes after the session was deleted, but it is not true from my investigation.

Since I've been unable to reproduce this, I'm afraid we really need a sample app to be able to move forward with this.

[wanwaner]

@wangzw
add HttpSecurity Config code:
http.sessionManagement().sessionFixation().none();

[vpavic]

Closing due to lack of feedback. Please comment back if you can provide more details and we can re-open the issue.

[dai0304]

We have the same issue but I have no reproduce scenario.
Perhaps this problem is related with race condition and occurred only in heavily loaded environment.

IMHO, this part is a cause of this problem.

https://github.com/spring-projects/spring-session/blob/c5fc4b57ad2eb369564927e4fd13850c0f5a94f2/spring-session-data-redis/src/main/java/org/springframework/session/data/redis/RedisOperationsSessionRepository.java#L865-L874

When I deployed the following patch here in our environment, we did not see this problem.

String originalSessionIdKey = getSessionKey(this.originalSessionId);
String sessionIdKey = getSessionKey(sessionId);
try {
    RedisOperationsSessionRepository.this.sessionRedisOperations.rename(
            originalSessionIdKey, sessionIdKey);
    String originalExpiredKey = getExpiredKey(this.originalSessionId);
    String expiredKey = getExpiredKey(sessionId);
    RedisOperationsSessionRepository.this.sessionRedisOperations.rename(
            originalExpiredKey, expiredKey);
}

[vpavic]

Thanks for following up @dai0304 - can you share the info about your Spring Session version, and also any Spring Session and Spring Security related configuration details?

@wangzw, if you could share configuration details as well, that would be useful.

[dai0304]

We use spring-session-core and spring-session-data-redis v2.1.1.RELEASE.
Our application configuration is too complex, so I am not confident that it conveys all necessary information to you.

@Configuration
@EnableRedisHttpSession
public class AppSessionConfiguration {

  @Bean
  public static ConfigureRedisAction configureRedisAction() {
    // https://github.com/spring-projects/spring-session/issues/124
    return ConfigureRedisAction.NO_OP;
  }
}

@Configuration
@EnableResourceServer
public class AppOAuth2ResourceServerConfiguration extends ResourceServerConfigurerAdapter {

  // ...

  @Override
  public void configure(HttpSecurity http) throws Exception {
    // ...
    http.requestMatcher(API_ENDPOINT_MATCHER);
    http.sessionManagement()
        .sessionCreationPolicy(SessionCreationPolicy.STATELESS);
    // ...
  }
}

@Configuration
@EnableAuthorizationServer
public class AppOAuth2AuthorizationServerConfiguration extends AuthorizationServerConfigurerAdapter {

  // ...

}

@Configuration
@EnableWebSecurity
public class AppWebSecurityConfiguration extends WebSecurityConfigurerAdapter {

  // ...

  @Override
  protected void configure(HttpSecurity http) throws Exception {
    // ...
    http.requestMatcher(UI_ENDPOINT_MATCHER);
    http.sessionManagement()
        .sessionCreationPolicy(SessionCreationPolicy.IF_REQUIRED);
    // ...
  }
}

And we only see this problem when a client access to OAuth2 token endpoint (POST /oauth/token).

The token endpoint should be irrelevant to the session, and no session cookie has been issued. So it is incomprehensible...

[ilya40umov]

I'm also seeing this error in the logs:
org.springframework.data.redis.RedisSystemException: Error in execution; nested exception is io.lettuce.core.RedisCommandExecutionException: ERR no such key
and I also have OAuth2 set-up.
You can find all of the source code here: https://github.com/ilya40umov/KotLink

[veereshwaran]

Hi @vpavic ,
By referring #1311, You are correct, the browser sends concurrent requests to the application, In the new spring-session, it is changing the session id, but in older version new session is created instead of changing session id and the previous session kept. So we didn't face this issue in older spring-session version. After spring-session upgrade, we are facing this issue

[vpavic]

Yes @veereshwaran, the native support for changeSessionId was added in Spring Session 2.0 via #835.

[veereshwaran]

@vpavic But if I switch to In-memory session, I didn't see any this kind of issue

[vpavic]

This particular report is for Redis store so that's not really relevant here. Besides, in-memory session stores are not intended for production use but rather are offered as testing/convenience solution, as they don't offer session clustering which is the core benefit of Spring Session.

[veereshwaran]

Ok @vpavic

Is there any idea to fix this #1270 or shall I handle this exception in our application?

Because our customer facing this issue when using they are using our application.

[vpavic]

I've classified this as bug (see labels), so we'll try to do something about it.

[vpavic]

Knowing the issue was due to a concurrent requests attempting to change session id, putting together a unit test that reproduces the problem wasn't difficult - I've added handling for ERR no such key in the affected place. Thanks for the patience - we'll also backport this to 2.0.10.RELEASE.

[veereshwaran]

Hi @vpavic, here you handling that exception,

but when I run my sample application(https://github.com/veereshwaran/sso-server) with your new changes, By clicking refresh button it shows login page randomly.

[vpavic]

As explained, the actual root of the problem is that the application makes concurrent requests attempting to change session id. What we did here was simply to prevent the ERR no such key from blowing up things but rather handle the situation more gracefully.

We simply cannot do anything to prevent the concurrent requests attempt to change the session id, that's something that needs to be handled at application level.