From commits-return-7901-archive-asf-public=cust-asf.ponee.io@zookeeper.apache.org Sat Aug 3 06:42:50 2019 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [207.244.88.153]) by mx-eu-01.ponee.io (Postfix) with SMTP id 183F41802C7 for ; Sat, 3 Aug 2019 08:42:50 +0200 (CEST) Received: (qmail 67052 invoked by uid 500); 3 Aug 2019 06:42:49 -0000 Mailing-List: contact commits-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@zookeeper.apache.org Delivered-To: mailing list commits@zookeeper.apache.org Received: (qmail 67041 invoked by uid 99); 3 Aug 2019 06:42:49 -0000 Received: from ec2-52-202-80-70.compute-1.amazonaws.com (HELO gitbox.apache.org) (52.202.80.70) by apache.org (qpsmtpd/0.29) with ESMTP; Sat, 03 Aug 2019 06:42:49 +0000 Received: by gitbox.apache.org (ASF Mail Server at gitbox.apache.org, from userid 33) id F3FB385ED3; Sat, 3 Aug 2019 06:42:48 +0000 (UTC) Date: Sat, 03 Aug 2019 06:42:48 +0000 To: "commits@zookeeper.apache.org" Subject: [zookeeper] branch master updated: ZOOKEEPER-3339: Improve Debug and Trace Log Statements MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 8bit Message-ID: <156481456854.2828.2658371207174104414@gitbox.apache.org> From: fangmin@apache.org X-Git-Host: gitbox.apache.org X-Git-Repo: zookeeper X-Git-Refname: refs/heads/master X-Git-Reftype: branch X-Git-Oldrev: 3882a0171f91280bf1adbbd4ffaeb17cb5131316 X-Git-Newrev: d84b7a682eb4601005db9fac886079b1a9a4d4b0 X-Git-Rev: d84b7a682eb4601005db9fac886079b1a9a4d4b0 X-Git-NotificationType: ref_changed_plus_diff X-Git-Multimail-Version: 1.5.dev Auto-Submitted: auto-generated This is an automated email from the ASF dual-hosted git repository. fangmin pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/zookeeper.git The following commit(s) were added to refs/heads/master by this push: new d84b7a6 ZOOKEEPER-3339: Improve Debug and Trace Log Statements d84b7a6 is described below commit d84b7a682eb4601005db9fac886079b1a9a4d4b0 Author: Beluga Behr AuthorDate: Fri Aug 2 23:42:39 2019 -0700 ZOOKEEPER-3339: Improve Debug and Trace Log Statements Author: Beluga Behr Reviewers: andor@apache.org, nkalmar@apache.org, maoling@apache.org, fangmin@apache.org Closes #878 from belugabehr/ZOOKEEPER-3339 --- .../zookeeper/recipes/lock/ProtocolSupport.java | 6 +-- .../apache/zookeeper/recipes/lock/WriteLock.java | 15 ++----- .../zookeeper/recipes/queue/DistributedQueue.java | 3 +- .../main/java/org/apache/zookeeper/ClientCnxn.java | 6 +-- .../org/apache/zookeeper/ClientCnxnSocketNIO.java | 29 +++--------- .../src/main/java/org/apache/zookeeper/Login.java | 4 +- .../org/apache/zookeeper/SaslServerPrincipal.java | 4 +- .../src/main/java/org/apache/zookeeper/ZKUtil.java | 6 +-- .../main/java/org/apache/zookeeper/ZooKeeper.java | 8 +--- .../java/org/apache/zookeeper/ZooKeeperMain.java | 2 +- .../zookeeper/client/ZooKeeperSaslClient.java | 28 ++++++------ .../apache/zookeeper/common/FileChangeWatcher.java | 15 +++---- .../org/apache/zookeeper/common/NettyUtils.java | 6 +-- .../java/org/apache/zookeeper/server/DataTree.java | 16 +++---- .../zookeeper/server/FinalRequestProcessor.java | 9 ++-- .../org/apache/zookeeper/server/NIOServerCnxn.java | 51 +++++++++------------- .../zookeeper/server/NIOServerCnxnFactory.java | 9 ++-- .../apache/zookeeper/server/NettyServerCnxn.java | 24 ++++------ .../zookeeper/server/NettyServerCnxnFactory.java | 40 ++++++----------- .../zookeeper/server/SessionTrackerImpl.java | 12 +++-- .../apache/zookeeper/server/ZooKeeperServer.java | 48 ++++++++++---------- .../server/auth/KeyAuthenticationProvider.java | 4 +- .../server/auth/SaslServerCallbackHandler.java | 2 +- .../zookeeper/server/persistence/FileTxnLog.java | 6 +-- .../zookeeper/server/quorum/CommitProcessor.java | 8 +--- .../server/quorum/FastLeaderElection.java | 21 ++++----- .../org/apache/zookeeper/server/quorum/Leader.java | 14 ++---- .../zookeeper/server/quorum/LearnerHandler.java | 31 +++++++------ .../zookeeper/server/quorum/QuorumCnxManager.java | 30 ++++++------- .../apache/zookeeper/server/quorum/QuorumPeer.java | 7 +-- .../server/quorum/auth/SaslQuorumAuthLearner.java | 4 +- .../server/quorum/flexible/QuorumHierarchical.java | 10 ++--- .../org/apache/zookeeper/util/SecurityUtils.java | 9 ++-- 33 files changed, 207 insertions(+), 280 deletions(-) diff --git a/zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/ProtocolSupport.java b/zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/ProtocolSupport.java index 4efdb85..a4cd989 100644 --- a/zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/ProtocolSupport.java +++ b/zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/ProtocolSupport.java @@ -126,8 +126,8 @@ class ProtocolSupport { if (exception == null) { exception = e; } - LOG.debug("Attempt " + i + " failed with connection loss so " + - "attempting to reconnect: " + e, e); + LOG.debug("Attempt {} failed with connection loss so " + + "attempting to reconnect", i, e); retryDelay(i); } } @@ -186,7 +186,7 @@ class ProtocolSupport { try { Thread.sleep(attemptCount * retryDelay); } catch (InterruptedException e) { - LOG.debug("Failed to sleep: " + e, e); + LOG.debug("Failed to sleep", e); } } } diff --git a/zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/WriteLock.java b/zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/WriteLock.java index 09587ed..693d1e8 100644 --- a/zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/WriteLock.java +++ b/zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/WriteLock.java @@ -151,8 +151,7 @@ public class WriteLock extends ProtocolSupport { private class LockWatcher implements Watcher { public void process(WatchedEvent event) { // lets either become the leader or watch the new/updated node - LOG.debug("Watcher fired on path: " + event.getPath() + " state: " + - event.getState() + " type " + event.getType()); + LOG.debug("Watcher fired: {}", event); try { lock(); } catch (Exception e) { @@ -181,9 +180,7 @@ public class WriteLock extends ProtocolSupport { for (String name : names) { if (name.startsWith(prefix)) { id = name; - if (LOG.isDebugEnabled()) { - LOG.debug("Found id created last time: " + id); - } + LOG.debug("Found id created last time: {}", id); break; } } @@ -191,9 +188,7 @@ public class WriteLock extends ProtocolSupport { id = zookeeper.create(dir + "/" + prefix, data, getAcl(), EPHEMERAL_SEQUENTIAL); - if (LOG.isDebugEnabled()) { - LOG.debug("Created id: " + id); - } + LOG.debug("Created id: {}", id); } } @@ -232,9 +227,7 @@ public class WriteLock extends ProtocolSupport { if (!lessThanMe.isEmpty()) { ZNodeName lastChildName = lessThanMe.last(); lastChildId = lastChildName.getName(); - if (LOG.isDebugEnabled()) { - LOG.debug("watching less than me node: " + lastChildId); - } + LOG.debug("watching less than me node: {}", lastChildId); Stat stat = zookeeper.exists(lastChildId, new LockWatcher()); if (stat != null) { return Boolean.FALSE; diff --git a/zookeeper-recipes/zookeeper-recipes-queue/src/main/java/org/apache/zookeeper/recipes/queue/DistributedQueue.java b/zookeeper-recipes/zookeeper-recipes-queue/src/main/java/org/apache/zookeeper/recipes/queue/DistributedQueue.java index ca01541..ae11cc8 100644 --- a/zookeeper-recipes/zookeeper-recipes-queue/src/main/java/org/apache/zookeeper/recipes/queue/DistributedQueue.java +++ b/zookeeper-recipes/zookeeper-recipes-queue/src/main/java/org/apache/zookeeper/recipes/queue/DistributedQueue.java @@ -218,8 +218,7 @@ public class DistributedQueue { } public void process(WatchedEvent event){ - LOG.debug("Watcher fired on path: " + event.getPath() + " state: " + - event.getState() + " type " + event.getType()); + LOG.debug("Watcher fired: {}", event); latch.countDown(); } public void await() throws InterruptedException { diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxn.java b/zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxn.java index 4125f24..5148dab 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxn.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxn.java @@ -1050,10 +1050,8 @@ public class ClientCnxn { outgoingQueue.addFirst(new Packet(null, null, conReq, null, null, readOnly)); clientCnxnSocket.connectionPrimed(); - if (LOG.isDebugEnabled()) { - LOG.debug("Session establishment request sent on " - + clientCnxnSocket.getRemoteSocketAddress()); - } + LOG.debug("Session establishment request sent on {}", + clientCnxnSocket.getRemoteSocketAddress()); } private List prependChroot(List paths) { diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxnSocketNIO.java b/zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxnSocketNIO.java index bda31ba..0ce64ab 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxnSocketNIO.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxnSocketNIO.java @@ -196,39 +196,28 @@ public class ClientCnxnSocketNIO extends ClientCnxnSocket { try { sock.socket().shutdownInput(); } catch (IOException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("Ignoring exception during shutdown input", e); - } + LOG.debug("Ignoring exception during shutdown input", e); } try { sock.socket().shutdownOutput(); } catch (IOException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("Ignoring exception during shutdown output", - e); - } + LOG.debug("Ignoring exception during shutdown output", e); } try { sock.socket().close(); } catch (IOException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("Ignoring exception during socket close", e); - } + LOG.debug("Ignoring exception during socket close", e); } try { sock.close(); } catch (IOException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("Ignoring exception during channel close", e); - } + LOG.debug("Ignoring exception during channel close", e); } } try { Thread.sleep(100); } catch (InterruptedException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("SendThread interrupted during sleep, ignoring"); - } + LOG.debug("SendThread interrupted during sleep, ignoring"); } sockKey = null; } @@ -236,13 +225,9 @@ public class ClientCnxnSocketNIO extends ClientCnxnSocket { @Override void close() { try { - if (LOG.isTraceEnabled()) { - LOG.trace("Doing client selector close"); - } + LOG.trace("Doing client selector close"); selector.close(); - if (LOG.isTraceEnabled()) { - LOG.trace("Closed client selector"); - } + LOG.trace("Closed client selector"); } catch (IOException e) { LOG.warn("Ignoring exception during selector close", e); } diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/Login.java b/zookeeper-server/src/main/java/org/apache/zookeeper/Login.java index d97d6c1..5806fcb 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/Login.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/Login.java @@ -335,8 +335,8 @@ public class Login { for(KerberosTicket ticket: tickets) { KerberosPrincipal server = ticket.getServer(); if (server.getName().equals("krbtgt/" + server.getRealm() + "@" + server.getRealm())) { - LOG.debug("Client principal is \"" + ticket.getClient().getName() + "\"."); - LOG.debug("Server principal is \"" + ticket.getServer().getName() + "\"."); + LOG.debug("Client principal is \"{}\".", ticket.getClient().getName()); + LOG.debug("Server principal is \"{}\".", ticket.getServer().getName()); return ticket; } } diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/SaslServerPrincipal.java b/zookeeper-server/src/main/java/org/apache/zookeeper/SaslServerPrincipal.java index 2694f77..403bf07 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/SaslServerPrincipal.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/SaslServerPrincipal.java @@ -71,9 +71,7 @@ public class SaslServerPrincipal { if (!canonicalHostName.equals(ia.getHostAddress())) { hostName = canonicalHostName; } - if (LOG.isDebugEnabled()) { - LOG.debug("Canonicalized address to {}", hostName); - } + LOG.debug("Canonicalized address to {}", hostName); } String serverPrincipal = principalUserName + "/" + hostName; return serverPrincipal; diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/ZKUtil.java b/zookeeper-server/src/main/java/org/apache/zookeeper/ZKUtil.java index 8f758c9..b1bad3f 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/ZKUtil.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/ZKUtil.java @@ -53,8 +53,7 @@ public class ZKUtil { PathUtils.validatePath(pathRoot); List tree = listSubTreeBFS(zk, pathRoot); - LOG.debug("Deleting {}",tree); - LOG.debug("Deleting {} subnodes ",tree.size()); + LOG.debug("Deleting tree: {}", tree); return deleteInBatch(zk, tree, batchSize); } @@ -125,8 +124,7 @@ public class ZKUtil { PathUtils.validatePath(pathRoot); List tree = listSubTreeBFS(zk, pathRoot); - LOG.debug("Deleting {}",tree); - LOG.debug("Deleting {} subnodes ",tree.size()); + LOG.debug("Deleting tree: {}", tree); for (int i = tree.size() - 1; i >= 0 ; --i) { //Delete the leaves first and eventually get rid of the root zk.delete(tree.get(i), -1, cb, ctx); //Delete all versions of the node with -1. diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeper.java b/zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeper.java index 6f78925..ab45061 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeper.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeper.java @@ -1406,9 +1406,7 @@ public class ZooKeeper implements AutoCloseable { */ public synchronized void close() throws InterruptedException { if (!cnxn.getState().isAlive()) { - if (LOG.isDebugEnabled()) { - LOG.debug("Close called on already closed client"); - } + LOG.debug("Close called on already closed client"); return; } @@ -1419,9 +1417,7 @@ public class ZooKeeper implements AutoCloseable { try { cnxn.close(); } catch (IOException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("Ignoring unexpected exception during close", e); - } + LOG.debug("Ignoring unexpected exception during close", e); } LOG.info("Session: 0x" + Long.toHexString(getSessionId()) + " closed"); diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeperMain.java b/zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeperMain.java index 8b0caf9..ea7b21c 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeperMain.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeperMain.java @@ -405,7 +405,7 @@ public class ZooKeeperMain { } boolean watch = false; - LOG.debug("Processing " + cmd); + LOG.debug("Processing {}", cmd); if (cmd.equals("quit")) { diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/client/ZooKeeperSaslClient.java b/zookeeper-server/src/main/java/org/apache/zookeeper/client/ZooKeeperSaslClient.java index 34f6656..b8c2aaa 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/client/ZooKeeperSaslClient.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/client/ZooKeeperSaslClient.java @@ -225,11 +225,15 @@ public class ZooKeeperSaslClient { } byte[] usedata = data; if (data != null) { - LOG.debug("ServerSaslResponseCallback(): saslToken server response: (length="+usedata.length+")"); + LOG.debug( + "ServerSaslResponseCallback(): saslToken server response: (length={})", + usedata.length); } else { usedata = new byte[0]; - LOG.debug("ServerSaslResponseCallback(): using empty data[] as server response (length="+usedata.length+")"); + LOG.debug( + "ServerSaslResponseCallback(): using empty data[] as server response (length={})", + usedata.length); } client.respondToServer(usedata, (ClientCnxn)ctx); } @@ -241,9 +245,7 @@ public class ZooKeeperSaslClient { if (!initializedLogin) { synchronized (this) { if (login == null) { - if (LOG.isDebugEnabled()) { - LOG.debug("JAAS loginContext is: " + loginContext); - } + LOG.debug("JAAS loginContext is: {}", loginContext); // note that the login object is static: it's shared amongst all zookeeper-related connections. // in order to ensure the login is initialized only once, it must be synchronized the code snippet. login = new Login(loginContext, new SaslClientCallbackHandler(null, "Client"), clientConfig); @@ -319,7 +321,7 @@ public class ZooKeeperSaslClient { final byte[] retval = Subject.doAs(subject, new PrivilegedExceptionAction() { public byte[] run() throws SaslException { - LOG.debug("saslClient.evaluateChallenge(len="+saslToken.length+")"); + LOG.debug("saslClient.evaluateChallenge(len={})", saslToken.length); return saslClient.evaluateChallenge(saslToken); } }); @@ -352,9 +354,7 @@ public class ZooKeeperSaslClient { private void sendSaslPacket(byte[] saslToken, ClientCnxn cnxn) throws SaslException{ - if (LOG.isDebugEnabled()) { - LOG.debug("ClientCnxn:sendSaslPacket:length="+saslToken.length); - } + LOG.debug("ClientCnxn:sendSaslPacket:length={}", saslToken.length); GetSASLRequest request = new GetSASLRequest(); request.setToken(saslToken); @@ -370,9 +370,8 @@ public class ZooKeeperSaslClient { } private void sendSaslPacket(ClientCnxn cnxn) throws SaslException { - if (LOG.isDebugEnabled()) { - LOG.debug("ClientCnxn:sendSaslPacket:length="+saslToken.length); - } + LOG.debug("ClientCnxn:sendSaslPacket:length={}", saslToken.length); + GetSASLRequest request = new GetSASLRequest(); request.setToken(createSaslToken()); SetSASLResponse response = new SetSASLResponse(); @@ -456,9 +455,8 @@ public class ZooKeeperSaslClient { } catch (SecurityException e) { // Thrown if the caller does not have permission to retrieve the Configuration. // In this case, simply returning false is correct. - if (LOG.isDebugEnabled()) { - LOG.debug("Could not retrieve login configuration: " + e); - } + LOG.debug("Could not retrieve login configuration", e); + return false; } } diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/common/FileChangeWatcher.java b/zookeeper-server/src/main/java/org/apache/zookeeper/common/FileChangeWatcher.java index 8b49be9..4e7fba3 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/common/FileChangeWatcher.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/common/FileChangeWatcher.java @@ -69,9 +69,9 @@ public final class FileChangeWatcher { public FileChangeWatcher(Path dirPath, Consumer> callback) throws IOException { FileSystem fs = dirPath.getFileSystem(); WatchService watchService = fs.newWatchService(); - if (LOG.isDebugEnabled()) { - LOG.debug("Registering with watch service: " + dirPath); - } + + LOG.debug("Registering with watch service: {}", dirPath); + dirPath.register( watchService, new WatchEvent.Kind[]{ @@ -223,15 +223,12 @@ public final class FileChangeWatcher { try { key = watchService.take(); } catch (InterruptedException|ClosedWatchServiceException e) { - if (LOG.isDebugEnabled()) { - LOG.debug(getName() + " was interrupted and is shutting down ..."); - } + LOG.debug("{} was interrupted and is shutting down...", getName()); break; } for (WatchEvent event : key.pollEvents()) { - if (LOG.isDebugEnabled()) { - LOG.debug("Got file changed event: " + event.kind() + " with context: " + event.context()); - } + LOG.debug("Got file changed event: {} with context: {}", event.kind(), + event.context()); try { callback.accept(event); } catch (Throwable e) { diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/common/NettyUtils.java b/zookeeper-server/src/main/java/org/apache/zookeeper/common/NettyUtils.java index 283ea87..d55281f 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/common/NettyUtils.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/common/NettyUtils.java @@ -151,10 +151,8 @@ public class NettyUtils { validInetAddresses.add(inetAddress); } } - if (LOG.isDebugEnabled()) { - LOG.debug("Detected {} local network addresses", validInetAddresses.size()); - LOG.debug("Resolved local addresses are: {}", Arrays.toString(validInetAddresses.toArray())); - } + LOG.debug("Detected {} local network addresses: {}", + validInetAddresses.size(), validInetAddresses); return validInetAddresses.size() > 0 ? validInetAddresses.size() : DEFAULT_INET_ADDRESS_COUNT; } catch (SocketException ex) { LOG.warn("Failed to list all network interfaces, assuming 1", ex); diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/DataTree.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/DataTree.java index 1c7f4dc..d2371ff 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/DataTree.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/DataTree.java @@ -1033,14 +1033,10 @@ public class DataTree { break; } } catch (KeeperException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("Failed: " + header + ":" + txn, e); - } + LOG.debug("Failed: {}:{}", header, txn, e); rc.err = e.code().intValue(); } catch (IOException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("Failed: " + header + ":" + txn, e); - } + LOG.debug("Failed: {}:{}", header, txn, e); } /* @@ -1059,8 +1055,8 @@ public class DataTree { */ if (header.getType() == OpCode.create && rc.err == Code.NODEEXISTS.intValue()) { - LOG.debug("Adjusting parent cversion for Txn: " + header.getType() + - " path:" + rc.path + " err: " + rc.err); + LOG.debug("Adjusting parent cversion for Txn: {} path: {} err: {}", + header.getType(), rc.path, rc.err); int lastSlash = rc.path.lastIndexOf('/'); String parentName = rc.path.substring(0, lastSlash); CreateTxn cTxn = (CreateTxn)txn; @@ -1073,8 +1069,8 @@ public class DataTree { rc.err = e.code().intValue(); } } else if (rc.err != Code.OK.intValue()) { - LOG.debug("Ignoring processTxn failure hdr: " + header.getType() + - " : error: " + rc.err); + LOG.debug("Ignoring processTxn failure hdr: {} : error: {}", + header.getType(), rc.err); } /* diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/FinalRequestProcessor.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/FinalRequestProcessor.java index 962a267..528c4ba 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/FinalRequestProcessor.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/FinalRequestProcessor.java @@ -105,9 +105,8 @@ public class FinalRequestProcessor implements RequestProcessor { } public void processRequest(Request request) { - if (LOG.isDebugEnabled()) { - LOG.debug("Processing request:: " + request); - } + LOG.debug("Processing request:: {}", request); + // request.addRQRec(">final"); long traceMask = ZooTrace.CLIENT_REQUEST_TRACE_MASK; if (request.type == OpCode.ping) { @@ -213,9 +212,7 @@ public class FinalRequestProcessor implements RequestProcessor { throw ke; } - if (LOG.isDebugEnabled()) { - LOG.debug("{}",request); - } + LOG.debug("{}",request); if (request.isStale()) { ServerMetrics.getMetrics().STALE_REPLIES.add(1); diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxn.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxn.java index d94d407..10424ae 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxn.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxn.java @@ -135,10 +135,9 @@ public class NIOServerCnxn extends ServerCnxn { * asynchronous writes. */ public void sendBuffer(ByteBuffer... buffers) { - if (LOG.isTraceEnabled()) { - LOG.trace("Add a buffer to outgoingBuffers, sk " + sk - + " is valid: " + sk.isValid()); - } + LOG.trace("Add a buffer to outgoingBuffers, sk {} is valid: {}", sk, + sk.isValid()); + synchronized (outgoingBuffers) { for (ByteBuffer buffer : buffers) { outgoingBuffers.add(buffer); @@ -363,9 +362,9 @@ public class NIOServerCnxn extends ServerCnxn { } catch (CancelledKeyException e) { LOG.warn("CancelledKeyException causing close of session 0x" + Long.toHexString(sessionId)); - if (LOG.isDebugEnabled()) { - LOG.debug("CancelledKeyException stack trace", e); - } + + LOG.debug("CancelledKeyException stack trace", e); + close(DisconnectReason.CANCELLED_KEY_EXCEPTION); } catch (CloseRequestException e) { // expecting close to log session closure @@ -385,9 +384,8 @@ public class NIOServerCnxn extends ServerCnxn { } catch (IOException e) { LOG.warn("Exception causing close of session 0x" + Long.toHexString(sessionId) + ": " + e.getMessage()); - if (LOG.isDebugEnabled()) { - LOG.debug("IOException stack trace", e); - } + + LOG.debug("IOException stack trace", e); close(DisconnectReason.IO_EXCEPTION); } } @@ -613,9 +611,7 @@ public class NIOServerCnxn extends ServerCnxn { // need to cancel this selection key from the selector sk.cancel(); } catch (Exception e) { - if (LOG.isDebugEnabled()) { - LOG.debug("ignoring exception during selectionkey cancel", e); - } + LOG.debug("ignoring exception during selectionkey cancel", e); } } @@ -630,11 +626,14 @@ public class NIOServerCnxn extends ServerCnxn { return; } - LOG.debug("Closed socket connection for client " - + sock.socket().getRemoteSocketAddress() - + (sessionId != 0 ? - " which had sessionid 0x" + Long.toHexString(sessionId) : - " (no session established for client)")); + if (LOG.isDebugEnabled()) { + LOG.debug("Closed socket connection for client " + + sock.socket().getRemoteSocketAddress() + + (sessionId != 0 ? + " which had sessionid 0x" + Long.toHexString(sessionId) : + " (no session established for client)")); + } + closeSock(sock); } @@ -656,31 +655,23 @@ public class NIOServerCnxn extends ServerCnxn { sock.socket().shutdownOutput(); } catch (IOException e) { // This is a relatively common exception that we can't avoid - if (LOG.isDebugEnabled()) { - LOG.debug("ignoring exception during output shutdown", e); - } + LOG.debug("ignoring exception during output shutdown", e); } try { sock.socket().shutdownInput(); } catch (IOException e) { // This is a relatively common exception that we can't avoid - if (LOG.isDebugEnabled()) { - LOG.debug("ignoring exception during input shutdown", e); - } + LOG.debug("ignoring exception during input shutdown", e); } try { sock.socket().close(); } catch (IOException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("ignoring exception during socket close", e); - } + LOG.debug("ignoring exception during socket close", e); } try { sock.close(); } catch (IOException e) { - if (LOG.isDebugEnabled()) { - LOG.debug("ignoring exception during socketchannel close", e); - } + LOG.debug("ignoring exception during socketchannel close", e); } } diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxnFactory.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxnFactory.java index 67d799b..f76279f 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxnFactory.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxnFactory.java @@ -151,9 +151,7 @@ public class NIOServerCnxnFactory extends ServerCnxnFactory { try { key.cancel(); } catch (Exception ex) { - if (LOG.isDebugEnabled()) { - LOG.debug("ignoring exception during selectionkey cancel", ex); - } + LOG.debug("ignoring exception during selectionkey cancel", ex); } } } @@ -293,8 +291,9 @@ public class NIOServerCnxnFactory extends ServerCnxnFactory { + " - max is " + maxClientCnxns ); } - LOG.debug("Accepted socket connection from " - + sc.socket().getRemoteSocketAddress()); + LOG.debug("Accepted socket connection from {}", + sc.socket().getRemoteSocketAddress()); + sc.configureBlocking(false); // Round-robin assign this connection to a selector thread diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxn.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxn.java index 33161e4..245b55d 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxn.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxn.java @@ -371,9 +371,8 @@ public class NettyServerCnxn extends ServerCnxn { // Have to check !closingChannel, because an error in // receiveMessage() could have led to close() being called. if (!closingChannel && buf.isReadable()) { - if (LOG.isTraceEnabled()) { - LOG.trace("Before copy {}", buf); - } + LOG.trace("Before copy {}", buf); + if (queuedBuffer == null) { queuedBuffer = channel.alloc().compositeBuffer(); } @@ -488,10 +487,8 @@ public class NettyServerCnxn extends ServerCnxn { // we could implement zero-copy queueing. zks.processPacket(this, bb); } else { - if (LOG.isDebugEnabled()) { - LOG.debug("got conn req request from {}", - getRemoteSocketAddress()); - } + LOG.debug("got conn req request from {}", + getRemoteSocketAddress()); zks.processConnectRequest(this, bb); initialized = true; } @@ -548,9 +545,8 @@ public class NettyServerCnxn extends ServerCnxn { } catch(ClientCnxnLimitException e) { // Common case exception, print at debug level ServerMetrics.getMetrics().CONNECTION_REJECTED.add(1); - if (LOG.isDebugEnabled()) { - LOG.debug("Closing connection to " + getRemoteSocketAddress(), e); - } + + LOG.debug("Closing connection to " + getRemoteSocketAddress(), e); close(DisconnectReason.CLIENT_RATE_LIMIT); } } @@ -573,9 +569,7 @@ public class NettyServerCnxn extends ServerCnxn { @Override public void disableRecv(boolean waitDisableRecv) { if (throttled.compareAndSet(false, true)) { - if (LOG.isDebugEnabled()) { - LOG.debug("Throttling - disabling recv {}", this); - } + LOG.debug("Throttling - disabling recv {}", this); channel.pipeline().fireUserEventTriggered(ReadEvent.DISABLE); } } @@ -583,9 +577,7 @@ public class NettyServerCnxn extends ServerCnxn { @Override public void enableRecv() { if (throttled.compareAndSet(true, false)) { - if (LOG.isDebugEnabled()) { - LOG.debug("Sending unthrottle event {}", this); - } + LOG.debug("Sending unthrottle event {}", this); channel.pipeline().fireUserEventTriggered(ReadEvent.ENABLE); } } diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxnFactory.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxnFactory.java index e3ae959..8928c53 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxnFactory.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxnFactory.java @@ -232,9 +232,7 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { LOG.warn("Exception caught", cause); NettyServerCnxn cnxn = ctx.channel().attr(CONNECTION_ATTRIBUTE).getAndSet(null); if (cnxn != null) { - if (LOG.isDebugEnabled()) { - LOG.debug("Closing {}", cnxn); - } + LOG.debug("Closing {}", cnxn); cnxn.close(ServerCnxn.DisconnectReason.CHANNEL_CLOSED_EXCEPTION); } } @@ -256,9 +254,7 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { // trigger a read if we have consumed all // backlog ctx.read(); - if (LOG.isDebugEnabled()) { - LOG.debug("Issued a read after queuedBuffer drained"); - } + LOG.debug("Issued a read after queuedBuffer drained"); } } } @@ -277,13 +273,9 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { @Override public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception { try { - if (LOG.isTraceEnabled()) { - LOG.trace("message received called {}", msg); - } + LOG.trace("message received called {}", msg); try { - if (LOG.isDebugEnabled()) { - LOG.debug("New message {} from {}", msg, ctx.channel()); - } + LOG.debug("New message {} from {}", msg, ctx.channel()); NettyServerCnxn cnxn = ctx.channel().attr(CONNECTION_ATTRIBUTE).get(); if (cnxn == null) { LOG.error("channelRead() on a closed or closing NettyServerCnxn"); @@ -306,10 +298,8 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { if (cnxn != null && cnxn.getQueuedReadableBytes() == 0 && cnxn.readIssuedAfterReadComplete == 0) { ctx.read(); - if (LOG.isDebugEnabled()) { - LOG.debug("Issued a read since we don't have " + - "anything to consume after channelReadComplete"); - } + LOG.debug("Issued a read since we do not have " + + "anything to consume after channelReadComplete"); } } @@ -320,7 +310,7 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { // Note: this listener is only added when LOG.isTraceEnabled() is true, // so it should not do any work other than trace logging. private final GenericFutureListener> onWriteCompletedTracer = (f) -> { - LOG.trace("write {}", f.isSuccess() ? "complete" : "failed"); + LOG.trace("write success: {}", f.isSuccess()); }; @Override @@ -534,9 +524,8 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { @Override public void closeAll(ServerCnxn.DisconnectReason reason) { - if (LOG.isDebugEnabled()) { - LOG.debug("closeAll()"); - } + LOG.debug("closeAll()"); + // clear all the connections on which we are selecting int length = cnxns.size(); for (ServerCnxn cnxn : cnxns) { @@ -548,10 +537,9 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { + Long.toHexString(cnxn.getSessionId()), e); } } - if (LOG.isDebugEnabled()) { - LOG.debug("allChannels size:" + allChannels.size() + " cnxns size:" - + length); - } + + LOG.debug("allChannels size: {} cnxns size: {}", allChannels.size(), + length); } @Override @@ -656,7 +644,7 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { // Port changes after bind() if the original port was 0, update // localAddress to get the real port. localAddress = (InetSocketAddress) parentChannel.localAddress(); - LOG.info("bound to port " + getLocalPort()); + LOG.info("bound to port {}", getLocalPort()); } public void reconfigure(InetSocketAddress addr) { @@ -667,7 +655,7 @@ public class NettyServerCnxnFactory extends ServerCnxnFactory { // Port changes after bind() if the original port was 0, update // localAddress to get the real port. localAddress = (InetSocketAddress) parentChannel.localAddress(); - LOG.info("bound to port " + getLocalPort()); + LOG.info("bound to port {}", getLocalPort()); } catch (Exception e) { LOG.error("Error while reconfiguring", e); } finally { diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/SessionTrackerImpl.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/SessionTrackerImpl.java index a984f20..28b0948 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/SessionTrackerImpl.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/SessionTrackerImpl.java @@ -221,7 +221,9 @@ public class SessionTrackerImpl extends ZooKeeperCriticalThread implements } synchronized public void removeSession(long sessionId) { - LOG.debug("Removing session 0x" + Long.toHexString(sessionId)); + if (LOG.isDebugEnabled()) { + LOG.debug("Removing session 0x{}", Long.toHexString(sessionId)); + } SessionImpl s = sessionsById.remove(sessionId); sessionsWithTimeout.remove(sessionId); if (LOG.isTraceEnabled()) { @@ -267,7 +269,9 @@ public class SessionTrackerImpl extends ZooKeeperCriticalThread implements session = existedSession; } else { added = true; - LOG.debug("Adding session 0x" + Long.toHexString(id)); + if (LOG.isDebugEnabled()) { + LOG.debug("Adding session 0x{}", Long.toHexString(id)); + } } if (LOG.isTraceEnabled()) { @@ -293,7 +297,9 @@ public class SessionTrackerImpl extends ZooKeeperCriticalThread implements throws KeeperException.SessionExpiredException, KeeperException.SessionMovedException, KeeperException.UnknownSessionException { - LOG.debug("Checking session 0x" + Long.toHexString(sessionId)); + if (LOG.isDebugEnabled()) { + LOG.debug("Checking session 0x" + Long.toHexString(sessionId)); + } SessionImpl session = sessionsById.get(sessionId); if (session == null) { diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/ZooKeeperServer.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/ZooKeeperServer.java index e580ab5..fd24873 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/ZooKeeperServer.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/ZooKeeperServer.java @@ -938,11 +938,13 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider { cnxn.sendBuffer(bb); if (valid) { - LOG.debug("Established session 0x" - + Long.toHexString(cnxn.getSessionId()) - + " with negotiated timeout " + cnxn.getSessionTimeout() - + " for client " - + cnxn.getRemoteSocketAddress()); + if (LOG.isDebugEnabled()) { + LOG.debug("Established session 0x" + + Long.toHexString(cnxn.getSessionId()) + + " with negotiated timeout " + cnxn.getSessionTimeout() + + " for client " + + cnxn.getRemoteSocketAddress()); + } cnxn.enableRecv(); } else { @@ -1291,20 +1293,24 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider { long sessionId = connReq.getSessionId(); if (sessionId == 0) { long id = createSession(cnxn, passwd, sessionTimeout); - LOG.debug("Client attempting to establish new session:" + - " session = 0x{}, zxid = 0x{}, timeout = {}, address = {}", - Long.toHexString(id), - Long.toHexString(connReq.getLastZxidSeen()), - connReq.getTimeOut(), - cnxn.getRemoteSocketAddress()); + if (LOG.isDebugEnabled()) { + LOG.debug("Client attempting to establish new session:" + + " session = 0x{}, zxid = 0x{}, timeout = {}, address = {}", + Long.toHexString(id), + Long.toHexString(connReq.getLastZxidSeen()), + connReq.getTimeOut(), + cnxn.getRemoteSocketAddress()); + } } else { long clientSessionId = connReq.getSessionId(); - LOG.debug("Client attempting to renew session:" + - " session = 0x{}, zxid = 0x{}, timeout = {}, address = {}", - Long.toHexString(clientSessionId), - Long.toHexString(connReq.getLastZxidSeen()), - connReq.getTimeOut(), - cnxn.getRemoteSocketAddress()); + if (LOG.isDebugEnabled()) { + LOG.debug("Client attempting to renew session:" + + " session = 0x{}, zxid = 0x{}, timeout = {}, address = {}", + Long.toHexString(clientSessionId), + Long.toHexString(connReq.getLastZxidSeen()), + connReq.getTimeOut(), + cnxn.getRemoteSocketAddress()); + } if (serverCnxnFactory != null) { serverCnxnFactory.closeSession(sessionId, ServerCnxn.DisconnectReason.CLIENT_RECONNECT); } @@ -1392,9 +1398,7 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider { } } if (authReturn == KeeperException.Code.OK) { - if (LOG.isDebugEnabled()) { - LOG.debug("Authentication succeeded for scheme: " + scheme); - } + LOG.debug("Authentication succeeded for scheme: {}", scheme); LOG.info("auth success " + cnxn.getRemoteSocketAddress()); ReplyHeader rh = new ReplyHeader(h.getXid(), 0, KeeperException.Code.OK.intValue()); @@ -1460,7 +1464,7 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider { GetSASLRequest clientTokenRecord = new GetSASLRequest(); ByteBufferInputStream.byteBuffer2Record(incomingBuffer,clientTokenRecord); byte[] clientToken = clientTokenRecord.getToken(); - LOG.debug("Size of client SASL token: " + clientToken.length); + LOG.debug("Size of client SASL token: {}", clientToken.length); byte[] responseToken = null; try { ZooKeeperSaslServer saslServer = cnxn.zooKeeperSaslServer; @@ -1506,7 +1510,7 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider { LOG.error("cnxn.saslServer is null: cnxn object did not initialize its saslServer properly."); } if (responseToken != null) { - LOG.debug("Size of server SASL response: " + responseToken.length); + LOG.debug("Size of server SASL response: {}", responseToken.length); } ReplyHeader replyHeader = new ReplyHeader(requestHeader.getXid(), 0, Code.OK.intValue()); diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/KeyAuthenticationProvider.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/KeyAuthenticationProvider.java index 90cfe92..0b53bba 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/KeyAuthenticationProvider.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/KeyAuthenticationProvider.java @@ -108,7 +108,9 @@ public class KeyAuthenticationProvider extends ServerAuthenticationProvider { // empty key keyStr = authStr; } - LOG.debug("KeyAuthenticationProvider handleAuthentication ("+keyStr+", "+authStr+") -> FAIL.\n"); + LOG.debug( + "KeyAuthenticationProvider handleAuthentication ({}, {}) -> FAIL.\n", + keyStr, authStr); return KeeperException.Code.AUTHFAILED; } } diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/SaslServerCallbackHandler.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/SaslServerCallbackHandler.java index 9f53a4d..f3d767b 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/SaslServerCallbackHandler.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/SaslServerCallbackHandler.java @@ -109,7 +109,7 @@ public class SaslServerCallbackHandler implements CallbackHandler { } private void handleRealmCallback(RealmCallback rc) { - LOG.debug("client supplied realm: " + rc.getDefaultText()); + LOG.debug("client supplied realm: {}", rc.getDefaultText()); rc.setText(rc.getDefaultText()); } diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnLog.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnLog.java index ec3113b..41f293b 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnLog.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnLog.java @@ -723,10 +723,10 @@ public class FileTxnLog implements TxnLog { protected InputArchive createInputArchive(File logFile) throws IOException { if(inputStream==null){ inputStream= new PositionInputStream(new BufferedInputStream(new FileInputStream(logFile))); - LOG.debug("Created new input stream " + logFile); + LOG.debug("Created new input stream: {}", logFile); ia = BinaryInputArchive.getArchive(inputStream); inStreamCreated(ia,inputStream); - LOG.debug("Created new input archive " + logFile); + LOG.debug("Created new input archive: {}", logFile); } return ia; } @@ -764,7 +764,7 @@ public class FileTxnLog implements TxnLog { hdr = new TxnHeader(); record = SerializeUtils.deserializeTxn(bytes, hdr); } catch (EOFException e) { - LOG.debug("EOF exception " + e); + LOG.debug("EOF exception", e); inputStream.close(); inputStream = null; ia = null; diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/CommitProcessor.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/CommitProcessor.java index 77635c9..22b8956 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/CommitProcessor.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/CommitProcessor.java @@ -602,9 +602,7 @@ public class CommitProcessor extends ZooKeeperCriticalThread implements if (stopped || request == null) { return; } - if (LOG.isDebugEnabled()) { - LOG.debug("Committing request:: " + request); - } + LOG.debug("Committing request:: {}", request); request.commitRecvTime = Time.currentElapsedTime(); ServerMetrics.getMetrics().COMMITS_QUEUED.add(1); committedRequests.add(request); @@ -616,9 +614,7 @@ public class CommitProcessor extends ZooKeeperCriticalThread implements if (stopped) { return; } - if (LOG.isDebugEnabled()) { - LOG.debug("Processing request:: " + request); - } + LOG.debug("Processing request:: {}", request); request.commitProcQueueStartTime = Time.currentElapsedTime(); queuedRequests.add(request); // If the request will block, add it to the queue of blocking requests diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java index 42fed41..dbc1425 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java @@ -356,10 +356,7 @@ public class FastLeaderElection implements Election { sendqueue.offer(notmsg); } else { // Receive new message - if (LOG.isDebugEnabled()) { - LOG.debug("Receive new notification message. My id = " - + self.getId()); - } + LOG.debug("Receive new notification message. My id = {}", self.getId()); // State of peer that sent this message QuorumPeer.ServerState ackstate = QuorumPeer.ServerState.LOOKING; @@ -726,8 +723,12 @@ public class FastLeaderElection implements Election { * */ protected boolean totalOrderPredicate(long newId, long newZxid, long newEpoch, long curId, long curZxid, long curEpoch) { - LOG.debug("id: " + newId + ", proposed id: " + curId + ", zxid: 0x" + - Long.toHexString(newZxid) + ", proposed zxid: 0x" + Long.toHexString(curZxid)); + if (LOG.isDebugEnabled()) { + LOG.debug("id: " + newId + ", proposed id: " + curId + ", zxid: 0x" + + Long.toHexString(newZxid) + ", proposed zxid: 0x" + + Long.toHexString(curZxid)); + } + if(self.getQuorumVerifier().getWeight(newId) == 0){ return false; } @@ -836,11 +837,11 @@ public class FastLeaderElection implements Election { */ private ServerState learningState(){ if(self.getLearnerType() == LearnerType.PARTICIPANT){ - LOG.debug("I'm a participant: " + self.getId()); + LOG.debug("I am a participant: {}", self.getId()); return ServerState.FOLLOWING; } else{ - LOG.debug("I'm an observer: " + self.getId()); + LOG.debug("I am an observer: {}", self.getId()); return ServerState.OBSERVING; } } @@ -975,7 +976,7 @@ public class FastLeaderElection implements Election { break; } if (n.zxid == -1) { - LOG.debug("Ignoring notification from member with -1 zxid" + n.sid); + LOG.debug("Ignoring notification from member with -1 zxid {}", n.sid); break; } // If notification > current, replace and send messages out @@ -1045,7 +1046,7 @@ public class FastLeaderElection implements Election { } break; case OBSERVING: - LOG.debug("Notification from observer: " + n.sid); + LOG.debug("Notification from observer: {}", n.sid); break; case FOLLOWING: case LEADING: diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/Leader.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/Leader.java index 8d90996..f9be136 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/Leader.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/Leader.java @@ -856,7 +856,7 @@ public class Leader extends LearnerMaster { if (p.request == null) { LOG.warn("Going to commmit null: " + p); } else if (p.request.getHdr().getType() == OpCode.reconfig) { - LOG.debug("Committing a reconfiguration! " + outstandingProposals.size()); + LOG.debug("Committing a reconfiguration! {}", outstandingProposals.size()); //if this server is voter in new config with the same quorum address, //then it will remain the leader @@ -927,9 +927,7 @@ public class Leader extends LearnerMaster { if (outstandingProposals.size() == 0) { - if (LOG.isDebugEnabled()) { - LOG.debug("outstanding is 0"); - } + LOG.debug("outstanding is 0"); return; } if (lastCommitted >= zxid) { @@ -952,10 +950,6 @@ public class Leader extends LearnerMaster { } p.addAck(sid); - /*if (LOG.isDebugEnabled()) { - LOG.debug("Count for zxid: 0x{} is {}", - Long.toHexString(zxid), p.ackSet.size()); - }*/ boolean hasCommitted = tryToCommit(p, zxid, followerAddr); @@ -1183,9 +1177,7 @@ public class Leader extends LearnerMaster { p.addQuorumVerifier(self.getLastSeenQuorumVerifier()); } - if (LOG.isDebugEnabled()) { - LOG.debug("Proposing:: " + request); - } + LOG.debug("Proposing:: {}", request); lastProposed = p.packet.getZxid(); outstandingProposals.put(lastProposed, p); diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/LearnerHandler.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/LearnerHandler.java index e59ac6b..81ca163 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/LearnerHandler.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/LearnerHandler.java @@ -575,7 +575,7 @@ public class LearnerHandler extends ZooKeeperThread { ServerMetrics.getMetrics().DIFF_COUNT.add(1); } - LOG.debug("Sending NEWLEADER message to " + sid); + LOG.debug("Sending NEWLEADER message to {}", sid); // the version of this quorumVerifier will be set by leader.lead() in case // the leader is just being established. waitForEpochAck makes sure that readyToStart is true if // we got here, so the version was set @@ -606,9 +606,8 @@ public class LearnerHandler extends ZooKeeperThread { return; } - if(LOG.isDebugEnabled()){ - LOG.debug("Received NEWLEADER-ACK message from " + sid); - } + LOG.debug("Received NEWLEADER-ACK message from {}", sid); + learnerMaster.waitForNewLeaderAck(getSid(), qp.getZxid()); syncLimitCheck.start(); @@ -628,7 +627,7 @@ public class LearnerHandler extends ZooKeeperThread { // so we need to mark when the peer can actually start // using the data // - LOG.debug("Sending UPTODATE message to " + sid); + LOG.debug("Sending UPTODATE message to {}", sid); queuedPackets.add(new QuorumPacket(Leader.UPTODATE, -1, null, null)); while (true) { @@ -654,9 +653,7 @@ public class LearnerHandler extends ZooKeeperThread { switch (qp.getType()) { case Leader.ACK: if (this.learnerType == LearnerType.OBSERVER) { - if (LOG.isDebugEnabled()) { - LOG.debug("Received ACK from Observer " + this.sid); - } + LOG.debug("Received ACK from Observer {}", this.sid); } syncLimitCheck.updateAck(qp.getZxid()); learnerMaster.processAck(this.sid, qp.getZxid(), sock.getLocalSocketAddress()); @@ -843,9 +840,11 @@ public class LearnerHandler extends ZooKeeperThread { needSnap = false; } else if (peerLastZxid > maxCommittedLog && !isPeerNewEpochZxid) { // Newer than committedLog, send trunc and done - LOG.debug("Sending TRUNC to follower zxidToSend=0x" + - Long.toHexString(maxCommittedLog) + - " for peer sid:" + getSid()); + if (LOG.isDebugEnabled()) { + LOG.debug("Sending TRUNC to follower zxidToSend=0x" + + Long.toHexString(maxCommittedLog) + + " for peer sid:" + getSid()); + } queueOpPacket(Leader.TRUNC, maxCommittedLog); currentZxid = maxCommittedLog; needOpPacket = false; @@ -882,8 +881,10 @@ public class LearnerHandler extends ZooKeeperThread { queuedPackets.clear(); needOpPacket = true; } else { - LOG.debug("Queueing committedLog 0x{}", + if (LOG.isDebugEnabled()) { + LOG.debug("Queueing committedLog 0x{}", Long.toHexString(currentZxid)); + } Iterator committedLogItr = db.getCommittedLog().iterator(); currentZxid = queueCommittedProposals(committedLogItr, @@ -909,8 +910,10 @@ public class LearnerHandler extends ZooKeeperThread { if (needSnap) { currentZxid = db.getDataTreeLastProcessedZxid(); } - LOG.debug("Start forwarding 0x" + Long.toHexString(currentZxid) + - " for peer sid: " + getSid()); + if (LOG.isDebugEnabled()) { + LOG.debug("Start forwarding 0x" + Long.toHexString(currentZxid) + + " for peer sid: " + getSid()); + } leaderLastZxid = learnerMaster.startForwarding(this, currentZxid); } finally { rl.unlock(); diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumCnxManager.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumCnxManager.java index d97da2a..3b6133a 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumCnxManager.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumCnxManager.java @@ -329,7 +329,7 @@ public class QuorumCnxManager { * @param sid */ public void testInitiateConnection(long sid) throws Exception { - LOG.debug("Opening channel to server " + sid); + LOG.debug("Opening channel to server {}", sid); Socket sock = new Socket(); setSockOpts(sock); sock.connect(self.getVotingView().get(sid).electionAddr, cnxTO); @@ -637,13 +637,13 @@ public class QuorumCnxManager { */ synchronized boolean connectOne(long sid, InetSocketAddress electionAddr){ if (senderWorkerMap.get(sid) != null) { - LOG.debug("There is a connection already for server " + sid); + LOG.debug("There is a connection already for server {}", sid); return true; } Socket sock = null; try { - LOG.debug("Opening channel to server " + sid); + LOG.debug("Opening channel to server {}", sid); if (self.isSslQuorum()) { sock = self.getX509Util().createSSLSocket(); } else { @@ -657,7 +657,7 @@ public class QuorumCnxManager { LOG.info("SSL handshake complete with {} - {} - {}", sslSock.getRemoteSocketAddress(), sslSock.getSession().getProtocol(), sslSock.getSession().getCipherSuite()); } - LOG.debug("Connected to server " + sid); + LOG.debug("Connected to server {}", sid); // Sends connection request asynchronously if the quorum // sasl authentication is enabled. This is required because // sasl server authentication process may take few seconds to @@ -698,7 +698,7 @@ public class QuorumCnxManager { */ synchronized void connectOne(long sid){ if (senderWorkerMap.get(sid) != null) { - LOG.debug("There is a connection already for server " + sid); + LOG.debug("There is a connection already for server {}", sid); return; } synchronized (self.QV_LOCK) { @@ -749,7 +749,7 @@ public class QuorumCnxManager { */ boolean haveDelivered() { for (ArrayBlockingQueue queue : queueSendMap.values()) { - LOG.debug("Queue size: " + queue.size()); + LOG.debug("Queue size: {}", queue.size()); if (queue.size() == 0) { return true; } @@ -787,7 +787,7 @@ public class QuorumCnxManager { */ public void softHalt() { for (SendWorker sw : senderWorkerMap.values()) { - LOG.debug("Halting sender: " + sw); + LOG.debug("Halting sender: {}", sw); sw.finish(); } } @@ -961,9 +961,9 @@ public class QuorumCnxManager { */ void halt(){ try{ - LOG.debug("Trying to close listener: " + ss); + LOG.debug("Trying to close listener: {}", ss); if(ss != null) { - LOG.debug("Closing listener: " + LOG.debug("Closing listener: {}", + QuorumCnxManager.this.mySid); ss.close(); } @@ -1006,7 +1006,7 @@ public class QuorumCnxManager { closeSocket(sock); running = false; } - LOG.debug("Address of remote peer: " + this.sid); + LOG.debug("Address of remote peer: {}", this.sid); } synchronized void setRecv(RecvWorker recvWorker) { @@ -1023,7 +1023,7 @@ public class QuorumCnxManager { } synchronized boolean finish() { - LOG.debug("Calling finish for " + sid); + LOG.debug("Calling finish for {}", sid); if(!running){ /* @@ -1040,7 +1040,7 @@ public class QuorumCnxManager { recvWorker.finish(); } - LOG.debug("Removing entry from senderWorkerMap sid=" + sid); + LOG.debug("Removing entry from senderWorkerMap sid={}", sid); senderWorkerMap.remove(sid, this); threadCnt.decrementAndGet(); @@ -1082,7 +1082,7 @@ public class QuorumCnxManager { if (bq == null || isSendQueueEmpty(bq)) { ByteBuffer b = lastMessageSent.get(sid); if (b != null) { - LOG.debug("Attempting to send lastMessage to sid=" + sid); + LOG.debug("Attempting to send lastMessage to sid={}", sid); send(b); } } @@ -1230,7 +1230,7 @@ public class QuorumCnxManager { } catch (NoSuchElementException ne) { // element could be removed by poll() LOG.debug("Trying to remove from an empty " + - "Queue. Ignoring exception " + ne); + "Queue. Ignoring exception.", ne); } } try { @@ -1292,7 +1292,7 @@ public class QuorumCnxManager { } catch (NoSuchElementException ne) { // element could be removed by poll() LOG.debug("Trying to remove from an empty " + - "recvQueue. Ignoring exception " + ne); + "recvQueue. Ignoring exception.", ne); } } try { diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java index ce794d1..2e202d0 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java @@ -1434,7 +1434,7 @@ public class QuorumPeer extends ZooKeeperThread implements QuorumStats.Provider LOG.debug("PeerState set to OBSERVER"); } else { // currently shouldn't happen since there are only 2 learner types setPeerState(ServerState.LOOKING); - LOG.debug("Shouldn't be here"); + LOG.debug("Should not be here"); } reconfigFlag = false; } @@ -1771,8 +1771,9 @@ public class QuorumPeer extends ZooKeeperThread implements QuorumStats.Provider if ((quorumVerifier != null) && (quorumVerifier.getVersion() >= qv.getVersion())) { // this is normal. For example - server found out about new config through FastLeaderElection gossiping // and then got the same config in UPTODATE message so its already known - LOG.debug(getId() + " setQuorumVerifier called with known or old config " + qv.getVersion() + - ". Current version: " + quorumVerifier.getVersion()); + LOG.debug("{} setQuorumVerifier called with known or old config {}." + + " Current version: {}", getId(), qv.getVersion(), + quorumVerifier.getVersion()); return quorumVerifier; } QuorumVerifier prevQV = quorumVerifier; diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/auth/SaslQuorumAuthLearner.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/auth/SaslQuorumAuthLearner.java index 31f4f55..96e2e92 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/auth/SaslQuorumAuthLearner.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/auth/SaslQuorumAuthLearner.java @@ -191,8 +191,8 @@ public class SaslQuorumAuthLearner implements QuorumAuthLearner { final byte[] retval = Subject.doAs(login.getSubject(), new PrivilegedExceptionAction() { public byte[] run() throws SaslException { - LOG.debug("saslClient.evaluateChallenge(len=" - + saslToken.length + ")"); + LOG.debug("saslClient.evaluateChallenge(len={})", + saslToken.length); return saslClient.evaluateChallenge(saslToken); } }); diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/flexible/QuorumHierarchical.java b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/flexible/QuorumHierarchical.java index 9abeca8..237f174 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/flexible/QuorumHierarchical.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/flexible/QuorumHierarchical.java @@ -310,10 +310,10 @@ public class QuorumHierarchical implements QuorumVerifier { * Do not consider groups with weight zero */ for(long weight: groupWeight.values()){ - LOG.debug("Group weight: " + weight); + LOG.debug("Group weight: {}", weight); if(weight == ((long) 0)){ numGroups--; - LOG.debug("One zero-weight group: " + 1 + ", " + numGroups); + LOG.debug("One zero-weight group: 1, {}", numGroups); } } } @@ -327,9 +327,9 @@ public class QuorumHierarchical implements QuorumVerifier { /* * Adds up weights per group */ - if(set.size() == 0) return false; - else LOG.debug("Set size: " + set.size()); - + LOG.debug("Set size: {}", set.size()); + if (set.size() == 0) return false; + for(long sid : set){ Long gid = serverGroup.get(sid); if (gid == null) continue; diff --git a/zookeeper-server/src/main/java/org/apache/zookeeper/util/SecurityUtils.java b/zookeeper-server/src/main/java/org/apache/zookeeper/util/SecurityUtils.java index 67484e4..7f658ab 100644 --- a/zookeeper-server/src/main/java/org/apache/zookeeper/util/SecurityUtils.java +++ b/zookeeper-server/src/main/java/org/apache/zookeeper/util/SecurityUtils.java @@ -124,7 +124,7 @@ public final class SecurityUtils { LOG.info("{} will use GSSAPI as SASL mechanism.", entity); String[] mechs = { "GSSAPI" }; LOG.debug("creating sasl client: {}={};service={};serviceHostname={}", - new Object[] { entity, clientPrincipalName, serviceName, serviceHostname }); + entity, clientPrincipalName, serviceName, serviceHostname); SaslClient saslClient = Sasl.createSaslClient( mechs, clientPrincipalName, serviceName, serviceHostname, null, @@ -188,10 +188,9 @@ public final class SecurityUtils { // subject is non-null, it can be assumed to be GSSAPI. final String mech = "GSSAPI"; - LOG.debug("serviceHostname is '" + serviceHostname + "'"); - LOG.debug("servicePrincipalName is '" + servicePrincipalName - + "'"); - LOG.debug("SASL mechanism(mech) is '" + mech + "'"); + LOG.debug("serviceHostname is '{}'", serviceHostname); + LOG.debug("servicePrincipalName is '{}'", servicePrincipalName); + LOG.debug("SASL mechanism(mech) is '{}'", mech); boolean usingNativeJgss = Boolean .getBoolean("sun.security.jgss.native");