NPE in RedisStateMachine

[nikolayk812]

Hello.

I have a lot of warnings like in my production. Lettuce 4.3.3 is used.

I have one connection for set/get and atomic get and delete using Lua script (not Tx anymore). And another connection is for expiration notificaitons.

However this exception happens completely inside Lettuce.

23-07 21:29:59.971 WARN  [lettuce-nioEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0x32a9d0ae, / -> /:6379, chid=0x1] Unexpected exception during request: java.lang.NullPointerException
java.lang.NullPointerException: null
	at com.lambdaworks.redis.protocol.RedisStateMachine.safeSet(RedisStateMachine.java:414)
	at com.lambdaworks.redis.protocol.RedisStateMachine.decode(RedisStateMachine.java:215)
	at com.lambdaworks.redis.protocol.RedisStateMachine.decode(RedisStateMachine.java:115)
	at com.lambdaworks.redis.pubsub.PubSubCommandHandler.decode(PubSubCommandHandler.java:74)
	at com.lambdaworks.redis.protocol.CommandHandler.channelRead(CommandHandler.java:200)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	at java.lang.Thread.run(Thread.java:748)

In RedisStateMachine.java:115 null is passed intentionally and then NPE happens.
return decode(buffer, null, output);

Another issue is

com.lambdaworks.redis.RedisException: Invalid first byte: 100
	at com.lambdaworks.redis.protocol.RedisStateMachine.readReplyType(RedisStateMachine.java:272)
	at com.lambdaworks.redis.protocol.RedisStateMachine.decode(RedisStateMachine.java:151)
	at com.lambdaworks.redis.protocol.RedisStateMachine.decode(RedisStateMachine.java:115)
	at com.lambdaworks.redis.pubsub.PubSubCommandHandler.decode(PubSubCommandHandler.java:64)
	at com.lambdaworks.redis.protocol.CommandHandler.channelRead(CommandHandler.java:200)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	at java.lang.Thread.run(Thread.java:748)

I am not sure if they are related or not.

[mp911de]

Looks like the output you choose for your Lua runs into an error. PubSubCommandHandler uses the wrong method, that's why you see an NPE in the first place. The second stack trace is caused is a symptom of the first one because the protocol stack got out of sync.

Can you provide a minimal reproducible test case for the first error?

[nikolayk812]

This is my API usage pattern
https://github.com/nikolayspb/lettucedemo
though I cannot reproduce it locally.
I use setex, get, Lua script, pubsub and ping.

In production I use sentinel configuration, btw.
https://github.com/nikolayspb/lettucedemo/blob/master/src/main/java/com/lettuce/demo/SomeValueRedisRepo.java
https://github.com/nikolayspb/lettucedemo/blob/master/src/main/java/com/lettuce/demo/SimulationRunner.java

I see you made some commits, can I try as snapshot?

[mp911de]

Sure, you can get the snapshots from oss.sonatype.org, see https://github.com/lettuce-io/lettuce-core#binariesdownload.

The changes prevent a NPE caused by a null command although the command should be present. This change should reveal the real cause.

I took a cursory look on your code. There's nothing really wrong with it. You can raise the log level for com.lambdaworks.redis.protocol to DEBUG to get more details on the payload and to see where the actual errors happen.

[nikolayk812]

Now I get exceptions much less frequently. And they gone after reconnetion.
I attach logs with some offset. IP addresses are renamed.

