From 25f832e613bb6087327c293b527d5445babb4319 Mon Sep 17 00:00:00 2001 From: gjoranv Date: Fri, 24 Apr 2020 13:12:46 +0200 Subject: LogLevel.DEBUG -> Level.FINE --- .../clustercontroller/core/ClusterStateView.java | 2 +- .../clustercontroller/core/FleetController.java | 10 ++-- .../core/MasterElectionHandler.java | 4 +- .../vespa/clustercontroller/core/NodeInfo.java | 14 +++--- .../clustercontroller/core/NodeStateGatherer.java | 30 ++++++------ .../clustercontroller/core/StateChangeHandler.java | 28 +++++------ .../core/SystemStateBroadcaster.java | 20 ++++---- .../core/database/DatabaseHandler.java | 56 +++++++++++----------- .../core/database/MasterDataGatherer.java | 14 +++--- .../core/database/ZooKeeperDatabase.java | 20 ++++---- .../restapiv2/requests/SetNodeStateRequest.java | 2 +- .../core/rpc/RPCCommunicator.java | 10 ++-- .../clustercontroller/core/rpc/RpcServer.java | 20 ++++---- .../core/status/statuspage/StatusPageServer.java | 8 ++-- .../vespa/clustercontroller/core/DummyVdsNode.java | 48 +++++++++---------- .../vespa/clustercontroller/core/FakeTimer.java | 2 +- .../core/FleetControllerTest.java | 4 +- 17 files changed, 146 insertions(+), 146 deletions(-) (limited to 'clustercontroller-core') diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateView.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateView.java index 0fcb5b65237..eefa7dfb322 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateView.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateView.java @@ -102,7 +102,7 @@ public class ClusterStateView { // The distributor may be old (null), or the distributor may not have updated // to the latest state version just yet. We log here with fine, because it may // also be a symptom of something wrong. - log.log(LogLevel.DEBUG, "Current state version is " + currentStateVersion + + log.log(Level.FINE, "Current state version is " + currentStateVersion + ", while host info received from distributor " + node.getNodeIndex() + " is " + hostVersion); return; diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java index 82fb4c825b9..1e66c397b88 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java @@ -548,7 +548,7 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd responseCode = StatusPageResponse.ResponseCode.INTERNAL_SERVER_ERROR; message = "Internal Server Error"; hiddenMessage = ExceptionUtils.getStackTraceAsString(e);; - log.log(LogLevel.DEBUG, "Unknown exception thrown for request " + httpRequest.getRequest() + + log.log(Level.FINE, "Unknown exception thrown for request " + httpRequest.getRequest() + ": " + hiddenMessage); } @@ -671,7 +671,7 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd // If there's a pending DB store we have not yet been able to store the // current state bundle to ZK and must therefore _not_ allow it to be published. if (database.hasPendingClusterStateMetaDataStore()) { - log.log(LogLevel.DEBUG, "Can't publish current cluster state as it has one or more pending ZooKeeper stores"); + log.log(Level.FINE, "Can't publish current cluster state as it has one or more pending ZooKeeper stores"); return false; } boolean sentAny = false; @@ -682,7 +682,7 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd && currentTime >= nextStateSendTime) { if (currentTime < firstAllowedStateBroadcast) { - log.log(LogLevel.DEBUG, "Not set to broadcast states just yet, but as we have gotten info from all nodes we can do so safely."); + log.log(Level.FINE, "Not set to broadcast states just yet, but as we have gotten info from all nodes we can do so safely."); // Reset timer to only see warning once. firstAllowedStateBroadcast = currentTime; } @@ -1037,7 +1037,7 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd + stateVersionTracker.getCurrentVersion() + " to be in line.", timer.getCurrentTimeInMillis())); long currentTime = timer.getCurrentTimeInMillis(); firstAllowedStateBroadcast = currentTime + options.minTimeBeforeFirstSystemStateBroadcast; - log.log(LogLevel.DEBUG, "At time " + currentTime + " we set first system state broadcast time to be " + log.log(Level.FINE, "At time " + currentTime + " we set first system state broadcast time to be " + options.minTimeBeforeFirstSystemStateBroadcast + " ms after at time " + firstAllowedStateBroadcast + "."); didWork = true; } @@ -1067,7 +1067,7 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd tick(); } } catch (InterruptedException e) { - log.log(LogLevel.DEBUG, "Event thread stopped by interrupt exception: " + e); + log.log(Level.FINE, "Event thread stopped by interrupt exception: " + e); } catch (Throwable t) { t.printStackTrace(); log.log(LogLevel.ERROR, "Fatal error killed fleet controller", t); diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/MasterElectionHandler.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/MasterElectionHandler.java index 205a6e13242..8299e77e01a 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/MasterElectionHandler.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/MasterElectionHandler.java @@ -34,7 +34,7 @@ public class MasterElectionHandler implements MasterInterface { this.nextInLineCount = Integer.MAX_VALUE; // Only a given set of nodes can ever become master if (index > (totalCount - 1) / 2) { - log.log(LogLevel.DEBUG, "Cluster controller " + index + ": We can never become master and will always stay a follower."); + log.log(Level.FINE, "Cluster controller " + index + ": We can never become master and will always stay a follower."); } // Tag current time as when we have not seen any other master. Make sure we're not taking over at once for master that is on the way down masterGoneFromZooKeeperTime = timer.getCurrentTimeInMillis(); @@ -179,7 +179,7 @@ public class MasterElectionHandler implements MasterInterface { if (nextInLineCount != ourPosition) { nextInLineCount = ourPosition; if (ourPosition > 0) { - log.log(LogLevel.DEBUG, "Cluster controller " + index + ": We are now " + getPosition(nextInLineCount) + " in queue to take over being master."); + log.log(Level.FINE, "Cluster controller " + index + ": We are now " + getPosition(nextInLineCount) + " in queue to take over being master."); } } } diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeInfo.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeInfo.java index f98de8ca581..12cfe979511 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeInfo.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeInfo.java @@ -167,7 +167,7 @@ abstract public class NodeInfo implements Comparable { } if (prematureCrashCount != count) { prematureCrashCount = count; - log.log(LogLevel.DEBUG, "Premature crash count on " + toString() + " set to " + count); + log.log(Level.FINE, "Premature crash count on " + toString() + " set to " + count); } } public int getPrematureCrashCount() { return prematureCrashCount; } @@ -309,17 +309,17 @@ abstract public class NodeInfo implements Comparable { if (state.getState().oneOf("dsm") && !reportedState.getState().oneOf("dsm")) { wentDownWithStartTime = reportedState.getStartTimestamp(); wentDownAtClusterState = getNewestSystemStateSent(); - log.log(LogLevel.DEBUG, "Setting going down timestamp of node " + node + " to " + wentDownWithStartTime); + log.log(Level.FINE, "Setting going down timestamp of node " + node + " to " + wentDownWithStartTime); } if (state.getState().equals(State.DOWN) && !reportedState.getState().oneOf("d")) { downStableStateTime = time; - log.log(LogLevel.DEBUG, "Down stable state on " + toString() + " altered to " + time); + log.log(Level.FINE, "Down stable state on " + toString() + " altered to " + time); if (reportedState.getState() == State.INITIALIZING) { recentlyObservedUnstableDuringInit = true; } } else if (state.getState().equals(State.UP) && !reportedState.getState().oneOf("u")) { upStableStateTime = time; - log.log(LogLevel.DEBUG, "Up stable state on " + toString() + " altered to " + time); + log.log(Level.FINE, "Up stable state on " + toString() + " altered to " + time); } if (!state.getState().validReportedNodeState(node.getType())) { throw new IllegalStateException("Trying to set illegal reported node state: " + state); @@ -388,7 +388,7 @@ abstract public class NodeInfo implements Comparable { downgradeToRpcVersion(RPCCommunicator.LEGACY_SET_SYSTEM_STATE2_RPC_VERSION, methodName, timer); return true; } else if (timer.getCurrentTimeInMillis() - 2000 < adjustedVersionTime) { - log.log(LogLevel.DEBUG, () -> "Node " + toString() + " does not support " + methodName + " call. Version already downgraded, so ignoring it."); + log.log(Level.FINE, () -> "Node " + toString() + " does not support " + methodName + " call. Version already downgraded, so ignoring it."); return true; } } @@ -397,7 +397,7 @@ abstract public class NodeInfo implements Comparable { } private void downgradeToRpcVersion(int newVersion, String methodName, Timer timer) { - log.log(LogLevel.DEBUG, () -> String.format("Node %s does not support %s call. Downgrading to version %d.", + log.log(Level.FINE, () -> String.format("Node %s does not support %s call. Downgrading to version %d.", toString(), methodName, newVersion)); version = newVersion; nextAttemptTime = 0; @@ -453,7 +453,7 @@ abstract public class NodeInfo implements Comparable { && (wentDownAtClusterState == null || wentDownAtClusterState.getVersion() < stateBundle.getVersion()) && !stateBundle.getBaselineClusterState().getNodeState(node).getState().oneOf("dsm")) { - log.log(LogLevel.DEBUG, () -> String.format("Clearing going down timestamp of node %s after " + + log.log(Level.FINE, () -> String.format("Clearing going down timestamp of node %s after " + "receiving ack of cluster state bundle %s", node, stateBundle)); wentDownWithStartTime = 0; } diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateGatherer.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateGatherer.java index f1fe29cf0e3..7e7092eb67e 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateGatherer.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateGatherer.java @@ -64,12 +64,12 @@ public class NodeStateGatherer { if (info.getTimeForNextStateRequestAttempt() > currentTime) continue; // too early if (info.getRpcAddress() == null || info.isRpcAddressOutdated()) { // Cannot query state of node without RPC address - log.log(LogLevel.DEBUG, "Not sending getNodeState request to node " + info.getNode() + ": Not in slobrok"); + log.log(Level.FINE, "Not sending getNodeState request to node " + info.getNode() + ": Not in slobrok"); NodeState reportedState = info.getReportedState().clone(); if (( ! reportedState.getState().equals(State.DOWN) && currentTime - info.getRpcAddressOutdatedTimestamp() > maxSlobrokDisconnectGracePeriod) || reportedState.getState().equals(State.STOPPING)) // Don't wait for grace period if we expect node to be stopping { - log.log(LogLevel.DEBUG, "Setting reported state to DOWN " + log.log(Level.FINE, "Setting reported state to DOWN " + (reportedState.getState().equals(State.STOPPING) ? "as node completed stopping." : "as node has been out of slobrok longer than " + maxSlobrokDisconnectGracePeriod + ".")); @@ -102,7 +102,7 @@ public class NodeStateGatherer { NodeInfo info = req.getNodeInfo(); if (!info.isPendingGetNodeStateRequest(req)) { - log.log(LogLevel.DEBUG, "Ignoring getnodestate response from " + info.getNode() + log.log(Level.FINE, "Ignoring getnodestate response from " + info.getNode() + " as request replied to is not the most recent pending request."); continue; } @@ -118,10 +118,10 @@ public class NodeStateGatherer { listener.handleNewNodeState(info, newState.clone()); info.setReportedState(newState, currentTime); } else { - log.log(LogLevel.DEBUG, "Ignoring get node state error. Need to resend"); + log.log(Level.FINE, "Ignoring get node state error. Need to resend"); } } else { - log.log(LogLevel.DEBUG, "Ignoring getnodestate response from " + info.getNode() + " as it was aborted by client"); + log.log(Level.FINE, "Ignoring getnodestate response from " + info.getNode() + " as it was aborted by client"); } continue; @@ -159,7 +159,7 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + "RPC timeout talking to node.", NodeEvent.Type.REPORTED, currentTime), LogLevel.INFO); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setDescription(msg); } else if (req.getReply().getReturnCode() == ErrorCode.CONNECTION) { @@ -174,7 +174,7 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), LogLevel.INFO); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setState(State.DOWN); @@ -186,7 +186,7 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), LogLevel.INFO); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setState(State.DOWN).setDescription(msg); } else if (msg.equals("Connection timed out")) { @@ -194,14 +194,14 @@ public class NodeStateGatherer { msg = "Connection error: Timeout"; eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), LogLevel.INFO); } else { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } } else { msg = "Connection error: " + reason; if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), LogLevel.WARNING); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setDescription(msg); } @@ -212,7 +212,7 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), LogLevel.WARNING); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setDescription(msg); } @@ -223,19 +223,19 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), LogLevel.WARNING); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setState(State.DOWN).setDescription(msg + ": get node state"); } else if (req.getReply().getReturnCode() == 75004) { String msg = "Node refused to answer RPC request and is likely stopping: " + req.getReply().getReturnMessage(); // The node is shutting down and is not accepting requests from anyone if (info.getReportedState().getState().equals(State.STOPPING)) { - log.log(LogLevel.DEBUG, "Failed to get node state from " + info + " because it is still shutting down."); + log.log(Level.FINE, "Failed to get node state from " + info + " because it is still shutting down."); } else { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), LogLevel.INFO); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } } newState.setState(State.STOPPING).setDescription(msg); @@ -244,7 +244,7 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), LogLevel.WARNING); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(LogLevel.DEBUG, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setState(State.DOWN).setDescription(msg); } diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java index a8aa15d5959..e9005509c52 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java @@ -51,7 +51,7 @@ public class StateChangeHandler { final DatabaseHandler database, final DatabaseHandler.Context dbContext) throws InterruptedException { int startTimestampsReset = 0; - log.log(LogLevel.DEBUG, String.format("handleAllDistributorsInSync invoked for state version %d", currentState.getVersion())); + log.log(Level.FINE, String.format("handleAllDistributorsInSync invoked for state version %d", currentState.getVersion())); for (NodeType nodeType : NodeType.getTypes()) { for (ConfiguredNode configuredNode : nodes) { final Node node = new Node(nodeType, configuredNode.index()); @@ -60,19 +60,19 @@ public class StateChangeHandler { if (nodeInfo != null && nodeState != null) { if (nodeState.getStartTimestamp() > nodeInfo.getStartTimestamp()) { if (log.isLoggable(LogLevel.DEBUG)) { - log.log(LogLevel.DEBUG, String.format("Storing away new start timestamp for node %s (%d)", + log.log(Level.FINE, String.format("Storing away new start timestamp for node %s (%d)", node, nodeState.getStartTimestamp())); } nodeInfo.setStartTimestamp(nodeState.getStartTimestamp()); } if (nodeState.getStartTimestamp() > 0) { if (log.isLoggable(LogLevel.DEBUG)) { - log.log(LogLevel.DEBUG, String.format("Resetting timestamp in cluster state for node %s", node)); + log.log(Level.FINE, String.format("Resetting timestamp in cluster state for node %s", node)); } ++startTimestampsReset; } } else if (log.isLoggable(LogLevel.DEBUG)) { - log.log(LogLevel.DEBUG, node + ": " + + log.log(Level.FINE, node + ": " + (nodeInfo == null ? "null" : nodeInfo.getStartTimestamp()) + ", " + (nodeState == null ? "null" : nodeState.getStartTimestamp())); } @@ -85,7 +85,7 @@ public class StateChangeHandler { stateMayHaveChanged = true; database.saveStartTimestamps(dbContext); } else { - log.log(LogLevel.DEBUG, "Found no start timestamps to reset in cluster state."); + log.log(Level.FINE, "Found no start timestamps to reset in cluster state."); } } @@ -147,13 +147,13 @@ public class StateChangeHandler { if (reportedState.getMinUsedBits() != currentState.getMinUsedBits()) { final int oldCount = currentState.getMinUsedBits(); final int newCount = reportedState.getMinUsedBits(); - log.log(LogLevel.DEBUG, + log.log(Level.FINE, String.format("Altering node state to reflect that min distribution bit count has changed from %d to %d", oldCount, newCount)); eventLog.add(NodeEvent.forBaseline(node, String.format("Altered min distribution bit count from %d to %d", oldCount, newCount), NodeEvent.Type.CURRENT, currentTime), isMaster); } else if (log.isLoggable(LogLevel.DEBUG)) { - log.log(LogLevel.DEBUG, String.format("Not altering state of %s in cluster state because new state is too similar: %s", + log.log(Level.FINE, String.format("Not altering state of %s in cluster state because new state is too similar: %s", node, currentState.getTextualDifference(reportedState))); } @@ -181,12 +181,12 @@ public class StateChangeHandler { } if (node.getReportedState().getState().equals(State.STOPPING)) { - log.log(LogLevel.DEBUG, "Node " + node.getNode() + " is no longer in slobrok. Was in stopping state, so assuming it has shut down normally. Setting node down"); + log.log(Level.FINE, "Node " + node.getNode() + " is no longer in slobrok. Was in stopping state, so assuming it has shut down normally. Setting node down"); NodeState ns = node.getReportedState().clone(); ns.setState(State.DOWN); handleNewReportedNodeState(currentClusterState, node, ns.clone(), nodeListener); } else { - log.log(LogLevel.DEBUG, "Node " + node.getNode() + " no longer in slobrok was in state " + node.getReportedState() + ". Waiting to see if it reappears in slobrok"); + log.log(Level.FINE, "Node " + node.getNode() + " no longer in slobrok was in state " + node.getReportedState() + ". Waiting to see if it reappears in slobrok"); } stateMayHaveChanged = true; @@ -209,7 +209,7 @@ public class StateChangeHandler { stateMayHaveChanged = true; if (log.isLoggable(LogLevel.DEBUG)) { - log.log(LogLevel.DEBUG, String.format("Got new wanted nodestate for %s: %s", node, currentState.getTextualDifference(proposedState))); + log.log(Level.FINE, String.format("Got new wanted nodestate for %s: %s", node, currentState.getTextualDifference(proposedState))); } // Should be checked earlier before state was set in cluster assert(proposedState.getState().validWantedNodeState(node.getNode().getType())); @@ -321,11 +321,11 @@ public class StateChangeHandler { if (mayResetCrashCounterOnStableUpNode(currentTime, node, lastReportedState)) { node.setPrematureCrashCount(0); - log.log(LogLevel.DEBUG, "Resetting premature crash count on node " + node + " as it has been up for a long time."); + log.log(Level.FINE, "Resetting premature crash count on node " + node + " as it has been up for a long time."); triggeredAnyTimers = true; } else if (mayResetCrashCounterOnStableDownNode(currentTime, node, lastReportedState)) { node.setPrematureCrashCount(0); - log.log(LogLevel.DEBUG, "Resetting premature crash count on node " + node + " as it has been down for a long time."); + log.log(Level.FINE, "Resetting premature crash count on node " + node + " as it has been down for a long time."); triggeredAnyTimers = true; } @@ -416,7 +416,7 @@ public class StateChangeHandler { final NodeStateOrHostInfoChangeHandler nodeListener) { final long timeNow = timer.getCurrentTimeInMillis(); if (log.isLoggable(LogLevel.DEBUG)) { - log.log(LogLevel.DEBUG, String.format("Finding new cluster state entry for %s switching state %s", + log.log(Level.FINE, String.format("Finding new cluster state entry for %s switching state %s", node, currentState.getTextualDifference(reportedState))); } @@ -482,7 +482,7 @@ public class StateChangeHandler { if (nodeUpToDownEdge(node, currentState, reportedState)) { node.setTransitionTime(timeNow); if (node.getUpStableStateTime() + stableStateTimePeriod > timeNow && !isControlledShutdown(reportedState)) { - log.log(LogLevel.DEBUG, "Stable state: " + node.getUpStableStateTime() + " + " + stableStateTimePeriod + " > " + timeNow); + log.log(Level.FINE, "Stable state: " + node.getUpStableStateTime() + " + " + stableStateTimePeriod + " > " + timeNow); eventLog.add(NodeEvent.forBaseline(node, String.format("Stopped or possibly crashed after %d ms, which is before " + "stable state time period. Premature crash count is now %d.", diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/SystemStateBroadcaster.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/SystemStateBroadcaster.java index 55fc0294dd7..d6b8364954b 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/SystemStateBroadcaster.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/SystemStateBroadcaster.java @@ -92,11 +92,11 @@ public class SystemStateBroadcaster { // NO_SUCH_METHOD implies node is on a version that does not understand explicit activations // and it has already merrily started using the state version. Treat as if it had been ACKed. if (reply.getReturnCode() != ErrorCode.NO_SUCH_METHOD) { - log.log(LogLevel.DEBUG, () -> String.format("Activation NACK for node %s with version %d, message %s", + log.log(Level.FINE, () -> String.format("Activation NACK for node %s with version %d, message %s", info, version, reply.getReturnMessage())); success = false; } else { - log.log(LogLevel.DEBUG, () -> String.format("Node %s did not understand state activation RPC; " + + log.log(Level.FINE, () -> String.format("Node %s did not understand state activation RPC; " + "implicitly treating state %d as activated on node", info, version)); } } else if (reply.getActualVersion() != version) { @@ -109,7 +109,7 @@ public class SystemStateBroadcaster { version, info, reply.getActualVersion())); success = false; } else { - log.log(LogLevel.DEBUG, () -> String.format("Node %s reports successful activation of state " + + log.log(Level.FINE, () -> String.format("Node %s reports successful activation of state " + "version %d", info, version)); } info.setSystemStateVersionActivationAcked(version, success); @@ -140,7 +140,7 @@ public class SystemStateBroadcaster { } } else { info.setClusterStateBundleVersionAcknowledged(version, true); - log.log(LogLevel.DEBUG, () -> String.format("Node %s ACKed system state version %d.", info, version)); + log.log(Level.FINE, () -> String.format("Node %s ACKed system state version %d.", info, version)); lastErrorReported.remove(info.getNode()); } } @@ -216,7 +216,7 @@ public class SystemStateBroadcaster { if (!anyDistributorsNeedStateBundle && (currentStateVersion > lastStateVersionBundleAcked)) { markCurrentClusterStateBundleAsReceivedByAllDistributors(); if (clusterStateBundle.deferredActivation()) { - log.log(LogLevel.DEBUG, () -> String.format("All distributors have ACKed cluster state " + + log.log(Level.FINE, () -> String.format("All distributors have ACKed cluster state " + "version %d, sending activation", currentStateVersion)); } else { markCurrentClusterStateAsConverged(database, dbContext, fleetController); @@ -235,7 +235,7 @@ public class SystemStateBroadcaster { if (!anyDistributorsNeedActivation && (currentStateVersion > lastClusterStateVersionConverged)) { markCurrentClusterStateAsConverged(database, dbContext, fleetController); } else { - log.log(LogLevel.DEBUG, () -> String.format("distributors still need activation in state %d (last converged: %d)", + log.log(Level.FINE, () -> String.format("distributors still need activation in state %d (last converged: %d)", currentStateVersion, lastClusterStateVersionConverged)); } } @@ -245,7 +245,7 @@ public class SystemStateBroadcaster { } private void markCurrentClusterStateAsConverged(DatabaseHandler database, DatabaseHandler.Context dbContext, FleetController fleetController) throws InterruptedException { - log.log(LogLevel.DEBUG, "All distributors have newest clusterstate, updating start timestamps in zookeeper and clearing them from cluster state"); + log.log(Level.FINE, "All distributors have newest clusterstate, updating start timestamps in zookeeper and clearing them from cluster state"); lastClusterStateVersionConverged = clusterStateBundle.getVersion(); lastClusterStateBundleConverged = clusterStateBundle; fleetController.handleAllDistributorsInSync(database, dbContext); @@ -272,11 +272,11 @@ public class SystemStateBroadcaster { if (nodeNeedsToObserveStartupTimestamps(node)) { // TODO this is the same for all nodes, compute only once ClusterStateBundle modifiedBundle = clusterStateBundle.cloneWithMapper(state -> buildModifiedClusterState(state, dbContext)); - log.log(LogLevel.DEBUG, () -> String.format("Sending modified cluster state version %d" + + log.log(Level.FINE, () -> String.format("Sending modified cluster state version %d" + " to node %s: %s", baselineState.getVersion(), node, modifiedBundle)); communicator.setSystemState(modifiedBundle, node, setClusterStateWaiter); } else { - log.log(LogLevel.DEBUG, () -> String.format("Sending system state version %d to node %s. " + + log.log(Level.FINE, () -> String.format("Sending system state version %d to node %s. " + "(went down time %d, node start time %d)", baselineState.getVersion(), node, node.getWentDownWithStartTime(), node.getStartTimestamp())); communicator.setSystemState(clusterStateBundle, node, setClusterStateWaiter); @@ -297,7 +297,7 @@ public class SystemStateBroadcaster { var recipients = resolveStateActivationSendSet(dbContext); for (NodeInfo node : recipients) { - log.log(LogLevel.DEBUG, () -> String.format("Sending cluster state activation to node %s for version %d", + log.log(Level.FINE, () -> String.format("Sending cluster state activation to node %s for version %d", node, clusterStateBundle.getVersion())); communicator.activateClusterStateVersion(clusterStateBundle.getVersion(), node, activateClusterStateVersionWaiter); } diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/DatabaseHandler.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/DatabaseHandler.java index 78e71d63e6a..a7570ce5028 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/DatabaseHandler.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/DatabaseHandler.java @@ -52,7 +52,7 @@ public class DatabaseHandler { } private class DatabaseListener implements Database.DatabaseListener { public void handleZooKeeperSessionDown() { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Lost contact with zookeeper server"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Lost contact with zookeeper server"); synchronized(monitor) { lostZooKeeperConnectionEvent = true; monitor.notifyAll(); @@ -62,7 +62,7 @@ public class DatabaseHandler { public void handleMasterData(Map data) { synchronized (monitor) { if (masterDataEvent != null && masterDataEvent.equals(data)) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": New master data was the same as the last one. Not responding to it"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": New master data was the same as the last one. Not responding to it"); } else { masterDataEvent = data; } @@ -133,7 +133,7 @@ public class DatabaseHandler { currentlyStored.clear(); pendingStore.clear(); pendingStore.masterVote = currentVote; - log.log(LogLevel.DEBUG, "Cleared session metadata. Pending master vote is now " + log.log(Level.FINE, "Cleared session metadata. Pending master vote is now " + pendingStore.masterVote); } @@ -149,7 +149,7 @@ public class DatabaseHandler { public void setZooKeeperSessionTimeout(int timeout) { if (timeout == zooKeeperSessionTimeout) return; - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Got new ZooKeeper session timeout of " + timeout + " milliseconds."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Got new ZooKeeper session timeout of " + timeout + " milliseconds."); zooKeeperSessionTimeout = timeout; reset(); } @@ -176,7 +176,7 @@ public class DatabaseHandler { database = databaseFactory.create(params); } } catch (KeeperException.NodeExistsException e) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Cannot create ephemeral fleetcontroller node. ZooKeeper server " + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Cannot create ephemeral fleetcontroller node. ZooKeeper server " + "not seen old fleetcontroller instance disappear? It already exists. Will retry later: " + e.getMessage()); } catch (InterruptedException e) { throw (InterruptedException) new InterruptedException("Interrupted").initCause(e); @@ -202,17 +202,17 @@ public class DatabaseHandler { synchronized (monitor) { if (zooKeeperAddress == null) return false; // If not using zookeeper no work to be done if (lostZooKeeperConnectionEvent) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": doNextZooKeeperTask(): lost connection"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": doNextZooKeeperTask(): lost connection"); context.getFleetController().lostDatabaseConnection(); lostZooKeeperConnectionEvent = false; didWork = true; if (masterDataEvent != null) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Had new master data queued on disconnect. Removing master data event"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Had new master data queued on disconnect. Removing master data event"); masterDataEvent = null; } } if (masterDataEvent != null) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": doNextZooKeeperTask(): new master data"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": doNextZooKeeperTask(): new master data"); if (!masterDataEvent.containsKey(nodeIndex)) { Integer currentVote = (pendingStore.masterVote != null ? pendingStore.masterVote : currentlyStored.masterVote); assert(currentVote != null); @@ -257,10 +257,10 @@ public class DatabaseHandler { boolean didWork = false; if (pendingStore.masterVote != null) { didWork = true; - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Attempting to store master vote " + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Attempting to store master vote " + pendingStore.masterVote + " into zookeeper."); if (database.storeMasterVote(pendingStore.masterVote)) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Managed to store master vote " + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Managed to store master vote " + pendingStore.masterVote + " into zookeeper."); currentlyStored.masterVote = pendingStore.masterVote; pendingStore.masterVote = null; @@ -271,7 +271,7 @@ public class DatabaseHandler { } if (pendingStore.lastSystemStateVersion != null) { didWork = true; - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Attempting to store last system state version " + pendingStore.lastSystemStateVersion + " into zookeeper."); if (database.storeLatestSystemStateVersion(pendingStore.lastSystemStateVersion)) { @@ -283,7 +283,7 @@ public class DatabaseHandler { } if (pendingStore.startTimestamps != null) { didWork = true; - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Attempting to store " + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Attempting to store " + pendingStore.startTimestamps.size() + " start timestamps into zookeeper."); if (database.storeStartTimestamps(pendingStore.startTimestamps)) { currentlyStored.startTimestamps = pendingStore.startTimestamps; @@ -294,7 +294,7 @@ public class DatabaseHandler { } if (pendingStore.wantedStates != null) { didWork = true; - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Attempting to store " + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Attempting to store " + pendingStore.wantedStates.size() + " wanted states into zookeeper."); if (database.storeWantedStates(pendingStore.wantedStates)) { currentlyStored.wantedStates = pendingStore.wantedStates; @@ -316,7 +316,7 @@ public class DatabaseHandler { } public void setMasterVote(Context context, int wantedMasterCandidate) throws InterruptedException { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Checking if master vote has been updated and need to be stored."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Checking if master vote has been updated and need to be stored."); // Schedule a write if one of the following is true: // - There is already a pending vote to be written, that may have been written already without our knowledge // - We don't know what is actually stored now @@ -324,14 +324,14 @@ public class DatabaseHandler { if (pendingStore.masterVote != null || currentlyStored.masterVote == null || currentlyStored.masterVote != wantedMasterCandidate) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Scheduling master vote " + wantedMasterCandidate + " to be stored in zookeeper."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Scheduling master vote " + wantedMasterCandidate + " to be stored in zookeeper."); pendingStore.masterVote = wantedMasterCandidate; doNextZooKeeperTask(context); } } public void saveLatestSystemStateVersion(Context context, int version) throws InterruptedException { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Checking if latest system state version has been updated and need to be stored."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Checking if latest system state version has been updated and need to be stored."); // Schedule a write if one of the following is true: // - There is already a pending vote to be written, that may have been written already without our knowledge // - We don't know what is actually stored now @@ -339,14 +339,14 @@ public class DatabaseHandler { if (pendingStore.lastSystemStateVersion != null || currentlyStored.lastSystemStateVersion == null || currentlyStored.lastSystemStateVersion != version) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Scheduling new last system state version " + version + " to be stored in zookeeper."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Scheduling new last system state version " + version + " to be stored in zookeeper."); pendingStore.lastSystemStateVersion = version; doNextZooKeeperTask(context); } } public int getLatestSystemStateVersion() throws InterruptedException { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Retrieving latest system state version."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Retrieving latest system state version."); synchronized (databaseMonitor) { if (database != null && !database.isClosed()) { currentlyStored.lastSystemStateVersion = database.retrieveLatestSystemStateVersion(); @@ -363,7 +363,7 @@ public class DatabaseHandler { } public void saveLatestClusterStateBundle(Context context, ClusterStateBundle clusterStateBundle) throws InterruptedException { - log.log(LogLevel.DEBUG, () -> String.format("Fleetcontroller %d: Scheduling bundle %s to be saved to ZooKeeper", nodeIndex, clusterStateBundle)); + log.log(Level.FINE, () -> String.format("Fleetcontroller %d: Scheduling bundle %s to be saved to ZooKeeper", nodeIndex, clusterStateBundle)); pendingStore.clusterStateBundle = clusterStateBundle; doNextZooKeeperTask(context); } @@ -378,7 +378,7 @@ public class DatabaseHandler { } public ClusterStateBundle getLatestClusterStateBundle() throws InterruptedException { - log.log(LogLevel.DEBUG, () -> String.format("Fleetcontroller %d: Retrieving latest cluster state bundle from ZooKeeper", nodeIndex)); + log.log(Level.FINE, () -> String.format("Fleetcontroller %d: Retrieving latest cluster state bundle from ZooKeeper", nodeIndex)); synchronized (databaseMonitor) { if (database != null && !database.isClosed()) { return database.retrieveLastPublishedStateBundle(); @@ -389,7 +389,7 @@ public class DatabaseHandler { } public void saveWantedStates(Context context) throws InterruptedException { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Checking whether wanted states have changed compared to zookeeper version."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Checking whether wanted states have changed compared to zookeeper version."); Map wantedStates = new TreeMap<>(); for (NodeInfo info : context.getCluster().getNodeInfo()) { if (!info.getUserWantedState().equals(new NodeState(info.getNode().getType(), State.UP))) { @@ -403,14 +403,14 @@ public class DatabaseHandler { if (pendingStore.wantedStates != null || currentlyStored.wantedStates == null || !currentlyStored.wantedStates.equals(wantedStates)) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Scheduling new wanted states to be stored into zookeeper."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Scheduling new wanted states to be stored into zookeeper."); pendingStore.wantedStates = wantedStates; doNextZooKeeperTask(context); } } public boolean loadWantedStates(Context context) throws InterruptedException { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Retrieving node wanted states."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Retrieving node wanted states."); synchronized (databaseMonitor) { if (database != null && !database.isClosed()) { currentlyStored.wantedStates = database.retrieveWantedStates(); @@ -421,7 +421,7 @@ public class DatabaseHandler { if (usingZooKeeper()) { // We get here if the ZooKeeper client has lost the connection to ZooKeeper. // TODO: Should instead fail the tick until connected!? - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Failed to retrieve wanted states from ZooKeeper. Assuming UP for all nodes."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Failed to retrieve wanted states from ZooKeeper. Assuming UP for all nodes."); } wantedStates = new TreeMap<>(); } @@ -435,7 +435,7 @@ public class DatabaseHandler { context.getNodeStateUpdateListener().handleNewWantedNodeState(nodeInfo, wantedState); altered = true; } - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Node " + node + " has wanted state " + wantedState); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Node " + node + " has wanted state " + wantedState); } // Remove wanted state from any node having a wanted state set that is no longer valid @@ -451,13 +451,13 @@ public class DatabaseHandler { } public void saveStartTimestamps(Context context) throws InterruptedException { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Scheduling start timestamps to be stored into zookeeper."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Scheduling start timestamps to be stored into zookeeper."); pendingStore.startTimestamps = context.getCluster().getStartTimestamps(); doNextZooKeeperTask(context); } public boolean loadStartTimestamps(ContentCluster cluster) throws InterruptedException { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Retrieving start timestamps"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Retrieving start timestamps"); synchronized (databaseMonitor) { if (database == null || database.isClosed()) { return false; @@ -473,7 +473,7 @@ public class DatabaseHandler { } for (Map.Entry e : startTimestamps.entrySet()) { cluster.setStartTimestamp(e.getKey(), e.getValue()); - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Node " + e.getKey() + " has start timestamp " + e.getValue()); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Node " + e.getKey() + " has start timestamp " + e.getValue()); } return true; } diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/MasterDataGatherer.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/MasterDataGatherer.java index 0fdfd46dec5..28527162b71 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/MasterDataGatherer.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/MasterDataGatherer.java @@ -68,10 +68,10 @@ public class MasterDataGatherer { case NodeDeleted: // We get this event when fleetcontrollers shut down and node in dir disappears. But it should also trigger a NodeChildrenChanged event, so // ignoring this one. - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Node deleted event gotten. Ignoring it, expecting a NodeChildrenChanged event too."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Node deleted event gotten. Ignoring it, expecting a NodeChildrenChanged event too."); break; case None: - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Got ZooKeeper event None."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Got ZooKeeper event None."); } } } @@ -90,7 +90,7 @@ public class MasterDataGatherer { for (String node : nodes) { int index = Integer.parseInt(node); nextMasterData.put(index, null); - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Attempting to fetch data in node '" + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Attempting to fetch data in node '" + zooKeeperRoot + index + "' to see vote"); session.getData(zooKeeperRoot + "indexes/" + index, changeWatcher, nodeListener, null); // Invocation of cycleCompleted() for fully accumulated election state will happen @@ -127,7 +127,7 @@ public class MasterDataGatherer { Integer value = Integer.valueOf(data); if (nextMasterData.containsKey(index)) { if (value.equals(nextMasterData.get(index))) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Got vote from fleetcontroller " + index + ", which already was " + value + "."); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Got vote from fleetcontroller " + index + ", which already was " + value + "."); } else { log.log(LogLevel.INFO, "Fleetcontroller " + nodeIndex + ": Got vote from fleetcontroller " + index + ". Altering vote from " + nextMasterData.get(index) + " to " + value + "."); nextMasterData.put(index, value); @@ -143,7 +143,7 @@ public class MasterDataGatherer { } } } - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Got votes for all fleetcontrollers. Sending event with new fleet data for update"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Got votes for all fleetcontrollers. Sending event with new fleet data for update"); cycleCompleted(); } } @@ -173,14 +173,14 @@ public class MasterDataGatherer { Map copy; synchronized (nextMasterData) { if (nextMasterData.equals(masterData)) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": No change in master data detected, not sending it on"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": No change in master data detected, not sending it on"); // for(Integer i : nextMasterData.keySet()) { System.err.println(i + " -> " + nextMasterData.get(i)); } return; } masterData = new TreeMap(nextMasterData); copy = masterData; } - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Got new master data, sending it on"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Got new master data, sending it on"); listener.handleMasterData(copy); } diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/ZooKeeperDatabase.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/ZooKeeperDatabase.java index 453216039d9..a2d370a6fe8 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/ZooKeeperDatabase.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/ZooKeeperDatabase.java @@ -114,13 +114,13 @@ public class ZooKeeperDatabase extends Database { private void createNode(String prefix, String nodename, byte value[]) throws KeeperException, InterruptedException { try{ if (session.exists(prefix + nodename, false) != null) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Zookeeper node '" + prefix + nodename + "' already exists. Not creating it"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Zookeeper node '" + prefix + nodename + "' already exists. Not creating it"); return; } session.create(prefix + nodename, value, acl, CreateMode.PERSISTENT); - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Created zookeeper node '" + prefix + nodename + "'"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Created zookeeper node '" + prefix + nodename + "'"); } catch (KeeperException.NodeExistsException e) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Node to create existed, " + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Node to create existed, " + "but this is normal as other nodes may create them at the same time."); } } @@ -162,7 +162,7 @@ public class ZooKeeperDatabase extends Database { public void close() { sessionOpen = false; try{ - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Trying to close ZooKeeper session 0x" + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Trying to close ZooKeeper session 0x" + Long.toHexString(session.getSessionId())); session.close(); } catch (InterruptedException e) { @@ -217,7 +217,7 @@ public class ZooKeeperDatabase extends Database { public Integer retrieveLatestSystemStateVersion() throws InterruptedException { Stat stat = new Stat(); try{ - log.log(LogLevel.DEBUG, () -> String.format("Fleetcontroller %d: Fetching latest cluster state at '%slatestversion'", + log.log(Level.FINE, () -> String.format("Fleetcontroller %d: Fetching latest cluster state at '%slatestversion'", nodeIndex, zooKeeperRoot)); byte[] data = session.getData(zooKeeperRoot + "latestversion", false, stat); lastKnownStateVersionZNodeVersion = stat.getVersion(); @@ -249,7 +249,7 @@ public class ZooKeeperDatabase extends Database { } byte val[] = sb.toString().getBytes(utf8); try{ - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Storing wanted states at '" + zooKeeperRoot + "wantedstates'"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Storing wanted states at '" + zooKeeperRoot + "wantedstates'"); session.setData(zooKeeperRoot + "wantedstates", val, -1); return true; } catch (InterruptedException e) { @@ -262,7 +262,7 @@ public class ZooKeeperDatabase extends Database { public Map retrieveWantedStates() throws InterruptedException { try{ - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Fetching wanted states at '" + zooKeeperRoot + "wantedstates'"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Fetching wanted states at '" + zooKeeperRoot + "wantedstates'"); Stat stat = new Stat(); byte[] data = session.getData(zooKeeperRoot + "wantedstates", false, stat); Map wanted = new TreeMap<>(); @@ -300,7 +300,7 @@ public class ZooKeeperDatabase extends Database { } byte val[] = sb.toString().getBytes(utf8); try{ - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Storing start timestamps at '" + zooKeeperRoot + "starttimestamps"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Storing start timestamps at '" + zooKeeperRoot + "starttimestamps"); session.setData(zooKeeperRoot + "starttimestamps", val, -1); return true; } catch (InterruptedException e) { @@ -314,7 +314,7 @@ public class ZooKeeperDatabase extends Database { @Override public Map retrieveStartTimestamps() throws InterruptedException { try{ - log.log(LogLevel.DEBUG, "Fleetcontroller " + nodeIndex + ": Fetching start timestamps at '" + zooKeeperRoot + "starttimestamps'"); + log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Fetching start timestamps at '" + zooKeeperRoot + "starttimestamps'"); Stat stat = new Stat(); byte[] data = session.getData(zooKeeperRoot + "starttimestamps", false, stat); Map wanted = new TreeMap(); @@ -347,7 +347,7 @@ public class ZooKeeperDatabase extends Database { EnvelopedClusterStateBundleCodec envelopedBundleCodec = new SlimeClusterStateBundleCodec(); byte[] encodedBundle = envelopedBundleCodec.encodeWithEnvelope(stateBundle); try{ - log.log(LogLevel.DEBUG, () -> String.format("Fleetcontroller %d: Storing published state bundle %s at " + + log.log(Level.FINE, () -> String.format("Fleetcontroller %d: Storing published state bundle %s at " + "'%spublished_state_bundle' with expected znode version %d", nodeIndex, stateBundle, zooKeeperRoot, lastKnownStateBundleZNodeVersion)); var stat = session.setData(zooKeeperRoot + "published_state_bundle", encodedBundle, lastKnownStateBundleZNodeVersion); diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/restapiv2/requests/SetNodeStateRequest.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/restapiv2/requests/SetNodeStateRequest.java index 64ca08dc997..94b1a9e1fbc 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/restapiv2/requests/SetNodeStateRequest.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/restapiv2/requests/SetNodeStateRequest.java @@ -117,7 +117,7 @@ public class SetNodeStateRequest extends Request { NodeStateChangeChecker.Result result = cluster.calculateEffectOfNewState( node, currentClusterState, condition, wantedState, newWantedState); - log.log(LogLevel.DEBUG, "node=" + node + + log.log(Level.FINE, "node=" + node + " current-cluster-state=" + currentClusterState + // Includes version in output format " condition=" + condition + " wanted-state=" + wantedState + diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RPCCommunicator.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RPCCommunicator.java index a2619692961..d8a72a9272c 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RPCCommunicator.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RPCCommunicator.java @@ -110,7 +110,7 @@ public class RPCCommunicator implements Communicator { public void getNodeState(NodeInfo node, Waiter externalWaiter) { Target connection = getConnection(node); if ( ! connection.isValid()) { - log.log(LogLevel.DEBUG, () -> String.format("Connection to '%s' could not be created.", node.getRpcAddress())); + log.log(Level.FINE, () -> String.format("Connection to '%s' could not be created.", node.getRpcAddress())); } NodeState currentState = node.getReportedState(); Request req = new Request("getnodestate3"); @@ -138,7 +138,7 @@ public class RPCCommunicator implements Communicator { Target connection = getConnection(node); if ( ! connection.isValid()) { - log.log(LogLevel.DEBUG, () -> String.format("Connection to '%s' could not be created.", node.getRpcAddress())); + log.log(Level.FINE, () -> String.format("Connection to '%s' could not be created.", node.getRpcAddress())); return; } int nodeVersion = node.getVersion(); @@ -156,7 +156,7 @@ public class RPCCommunicator implements Communicator { v.add(new DataValue(encodedBundle.getCompression().data())); } - log.log(LogLevel.DEBUG, () -> String.format("Sending '%s' RPC to %s for state version %d", + log.log(Level.FINE, () -> String.format("Sending '%s' RPC to %s for state version %d", req.methodName(), node.getRpcAddress(), stateBundle.getVersion())); RPCSetClusterStateRequest stateRequest = new RPCSetClusterStateRequest(node, req, baselineState.getVersion()); waiter.setRequest(stateRequest); @@ -171,14 +171,14 @@ public class RPCCommunicator implements Communicator { Target connection = getConnection(node); if ( ! connection.isValid()) { - log.log(LogLevel.DEBUG, () -> String.format("Connection to '%s' could not be created.", node.getRpcAddress())); + log.log(Level.FINE, () -> String.format("Connection to '%s' could not be created.", node.getRpcAddress())); return; } var req = new Request(ACTIVATE_CLUSTER_STATE_VERSION_RPC_METHOD_NAME); req.parameters().add(new Int32Value(clusterStateVersion)); - log.log(LogLevel.DEBUG, () -> String.format("Sending '%s' RPC to %s for state version %d", + log.log(Level.FINE, () -> String.format("Sending '%s' RPC to %s for state version %d", req.methodName(), node.getRpcAddress(), clusterStateVersion)); var activationRequest = new RPCActivateClusterStateVersionRequest(node, req, clusterStateVersion); waiter.setRequest(activationRequest); diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RpcServer.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RpcServer.java index d368d377aee..e3ae95b0abe 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RpcServer.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RpcServer.java @@ -97,13 +97,13 @@ public class RpcServer { public void connect() throws ListenFailedException, UnknownHostException { disconnect(); - log.log(LogLevel.DEBUG, "Fleetcontroller " + fleetControllerIndex + ": Connecting RPC server."); + log.log(Level.FINE, "Fleetcontroller " + fleetControllerIndex + ": Connecting RPC server."); if (supervisor != null) disconnect(); supervisor = new Supervisor(new Transport()); addMethods(); - log.log(LogLevel.DEBUG, "Fleetcontroller " + fleetControllerIndex + ": Attempting to bind to port " + port); + log.log(Level.FINE, "Fleetcontroller " + fleetControllerIndex + ": Attempting to bind to port " + port); acceptor = supervisor.listen(new Spec(port)); - log.log(LogLevel.DEBUG, "Fleetcontroller " + fleetControllerIndex + ": RPC server listening to port " + acceptor.port()); + log.log(Level.FINE, "Fleetcontroller " + fleetControllerIndex + ": RPC server listening to port " + acceptor.port()); StringBuffer slobroks = new StringBuffer("("); for (String s : slobrokConnectionSpecs) { slobroks.append(" ").append(s); @@ -123,7 +123,7 @@ public class RpcServer { public void disconnect() { if (register != null) { - log.log(LogLevel.DEBUG, "Fleetcontroller " + fleetControllerIndex + ": Disconnecting RPC server."); + log.log(Level.FINE, "Fleetcontroller " + fleetControllerIndex + ": Disconnecting RPC server."); register.shutdown(); register = null; } @@ -218,7 +218,7 @@ public class RpcServer { } try{ if (req.methodName().equals("getMaster")) { - log.log(LogLevel.DEBUG, "Resolving RPC getMaster request"); + log.log(Level.FINE, "Resolving RPC getMaster request"); Integer master = masterHandler.getMaster(); String masterReason = masterHandler.getMasterReason(); req.returnValues().add(new Int32Value(master == null ? -1 : master)); @@ -230,7 +230,7 @@ public class RpcServer { throw new IllegalStateException("Refusing to answer RPC calls as we are not the master fleetcontroller."); } if (req.methodName().equals("getNodeList")) { - log.log(LogLevel.DEBUG, "Resolving RPC getNodeList request"); + log.log(Level.FINE, "Resolving RPC getNodeList request"); List slobrok = new ArrayList(); List rpc = new ArrayList(); for(NodeInfo node : cluster.getNodeInfo()) { @@ -244,12 +244,12 @@ public class RpcServer { req.returnValues().add(new StringArray(rpc.toArray(new String[rpc.size()]))); req.returnRequest(); } else if (req.methodName().equals("getSystemState")) { - log.log(LogLevel.DEBUG, "Resolving RPC getSystemState request"); + log.log(Level.FINE, "Resolving RPC getSystemState request"); req.returnValues().add(new StringValue("")); req.returnValues().add(new StringValue(systemState.toString(true))); req.returnRequest(); } else if (req.methodName().equals("getNodeState")) { - log.log(LogLevel.DEBUG, "Resolving RPC getNodeState request"); + log.log(Level.FINE, "Resolving RPC getNodeState request"); NodeType nodeType = NodeType.get(req.parameters().get(0).asString()); int nodeIndex = req.parameters().get(1).asInt32(); @@ -296,7 +296,7 @@ public class RpcServer { changeListener.handleNewWantedNodeState(node, nodeState); } else { message = "Node " + node + " already had wanted state " + nodeState.toString(); - log.log(LogLevel.DEBUG, message); + log.log(Level.FINE, message); } req.returnValues().add(new StringValue(message)); req.returnRequest(); @@ -309,7 +309,7 @@ public class RpcServer { if (log.isLoggable(LogLevel.DEBUG)) { StringWriter sw = new StringWriter(); e.printStackTrace(new PrintWriter(sw)); - log.log(LogLevel.DEBUG, "Failed RPC Request: " + sw); + log.log(Level.FINE, "Failed RPC Request: " + sw); } String errorMsg = e.getMessage(); if (errorMsg == null) { errorMsg = e.toString(); } diff --git a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/status/statuspage/StatusPageServer.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/status/statuspage/StatusPageServer.java index c7f7682a62a..8e6cbc28a85 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/status/statuspage/StatusPageServer.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/status/statuspage/StatusPageServer.java @@ -85,7 +85,7 @@ public class StatusPageServer implements Runnable, StatusPageServerInterface { if (!isConnected()) { log.log(LogLevel.INFO, "Fleetcontroller: Server Socket not ready after connect()"); } - log.log(LogLevel.DEBUG, "Fleet controller status page viewer listening to " + ssocket.getLocalSocketAddress()); + log.log(Level.FINE, "Fleet controller status page viewer listening to " + ssocket.getLocalSocketAddress()); monitor.notifyAll(); } } @@ -149,7 +149,7 @@ public class StatusPageServer implements Runnable, StatusPageServerInterface { log.log(shouldBeConnected ? LogLevel.WARNING : LogLevel.DEBUG, "Caught IO exception in ServerSocket.accept(): " + e.getMessage()); } if (connection == null) continue; - log.log(LogLevel.DEBUG, "Got a status page request."); + log.log(Level.FINE, "Got a status page request."); String requestString = ""; OutputStream output = null; try (BufferedReader br = new BufferedReader(new InputStreamReader(connection.getInputStream()))) { @@ -168,7 +168,7 @@ public class StatusPageServer implements Runnable, StatusPageServerInterface { if (s == null || s.equals("")) break; sb.append(s).append("\n"); } - log.log(LogLevel.DEBUG, "Got HTTP request: " + sb.toString()); + log.log(Level.FINE, "Got HTTP request: " + sb.toString()); HttpRequest httpRequest = null; StatusPageResponse response = null; @@ -255,7 +255,7 @@ public class StatusPageServer implements Runnable, StatusPageServerInterface { } } } catch (InterruptedException e) { - log.log(LogLevel.DEBUG, "Status processing thread shut down by interrupt exception: " + e); + log.log(Level.FINE, "Status processing thread shut down by interrupt exception: " + e); } } diff --git a/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/DummyVdsNode.java b/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/DummyVdsNode.java index 8d8835d5932..d6959ed1952 100644 --- a/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/DummyVdsNode.java +++ b/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/DummyVdsNode.java @@ -84,7 +84,7 @@ public class DummyVdsNode { private Thread messageResponder = new Thread() { public void run() { - log.log(LogLevel.DEBUG, "Dummy node " + DummyVdsNode.this.toString() + ": starting message reponder thread"); + log.log(Level.FINE, "Dummy node " + DummyVdsNode.this.toString() + ": starting message reponder thread"); while (true) { synchronized (timer) { if (isInterrupted()) break; @@ -92,7 +92,7 @@ public class DummyVdsNode { for (Iterator it = waitingRequests.iterator(); it.hasNext(); ) { Req r = it.next(); if (r.timeout <= currentTime) { - log.log(LogLevel.DEBUG, "Dummy node " + DummyVdsNode.this.toString() + ": Responding to node state request at time " + currentTime); + log.log(Level.FINE, "Dummy node " + DummyVdsNode.this.toString() + ": Responding to node state request at time " + currentTime); r.request.returnValues().add(new StringValue(nodeState.serialize())); if (r.request.methodName().equals("getnodestate3")) { r.request.returnValues().add(new StringValue("No host info in dummy implementation")); @@ -109,7 +109,7 @@ public class DummyVdsNode { } } } - log.log(LogLevel.DEBUG, "Dummy node " + DummyVdsNode.this.toString() + ": shut down message reponder thread"); + log.log(Level.FINE, "Dummy node " + DummyVdsNode.this.toString() + ": shut down message reponder thread"); } }; @@ -171,7 +171,7 @@ public class DummyVdsNode { void disconnectBreakConnection() { disconnect(true, FleetControllerTest.timeoutMS, false); } void disconnectAsShutdown() { disconnect(true, FleetControllerTest.timeoutMS, true); } private void disconnect(boolean waitForPendingNodeStateRequest, long timeoutms, boolean setStoppingStateFirst) { - log.log(LogLevel.DEBUG, "Dummy node " + DummyVdsNode.this.toString() + ": Breaking connection." + (waitForPendingNodeStateRequest ? " Waiting for pending state first." : "")); + log.log(Level.FINE, "Dummy node " + DummyVdsNode.this.toString() + ": Breaking connection." + (waitForPendingNodeStateRequest ? " Waiting for pending state first." : "")); if (waitForPendingNodeStateRequest) { this.waitForPendingGetNodeStateRequest(timeoutms); } @@ -190,7 +190,7 @@ public class DummyVdsNode { acceptor.shutdown().join(); supervisor.transport().shutdown().join(); supervisor = null; - log.log(LogLevel.DEBUG, "Dummy node " + DummyVdsNode.this.toString() + ": Done breaking connection."); + log.log(Level.FINE, "Dummy node " + DummyVdsNode.this.toString() + ": Done breaking connection."); } public String toString() { @@ -244,25 +244,25 @@ public class DummyVdsNode { private void waitForPendingGetNodeStateRequest(long timeout) { long startTime = System.currentTimeMillis(); long endTime = startTime + timeout; - log.log(LogLevel.DEBUG, "Dummy node " + this + " waiting for pending node state request."); + log.log(Level.FINE, "Dummy node " + this + " waiting for pending node state request."); while (true) { synchronized(timer) { if (!waitingRequests.isEmpty()) { - log.log(LogLevel.DEBUG, "Dummy node " + this + " has pending request, returning."); + log.log(Level.FINE, "Dummy node " + this + " has pending request, returning."); return; } try{ - log.log(LogLevel.DEBUG, "Dummy node " + this + " waiting " + (endTime - startTime) + " ms for pending request."); + log.log(Level.FINE, "Dummy node " + this + " waiting " + (endTime - startTime) + " ms for pending request."); timer.wait(endTime - startTime); } catch (InterruptedException e) { } - log.log(LogLevel.DEBUG, "Dummy node " + this + " woke up to recheck."); + log.log(Level.FINE, "Dummy node " + this + " woke up to recheck."); } startTime = System.currentTimeMillis(); if (startTime >= endTime) { - log.log(LogLevel.DEBUG, "Dummy node " + this + " timeout passed. Don't have pending request."); + log.log(Level.FINE, "Dummy node " + this + " timeout passed. Don't have pending request."); if (!waitingRequests.isEmpty()) { - log.log(LogLevel.DEBUG, "Dummy node " + this + ". Non-empty set of waiting requests"); + log.log(Level.FINE, "Dummy node " + this + ". Non-empty set of waiting requests"); } throw new IllegalStateException("Timeout. No pending get node state request pending after waiting " + timeout + " milliseconds."); } @@ -271,7 +271,7 @@ public class DummyVdsNode { void replyToPendingNodeStateRequests() { for(Req req : waitingRequests) { - log.log(LogLevel.DEBUG, "Dummy node " + this + " answering pending node state request."); + log.log(Level.FINE, "Dummy node " + this + " answering pending node state request."); req.request.returnValues().add(new StringValue(nodeState.serialize())); if (req.request.methodName().equals("getnodestate3")) { req.request.returnValues().add(new StringValue(hostInfo)); @@ -283,7 +283,7 @@ public class DummyVdsNode { } public void setNodeState(NodeState state, String hostInfo) { - log.log(LogLevel.DEBUG, "Dummy node " + this + " got new state: " + state); + log.log(Level.FINE, "Dummy node " + this + " got new state: " + state); synchronized(timer) { this.nodeState = state; this.hostInfo = hostInfo; @@ -415,7 +415,7 @@ public class DummyVdsNode { return; } String stateString = nodeState.serialize(-1, true); - log.log(LogLevel.DEBUG, "Dummy node " + this + " got old type get node state request, answering: " + stateString); + log.log(Level.FINE, "Dummy node " + this + " got old type get node state request, answering: " + stateString); req.returnValues().add(new Int32Value(1)); req.returnValues().add(new StringValue("")); req.returnValues().add(new StringValue(stateString)); @@ -427,7 +427,7 @@ public class DummyVdsNode { for (Iterator it = waitingRequests.iterator(); it.hasNext(); ) { Req r = it.next(); if (r.request.parameters().size() > 2 && r.request.parameters().get(2).asInt32() == index) { - log.log(LogLevel.DEBUG, "Dummy node " + DummyVdsNode.this.toString() + ": Responding to node state reply from controller " + index + " as we received new one"); + log.log(Level.FINE, "Dummy node " + DummyVdsNode.this.toString() + ": Responding to node state reply from controller " + index + " as we received new one"); r.request.returnValues().add(new StringValue(nodeState.serialize())); r.request.returnValues().add(new StringValue("No host info from dummy implementation")); r.request.returnRequest(); @@ -440,7 +440,7 @@ public class DummyVdsNode { } private void rpc_getNodeState2(Request req) { - log.log(LogLevel.DEBUG, "Dummy node " + this + ": Got " + req.methodName() + " request"); + log.log(Level.FINE, "Dummy node " + this + ": Got " + req.methodName() + " request"); try{ String oldState = req.parameters().get(0).asString(); int timeout = req.parameters().get(1).asInt32(); @@ -452,14 +452,14 @@ public class DummyVdsNode { boolean sentReply = sendGetNodeStateReply(index); NodeState givenState = (oldState.equals("unknown") ? null : NodeState.deserialize(type, oldState)); if (givenState != null && (givenState.equals(nodeState) || sentReply)) { - log.log(LogLevel.DEBUG, "Dummy node " + this + ": Has same state as reported " + givenState + ". Queing request. Timeout is " + timeout + " ms. " + log.log(Level.FINE, "Dummy node " + this + ": Has same state as reported " + givenState + ". Queing request. Timeout is " + timeout + " ms. " + "Will be answered at time " + (timer.getCurrentTimeInMillis() + timeout * 800l / 1000)); req.detach(); waitingRequests.add(new Req(req, timer.getCurrentTimeInMillis() + timeout * 800l / 1000)); - log.log(LogLevel.DEBUG, "Dummy node " + this + " has now " + waitingRequests.size() + " entries and is " + (waitingRequests.isEmpty() ? "empty" : "not empty")); + log.log(Level.FINE, "Dummy node " + this + " has now " + waitingRequests.size() + " entries and is " + (waitingRequests.isEmpty() ? "empty" : "not empty")); timer.notifyAll(); } else { - log.log(LogLevel.DEBUG, "Dummy node " + this + ": Request had " + (givenState == null ? "no state" : "different state(" + givenState +")") + ". Answering with " + nodeState); + log.log(Level.FINE, "Dummy node " + this + ": Request had " + (givenState == null ? "no state" : "different state(" + givenState +")") + ". Answering with " + nodeState); req.returnValues().add(new StringValue(nodeState.serialize())); if (req.methodName().equals("getnodestate3")) { req.returnValues().add(new StringValue("Dummy node host info")); @@ -526,7 +526,7 @@ public class DummyVdsNode { } req.returnValues().add(new Int32Value(1)); req.returnValues().add(new StringValue("OK")); - log.log(LogLevel.DEBUG, "Dummy node " + this + ": Got new system state (through old setsystemstate call) " + newState); + log.log(Level.FINE, "Dummy node " + this + ": Got new system state (through old setsystemstate call) " + newState); } catch (Exception e) { log.log(LogLevel.ERROR, "Dummy node " + this + ": An error occurred when answering setsystemstate request: " + e.getMessage()); e.printStackTrace(System.err); @@ -550,7 +550,7 @@ public class DummyVdsNode { } timer.notifyAll(); } - log.log(LogLevel.DEBUG, "Dummy node " + this + ": Got new system state " + newState); + log.log(Level.FINE, "Dummy node " + this + ": Got new system state " + newState); } catch (Exception e) { log.log(LogLevel.ERROR, "Dummy node " + this + ": An error occurred when answering setsystemstate request: " + e.getMessage()); e.printStackTrace(System.err); @@ -573,7 +573,7 @@ public class DummyVdsNode { } timer.notifyAll(); } - log.log(LogLevel.DEBUG, "Dummy node " + this + ": Got new cluster state " + stateBundle); + log.log(Level.FINE, "Dummy node " + this + ": Got new cluster state " + stateBundle); } catch (Exception e) { log.log(LogLevel.ERROR, "Dummy node " + this + ": An error occurred when answering setdistributionstates request: " + e.getMessage()); e.printStackTrace(System.err); @@ -596,11 +596,11 @@ public class DummyVdsNode { activatedClusterStateVersion = activateVersion; timer.notifyAll(); } else { - log.log(LogLevel.DEBUG, () -> String.format("Dummy node %s: got a mismatching activation (request version %d, " + + log.log(Level.FINE, () -> String.format("Dummy node %s: got a mismatching activation (request version %d, " + "actual %d), not marking version as active", this, activateVersion, actualVersion)); } } - log.log(LogLevel.DEBUG, "Dummy node " + this + ": Activating cluster state version " + activateVersion); + log.log(Level.FINE, "Dummy node " + this + ": Activating cluster state version " + activateVersion); } catch (Exception e) { log.log(LogLevel.ERROR, "Dummy node " + this + ": An error occurred when answering activate_cluster_state_version request: " + e.getMessage()); e.printStackTrace(System.err); diff --git a/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FakeTimer.java b/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FakeTimer.java index bcf98d003a6..bda24b826fd 100644 --- a/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FakeTimer.java +++ b/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FakeTimer.java @@ -23,7 +23,7 @@ public class FakeTimer implements Timer { public synchronized void advanceTime(long time) { long currentTime = getCurrentTimeInMillis(); this.currentTime += time; - log.log(LogLevel.DEBUG, "Time advanced by " + time + " ms. Time increased from " + currentTime + " to " + (currentTime + time)); + log.log(Level.FINE, "Time advanced by " + time + " ms. Time increased from " + currentTime + " to " + (currentTime + time)); notifyAll(); } diff --git a/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FleetControllerTest.java b/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FleetControllerTest.java index d69725ebe20..6d8afa14f3e 100644 --- a/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FleetControllerTest.java +++ b/clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FleetControllerTest.java @@ -135,13 +135,13 @@ public abstract class FleetControllerTest implements Waiter { } void setUpSystem(boolean useFakeTimer, FleetControllerOptions options) throws Exception { - log.log(LogLevel.DEBUG, "Setting up system"); + log.log(Level.FINE, "Setting up system"); slobrok = new Slobrok(); this.options = options; if (options.zooKeeperServerAddress != null) { zooKeeperServer = new ZooKeeperTestServer(); this.options.zooKeeperServerAddress = zooKeeperServer.getAddress(); - log.log(LogLevel.DEBUG, "Set up new zookeeper server at " + this.options.zooKeeperServerAddress); + log.log(Level.FINE, "Set up new zookeeper server at " + this.options.zooKeeperServerAddress); } this.options.slobrokConnectionSpecs = new String[1]; this.options.slobrokConnectionSpecs[0] = "tcp/localhost:" + slobrok.port(); -- cgit v1.2.3