diff options
author | Jon Marius Venstad <venstad@gmail.com> | 2021-04-28 15:56:45 +0200 |
---|---|---|
committer | Jon Marius Venstad <venstad@gmail.com> | 2021-04-28 15:56:45 +0200 |
commit | 5d2c85de4e5e5f9182189cb2aaf9369070f41533 (patch) | |
tree | 306f65d364d04f5c23e41b8cdc3d3c90c7162342 /clustercontroller-core/src | |
parent | 4fbd27dddde4aff5de1be48f79057b6357bed123 (diff) |
More lazy debug log message generation
Diffstat (limited to 'clustercontroller-core/src')
14 files changed, 123 insertions, 133 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 f8774b87b2a..c2215ef94c7 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 @@ -89,7 +89,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(Level.FINE, "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/EventLog.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/EventLog.java index f6a90124b1e..93fd176edd1 100644 --- a/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/EventLog.java +++ b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/EventLog.java @@ -64,7 +64,7 @@ public class EventLog implements EventLogInterface { if (e instanceof NodeEvent) { addNodeOnlyEvent((NodeEvent)e, logInfo ? Level.INFO: Level.FINE); } else { - log.log(logInfo ? Level.INFO : Level.FINE, e.toString()); + log.log(logInfo ? Level.INFO : Level.FINE, e::toString); } } 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 75eea998346..2bb0fb2afc4 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 @@ -579,8 +579,7 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd responseCode = StatusPageResponse.ResponseCode.INTERNAL_SERVER_ERROR; message = "Internal Server Error"; hiddenMessage = ExceptionUtils.getStackTraceAsString(e); - log.log(Level.FINE, "Unknown exception thrown for request " + httpRequest.getRequest() + - ": " + hiddenMessage); + log.log(Level.FINE, "Unknown exception thrown for request " + httpRequest.getRequest() + ": " + hiddenMessage); } TimeZone tz = TimeZone.getTimeZone("UTC"); @@ -1093,7 +1092,7 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd firstAllowedStateBroadcast = currentTime + options.minTimeBeforeFirstSystemStateBroadcast; isMaster = true; inMasterMoratorium = true; - log.log(Level.FINE, "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; } @@ -1127,7 +1126,7 @@ public class FleetController implements NodeStateOrHostInfoChangeHandler, NodeAd tick(); } } catch (InterruptedException e) { - log.log(Level.FINE, "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(Level.SEVERE, "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 2c03520ec01..b6b1593034e 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 @@ -35,7 +35,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(Level.FINE, "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(); @@ -125,7 +125,7 @@ public class MasterElectionHandler implements MasterInterface { } if (nextMasterData == null) { if (masterCandidate == null) { - log.log(Level.FINEST, "Cluster controller " + index + ": No current master candidate. Waiting for data to do master election."); + log.log(Level.FINEST, () -> "Cluster controller " + index + ": No current master candidate. Waiting for data to do master election."); } return false; // Nothing have happened since last time. } @@ -195,7 +195,7 @@ public class MasterElectionHandler implements MasterInterface { if (nextInLineCount != ourPosition) { nextInLineCount = ourPosition; if (ourPosition > 0) { - log.log(Level.FINE, "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 f014690947d..2ce6a5261e1 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(Level.FINE, "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(Level.FINE, "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(Level.FINE, "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(Level.FINE, "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); @@ -342,19 +342,19 @@ abstract public class NodeInfo implements Comparable<NodeInfo> { } else { nextAttemptTime = time + 5000; } - log.log(Level.FINEST, "Failed to get state from node " + toString() + ", scheduling next attempt in " + (nextAttemptTime - time) + " ms."); + log.log(Level.FINEST, () -> "Failed to get state from node " + toString() + ", scheduling next attempt in " + (nextAttemptTime - time) + " ms."); } else { connectionAttemptCount = 0; timeOfFirstFailingConnectionAttempt = 0; reportedState = state; if (version == 0 || state.getState().equals(State.STOPPING)) { nextAttemptTime = time + cluster.getPollingFrequency(); - log.log(Level.FINEST, "Scheduling next attempt to get state from " + toString() + " in " + (nextAttemptTime - time) + " ms (polling freq)."); + log.log(Level.FINEST, () -> "Scheduling next attempt to get state from " + toString() + " in " + (nextAttemptTime - time) + " ms (polling freq)."); } else { nextAttemptTime = time; } } - log.log(Level.FINEST, "Set reported state of node " + this + " to " + reportedState + ". Next connection attempt is at " + nextAttemptTime); + log.log(Level.FINEST, () -> "Set reported state of node " + this + " to " + reportedState + ". Next connection attempt is at " + nextAttemptTime); } /** Sets the wanted state. The wanted state is taken as UP if a null argument is given */ @@ -374,7 +374,7 @@ abstract public class NodeInfo implements Comparable<NodeInfo> { } } wantedState = newWanted; - log.log(Level.FINEST, "Set wanted state of node " + this + " to " + wantedState + "."); + log.log(Level.FINEST, () -> "Set wanted state of node " + this + " to " + wantedState + "."); } public long getTimeForNextStateRequestAttempt() { 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 da32caa0c4e..995a7c7ed1f 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(Level.FINE, "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(Level.FINE, "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(Level.FINE, "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(Level.FINE, "Ignoring get node state error. Need to resend"); + log.log(Level.FINE, () -> "Ignoring get node state error. Need to resend"); } } else { - log.log(Level.FINE, "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), Level.INFO); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(Level.FINE, "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,8 +174,9 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), Level.INFO); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() - + " " + req.getReply().getReturnMessage() + ": " + msg); + if (log.isLoggable(Level.FINE)) + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setState(State.DOWN); } else if (msg.equals("jrt: Connection closed by peer") || msg.equals("Connection reset by peer")) { @@ -186,7 +187,8 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), Level.INFO); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + if (log.isLoggable(Level.FINE)) + 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 +196,16 @@ public class NodeStateGatherer { msg = "Connection error: Timeout"; eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), Level.INFO); } else { - log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + if (log.isLoggable(Level.FINE)) + 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), Level.WARNING); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); + if (log.isLoggable(Level.FINE)) + log.log(Level.FINE, "Failed to talk to node " + info + ": " + req.getReply().getReturnCode() + " " + req.getReply().getReturnMessage() + ": " + msg); } newState.setDescription(msg); } @@ -212,7 +216,7 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), Level.WARNING); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(Level.FINE, "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 +227,19 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), Level.WARNING); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(Level.FINE, "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(Level.FINE, "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), Level.INFO); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(Level.FINE, "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 +248,7 @@ public class NodeStateGatherer { if (info.getReportedState().getState().oneOf("ui")) { eventLog.addNodeOnlyEvent(NodeEvent.forBaseline(info, prefix + msg, NodeEvent.Type.REPORTED, currentTime), Level.WARNING); } else if (!info.getReportedState().hasDescription() || !info.getReportedState().getDescription().equals(msg)) { - log.log(Level.FINE, "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 fdc5b664180..3e1390a608c 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 @@ -52,7 +52,7 @@ public class StateChangeHandler { final DatabaseHandler database, final DatabaseHandler.Context dbContext) throws InterruptedException { int startTimestampsReset = 0; - log.log(Level.FINE, String.format("handleAllDistributorsInSync invoked for state version %d", currentState.getVersion())); + log.log(Level.FINE, "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,16 +60,11 @@ public class StateChangeHandler { final NodeState nodeState = currentState.getNodeState(node); if (nodeInfo != null && nodeState != null) { if (nodeState.getStartTimestamp() > nodeInfo.getStartTimestamp()) { - if (log.isLoggable(Level.FINE)) { - log.log(Level.FINE, String.format("Storing away new start timestamp for node %s (%d)", - node, nodeState.getStartTimestamp())); - } + 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(Level.FINE)) { - log.log(Level.FINE, String.format("Resetting timestamp in cluster state for node %s", node)); - } + log.log(Level.FINE, "Resetting timestamp in cluster state for node %s", node); ++startTimestampsReset; } } else if (log.isLoggable(Level.FINE)) { @@ -149,12 +144,11 @@ public class StateChangeHandler { final int oldCount = currentState.getMinUsedBits(); final int newCount = reportedState.getMinUsedBits(); log.log(Level.FINE, - String.format("Altering node state to reflect that min distribution bit count has changed from %d to %d", - oldCount, newCount)); + () -> 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(Level.FINE)) { - log.log(Level.FINE, String.format("Not altering state of %s in cluster state because new state is too similar: %s", + } else { + 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))); } @@ -178,12 +172,12 @@ public class StateChangeHandler { } if (node.getReportedState().getState().equals(State.STOPPING)) { - 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"); + 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(Level.FINE, "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; @@ -205,9 +199,7 @@ public class StateChangeHandler { } stateMayHaveChanged = true; - if (log.isLoggable(Level.FINE)) { - log.log(Level.FINE, 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())); long timeNow = timer.getCurrentTimeInMillis(); @@ -293,11 +285,11 @@ public class StateChangeHandler { if (mayResetCrashCounterOnStableUpNode(currentTime, node, lastReportedState)) { node.setPrematureCrashCount(0); - log.log(Level.FINE, "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(Level.FINE, "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; } @@ -387,19 +379,14 @@ public class StateChangeHandler { final NodeState reportedState, final NodeStateOrHostInfoChangeHandler nodeListener) { final long timeNow = timer.getCurrentTimeInMillis(); - if (log.isLoggable(Level.FINE)) { - log.log(Level.FINE, String.format("Finding new cluster state entry for %s switching state %s", - node, currentState.getTextualDifference(reportedState))); - } + log.log(Level.FINE, () -> String.format("Finding new cluster state entry for %s switching state %s", node, currentState.getTextualDifference(reportedState))); if (handleReportedNodeCrashEdge(node, currentState, reportedState, nodeListener, timeNow)) { return; } if (initializationProgressHasIncreased(currentState, reportedState)) { node.setInitProgressTime(timeNow); - if (log.isLoggable(Level.FINEST)) { - log.log(Level.FINEST, "Reset initialize timer on " + node + " to " + node.getInitProgressTime()); - } + log.log(Level.FINEST, () -> "Reset initialize timer on " + node + " to " + node.getInitProgressTime()); } if (handleImplicitCrashEdgeFromReverseInitProgress(node, currentState, reportedState, nodeListener, timeNow)) { return; @@ -454,7 +441,7 @@ public class StateChangeHandler { if (nodeUpToDownEdge(node, currentState, reportedState)) { node.setTransitionTime(timeNow); if (node.getUpStableStateTime() + stableStateTimePeriod > timeNow && !isControlledShutdown(reportedState)) { - log.log(Level.FINE, "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/database/DatabaseHandler.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/database/DatabaseHandler.java index d19425a7c95..2bf86d7056b 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 @@ -56,7 +56,7 @@ public class DatabaseHandler { } private class DatabaseListener implements Database.DatabaseListener { public void handleZooKeeperSessionDown() { - log.log(Level.FINE, "Fleetcontroller " + nodeIndex + ": Lost contact with zookeeper server"); + log.log(Level.FINE, () -> "Fleetcontroller " + nodeIndex + ": Lost contact with zookeeper server"); synchronized(monitor) { lostZooKeeperConnectionEvent = true; monitor.notifyAll(); @@ -66,7 +66,7 @@ public class DatabaseHandler { public void handleMasterData(Map<Integer, Integer> data) { synchronized (monitor) { if (masterDataEvent != null && masterDataEvent.equals(data)) { - log.log(Level.FINE, "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; } @@ -153,7 +153,7 @@ public class DatabaseHandler { pendingStore.clearNonClusterStateFields(); } pendingStore.masterVote = currentVote; - log.log(Level.FINE, "Cleared session metadata. Pending master vote is now " + pendingStore.masterVote); + log.log(Level.FINE, () -> "Cleared session metadata. Pending master vote is now " + pendingStore.masterVote); } public void setZooKeeperAddress(String address, Context context) { @@ -168,7 +168,7 @@ public class DatabaseHandler { public void setZooKeeperSessionTimeout(int timeout, Context context) { if (timeout == zooKeeperSessionTimeout) return; - log.log(Level.FINE, "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(context); } @@ -197,7 +197,7 @@ public class DatabaseHandler { database = databaseFactory.create(params); } } catch (KeeperException.NodeExistsException e) { - log.log(Level.FINE, "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); @@ -222,17 +222,17 @@ public class DatabaseHandler { boolean didWork = false; synchronized (monitor) { if (lostZooKeeperConnectionEvent) { - log.log(Level.FINE, "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(Level.FINE, "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(Level.FINE, "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); @@ -282,10 +282,10 @@ public class DatabaseHandler { boolean didWork = false; if (pendingStore.masterVote != null) { didWork = true; - log.log(Level.FINE, "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(Level.FINE, "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; @@ -296,7 +296,7 @@ public class DatabaseHandler { } if (pendingStore.lastSystemStateVersion != null) { didWork = true; - log.log(Level.FINE, "Fleetcontroller " + nodeIndex + log.log(Level.FINE, () -> "Fleetcontroller " + nodeIndex + ": Attempting to store last system state version " + pendingStore.lastSystemStateVersion + " into zookeeper."); if (database.storeLatestSystemStateVersion(pendingStore.lastSystemStateVersion)) { @@ -308,7 +308,7 @@ public class DatabaseHandler { } if (pendingStore.startTimestamps != null) { didWork = true; - log.log(Level.FINE, "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; @@ -319,7 +319,7 @@ public class DatabaseHandler { } if (pendingStore.wantedStates != null) { didWork = true; - log.log(Level.FINE, "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; @@ -344,7 +344,7 @@ public class DatabaseHandler { } public void setMasterVote(Context context, int wantedMasterCandidate) throws InterruptedException { - log.log(Level.FINE, "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 @@ -352,14 +352,14 @@ public class DatabaseHandler { if (pendingStore.masterVote != null || currentlyStored.masterVote == null || currentlyStored.masterVote != wantedMasterCandidate) { - log.log(Level.FINE, "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(Level.FINE, "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 @@ -367,14 +367,14 @@ public class DatabaseHandler { if (pendingStore.lastSystemStateVersion != null || currentlyStored.lastSystemStateVersion == null || currentlyStored.lastSystemStateVersion != version) { - log.log(Level.FINE, "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(Level.FINE, "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(); @@ -425,7 +425,7 @@ public class DatabaseHandler { } public void saveWantedStates(Context context) throws InterruptedException { - log.log(Level.FINE, "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))) { @@ -439,14 +439,14 @@ public class DatabaseHandler { if (pendingStore.wantedStates != null || currentlyStored.wantedStates == null || !currentlyStored.wantedStates.equals(wantedStates)) { - log.log(Level.FINE, "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(Level.FINE, "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(); @@ -457,7 +457,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(Level.FINE, "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<>(); } @@ -471,7 +471,7 @@ public class DatabaseHandler { context.getNodeStateUpdateListener().handleNewWantedNodeState(nodeInfo, wantedState); altered = true; } - log.log(Level.FINE, "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 @@ -487,13 +487,13 @@ public class DatabaseHandler { } public void saveStartTimestamps(Context context) throws InterruptedException { - log.log(Level.FINE, "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(Level.FINE, "Fleetcontroller " + nodeIndex + ": Retrieving start timestamps"); + log.log(Level.FINE, () -> "Fleetcontroller " + nodeIndex + ": Retrieving start timestamps"); synchronized (databaseMonitor) { if (database == null || database.isClosed()) { return false; @@ -509,7 +509,7 @@ public class DatabaseHandler { } for (Map.Entry<Node, Long> e : startTimestamps.entrySet()) { cluster.setStartTimestamp(e.getKey(), e.getValue()); - log.log(Level.FINE, "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 0f16ffbaf76..2933e353da0 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 @@ -62,10 +62,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(Level.FINE, "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(Level.FINE, "Fleetcontroller " + nodeIndex + ": Got ZooKeeper event None."); + log.log(Level.FINE, () -> "Fleetcontroller " + nodeIndex + ": Got ZooKeeper event None."); } } } @@ -84,7 +84,7 @@ public class MasterDataGatherer { for (String node : nodes) { int index = Integer.parseInt(node); nextMasterData.put(index, null); - log.log(Level.FINE, "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 @@ -124,7 +124,7 @@ public class MasterDataGatherer { Integer value = Integer.valueOf(data); if (nextMasterData.containsKey(index)) { if (value.equals(nextMasterData.get(index))) { - log.log(Level.FINE, "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(Level.INFO, "Fleetcontroller " + nodeIndex + ": Got vote from fleetcontroller " + index + ". Altering vote from " + nextMasterData.get(index) + " to " + value + "."); nextMasterData.put(index, value); @@ -135,12 +135,12 @@ public class MasterDataGatherer { } for(Integer vote : nextMasterData.values()) { if (vote == null) { - log.log(Level.FINEST, "Fleetcontroller " + nodeIndex + ": Still not received votes from all fleet controllers. Awaiting more responses."); + log.log(Level.FINEST, () -> "Fleetcontroller " + nodeIndex + ": Still not received votes from all fleet controllers. Awaiting more responses."); return; } } } - log.log(Level.FINE, "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(); } } @@ -170,14 +170,14 @@ public class MasterDataGatherer { Map<Integer, Integer> copy; synchronized (nextMasterData) { if (nextMasterData.equals(masterData)) { - log.log(Level.FINE, "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(Level.FINE, "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 5e0d050cbcf..97f2126e2ff 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 @@ -113,7 +113,7 @@ public class ZooKeeperDatabase extends Database { try{ this.listener = zksl; setupRoot(); - log.log(Level.FINEST, "Fleetcontroller " + nodeIndex + ": Asking for initial data on master election"); + log.log(Level.FINEST, () -> "Fleetcontroller " + nodeIndex + ": Asking for initial data on master election"); masterDataGatherer = new MasterDataGatherer(session, zooKeeperRoot, listener, nodeIndex); completedOk = true; } finally { @@ -124,13 +124,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(Level.FINE, "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(Level.FINE, "Fleetcontroller " + nodeIndex + ": Created zookeeper node '" + prefix + nodename + "'"); + log.log(Level.FINE, () -> "Fleetcontroller " + nodeIndex + ": Created zookeeper node '" + prefix + nodename + "'"); } catch (KeeperException.NodeExistsException e) { - log.log(Level.FINE, "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."); } } @@ -172,7 +172,7 @@ public class ZooKeeperDatabase extends Database { public void close() { sessionOpen = false; try{ - log.log(Level.FINE, "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) { @@ -262,7 +262,7 @@ public class ZooKeeperDatabase extends Database { } byte[] val = sb.toString().getBytes(utf8); try{ - log.log(Level.FINE, "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) { @@ -275,7 +275,7 @@ public class ZooKeeperDatabase extends Database { public Map<Node, NodeState> retrieveWantedStates() throws InterruptedException { try{ - log.log(Level.FINE, "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<>(); @@ -313,7 +313,7 @@ public class ZooKeeperDatabase extends Database { } byte val[] = sb.toString().getBytes(utf8); try{ - log.log(Level.FINE, "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) { @@ -327,7 +327,7 @@ public class ZooKeeperDatabase extends Database { @Override public Map<Node, Long> retrieveStartTimestamps() throws InterruptedException { try{ - log.log(Level.FINE, "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>(); 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 dcd7a176aa7..d5ec5751bec 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 @@ -119,7 +119,7 @@ public class SetNodeStateRequest extends Request<SetResponse> { NodeStateChangeChecker.Result result = cluster.calculateEffectOfNewState( node, currentClusterState, condition, wantedState, newWantedState, inMasterMoratorium); - log.log(Level.FINE, "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/RpcServer.java b/clustercontroller-core/src/main/java/com/yahoo/vespa/clustercontroller/core/rpc/RpcServer.java index 3a432e57f1f..73597e995d4 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(Level.FINE, "Fleetcontroller " + fleetControllerIndex + ": Connecting RPC server."); + log.log(Level.FINE, () -> "Fleetcontroller " + fleetControllerIndex + ": Connecting RPC server."); if (supervisor != null) disconnect(); supervisor = new Supervisor(new Transport("rpc" + port)).useSmallBuffers(); addMethods(); - log.log(Level.FINE, "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(Level.FINE, "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(Level.FINE, "Fleetcontroller " + fleetControllerIndex + ": Disconnecting RPC server."); + log.log(Level.FINE, () -> "Fleetcontroller " + fleetControllerIndex + ": Disconnecting RPC server."); register.shutdown(); register = null; } 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 b54d816308b..92158692a20 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 @@ -85,7 +85,7 @@ public class DummyVdsNode { private final Thread messageResponder = new Thread() { public void run() { - log.log(Level.FINE, "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; @@ -93,7 +93,7 @@ public class DummyVdsNode { for (Iterator<Req> it = waitingRequests.iterator(); it.hasNext(); ) { Req r = it.next(); if (r.timeout <= currentTime) { - log.log(Level.FINE, "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")); @@ -110,7 +110,7 @@ public class DummyVdsNode { } } } - log.log(Level.FINE, "Dummy node " + DummyVdsNode.this.toString() + ": shut down message reponder thread"); + log.log(Level.FINE, () -> "Dummy node " + DummyVdsNode.this.toString() + ": shut down message reponder thread"); } }; @@ -172,7 +172,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(Level.FINE, "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); } @@ -191,7 +191,7 @@ public class DummyVdsNode { acceptor.shutdown().join(); supervisor.transport().shutdown().join(); supervisor = null; - log.log(Level.FINE, "Dummy node " + DummyVdsNode.this.toString() + ": Done breaking connection."); + log.log(Level.FINE, () -> "Dummy node " + DummyVdsNode.this.toString() + ": Done breaking connection."); } public String toString() { @@ -237,24 +237,24 @@ public class DummyVdsNode { private void waitForPendingGetNodeStateRequest(long timeout) { long startTime = System.currentTimeMillis(); long endTime = startTime + timeout; - log.log(Level.FINE, "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(Level.FINE, "Dummy node " + this + " has pending request, returning."); + log.log(Level.FINE, () -> "Dummy node " + this + " has pending request, returning."); return; } - try{ + try { log.log(Level.FINE, "Dummy node " + this + " waiting " + (endTime - startTime) + " ms for pending request."); timer.wait(endTime - startTime); } catch (InterruptedException e) { /* ignore */ } - log.log(Level.FINE, "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(Level.FINE, "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(Level.FINE, "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."); } @@ -263,7 +263,7 @@ public class DummyVdsNode { void replyToPendingNodeStateRequests() { for(Req req : waitingRequests) { - log.log(Level.FINE, "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)); @@ -275,7 +275,7 @@ public class DummyVdsNode { } public void setNodeState(NodeState state, String hostInfo) { - log.log(Level.FINE, "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; @@ -394,7 +394,7 @@ public class DummyVdsNode { private void rpc_storageConnect(Request req) { synchronized(timer) { - log.log(Level.FINEST, "Dummy node " + this + " got old type handle connect message."); + log.log(Level.FINEST, () -> "Dummy node " + this + " got old type handle connect message."); req.returnValues().add(new Int32Value(0)); negotiatedHandle = true; } @@ -407,7 +407,7 @@ public class DummyVdsNode { return; } String stateString = nodeState.serialize(-1, true); - log.log(Level.FINE, "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)); @@ -419,7 +419,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(Level.FINE, "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(); @@ -432,7 +432,7 @@ public class DummyVdsNode { } private void rpc_getNodeState2(Request req) { - log.log(Level.FINE, "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(); @@ -444,14 +444,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(Level.FINE, "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(Level.FINE, "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(Level.FINE, "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")); @@ -513,7 +513,7 @@ public class DummyVdsNode { } req.returnValues().add(new Int32Value(1)); req.returnValues().add(new StringValue("OK")); - log.log(Level.FINE, "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(Level.SEVERE, "Dummy node " + this + ": An error occurred when answering setsystemstate request: " + e.getMessage()); e.printStackTrace(System.err); @@ -537,7 +537,7 @@ public class DummyVdsNode { } timer.notifyAll(); } - log.log(Level.FINE, "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(Level.SEVERE, "Dummy node " + this + ": An error occurred when answering setsystemstate request: " + e.getMessage()); e.printStackTrace(System.err); @@ -560,7 +560,7 @@ public class DummyVdsNode { } timer.notifyAll(); } - log.log(Level.FINE, "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(Level.SEVERE, "Dummy node " + this + ": An error occurred when answering setdistributionstates request: " + e.getMessage()); e.printStackTrace(System.err); @@ -587,7 +587,7 @@ public class DummyVdsNode { "actual %d), not marking version as active", this, activateVersion, actualVersion)); } } - log.log(Level.FINE, "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(Level.SEVERE, "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 3f9ebaf319c..fe4ecde95b5 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 @@ -29,7 +29,7 @@ public class FakeTimer implements Timer { public synchronized void advanceTime(long time) { long currentTime = getCurrentTimeInMillis(); this.currentTime += time; - log.log(Level.FINE, "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(); } |