Bläddra i källkod

ZOOKEEPER-3339: Improve Debug and Trace Log Statements

Author: Beluga Behr <dam6923@gmail.com>

Reviewers: andor@apache.org, nkalmar@apache.org, maoling@apache.org, fangmin@apache.org

Closes #878 from belugabehr/ZOOKEEPER-3339
Beluga Behr 5 år sedan
förälder
incheckning
d84b7a682e
33 ändrade filer med 207 tillägg och 280 borttagningar
  1. 3 3
      zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/ProtocolSupport.java
  2. 4 11
      zookeeper-recipes/zookeeper-recipes-lock/src/main/java/org/apache/zookeeper/recipes/lock/WriteLock.java
  3. 1 2
      zookeeper-recipes/zookeeper-recipes-queue/src/main/java/org/apache/zookeeper/recipes/queue/DistributedQueue.java
  4. 2 4
      zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxn.java
  5. 7 22
      zookeeper-server/src/main/java/org/apache/zookeeper/ClientCnxnSocketNIO.java
  6. 2 2
      zookeeper-server/src/main/java/org/apache/zookeeper/Login.java
  7. 1 3
      zookeeper-server/src/main/java/org/apache/zookeeper/SaslServerPrincipal.java
  8. 2 4
      zookeeper-server/src/main/java/org/apache/zookeeper/ZKUtil.java
  9. 2 6
      zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeper.java
  10. 1 1
      zookeeper-server/src/main/java/org/apache/zookeeper/ZooKeeperMain.java
  11. 13 15
      zookeeper-server/src/main/java/org/apache/zookeeper/client/ZooKeeperSaslClient.java
  12. 6 9
      zookeeper-server/src/main/java/org/apache/zookeeper/common/FileChangeWatcher.java
  13. 2 4
      zookeeper-server/src/main/java/org/apache/zookeeper/common/NettyUtils.java
  14. 6 10
      zookeeper-server/src/main/java/org/apache/zookeeper/server/DataTree.java
  15. 3 6
      zookeeper-server/src/main/java/org/apache/zookeeper/server/FinalRequestProcessor.java
  16. 21 30
      zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxn.java
  17. 4 5
      zookeeper-server/src/main/java/org/apache/zookeeper/server/NIOServerCnxnFactory.java
  18. 8 16
      zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxn.java
  19. 14 26
      zookeeper-server/src/main/java/org/apache/zookeeper/server/NettyServerCnxnFactory.java
  20. 9 3
      zookeeper-server/src/main/java/org/apache/zookeeper/server/SessionTrackerImpl.java
  21. 26 22
      zookeeper-server/src/main/java/org/apache/zookeeper/server/ZooKeeperServer.java
  22. 3 1
      zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/KeyAuthenticationProvider.java
  23. 1 1
      zookeeper-server/src/main/java/org/apache/zookeeper/server/auth/SaslServerCallbackHandler.java
  24. 3 3
      zookeeper-server/src/main/java/org/apache/zookeeper/server/persistence/FileTxnLog.java
  25. 2 6
      zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/CommitProcessor.java
  26. 11 10
      zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/FastLeaderElection.java
  27. 3 11
      zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/Leader.java
  28. 17 14
      zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/LearnerHandler.java
  29. 15 15
      zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumCnxManager.java
  30. 4 3
      zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/QuorumPeer.java
  31. 2 2
      zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/auth/SaslQuorumAuthLearner.java
  32. 5 5
      zookeeper-server/src/main/java/org/apache/zookeeper/server/quorum/flexible/QuorumHierarchical.java
  33. 4 5
      zookeeper-server/src/main/java/org/apache/zookeeper/util/SecurityUtils.java

+ 3 - 3
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);
             }
         }
     }

+ 4 - 11
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;

+ 1 - 2
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 {

+ 2 - 4
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<String> prependChroot(List<String> paths) {

+ 7 - 22
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);
         }

+ 2 - 2
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;
             }
         }

+ 1 - 3
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;

+ 2 - 4
zookeeper-server/src/main/java/org/apache/zookeeper/ZKUtil.java

@@ -53,8 +53,7 @@ public class ZKUtil {
         PathUtils.validatePath(pathRoot);
 
         List<String> 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<String> 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.

+ 2 - 6
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");

+ 1 - 1
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")) {

+ 13 - 15
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<byte[]>() {
                                 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;
         }
     }

+ 6 - 9
zookeeper-server/src/main/java/org/apache/zookeeper/common/FileChangeWatcher.java

@@ -69,9 +69,9 @@ public final class FileChangeWatcher {
     public FileChangeWatcher(Path dirPath, Consumer<WatchEvent<?>> 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) {

+ 2 - 4
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);

+ 6 - 10
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);
         }
 
         /*

+ 3 - 6
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);

+ 21 - 30
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);
         }
     }
 

+ 4 - 5
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

+ 8 - 16
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);
         }
     }

+ 14 - 26
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<Future<Void>> 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 {

+ 9 - 3
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) {

+ 26 - 22
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());

+ 3 - 1
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;
             }
         }

+ 1 - 1
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());
     }
 

+ 3 - 3
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;

+ 2 - 6
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

+ 11 - 10
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:

+ 3 - 11
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);

+ 17 - 14
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<Proposal> 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();

+ 15 - 15
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<ByteBuffer> 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 {

+ 4 - 3
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;

+ 2 - 2
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<byte[]>() {
                                 public byte[] run() throws SaslException {
-                                    LOG.debug("saslClient.evaluateChallenge(len="
-                                                    + saslToken.length + ")");
+                                    LOG.debug("saslClient.evaluateChallenge(len={})",
+                                        saslToken.length);
                                     return saslClient.evaluateChallenge(saslToken);
                                 }
                             });

+ 5 - 5
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;

+ 4 - 5
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");