redisson: Strange mess with data being read from different keys causing mysterious ClassCastExceptions until application is restarted

Expected behavior Values read from different keys concurrently should be returned to a proper calling thread. I.e. RedissonClient.getBucket("Key_1", new FstCodec()).get() should return value stored under key “Key_1”.

Actual behavior We get sometimes very strange situtations causing the whole process to mix up all values from different caches, causing ClassCastException(s) or deserialization exceptions with values from different types of keys trying to be deserialized or cast to types used by completely different redis keys. Probably it happens after a small networking problem in production when there are some timeouts or slow server responses.

Here is an excerpt from our production logs from a single application instance:

01/11/2021, 09:10:08.024 org.redisson.client.RedisTimeoutException: Command still hasn't been written into connection! Try to increase nettyThreads setting. Payload size in bytes: 0. Node source: NodeSource [slot=null, addr=null, redisClient=null, redirect=null, entry=MasterSlaveEntry [masterEntry=[freeSubscribeConnectionsAmount=0, freeSubscribeConnectionsCounter=value:49:queue:0, freeConnectionsAmount=87, freeConnectionsCounter=value:53611606:queue:0, freezeReason=null, client=[addr=redis://10.20.1.136:6379], nodeType=MASTER, firstFail=0]]], connection: RedisConnection@604648282 [redisClient=[addr=redis://10.20.1.136:6379], channel=[id: 0xa32106a8, L:/10.20.1.81:44254 - R:10.20.1.136/10.20.1.136:6379], currentCommand=null], command: null, params: null after 3 retry attempts
01/11/2021, 09:10:08.029 org.redisson.client.RedisTimeoutException: Command still hasn't been written into connection! Try to increase nettyThreads setting. Payload size in bytes: 0. Node source: NodeSource [slot=null, addr=null, redisClient=null, redirect=null, entry=MasterSlaveEntry [masterEntry=[freeSubscribeConnectionsAmount=0, freeSubscribeConnectionsCounter=value:49:queue:0, freeConnectionsAmount=88, freeConnectionsCounter=value:53611608:queue:0, freezeReason=null, client=[addr=redis://10.20.1.136:6379], nodeType=MASTER, firstFail=0]]], connection: RedisConnection@1143058814 [redisClient=[addr=redis://10.20.1.136:6379], channel=[id: 0xbb0da068, L:/10.20.1.81:35820 - R:10.20.1.136/10.20.1.136:6379], currentCommand=null], command: null, params: null after 3 retry attempts
01/11/2021, 09:10:08.180 org.redisson.client.RedisTimeoutException: Command still hasn't been written into connection! Try to increase nettyThreads setting. Payload size in bytes: 0. Node source: NodeSource [slot=null, addr=null, redisClient=null, redirect=null, entry=MasterSlaveEntry [masterEntry=[freeSubscribeConnectionsAmount=0, freeSubscribeConnectionsCounter=value:49:queue:0, freeConnectionsAmount=89, freeConnectionsCounter=value:53611619:queue:0, freezeReason=null, client=[addr=redis://10.20.1.136:6379], nodeType=MASTER, firstFail=0]]], connection: RedisConnection@693236936 [redisClient=[addr=redis://10.20.1.136:6379], channel=[id: 0x232f153c, L:/10.20.1.81:55238 - R:10.20.1.136/10.20.1.136:6379], currentCommand=CommandData [promise=RedissonPromise [promise=ImmediateEventExecutor$ImmediatePromise@2aaa204f(success: [com.xxx.models.customer.CustomerBaseReport@5f4f56a3, com.xxx.models.customer.CustomerBaseReport@16acb675, <<2.7MB omitted>>, com.xxx.models.customer.CustomerBaseReport@5a6a800f])], command=(GET), params=[cache:ip-check-tool-cache-v3:2131228], codec=org.redisson.codec.FstCodec]], command: null, params: null after 3 retry attempts

01/11/2021, 09:10:10.780 org.redisson.client.handler.ErrorsLoggingHandler	Exception occured. Channel: [id: 0x8908f806, L:/10.20.1.81:55192 - R:10.20.1.136/10.20.1.136:6379]
io.netty.handler.codec.DecoderException: com.fasterxml.jackson.core.JsonParseException: Illegal character ((CTRL-CHAR, code 1)): only regular white space (\r, \n, \t) is allowed between tokens
 at [Source: (io.netty.buffer.ByteBufInputStream); line: 1, column: 2]
	at io.netty.handler.codec.ReplayingDecoder.callDecode(ReplayingDecoder.java:421) ~[netty-codec-4.1.66.Final.jar:4.1.66.Final]
Caused by: com.fasterxml.jackson.core.JsonParseException: Illegal character ((CTRL-CHAR, code 1)): only regular white space (\r, \n, \t) is allowed between tokens
 at [Source: (io.netty.buffer.ByteBufInputStream); line: 1, column: 2]
	at com.fasterxml.jackson.core.JsonParser._constructError(JsonParser.java:1804) ~[jackson-core-2.9.9.jar:2.9.9]

01/11/2021, 09:10:16.421 java.lang.RuntimeException: Failed to get customer by id 4094937
Caused by: java.lang.ClassCastException: class java.lang.Long cannot be cast to class com.xxx.customers.CustomerInfo (java.lang.Long is in module java.base of loader 'bootstrap'; com.xxx.customers.CustomerInfo is in unnamed module of loader org.apache.catalina.loader.ParallelWebappClassLoader @7fe8c7db)
01/11/2021, 09:10:16.920 org.redisson.client.RedisException: Unexpected exception while processing command
	at org.redisson.command.CommandAsyncService.convertException(CommandAsyncService.java:324) ~[redisson-3.16.1.jar:3.16.1]
	at org.redisson.command.CommandAsyncService.get(CommandAsyncService.java:121) ~[redisson-3.16.1.jar:3.16.1]
	at org.redisson.RedissonObject.get(RedissonObject.java:82) ~[redisson-3.16.1.jar:3.16.1]
	at org.redisson.RedissonLock.tryAcquire(RedissonLock.java:143) ~[redisson-3.16.1.jar:3.16.1]
	at org.redisson.RedissonLock.tryLock(RedissonLock.java:223) ~[redisson-3.16.1.jar:3.16.1]
