lettuce
lettuce copied to clipboard
redis
Commands on newly created connections remain un-flushed
Feature Request
Is your feature request related to a problem? Please describe
Hi team, I've come across the same problem others have (ex. https://github.com/lettuce-io/lettuce-core/issues/2380) where manual flushing with the cluster client can cause commands not to be flushed, leading to timeouts or hanging futures.
Describe the solution you'd like
If a flush is initiated while a connection is in progress, queue the flush to occur after the pending commands are queued to the connection. As an idea, when new connections are created in the ClusterDistributionChannelWriter, if the future is held in a list, we could queue flushes to occur on these connections after pending commands have been written to them.
Describe alternatives you've considered
I've tried to work around this by listening to connection-activated events or checking that nodes are connected with the partition table, but none of these have been fool-proof and have become quite hacky.
Listening to connection-activated events has been the most reliable but needs a delay since the connection is established before the command is written. Trying to use the partition table has been flaky, I believe (correct me if I'm wrong) because the client can use separate read/write connections so the node could be connected without both connections existing.
Teachability, Documentation, Adoption, Migration Strategy
This is a very rough patch for an example. There are a few problems with it as is.
ClusterDistributionChannelWriter Patch
Subject: [PATCH] Flush connection after queuing
---
Index: src/main/java/io/lettuce/core/cluster/ClusterDistributionChannelWriter.java
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
diff --git a/src/main/java/io/lettuce/core/cluster/ClusterDistributionChannelWriter.java b/src/main/java/io/lettuce/core/cluster/ClusterDistributionChannelWriter.java
--- a/src/main/java/io/lettuce/core/cluster/ClusterDistributionChannelWriter.java (revision 2ad862f5a1db860d57236c21c473cfd9aefebfea)
+++ b/src/main/java/io/lettuce/core/cluster/ClusterDistributionChannelWriter.java (date 1686186198095)
@@ -21,6 +21,7 @@
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collection;
+import java.util.Collections;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
@@ -105,6 +106,8 @@
return doWrite(command);
}
+ private final List<CompletableFuture<? extends StatefulRedisConnection<?, ?>>> pendingConnections = Collections.synchronizedList(new ArrayList<>());
+
private <K, V, T> RedisCommand<K, V, T> doWrite(RedisCommand<K, V, T> command) {
if (command instanceof ClusterCommand && !command.isDone()) {
@@ -148,7 +151,9 @@
if (isSuccessfullyCompleted(connectFuture)) {
writeCommand(command, asking, connectFuture.join(), null);
} else {
- connectFuture.whenComplete((connection, throwable) -> writeCommand(command, asking, connection, throwable));
+ CompletableFuture<StatefulRedisConnection<K, V>> writeFuture = connectFuture.whenComplete((connection, throwable) -> writeCommand(command, asking, connection, throwable));
+ pendingConnections.add(writeFuture);
+ writeFuture.whenComplete((ignored1, ignored2) -> pendingConnections.remove(connectFuture));
}
return command;
@@ -173,8 +178,10 @@
if (isSuccessfullyCompleted(connectFuture)) {
writeCommand(commandToSend, false, connectFuture.join(), null);
} else {
- connectFuture
- .whenComplete((connection, throwable) -> writeCommand(commandToSend, false, connection, throwable));
+ CompletableFuture<StatefulRedisConnection<K, V>> writeFuture = connectFuture.whenComplete((connection, throwable) -> writeCommand(commandToSend, false, connection, throwable));
+ pendingConnections.add(writeFuture);
+ writeFuture.whenComplete((ignored1, ignored2) -> pendingConnections.remove(connectFuture));
+
}
return commandToSend;
@@ -493,6 +500,7 @@
@Override
public void flushCommands() {
getClusterConnectionProvider().flushCommands();
+ pendingConnections.forEach(f -> f.whenComplete((c, t) -> c.flushCommands()));
}
public ClusterConnectionProvider getClusterConnectionProvider() {
AsyncConnectionProvider does exactly that through the forEach(…) method. The action is either invoked on the actual object or queued through a Future.
If you have a reproducer that we can use for debugging, then happy to look into things.
Hey Mark, thanks for getting back to me.
I tried making a minimal reproducer for you, but it's not failing as expected. The logs clearly show the connection event after I've flushed, but just like you said the connection is being flushed correctly.
With that knowledge, I'll see if I can figure out what I've done wrong.
I'll close this issue since I think it's a problem on my end.
Hi Mark (@mp911de), I have a reproducer for the problem.
I believe the problem is that the flush queued by the AsyncConnectionProvider to occur after a connection is established can occur before all the commands are buffered when multiple commands are sent to a node at once.
I've attached the reproducer code below, as well as logs.
I'm testing with a cluster of 6 nodes locally (3M/3R), and it's reproducible most consistently with 6-10 commands sent at once to a node.
Reproducer code
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import io.lettuce.core.RedisURI;
import io.lettuce.core.SocketOptions;
import io.lettuce.core.TimeoutOptions;
import io.lettuce.core.cluster.ClusterClientOptions;
import io.lettuce.core.cluster.ClusterTopologyRefreshOptions;
import io.lettuce.core.cluster.RedisClusterClient;
import io.lettuce.core.codec.StringCodec;
import org.slf4j.LoggerFactory;
import java.time.Duration;
import java.util.ArrayList;
import java.util.concurrent.CompletableFuture;
public class Main {
private static final org.slf4j.Logger logger = LoggerFactory.getLogger(Main.class);
private static void configureLogging() {
((Logger) LoggerFactory.getLogger("io.netty")).setLevel(Level.WARN);
((Logger) LoggerFactory.getLogger("io.lettuce.core")).setLevel(Level.WARN);
((Logger) LoggerFactory.getLogger("io.lettuce.core.RedisChannelHandler")).setLevel(Level.ERROR);
((Logger) LoggerFactory.getLogger("io.lettuce.core.cluster.ClusterDistributionChannelWriter")).setLevel(Level.INFO);
((Logger) LoggerFactory.getLogger("io.lettuce.core.protocol.DefaultEndpoint")).setLevel(Level.DEBUG);
}
public static void main(String[] args) throws InterruptedException {
configureLogging();
var uri = RedisURI.create("redis://localhost:7000");
uri.setTimeout(Duration.ofSeconds(2));
var clusterClient = RedisClusterClient.create(uri);
var options = ClusterClientOptions.builder()
.timeoutOptions(TimeoutOptions.builder().fixedTimeout(Duration.ofSeconds(2)).build())
.socketOptions(SocketOptions.builder().connectTimeout(Duration.ofSeconds(2)).build())
.topologyRefreshOptions(ClusterTopologyRefreshOptions.builder().enableAllAdaptiveRefreshTriggers().build());
clusterClient.setOptions(options.build());
clusterClient.getPartitions();
var i = 0;
while (i++ < 10) {
logger.info("Run {}", i);
Thread.sleep(100);
run(clusterClient);
}
}
public static void run(RedisClusterClient clusterClient) {
try (var conn = clusterClient.connect(StringCodec.UTF8)) {
conn.setAutoFlushCommands(false);
var async = conn.async();
var futures = new ArrayList<CompletableFuture<?>>();
for (int i = 0; i < 5; i++) {
futures.add(async.get("hello" + i).toCompletableFuture());
futures.add(async.ttl("hello" + i).toCompletableFuture());
futures.add(async.get("hello" + i).toCompletableFuture());
futures.add(async.ttl("hello" + i).toCompletableFuture());
futures.add(async.get("hello" + i).toCompletableFuture());
futures.add(async.ttl("hello" + i).toCompletableFuture());
futures.add(async.get("hello" + i).toCompletableFuture());
futures.add(async.ttl("hello" + i).toCompletableFuture());
futures.add(async.get("hello" + i).toCompletableFuture());
futures.add(async.ttl("hello" + i).toCompletableFuture());
}
conn.flushCommands();
while (!futures.stream().allMatch(CompletableFuture::isDone));
var failed = futures.stream().filter(CompletableFuture::isCompletedExceptionally).count();
var success = futures.size() - failed;
logger.info("Success: {} | Failed: {}", success, failed);
if (failed > 0) {
futures.stream().filter(CompletableFuture::isCompletedExceptionally).findFirst().get().join();
}
}
}
}
Logs
19:57:09.337 [main] DEBUG reactor.util.Loggers - Using Slf4j logging framework
19:57:09.586 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.586 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] activating endpoint
19:57:09.586 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] flushCommands()
19:57:09.587 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] flushCommands() Flushing 0 commands
19:57:09.590 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] write() writeAndFlush command AsyncCommand [type=CLIENT, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.590 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] write() done
19:57:09.591 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] write() writeAndFlush command TimedAsyncCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.594 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] write() done
19:57:09.595 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] write() writeAndFlush command TimedAsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.595 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] write() done
19:57:09.609 [lettuce-nioEventLoop-4-2] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.609 [lettuce-nioEventLoop-4-2] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] activating endpoint
19:57:09.609 [lettuce-nioEventLoop-4-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.610 [lettuce-nioEventLoop-4-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] activating endpoint
19:57:09.610 [lettuce-nioEventLoop-4-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] flushCommands()
19:57:09.609 [lettuce-nioEventLoop-4-2] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] flushCommands()
19:57:09.610 [lettuce-nioEventLoop-4-4] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.610 [lettuce-nioEventLoop-4-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] flushCommands() Flushing 0 commands
19:57:09.610 [lettuce-nioEventLoop-4-4] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] activating endpoint
19:57:09.610 [lettuce-nioEventLoop-4-4] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] flushCommands()
19:57:09.610 [lettuce-nioEventLoop-4-2] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] flushCommands() Flushing 0 commands
19:57:09.610 [lettuce-nioEventLoop-4-4] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] flushCommands() Flushing 0 commands
19:57:09.610 [lettuce-nioEventLoop-4-5] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.610 [lettuce-nioEventLoop-4-5] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] activating endpoint
19:57:09.610 [lettuce-nioEventLoop-4-5] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] flushCommands()
19:57:09.610 [lettuce-nioEventLoop-4-5] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] flushCommands() Flushing 0 commands
19:57:09.610 [lettuce-nioEventLoop-4-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] write() writeAndFlush command AsyncCommand [type=CLIENT, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.610 [lettuce-nioEventLoop-4-6] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.610 [lettuce-nioEventLoop-4-6] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] activating endpoint
19:57:09.610 [lettuce-nioEventLoop-4-6] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] flushCommands()
19:57:09.610 [lettuce-nioEventLoop-4-6] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] flushCommands() Flushing 0 commands
19:57:09.610 [lettuce-nioEventLoop-4-2] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] write() writeAndFlush command AsyncCommand [type=CLIENT, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.610 [lettuce-nioEventLoop-4-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] write() done
19:57:09.610 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.610 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] activating endpoint
19:57:09.610 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] flushCommands()
19:57:09.610 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] flushCommands() Flushing 0 commands
19:57:09.610 [lettuce-nioEventLoop-4-2] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] write() done
19:57:09.611 [lettuce-nioEventLoop-4-4] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] write() writeAndFlush command AsyncCommand [type=CLIENT, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.611 [lettuce-nioEventLoop-4-5] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] write() writeAndFlush command AsyncCommand [type=CLIENT, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.611 [lettuce-nioEventLoop-4-6] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] write() writeAndFlush command AsyncCommand [type=CLIENT, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.611 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] write() writeAndFlush command AsyncCommand [type=CLIENT, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.611 [lettuce-nioEventLoop-4-4] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] write() done
19:57:09.611 [lettuce-nioEventLoop-4-5] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] write() done
19:57:09.611 [lettuce-nioEventLoop-4-6] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] write() done
19:57:09.611 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] write() done
19:57:09.611 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] write() writeAndFlush command TimedAsyncCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.612 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] write() done
19:57:09.612 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] write() writeAndFlush command TimedAsyncCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.612 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] write() done
19:57:09.612 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] write() writeAndFlush command TimedAsyncCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.612 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] write() done
19:57:09.612 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] write() writeAndFlush command TimedAsyncCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.612 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] write() done
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] write() writeAndFlush command TimedAsyncCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] write() done
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] write() writeAndFlush command TimedAsyncCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] write() done
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] write() writeAndFlush command TimedAsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] write() done
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] write() writeAndFlush command TimedAsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] write() done
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] write() writeAndFlush command TimedAsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] write() done
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] write() writeAndFlush command TimedAsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] write() done
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] write() writeAndFlush command TimedAsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] write() done
19:57:09.613 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] write() writeAndFlush command TimedAsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
19:57:09.614 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] write() done
19:57:09.623 [lettuce-eventExecutorLoop-1-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] closeAsync()
19:57:09.625 [lettuce-eventExecutorLoop-1-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] closeAsync()
19:57:09.625 [lettuce-eventExecutorLoop-1-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] closeAsync()
19:57:09.625 [lettuce-eventExecutorLoop-1-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] closeAsync()
19:57:09.625 [lettuce-eventExecutorLoop-1-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] closeAsync()
19:57:09.625 [lettuce-eventExecutorLoop-1-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] closeAsync()
19:57:09.625 [lettuce-eventExecutorLoop-1-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] closeAsync()
19:57:09.626 [lettuce-nioEventLoop-4-5] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xb125b4f0, /127.0.0.1:64533 -> /127.0.0.1:7003, epid=0x5] deactivating endpoint handler
19:57:09.626 [lettuce-nioEventLoop-4-2] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x89317e8b, /127.0.0.1:64530 -> /127.0.0.1:7000, epid=0x2] deactivating endpoint handler
19:57:09.626 [lettuce-nioEventLoop-4-4] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x39d64a77, /127.0.0.1:64532 -> /127.0.0.1:7002, epid=0x4] deactivating endpoint handler
19:57:09.626 [lettuce-nioEventLoop-4-3] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x1ff08ee1, /127.0.0.1:64531 -> /127.0.0.1:7001, epid=0x3] deactivating endpoint handler
19:57:09.626 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x510f0cb0, /127.0.0.1:64529 -> localhost/127.0.0.1:7000, epid=0x1] deactivating endpoint handler
19:57:09.626 [lettuce-nioEventLoop-4-6] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xf1baeadb, /127.0.0.1:64534 -> /127.0.0.1:7004, epid=0x6] deactivating endpoint handler
19:57:09.627 [main] INFO playground.rediscachebug.Main - Run 1
19:57:09.627 [lettuce-nioEventLoop-4-7] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x906e5f8e, /127.0.0.1:64535 -> /127.0.0.1:7005, epid=0x7] deactivating endpoint handler
19:57:09.760 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.760 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] activating endpoint
19:57:09.761 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] write() writeAndFlush command ActivationCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.cluster.ClusterCommand]
19:57:09.761 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] write() done
19:57:09.761 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] flushCommands()
19:57:09.761 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] flushCommands() Flushing 0 commands
19:57:09.769 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.769 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] activating endpoint
19:57:09.769 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] flushCommands()
19:57:09.769 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] flushCommands() Flushing 0 commands
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] flushCommands()
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] flushCommands() Flushing 13 commands
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.772 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] activating endpoint
19:57:09.772 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] flushCommands()
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.772 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] flushCommands() Flushing 0 commands
19:57:09.772 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] activating endpoint
19:57:09.772 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] flushCommands()
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] flushCommands() Flushing 0 commands
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelFlush
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] flushCommands()
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] flushCommands() Flushing 6 commands
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.774 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelFlush
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] flushCommands()
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] flushCommands() Flushing 10 commands
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelFlush
19:57:11.780 [main] INFO playground.rediscachebug.Main - Success: 29 | Failed: 21
19:57:11.780 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] closeAsync()
19:57:11.780 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] deactivating endpoint handler
19:57:11.781 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] closeAsync()
19:57:11.781 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] closeAsync()
19:57:11.781 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] closeAsync()
19:57:11.782 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] deactivating endpoint handler
19:57:11.782 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] deactivating endpoint handler
19:57:11.782 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] deactivating endpoint handler
Exception in thread "main" java.util.concurrent.CompletionException: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 2 second(s)
at java.base/java.util.concurrent.CompletableFuture.reportJoin(CompletableFuture.java:413)
at java.base/java.util.concurrent.CompletableFuture.join(CompletableFuture.java:2118)
at playground.rediscachebug.Main.doThing(Main.java:83)
at playground.rediscachebug.Main.main(Main.java:49)
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 2 second(s)
at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:59)
at io.lettuce.core.protocol.CommandExpiryWriter.lambda$potentiallyExpire$0(CommandExpiryWriter.java:176)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
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:833)
I've split the logs by port for you so you can what is buffered and flushed to each node
In this run there were 29 successes and 21 failures
7002 flushed 13 / 30 7003 flushed 10 / 10 7004 flushed 6 / 10
port 7002
19:57:09.760 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.760 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] activating endpoint
19:57:09.761 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] write() writeAndFlush command ActivationCommand [type=CLUSTER, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.cluster.ClusterCommand]
19:57:09.761 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] write() done
19:57:09.761 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] flushCommands()
19:57:09.761 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] flushCommands() Flushing 0 commands
19:57:09.769 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.769 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] activating endpoint
19:57:09.769 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] flushCommands()
19:57:09.769 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] flushCommands() Flushing 0 commands
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.770 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] flushCommands()
19:57:09.770 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] flushCommands() Flushing 13 commands
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.771 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.772 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.773 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() channelFlush
19:57:09.773 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] write() done
19:57:11.780 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] closeAsync()
19:57:11.780 [lettuce-nioEventLoop-4-8] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x817c1c8a, /127.0.0.1:64536 -> /127.0.0.1:7002, epid=0x8] deactivating endpoint handler
19:57:11.781 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] closeAsync()
19:57:11.782 [lettuce-nioEventLoop-4-9] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x4eb30987, /127.0.0.1:64537 -> /127.0.0.1:7002, epid=0x9] deactivating endpoint handler
port 7003
19:57:09.772 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.772 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] activating endpoint
19:57:09.772 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] flushCommands()
19:57:09.772 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] flushCommands() Flushing 0 commands
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.773 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.774 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.775 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() done
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] flushCommands()
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] flushCommands() Flushing 10 commands
19:57:09.776 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.777 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.778 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] write() channelFlush
19:57:11.781 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] closeAsync()
19:57:11.782 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0x2adf8e55, /127.0.0.1:64538 -> /127.0.0.1:7003, epid=0xb] deactivating endpoint handler
port 7004
19:57:09.772 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
19:57:09.772 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] activating endpoint
19:57:09.772 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] flushCommands()
19:57:09.772 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] flushCommands() Flushing 0 commands
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.773 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] flushCommands()
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] flushCommands() Flushing 6 commands
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.774 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.774 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelFlush
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:11.781 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] closeAsync()
19:57:11.782 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] deactivating endpoint handler
Thanks for the detail. I reopened the ticket and marked it as bug. I'll have a look.
I tried to reproduce the issue with no luck. I had another look at the code and I noticed that AsyncConnectionProvider.Sync uses a shortcut for running actions. This can introduce non-sequential behavior. Can you try the following:
Replace the two
if (isComplete()) {
action.accept(connection);
} else {
future.thenAccept(action);
}
occurrences with future.thenAccept calls and retry your test?
Hi Mark, I can still see the error with your suggestion, but I think you're right about non-sequential behaviour.
In my tests (and in the logs I gave you), I noticed that it fails when flushCommands() runs on the main thread. If it runs on the event loop, it works as intended.
Can you try to reproduce the error again and see if it succeeds when flushCommands() executes on main?
I believe the error still occurs with future.thenAccept because the command is executed immediately on the calling thread if the future is already completed.
Also, unrelated, but is there a race condition here with isComplete() 🤔
I believe it's possible for a thread to try to access connection before it's been set.
DefaultEndpoint.flushCommands() is called on the main thread if the connection is already established.
I'm still not able to reproduce the issue, neither via delaying the connection activation nor delaying the events in the loop.
In any case, I'll apply the change to ensure proper ordering of the actions.
I think that we might have a couple more races here, as some writes are being called after the flush:
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelWrite command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.775 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() channelFlush
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] writeToBuffer() buffering command ClusterCommand [command=AsyncCommand [type=TTL, output=IntegerOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], redirections=0, maxRedirections=5]
19:57:09.776 [lettuce-nioEventLoop-4-10] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xd5612147, /127.0.0.1:64539 -> /127.0.0.1:7004, epid=0xa] write() done
There's another out of sync access to the connection future when the connection is considered to be established in ClusterDistributionChannelWriter. It plays into the race when we call isSuccessfullyCompleted that we do not consider the remaining queued action on the initial future.
I'm still not able to reproduce the issue, neither via delaying the connection activation nor delaying the events in the loop.
Interesting 🤔, I have been able to reproduce it on Apple Silicon and Windows.
In any case, I'll apply the change to ensure proper ordering of the actions.
The task runs immediately on the calling thread when a future is already complete. Doesn't that mean the ordering remains the same whether or not you use the future or the connection directly?
AIUI, the execution order of futures changes once the future is complete. If the future is incomplete tasks are queued and execute in reverse, but if it's complete they execute immediately.
Actually, given this, I'm not sure why the flush executes correctly ever 😅
future example
var f = new CompletableFuture<Void>();
f.whenComplete((x, t) -> System.out.println("A"));
f.whenComplete((x, t) -> System.out.println("B"));
f.whenComplete((x, t) -> System.out.println("C"));
f.complete(null);
// C
// B
// A
f.whenComplete((x, t) -> System.out.println("D"));
// D
f.whenComplete((x, t) -> System.out.println("E"));
// E
Well, I was under the impression that all action is queued in order. Apparently, that is not the case and I currently do not have a good idea how to resolve the issue. Maybe we could have our own stack of actions to queue actions and then drain the stack.
FWIW,
f.whenComplete((x, t) -> System.out.println("A"))
.whenComplete((x, t) -> System.out.println("B"))
.whenComplete((x, t) -> System.out.println("C"));
retains the order.
Well, I was under the impression that all action is queued in order. Apparently, that is not the case
It's bitten me too. I'm actually surprised this hasn't presented itself as a bigger problem 🤷
I thought the execution order was reversed, but I found this STO post yesterday which shows it's possible to have any order of execution. https://stackoverflow.com/a/65050322
FWIW ...
If the futures are chained the order is retained since each has a queue of 1, but I was under the impression that the buffer and flush commands are all queued on the connection future. f.a; f.b; f.c not f.a.b.c