Make failed-join logging deterministic (#143808)

DaveCTurner · web-flow · commit 1e07b3afce9e · 2026-03-09T15:30:43.000+01:00
No need for nanosecond precision here, and this is the only source of
nondeterminism in the log output of `CoordinatorTests`. With this commit
we move to retrieving the current time from `ThreadPool`, making the
test outputs completely deterministic.
diff --git a/server/src/main/java/org/elasticsearch/cluster/coordination/JoinHelper.java b/server/src/main/java/org/elasticsearch/cluster/coordination/JoinHelper.java
@@ -207,18 +207,19 @@ static class FailedJoinAttempt {
         private final DiscoveryNode destination;
         private final JoinRequest joinRequest;
         private final ElasticsearchException exception;
-        private final long timestamp;
+        private final long attemptTimeMillis;
 
         /**
-         * @param destination the master node targeted by the join request.
-         * @param joinRequest the join request that was sent to the perceived master node.
-         * @param exception   the error response received in reply to the join request attempt.
+         * @param destination       the master node targeted by the join request.
+         * @param joinRequest       the join request that was sent to the perceived master node.
+         * @param exception         the error response received in reply to the join request attempt.
+         * @param attemptTimeMillis the (relative milliseconds) time at which the failed attempt occurred.
          */
-        FailedJoinAttempt(DiscoveryNode destination, JoinRequest joinRequest, ElasticsearchException exception) {
+        FailedJoinAttempt(DiscoveryNode destination, JoinRequest joinRequest, ElasticsearchException exception, long attemptTimeMillis) {
             this.destination = destination;
             this.joinRequest = joinRequest;
             this.exception = exception;
-            this.timestamp = System.nanoTime();
+            this.attemptTimeMillis = attemptTimeMillis;
         }
 
         /**
@@ -243,15 +244,15 @@ static Level getLogLevel(ElasticsearchException e) {
             return Level.INFO;
         }
 
-        void logWarnWithTimestamp() {
+        void logWarnWithTimestamp(LongSupplier relativeTimeMillisSupplier) {
             logger.warn(
                 () -> format(
                     "last failed join attempt was %s ago, failed to join %s with %s",
-                    // 'timestamp' is when this error exception was received by the local node. If the time that has passed since the error
-                    // was originally received is quite large, it could indicate that this is a stale error exception from some prior
-                    // out-of-order request response (where a later sent request but earlier received response was successful); or
+                    // 'attemptTimeMillis' is when this error exception was received by the local node. If the time that has passed since
+                    // the error was originally received is quite large, it could indicate that this is a stale error exception from some
+                    // prior out-of-order request response (where a later sent request but earlier received response was successful); or
                     // alternatively an old error could indicate that this node did not retry the join request for a very long time.
-                    TimeValue.timeValueMillis(TimeValue.nsecToMSec(System.nanoTime() - timestamp)),
+                    TimeValue.timeValueMillis(relativeTimeMillisSupplier.getAsLong() - attemptTimeMillis),
                     destination,
                     joinRequest
                 ),
@@ -266,7 +267,7 @@ void logWarnWithTimestamp() {
     void logLastFailedJoinAttempt() {
         FailedJoinAttempt attempt = lastFailedJoinAttempt.get();
         if (attempt != null) {
-            attempt.logWarnWithTimestamp();
+            attempt.logWarnWithTimestamp(transportService.getThreadPool().relativeTimeInMillisSupplier());
             lastFailedJoinAttempt.compareAndSet(attempt, null);
         }
     }
@@ -299,7 +300,12 @@ public void sendJoinRequest(DiscoveryNode destination, long term, Optional<Join>
                 pendingJoinInfo.message = PENDING_JOIN_FAILED;
                 pendingOutgoingJoins.remove(dedupKey);
                 if (e instanceof ElasticsearchException elasticsearchException) {
-                    final var attempt = new FailedJoinAttempt(destination, joinRequest, elasticsearchException);
+                    final var attempt = new FailedJoinAttempt(
+                        destination,
+                        joinRequest,
+                        elasticsearchException,
+                        transportService.getThreadPool().relativeTimeInMillis()
+                    );
                     attempt.logNow();
                     lastFailedJoinAttempt.set(attempt);
                     assert elasticsearchException instanceof CircuitBreakingException : e; // others shouldn't happen, handle them anyway
@@ -374,7 +380,12 @@ public void onFailure(Exception e) {
                             private void cleanUpOnFailure(TransportException exp) {
                                 pendingJoinInfo.message = PENDING_JOIN_FAILED;
                                 pendingOutgoingJoins.remove(dedupKey);
-                                final var attempt = new FailedJoinAttempt(destination, joinRequest, exp);
+                                final var attempt = new FailedJoinAttempt(
+                                    destination,
+                                    joinRequest,
+                                    exp,
+                                    transportService.getThreadPool().relativeTimeInMillis()
+                                );
                                 attempt.logNow();
                                 lastFailedJoinAttempt.set(attempt);
                                 unregisterAndReleaseConnection(destination, connectionReference);
@@ -390,7 +401,8 @@ public void onFailure(Exception e) {
                     final var attempt = new FailedJoinAttempt(
                         destination,
                         joinRequest,
-                        new ConnectTransportException(destination, "failed to acquire connection", e)
+                        new ConnectTransportException(destination, "failed to acquire connection", e),
+                        transportService.getThreadPool().relativeTimeInMillis()
                     );
                     attempt.logNow();
                     lastFailedJoinAttempt.set(attempt);
diff --git a/server/src/test/java/org/elasticsearch/cluster/coordination/JoinHelperTests.java b/server/src/test/java/org/elasticsearch/cluster/coordination/JoinHelperTests.java
@@ -177,6 +177,19 @@ public void testJoinDeduplication() {
         if (mightSucceed) {
             // successful requests hold the connections open until the cluster state is applied
             joinHelper.onClusterStateApplied();
+        } else {
+            final var elapsedTime = randomBoolean() ? TimeValue.ZERO : TimeValue.timeValueMillis(between(0, 100000));
+            deterministicTaskQueue.runTasksUpToTimeInOrder(deterministicTaskQueue.getCurrentTimeMillis() + elapsedTime.millis());
+            MockLog.assertThatLogger(
+                joinHelper::logLastFailedJoinAttempt,
+                JoinHelper.class,
+                new MockLog.SeenEventExpectation(
+                    "failed to join message",
+                    JoinHelper.class.getCanonicalName(),
+                    Level.WARN,
+                    "last failed join attempt was " + elapsedTime + " ago, failed to join *"
+                )
+            );
         }
         assertFalse(transportService.nodeConnected(node1));
         assertFalse(transportService.nodeConnected(node2));
