diff options
97 files changed, 329 insertions, 358 deletions
diff --git a/athenz-identity-provider-service/src/main/java/com/yahoo/vespa/hosted/athenz/instanceproviderservice/IdentityProviderRequestHandler.java b/athenz-identity-provider-service/src/main/java/com/yahoo/vespa/hosted/athenz/instanceproviderservice/IdentityProviderRequestHandler.java index fe6fa0baf2d..afb3b1211a4 100644 --- a/athenz-identity-provider-service/src/main/java/com/yahoo/vespa/hosted/athenz/instanceproviderservice/IdentityProviderRequestHandler.java +++ b/athenz-identity-provider-service/src/main/java/com/yahoo/vespa/hosted/athenz/instanceproviderservice/IdentityProviderRequestHandler.java @@ -67,7 +67,7 @@ public class IdentityProviderRequestHandler extends RestApiRequestHandler<Identi } private InstanceConfirmation confirmInstance(RestApi.RequestContext context, InstanceConfirmation instanceConfirmation) { - log.log(Level.FINE, instanceConfirmation.toString()); + log.log(Level.FINE, () -> instanceConfirmation.toString()); if (!instanceValidator.isValidInstance(instanceConfirmation)) { log.log(Level.SEVERE, "Invalid instance: " + instanceConfirmation); throw new RestApiException.Forbidden("Instance is invalid"); @@ -76,7 +76,7 @@ public class IdentityProviderRequestHandler extends RestApiRequestHandler<Identi } private InstanceConfirmation confirmInstanceRefresh(RestApi.RequestContext context, InstanceConfirmation instanceConfirmation) { - log.log(Level.FINE, instanceConfirmation.toString()); + log.log(Level.FINE, () -> instanceConfirmation.toString()); if (!instanceValidator.isValidRefresh(instanceConfirmation)) { log.log(Level.SEVERE, "Invalid instance refresh: " + instanceConfirmation); throw new RestApiException.Forbidden("Instance is invalid"); 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(); } diff --git a/config-application-package/src/main/java/com/yahoo/config/application/OverrideProcessor.java b/config-application-package/src/main/java/com/yahoo/config/application/OverrideProcessor.java index 35584bf9608..d2a3fd8c161 100644 --- a/config-application-package/src/main/java/com/yahoo/config/application/OverrideProcessor.java +++ b/config-application-package/src/main/java/com/yahoo/config/application/OverrideProcessor.java @@ -54,7 +54,7 @@ class OverrideProcessor implements PreProcessor { } public Document process(Document input) throws TransformerException { - log.log(Level.FINE, "Preprocessing overrides with " + environment + "." + region); + log.log(Level.FINE, () -> "Preprocessing overrides with " + environment + "." + region); Document ret = Xml.copyDocument(input); Element root = ret.getDocumentElement(); applyOverrides(root, Context.empty()); diff --git a/config-application-package/src/main/java/com/yahoo/config/model/application/provider/FilesApplicationFile.java b/config-application-package/src/main/java/com/yahoo/config/model/application/provider/FilesApplicationFile.java index 31349967462..5753945133c 100644 --- a/config-application-package/src/main/java/com/yahoo/config/model/application/provider/FilesApplicationFile.java +++ b/config-application-package/src/main/java/com/yahoo/config/model/application/provider/FilesApplicationFile.java @@ -41,7 +41,7 @@ public class FilesApplicationFile extends ApplicationFile { @Override public ApplicationFile delete() { - log.log(Level.FINE, "Delete " + file); + log.log(Level.FINE, () -> "Delete " + file); if (file.isDirectory() && !listFiles().isEmpty()) { throw new RuntimeException("files. Can't delete, directory not empty: " + this + "(" + listFiles() + ")." + listFiles().size()); } @@ -154,7 +154,7 @@ public class FilesApplicationFile extends ApplicationFile { private void writeMetaFile(String data, String status) throws IOException { File metaDir = createMetaDir(); - log.log(Level.FINE, "meta dir=" + metaDir); + log.log(Level.FINE, () -> "meta dir=" + metaDir); File metaFile = new File(metaDir + "/" + getPath().getName()); if (status == null) { status = ApplicationFile.ContentStatusNew; @@ -174,7 +174,7 @@ public class FilesApplicationFile extends ApplicationFile { private File createMetaDir() { File metaDir = getMetaDir(); if (!metaDir.exists()) { - log.log(Level.FINE, "Creating meta dir " + metaDir); + log.log(Level.FINE, () -> "Creating meta dir " + metaDir); metaDir.mkdirs(); } return metaDir; @@ -188,7 +188,7 @@ public class FilesApplicationFile extends ApplicationFile { public MetaData getMetaData() { File metaDir = getMetaDir(); File metaFile = new File(metaDir + "/" + getPath().getName()); - log.log(Level.FINE, "Getting metadata for " + metaFile); + log.log(Level.FINE, () -> "Getting metadata for " + metaFile); if (metaFile.exists()) { try { return mapper.readValue(metaFile, MetaData.class); diff --git a/config-application-package/src/main/java/com/yahoo/config/model/application/provider/FilesApplicationPackage.java b/config-application-package/src/main/java/com/yahoo/config/model/application/provider/FilesApplicationPackage.java index 2f9793112b6..da5bff984db 100644 --- a/config-application-package/src/main/java/com/yahoo/config/model/application/provider/FilesApplicationPackage.java +++ b/config-application-package/src/main/java/com/yahoo/config/model/application/provider/FilesApplicationPackage.java @@ -294,7 +294,7 @@ public class FilesApplicationPackage implements ApplicationPackage { String dir = include.getAttribute(IncludeDirs.DIR); validateIncludeDir(dir); IncludeDirs.validateFilesInIncludedDir(dir, include.getParentNode(), this); - log.log(Level.FINE, "Adding user include dir '" + dir + "'"); + log.log(Level.FINE, () -> "Adding user include dir '" + dir + "'"); userIncludeDirs.add(dir); } @@ -368,7 +368,7 @@ public class FilesApplicationPackage implements ApplicationPackage { private void addAllDefsFromConfigDir(Map<ConfigDefinitionKey, UnparsedConfigDefinition> defs, File configDefsDir) { if (! configDefsDir.isDirectory()) return; - log.log(Level.FINE, "Getting all config definitions from '" + configDefsDir + "'"); + log.log(Level.FINE, () -> "Getting all config definitions from '" + configDefsDir + "'"); for (File def : configDefsDir.listFiles((File dir, String name) -> name.matches(".*\\.def"))) { String[] nv = def.getName().split("\\.def"); ConfigDefinitionKey key; diff --git a/config-application-package/src/main/java/com/yahoo/config/model/application/provider/SchemaValidators.java b/config-application-package/src/main/java/com/yahoo/config/model/application/provider/SchemaValidators.java index 28f74b4adc0..6d7fb398608 100644 --- a/config-application-package/src/main/java/com/yahoo/config/model/application/provider/SchemaValidators.java +++ b/config-application-package/src/main/java/com/yahoo/config/model/application/provider/SchemaValidators.java @@ -110,10 +110,10 @@ public class SchemaValidators { if (uris == null) throw new IllegalArgumentException("Could not find XML schemas "); File tmpDir = createTempDirectory(tmpBase.toPath(), "vespa").toFile(); - log.log(Level.FINE, "Will save all XML schemas for " + vespaVersion + " to " + tmpDir); + log.log(Level.FINE, () -> "Will save all XML schemas for " + vespaVersion + " to " + tmpDir); while (uris.hasMoreElements()) { URL u = uris.nextElement(); - log.log(Level.FINE, "uri for resource 'schema'=" + u.toString()); + log.log(Level.FINE, () -> "uri for resource 'schema'=" + u.toString()); // TODO: When is this the case? Remove? if ("jar".equals(u.getProtocol())) { JarURLConnection jarConnection = (JarURLConnection) u.openConnection(); @@ -127,7 +127,7 @@ public class SchemaValidators { jarFile.close(); } else if ("bundle".equals(u.getProtocol())) { Bundle bundle = getBundle(schemaValidatorClass); - log.log(Level.FINE, "bundle=" + bundle); + log.log(Level.FINE, () -> "bundle=" + bundle); // TODO: Hack to handle cases where bundle=null (which seems to always be the case with config-model-fat-amended.jar) if (bundle == null) { String pathPrefix = getDefaults().underVespaHome("share/vespa/schema/"); @@ -135,11 +135,10 @@ public class SchemaValidators { // Fallback to path without version if path with version does not exist if (! schemaPath.exists()) schemaPath = new File(pathPrefix); - log.log(Level.FINE, "Using schemas found in " + schemaPath); + log.log(Level.FINE, "Using schemas found in %s", schemaPath); copySchemas(schemaPath, tmpDir); } else { - log.log(Level.FINE, String.format("Saving schemas for model bundle %s:%s", bundle.getSymbolicName(), bundle - .getVersion())); + log.log(Level.FINE, () -> String.format("Saving schemas for model bundle %s:%s", bundle.getSymbolicName(), bundle.getVersion())); for (Enumeration<URL> entries = bundle.findEntries("schema", "*.rnc", true); entries.hasMoreElements(); ) { diff --git a/config-model/src/main/java/com/yahoo/config/model/ConfigModelRepo.java b/config-model/src/main/java/com/yahoo/config/model/ConfigModelRepo.java index 454da0d657a..557df4bd106 100644 --- a/config-model/src/main/java/com/yahoo/config/model/ConfigModelRepo.java +++ b/config-model/src/main/java/com/yahoo/config/model/ConfigModelRepo.java @@ -266,7 +266,7 @@ public class ConfigModelRepo implements ConfigModelRepoAdder, Serializable, Iter // TODO: Doctoring on the XML is the wrong level for this. We should be able to mark a model as default instead -Jon private static Element getImplicitAdmin(DeployState deployState) throws IOException, SAXException { String defaultAdminElement = deployState.isHosted() ? getImplicitAdminV4() : getImplicitAdminV2(); - log.log(Level.FINE, "No <admin> defined, using " + defaultAdminElement); + log.log(Level.FINE, () -> "No <admin> defined, using " + defaultAdminElement); return XmlHelper.getDocumentBuilder().parse(new InputSource(new StringReader(defaultAdminElement))).getDocumentElement(); } diff --git a/config-model/src/main/java/com/yahoo/vespa/model/PortFinder.java b/config-model/src/main/java/com/yahoo/vespa/model/PortFinder.java index 968f8399e4b..a3d0d2777ab 100644 --- a/config-model/src/main/java/com/yahoo/vespa/model/PortFinder.java +++ b/config-model/src/main/java/com/yahoo/vespa/model/PortFinder.java @@ -41,7 +41,7 @@ public class PortFinder { String key = request.key(); if (byKeys.containsKey(key)) { int port = byKeys.get(key).port; - log.log(Level.FINE, "Re-using port "+port+" for allocation " + request + " on " + host); + log.log(Level.FINE, () -> "Re-using port "+port+" for allocation " + request + " on " + host); return port; } int port = request.port; diff --git a/config-model/src/main/java/com/yahoo/vespa/model/VespaModel.java b/config-model/src/main/java/com/yahoo/vespa/model/VespaModel.java index 44bade4cd84..d78a69b4802 100644 --- a/config-model/src/main/java/com/yahoo/vespa/model/VespaModel.java +++ b/config-model/src/main/java/com/yahoo/vespa/model/VespaModel.java @@ -407,7 +407,7 @@ public final class VespaModel extends AbstractConfigProducerRoot implements Seri */ protected void checkId(String configId) { if ( ! id2producer.containsKey(configId)) { - log.log(Level.FINE, "Invalid config id: " + configId); + log.log(Level.FINE, () -> "Invalid config id: " + configId); } } diff --git a/config-model/src/main/java/com/yahoo/vespa/model/application/validation/RankSetupValidator.java b/config-model/src/main/java/com/yahoo/vespa/model/application/validation/RankSetupValidator.java index 776ee675ffd..7049213ddab 100644 --- a/config-model/src/main/java/com/yahoo/vespa/model/application/validation/RankSetupValidator.java +++ b/config-model/src/main/java/com/yahoo/vespa/model/application/validation/RankSetupValidator.java @@ -99,11 +99,11 @@ public class RankSetupValidator extends Validator { // Give up, don't say same error msg repeatedly deleteTempDir(tempDir); } - log.log(Level.FINE, String.format("Validating %s for %s, %s took %s ms", - sdName, - searchCluster, - configId, - Duration.between(start, Instant.now()).toMillis())); + log.log(Level.FINE, () -> String.format("Validating %s for %s, %s took %s ms", + sdName, + searchCluster, + configId, + Duration.between(start, Instant.now()).toMillis())); return ret; } catch (IllegalArgumentException e) { deleteTempDir(tempDir); diff --git a/config-model/src/main/java/com/yahoo/vespa/model/builder/UserConfigBuilder.java b/config-model/src/main/java/com/yahoo/vespa/model/builder/UserConfigBuilder.java index 3390eea21bc..4606d9aa885 100644 --- a/config-model/src/main/java/com/yahoo/vespa/model/builder/UserConfigBuilder.java +++ b/config-model/src/main/java/com/yahoo/vespa/model/builder/UserConfigBuilder.java @@ -26,7 +26,7 @@ public class UserConfigBuilder { if (producerSpec == null) { log.log(Level.FINEST, "In getUserConfigs. producerSpec is null"); } - log.log(Level.FINE, "getUserConfigs for " + producerSpec); + log.log(Level.FINE, () -> "getUserConfigs for " + producerSpec); for (Element configE : XML.getChildren(producerSpec, "config")) { buildElement(configE, builderMap, configDefinitionStore, deployLogger); } diff --git a/config-model/src/main/java/com/yahoo/vespa/model/builder/xml/dom/VespaDomBuilder.java b/config-model/src/main/java/com/yahoo/vespa/model/builder/xml/dom/VespaDomBuilder.java index e65fd863d7d..df4cb06ec47 100644 --- a/config-model/src/main/java/com/yahoo/vespa/model/builder/xml/dom/VespaDomBuilder.java +++ b/config-model/src/main/java/com/yahoo/vespa/model/builder/xml/dom/VespaDomBuilder.java @@ -136,7 +136,7 @@ public class VespaDomBuilder extends VespaModelBuilder { UserConfigRepo userConfigs = UserConfigBuilder.build(producerSpec, deployState, deployState.getDeployLogger()); // TODO: must be made to work: //userConfigs.applyWarnings(child); - log.log(Level.FINE, "Adding user configs " + userConfigs + " for " + producerSpec); + log.log(Level.FINE, () -> "Adding user configs " + userConfigs + " for " + producerSpec); child.mergeUserConfigs(userConfigs); } diff --git a/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/ConfigProxyRpcServer.java b/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/ConfigProxyRpcServer.java index fbc10c772d7..3700dee92e3 100644 --- a/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/ConfigProxyRpcServer.java +++ b/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/ConfigProxyRpcServer.java @@ -50,7 +50,7 @@ public class ConfigProxyRpcServer implements Runnable, TargetWatcher, RpcServer public void run() { try { Acceptor acceptor = supervisor.listen(spec); - log.log(Level.FINE, "Ready for requests on " + spec); + log.log(Level.FINE, () -> "Ready for requests on " + spec); supervisor.transport().join(); acceptor.shutdown().join(); } catch (ListenFailedException e) { @@ -284,7 +284,7 @@ public class ConfigProxyRpcServer implements Runnable, TargetWatcher, RpcServer } else if (ProxyServer.configOrGenerationHasChanged(config, request)) { returnOkResponse(request, config); } else { - log.log(Level.FINEST, "No new config for " + request.getShortDescription() + ", not sending response"); + log.log(Level.FINEST, () -> "No new config for " + request.getShortDescription() + ", not sending response"); } } catch (Exception e) { e.printStackTrace(); diff --git a/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/MemoryCache.java b/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/MemoryCache.java index ac6fac3b16c..86f2022fa82 100644 --- a/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/MemoryCache.java +++ b/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/MemoryCache.java @@ -109,16 +109,15 @@ public class MemoryCache { } private void writeConfigToFile(RawConfig config, String path) { - String filename = null; + String filename = path + File.separator + createCacheFileName(config); Writer writer = null; try { - filename = path + File.separator + createCacheFileName(config); if (log.isLoggable(Level.FINE)) { log.log(Level.FINE, "Writing '" + config.getKey() + "' to '" + filename + "'"); } final Payload payload = config.getPayload(); long protocolVersion = 3; - log.log(Level.FINE, "Writing config '" + config + "' to file '" + filename + "' with protocol version " + protocolVersion); + log.log(Level.FINE, () -> "Writing config '" + config + "' to file '" + filename + "' with protocol version " + protocolVersion); writer = IOUtils.createWriter(filename, "UTF-8", false); // First three lines are meta-data about config as comment lines, fourth line is empty diff --git a/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/ProxyServer.java b/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/ProxyServer.java index ccd53cf8491..047cec87ed7 100644 --- a/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/ProxyServer.java +++ b/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/ProxyServer.java @@ -57,7 +57,7 @@ public class ProxyServer implements Runnable { ProxyServer(Spec spec, ConfigSourceSet source, MemoryCache memoryCache, ConfigSourceClient configClient) { this.configSource = source; supervisor = new Supervisor(new Transport("proxy-server", JRT_TRANSPORT_THREADS)).useSmallBuffers(); - log.log(Level.FINE, "Using config source '" + source); + log.log(Level.FINE, () -> "Using config source '" + source); this.memoryCache = memoryCache; this.rpcServer = createRpcServer(spec); this.configClient = (configClient == null) ? createRpcClient(rpcServer, source, memoryCache) : configClient; diff --git a/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/filedistribution/CachedFilesMaintainer.java b/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/filedistribution/CachedFilesMaintainer.java index 247ef8a4dbf..27790eedec7 100644 --- a/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/filedistribution/CachedFilesMaintainer.java +++ b/config-proxy/src/main/java/com/yahoo/vespa/config/proxy/filedistribution/CachedFilesMaintainer.java @@ -63,7 +63,7 @@ class CachedFilesMaintainer implements Runnable { File[] files = directory.listFiles(); if (files != null) filesOnDisk.addAll(Arrays.stream(files).map(File::getName).collect(Collectors.toSet())); - log.log(Level.FINE, "Files on disk (in " + directory + "): " + filesOnDisk); + log.log(Level.FINE, () -> "Files on disk (in " + directory + "): " + filesOnDisk); Set<String> filesToDelete = filesOnDisk .stream() diff --git a/config/src/main/java/com/yahoo/config/subscription/impl/FileConfigSubscription.java b/config/src/main/java/com/yahoo/config/subscription/impl/FileConfigSubscription.java index 365f6a4d4c5..ce375f9fdbf 100644 --- a/config/src/main/java/com/yahoo/config/subscription/impl/FileConfigSubscription.java +++ b/config/src/main/java/com/yahoo/config/subscription/impl/FileConfigSubscription.java @@ -38,12 +38,12 @@ public class FileConfigSubscription<T extends ConfigInstance> extends ConfigSubs public boolean nextConfig(long timeout) { if (!file.exists() && !file.isFile()) throw new IllegalArgumentException("Not a file: "+file); if (checkReloaded()) { - log.log(FINE, "User forced config reload at " + System.currentTimeMillis()); + log.log(FINE, () -> "User forced config reload at " + System.currentTimeMillis()); // User forced reload setConfigIfChanged(updateConfig()); ConfigState<T> configState = getConfigState(); - log.log(FINE, "Config updated at " + System.currentTimeMillis() + ", changed: " + configState.isConfigChanged()); - log.log(FINE, "Config: " + configState.getConfig().toString()); + log.log(FINE, () -> "Config updated at " + System.currentTimeMillis() + ", changed: " + configState.isConfigChanged()); + log.log(FINE, () -> "Config: " + configState.getConfig().toString()); return true; } if (file.lastModified()!=ts) { diff --git a/configserver-client/src/main/java/ai/vespa/hosted/client/AbstractConfigServerClient.java b/configserver-client/src/main/java/ai/vespa/hosted/client/AbstractConfigServerClient.java index 2e5e445d63a..81970d47bc7 100644 --- a/configserver-client/src/main/java/ai/vespa/hosted/client/AbstractConfigServerClient.java +++ b/configserver-client/src/main/java/ai/vespa/hosted/client/AbstractConfigServerClient.java @@ -71,7 +71,7 @@ public abstract class AbstractConfigServerClient implements ConfigServerClient { log.log(WARNING, "Cannot retry " + request + " as entity is not repeatable"); break; } - log.log(FINE, request + " failed; will retry", e.getCause()); + log.log(FINE, e.getCause(), () -> request + " failed; will retry"); } } if (thrown != null) { diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/ApplicationRepository.java b/configserver/src/main/java/com/yahoo/vespa/config/server/ApplicationRepository.java index 536d8894526..9c6786886ef 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/ApplicationRepository.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/ApplicationRepository.java @@ -462,12 +462,12 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye static void checkIfActiveHasChanged(Session session, Session activeSession, boolean ignoreStaleSessionFailure) { long activeSessionAtCreate = session.getActiveSessionAtCreate(); - log.log(Level.FINE, activeSession.logPre() + "active session id at create time=" + activeSessionAtCreate); + log.log(Level.FINE, () -> activeSession.logPre() + "active session id at create time=" + activeSessionAtCreate); if (activeSessionAtCreate == 0) return; // No active session at create time long sessionId = session.getSessionId(); long activeSessionSessionId = activeSession.getSessionId(); - log.log(Level.FINE, activeSession.logPre() + "sessionId=" + sessionId + + log.log(Level.FINE, () -> activeSession.logPre() + "sessionId=" + sessionId + ", current active session=" + activeSessionSessionId); if (activeSession.isNewerThan(activeSessionAtCreate) && activeSessionSessionId != sessionId) { @@ -579,17 +579,17 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye } public List<String> deleteUnusedFiledistributionReferences(File fileReferencesPath, Duration keepFileReferences) { - log.log(Level.FINE, "Keep unused file references for " + keepFileReferences); + log.log(Level.FINE, () -> "Keep unused file references for " + keepFileReferences); if (!fileReferencesPath.isDirectory()) throw new RuntimeException(fileReferencesPath + " is not a directory"); Set<String> fileReferencesInUse = getFileReferencesInUse(); - log.log(Level.FINE, "File references in use : " + fileReferencesInUse); + log.log(Level.FINE, () -> "File references in use : " + fileReferencesInUse); List<String> candidates = sortedUnusedFileReferences(fileReferencesPath, fileReferencesInUse, keepFileReferences); // Do not delete the newest ones List<String> fileReferencesToDelete = candidates.subList(0, Math.max(0, candidates.size() - 5)); if (fileReferencesToDelete.size() > 0) { - log.log(Level.FINE, "Will delete file references not in use: " + fileReferencesToDelete); + log.log(Level.FINE, () -> "Will delete file references not in use: " + fileReferencesToDelete); fileReferencesToDelete.forEach(fileReference -> { File file = new File(fileReferencesPath, fileReference); if ( ! IOUtils.recursiveDeleteDir(file)) @@ -619,7 +619,7 @@ public class ApplicationRepository implements com.yahoo.config.provision.Deploye private List<String> sortedUnusedFileReferences(File fileReferencesPath, Set<String> fileReferencesInUse, Duration keepFileReferences) { Set<String> fileReferencesOnDisk = getFileReferencesOnDisk(fileReferencesPath); - log.log(Level.FINE, "File references on disk (in " + fileReferencesPath + "): " + fileReferencesOnDisk); + log.log(Level.FINE, () -> "File references on disk (in " + fileReferencesPath + "): " + fileReferencesOnDisk); Instant instant = Instant.now().minus(keepFileReferences); return fileReferencesOnDisk .stream() diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/ConfigServerBootstrap.java b/configserver/src/main/java/com/yahoo/vespa/config/server/ConfigServerBootstrap.java index 8a7738bc672..62f3e40cb50 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/ConfigServerBootstrap.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/ConfigServerBootstrap.java @@ -98,7 +98,7 @@ public class ConfigServerBootstrap extends AbstractComponent implements Runnable this.exitIfRedeployingApplicationsFails = exitIfRedeployingApplicationsFails; rpcServerExecutor = Executors.newSingleThreadExecutor(new DaemonThreadFactory("config server RPC server")); - log.log(Level.FINE, "Bootstrap mode: " + mode + ", VIP status mode: " + vipStatusMode); + log.log(Level.FINE, () -> "Bootstrap mode: " + mode + ", VIP status mode: " + vipStatusMode); initializing(vipStatusMode); switch (mode) { diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/ConfigServerDB.java b/configserver/src/main/java/com/yahoo/vespa/config/server/ConfigServerDB.java index c788b73720d..8594c7857a9 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/ConfigServerDB.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/ConfigServerDB.java @@ -68,10 +68,10 @@ public class ConfigServerDB { for (String pluginDirectory : pluginDirectories) { bundles.addAll(Bundle.getBundles(new File(pluginDirectory))); } - log.log(Level.FINE, "Found " + bundles.size() + " bundles"); + log.log(Level.FINE, () -> "Found " + bundles.size() + " bundles"); List<Bundle> addedBundles = new ArrayList<>(); for (Bundle bundle : bundles) { - log.log(Level.FINE, "Bundle in " + bundle.getFile().getAbsolutePath() + " appears to contain " + bundle.getDefEntries().size() + " entries"); + log.log(Level.FINE, () -> "Bundle in " + bundle.getFile().getAbsolutePath() + " appears to contain " + bundle.getDefEntries().size() + " entries"); configDefinitionDir.addConfigDefinitionsFromBundle(bundle, addedBundles); addedBundles.add(bundle); } diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/application/Application.java b/configserver/src/main/java/com/yahoo/vespa/config/server/application/Application.java index 8e98bf5884b..baded957475 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/application/Application.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/application/Application.java @@ -105,16 +105,12 @@ public class Application implements ModelResult { defMd5 = ConfigUtils.getDefMd5(req.getDefContent().asList()); } ConfigCacheKey cacheKey = new ConfigCacheKey(configKey, defMd5); - if (logDebug()) { - debug("Resolving config " + cacheKey); - } + log.log(Level.FINE, () -> TenantRepository.logPre(getId()) + ("Resolving config " + cacheKey)); if (useCache(req)) { ConfigResponse config = cache.get(cacheKey); if (config != null) { - if (logDebug()) { - debug("Found config " + cacheKey + " in cache"); - } + log.log(Level.FINE, () -> TenantRepository.logPre(getId()) + ("Found config " + cacheKey + " in cache")); metricUpdater.incrementProcTime(System.currentTimeMillis() - start); return config; } @@ -125,9 +121,7 @@ public class Application implements ModelResult { metricUpdater.incrementFailedRequests(); throw new UnknownConfigDefinitionException("Unable to find config definition for '" + configKey.getNamespace() + "." + configKey.getName()); } - if (logDebug()) { - debug("Resolving " + configKey + " with config definition " + def); - } + log.log(Level.FINE, () -> TenantRepository.logPre(getId()) + ("Resolving " + configKey + " with config definition " + def)); ConfigInstance.Builder builder; ConfigPayload payload; @@ -174,27 +168,15 @@ public class Application implements ModelResult { return !request.noCache(); } - private boolean logDebug() { - return log.isLoggable(Level.FINE); - } - - private void debug(String message) { - log.log(Level.FINE, TenantRepository.logPre(getId()) + message); - } - private ConfigDefinition getTargetDef(GetConfigRequest req) { ConfigKey<?> configKey = req.getConfigKey(); DefContent def = req.getDefContent(); ConfigDefinitionKey configDefinitionKey = new ConfigDefinitionKey(configKey.getName(), configKey.getNamespace()); if (def.isEmpty()) { - if (logDebug()) { - debug("No config schema in request for " + configKey); - } + log.log(Level.FINE, () -> TenantRepository.logPre(getId()) + ("No config schema in request for " + configKey)); return cache.getDef(configDefinitionKey); } else { - if (logDebug()) { - debug("Got config schema from request, length:" + def.asList().size() + " : " + configKey); - } + log.log(Level.FINE, () -> TenantRepository.logPre(getId()) + ("Got config schema from request, length:" + def.asList().size() + " : " + configKey)); return new ConfigDefinition(configKey.getName(), def.asStringArray()); } } diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/application/CompressedApplicationInputStream.java b/configserver/src/main/java/com/yahoo/vespa/config/server/application/CompressedApplicationInputStream.java index dae5c6aecef..858731b5a89 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/application/CompressedApplicationInputStream.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/application/CompressedApplicationInputStream.java @@ -89,23 +89,23 @@ public class CompressedApplicationInputStream implements AutoCloseable { } private void decompressInto(File application) throws IOException { - log.log(Level.FINE, "Application is in " + application.getAbsolutePath()); + log.log(Level.FINE, () -> "Application is in " + application.getAbsolutePath()); int entries = 0; ArchiveEntry entry; while ((entry = ais.getNextEntry()) != null) { - log.log(Level.FINE, "Unpacking " + entry.getName()); + log.log(Level.FINE, "Unpacking %s", entry.getName()); File outFile = new File(application, entry.getName()); // FIXME/TODO: write more tests that break this logic. I have a feeling it is not very robust. if (entry.isDirectory()) { if (!(outFile.exists() && outFile.isDirectory())) { - log.log(Level.FINE, "Creating dir: " + outFile.getAbsolutePath()); + log.log(Level.FINE, () -> "Creating dir: " + outFile.getAbsolutePath()); boolean res = outFile.mkdirs(); if (!res) { log.log(Level.WARNING, "Could not create dir " + entry.getName()); } } } else { - log.log(Level.FINE, "Creating output file: " + outFile.getAbsolutePath()); + log.log(Level.FINE, () -> "Creating output file: " + outFile.getAbsolutePath()); // Create parent dir if necessary String parent = outFile.getParent(); diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/application/PermanentApplicationPackage.java b/configserver/src/main/java/com/yahoo/vespa/config/server/application/PermanentApplicationPackage.java index ac994e8405d..a028f92d681 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/application/PermanentApplicationPackage.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/application/PermanentApplicationPackage.java @@ -25,7 +25,7 @@ public class PermanentApplicationPackage { File app = new File(getDefaults().underVespaHome(config.applicationDirectory())); applicationPackage = Optional.ofNullable(app.exists() ? FilesApplicationPackage.fromFile(app) : null); if (applicationPackage.isPresent()) { - log.log(Level.FINE, "Detected permanent application package in '" + + log.log(Level.FINE, () -> "Detected permanent application package in '" + getDefaults().underVespaHome(config.applicationDirectory()) + "'. This might add extra services to config models"); } diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/application/TenantApplications.java b/configserver/src/main/java/com/yahoo/vespa/config/server/application/TenantApplications.java index eb179d2d9aa..dd514e0d843 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/application/TenantApplications.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/application/TenantApplications.java @@ -184,7 +184,7 @@ public class TenantApplications implements RequestHandler, HostValidator<Applica /* A new application is added when a session is added, @see {@link com.yahoo.vespa.config.server.session.SessionRepository#childEvent(CuratorFramework, PathChildrenCacheEvent)} */ ApplicationId applicationId = ApplicationId.fromSerializedForm(Path.fromString(event.getData().getPath()).getName()); - log.log(Level.FINE, TenantRepository.logPre(applicationId) + "Application added: " + applicationId); + log.log(Level.FINE, () -> TenantRepository.logPre(applicationId) + "Application added: " + applicationId); break; // Event CHILD_REMOVED will be triggered on all config servers if deleteApplication() above is called on one of them case CHILD_REMOVED: @@ -241,7 +241,7 @@ public class TenantApplications implements RequestHandler, HostValidator<Applica // (when getting event from zookeeper to remove application, // the lock should be held by the thread that causes the event to happen) public void removeApplication(ApplicationId applicationId) { - log.log(Level.FINE, "Removing application " + applicationId); + log.log(Level.FINE, () -> "Removing application " + applicationId); if (exists(applicationId)) { log.log(Level.INFO, "Tried removing application " + applicationId + ", but it seems to have been deployed again"); return; @@ -491,7 +491,7 @@ public class TenantApplications implements RequestHandler, HostValidator<Applica private void logBarrierCompleted(List<String> respondents, Instant startTime) { Duration duration = Duration.between(startTime, Instant.now()); Level level = (duration.minus(Duration.ofSeconds(5))).isNegative() ? Level.FINE : Level.INFO; - log.log(level, barrierCompletedMessage(respondents, duration)); + log.log(level, () -> barrierCompletedMessage(respondents, duration)); } private String barrierCompletedMessage(List<String> respondents, Duration duration) { diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileDirectory.java b/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileDirectory.java index 07a686a63bd..f7ba895666b 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileDirectory.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileDirectory.java @@ -80,7 +80,7 @@ public class FileDirectory { if (file.isDirectory()) { return Files.walk(file.toPath(), 100).map(path -> { try { - log.log(Level.FINE, "Calculating hash for '" + path + "'"); + log.log(Level.FINE, () -> "Calculating hash for '" + path + "'"); return hash(path.toFile(), hasher); } catch (IOException e) { log.log(Level.WARNING, "Failed getting hash from '" + path + "'"); @@ -141,15 +141,15 @@ public class FileDirectory { File destination = new File(tempDestinationDir.toFile(), source.getName()); if (!destinationDir.exists()) { destinationDir.mkdir(); - log.log(Level.FINE, "file reference ' " + reference.value() + "', source: " + source.getAbsolutePath() ); + log.log(Level.FINE, () -> "file reference ' " + reference.value() + "', source: " + source.getAbsolutePath() ); if (source.isDirectory()) { - log.log(Level.FINE, "Copying source " + source.getAbsolutePath() + " to " + destination.getAbsolutePath()); + log.log(Level.FINE, () -> "Copying source " + source.getAbsolutePath() + " to " + destination.getAbsolutePath()); IOUtils.copyDirectory(source, destination, -1); } else { copyFile(source, destination); } if (!destinationDir.exists()) { - log.log(Level.FINE, "Moving from " + tempDestinationDir + " to " + destinationDir.getAbsolutePath()); + log.log(Level.FINE, () -> "Moving from " + tempDestinationDir + " to " + destinationDir.getAbsolutePath()); if ( ! tempDestinationDir.toFile().renameTo(destinationDir)) { log.log(Level.WARNING, "Failed moving '" + tempDestinationDir.toFile().getAbsolutePath() + "' to '" + destination.getAbsolutePath() + "'."); } @@ -166,7 +166,7 @@ public class FileDirectory { private void logfileInfo(File file ) throws IOException { BasicFileAttributes basicFileAttributes = Files.readAttributes(file.toPath(), BasicFileAttributes.class); - log.log(Level.FINE, "Adding file " + file.getAbsolutePath() + " (created " + basicFileAttributes.creationTime() + + log.log(Level.FINE, () -> "Adding file " + file.getAbsolutePath() + " (created " + basicFileAttributes.creationTime() + ", modified " + basicFileAttributes.lastModifiedTime() + ", size " + basicFileAttributes.size() + ")"); } diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileDistributionImpl.java b/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileDistributionImpl.java index 56bdeab76b2..2eebbfa4acf 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileDistributionImpl.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileDistributionImpl.java @@ -49,7 +49,7 @@ public class FileDistributionImpl implements FileDistribution, RequestWaiter { Request request = new Request("filedistribution.setFileReferencesToDownload"); request.setContext(target); request.parameters().add(new StringArray(fileReferences.stream().map(FileReference::value).toArray(String[]::new))); - log.log(Level.FINE, "Executing " + request.methodName() + " against " + target); + log.log(Level.FINE, () -> "Executing " + request.methodName() + " against " + target); target.invokeAsync(request, rpcTimeout, this); } @@ -58,7 +58,7 @@ public class FileDistributionImpl implements FileDistribution, RequestWaiter { public void handleRequestDone(Request req) { Target target = (Target) req.getContext(); if (req.isError()) { - log.log(Level.FINE, req.methodName() + " failed for " + target + ": " + req.errorCode() + " (" + req.errorMessage() + ")"); + log.log(Level.FINE, () -> req.methodName() + " failed for " + target + ": " + req.errorCode() + " (" + req.errorMessage() + ")"); } if (target != null) target.close(); } diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileServer.java b/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileServer.java index 66f886a8fcc..c123a0c058f 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileServer.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/filedistribution/FileServer.java @@ -100,7 +100,7 @@ public class FileServer { try { return root.getFile(reference).exists(); } catch (IllegalArgumentException e) { - log.log(Level.FINE, "Failed locating file reference '" + reference + "' with error " + e.toString()); + log.log(Level.FINE, () -> "Failed locating file reference '" + reference + "' with error " + e.toString()); } return false; } @@ -130,7 +130,7 @@ public class FileServer { try { target.receive(fileData, new ReplayStatus(success ? 0 : 1, success ? "OK" : errorDescription)); - log.log(Level.FINE, "Done serving file reference '" + reference.value() + "' with file '" + file.getAbsolutePath() + "'"); + log.log(Level.FINE, () -> "Done serving file reference '" + reference.value() + "' with file '" + file.getAbsolutePath() + "'"); } catch (Exception e) { log.log(Level.WARNING, "Failed serving file reference '" + reference.value() + "': " + Exceptions.toMessageString(e)); } finally { diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/http/HttpGetConfigHandler.java b/configserver/src/main/java/com/yahoo/vespa/config/server/http/HttpGetConfigHandler.java index 7458c82942f..b6f2c2e0919 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/http/HttpGetConfigHandler.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/http/HttpGetConfigHandler.java @@ -41,7 +41,7 @@ public class HttpGetConfigHandler extends HttpHandler { } private ConfigResponse resolveConfig(HttpConfigRequest request) { - log.log(Level.FINE, "nocache=" + request.noCache()); + log.log(Level.FINE, () -> "nocache=" + request.noCache()); ConfigResponse config = requestHandler.resolveConfig(ApplicationId.defaultId(), request, Optional.empty()); if (config == null) HttpConfigRequest.throwModelNotReady(); return config; diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/http/HttpHandler.java b/configserver/src/main/java/com/yahoo/vespa/config/server/http/HttpHandler.java index e92eb52028b..78a7b8aaa8f 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/http/HttpHandler.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/http/HttpHandler.java @@ -32,7 +32,7 @@ public class HttpHandler extends LoggingRequestHandler { @Override public HttpResponse handle(HttpRequest request) { - log.log(Level.FINE, request.getMethod() + " " + request.getUri().toString()); + log.log(Level.FINE, () -> request.getMethod() + " " + request.getUri().toString()); try { switch (request.getMethod()) { case POST: diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/http/SessionContentStatusListResponse.java b/configserver/src/main/java/com/yahoo/vespa/config/server/http/SessionContentStatusListResponse.java index 08cda869111..860189a171c 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/http/SessionContentStatusListResponse.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/http/SessionContentStatusListResponse.java @@ -25,7 +25,7 @@ class SessionContentStatusListResponse extends SlimeJsonResponse { element.setString("status", f.getMetaData().getStatus()); element.setString("md5", f.getMetaData().getMd5()); element.setString("name", urlBase + f.getPath()); - log.log(Level.FINE, "Adding file " + urlBase + f.getPath()); + log.log(Level.FINE, () -> "Adding file " + urlBase + f.getPath()); } } diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/http/TesterClient.java b/configserver/src/main/java/com/yahoo/vespa/config/server/http/TesterClient.java index 4292a0806c2..43552d317cd 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/http/TesterClient.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/http/TesterClient.java @@ -65,7 +65,7 @@ public class TesterClient { } private HttpResponse execute(HttpUriRequest request, String messageIfRequestFails) { - logger.log(Level.FINE, "Sending request to tester container " + request.getURI().toString()); + logger.log(Level.FINE, () -> "Sending request to tester container " + request.getURI().toString()); try { return new ProxyResponse(httpClient.execute(request)); } catch (IOException e) { diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/http/v2/HttpGetConfigHandler.java b/configserver/src/main/java/com/yahoo/vespa/config/server/http/v2/HttpGetConfigHandler.java index b4ce833cb75..1787431e841 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/http/v2/HttpGetConfigHandler.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/http/v2/HttpGetConfigHandler.java @@ -41,7 +41,7 @@ public class HttpGetConfigHandler extends HttpHandler { } private ConfigResponse resolveConfig(HttpConfigRequest request, RequestHandler requestHandler) { - log.log(Level.FINE, "nocache=" + request.noCache()); + log.log(Level.FINE, () -> "nocache=" + request.noCache()); ConfigResponse config = requestHandler.resolveConfig(request.getApplicationId(), request, Optional.empty()); if (config == null) HttpConfigRequest.throwModelNotReady(); return config; diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/ActivatedModelsBuilder.java b/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/ActivatedModelsBuilder.java index da720ca8cb9..5c0207878f1 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/ActivatedModelsBuilder.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/ActivatedModelsBuilder.java @@ -102,8 +102,8 @@ public class ActivatedModelsBuilder extends ModelsBuilder<Application> { Version wantedNodeVespaVersion, Optional<AllocatedHosts> ignored // Ignored since we have this in the app package for activated models ) { - log.log(Level.FINE, String.format("Loading model version %s for session %s application %s", - modelFactory.version(), applicationGeneration, applicationId)); + log.log(Level.FINE, () -> String.format("Loading model version %s for session %s application %s", + modelFactory.version(), applicationGeneration, applicationId)); ModelContext.Properties modelContextProperties = createModelContextProperties(applicationId); Provisioned provisioned = new Provisioned(); ModelContext modelContext = new ModelContextImpl( diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/ModelsBuilder.java b/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/ModelsBuilder.java index b80037eef56..227e9c6a977 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/ModelsBuilder.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/ModelsBuilder.java @@ -81,7 +81,7 @@ public abstract class ModelsBuilder<MODELRESULT extends ModelResult> { SettableOptional<AllocatedHosts> allocatedHosts, Instant now) { Instant start = Instant.now(); - log.log(Level.FINE, "Will build models for " + applicationId); + log.log(Level.FINE, () -> "Will build models for " + applicationId); Set<Version> versions = modelFactoryRegistry.allVersions(); // If the application specifies a major, skip models on a newer major @@ -133,7 +133,7 @@ public abstract class ModelsBuilder<MODELRESULT extends ModelResult> { } } } - log.log(Level.FINE, "Done building models for " + applicationId + ". Built models for versions " + + log.log(Level.FINE, () -> "Done building models for " + applicationId + ". Built models for versions " + allApplicationModels.stream() .map(result -> result.getModel().version()) .map(Version::toFullString) diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/PreparedModelsBuilder.java b/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/PreparedModelsBuilder.java index 4dd3171fbf1..7a0a261c7ad 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/PreparedModelsBuilder.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/modelfactory/PreparedModelsBuilder.java @@ -91,7 +91,7 @@ public class PreparedModelsBuilder extends ModelsBuilder<PreparedModelsBuilder.P Version wantedNodeVespaVersion, Optional<AllocatedHosts> allocatedHosts) { Version modelVersion = modelFactory.version(); - log.log(Level.FINE, "Building model " + modelVersion + " for " + applicationId); + log.log(Level.FINE, () -> "Building model " + modelVersion + " for " + applicationId); // Use empty on non-hosted systems, use already allocated hosts if available, create connection to a host provisioner otherwise Provisioned provisioned = new Provisioned(); @@ -117,13 +117,13 @@ public class PreparedModelsBuilder extends ModelsBuilder<PreparedModelsBuilder.P private ModelCreateResult createAndValidateModel(ModelFactory modelFactory, ApplicationId applicationId, Version modelVersion, ModelContext modelContext) { log.log(properties.zone().system().isCd() ? Level.INFO : Level.FINE, - "Create and validate model " + modelVersion + " for " + applicationId + ", previous model is " + + () -> "Create and validate model " + modelVersion + " for " + applicationId + ", previous model is " + modelOf(modelVersion).map(Model::version).map(Version::toFullString).orElse("non-existing")); ValidationParameters validationParameters = new ValidationParameters(params.ignoreValidationErrors() ? IgnoreValidationErrors.TRUE : IgnoreValidationErrors.FALSE); ModelCreateResult result = modelFactory.createAndValidateModel(modelContext, validationParameters); validateModelHosts(hostValidator, applicationId, result.getModel()); - log.log(Level.FINE, "Done building model " + modelVersion + " for " + applicationId); + log.log(Level.FINE, () -> "Done building model " + modelVersion + " for " + applicationId); params.getTimeoutBudget().assertNotTimedOut(() -> "prepare timed out after building model " + modelVersion + " (timeout " + params.getTimeoutBudget().timeout() + "): " + applicationId); return result; diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/monitoring/Metrics.java b/configserver/src/main/java/com/yahoo/vespa/config/server/monitoring/Metrics.java index e3516535b46..dca58665f57 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/monitoring/Metrics.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/monitoring/Metrics.java @@ -57,7 +57,7 @@ public class Metrics extends AbstractComponent implements MetricUpdaterFactory, procTimeCounter = createCounter("procTime", statistics); if (createZkMetricUpdater) { - log.log(Level.FINE, "Metric update interval is " + healthMonitorConfig.snapshot_interval() + " seconds"); + log.log(Level.FINE, () -> "Metric update interval is " + healthMonitorConfig.snapshot_interval() + " seconds"); long intervalMs = (long) (healthMonitorConfig.snapshot_interval() * 1000); executorService = Optional.of(new ScheduledThreadPoolExecutor(1, new DaemonThreadFactory("configserver-metrics"))); executorService.get().scheduleAtFixedRate(this, 20000, intervalMs, TimeUnit.MILLISECONDS); @@ -130,9 +130,9 @@ public class Metrics extends AbstractComponent implements MetricUpdaterFactory, @Override public void run() { for (MetricUpdater metricUpdater : metricUpdaters.values()) { - log.log(Level.FINE, "Running metric updater for static values for " + metricUpdater.getDimensions()); + log.log(Level.FINE, () -> "Running metric updater for static values for " + metricUpdater.getDimensions()); for (Map.Entry<String, Number> fixedMetric : metricUpdater.getStaticMetrics().entrySet()) { - log.log(Level.FINE, "Setting " + fixedMetric.getKey()); + log.log(Level.FINE, () -> "Setting " + fixedMetric.getKey()); metric.set(fixedMetric.getKey(), fixedMetric.getValue(), metricUpdater.getMetricContext()); } } diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/DelayedConfigResponses.java b/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/DelayedConfigResponses.java index 9820eac2f30..960efc876ee 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/DelayedConfigResponses.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/DelayedConfigResponses.java @@ -171,7 +171,7 @@ public class DelayedConfigResponses { */ final void delayResponse(JRTServerConfigRequest request, GetConfigContext context) { if (request.isDelayedResponse()) { - log.log(Level.FINE, context.logPre()+"Request already delayed"); + log.log(Level.FINE, () -> context.logPre()+"Request already delayed"); } else { createQueueIfNotExists(context); BlockingQueue<DelayedConfigResponse> delayedResponsesQueue = delayedResponses.get(context.applicationId()); diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/GetConfigProcessor.java b/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/GetConfigProcessor.java index 010640b967f..637fc421457 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/GetConfigProcessor.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/GetConfigProcessor.java @@ -49,7 +49,7 @@ class GetConfigProcessor implements Runnable { Request req = request.getRequest(); if (req.isError()) { Level logLevel = (req.errorCode() == ErrorCode.APPLICATION_NOT_LOADED) ? Level.FINE : Level.INFO; - log.log(logLevel, logPre + req.errorMessage()); + log.log(logLevel, () -> logPre + req.errorMessage()); } rpcServer.respond(request); } @@ -177,7 +177,7 @@ class GetConfigProcessor implements Runnable { private void debugLog(Trace trace, String message) { if (logDebug(trace)) { - log.log(Level.FINE, logPre + message); + log.log(Level.FINE, () -> logPre + message); trace.trace(RpcServer.TRACELEVEL_DEBUG, logPre + message); } } diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/RpcServer.java b/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/RpcServer.java index 370ae72bbbd..5b9b3077008 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/RpcServer.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/rpc/RpcServer.java @@ -280,7 +280,7 @@ public class RpcServer implements Runnable, ReloadListener, TenantListener { responsesSent++; } } else { - log.log(Level.FINE, logPre + "Timer already cancelled or finished or never scheduled"); + log.log(Level.FINE, () -> logPre + "Timer already cancelled or finished or never scheduled"); } } @@ -292,7 +292,8 @@ public class RpcServer implements Runnable, ReloadListener, TenantListener { } } - log.log(Level.FINE, logPre + "Finished reloading " + responsesSent + " requests"); + if (log.isLoggable(Level.FINE)) + log.log(Level.FINE, logPre + "Finished reloading " + responsesSent + " requests"); } private void logRequestDebug(Level level, String message, JRTServerConfigRequest request) { @@ -303,7 +304,7 @@ public class RpcServer implements Runnable, ReloadListener, TenantListener { @Override public void hostsUpdated(ApplicationId applicationId, Collection<String> newHosts) { - log.log(Level.FINE, "Updating hosts in tenant host registry '" + hostRegistry + "' with " + newHosts); + log.log(Level.FINE, () -> "Updating hosts in tenant host registry '" + hostRegistry + "' with " + newHosts); hostRegistry.update(applicationId, newHosts); } @@ -338,7 +339,7 @@ public class RpcServer implements Runnable, ReloadListener, TenantListener { if (GetConfigProcessor.logDebug(trace)) { String message = "Did not find tenant for host '" + hostname + "', using " + TenantName.defaultName(); log.log(Level.FINE, message); - log.log(Level.FINE, "hosts in host registry: " + hostRegistry.getAllHosts()); + log.log(Level.FINE, () -> "hosts in host registry: " + hostRegistry.getAllHosts()); trace.trace(6, message); } return Optional.empty(); @@ -424,7 +425,7 @@ public class RpcServer implements Runnable, ReloadListener, TenantListener { @Override public void onTenantDelete(TenantName tenant) { - log.log(Level.FINE, TenantRepository.logPre(tenant) + + log.log(Level.FINE, () -> TenantRepository.logPre(tenant) + "Tenant deleted, removing request handler and cleaning host registry"); tenants.remove(tenant); hostRegistry.removeHostsForKey(tenant); diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/session/SessionRepository.java b/configserver/src/main/java/com/yahoo/vespa/config/server/session/SessionRepository.java index 181ed880fd7..cb46d65c4c5 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/session/SessionRepository.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/session/SessionRepository.java @@ -457,9 +457,9 @@ public class SessionRepository { void confirmUpload(Session session) { CompletionWaiter waiter = session.getSessionZooKeeperClient().getUploadWaiter(); long sessionId = session.getSessionId(); - log.log(Level.FINE, "Notifying upload waiter for session " + sessionId); + log.log(Level.FINE, () -> "Notifying upload waiter for session " + sessionId); notifyCompletion(waiter); - log.log(Level.FINE, "Done notifying upload for session " + sessionId); + log.log(Level.FINE, () -> "Done notifying upload for session " + sessionId); } void notifyCompletion(CompletionWaiter completionWaiter) { @@ -476,7 +476,7 @@ public class SessionRepository { KeeperException.NodeExistsException.class); Class<? extends Throwable> exceptionClass = e.getCause().getClass(); if (acceptedExceptions.contains(exceptionClass)) - log.log(Level.FINE, "Not able to notify completion for session (" + completionWaiter + ")," + + log.log(Level.FINE, () -> "Not able to notify completion for session (" + completionWaiter + ")," + " node " + (exceptionClass.equals(KeeperException.NoNodeException.class) ? "has been deleted" : "already exists")); @@ -726,7 +726,7 @@ public class SessionRepository { } catch (IllegalArgumentException e) { // We cannot be guaranteed that the file reference exists (it could be that it has not // been downloaded yet), and e.g when bootstrapping we cannot throw an exception in that case - log.log(Level.FINE, "File reference for session id " + sessionId + ": " + fileReference + " not found in " + fileDirectory); + log.log(Level.FINE, () -> "File reference for session id " + sessionId + ": " + fileReference + " not found in " + fileDirectory); return; } ApplicationId applicationId = sessionZKClient.readApplicationId() diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/session/SessionStateWatcher.java b/configserver/src/main/java/com/yahoo/vespa/config/server/session/SessionStateWatcher.java index b27cdbdc341..880519b3d61 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/session/SessionStateWatcher.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/session/SessionStateWatcher.java @@ -91,8 +91,9 @@ public class SessionStateWatcher { ChildData node = fileCache.getCurrentData(); if (node != null) { newStatus = Status.parse(Utf8.toString(node.getData())); - log.log(Level.FINE, session.logPre() + "Session change: Session " - + session.getSessionId() + " changed status to " + newStatus.name()); + if (log.isLoggable(Level.FINE)) + log.log(Level.FINE, session.logPre() + "Session change: Session " + + session.getSessionId() + " changed status to " + newStatus.name()); sessionStatusChanged(newStatus); } } catch (Exception e) { diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/tenant/TenantRepository.java b/configserver/src/main/java/com/yahoo/vespa/config/server/tenant/TenantRepository.java index 52d1484897c..1c1d2534341 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/tenant/TenantRepository.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/tenant/TenantRepository.java @@ -318,7 +318,7 @@ public class TenantRepository { if (tenants.containsKey(tenantName)) return getTenant(tenantName); Instant start = Instant.now(); - log.log(Level.FINE, "Adding tenant '" + tenantName); + log.log(Level.FINE, () -> "Adding tenant '" + tenantName); TenantApplications applicationRepo = new TenantApplications(tenantName, curator, diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/zookeeper/InitializedCounter.java b/configserver/src/main/java/com/yahoo/vespa/config/server/zookeeper/InitializedCounter.java index 6a1eaba34a6..216c9edd0d0 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/zookeeper/InitializedCounter.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/zookeeper/InitializedCounter.java @@ -27,7 +27,7 @@ public class InitializedCounter { } private void initializeCounterValue(Long latestSessionId) { - log.log(Level.FINE, "path=" + sessionsDirPath + ", current=" + latestSessionId); + log.log(Level.FINE, () -> "path=" + sessionsDirPath + ", current=" + latestSessionId); if (latestSessionId != null) { counter.initialize(latestSessionId); } else { diff --git a/configserver/src/main/java/com/yahoo/vespa/config/server/zookeeper/ZKApplicationFile.java b/configserver/src/main/java/com/yahoo/vespa/config/server/zookeeper/ZKApplicationFile.java index e598a73ebfb..2a933ddf3e5 100644 --- a/configserver/src/main/java/com/yahoo/vespa/config/server/zookeeper/ZKApplicationFile.java +++ b/configserver/src/main/java/com/yahoo/vespa/config/server/zookeeper/ZKApplicationFile.java @@ -148,7 +148,7 @@ class ZKApplicationFile extends ApplicationFile { StringWriter writer = new StringWriter(); try { mapper.writeValue(writer, new MetaData(status, input == null ? "" : ConfigUtils.getMd5(input))); - log.log(Level.FINE, "Writing meta file to " + metaPath); + log.log(Level.FINE, () -> "Writing meta file to " + metaPath); zkApp.putData(metaPath, writer.toString()); } catch (IOException e) { throw new RuntimeException("Error writing meta file to " + metaPath, e); @@ -157,7 +157,7 @@ class ZKApplicationFile extends ApplicationFile { public MetaData getMetaData() { String metaPath = getZKPath(getMetaPath()); - log.log(Level.FINE, "Getting metadata for " + metaPath); + log.log(Level.FINE, () -> "Getting metadata for " + metaPath); if (!zkApp.exists(getZKPath(path))) { if (zkApp.exists(metaPath)) { return getMetaDataFromZk(metaPath); diff --git a/container-core/src/main/java/com/yahoo/container/core/config/HandlersConfigurerDi.java b/container-core/src/main/java/com/yahoo/container/core/config/HandlersConfigurerDi.java index 236602b7767..9f6f5cf7ea1 100644 --- a/container-core/src/main/java/com/yahoo/container/core/config/HandlersConfigurerDi.java +++ b/container-core/src/main/java/com/yahoo/container/core/config/HandlersConfigurerDi.java @@ -176,7 +176,7 @@ public class HandlersConfigurerDi { ComponentRegistry<RequestHandler> requestHandlerRegistry, ComponentRegistry<ClientProvider> clientProviderRegistry, ComponentRegistry<ServerProvider> serverProviderRegistry) { - log.log(Level.FINE, "RegistriesHack.init " + System.identityHashCode(this)); + log.log(Level.FINE, () -> "RegistriesHack.init " + System.identityHashCode(this)); vespaContainer.setComponentRegistry(allComponents); vespaContainer.setRequestHandlerRegistry(requestHandlerRegistry); diff --git a/container-core/src/main/java/com/yahoo/container/di/ConfigRetriever.java b/container-core/src/main/java/com/yahoo/container/di/ConfigRetriever.java index a7ff6c46a8b..33771bd0c1e 100644 --- a/container-core/src/main/java/com/yahoo/container/di/ConfigRetriever.java +++ b/container-core/src/main/java/com/yahoo/container/di/ConfigRetriever.java @@ -64,7 +64,7 @@ public final class ConfigRetriever { throw new IllegalArgumentException( "Component config keys [" + componentConfigKeys + "] overlaps with bootstrap config keys [" + bootstrapKeys + "]"); } - log.log(FINE, "getConfigsOnce: " + componentConfigKeys); + log.log(FINE, () -> "getConfigsOnce: " + componentConfigKeys); Set<ConfigKey<? extends ConfigInstance>> allKeys = new HashSet<>(componentConfigKeys); allKeys.addAll(bootstrapKeys); @@ -75,20 +75,20 @@ public final class ConfigRetriever { private Optional<ConfigSnapshot> getConfigsOptional(long leastGeneration, boolean isInitializing) { long newestComponentGeneration = componentSubscriber.waitNextGeneration(isInitializing); - log.log(FINE, "getConfigsOptional: new component generation: " + newestComponentGeneration); + log.log(FINE, () -> "getConfigsOptional: new component generation: " + newestComponentGeneration); // leastGeneration is only used to ensure newer generation when the previous generation was invalidated due to an exception if (newestComponentGeneration < leastGeneration) { return Optional.empty(); } else if (bootstrapSubscriber.generation() < newestComponentGeneration) { long newestBootstrapGeneration = bootstrapSubscriber.waitNextGeneration(isInitializing); - log.log(FINE, "getConfigsOptional: new bootstrap generation: " + bootstrapSubscriber.generation()); + log.log(FINE, () -> "getConfigsOptional: new bootstrap generation: " + bootstrapSubscriber.generation()); Optional<ConfigSnapshot> bootstrapConfig = bootstrapConfigIfChanged(); if (bootstrapConfig.isPresent()) { return bootstrapConfig; } else { if (newestBootstrapGeneration == newestComponentGeneration) { - log.log(FINE, "Got new components configs with unchanged bootstrap configs."); + log.log(FINE, () -> "Got new components configs with unchanged bootstrap configs."); return componentsConfigIfChanged(); } else { // This should not be a normal case, and hence a warning to allow investigation. @@ -131,7 +131,7 @@ public final class ConfigRetriever { componentSubscriber.close(); componentSubscriberKeys = keys; try { - log.log(FINE, "Setting up new component subscriber for keys: " + keys); + log.log(FINE, () -> "Setting up new component subscriber for keys: " + keys); componentSubscriber = subscribe.apply(keys); } catch (Throwable e) { log.log(Level.WARNING, "Failed setting up subscriptions for component configs: " + e.getMessage()); diff --git a/container-core/src/main/java/com/yahoo/container/di/Container.java b/container-core/src/main/java/com/yahoo/container/di/Container.java index 82c7f65bc2a..a91aa6eb588 100644 --- a/container-core/src/main/java/com/yahoo/container/di/Container.java +++ b/container-core/src/main/java/com/yahoo/container/di/Container.java @@ -95,8 +95,9 @@ public class Container { while (true) { snapshot = configurer.getConfigs(graph.configKeys(), leastGeneration, isInitializing); - log.log(FINE, String.format("createNewGraph:\n" + "graph.configKeys = %s\n" + "graph.generation = %s\n" + "snapshot = %s\n", - graph.configKeys(), graph.generation(), snapshot)); + if (log.isLoggable(FINE)) + log.log(FINE, String.format("createNewGraph:\n" + "graph.configKeys = %s\n" + "graph.generation = %s\n" + "snapshot = %s\n", + graph.configKeys(), graph.generation(), snapshot)); if (snapshot instanceof BootstrapConfigs) { if (getBootstrapGeneration() <= previousConfigGeneration) { @@ -104,7 +105,7 @@ public class Container { "Got bootstrap configs out of sequence for old config generation %d.\n" + "Previous config generation is %d", getBootstrapGeneration(), previousConfigGeneration)); } - log.log(FINE, "Got new bootstrap generation\n" + configGenerationsString()); + log.log(FINE, () -> "Got new bootstrap generation\n" + configGenerationsString()); if (graph.generation() == 0) { platformBundles = getConfig(platformBundlesConfigKey, snapshot.configs()).bundlePaths(); @@ -123,7 +124,7 @@ public class Container { break; } } - log.log(FINE, "Got components configs,\n" + configGenerationsString()); + log.log(FINE, () -> "Got components configs,\n" + configGenerationsString()); return createAndConfigureComponentsGraph(snapshot.configs(), fallbackInjector); } diff --git a/container-core/src/main/java/com/yahoo/container/di/componentgraph/cycle/CycleFinder.java b/container-core/src/main/java/com/yahoo/container/di/componentgraph/cycle/CycleFinder.java index 327949bb8d0..3aa8ae56817 100644 --- a/container-core/src/main/java/com/yahoo/container/di/componentgraph/cycle/CycleFinder.java +++ b/container-core/src/main/java/com/yahoo/container/di/componentgraph/cycle/CycleFinder.java @@ -58,7 +58,7 @@ public class CycleFinder<T> { if (visitDepthFirst(vertex, new ArrayList<>(singletonList(vertex)))) { if (cycle == null) throw new IllegalStateException("Null cycle - this should never happen"); if (cycle.isEmpty()) throw new IllegalStateException("Empty cycle - this should never happen"); - log.log(FINE, "Cycle detected: " + cycle); + log.log(FINE, () -> "Cycle detected: " + cycle); return cycle; } } @@ -68,7 +68,7 @@ public class CycleFinder<T> { private boolean visitDepthFirst(T vertex, List<T> path) { colors.put(vertex, GRAY); - log.log(FINE, "Vertex start " + vertex + " - colors: " + colors + " - path: " + path); + log.log(FINE, () -> "Vertex start " + vertex + " - colors: " + colors + " - path: " + path); for (T adjacent : graph.getAdjacent(vertex)) { path.add(adjacent); if (colors.get(adjacent) == GRAY) { @@ -81,7 +81,7 @@ public class CycleFinder<T> { path.remove(adjacent); } colors.put(vertex, BLACK); - log.log(FINE, "Vertex end " + vertex + " - colors: " + colors + " - path: " + path); + log.log(FINE, () -> "Vertex end " + vertex + " - colors: " + colors + " - path: " + path); return false; } diff --git a/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java b/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java index 65dc1052a78..ba9f1804d34 100644 --- a/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java +++ b/container-search/src/main/java/com/yahoo/search/handler/SearchHandler.java @@ -190,7 +190,7 @@ public class SearchHandler extends LoggingRequestHandler { long numQueriesToTraceOnDebugAfterStartup, Optional<String> hostResponseHeaderKey) { super(executor, metric, true); - log.log(Level.FINE, "SearchHandler.init " + System.identityHashCode(this)); + log.log(Level.FINE, () -> "SearchHandler.init " + System.identityHashCode(this)); this.queryProfileRegistry = queryProfileRegistry; this.executionFactory = executionFactory; diff --git a/container-search/src/main/java/com/yahoo/search/query/rewrite/RewriterUtils.java b/container-search/src/main/java/com/yahoo/search/query/rewrite/RewriterUtils.java index d66aff7bcd7..af73e905f20 100644 --- a/container-search/src/main/java/com/yahoo/search/query/rewrite/RewriterUtils.java +++ b/container-search/src/main/java/com/yahoo/search/query/rewrite/RewriterUtils.java @@ -289,7 +289,7 @@ public class RewriterUtils { * @param msg Log message */ public static void log(Logger logger, String msg) { - logger.log(Level.FINE, logger.getName() + ": " + msg); + logger.log(Level.FINE, () -> logger.getName() + ": " + msg); } /** @@ -303,7 +303,7 @@ public class RewriterUtils { if(query!=null) { query.trace(logger.getName() + ": " + msg, true, TRACELEVEL); } - logger.log(Level.FINE, logger.getName() + ": " + msg); + logger.log(Level.FINE, () -> logger.getName() + ": " + msg); } /** diff --git a/container-search/src/main/java/com/yahoo/vespa/streamingvisitors/VdsVisitor.java b/container-search/src/main/java/com/yahoo/vespa/streamingvisitors/VdsVisitor.java index ef0a60c76c0..7d7b78f7153 100644 --- a/container-search/src/main/java/com/yahoo/vespa/streamingvisitors/VdsVisitor.java +++ b/container-search/src/main/java/com/yahoo/vespa/streamingvisitors/VdsVisitor.java @@ -331,8 +331,8 @@ class VdsVisitor extends VisitorDataHandler implements Visitor { public void doSearch() throws InterruptedException, ParseException, TimeoutException { VisitorSession session = visitorSessionFactory.createVisitorSession(params); try { - if ( !session.waitUntilDone(query.getTimeout())) { - log.log(Level.FINE, "Visitor returned from waitUntilDone without being completed for " + query + " with selection " + params.getDocumentSelection()); + if ( ! session.waitUntilDone(query.getTimeout())) { + log.log(Level.FINE, () -> "Visitor returned from waitUntilDone without being completed for " + query + " with selection " + params.getDocumentSelection()); session.abort(); throw new TimeoutException("Query timed out in " + VdsStreamingSearcher.class.getName()); } diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/athenz/impl/AthenzFacade.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/athenz/impl/AthenzFacade.java index 3c035ef01ec..073451f6309 100644 --- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/athenz/impl/AthenzFacade.java +++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/athenz/impl/AthenzFacade.java @@ -270,7 +270,7 @@ public class AthenzFacade implements AccessControl { } public List<AthenzDomain> getDomainList(String prefix) { - log.log(Level.FINE, String.format("getDomainList(prefix=%s)", prefix)); + log.log(Level.FINE, "getDomainList(prefix=%s)", prefix); return zmsClient.getDomainList(prefix); } @@ -290,7 +290,7 @@ public class AthenzFacade implements AccessControl { } private static void log(String format, Object... args) { - log.log(Level.FINE, String.format(format, args)); + log.log(Level.FINE, format, args); } private String resourceStringPrefix(AthenzDomain tenantDomain) { diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/DeploymentTrigger.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/DeploymentTrigger.java index c602ebd856a..53e88a9a5ac 100644 --- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/DeploymentTrigger.java +++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/deployment/DeploymentTrigger.java @@ -162,7 +162,7 @@ public class DeploymentTrigger { /** Attempts to trigger the given job. */ public void trigger(Job job) { - log.log(Level.FINE, "Triggering " + job); + log.log(Level.FINE, () -> "Triggering " + job); applications().lockApplicationOrThrow(TenantAndApplicationId.from(job.applicationId()), application -> { jobs.start(job.applicationId(), job.jobType, job.versions); applications().store(application.with(job.applicationId().instance(), instance -> diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/dns/NameServiceForwarder.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/dns/NameServiceForwarder.java index 4f36e713ba4..d9928bffba4 100644 --- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/dns/NameServiceForwarder.java +++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/dns/NameServiceForwarder.java @@ -78,7 +78,7 @@ public class NameServiceForwarder { "requests. This likely means that the name service is not successfully " + "executing requests"); } - log.log(Level.FINE, "Queueing name service request: " + request); + log.log(Level.FINE, () -> "Queueing name service request: " + request); db.writeNameServiceQueue(queue.with(request, priority).last(maxQueuedRequests)); } } diff --git a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/maintenance/ContactInformationMaintainer.java b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/maintenance/ContactInformationMaintainer.java index d6733955967..7b846fa288c 100644 --- a/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/maintenance/ContactInformationMaintainer.java +++ b/controller-server/src/main/java/com/yahoo/vespa/hosted/controller/maintenance/ContactInformationMaintainer.java @@ -39,13 +39,13 @@ public class ContactInformationMaintainer extends ControllerMaintainer { TenantController tenants = controller().tenants(); boolean success = true; for (Tenant tenant : tenants.asList()) { - log.log(FINE, "Updating contact information for " + tenant); + log.log(FINE, () -> "Updating contact information for " + tenant); try { switch (tenant.type()) { case athenz: tenants.lockIfPresent(tenant.name(), LockedTenant.Athenz.class, lockedTenant -> { Contact contact = contactRetriever.getContact(lockedTenant.get().propertyId()); - log.log(FINE, "Contact found for " + tenant + " was " + + log.log(FINE, () -> "Contact found for " + tenant + " was " + (Optional.of(contact).equals(tenant.contact()) ? "un" : "") + "changed"); tenants.store(lockedTenant.with(contact)); }); diff --git a/docproc/src/main/java/com/yahoo/docproc/jdisc/DocumentProcessingHandler.java b/docproc/src/main/java/com/yahoo/docproc/jdisc/DocumentProcessingHandler.java index c9b3c4f9b4a..830d66d38f5 100644 --- a/docproc/src/main/java/com/yahoo/docproc/jdisc/DocumentProcessingHandler.java +++ b/docproc/src/main/java/com/yahoo/docproc/jdisc/DocumentProcessingHandler.java @@ -200,7 +200,7 @@ public class DocumentProcessingHandler extends AbstractRequestHandler { @Override public void run() { - log.log(Level.FINE, "Submitting after having waited " + delay + " ms in LATER queue: " + processingTask); + log.log(Level.FINE, () -> "Submitting after having waited " + delay + " ms in LATER queue: " + processingTask); processingTask.submit(); } } diff --git a/docproc/src/main/java/com/yahoo/docproc/jdisc/DocumentProcessingTask.java b/docproc/src/main/java/com/yahoo/docproc/jdisc/DocumentProcessingTask.java index 8b330c13dff..5d5f63d3958 100644 --- a/docproc/src/main/java/com/yahoo/docproc/jdisc/DocumentProcessingTask.java +++ b/docproc/src/main/java/com/yahoo/docproc/jdisc/DocumentProcessingTask.java @@ -112,8 +112,7 @@ public class DocumentProcessingTask implements Runnable { } else { location = "no processing instance"; } - String errorMsg = processing + " failed, " + location; - log.log(Level.FINE, "Time is up for '" + errorMsg + "'."); + log.log(Level.FINE, () -> "Time is up for '" + processing + " failed, " + location + "'."); requestContext.processingFailed(RequestContext.ErrorCode.ERROR_PROCESSING_FAILURE, "Time is up."); return progress; } @@ -203,7 +202,7 @@ public class DocumentProcessingTask implements Runnable { if (exception != null) { StringWriter backtrace = new StringWriter(); exception.printStackTrace(new PrintWriter(backtrace)); - log.log(Level.FINE, "Failed to process " + processing + ": " + backtrace.toString()); + log.log(Level.FINE, () -> "Failed to process " + processing + ": " + backtrace); } } diff --git a/docproc/src/main/java/com/yahoo/docproc/util/JoinerDocumentProcessor.java b/docproc/src/main/java/com/yahoo/docproc/util/JoinerDocumentProcessor.java index 406fc9a6db9..a91565dcd9c 100644 --- a/docproc/src/main/java/com/yahoo/docproc/util/JoinerDocumentProcessor.java +++ b/docproc/src/main/java/com/yahoo/docproc/util/JoinerDocumentProcessor.java @@ -59,7 +59,7 @@ public class JoinerDocumentProcessor extends DocumentProcessor { if (op instanceof DocumentPut) { innerDocuments.add(((DocumentPut)op).getDocument()); } else { - log.log(Level.FINE, "Skipping: " + op); + log.log(Level.FINE, () -> "Skipping: " + op); } } processing.getDocumentOperations().clear(); diff --git a/docproc/src/main/java/com/yahoo/docproc/util/SplitterDocumentProcessor.java b/docproc/src/main/java/com/yahoo/docproc/util/SplitterDocumentProcessor.java index dfc36bfb641..43e9c95fc1d 100644 --- a/docproc/src/main/java/com/yahoo/docproc/util/SplitterDocumentProcessor.java +++ b/docproc/src/main/java/com/yahoo/docproc/util/SplitterDocumentProcessor.java @@ -42,8 +42,8 @@ public class SplitterDocumentProcessor extends DocumentProcessor { public Progress process(Processing processing) { if (processing.getDocumentOperations().size() != 1) { //we were given more than one document, return - log.log(Level.FINE, "More than one document given, returning. (Was given " - + processing.getDocumentOperations().size() + " documents)."); + log.log(Level.FINE, () -> "More than one document given, returning. (Was given " + + processing.getDocumentOperations().size() + " documents)."); return Progress.DONE; } @@ -57,15 +57,15 @@ public class SplitterDocumentProcessor extends DocumentProcessor { Array<Document> innerDocuments = (Array<Document>) outerDoc.getFieldValue(arrayFieldName); if (innerDocuments == null) { //the document does not have the field, return - log.log(Level.FINE, "The given Document does not have a field value for field " - + arrayFieldName + ", returning. (Was given " + outerDoc + ")."); + log.log(Level.FINE, () -> "The given Document does not have a field value for field " + + arrayFieldName + ", returning. (Was given " + outerDoc + ")."); return Progress.DONE; } if (innerDocuments.size() == 0) { //the array is empty, return - log.log(Level.FINE, "The given Document does not have any elements in array field " - + arrayFieldName + ", returning. (Was given " + outerDoc + ")."); + log.log(Level.FINE, () -> "The given Document does not have any elements in array field " + + arrayFieldName + ", returning. (Was given " + outerDoc + ")."); return Progress.DONE; } diff --git a/docprocs/src/main/java/com/yahoo/docprocs/indexing/IndexingProcessor.java b/docprocs/src/main/java/com/yahoo/docprocs/indexing/IndexingProcessor.java index ec17e5e37e4..285f3e83602 100644 --- a/docprocs/src/main/java/com/yahoo/docprocs/indexing/IndexingProcessor.java +++ b/docprocs/src/main/java/com/yahoo/docprocs/indexing/IndexingProcessor.java @@ -96,7 +96,7 @@ public class IndexingProcessor extends DocumentProcessor { log.log(Level.FINE, "Processing document '%s'.", prev.getId()); Document next = script.execute(adapterFactory, prev.getDocument()); if (next == null) { - log.log(Level.FINE, "Document '" + prev.getId() + "' produced no output."); + log.log(Level.FINE, "Document '%s' produced no output.", prev.getId()); return; } @@ -113,7 +113,7 @@ public class IndexingProcessor extends DocumentProcessor { log.log(Level.FINE, "Processing update '%s'.", prev.getId()); DocumentUpdate next = script.execute(adapterFactory, prev); if (next == null) { - log.log(Level.FINE, "Update '" + prev.getId() + "' produced no output."); + log.log(Level.FINE, "Update '%s' produced no output.", prev.getId()); return; } next.setCondition(prev.getCondition()); diff --git a/documentapi/src/main/java/com/yahoo/documentapi/messagebus/MessageBusVisitorDestinationSession.java b/documentapi/src/main/java/com/yahoo/documentapi/messagebus/MessageBusVisitorDestinationSession.java index ae0a89664a5..521908d661c 100644 --- a/documentapi/src/main/java/com/yahoo/documentapi/messagebus/MessageBusVisitorDestinationSession.java +++ b/documentapi/src/main/java/com/yahoo/documentapi/messagebus/MessageBusVisitorDestinationSession.java @@ -56,7 +56,7 @@ public class MessageBusVisitorDestinationSession implements VisitorDestinationSe public void ack(AckToken token) { try { - log.log(Level.FINE, "Sending ack " + token.ackObject); + log.log(Level.FINE, () -> "Sending ack " + token.ackObject); session.reply((Reply) token.ackObject); } catch (Exception e) { e.printStackTrace(); diff --git a/documentapi/src/main/java/com/yahoo/documentapi/messagebus/MessageBusVisitorSession.java b/documentapi/src/main/java/com/yahoo/documentapi/messagebus/MessageBusVisitorSession.java index 88ef67e1854..248fcf7a624 100755 --- a/documentapi/src/main/java/com/yahoo/documentapi/messagebus/MessageBusVisitorSession.java +++ b/documentapi/src/main/java/com/yahoo/documentapi/messagebus/MessageBusVisitorSession.java @@ -405,7 +405,7 @@ public class MessageBusVisitorSession implements VisitorSession { synchronized (progress.getToken()) { this.startTimeNanos = clock.monotonicNanoTime(); if (progress.getIterator().isDone()) { - log.log(Level.FINE, sessionName + ": progress token indicates " + + log.log(Level.FINE, () -> sessionName + ": progress token indicates " + "session is done before it could even start; no-op"); return; } @@ -433,7 +433,7 @@ public class MessageBusVisitorSession implements VisitorSession { * successful, will be equal to newState. */ private StateDescription transitionTo(StateDescription newState) { - log.log(Level.FINE, sessionName + ": attempting transition to state " + newState); + log.log(Level.FINE, () -> sessionName + ": attempting transition to state " + newState); switch (newState.getState()) { case WORKING: assert(state.getState() == State.NOT_STARTED); @@ -450,7 +450,7 @@ public class MessageBusVisitorSession implements VisitorSession { default: com.yahoo.protect.Process.logAndDie("Invalid target transition state: " + newState); } - log.log(Level.FINE, "Session '" + sessionName + "' is now in state " + state); + log.log(Level.FINE, () -> "Session '" + sessionName + "' is now in state " + state); return state; } @@ -500,7 +500,7 @@ public class MessageBusVisitorSession implements VisitorSession { // If no cluster route has been set by user arguments, attempt to retrieve it from mbus config. if (params.getRoute() == null || !params.getRoute().hasHops()) { params.setRoute(getClusterRoute(routingTable)); - log.log(Level.FINE, "No route specified; resolved implicit " + + log.log(Level.FINE, () -> "No route specified; resolved implicit " + "storage cluster: " + params.getRoute().toString()); } } @@ -650,7 +650,7 @@ public class MessageBusVisitorSession implements VisitorSession { VisitorIterator.BucketProgress bucket = progress.getIterator().getNext(); Result result = sender.send(createMessage(bucket)); if (result.isAccepted()) { - log.log(Level.FINE, sessionName + ": sent CreateVisitor for bucket " + + log.log(Level.FINE, () -> sessionName + ": sent CreateVisitor for bucket " + bucket.getSuperbucket() + " with progress " + bucket.getProgress()); ++pendingMessageCount; } else { @@ -690,7 +690,7 @@ public class MessageBusVisitorSession implements VisitorSession { private void markSessionCompleted() { // 'done' is only ever written when token mutex is held, so safe to check // outside of completionMonitor lock. - log.log(Level.FINE, "Visitor session '" + sessionName + "' has completed"); + log.log(Level.FINE, () -> "Visitor session '" + sessionName + "' has completed"); if (params.getLocalDataHandler() != null) { params.getLocalDataHandler().onDone(); } @@ -904,7 +904,7 @@ public class MessageBusVisitorSession implements VisitorSession { progress.getIterator().update(bucket, subProgress); String message = getErrorMessage(reply.getError(0)); - log.log(Level.FINE, sessionName + ": received error reply for bucket " + + log.log(Level.FINE, () -> sessionName + ": received error reply for bucket " + bucket + " with message '" + message + "'"); if (isFatalError(reply)) { @@ -1029,7 +1029,7 @@ public class MessageBusVisitorSession implements VisitorSession { BucketId superbucket = msg.getBuckets().get(0); BucketId subBucketProgress = reply.getLastBucket(); - log.log(Level.FINE, sessionName + ": received CreateVisitorReply for bucket " + + log.log(Level.FINE, () -> sessionName + ": received CreateVisitorReply for bucket " + superbucket + " with progress " + subBucketProgress); progress.getIterator().update(superbucket, subBucketProgress); @@ -1051,7 +1051,7 @@ public class MessageBusVisitorSession implements VisitorSession { int newMaxBuckets = Math.max(Math.min((int)(params.getMaxBucketsPerVisitor() * params.getDynamicMaxBucketsIncreaseFactor()), 128), 1); params.setMaxBucketsPerVisitor(newMaxBuckets); - log.log(Level.FINE, sessionName + ": increasing max buckets per visitor to " + log.log(Level.FINE, () -> sessionName + ": increasing max buckets per visitor to " + params.getMaxBucketsPerVisitor()); } } @@ -1061,7 +1061,7 @@ public class MessageBusVisitorSession implements VisitorSession { ClusterState newState = new ClusterState(reply.getSystemState()); int stateBits = newState.getDistributionBitCount(); if (stateBits != progress.getIterator().getDistributionBitCount()) { - log.log(Level.FINE, "System state changed; now at " + + log.log(Level.FINE, () -> "System state changed; now at " + stateBits + " distribution bits"); // Update the internal state of the visitor iterator. If we're increasing // the number of distribution bits, this may lead to splitting of pending @@ -1150,7 +1150,7 @@ public class MessageBusVisitorSession implements VisitorSession { @Override public void destroy() { - log.log(Level.FINE, sessionName + ": synchronous destroy() called"); + log.log(Level.FINE, () -> sessionName + ": synchronous destroy() called"); try { synchronized (progress.getToken()) { synchronized (completionMonitor) { @@ -1178,7 +1178,7 @@ public class MessageBusVisitorSession implements VisitorSession { } catch (Exception e) { log.log(Level.SEVERE, "Caught exception destroying communication interfaces", e); } - log.log(Level.FINE, sessionName + ": synchronous destroy() done"); + log.log(Level.FINE, () -> sessionName + ": synchronous destroy() done"); } } } diff --git a/fileacquirer/src/main/java/com/yahoo/filedistribution/fileacquirer/FileAcquirerImpl.java b/fileacquirer/src/main/java/com/yahoo/filedistribution/fileacquirer/FileAcquirerImpl.java index 6f104ad6fc5..19aa1cc7e44 100644 --- a/fileacquirer/src/main/java/com/yahoo/filedistribution/fileacquirer/FileAcquirerImpl.java +++ b/fileacquirer/src/main/java/com/yahoo/filedistribution/fileacquirer/FileAcquirerImpl.java @@ -60,7 +60,7 @@ class FileAcquirerImpl implements FileAcquirer { logWarning(); target.close(); } else { - log.log(Level.FINE, "Successfully connected to '" + spec + "', this = " + System.identityHashCode(this)); + log.log(Level.FINE, () -> "Successfully connected to '" + spec + "', this = " + System.identityHashCode(this)); pauseTime = 0; logCount = 0; return; @@ -152,7 +152,7 @@ class FileAcquirerImpl implements FileAcquirer { request.parameters().add(new StringValue(fileReference.value())); double rpcTimeout = Math.min(timer.timeLeft(TimeUnit.SECONDS), 60.0); - log.log(Level.FINE, "InvokeSync waitFor " + fileReference + " with " + rpcTimeout + " seconds timeout"); + log.log(Level.FINE, () -> "InvokeSync waitFor " + fileReference + " with " + rpcTimeout + " seconds timeout"); target.invokeSync(request, rpcTimeout); if (request.checkReturnTypes("s")) { diff --git a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReceiver.java b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReceiver.java index 30c1d7cd673..1bc44e0bed2 100644 --- a/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReceiver.java +++ b/filedistribution/src/main/java/com/yahoo/vespa/filedistribution/FileReceiver.java @@ -195,7 +195,7 @@ public class FileReceiver { } catch (FileAlreadyExistsException e) { // Don't fail if it already exists (we might get the file from several config servers when retrying, servers are down etc. // so it might be written already). Delete temp file/dir in that case, to avoid filling the disk. - log.log(Level.FINE, "Failed moving file '" + tempFile.getAbsolutePath() + "' to '" + destination.getAbsolutePath() + + log.log(Level.FINE, () -> "Failed moving file '" + tempFile.getAbsolutePath() + "' to '" + destination.getAbsolutePath() + "', '" + destination.getAbsolutePath() + "' already exists"); deleteFileOrDirectory(tempFile); } catch (IOException e) { diff --git a/jrt/src/com/yahoo/jrt/slobrok/api/Register.java b/jrt/src/com/yahoo/jrt/slobrok/api/Register.java index 0da390f8bf6..b498e0b028c 100644 --- a/jrt/src/com/yahoo/jrt/slobrok/api/Register.java +++ b/jrt/src/com/yahoo/jrt/slobrok/api/Register.java @@ -213,7 +213,7 @@ public class Register { log.log(Level.WARNING, logMessagePrefix() + " failed: " + req.errorMessage()); } } else { - log.log(logOnSuccess ? Level.INFO : Level.FINE, logMessagePrefix() + " completed successfully"); + log.log(logOnSuccess ? Level.INFO : Level.FINE, () -> logMessagePrefix() + " completed successfully"); backOff.reset(); } req = null; diff --git a/logserver/src/main/java/com/yahoo/logserver/handlers/archive/ArchiverHandler.java b/logserver/src/main/java/com/yahoo/logserver/handlers/archive/ArchiverHandler.java index ee8c6e36cb8..021517f1cdc 100644 --- a/logserver/src/main/java/com/yahoo/logserver/handlers/archive/ArchiverHandler.java +++ b/logserver/src/main/java/com/yahoo/logserver/handlers/archive/ArchiverHandler.java @@ -211,12 +211,12 @@ public class ArchiverHandler extends AbstractLogHandler { // ensure that root dir exists if (root.isDirectory()) { - log.log(Level.FINE, "Using " + absoluteRootDir + " as root"); + log.log(Level.FINE, () -> "Using " + absoluteRootDir + " as root"); } else { if (! root.mkdirs()) { log.log(Level.SEVERE, "Unable to create directory " + absoluteRootDir); } else { - log.log(Level.FINE, "Created root at " + absoluteRootDir); + log.log(Level.FINE, () -> "Created root at " + absoluteRootDir); } } filesArchived = new FilesArchived(root); diff --git a/logserver/src/main/java/com/yahoo/logserver/handlers/archive/LogWriter.java b/logserver/src/main/java/com/yahoo/logserver/handlers/archive/LogWriter.java index e9d0ffc35b8..0d69131ff52 100644 --- a/logserver/src/main/java/com/yahoo/logserver/handlers/archive/LogWriter.java +++ b/logserver/src/main/java/com/yahoo/logserver/handlers/archive/LogWriter.java @@ -66,7 +66,7 @@ public class LogWriter { // if file does not exist we have a winner if (! f.exists()) { - log.log(Level.FINE, "nextWriter, new file: " + name); + log.log(Level.FINE, () -> "nextWriter, new file: " + name); currentFile = f; bytesWritten = 0; return new FileWriter(f, true); diff --git a/messagebus/src/main/java/com/yahoo/messagebus/SendProxy.java b/messagebus/src/main/java/com/yahoo/messagebus/SendProxy.java index d955a1a3d34..184d95dcd1d 100644 --- a/messagebus/src/main/java/com/yahoo/messagebus/SendProxy.java +++ b/messagebus/src/main/java/com/yahoo/messagebus/SendProxy.java @@ -58,11 +58,10 @@ public class SendProxy implements MessageHandler, ReplyHandler { } else { Trace trace = msg.getTrace(); if (logTrace) { - if (reply.hasErrors()) { - log.log(Level.FINE, "Trace for reply with error(s):\n" + reply.getTrace()); - } else if (log.isLoggable(Level.FINEST)) { - log.log(Level.FINEST, "Trace for reply:\n" + reply.getTrace()); - } + if (reply.hasErrors()) + log.log(Level.FINE, () -> "Trace for reply with error(s):\n" + reply.getTrace()); + else + log.log(Level.FINEST, () -> "Trace for reply:\n" + reply.getTrace()); Trace empty = new Trace(); trace.swap(empty); } else if (trace.getLevel() > 0) { diff --git a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/rpc/RpcConnector.java b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/rpc/RpcConnector.java index 6eb35b78f14..9d93b440a1d 100644 --- a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/rpc/RpcConnector.java +++ b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/rpc/RpcConnector.java @@ -31,7 +31,7 @@ public class RpcConnector extends AbstractComponent { Spec spec = new Spec(config.port()); try { acceptor = supervisor.listen(spec); - log.log(FINE, "Listening on " + spec.host() + ":" + acceptor.port()); + log.log(FINE, () -> "Listening on " + spec.host() + ":" + acceptor.port()); } catch (ListenFailedException e) { stop(); log.log(INFO, "Failed listening at " + spec.host() + ":" + spec.port()); diff --git a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/rpc/RpcServer.java b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/rpc/RpcServer.java index 79af500cde7..ee3cddf3fcb 100644 --- a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/rpc/RpcServer.java +++ b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/rpc/RpcServer.java @@ -146,7 +146,7 @@ public class RpcServer { void setExtraMetrics(Request req) { String metricsJson = req.parameters().get(0).asString(); - log.log(FINE, "setExtraMetrics called with argument: " + metricsJson); + log.log(FINE, () -> "setExtraMetrics called with argument: " + metricsJson); withExceptionHandling(req, () -> metricsManager.setExtraMetrics(toMetricsPackets(metricsJson))); } diff --git a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/ConfigSentinelClient.java b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/ConfigSentinelClient.java index a017b968e08..ab05e778ea6 100644 --- a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/ConfigSentinelClient.java +++ b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/ConfigSentinelClient.java @@ -59,7 +59,7 @@ public class ConfigSentinelClient extends AbstractComponent { synchronized void ping(VespaService s) { List<VespaService> services = new ArrayList<>(); services.add(s); - log.log(Level.FINE, "Ping for service " + s); + log.log(Level.FINE, () -> "Ping for service " + s); try { setStatus(services); } catch (Exception e) { @@ -93,7 +93,7 @@ public class ConfigSentinelClient extends AbstractComponent { //from the sentinel for (VespaService s : services) { if ((!s.getServiceName().equals("configserver")) && !updatedServices.contains(s)) { - log.log(Level.FINE,"Service " + s + " is no longer found with sentinel - setting alive = false"); + log.log(Level.FINE, () -> "Service " + s + " is no longer found with sentinel - setting alive = false"); s.setAlive(false); } } diff --git a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/HttpMetricFetcher.java b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/HttpMetricFetcher.java index 333d8696413..b4c116d1903 100644 --- a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/HttpMetricFetcher.java +++ b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/HttpMetricFetcher.java @@ -51,11 +51,11 @@ public abstract class HttpMetricFetcher { String u = "http://localhost:" + port + path; this.url = URI.create(u); - log.log(Level.FINE, "Fetching metrics from " + u + " with timeout " + CONNECTION_TIMEOUT); + log.log(Level.FINE, () -> "Fetching metrics from " + u + " with timeout " + CONNECTION_TIMEOUT); } InputStream getJson() throws IOException,InterruptedException, ExecutionException { - log.log(Level.FINE, "Connecting to url " + url + " for service '" + service + "'"); + log.log(Level.FINE, () -> "Connecting to url " + url + " for service '" + service + "'"); Future<Message<HttpResponse, InputStream>> response = httpClient.execute( new BasicRequestProducer(Method.GET, url), new BasicResponseConsumer<>(new AbstractClassicEntityConsumer<>(BUFFER_SIZE, Runnable::run) { diff --git a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/RemoteHealthMetricFetcher.java b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/RemoteHealthMetricFetcher.java index 2ebf5b2532c..09087c32914 100644 --- a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/RemoteHealthMetricFetcher.java +++ b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/RemoteHealthMetricFetcher.java @@ -66,7 +66,7 @@ public class RemoteHealthMetricFetcher extends HttpMetricFetcher { return HealthMetric.get(code, message); } catch (IOException e) { - log.log(Level.FINE, "Failed to parse json response from metrics page:" + e + ":" + data); + log.log(Level.FINE, () -> "Failed to parse json response from metrics page:" + e + ":" + data); return HealthMetric.getUnknown("Not able to parse json from status page"); } } diff --git a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/SystemPoller.java b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/SystemPoller.java index 05e65449163..5d119fc30e6 100644 --- a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/SystemPoller.java +++ b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/SystemPoller.java @@ -99,7 +99,7 @@ public class SystemPoller { return; } - log.log(Level.FINE, "Monitoring system metrics for " + services.size() + " services"); + log.log(Level.FINE, () -> "Monitoring system metrics for " + services.size() + " services"); long sysJiffies = getNormalizedSystemJiffies(); for (VespaService s : services) { @@ -110,10 +110,10 @@ public class SystemPoller { } Metrics metrics = new Metrics(); - log.log(Level.FINE, "Current size of system metrics for service " + s + " is " + metrics.size()); + log.log(Level.FINE, () -> "Current size of system metrics for service " + s + " is " + metrics.size()); long[] size = getMemoryUsage(s); - log.log(Level.FINE, "Updating memory metric for service " + s); + log.log(Level.FINE, () -> "Updating memory metric for service " + s); metrics.add(new Metric("memory_virt", size[memoryTypeVirtual], startTime / 1000)); metrics.add(new Metric("memory_rss", size[memoryTypeResident], startTime / 1000)); @@ -150,7 +150,7 @@ public class SystemPoller { try { in = new BufferedReader(new FileReader("/proc/" + pid + "/stat")); } catch (FileNotFoundException ex) { - log.log(Level.FINE, "Unable to find pid " + pid + " in proc directory, for service " + service.getInstanceName()); + log.log(Level.FINE, () -> "Unable to find pid " + pid + " in proc directory, for service " + service.getInstanceName()); service.setAlive(false); return 0; } diff --git a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/VespaServices.java b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/VespaServices.java index 71f8a5f2b21..b0ea7e709a1 100644 --- a/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/VespaServices.java +++ b/metrics-proxy/src/main/java/ai/vespa/metricsproxy/service/VespaServices.java @@ -48,12 +48,12 @@ public class VespaServices { private List<VespaService> createServices(VespaServicesConfig servicesConfig, String monitoringSystemName) { List<VespaService> services = new ArrayList<>(); for (Service s : servicesConfig.service()) { - log.log(FINE, "Creating service " + s.name()); + log.log(FINE, () -> "Creating service " + s.name()); VespaService vespaService = VespaService.create(s.name(), s.configId(), s.port(), monitoringSystemName, createServiceDimensions(s)); services.add(vespaService); } - log.log(FINE, "Created new services: " + services.size()); + log.log(FINE, () -> "Created new services: " + services.size()); return services; } diff --git a/node-repository/src/main/java/com/yahoo/vespa/hosted/provision/provisioning/InfraDeployerImpl.java b/node-repository/src/main/java/com/yahoo/vespa/hosted/provision/provisioning/InfraDeployerImpl.java index 1b98514e3a8..738a7e5ad4a 100644 --- a/node-repository/src/main/java/com/yahoo/vespa/hosted/provision/provisioning/InfraDeployerImpl.java +++ b/node-repository/src/main/java/com/yahoo/vespa/hosted/provision/provisioning/InfraDeployerImpl.java @@ -107,7 +107,7 @@ public class InfraDeployerImpl implements InfraDeployer { prepare(); if (hostSpecs.isEmpty()) { - logger.log(Level.FINE, "No nodes to provision for " + application.getCapacity().type() + ", removing application"); + logger.log(Level.FINE, () -> "No nodes to provision for " + application.getCapacity().type() + ", removing application"); removeApplication(application.getApplicationId()); } else { NestedTransaction nestedTransaction = new NestedTransaction(); diff --git a/node-repository/src/main/java/com/yahoo/vespa/hosted/provision/provisioning/LoadBalancerProvisioner.java b/node-repository/src/main/java/com/yahoo/vespa/hosted/provision/provisioning/LoadBalancerProvisioner.java index f53eb189ec1..e665ace6334 100644 --- a/node-repository/src/main/java/com/yahoo/vespa/hosted/provision/provisioning/LoadBalancerProvisioner.java +++ b/node-repository/src/main/java/com/yahoo/vespa/hosted/provision/provisioning/LoadBalancerProvisioner.java @@ -182,7 +182,7 @@ public class LoadBalancerProvisioner { : loadBalancer.get().state(); newLoadBalancer = loadBalancer.get().with(instance).with(state, now); if (loadBalancer.get().state() != newLoadBalancer.state()) { - log.log(Level.FINE, "Moving " + newLoadBalancer.id() + " to state " + newLoadBalancer.state()); + log.log(Level.FINE, () -> "Moving " + newLoadBalancer.id() + " to state " + newLoadBalancer.state()); } } @@ -209,7 +209,7 @@ public class LoadBalancerProvisioner { private Optional<LoadBalancerInstance> provisionInstance(LoadBalancerId id, Set<Real> reals, Optional<LoadBalancer> currentLoadBalancer) { if (hasReals(currentLoadBalancer, reals)) return currentLoadBalancer.get().instance(); - log.log(Level.FINE, "Creating " + id + ", targeting: " + reals); + log.log(Level.FINE, () -> "Creating " + id + ", targeting: " + reals); try { return Optional.of(service.create(new LoadBalancerSpec(id.application(), id.cluster(), reals), allowEmptyReals(currentLoadBalancer))); diff --git a/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/resources/HostRequestHandler.java b/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/resources/HostRequestHandler.java index 7b28925205f..4b8b295964a 100644 --- a/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/resources/HostRequestHandler.java +++ b/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/resources/HostRequestHandler.java @@ -90,10 +90,10 @@ public class HostRequestHandler extends RestApiRequestHandler<HostRequestHandler applicationUri.toString(), hostServices); } catch (UncheckedTimeoutException e) { - log.log(Level.FINE, "Failed to get host " + hostName + ": " + e.getMessage()); + log.log(Level.FINE, () -> "Failed to get host " + hostName + ": " + e.getMessage()); throw restApiExceptionFromTimeout("getHost", hostName, e); } catch (HostNameNotFoundException e) { - log.log(Level.FINE, "Host not found: " + hostName); + log.log(Level.FINE, () -> "Host not found: " + hostName); throw new RestApiException.NotFound(e); } } @@ -116,10 +116,10 @@ public class HostRequestHandler extends RestApiRequestHandler<HostRequestHandler try { orchestrator.setNodeStatus(hostName, state); } catch (HostNameNotFoundException e) { - log.log(Level.FINE, "Host not found: " + hostName); + log.log(Level.FINE, () -> "Host not found: " + hostName); throw new RestApiException.NotFound(e); } catch (UncheckedTimeoutException e) { - log.log(Level.FINE, "Failed to patch " + hostName + ": " + e.getMessage()); + log.log(Level.FINE, () -> "Failed to patch " + hostName + ": " + e.getMessage()); throw restApiExceptionFromTimeout("patch", hostName, e); } catch (OrchestrationException e) { String message = "Failed to set " + hostName + " to " + state + ": " + e.getMessage(); @@ -150,13 +150,13 @@ public class HostRequestHandler extends RestApiRequestHandler<HostRequestHandler try { orchestrator.suspend(hostName); } catch (HostNameNotFoundException e) { - log.log(Level.FINE, "Host not found: " + hostName); + log.log(Level.FINE, () -> "Host not found: " + hostName); throw new RestApiException.NotFound(e); } catch (UncheckedTimeoutException e) { - log.log(Level.FINE, "Failed to suspend " + hostName + ": " + e.getMessage()); + log.log(Level.FINE, () -> "Failed to suspend " + hostName + ": " + e.getMessage()); throw restApiExceptionFromTimeout("suspend", hostName, e); } catch (HostStateChangeDeniedException e) { - log.log(Level.FINE, "Failed to suspend " + hostName + ": " + e.getMessage()); + log.log(Level.FINE, () -> "Failed to suspend " + hostName + ": " + e.getMessage()); throw restApiExceptionWithDenialReason("suspend", hostName, e); } return new UpdateHostResponse(hostName.s(), null); @@ -173,13 +173,13 @@ public class HostRequestHandler extends RestApiRequestHandler<HostRequestHandler try { orchestrator.resume(hostName); } catch (HostNameNotFoundException e) { - log.log(Level.FINE, "Host not found: " + hostName); + log.log(Level.FINE, () -> "Host not found: " + hostName); throw new RestApiException.NotFound(e); } catch (UncheckedTimeoutException e) { - log.log(Level.FINE, "Failed to resume " + hostName + ": " + e.getMessage()); + log.log(Level.FINE, () -> "Failed to resume " + hostName + ": " + e.getMessage()); throw restApiExceptionFromTimeout("resume", hostName, e); } catch (HostStateChangeDeniedException e) { - log.log(Level.FINE, "Failed to resume " + hostName + ": " + e.getMessage()); + log.log(Level.FINE, () -> "Failed to resume " + hostName + ": " + e.getMessage()); throw restApiExceptionWithDenialReason("resume", hostName, e); } return new UpdateHostResponse(hostName.s(), null); diff --git a/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/resources/HostSuspensionRequestHandler.java b/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/resources/HostSuspensionRequestHandler.java index 73859f385e1..d2fdf70df19 100644 --- a/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/resources/HostSuspensionRequestHandler.java +++ b/orchestrator/src/main/java/com/yahoo/vespa/orchestrator/resources/HostSuspensionRequestHandler.java @@ -54,21 +54,21 @@ public class HostSuspensionRequestHandler extends RestApiRequestHandler<HostSusp try { orchestrator.suspendAll(parentHostname, hostnames); } catch (BatchHostStateChangeDeniedException e) { - log.log(Level.FINE, "Failed to suspend nodes " + hostnames + " with parent host " + parentHostname, e); + log.log(Level.FINE, e, () -> "Failed to suspend nodes " + hostnames + " with parent host " + parentHostname); throw createRestApiException(e.getMessage(), Response.Status.CONFLICT, e); } catch (UncheckedTimeoutException e) { - log.log(Level.FINE, "Failed to suspend nodes " + hostnames + " with parent host " + parentHostname, e); + log.log(Level.FINE, e, () -> "Failed to suspend nodes " + hostnames + " with parent host " + parentHostname); throw createRestApiException(e.getMessage(), Response.Status.CONFLICT, e); } catch (BatchHostNameNotFoundException e) { - log.log(Level.FINE, "Failed to suspend nodes " + hostnames + " with parent host " + parentHostname, e); + log.log(Level.FINE, e, () -> "Failed to suspend nodes " + hostnames + " with parent host " + parentHostname); // Note that we're returning BAD_REQUEST instead of NOT_FOUND because the resource identified // by the URL path was found. It's one of the hostnames in the request it failed to find. throw createRestApiException(e.getMessage(), Response.Status.BAD_REQUEST, e); } catch (BatchInternalErrorException e) { - log.log(Level.FINE, "Failed to suspend nodes " + hostnames + " with parent host " + parentHostname, e); + log.log(Level.FINE, e, () -> "Failed to suspend nodes " + hostnames + " with parent host " + parentHostname); throw createRestApiException(e.getMessage(), Response.Status.INTERNAL_SERVER_ERROR, e); } - log.log(Level.FINE, "Suspended " + hostnames + " with parent " + parentHostname); + log.log(Level.FINE, () -> "Suspended " + hostnames + " with parent " + parentHostname); return BatchOperationResult.successResult(); } diff --git a/service-monitor/src/main/java/com/yahoo/vespa/service/duper/DuperModel.java b/service-monitor/src/main/java/com/yahoo/vespa/service/duper/DuperModel.java index c9df077aeef..d4cb1e6a480 100644 --- a/service-monitor/src/main/java/com/yahoo/vespa/service/duper/DuperModel.java +++ b/service-monitor/src/main/java/com/yahoo/vespa/service/duper/DuperModel.java @@ -95,7 +95,7 @@ public class DuperModel { } else { logPrefix = isComplete ? "Reactivated application " : "Rebootstrapped application "; } - logger.log(Level.FINE, logPrefix + id.toFullString()); + logger.log(Level.FINE, () -> logPrefix + id.toFullString()); updateHostnameVsIdMaps(applicationInfo, id); @@ -110,7 +110,7 @@ public class DuperModel { ApplicationInfo application = applicationsById.remove(applicationId); if (application != null) { - logger.log(Level.FINE, "Removed application " + applicationId.toFullString()); + logger.log(Level.FINE, () -> "Removed application " + applicationId.toFullString()); listeners.forEach(listener -> listener.applicationRemoved(applicationId)); } } diff --git a/service-monitor/src/main/java/com/yahoo/vespa/service/slobrok/SlobrokMonitorManagerImpl.java b/service-monitor/src/main/java/com/yahoo/vespa/service/slobrok/SlobrokMonitorManagerImpl.java index b2696f8573f..2cc3359d449 100644 --- a/service-monitor/src/main/java/com/yahoo/vespa/service/slobrok/SlobrokMonitorManagerImpl.java +++ b/service-monitor/src/main/java/com/yahoo/vespa/service/slobrok/SlobrokMonitorManagerImpl.java @@ -145,7 +145,7 @@ public class SlobrokMonitorManagerImpl implements SlobrokApi, MonitorManager { case "storagenode": return Optional.of("storage/cluster." + configId.s()); default: - logger.log(Level.FINE, "Unknown service type " + serviceType.s() + + logger.log(Level.FINE, () -> "Unknown service type " + serviceType.s() + " with config id " + configId.s()); return Optional.empty(); } diff --git a/vespaclient-core/src/main/java/com/yahoo/feedapi/SharedSender.java b/vespaclient-core/src/main/java/com/yahoo/feedapi/SharedSender.java index d2e0434f273..997b575612e 100755 --- a/vespaclient-core/src/main/java/com/yahoo/feedapi/SharedSender.java +++ b/vespaclient-core/src/main/java/com/yahoo/feedapi/SharedSender.java @@ -124,18 +124,16 @@ public class SharedSender implements ReplyHandler { synchronized (metrics) { metrics.addReply(r); } - if (log.isLoggable(Level.FINEST)) { - log.log(Level.FINEST, "Received reply for file " + owner.toString() + " count was " + owner.getPending().val()); - } + log.log(Level.FINEST, () -> "Received reply for file " + owner.toString() + " count was " + owner.getPending().val()); if (owner.isAborted()) { - log.log(Level.FINE, "Received reply for file " + owner.toString() + " which is aborted"); + log.log(Level.FINE, () -> "Received reply for file " + owner.toString() + " which is aborted"); owner.getPending().clear(); return; } if (owner.handleReply(r)) { owner.getPending().dec(); } else { - log.log(Level.FINE, "Received reply for file " + owner.toString() + " which wants to abort"); + log.log(Level.FINE, () -> "Received reply for file " + owner.toString() + " which wants to abort"); owner.getPending().clear(); } } else { diff --git a/zkfacade/src/main/java/com/yahoo/vespa/curator/CuratorCompletionWaiter.java b/zkfacade/src/main/java/com/yahoo/vespa/curator/CuratorCompletionWaiter.java index 3789e30509c..af269fc2ad5 100644 --- a/zkfacade/src/main/java/com/yahoo/vespa/curator/CuratorCompletionWaiter.java +++ b/zkfacade/src/main/java/com/yahoo/vespa/curator/CuratorCompletionWaiter.java @@ -1,6 +1,7 @@ // Copyright Verizon Media. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.vespa.curator; +import java.util.ArrayList; import java.util.logging.Level; import com.yahoo.path.Path; @@ -36,9 +37,9 @@ class CuratorCompletionWaiter implements Curator.CompletionWaiter { public void awaitCompletion(Duration timeout) { List<String> respondents; try { - log.log(Level.FINE, "Synchronizing on barrier " + barrierPath); + log.log(Level.FINE, () -> "Synchronizing on barrier " + barrierPath); respondents = awaitInternal(timeout); - log.log(Level.FINE, "Done synchronizing on barrier " + barrierPath); + log.log(Level.FINE, () -> "Done synchronizing on barrier " + barrierPath); } catch (Exception e) { throw new RuntimeException(e); } @@ -54,9 +55,10 @@ class CuratorCompletionWaiter implements Curator.CompletionWaiter { private List<String> awaitInternal(Duration timeout) throws Exception { Instant startTime = clock.instant(); Instant endTime = startTime.plus(timeout); - List<String> respondents; + List<String> respondents = new ArrayList<>(); do { - respondents = curator.framework().getChildren().forPath(barrierPath); + respondents.clear(); + respondents.addAll(curator.framework().getChildren().forPath(barrierPath)); if (log.isLoggable(Level.FINE)) { log.log(Level.FINE, respondents.size() + "/" + curator.zooKeeperEnsembleCount() + " responded: " + respondents + ", all participants: " + curator.zooKeeperEnsembleConnectionSpec()); @@ -64,12 +66,12 @@ class CuratorCompletionWaiter implements Curator.CompletionWaiter { // First, check if all config servers responded if (respondents.size() == curator.zooKeeperEnsembleCount()) { - log.log(Level.FINE, barrierCompletedMessage(respondents, startTime)); + log.log(Level.FINE, () -> barrierCompletedMessage(respondents, startTime)); break; } // If some are missing, quorum is enough if (respondents.size() >= barrierMemberCount()) { - log.log(Level.FINE, barrierCompletedMessage(respondents, startTime)); + log.log(Level.FINE, () -> barrierCompletedMessage(respondents, startTime)); break; } |