25-07 15:35:42.624 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.625 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:35:42.625 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 1 commands
25-07 15:35:42.625 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.625 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.636 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.636 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() done
25-07 15:35:42.636 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.637 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.637 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:35:42.637 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 1 commands
25-07 15:35:42.637 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.637 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.640 DEBUG [qtp164757726-106] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.640 DEBUG [qtp164757726-106] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() done
25-07 15:35:42.640 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.640 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.641 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:35:42.641 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 1 commands
25-07 15:35:42.641 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.641 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.656 DEBUG [healthChecker-1] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] write() writeAndFlush command AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.656 DEBUG [healthChecker-1] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] write() done
25-07 15:35:42.657 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] write(ctx, AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.657 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandEncoder - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.658 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] Received: 20 bytes, 1 commands in the stack
25-07 15:35:42.658 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] Stack contains: 1 commands
25-07 15:35:42.658 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.658 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] Storing exception in AsyncCommand [type=PING, output=StatusOutput [output=1
s, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.659 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] Storing exception in connectionError
25-07 15:35:42.659 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] Unexpected exception during request: com.lambdaworks.redis.RedisException: Invalid first byte: 116
com.lambdaworks.redis.RedisException: Invalid first byte: 116
	at com.lambdaworks.redis.protocol.RedisStateMachine.readReplyType(RedisStateMachine.java:289)
	at com.lambdaworks.redis.protocol.RedisStateMachine.decode(RedisStateMachine.java:169)
	at com.lambdaworks.redis.protocol.CommandHandler.decode(CommandHandler.java:313)
	at com.lambdaworks.redis.protocol.CommandHandler.decode(CommandHandler.java:257)
	at com.lambdaworks.redis.pubsub.PubSubCommandHandler.decode(PubSubCommandHandler.java:60)
	at com.lambdaworks.redis.protocol.CommandHandler.channelRead(CommandHandler.java:241)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)
	at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:934)
	at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:397)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:302)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	at java.lang.Thread.run(Thread.java:748)
25-07 15:35:42.659 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] channelInactive()
25-07 15:35:42.659 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] deactivating channel handler
25-07 15:35:42.659 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] rebuildQueue 0 command(s) added to buffer
25-07 15:35:42.659 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] channelInactive() done
25-07 15:35:42.659 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - [channel=0xda5d3b84, /127.0.0.1:47264 -> 127.0.0.3/127.0.0.3:6379, last known addr=127.0.0.3/127.0.0.3:6379] channelInactive(io.netty.channel.DefaultChannelHandlerContext@7ded6a6e)
25-07 15:35:42.662 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - [channel=0xda5d3b84, /127.0.0.1:47264 -> 127.0.0.3/127.0.0.3:6379, last known addr=127.0.0.3/127.0.0.3:6379] scheduleReconnect()
25-07 15:35:42.662 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - Reconnect attempt 1, delay 1ms
25-07 15:35:42.662 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] channelUnregistered()
25-07 15:35:42.662 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.662 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() done
25-07 15:35:42.662 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.662 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.662 ERROR [Thread-333] o.i.d.r.RedisCachedStatusProvider - Redis is down
com.lambdaworks.redis.RedisException: Invalid first byte: 116
	at com.lambdaworks.redis.protocol.RedisStateMachine.readReplyType(RedisStateMachine.java:289)
	at com.lambdaworks.redis.protocol.RedisStateMachine.decode(RedisStateMachine.java:169)
	at com.lambdaworks.redis.protocol.CommandHandler.decode(CommandHandler.java:313)
	at com.lambdaworks.redis.protocol.CommandHandler.decode(CommandHandler.java:257)
	at com.lambdaworks.redis.pubsub.PubSubCommandHandler.decode(PubSubCommandHandler.java:60)
	at com.lambdaworks.redis.protocol.CommandHandler.channelRead(CommandHandler.java:241)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)
	at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:934)
	at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:397)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:302)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	at java.lang.Thread.run(Thread.java:748)
