From 52d34e45e73c45e7b11e26397c5f23e2dc4108bc Mon Sep 17 00:00:00 2001 From: David Turner Date: Thu, 20 Dec 2018 15:31:52 +0000 Subject: [PATCH] [Zen2] Minor logging improvements (#36818) * Adds term number and greppable phrase 'coordinator becoming' to Coordinator mode changes * Adds term and version to messages from the ClusterApplier about master changes * Reduces some LeaderChecker messages to TRACE level --- .../elasticsearch/cluster/coordination/Coordinator.java | 9 ++++++--- .../cluster/coordination/LeaderChecker.java | 6 +++--- .../cluster/service/ClusterApplierService.java | 3 ++- .../org/elasticsearch/cluster/service/MasterService.java | 3 ++- 4 files changed, 13 insertions(+), 8 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/cluster/coordination/Coordinator.java b/server/src/main/java/org/elasticsearch/cluster/coordination/Coordinator.java index ef7f3b9c3ec1a..01b2fae997749 100644 --- a/server/src/main/java/org/elasticsearch/cluster/coordination/Coordinator.java +++ b/server/src/main/java/org/elasticsearch/cluster/coordination/Coordinator.java @@ -403,7 +403,8 @@ private void handleJoinRequest(JoinRequest joinRequest, JoinHelper.JoinCallback void becomeCandidate(String method) { assert Thread.holdsLock(mutex) : "Coordinator mutex not held"; - logger.debug("{}: becoming CANDIDATE (was {}, lastKnownLeader was [{}])", method, mode, lastKnownLeader); + logger.debug("{}: coordinator becoming CANDIDATE in term {} (was {}, lastKnownLeader was [{}])", + method, getCurrentTerm(), mode, lastKnownLeader); if (mode != Mode.CANDIDATE) { mode = Mode.CANDIDATE; @@ -440,7 +441,8 @@ void becomeLeader(String method) { assert mode == Mode.CANDIDATE : "expected candidate but was " + mode; assert getLocalNode().isMasterNode() : getLocalNode() + " became a leader but is not master-eligible"; - logger.debug("{}: becoming LEADER (was {}, lastKnownLeader was [{}])", method, mode, lastKnownLeader); + logger.debug("{}: coordinator becoming LEADER in term {} (was {}, lastKnownLeader was [{}])", + method, getCurrentTerm(), mode, lastKnownLeader); mode = Mode.LEADER; joinAccumulator.close(mode); @@ -461,7 +463,8 @@ void becomeFollower(String method, DiscoveryNode leaderNode) { assert Thread.holdsLock(mutex) : "Coordinator mutex not held"; assert leaderNode.isMasterNode() : leaderNode + " became a leader but is not master-eligible"; - logger.debug("{}: becoming FOLLOWER of [{}] (was {}, lastKnownLeader was [{}])", method, leaderNode, mode, lastKnownLeader); + logger.debug("{}: coordinator becoming FOLLOWER of [{}] in term {} (was {}, lastKnownLeader was [{}])", + method, leaderNode, getCurrentTerm(), mode, lastKnownLeader); final boolean restartLeaderChecker = (mode == Mode.FOLLOWER && Optional.of(leaderNode).equals(lastKnownLeader)) == false; diff --git a/server/src/main/java/org/elasticsearch/cluster/coordination/LeaderChecker.java b/server/src/main/java/org/elasticsearch/cluster/coordination/LeaderChecker.java index cccbde35c18a9..0f387fca18a13 100644 --- a/server/src/main/java/org/elasticsearch/cluster/coordination/LeaderChecker.java +++ b/server/src/main/java/org/elasticsearch/cluster/coordination/LeaderChecker.java @@ -203,7 +203,7 @@ private class CheckScheduler implements Releasable { @Override public void close() { if (isClosed.compareAndSet(false, true) == false) { - logger.debug("already closed"); + logger.trace("already closed, doing nothing"); } else { logger.debug("closed"); } @@ -211,7 +211,7 @@ public void close() { void handleWakeUp() { if (isClosed.get()) { - logger.debug("closed check scheduler woken up, doing nothing"); + logger.trace("closed check scheduler woken up, doing nothing"); return; } @@ -289,7 +289,7 @@ void leaderFailed() { if (isClosed.compareAndSet(false, true)) { transportService.getThreadPool().generic().execute(onLeaderFailure); } else { - logger.debug("already closed, not failing leader"); + logger.trace("already closed, not failing leader"); } } diff --git a/server/src/main/java/org/elasticsearch/cluster/service/ClusterApplierService.java b/server/src/main/java/org/elasticsearch/cluster/service/ClusterApplierService.java index 3e94245a8975d..c331a9a137e0f 100644 --- a/server/src/main/java/org/elasticsearch/cluster/service/ClusterApplierService.java +++ b/server/src/main/java/org/elasticsearch/cluster/service/ClusterApplierService.java @@ -446,7 +446,8 @@ private void applyChanges(UpdateTask task, ClusterState previousClusterState, Cl if (nodesDelta.hasChanges() && logger.isInfoEnabled()) { String summary = nodesDelta.shortSummary(); if (summary.length() > 0) { - logger.info("{}, reason: {}", summary, task.source); + logger.info("{}, term: {}, version: {}, reason: {}", + summary, newClusterState.term(), newClusterState.version(), task.source); } } diff --git a/server/src/main/java/org/elasticsearch/cluster/service/MasterService.java b/server/src/main/java/org/elasticsearch/cluster/service/MasterService.java index fbc1a08182109..472ffcd73effd 100644 --- a/server/src/main/java/org/elasticsearch/cluster/service/MasterService.java +++ b/server/src/main/java/org/elasticsearch/cluster/service/MasterService.java @@ -230,7 +230,8 @@ protected void runTasks(TaskInputs taskInputs) { if (nodesDelta.hasChanges() && logger.isInfoEnabled()) { String nodeSummary = nodesDelta.shortSummary(); if (nodeSummary.length() > 0) { - logger.info("{}, reason: {}", summary, nodeSummary); + logger.info("{}, term: {}, version: {}, reason: {}", + summary, newClusterState.term(), newClusterState.version(), nodeSummary); } }