Caused by: java.lang.NumberFormatException: For input string: "
$com.xxx.customers.CustomerInfo
��cs03_domain_skin
7com.xxx.additionalinfo.AdditionalInfoBase$ASValue�
�,�
1�cs03_affiliated_as_partner_date����,� (the rest is truncated)"
	at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65) ~[?:?]
	at java.lang.Long.parseLong(Long.java:678) ~[?:?]
	at java.lang.Long.valueOf(Long.java:1144) ~[?:?]
	at org.redisson.client.codec.LongCodec$1.decode(LongCodec.java:38) ~[redisson-3.16.1.jar:3.16.1]
	at org.redisson.client.handler.CommandDecoder.decode(CommandDecoder.java:366) ~[redisson-3.16.1.jar:3.16.1]

01/11/2021, 09:10:18.120 redisson-netty-5-18	WARN	io.netty.util.concurrent.DefaultPromise	An exception was thrown by org.redisson.misc.RedissonPromise$$Lambda$269/0x00000008405b2440.operationComplete()
java.lang.ClassCastException: class java.lang.String cannot be cast to class java.lang.Long (java.lang.String and java.lang.Long are in module java.base of loader 'bootstrap')
	at org.redisson.misc.RedissonPromise.lambda$onComplete$0(RedissonPromise.java:187) ~[redisson-3.16.1.jar:3.16.1]
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:605) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at org.redisson.misc.RedissonPromise.trySuccess(RedissonPromise.java:82) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.RedissonBaseLock.lambda$evalWriteAsync$0(RedissonBaseLock.java:226) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.misc.RedissonPromise.lambda$onComplete$0(RedissonPromise.java:187) [redisson-3.16.1.jar:3.16.1]
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:605) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at org.redisson.misc.RedissonPromise.trySuccess(RedissonPromise.java:82) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.command.CommandBatchService.lambda$executeAsync$7(CommandBatchService.java:335) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.misc.RedissonPromise.lambda$onComplete$0(RedissonPromise.java:187) [redisson-3.16.1.jar:3.16.1]
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:605) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at org.redisson.misc.RedissonPromise.trySuccess(RedissonPromise.java:82) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.command.RedisCommonBatchExecutor.handleResult(RedisCommonBatchExecutor.java:130) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.command.RedisExecutor.checkAttemptPromise(RedisExecutor.java:449) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.command.RedisExecutor.lambda$execute$3(RedisExecutor.java:169) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.misc.RedissonPromise.lambda$onComplete$0(RedissonPromise.java:187) [redisson-3.16.1.jar:3.16.1]
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:605) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at org.redisson.misc.RedissonPromise.trySuccess(RedissonPromise.java:82) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.client.handler.CommandDecoder.decodeCommandBatch(CommandDecoder.java:301) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.client.handler.CommandDecoder.decodeCommand(CommandDecoder.java:194) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.client.handler.CommandDecoder.decode(CommandDecoder.java:122) [redisson-3.16.1.jar:3.16.1]
	at org.redisson.client.handler.CommandDecoder.decode(CommandDecoder.java:107) [redisson-3.16.1.jar:3.16.1]
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) [netty-codec-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.handler.codec.ReplayingDecoder.callDecode(ReplayingDecoder.java:366) [netty-codec-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) [netty-codec-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [netty-transport-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.66.Final.jar:4.1.66.Final]
	at java.lang.Thread.run(Thread.java:834) [?:?]
01/11/2021, 09:10:18.120 java.lang.ClassCastException: class java.lang.String cannot be cast to class java.lang.Long (java.lang.String and java.lang.Long are in module java.base of loader 'bootstrap')
	at org.redisson.RedissonLock.tryAcquire(RedissonLock.java:143) ~[redisson-3.16.1.jar:3.16.1]
	at org.redisson.RedissonLock.tryLock(RedissonLock.java:223) ~[redisson-3.16.1.jar:3.16.1]

It looks like it has read Long value from a key that is used for RedissonLock objects instead of com.xxx.customers.CustomerInfo at 01/11/2021, 09:10:16.421, and then later at 01/11/2021, 09:10:18.120 tried to cast String read from com.xxx.customers.CustomerInfo key (which is actually a FstCodec encoded binary object) cast to Long used by RedissonLock.

And if such thing happens, then we continue getting such strange errors for other keys/locks until we restart the JVM.

Steps to reproduce or test case Don’t know, it happens too randomly and not so frequently, but if it happens, it causes random errors in production causing problems to our customers.

Redis version 6.2.4

Redisson version 3.16.1

Redisson configuration

        Config config = new Config().setCodec(new SerializationCodec());
	            config.useSentinelServers()
	                    .setRetryInterval(settings.getRetryInterval())
	                    .setRetryAttempts(settings.getRetryAttempts())
                        .setTimeout(settings.getTimeout())
	                    .setTcpNoDelay(true)
	                    .setPassword(settings.getPassword())
	                    .addSentinelAddress(settings.getSentinelHosts())
	                    .setDatabase(settings.getDatabase())
	                    .setMasterName(settings.getSentinelMaster())
                        .setReadMode(ReadMode.MASTER);
        return new Config(config);