25-07 15:35:42.663 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:35:42.663 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 1 commands
25-07 15:35:42.663 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.663 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.682 DEBUG [qtp164757726-106] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.682 DEBUG [qtp164757726-106] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() done
25-07 15:35:42.682 DEBUG [qtp164757726-106] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.682 DEBUG [qtp164757726-106] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() done
25-07 15:35:42.682 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.682 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.682 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.682 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.683 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 2 commands in the stack
25-07 15:35:42.683 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 2 commands
25-07 15:35:42.683 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.683 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.683 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:35:42.683 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 1 commands
25-07 15:35:42.683 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.683 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.699 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.699 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() done
25-07 15:35:42.699 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.699 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.700 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:35:42.700 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 1 commands
25-07 15:35:42.700 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.700 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.756 INFO  [lettuce-eventExecutorLoop-7-3] c.l.r.protocol.ConnectionWatchdog - Reconnecting, last destination was 127.0.0.3/127.0.0.3:6379
25-07 15:35:42.758 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, [id: 0x4f86502c] (inactive), chid=0x6] channelRegistered()
25-07 15:35:42.759 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.759 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() done
25-07 15:35:42.759 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.759 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write() done
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] channelActive()
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] rebuildQueue 0 command(s) added to buffer
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] activateCommandHandlerAndExecuteBufferedCommands 0 command(s) buffered
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] activating channel handler
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] flushCommands()
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.r.protocol.ConnectionWatchdog - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, last known addr=127.0.0.2/127.0.0.2:26379] channelActive(io.netty.channel.DefaultChannelHandlerContext@4b88a7bc)
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] channelActive() done
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.759 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.r.protocol.ConnectionWatchdog - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, last known addr=127.0.0.2/127.0.0.2:26379] userEventTriggered(io.netty.channel.DefaultChannelHandlerContext@4b88a7bc, com.lambdaworks.redis.ConnectionEvents$Activated@33dca24)
25-07 15:35:42.760 DEBUG [lettuce-eventExecutorLoop-7-3] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] write() writeAndFlush command AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[], error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.760 DEBUG [lettuce-eventExecutorLoop-7-3] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] write() done
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 2 commands in the stack
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 2 commands
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] write(ctx, AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[], error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379] writing command AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[], error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.3/127.0.0.3:6379, chid=0x3] Stack contains: 1 commands
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] Received: 34 bytes, 1 commands in the stack
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] Stack contains: 1 commands
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[], error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.760 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[127.0.0.3, 6379], error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:35:42.761 DEBUG [lettuce-eventExecutorLoop-7-3] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] close()
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.r.protocol.ConnectionWatchdog - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, last known addr=127.0.0.2/127.0.0.2:26379] userEventTriggered(io.netty.channel.DefaultChannelHandlerContext@4b88a7bc, com.lambdaworks.redis.ConnectionEvents$PrepareClose@322aefaa)
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.r.protocol.ConnectionWatchdog - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, last known addr=127.0.0.2/127.0.0.2:26379] userEventTriggered(io.netty.channel.DefaultChannelHandlerContext@4b88a7bc, com.lambdaworks.redis.ConnectionEvents$Close@42cfa241)
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] channelInactive()
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] deactivating channel handler
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] rebuildQueue 0 command(s) added to buffer
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] channelInactive() done
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.r.protocol.ConnectionWatchdog - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, last known addr=127.0.0.2/127.0.0.2:26379] channelInactive(io.netty.channel.DefaultChannelHandlerContext@4b88a7bc)
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.r.protocol.ConnectionWatchdog - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, last known addr=127.0.0.2/127.0.0.2:26379] Reconnect scheduling disabled
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x4f86502c, /127.0.0.1:55368 -> 127.0.0.2/127.0.0.2:26379, chid=0x6] channelUnregistered()
25-07 15:35:42.761 DEBUG [lettuce-eventExecutorLoop-7-3] c.l.r.protocol.ReconnectionHandler - Reconnecting to Redis at /127.0.0.3:6379
25-07 15:35:42.761 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, [id: 0xb9542fee] (inactive), chid=0x1] channelRegistered()
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] channelActive()
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] rebuildQueue 0 command(s) added to buffer
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] activateCommandHandlerAndExecuteBufferedCommands 0 command(s) buffered
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] activating channel handler
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] write() writeAndFlush command AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] write(ctx, AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandEncoder - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379] writing command AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] write() done
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] flushCommands()
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.r.protocol.ConnectionWatchdog - [channel=0xda5d3b84, /127.0.0.1:47264 -> 127.0.0.3/127.0.0.3:6379, last known addr=127.0.0.3/127.0.0.3:6379] channelActive(io.netty.channel.DefaultChannelHandlerContext@4b84fe6f)
25-07 15:35:42.762 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] channelActive() done

[nikolayk812]

Another digit

