Further determinism improvements to CoordinatorTests (elastic#95032)

A handful of small changes to make the logging output of `CoordinatorTests` even more deterministic, for easier diffing. Relates elastic#94946
rjernst · Apr 6, 2023 · cccb892 · cccb892
1 parent 0e45844
commit cccb892
Show file tree

Hide file tree

Showing 6 changed files with 48 additions and 14 deletions.
diff --git a/server/src/main/java/org/elasticsearch/cluster/coordination/CoordinationMetadata.java b/server/src/main/java/org/elasticsearch/cluster/coordination/CoordinationMetadata.java
@@ -361,7 +361,8 @@ public Set<String> getNodeIds() {
 
         @Override
         public String toString() {
-            return "VotingConfiguration{" + String.join(",", nodeIds) + "}";
+            // Sorting the node IDs for deterministic logging until https://github.com/elastic/elasticsearch/issues/94946 is fixed
+            return "VotingConfiguration{" + nodeIds.stream().sorted().collect(Collectors.joining(",")) + "}";
         }
 
         @Override

diff --git a/server/src/main/java/org/elasticsearch/cluster/coordination/Coordinator.java b/server/src/main/java/org/elasticsearch/cluster/coordination/Coordinator.java
@@ -915,6 +915,11 @@ public void onFailure(Exception e) {
                         }
                     }
                 }
+
+                @Override
+                public String toString() {
+                    return "term change heartbeat listener";
+                }
             })
         );
 

diff --git a/server/src/main/java/org/elasticsearch/cluster/coordination/LeaderChecker.java b/server/src/main/java/org/elasticsearch/cluster/coordination/LeaderChecker.java
@@ -13,6 +13,7 @@
 import org.elasticsearch.ExceptionsHelper;
 import org.elasticsearch.cluster.node.DiscoveryNode;
 import org.elasticsearch.cluster.node.DiscoveryNodes;
+import org.elasticsearch.common.Strings;
 import org.elasticsearch.common.io.stream.StreamInput;
 import org.elasticsearch.common.io.stream.StreamOutput;
 import org.elasticsearch.common.settings.Setting;
@@ -160,7 +161,8 @@ void updateLeader(@Nullable final DiscoveryNode leader) {
      * publication targets, and also called if a leader becomes a non-leader.
      */
     void setCurrentNodes(DiscoveryNodes discoveryNodes) {
-        logger.trace("setCurrentNodes: {}", discoveryNodes);
+        // Sorting the nodes for deterministic logging until https://github.com/elastic/elasticsearch/issues/94946 is fixed
+        logger.trace(() -> Strings.format("setCurrentNodes: {}", discoveryNodes.mastersFirstStream().toList()));
         this.discoveryNodes = discoveryNodes;
     }
 

diff --git a/server/src/main/java/org/elasticsearch/cluster/coordination/Reconfigurator.java b/server/src/main/java/org/elasticsearch/cluster/coordination/Reconfigurator.java
@@ -13,6 +13,7 @@
 import org.elasticsearch.cluster.ClusterState;
 import org.elasticsearch.cluster.coordination.CoordinationMetadata.VotingConfiguration;
 import org.elasticsearch.cluster.node.DiscoveryNode;
+import org.elasticsearch.common.Strings;
 import org.elasticsearch.common.settings.ClusterSettings;
 import org.elasticsearch.common.settings.Setting;
 import org.elasticsearch.common.settings.Setting.Property;
@@ -91,12 +92,15 @@ public VotingConfiguration reconfigure(
     ) {
         assert liveNodes.contains(currentMaster) : "liveNodes = " + liveNodes + " master = " + currentMaster;
         logger.trace(
-            "{} reconfiguring {} based on liveNodes={}, retiredNodeIds={}, currentMaster={}",
-            this,
-            currentConfig,
-            liveNodes,
-            retiredNodeIds,
-            currentMaster
+            () -> Strings.format(
+                "%s reconfiguring %s based on liveNodes=%s, retiredNodeIds=%s, currentMaster=%s",
+                this,
+                currentConfig,
+                // Sorting the node IDs for deterministic logging until https://github.com/elastic/elasticsearch/issues/94946 is fixed
+                liveNodes.stream().map(DiscoveryNode::toString).sorted().collect(Collectors.joining(", ", "[", "]")),
+                retiredNodeIds.stream().sorted().collect(Collectors.joining(", ")),
+                currentMaster
+            )
         );
 
         final Set<String> liveNodeIds = liveNodes.stream()

diff --git a/server/src/main/java/org/elasticsearch/cluster/service/MasterService.java b/server/src/main/java/org/elasticsearch/cluster/service/MasterService.java
@@ -11,6 +11,7 @@
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
 import org.elasticsearch.action.ActionListener;
+import org.elasticsearch.action.DelegatingActionListener;
 import org.elasticsearch.action.support.ContextPreservingActionListener;
 import org.elasticsearch.action.support.ThreadedActionListener;
 import org.elasticsearch.action.support.master.TransportMasterNodeAction;
@@ -250,6 +251,8 @@ private <T extends ClusterStateTaskListener> void executeAndPublishBatch(
         } else {
             final long publicationStartTime = threadPool.rawRelativeTimeInMillis();
             try (var ignored = threadPool.getThreadContext().newTraceContext()) {
+                final var newClusterStateVersion = newClusterState.getVersion();
+
                 final Task task = taskManager.register("master", STATE_UPDATE_ACTION_NAME, new TaskAwareRequest() {
                     @Override
                     public void setParentTask(TaskId taskId) {}
@@ -264,14 +267,28 @@ public TaskId getParentTask() {
 
                     @Override
                     public String getDescription() {
-                        return "publication of cluster state [" + newClusterState.getVersion() + "]";
+                        return "publication of cluster state [" + newClusterStateVersion + "]";
                     }
                 });
-                ActionListener.run(ActionListener.runAfter(listener, () -> taskManager.unregister(task)).delegateResponse((l, e) -> {
-                    assert publicationMayFail() : e;
-                    handleException(summary, publicationStartTime, newClusterState, e);
-                    l.onResponse(null);
-                }),
+
+                ActionListener.run(
+                    new DelegatingActionListener<Void, Void>(
+                        ActionListener.runAfter(listener, () -> taskManager.unregister(task)).delegateResponse((l, e) -> {
+                            assert publicationMayFail() : e;
+                            handleException(summary, publicationStartTime, newClusterState, e);
+                            l.onResponse(null);
+                        })
+                    ) {
+                        @Override
+                        public void onResponse(Void response) {
+                            delegate.onResponse(response);
+                        }
+
+                        @Override
+                        public String toString() {
+                            return "listener for publication of cluster state [" + newClusterStateVersion + "]";
+                        }
+                    },
                     l -> publishClusterStateUpdate(
                         executor,
                         summary,

diff --git a/...ramework/src/main/java/org/elasticsearch/cluster/service/FakeThreadPoolMasterService.java b/...ramework/src/main/java/org/elasticsearch/cluster/service/FakeThreadPoolMasterService.java
@@ -59,6 +59,11 @@ protected ExecutorService createThreadPoolExecutor() {
             public void execute(Runnable command) {
                 taskExecutor.accept(threadContext.preserveContext(command));
             }
+
+            @Override
+            public String toString() {
+                return "FakeThreadPoolMasterService executor";
+            }
         };
     }