Lettuce is consistently failing because of full stack after few Redis reconnects

[semberal]

Bug Report

Current Behavior

This issue is a reproducible case from #907 (comment). It is a bit tricky to reproduce, but the following code should do.

Input Code

I create a Lettuce client with queueSize=4, timeout=40ms and then I start 10 threads that are sending GET async commands in a loop. Many calls fail because of timeout or full queue, which is expected, but many calls also succeed. When I close-open Redis connection a few times, there are no more success messages (seems like Lettuce does not even reconnect).

I was able to reproduce it either with local Redis running in Docker (reconnect forced by restarting the container) or remote, port-forwarded Redis running in a Kubernetes pod (reconnect forced by restarting port forwarding).

package test;

import io.lettuce.core.ClientOptions;
import io.lettuce.core.RedisClient;
import io.lettuce.core.RedisURI;
import io.lettuce.core.TimeoutOptions;
import io.lettuce.core.api.async.RedisAsyncCommands;
import io.lettuce.core.resource.ClientResources;
import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.time.Duration;
import java.util.List;
import java.util.stream.Collectors;
import java.util.stream.IntStream;

public class LettuceReconnectionTest {

    private final Logger log = LoggerFactory.getLogger(this.getClass());

    @Test
    public void test() throws InterruptedException {

        final RedisURI uri = new RedisURI("127.0.0.1", 6379, Duration.ofSeconds(1));
        final ClientResources clientResources = ClientResources.builder().computationThreadPoolSize(3).ioThreadPoolSize(3).build();
        final RedisClient client = RedisClient.create(clientResources, uri);
        final TimeoutOptions timeoutOptions = TimeoutOptions.enabled(Duration.ofMillis(40));
        client.setOptions(ClientOptions.builder().requestQueueSize(4).autoReconnect(true).cancelCommandsOnReconnectFailure(true).timeoutOptions(timeoutOptions).disconnectedBehavior(ClientOptions.DisconnectedBehavior.REJECT_COMMANDS).build());
        final RedisAsyncCommands<String, String> async = client.connect().async();

        final List<Thread> threads = IntStream.range(0, 10).mapToObj(x -> createThread(async)).collect(Collectors.toList());

        threads.forEach(Thread::start);

        for (final Thread t : threads)
            t.join();
    }

    private Thread createThread(final RedisAsyncCommands<String, String> async) {

        return new Thread(() -> {
            while (true) {
                try {
                    async.get("a").get();
                    log.info("Success!");
                } catch (final Exception ignored) {
                }
            }
        });
    }
}

Expected behavior/code

When Redis is up, I would expect Lettuce to print Success message with similar frequency as in the beginning.

Environment

• Lettuce version(s): 5.1.2.RELEASE
• Redis version: 4.0.10

[mp911de]

Thanks for the reproducer. I tried to reproduce the issue but had no luck so far. I'm using Redis Server locally to start/kill the server at a faster rate. Every time, Redis comes back up, the reconnect resumes command triggering.

If you can reproduce the issue, please set a breakpoint in DefaultEndpoint.notifyChannelActive(…) to inspect the disconnectedBuffer and to inspect the stack of CommandHandler (channel.pipeline().get(CommandHandler.class)).

[semberal]

Can you try it with remote Redis? Locally it is hard to reproduce. To avoid any Kubernetes or port-forwarding-related issues, I created a new EC2 Redis instance and was able to reproduce quite easily after only few restarts.

I added a log line to into the catch (final Exception ignored) block and Lettuce says: Currently not connected. Commands are rejected. Interestingly, when I log every exception, it is harder to reproduce (there are way too many of them), so I only log every 1000th exception.

As you suggested, I also looked at DefaultEndpoint.notifyChannelActive and channel.pipeline().get(CommandHandler.class).getStack().size() is always 0.

[mp911de]

Closing due to lack of actionability. If you would like us to look at this issue, please provide additional information and we will re-open the issue.