25-07 15:55:45.150 DEBUG [qtp164757726-104] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.150 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.150 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.151 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:55:45.151 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Stack contains: 1 commands
25-07 15:55:45.151 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.151 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.183 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.183 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.183 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.183 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.184 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:55:45.184 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Stack contains: 1 commands
25-07 15:55:45.184 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.184 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.186 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.186 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.186 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.187 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.187 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:55:45.187 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Stack contains: 1 commands
25-07 15:55:45.187 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.187 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.188 DEBUG [healthChecker-1] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] write() writeAndFlush command AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.189 DEBUG [healthChecker-1] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] write() done
25-07 15:55:45.189 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] write(ctx, AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.189 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandEncoder - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.189 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] Received: 20 bytes, 1 commands in the stack
25-07 15:55:45.190 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] Stack contains: 1 commands
25-07 15:55:45.190 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.190 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] Storing exception in AsyncCommand [type=PING, output=StatusOutput [output=texp, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] Storing exception in connectionError
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] Unexpected exception during request: com.lambdaworks.redis.RedisException: Invalid first byte: 49
com.lambdaworks.redis.RedisException: Invalid first byte: 49
	at com.lambdaworks.redis.protocol.RedisStateMachine.readReplyType(RedisStateMachine.java:289)
	at com.lambdaworks.redis.protocol.RedisStateMachine.decode(RedisStateMachine.java:169)
	at com.lambdaworks.redis.protocol.CommandHandler.decode(CommandHandler.java:313)
	at com.lambdaworks.redis.protocol.CommandHandler.decode(CommandHandler.java:257)
	at com.lambdaworks.redis.pubsub.PubSubCommandHandler.decode(PubSubCommandHandler.java:60)
	at com.lambdaworks.redis.protocol.CommandHandler.channelRead(CommandHandler.java:241)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)
	at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:934)
	at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:397)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:302)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	at java.lang.Thread.run(Thread.java:748)
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] channelInactive()
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] deactivating channel handler
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] rebuildQueue 0 command(s) added to buffer
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] channelInactive() done
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.r.protocol.ConnectionWatchdog - [channel=0xda5d3b84, /127.0.0.1:47264 -> 127.0.0.2/127.0.0.2:6379, last known addr=127.0.0.2/127.0.0.2:6379] channelInactive(io.netty.channel.DefaultChannelHandlerContext@4b84fe6f)
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.r.protocol.ConnectionWatchdog - [channel=0xda5d3b84, /127.0.0.1:47264 -> 127.0.0.2/127.0.0.2:6379, last known addr=127.0.0.2/127.0.0.2:6379] scheduleReconnect()
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.r.protocol.ConnectionWatchdog - Reconnect attempt 1, delay 1ms
25-07 15:55:45.191 DEBUG [lettuce-epollEventLoop-10-2] c.l.redis.protocol.CommandHandler - [channel=0xb9542fee, /127.0.0.1:33574 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] channelUnregistered()
25-07 15:55:45.191 ERROR [Thread-811] o.i.d.r.RedisCachedStatusProvider - Redis is down
com.lambdaworks.redis.RedisException: Invalid first byte: 49
	at com.lambdaworks.redis.protocol.RedisStateMachine.readReplyType(RedisStateMachine.java:289)
	at com.lambdaworks.redis.protocol.RedisStateMachine.decode(RedisStateMachine.java:169)
	at com.lambdaworks.redis.protocol.CommandHandler.decode(CommandHandler.java:313)
	at com.lambdaworks.redis.protocol.CommandHandler.decode(CommandHandler.java:257)
	at com.lambdaworks.redis.pubsub.PubSubCommandHandler.decode(PubSubCommandHandler.java:60)
	at com.lambdaworks.redis.protocol.CommandHandler.channelRead(CommandHandler.java:241)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:335)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1294)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:356)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:342)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:911)
	at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:934)
	at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:397)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:302)
	at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131)
	at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
	at java.lang.Thread.run(Thread.java:748)
