6.0.0.RELEASE IllegalStateExceptions

[ToxicMushroom]

Bug Report

I yesterday tried to update to the new library version but lettuce was just spamming my console (I'm guessing every Redis request was failing).

Current Behavior

IllegalStateExceptions all over the place.

Stack trace

java.lang.IllegalStateException
        at io.lettuce.core.output.CommandOutput.set(CommandOutput.java:98)
        at io.lettuce.core.protocol.RedisStateMachine.safeSet(RedisStateMachine.java:778)
        at io.lettuce.core.protocol.RedisStateMachine.handleInteger(RedisStateMachine.java:404)
        at io.lettuce.core.protocol.RedisStateMachine$State$Type.handle(RedisStateMachine.java:206)
        at io.lettuce.core.protocol.RedisStateMachine.doDecode(RedisStateMachine.java:334)
        at io.lettuce.core.protocol.RedisStateMachine.decode(RedisStateMachine.java:295)
        at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:799)
        at io.lettuce.core.protocol.CommandHandler.decode0(CommandHandler.java:750)
        at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:733)
        at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:618)
        at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:560)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:835)

Input Code

https://github.com/ToxicMushroom/Melijn
commit hash: 6060a804bf23949089cf441d91dc380c8c11c80a
branch: staging

Expected behavior/code

No errors like with 5.3.4.RELEASE

Environment

• Lettuce version(s): [6.0.0.RELEASE]
• Redis version: [6.0.6-alpine and 6.0.8-alpine]

Additional context

Runs in Kubernetes pods, can't reproduce this in a local environment or in docker

[mp911de]

Can you switch to RESP2 mode (via ClientOptions) to verify whether the failures originate from RESP3 protocol usage? From a quick look at the code, you're using GET, SET, EXPIRE, and DEL commands. Can you isolate a specific command that fails?

[ToxicMushroom]

RESP2 didn't solve the issue,
every Redis action you mentioned succeeds at startup in both RESP2 and RESP3

[mp911de]

That's weird. Can you enable trace logging and attach a snippet of a few commands including their failure to find out which commands are affected and what response is sent by Redis?

[ToxicMushroom]

https://hasteb.in/bibepeqo.lua
I don't know if this is enough?

[mp911de]

Thanks. Somehow the protocol gets out of sync and it looks that the SET command is being attempted to complete with an integer response. Let me verify this in a test to see what happens and why.

[mp911de]

I wasn't able to reproduce the issue, neither through a standalone test nor with commit ToxicMushroom/Melijn@22eb476. It gave me the following (successful output):

06-10-2020 16:48:55 main MelijnBot INFO Start redis tests
06-10-2020 16:48:57 main MelijnBot INFO try redis set
06-10-2020 16:48:58 main MelijnBot INFO try redis get
06-10-2020 16:49:00 main MelijnBot INFO got value
06-10-2020 16:49:00 main MelijnBot INFO try redis expire
06-10-2020 16:49:01 main MelijnBot INFO try redis delete
06-10-2020 16:49:02 main MelijnBot INFO Finished redis tests

Since I have no way to reproduce/find out what's happening here, I'm inclined to close the issue. The last attempt would be having the full log Lettuce trace of the startup to see whether things go wrong in there.

[ToxicMushroom]

I'll try to get a full trace log from start until the first exception tomorrow.
Do you just need lettuce logs?

[mp911de]

Yes, only the Lettuce part. Anything else would add noise to the logs.

[ToxicMushroom]

Well, I somehow am unable to catch the exceptions as if they're printed to stdout instead of stderr but I might just be to unexperienced with log back. Thing is that this 200MB file contains too much user data that I'm not gonna filter through.
You can close the issue and I'll just continue with the previous version and switch to a different library when needed.
I'm not willing to keep crashing production to get a better log file where I then have to filter every line and make sure there's no sensitive data left.

[mp911de]

Closing due to lack of activity. If you would like us to look at this issue, please let us know and we will re-open the issue.