summaryrefslogtreecommitdiffstats
path: root/clustercontroller-core
diff options
context:
space:
mode:
authorgjoranv <gv@verizonmedia.com>2020-04-24 13:12:46 +0200
committergjoranv <gv@verizonmedia.com>2020-04-25 02:22:55 +0200
commit25f832e613bb6087327c293b527d5445babb4319 (patch)
tree8197a5b331e845bfe91f006d9cfe8bec9a28170f /clustercontroller-core
parent4e6825b47270804a36e7d76b873ca6c2fe360eac (diff)
LogLevel.DEBUG -> Level.FINE
Diffstat (limited to 'clustercontroller-core')
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/ClusterStateView.java2
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/FleetController.java10
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/MasterElectionHandler.java4
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeInfo.java14
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/NodeStateGatherer.java30
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/StateChangeHandler.java28
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/SystemStateBroadcaster.java20
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/DatabaseHandler.java56
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/MasterDataGatherer.java14
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/ZooKeeperDatabase.java20
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/restapiv2/requests/SetNodeStateRequest.java2
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RPCCommunicator.java10
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RpcServer.java20
-rw-r--r--clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/status/statuspage/StatusPageServer.java8
-rw-r--r--clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/DummyVdsNode.java48
-rw-r--r--clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FakeTimer.java2
-rw-r--r--clustercontroller-core/src/test/java/com/yahoo/vespa/clustercontroller/core/FleetControllerTest.java4
17 files changed, 146 insertions, 146 deletions
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<NodeInfo> {
}
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<NodeInfo> {
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<NodeInfo> {
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<NodeInfo> {
}
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<NodeInfo> {
&& (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<Integer, Integer> 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<Node, NodeState> 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<Node, Long> 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<Integer, Integer> 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<Integer, Integer>(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<Node, NodeState> 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<Node, NodeState> 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<Node, Long> 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<Node, Long> wanted = new TreeMap<Node, Long>();
@@ -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<SetResponse> {
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<GetNodeStateRequest> 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<String> slobrok = new ArrayList<String>();
List<String> rpc = new ArrayList<String>();
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<Req> 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<Req> 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();