25-07 15:55:45.212 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.212 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.212 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.212 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.213 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:55:45.213 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Stack contains: 1 commands
25-07 15:55:45.213 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.213 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.231 DEBUG [qtp164757726-106] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.231 DEBUG [qtp164757726-106] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.231 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.231 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.231 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:55:45.231 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Stack contains: 1 commands
25-07 15:55:45.231 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.231 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.247 DEBUG [qtp164757726-105] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.247 DEBUG [qtp164757726-105] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.247 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.247 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.248 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:55:45.248 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Stack contains: 1 commands
25-07 15:55:45.248 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.248 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.251 DEBUG [qtp164757726-104] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.251 DEBUG [qtp164757726-104] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.251 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.251 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.251 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.251 DEBUG [pool-10-thread-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.251 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:55:45.251 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Stack contains: 1 commands
25-07 15:55:45.251 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.251 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.251 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write(ctx, AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.251 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.252 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Received: 5 bytes, 1 commands in the stack
25-07 15:55:45.252 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] Stack contains: 1 commands
25-07 15:55:45.252 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.252 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.256 INFO  [lettuce-eventExecutorLoop-7-1] c.l.r.protocol.ConnectionWatchdog - Reconnecting, last destination was 127.0.0.2/127.0.0.2:6379
25-07 15:55:45.258 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, [id: 0xd7de49db] (inactive), chid=0x7] channelRegistered()
25-07 15:55:45.263 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] channelActive()
25-07 15:55:45.263 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] rebuildQueue 0 command(s) added to buffer
25-07 15:55:45.263 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] activateCommandHandlerAndExecuteBufferedCommands 0 command(s) buffered
25-07 15:55:45.263 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] activating channel handler
25-07 15:55:45.263 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] flushCommands()
25-07 15:55:45.263 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, last known addr=127.0.0.3/127.0.0.3:26379] channelActive(io.netty.channel.DefaultChannelHandlerContext@372547e8)
25-07 15:55:45.263 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] channelActive() done
25-07 15:55:45.263 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, last known addr=127.0.0.3/127.0.0.3:26379] userEventTriggered(io.netty.channel.DefaultChannelHandlerContext@372547e8, com.lambdaworks.redis.ConnectionEvents$Activated@2ed5222c)
25-07 15:55:45.263 DEBUG [lettuce-eventExecutorLoop-7-1] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] write() writeAndFlush command AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[], error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.264 DEBUG [lettuce-eventExecutorLoop-7-1] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] write() done
25-07 15:55:45.264 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] write(ctx, AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[], error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.264 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandEncoder - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379] writing command AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[], error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] Received: 34 bytes, 1 commands in the stack
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] Stack contains: 1 commands
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[], error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=SENTINEL, output=ValueListOutput [output=[127.0.0.2, 6379], error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.270 DEBUG [lettuce-eventExecutorLoop-7-1] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] close()
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, last known addr=127.0.0.3/127.0.0.3:26379] userEventTriggered(io.netty.channel.DefaultChannelHandlerContext@372547e8, com.lambdaworks.redis.ConnectionEvents$PrepareClose@11f84694)
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, last known addr=127.0.0.3/127.0.0.3:26379] userEventTriggered(io.netty.channel.DefaultChannelHandlerContext@372547e8, com.lambdaworks.redis.ConnectionEvents$Close@16bbd2c5)
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] channelInactive()
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] deactivating channel handler
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] rebuildQueue 0 command(s) added to buffer
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] channelInactive() done
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, last known addr=127.0.0.3/127.0.0.3:26379] channelInactive(io.netty.channel.DefaultChannelHandlerContext@372547e8)
25-07 15:55:45.270 DEBUG [lettuce-eventExecutorLoop-7-1] c.l.r.protocol.ReconnectionHandler - Reconnecting to Redis at /127.0.0.2:6379
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.r.protocol.ConnectionWatchdog - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, last known addr=127.0.0.3/127.0.0.3:26379] Reconnect scheduling disabled
25-07 15:55:45.270 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xd7de49db, /127.0.0.1:49556 -> 127.0.0.3/127.0.0.3:26379, chid=0x7] channelUnregistered()
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, [id: 0x19a0d0ce] (inactive), chid=0x1] channelRegistered()
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] channelActive()
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] rebuildQueue 0 command(s) added to buffer
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] activateCommandHandlerAndExecuteBufferedCommands 0 command(s) buffered
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] activating channel handler
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] write() writeAndFlush command AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] write(ctx, AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], promise)
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandEncoder - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379] writing command AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] write() done
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] flushCommands()
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.r.protocol.ConnectionWatchdog - [channel=0xda5d3b84, /127.0.0.1:47264 -> 127.0.0.2/127.0.0.2:6379, last known addr=127.0.0.2/127.0.0.2:6379] channelActive(io.netty.channel.DefaultChannelHandlerContext@18dfea6c)
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] channelActive() done
25-07 15:55:45.271 INFO  [lettuce-epollEventLoop-10-1] c.l.r.protocol.ReconnectionHandler - Reconnected to /127.0.0.2:6379, Channel channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.r.protocol.ConnectionWatchdog - [channel=0xda5d3b84, /127.0.0.1:47264 -> 127.0.0.2/127.0.0.2:6379, last known addr=127.0.0.2/127.0.0.2:6379] userEventTriggered(io.netty.channel.DefaultChannelHandlerContext@18dfea6c, com.lambdaworks.redis.ConnectionEvents$Activated@3f672175)
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] Received: 52 bytes, 1 commands in the stack
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.CommandHandler - [channel=0x19a0d0ce, /127.0.0.1:55994 -> 127.0.0.2/127.0.0.2:6379, chid=0x1] Stack contains: 1 commands
25-07 15:55:45.271 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.272 DEBUG [lettuce-epollEventLoop-10-1] c.l.redis.protocol.RedisStateMachine - Decoded AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command], empty stack: true
25-07 15:55:45.288 DEBUG [qtp164757726-100] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=SETEX, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.288 DEBUG [qtp164757726-100] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.288 DEBUG [qtp164757726-100] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() writeAndFlush command AsyncCommand [type=SETEX, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:55:45.288 DEBUG [qtp164757726-100] c.l.redis.protocol.CommandHandler - [channel=0xc98393d0, /127.0.0.1:47322 -> 127.0.0.2/127.0.0.2:6379, chid=0x3] write() done
25-07 15:55:45.289 DEBUG [l

[nikolayk812]

I very much sure that issue is caused by ping command. I comment out that code of pinging and issue is gone.

[mp911de]

You're right. The reason is that Lettuce doesn't decode properly PING responses on Pub/Sub connections once a subscription is active.

You can see somewhat in the logs:

Expected:

2017-07-27 14:41:04 [DEBUG] [lettuce-kqueueEventLoop-5-1] Decode AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.AsyncCommand] (RedisStateMachine:76)
2017-07-27 14:41:04 [DEBUG] [lettuce-kqueueEventLoop-5-1] Decoded AsyncCommand [type=PING, output=StatusOutput [output=PONG, error='null'], commandType=com.lambdaworks.redis.protocol.AsyncCommand], empty stack: true (RedisStateMachine:81)

Actual:

25-07 15:35:42.658 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.RedisStateMachine - Decode AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=com.lambdaworks.redis.protocol.Command]
25-07 15:35:42.658 DEBUG [lettuce-epollEventLoop-10-3] c.l.redis.protocol.CommandHandler - [channel=0xb95577bd, /127.0.0.1:56120 -> 127.0.0.3/127.0.0.3:6379, chid=0x1] Storing exception in AsyncCommand [type=PING, output=StatusOutput [output=1
s, error='null'], commandType=com.lambdaworks.redis.protocol.Command]

The response is:

1
s

I didn't notice the fact that you PING on a Pub/Sub connection earlier. There's actually no need to issue pings. You can listen to disconnects via Connection Events and additionally check StatefulConnection.isOpen() if you need to know whether the connection is currently connected.

Thanks for your support to figure out the actual problem. I need to check how/whether a proper PING response handling is possible.

[nikolayk812]

In fact I am not doing ping on pub-sub connection. I use data connection for ping.

[mp911de]

The posted stack traces show something different. Your log contains PING commands that are sent and received on the same connection which is identifiable as Pub/Sub connection by having PubSubCommandHandler within the stack trace.

[nikolayk812]

I invoke ping on RedisAsyncCommands<String, SomeValue> but StatefulRedisPubSubConnection<String, String> does not even have that method. Could I potentially get the same connection for data and pubsub even though I try to create different? Or maybe those 2 are not so isolated as they supposed to be?

[mp911de]

You might want to debug the code. I don't think there's anything I could do right now. The original NPE is fixed and we have a ticket to address the PING issue.