ZOOKEEPER-259. cleanup the logging levels used (use the correct level)

and messages generated. (phunt via breed)


git-svn-id: https://svn.apache.org/repos/asf/hadoop/zookeeper/trunk@734857 13f79535-47bb-0310-9956-ffa450edef68

CHANGES.txt

@@ -105,6 +105,8 @@ IMPROVEMENTS:
    ZOOKEEPER-234. Eliminate using statics to initialize the sever. Should
    allow server to be more embeddable in OSGi enviorments. (phunt)
 
+   ZOOKEEPER-259. cleanup the logging levels used (use the correct level)
+   and messages generated. (phunt via breed)
 
 Release 3.0.0 - 2008-10-21
 

src/c/src/zk_adaptor.h

@@ -166,6 +166,7 @@ struct _zhandle {
     watcher_fn watcher; /* the registered watcher */
     struct timeval last_recv; /* The time that the last message was received */
     struct timeval last_send; /* The time that the last message was sent */
+    struct timeval last_ping; /* The time that the last PING was sent */
     struct timeval next_deadline; /* The time of the next deadline */
     int recv_timeout; /* The maximum amount of time that can go by without 
      receiving anything from the zookeeper server */

src/c/src/zookeeper.c

@@ -1060,6 +1060,7 @@ static struct timeval get_timeval(int interval)
 
     rc = serialize_RequestHeader(oa, "header", &h);
     enter_critical(zh);
+    gettimeofday(&zh->last_ping, 0);
     rc = rc < 0 ? rc : add_void_completion(zh, h.xid, 0, 0);
     rc = rc < 0 ? rc : queue_buffer_bytes(&zh->to_send, get_buffer(oa),
             get_buffer_len(oa));
@@ -1118,6 +1119,7 @@ static struct timeval get_timeval(int interval)
         *tv = get_timeval(zh->recv_timeout/3);
         zh->last_recv = now;
         zh->last_send = now;
+        zh->last_ping = now;
     }
     if (zh->fd != -1) {
         int idle_recv = calculate_interval(&zh->last_recv, &now);
@@ -1495,8 +1497,9 @@ int zookeeper_process(zhandle_t *zh, int events)
             // fprintf(stderr, "Got %llx for %x\n", hdr.zxid, hdr.xid);
         }
         
-        LOG_DEBUG(("Got response xid=%x", hdr.xid));
         if (hdr.xid == WATCHER_EVENT_XID) {
+            LOG_DEBUG(("Processing WATCHER_EVENT"));
+
             struct WatcherEvent evt;
             int type;
             char *path;
@@ -1514,8 +1517,11 @@ int zookeeper_process(zhandle_t *zh, int events)
             deallocate_WatcherEvent(&evt);
             queue_completion(&zh->completions_to_process, c, 0);
         } else if (hdr.xid == SET_WATCHES_XID) {
+            LOG_DEBUG(("Processing SET_WATCHES"));
             free_buffer(bptr);
         } else if (hdr.xid == AUTH_XID){
+            LOG_DEBUG(("Processing AUTH_XID"));
+
             /* special handling for the AUTH response as it may come back 
              * out-of-band */
             auth_completion_func(hdr.err,zh);
@@ -1534,6 +1540,8 @@ int zookeeper_process(zhandle_t *zh, int events)
             assert(cptr);
             /* The requests are going to come back in order */
             if (cptr->xid != hdr.xid) {
+                LOG_DEBUG(("Processing unexpected or out-of-order response!"));
+
                 // received unexpected (or out-of-order) response
                 close_buffer_iarchive(&ia);
                 free_buffer(bptr);
@@ -1549,10 +1557,17 @@ int zookeeper_process(zhandle_t *zh, int events)
 
             if (cptr->c.void_result != SYNCHRONOUS_MARKER) {
                 if(hdr.xid == PING_XID){
+                    struct timeval now;
+                    gettimeofday(&now, 0);
+                    int elapsed = calculate_interval(&zh->last_ping, &now);
+                    LOG_DEBUG(("Got ping response in %d ms", elapsed));
+
                     // Nothing to do with a ping response
                     free_buffer(bptr);
                     destroy_completion_entry(cptr);
                 } else { 
+                    LOG_DEBUG(("Queueing asynchronous response"));
+
                     cptr->buffer = bptr;
                     queue_completion(&zh->completions_to_process, cptr, 0);
                 }
@@ -1562,7 +1577,8 @@ int zookeeper_process(zhandle_t *zh, int events)
                 sc->rc = rc;
                 switch(cptr->completion_type) {
                 case COMPLETION_DATA:
-                    LOG_DEBUG(("Calling COMPLETION_DATA for xid=%x rc=%d",cptr->xid,rc));
+                    LOG_DEBUG(("Calling COMPLETION_DATA for xid=%x rc=%d",
+                               cptr->xid, rc));
                     if (rc==0) {
                         struct GetDataResponse res;
                         int len;
@@ -1579,7 +1595,8 @@ int zookeeper_process(zhandle_t *zh, int events)
                     }
                     break;
                 case COMPLETION_STAT:
-                    LOG_DEBUG(("Calling COMPLETION_STAT for xid=%x rc=%d",cptr->xid,rc));
+                    LOG_DEBUG(("Calling COMPLETION_STAT for xid=%x rc=%d",
+                               cptr->xid, rc));
                     if (rc == 0) {
                         struct SetDataResponse res;
                         deserialize_SetDataResponse(ia, "reply", &res);
@@ -1588,7 +1605,8 @@ int zookeeper_process(zhandle_t *zh, int events)
                     }
                     break;
                 case COMPLETION_STRINGLIST:
-                    LOG_DEBUG(("Calling COMPLETION_STRINGLIST for xid=%x rc=%d",cptr->xid,rc));
+                    LOG_DEBUG(("Calling COMPLETION_STRINGLIST for xid=%x rc=%d",
+                               cptr->xid, rc));
                     if (rc == 0) {
                         struct GetChildrenResponse res;
                         deserialize_GetChildrenResponse(ia, "reply", &res);
@@ -1598,7 +1616,8 @@ int zookeeper_process(zhandle_t *zh, int events)
                     }
                     break;
                 case COMPLETION_STRING:
-                    LOG_DEBUG(("Calling COMPLETION_STRING for xid=%x rc=%d",cptr->xid,rc));
+                    LOG_DEBUG(("Calling COMPLETION_STRING for xid=%x rc=%d",
+                               cptr->xid, rc));
                     if (rc == 0) {
                         struct CreateResponse res;
                         int len;
@@ -1616,7 +1635,8 @@ int zookeeper_process(zhandle_t *zh, int events)
                     }
                     break;
                 case COMPLETION_ACLLIST:
-                    LOG_DEBUG(("Calling COMPLETION_ACLLIST for xid=%x rc=%d",cptr->xid,rc));
+                    LOG_DEBUG(("Calling COMPLETION_ACLLIST for xid=%x rc=%d",
+                               cptr->xid, rc));
                     if (rc == 0) {
                         struct GetACLResponse res;
                         deserialize_GetACLResponse(ia, "reply", &res);
@@ -1628,7 +1648,12 @@ int zookeeper_process(zhandle_t *zh, int events)
                     }
                     break;
                 case COMPLETION_VOID:
-                    LOG_DEBUG(("Calling COMPLETION_VOID for xid=%x rc=%d",cptr->xid,rc));
+                    LOG_DEBUG(("Calling COMPLETION_VOID for xid=%x rc=%d",
+                               cptr->xid, rc));
+                    break;
+                default:
+                    LOG_DEBUG(("UNKNOWN response type xid=%x rc=%d",
+                               cptr->xid, rc));
                     break;
                 }
                 notify_sync_completion(sc);

src/java/main/org/apache/zookeeper/ClientCnxn.java

@@ -211,7 +211,7 @@ public class ClientCnxn {
                     this.bb.putInt(this.bb.capacity() - 4);
                     this.bb.rewind();
                 } catch (IOException e) {
-                    LOG.warn("Unexpected exception",e);
+                    LOG.warn("Ignoring unexpected exception", e);
                 }
             }
             this.watchRegistration = watchRegistration;
@@ -429,7 +429,7 @@ public class ClientCnxn {
                     }
                 }
             } catch (InterruptedException e) {
-                LOG.warn("Event thread exiting due to interruption", e);
+                LOG.error("Event thread exiting due to interruption", e);
             }
             
             LOG.info("EventThread shut down");
@@ -484,6 +484,8 @@ public class ClientCnxn {
 
         boolean initialized;
 
+        private long lastPingSentNs;
+
         void readLength() throws IOException {
             int len = incomingBuffer.getInt();
             if (len < 0 || len >= 4096 * 1024) {
@@ -524,16 +526,19 @@ public class ClientCnxn {
             replyHdr.deserialize(bbia, "header");
             if (replyHdr.getXid() == -2) {
                 // -2 is the xid for pings
-                LOG
-                    .debug("Got ping sessionid:0x"
-                    + Long.toHexString(sessionId));
+                if (LOG.isDebugEnabled()) {
+                    LOG.debug("Got ping response for sessionid:0x"
+                            + Long.toHexString(sessionId)
+                            + " after " 
+                            + ((System.nanoTime() - lastPingSentNs) / 1000000)
+                            + "ms");
+                }
                 return;
             }
             if (replyHdr.getXid() == -4) {
                 // -2 is the xid for AuthPacket
                 // TODO: process AuthPacket here
-                LOG
-                    .debug("Got auth sessionid:0x"
+                LOG.debug("Got auth sessionid:0x"
                         + Long.toHexString(sessionId));
                 return;
             }
@@ -732,6 +737,7 @@ public class ClientCnxn {
         }
 
         private void sendPing() {
+            lastPingSentNs = System.nanoTime();
             RequestHeader h = new RequestHeader(-2, OpCode.ping);
             queuePacket(h, null, null, null, null, null, null, null);
         }

src/java/main/org/apache/zookeeper/ZooKeeper.java

@@ -420,7 +420,7 @@ public class ZooKeeper {
         try {
             cnxn.close();
         } catch (IOException e) {
-            LOG.warn("Unexpected exception", e);
+            LOG.warn("Ignoring unexpected exception", e);
         }
 
         LOG.info("Session: 0x" + Long.toHexString(getSessionId()) + " closed");

src/java/main/org/apache/zookeeper/server/DataTree.java

@@ -37,6 +37,7 @@ import org.apache.zookeeper.KeeperException;
 import org.apache.zookeeper.WatchedEvent;
 import org.apache.zookeeper.Watcher;
 import org.apache.zookeeper.KeeperException.Code;
+import org.apache.zookeeper.KeeperException.NoNodeException;
 import org.apache.zookeeper.Watcher.Event;
 import org.apache.zookeeper.Watcher.Event.EventType;
 import org.apache.zookeeper.Watcher.Event.KeeperState;
@@ -44,6 +45,7 @@ import org.apache.zookeeper.ZooDefs.OpCode;
 import org.apache.zookeeper.data.ACL;
 import org.apache.zookeeper.data.Stat;
 import org.apache.zookeeper.data.StatPersisted;
+import org.apache.zookeeper.proto.WatcherEvent;
 import org.apache.zookeeper.txn.CreateTxn;
 import org.apache.zookeeper.txn.DeleteTxn;
 import org.apache.zookeeper.txn.ErrorTxn;
@@ -98,9 +100,6 @@ public class DataTree {
      */
     protected long aclIndex = 0;
     
-    /** A debug string * */
-    private String debug = "debug";
-
     @SuppressWarnings("unchecked")
     public HashSet<String> getEphemerals(long sessionId) {
         HashSet<String> retv = ephemerals.get(sessionId);
@@ -521,10 +520,10 @@ public class DataTree {
 
     public volatile long lastProcessedZxid = 0;
 
-    @SuppressWarnings("unchecked")
     public ProcessTxnResult processTxn(TxnHeader header, Record txn) {
         ProcessTxnResult rc = new ProcessTxnResult();
 
+        String debug = "";
         try {
             rc.clientId = header.getClientId();
             rc.cxid = header.getCxid();
@@ -557,6 +556,7 @@ public class DataTree {
                 break;
             case OpCode.setACL:
                 SetACLTxn setACLTxn = (SetACLTxn) txn;
+                debug = "Set ACL for  transaction for " + setACLTxn.getPath();
                 rc.stat = setACL(setACLTxn.getPath(), setACLTxn.getAcl(),
                         setACLTxn.getVersion());
                 break;
@@ -573,8 +573,7 @@ public class DataTree {
             if (initialized
                     || (e.code() != Code.NONODE 
                             && e.code() != Code.NODEEXISTS)) {
-                LOG.warn(debug);
-                LOG.error("FIXMSG",e);
+                LOG.warn("Failed:" + debug, e);
             }
         }
         return rc;
@@ -582,9 +581,9 @@ public class DataTree {
 
     void killSession(long session, long zxid) {
         // the list is already removed from the ephemerals
-        // so we do not have to worry about synchronyzing on
+        // so we do not have to worry about synchronizing on
         // the list. This is only called from FinalRequestProcessor
-        // so there is no need for synchornization. The list is not
+        // so there is no need for synchronization. The list is not
         // changed here. Only create and delete change the list which
         // are again called from FinalRequestProcessor in sequence.
         HashSet<String> list = ephemerals.remove(session);
@@ -592,13 +591,15 @@ public class DataTree {
             for (String path : list) {
                 try {
                     deleteNode(path, zxid);
-                    ZooTrace.logTraceMessage(LOG,
-                                             ZooTrace.SESSION_TRACE_MASK,
-                                             "Deleting ephemeral node "
-                                             + path + " for session 0x"
-                                             + Long.toHexString(session));
-                } catch (KeeperException e) {
-                    LOG.error("FIXMSG",e);
+                    if (LOG.isDebugEnabled()) {
+                        LOG.debug("Deleting ephemeral node " + path
+                                + " for session 0x"
+                                + Long.toHexString(session));
+                    }
+                } catch (NoNodeException e) {
+                    LOG.warn("Ignoring NoNodeException for path " + path
+                            + " while removing ephemeral for dead session 0x"
+                            + Long.toHexString(session));
                 }
             }
         }

src/java/main/org/apache/zookeeper/server/FinalRequestProcessor.java

@@ -238,15 +238,16 @@ public class FinalRequestProcessor implements RequestProcessor {
         } catch (KeeperException e) {
             err = e.code();
         } catch (Exception e) {
-            LOG.warn("****************************** " + request);
+            // log at error level as we are returning a marshalling
+            // error to the user
+            LOG.error("Failed to process " + request, e);
             StringBuffer sb = new StringBuffer();
             ByteBuffer bb = request.request;
             bb.rewind();
             while (bb.hasRemaining()) {
                 sb.append(Integer.toHexString(bb.get() & 0xff));
             }
-            LOG.warn(sb.toString());
-            LOG.error("FIXMSG",e);
+            LOG.error("Dumping request buffer: 0x" + sb.toString());
             err = Code.MARSHALLINGERROR;
         }
         ReplyHeader hdr =

src/java/main/org/apache/zookeeper/server/LogFormatter.java

@@ -65,7 +65,7 @@ public class LogFormatter {
                     + " " + TraceFormatter.op2String(hdr.getType()));
             if (logStream.readByte("EOR") != 'B') {
                 LOG.error("Last transaction was partial.");
-                throw new EOFException();
+                throw new EOFException("Last transaction was partial.");
             }
         }
     }

src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java

@@ -164,14 +164,11 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
                     }
                     selected.clear();
                 } catch (Exception e) {
-                    LOG.error("FIXMSG",e);
+                    LOG.warn("Ignoring exception", e);
                 }
             }
-            ZooTrace.logTraceMessage(LOG, ZooTrace.getTextTraceLevel(),
-                                     "NIOServerCnxn factory exitedloop.");
             clear();
-            LOG.error("=====> Goodbye cruel world <======");
-            // System.exit(0);
+            LOG.info("NIOServerCnxn factory exited run method");
         }
 
         /**
@@ -189,7 +186,8 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
                     try {
                         cnxn.close();
                     } catch (Exception e) {
-                        // Do nothing.
+                        LOG.warn("Ignoring exception closing cnxn sessionid 0x"
+                                + Long.toHexString(cnxn.sessionId), e);
                     }
                 }
             }
@@ -203,9 +201,9 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
                 this.interrupt();
                 this.join();
             } catch (InterruptedException e) {
-                LOG.warn("Interrupted",e);
+                LOG.warn("Ignoring interrupted exception during shutdown", e);
             } catch (Exception e) {
-                LOG.error("Unexpected exception", e);
+                LOG.warn("Ignoring unexpected exception during shutdown", e);
             }
             if (zks != null) {
                 zks.shutdown();
@@ -261,22 +259,14 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
 
     void sendBuffer(ByteBuffer bb) {
         synchronized (factory) {
-            try {
-                sk.selector().wakeup();
-                // ZooLog.logTraceMessage(LOG,
-                // ZooLog.CLIENT_DATA_PACKET_TRACE_MASK,
-                // "Add a buffer to outgoingBuffers");
-                // ZooLog.logTraceMessage(LOG,
-                // ZooLog.CLIENT_DATA_PACKET_TRACE_MASK,
-                //"sk " + sk + " is valid: " +
-                // sk.isValid(), );
-                outgoingBuffers.add(bb);
-                if (sk.isValid()) {
-                    sk.interestOps(sk.interestOps() | SelectionKey.OP_WRITE);
-                }
-            } catch (RuntimeException e) {
-                LOG.error("FIXMSG",e);
-                throw e;
+            sk.selector().wakeup();
+            if (LOG.isTraceEnabled()) {
+                LOG.trace("Add a buffer to outgoingBuffers, sk " + sk
+                        + " is valid: " + sk.isValid());
+            }
+            outgoingBuffers.add(bb);
+            if (sk.isValid()) {
+                sk.interestOps(sk.interestOps() | SelectionKey.OP_WRITE);
             }
         }
     }
@@ -403,9 +393,16 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
                 }
             }
         } catch (CancelledKeyException e) {
+            LOG.warn("Exception causing close of session 0x"
+                    + Long.toHexString(sessionId)
+                    + " due to " + e);
+            LOG.debug("CancelledKeyException stack trace", e);
             close();
         } catch (IOException e) {
-            // LOG.error("FIXMSG",e);
+            LOG.warn("Exception causing close of session 0x"
+                    + Long.toHexString(sessionId)
+                    + " due to " + e);
+            LOG.debug("IOException stack trace", e);
             close();
         }
     }
@@ -428,12 +425,13 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
             if (ap == null
                     || (ap.handleAuthentication(this, authPacket.getAuth())
                             != KeeperException.Code.OK)) {
-                if (ap == null)
-                    LOG.error("No authentication provider for scheme: "
-                            + scheme + " has " + ProviderRegistry.listProviders());
-                else
-                    LOG.debug("Authentication failed for scheme: "
-                            + scheme);
+                if (ap == null) {
+                    LOG.warn("No authentication provider for scheme: "
+                            + scheme + " has " 
+                            + ProviderRegistry.listProviders());
+                } else {
+                    LOG.warn("Authentication failed for scheme: " + scheme);
+                }
                 // send a response...
                 ReplyHeader rh = new ReplyHeader(h.getXid(), 0,
                         KeeperException.Code.AUTHFAILED.intValue());
@@ -487,17 +485,19 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
                 .getArchive(new ByteBufferInputStream(incomingBuffer));
         ConnectRequest connReq = new ConnectRequest();
         connReq.deserialize(bia, "connect");
-        LOG.warn("Connected to " + sock.socket().getRemoteSocketAddress()
+        LOG.info("Connected to " + sock.socket().getRemoteSocketAddress()
                 + " lastZxid " + connReq.getLastZxidSeen());
         if (zk == null) {
             throw new IOException("ZooKeeperServer not running");
         }
         if (connReq.getLastZxidSeen() > zk.dataTree.lastProcessedZxid) {
-            LOG.error("Client has seen zxid 0x"
-                    + Long.toHexString(connReq.getLastZxidSeen())
-                    + " our last zxid is 0x"
-                    + Long.toHexString(zk.dataTree.lastProcessedZxid));
-            throw new IOException("We are out of date");
+            String msg = "Client has seen zxid 0x"
+                + Long.toHexString(connReq.getLastZxidSeen())
+                + " our last zxid is 0x"
+                + Long.toHexString(zk.dataTree.lastProcessedZxid);
+            
+            LOG.error(msg);
+            throw new IOException(msg);
         }
         sessionTimeout = connReq.getTimeOut();
         byte passwd[] = connReq.getPasswd();
@@ -513,11 +513,10 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
         if (connReq.getSessionId() != 0) {
             setSessionId(connReq.getSessionId());
             zk.reopenSession(this, sessionId, passwd, sessionTimeout);
-            LOG.warn("Renewing session 0x" + Long.toHexString(sessionId));
+            LOG.info("Renewing session 0x" + Long.toHexString(sessionId));
         } else {
             zk.createSession(this, passwd, sessionTimeout);
-            LOG.warn("Creating new session 0x"
-                    + Long.toHexString(sessionId));
+            LOG.info("Creating new session 0x" + Long.toHexString(sessionId));
         }
         initialized = true;
     }
@@ -730,8 +729,8 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
             zk.removeCnxn(this);
         }
 
-        ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                                 "close  NIOServerCnxn: " + sock);
+        LOG.info("closing session:0x" + Long.toHexString(sessionId)
+                + " NIOServerCnxn: " + sock);
         try {
             /*
              * The following sequence of code is stupid! You would think that
@@ -742,11 +741,13 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
             sock.socket().shutdownOutput();
         } catch (IOException e) {
             // This is a relatively common exception that we can't avoid
+            LOG.debug("ignoring exception during output shutdown", e);
         }
         try {
             sock.socket().shutdownInput();
         } catch (IOException e) {
-            LOG.warn("ignoring exception during input shutdown", e);
+            // This is a relatively common exception that we can't avoid
+            LOG.debug("ignoring exception during input shutdown", e);
         }
         try {
             sock.socket().close();
@@ -855,8 +856,10 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
             ByteBuffer bb = ByteBuffer.wrap(baos.toByteArray());
             bb.putInt(bb.remaining() - 4).rewind();
             sendBuffer(bb);
-            LOG.warn("Finished init of 0x" + Long.toHexString(sessionId)
-                    + ": " + valid);
+
+            LOG.info("Finished init of 0x" + Long.toHexString(sessionId)
+                    + " valid:" + valid);
+
             if (!valid) {
                 sendBuffer(closeConn);
             }
@@ -866,7 +869,7 @@ public class NIOServerCnxn implements Watcher, ServerCnxn {
                 enableRecv();
             }
         } catch (Exception e) {
-            LOG.error("FIXMSG",e);
+            LOG.warn("Exception while establishing session, closing", e);
             close();
         }
     }

src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java

@@ -99,10 +99,9 @@ public class PrepRequestProcessor extends Thread implements RequestProcessor {
                 pRequest(request);
             }
         } catch (InterruptedException e) {
-            LOG.error("FIXMSG",e);
+            LOG.error("Unexpected interruption", e);
         }
-        ZooTrace.logTraceMessage(LOG, ZooTrace.getTextTraceLevel(),
-                "PrepRequestProcessor exited loop!");
+        LOG.info("PrepRequestProcessor exited loop!");
     }
 
     ChangeRecord getRecordForPath(String path) throws KeeperException.NoNodeException {
@@ -360,18 +359,22 @@ public class PrepRequestProcessor extends Thread implements RequestProcessor {
                 txn = new ErrorTxn(e.code().intValue());
             }
         } catch (Exception e) {
-            LOG.error("*********************************" + request);
+            // log at error level as we are returning a marshalling
+            // error to the user
+            LOG.error("Failed to process " + request, e);
+            
             StringBuffer sb = new StringBuffer();
             ByteBuffer bb = request.request;
-            if(bb!=null){
+            if(bb != null){
                 bb.rewind();
                 while (bb.hasRemaining()) {
                     sb.append(Integer.toHexString(bb.get() & 0xff));
                 }
-            }else
+            } else {
                 sb.append("request buffer is null");
-            LOG.error(sb.toString());
-            LOG.error("Unexpected exception", e);
+            }
+            
+            LOG.error("Dumping request buffer: 0x" + sb.toString());
             if (txnHeader != null) {
                 txnHeader.setType(OpCode.error);
                 txn = new ErrorTxn(Code.MARSHALLINGERROR.intValue());

src/java/main/org/apache/zookeeper/server/SessionTrackerImpl.java

@@ -129,7 +129,7 @@ public class SessionTrackerImpl extends Thread implements SessionTracker {
                 if (set != null) {
                     for (Session s : set.sessions) {
                         sessionsById.remove(s.sessionId);
-                        LOG.warn("Expiring session 0x"
+                        LOG.info("Expiring session 0x"
                                 + Long.toHexString(s.sessionId));
                         expirer.expire(s.sessionId);
                     }
@@ -137,10 +137,9 @@ public class SessionTrackerImpl extends Thread implements SessionTracker {
                 nextExpirationTime += expirationInterval;
             }
         } catch (InterruptedException e) {
-            LOG.error("FIXMSG",e);
+            LOG.error("Unexpected interruption", e);
         }
-        ZooTrace.logTraceMessage(LOG, ZooTrace.getTextTraceLevel(),
-                                 "SessionTrackerImpl exited loop!");
+        LOG.info("SessionTrackerImpl exited loop!");
     }
 
     synchronized public boolean touchSession(long sessionId, int timeout) {

src/java/main/org/apache/zookeeper/server/SyncRequestProcessor.java

@@ -110,15 +110,13 @@ public class SyncRequestProcessor extends Thread implements RequestProcessor {
                     }
                 }
             }
-        } catch (Exception e) {
-            LOG.error("Severe error, exiting",e);
+        } catch (Throwable t) {
+            LOG.fatal("Severe unrecoverable error, exiting", t);
             System.exit(11);
         }
-        ZooTrace.logTraceMessage(LOG, ZooTrace.getTextTraceLevel(),
-                                     "SyncRequestProcessor exited!");
+        LOG.info("SyncRequestProcessor exited!");
     }
 
-    @SuppressWarnings("unchecked")
     private void flush(LinkedList<Request> toFlush) throws IOException {
         if (toFlush.size() == 0)
             return;

src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java

@@ -242,8 +242,7 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
                 }
                 baos.close();
             } catch (IOException e) {
-                // This really should be impossible
-                LOG.error("FIXMSG",e);
+                LOG.error("This really should be impossible", e);
             }
             QuorumPacket pp = new QuorumPacket(Leader.PROPOSAL, request.zxid,
                     baos.toByteArray(), null);
@@ -259,7 +258,7 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
         try {
             txnLogFactory.save(dataTree, sessionsWithTimeouts);
         } catch (IOException e) {
-            LOG.error("Severe error, exiting",e);
+            LOG.fatal("Severe unrecoverable error, exiting", e);
             // This is a severe error that we cannot recover from,
             // so we need to exit
             System.exit(10);
@@ -293,13 +292,16 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
         return System.currentTimeMillis();
     }
 
-    public void closeSession(long sessionId) throws InterruptedException {
-        ZooTrace.logTraceMessage(LOG, ZooTrace.SESSION_TRACE_MASK,
-                                 "ZooKeeperServer --- Session to be closed: 0x"
-                + Long.toHexString(sessionId));
+    private void close(long sessionId) {
+        submitRequest(null, sessionId, OpCode.closeSession, 0, null, null);
+    }
+    
+    public void closeSession(long sessionId) {
+        LOG.info("Closing session 0x" + Long.toHexString(sessionId));
+        
         // we do not want to wait for a session close. send it as soon as we
         // detect it!
-        submitRequest(null, sessionId, OpCode.closeSession, 0, null, null);
+        close(sessionId);
     }
 
     protected void killSession(long sessionId, long zxid) {
@@ -313,15 +315,8 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
     }
 
     public void expire(long sessionId) {
-        try {
-            ZooTrace.logTraceMessage(LOG,
-                     ZooTrace.SESSION_TRACE_MASK,
-                    "ZooKeeperServer --- Session to expire: 0x" 
-                     + Long.toHexString(sessionId));
-            closeSession(sessionId);
-        } catch (Exception e) {
-            LOG.error("FIXMSG",e);
-        }
+        LOG.info("Expiring session 0x" + Long.toHexString(sessionId));
+        close(sessionId);
     }
 
     void touch(ServerCnxn cnxn) throws IOException {
@@ -502,8 +497,7 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
         }
     }
 
-    public void closeSession(ServerCnxn cnxn, RequestHeader requestHeader)
-            throws InterruptedException {
+    public void closeSession(ServerCnxn cnxn, RequestHeader requestHeader) {
         closeSession(cnxn.getSessionId());
     }
 
@@ -531,7 +525,7 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
                         wait(1000);
                     }
                 } catch (InterruptedException e) {
-                    LOG.error("FIXMSG",e);
+                    LOG.warn("Unexpected interruption", e);
                 }
                 if (firstProcessor == null) {
                     throw new RuntimeException("Not started");
@@ -548,10 +542,10 @@ public class ZooKeeperServer implements SessionExpirer, ServerStats.Provider {
                 }
             } else {
                 LOG.warn("Dropping packet at server of type " + si.type);
-                // if unvalid packet drop the packet.
+                // if invalid packet drop the packet.
             }
         } catch (IOException e) {
-            LOG.error("FIXMSG",e);
+            LOG.warn("Ignoring unexpected exception", e);
         }
     }
 

src/java/main/org/apache/zookeeper/server/quorum/AuthFastLeaderElection.java

@@ -234,7 +234,7 @@ public class AuthFastLeaderElection implements Election {
                         responseBuffer.clear();
                         mySocket.receive(responsePacket);
                     } catch (IOException e) {
-                        LOG.warn("Exception receiving: " + e.toString());
+                        LOG.warn("Ignoring exception receiving", e);
                     }
                     // Receive new message
                     if (responsePacket.getLength() != responseBytes.length) {
@@ -370,7 +370,7 @@ public class AuthFastLeaderElection implements Election {
                         break;
                     // Default case
                     default:
-                        LOG.warn("Received message of incorrect type");
+                        LOG.warn("Received message of incorrect type " + type);
                         break;
                     }
                 }
@@ -459,8 +459,7 @@ public class AuthFastLeaderElection implements Election {
                             mySocket.send(requestPacket);
                         }
                     } catch (IOException e) {
-                        LOG.warn("Exception while sending challenge: "
-                                + e.toString());
+                        LOG.warn("Exception while sending challenge: ", e);
                     }
 
                     break;
@@ -492,8 +491,7 @@ public class AuthFastLeaderElection implements Election {
                     try {
                         mySocket.send(requestPacket);
                     } catch (IOException e) {
-                        LOG.warn("Exception while sending challenge: "
-                                + e.toString());
+                        LOG.warn("Exception while sending challenge: ", e);
                     }
 
                     break;
@@ -545,8 +543,7 @@ public class AuthFastLeaderElection implements Election {
                                                 .containsKey(m.tag);
                                     }
                                 } catch (InterruptedException e) {
-                                    LOG.warn("Challenge request exception: "
-                                                    + e.toString());
+                                    LOG.warn("Challenge request exception: ", e);
                                 } 
                             }
 
@@ -574,8 +571,7 @@ public class AuthFastLeaderElection implements Election {
                                     l.wait((int) timeout);
                                 }
                             } catch (InterruptedException e) {
-                                LOG.warn("Ack exception: "
-                                                + e.toString());
+                                LOG.warn("Ack exception: ", e);
                             }
                             synchronized (acksqueue) {
                                 for (int i = 0; i < acksqueue.size(); ++i) {
@@ -598,8 +594,7 @@ public class AuthFastLeaderElection implements Election {
                                 }
                             }
                         } catch (IOException e) {
-                            LOG.warn("Sending exception: "
-                                            + e.toString());
+                            LOG.warn("Sending exception: ", e);
                             /*
                              * Do nothing, just try again
                              */
@@ -639,8 +634,7 @@ public class AuthFastLeaderElection implements Election {
                     try {
                         mySocket.send(requestPacket);
                     } catch (IOException e) {
-                        LOG.warn("Exception while sending ack: "
-                                + e.toString());
+                        LOG.warn("Exception while sending ack: ", e);
                     }
                     break;
                 }
@@ -781,7 +775,7 @@ public class AuthFastLeaderElection implements Election {
         proposedLeader = self.getId();
         proposedZxid = self.getLastLoggedZxid();
 
-        LOG.warn("Election tally");
+        LOG.info("Election tally");
         sendNotifications();
 
         /*
@@ -838,7 +832,7 @@ public class AuthFastLeaderElection implements Election {
                     } else if (termPredicate(recvset, proposedLeader,
                             proposedZxid)) {
                         // Otherwise, wait for a fixed amount of time
-                        LOG.warn("Passed predicate");
+                        LOG.info("Passed predicate");
                         Thread.sleep(finalizeWait);
 
                         // Notification probe = recvqueue.peek();

src/java/main/org/apache/zookeeper/server/quorum/CommitProcessor.java

@@ -144,10 +144,9 @@ public class CommitProcessor extends Thread implements RequestProcessor {
                 }
             }
         } catch (Exception e) {
-            LOG.error("FIXMSG",e);
+            LOG.error("Unexpected exception causing exit", e);
         }
-        ZooTrace.logTraceMessage(LOG, ZooTrace.getTextTraceLevel(),
-                                 "CommitProcessor exited loop!");
+        LOG.info("CommitProcessor exited loop!");
     }
 
     synchronized public void commit(Request request) {

src/java/main/org/apache/zookeeper/server/quorum/FastLeaderElection.java

@@ -514,7 +514,7 @@ public class FastLeaderElection implements Election {
             updateProposal(self.getId(), self.getLastLoggedZxid());
         }
         
-        LOG.warn("New election: " + proposedZxid);
+        LOG.info("New election: " + proposedZxid);
         sendNotifications();
 
         /*

src/java/main/org/apache/zookeeper/server/quorum/Follower.java

@@ -154,7 +154,7 @@ public class Follower {
                             LOG.error("Unexpected exception",e);
                             throw e;
                         } else {
-                            LOG.warn("Unexpected exception",e);
+                            LOG.warn("Unexpected exception, tries="+tries,e);
                             sock = new Socket();
                             sock.setSoTimeout(self.tickTime * self.initLimit);
                         }
@@ -199,7 +199,7 @@ public class Follower {
                         boolean truncated=zk.getLogWriter().truncateLog(qp.getZxid());
                         if (!truncated) {
                             // not able to truncate the log
-                            LOG.error("Not able to truncate the log "
+                            LOG.fatal("Not able to truncate the log "
                                     + Long.toHexString(qp.getZxid()));
                             System.exit(13);
                         }
@@ -207,7 +207,7 @@ public class Follower {
                         zk.loadData();
                     }
                     else {
-                        LOG.error("Got unexpected packet from leader "
+                        LOG.fatal("Got unexpected packet from leader "
                                 + qp.getType() + " exiting ... " );
                         System.exit(13);
                     }
@@ -398,6 +398,6 @@ public class Follower {
             zk.shutdown();
 
         }
-        LOG.error("FIXMSG",new Exception("shutdown Follower"));
+        LOG.info("shutdown called", new Exception("shutdown Follower"));
     }
 }

src/java/main/org/apache/zookeeper/server/quorum/FollowerHandler.java

@@ -280,7 +280,7 @@ public class FollowerHandler extends Thread {
                     try {
                         sendPackets();
                     } catch (InterruptedException e) {
-                        LOG.warn("Interrupted",e);
+                        LOG.warn("Unexpected interruption",e);
                     }
                 }
             }.start();
@@ -353,10 +353,11 @@ public class FollowerHandler extends Thread {
             }
         } catch (IOException e) {
             if (sock != null && !sock.isClosed()) {
-                LOG.error("FIXMSG",e);
+                LOG.error("Unexpected exception causing shutdown while sock "
+                        + "still open", e);
             }
         } catch (InterruptedException e) {
-            LOG.error("FIXMSG",e);
+            LOG.error("Unexpected exception causing shutdown", e);
         } finally {
             LOG.warn("******* GOODBYE " 
                     + (sock != null ? sock.getRemoteSocketAddress() : "<null>")
@@ -365,7 +366,7 @@ public class FollowerHandler extends Thread {
             try {
                 queuedPackets.put(proposalOfDeath);
             } catch (InterruptedException e) {
-                LOG.error("FIXMSG",e);
+                LOG.warn("Ignoring unexpected exception", e);
             }
             shutdown();
         }
@@ -377,7 +378,7 @@ public class FollowerHandler extends Thread {
                 sock.close();
             }
         } catch (IOException e) {
-            LOG.error("FIXMSG",e);
+            LOG.warn("Ignoring unexpected exception during socket close", e);
         }
         leader.removeFollowerHandler(this);
     }

src/java/main/org/apache/zookeeper/server/quorum/FollowerRequestProcessor.java

@@ -85,10 +85,9 @@ public class FollowerRequestProcessor extends Thread implements
                 }
             }
         } catch (Exception e) {
-            LOG.error("FIXMSG",e);
+            LOG.error("Unexpected exception causing exit", e);
         }
-        ZooTrace.logTraceMessage(LOG, ZooTrace.getTextTraceLevel(),
-                                 "FollowerRequestProcessor exited loop!");
+        LOG.info("FollowerRequestProcessor exited loop!");
     }
 
     public void processRequest(Request request) {

src/java/main/org/apache/zookeeper/server/quorum/FollowerZooKeeperServer.java

@@ -129,7 +129,7 @@ public class FollowerZooKeeperServer extends ZooKeeperServer {
         }
         long firstElementZxid = pendingTxns.element().zxid;
         if (firstElementZxid != zxid) {
-            LOG.error("Committing zxid 0x" + Long.toHexString(zxid)
+            LOG.fatal("Committing zxid 0x" + Long.toHexString(zxid)
                     + " but next pending txn 0x"
                     + Long.toHexString(firstElementZxid));
             System.exit(12);
@@ -166,14 +166,15 @@ public class FollowerZooKeeperServer extends ZooKeeperServer {
         try {
             super.shutdown();
         } catch (Exception e) {
-            LOG.error("FIXMSG",e);
+            LOG.warn("Ignoring unexpected exception during shutdown", e);
         }
         try {
             if (syncProcessor != null) {
                 syncProcessor.shutdown();
             }
         } catch (Exception e) {
-            LOG.error("FIXMSG",e);
+            LOG.warn("Ignoring unexpected exception in syncprocessor shutdown",
+                    e);
         }
     }
 

src/java/main/org/apache/zookeeper/server/quorum/Leader.java

@@ -113,7 +113,7 @@ public class Leader {
             ss = new ServerSocket(self.getQuorumAddress().getPort());
         } catch (BindException e) {
             LOG.error("Couldn't bind to port "
-                    + self.getQuorumAddress().getPort());
+                    + self.getQuorumAddress().getPort(), e);
             throw e;
         }
         this.zk=zk;
@@ -254,8 +254,8 @@ public class Leader {
             newLeaderProposal.packet = new QuorumPacket(NEWLEADER, zk.getZxid(),
                     null, null);
             if ((newLeaderProposal.packet.getZxid() & 0xffffffffL) != 0) {
-                LOG.warn("NEWLEADER proposal has Zxid of "
-                        + newLeaderProposal.packet.getZxid());
+                LOG.info("NEWLEADER proposal has Zxid of "
+                        + Long.toHexString(newLeaderProposal.packet.getZxid()));
             }
             outstandingProposals.add(newLeaderProposal);
             
@@ -354,7 +354,7 @@ public class Leader {
         try {
             ss.close();
         } catch (IOException e) {
-            LOG.error("FIXMSG",e);
+            LOG.warn("Ignoring unexpected exception during close",e);
         }
         synchronized (followers) {
             for (Iterator<FollowerHandler> it = followers.iterator(); it

src/java/main/org/apache/zookeeper/server/quorum/LeaderElection.java

@@ -97,13 +97,13 @@ public class LeaderElection implements Election  {
             }
         }
         result.winningCount = 0;
-        LOG.warn("Election tally: ");
+        LOG.info("Election tally: ");
         for (Entry<Vote, Integer> entry : countTable.entrySet()) {
             if (entry.getValue() > result.winningCount) {
                 result.winningCount = entry.getValue();
                 result.winner = entry.getKey();
             }
-            LOG.warn(entry.getKey().id + "\t-> " + entry.getValue());
+            LOG.info(entry.getKey().id + "\t-> " + entry.getValue());
         }
         return result;
     }
@@ -139,7 +139,7 @@ public class LeaderElection implements Election  {
             HashSet<Long> heardFrom = new HashSet<Long>();
             for (QuorumServer server : self.quorumPeers.values()) {
                 requestPacket.setSocketAddress(server.addr);
-                LOG.warn("Server address: " + server.addr);
+                LOG.info("Server address: " + server.addr);
                 try {
                     s.send(requestPacket);
                     responsePacket.setLength(responseBytes.length);
@@ -166,10 +166,9 @@ public class LeaderElection implements Election  {
                         votes.put(addr, vote);
                     //}
                 } catch (IOException e) {
-                    LOG.error("Error in looking for leader", e);
+                    LOG.warn("Ignoring exception while looking for leader", e);
                     // Errors are okay, since hosts may be
                     // down
-                    // ZooKeeperServer.logException(e);
                 }
             }
             ElectionResult result = countVotes(votes, heardFrom);

src/java/main/org/apache/zookeeper/server/quorum/QuorumCnxManager.java

@@ -21,14 +21,15 @@ package org.apache.zookeeper.server.quorum;
 import java.io.IOException;
 import java.net.InetAddress;
 import java.net.InetSocketAddress;
+import java.net.Socket;
 import java.net.UnknownHostException;
 import java.nio.ByteBuffer;
 import java.nio.channels.ServerSocketChannel;
 import java.nio.channels.SocketChannel;
+import java.util.Enumeration;
 import java.util.Random;
 import java.util.concurrent.ArrayBlockingQueue;
 import java.util.concurrent.ConcurrentHashMap;
-import java.util.Enumeration;
 
 import org.apache.log4j.Logger;
 
@@ -160,8 +161,7 @@ public class QuorumCnxManager {
             msgBuffer.position(0);
             s.write(msgBuffer);
         } catch (IOException e) {
-            LOG.warn("Exception reading or writing challenge: "
-                    + e.toString());
+            LOG.warn("Exception reading or writing challenge: ", e);
             return false;
         }
         
@@ -172,9 +172,8 @@ public class QuorumCnxManager {
                         sid + ", " + self.getId() + ")");
                 s.socket().close();
             } catch (IOException e) {
-                LOG.error("Error when closing socket or trying to reopen connection: "
-                                + e.toString());
-
+                LOG.warn("Ignoring exception when closing socket or trying to "
+                        + "reopen connection: ", e);
             }
         // Otherwise proceed with the connection
         } else {
@@ -294,7 +293,7 @@ public class QuorumCnxManager {
                 b.position(0);
                 recvQueue.put(new Message(b.duplicate(), sid));
             } catch (InterruptedException e) {
-                LOG.warn("Exception when loopbacking");
+                LOG.warn("Exception when loopbacking", e);
             }
         /*
          * Otherwise send to the corresponding thread to send. 
@@ -319,8 +318,8 @@ public class QuorumCnxManager {
                 connectOne(sid);
                 
             } catch (InterruptedException e) {
-                LOG.warn("Interrupted while waiting to put message in queue."
-                                + e.toString());
+                LOG.warn("Interrupted while waiting to put message in queue.",
+                        e);
             }
     }
     
@@ -339,9 +338,7 @@ public class QuorumCnxManager {
                 channel.socket().setTcpNoDelay(true);
                 initiateConnection(channel, sid);
             } catch (IOException e) {
-                LOG.warn("Cannot open channel to "
-                        + sid + "( " + e.toString()
-                        + ")");
+                LOG.warn("Cannot open channel to " + sid, e);
             }
         }
     }
@@ -379,11 +376,11 @@ public class QuorumCnxManager {
      */
     public void halt() {
         shutdown = true;
-        LOG.warn("Halting listener");
+        LOG.info("Halting listener");
         listener.halt();
         
         for(SendWorker sw: senderWorkerMap.values()){
-            LOG.warn("Halting sender: " + sw);
+            LOG.info("Halting sender: " + sw);
             sw.finish();
         }
     }
@@ -403,17 +400,17 @@ public class QuorumCnxManager {
             try {
                 ss = ServerSocketChannel.open();
                 int port = self.quorumPeers.get(self.getId()).electionAddr.getPort();
-                LOG.warn("My election bind port: " + port);
+                LOG.info("My election bind port: " + port);
                 ss.socket().bind(new InetSocketAddress(port));
 
                 while (!shutdown) {
                     SocketChannel client = ss.accept();
-                    client.socket().setTcpNoDelay(true);
+                    Socket sock = client.socket();
+                    sock.setTcpNoDelay(true);
                     
-                    //synchronized(senderWorkerMap){
-                    LOG.warn("Connection request");
+                    LOG.info("Connection request "
+                            + sock.getRemoteSocketAddress());
                     receiveConnection(client);
-                    //}
                 }
             } catch (IOException e) {
                 System.err.println("Listener.run: " + e.getMessage());
@@ -434,7 +431,6 @@ public class QuorumCnxManager {
      * soon as there is one available. If connection breaks, then opens a new
      * one.
      */
-
     class SendWorker extends Thread {
         // Send msgs to peer
         Long sid;
@@ -473,8 +469,8 @@ public class QuorumCnxManager {
                 try {
                     b = queueSendMap.get(sid).take();
                 } catch (InterruptedException e) {
-                    LOG.warn("Interrupted while waiting for message on queue ("
-                                    + e.toString() + ")");
+                    LOG.warn("Interrupted while waiting for message on queue",
+                            e);
                     continue;
                 }
 
@@ -493,8 +489,7 @@ public class QuorumCnxManager {
                      * If reconnection doesn't work, then put the
                      * message back to the beginning of the queue and leave.
                      */
-                    LOG.warn("Exception when using channel: " + sid
-                            + ")" + e.toString());
+                    LOG.warn("Exception when using channel: " + sid, e);
                     running = false;
                     synchronized (senderWorkerMap) {
                         recvWorker.finish();
@@ -509,7 +504,7 @@ public class QuorumCnxManager {
                     }
                 }
             }
-            LOG.warn("Leaving thread");
+            LOG.warn("Send worker leaving thread");
         }
     }
 
@@ -569,12 +564,11 @@ public class QuorumCnxManager {
                 }
 
             } catch (IOException e) {
-                LOG.warn("Connection broken: " + e.toString());
+                LOG.warn("Connection broken: ", e);
 
             } catch (InterruptedException e) {
                 LOG.warn("Interrupted while trying to add new "
-                        + "message to the reception queue (" + e.toString()
-                        + ")");
+                        + "message to the reception queue", e);
             }
         }
     }

src/java/main/org/apache/zookeeper/server/quorum/QuorumPeerConfig.java

@@ -96,9 +96,8 @@ public class QuorumPeerConfig extends ServerConfig {
                 long sid = Long.parseLong(key.substring(dot + 1));
                 String parts[] = value.split(":");
                 if ((parts.length != 2) && (parts.length != 3)) {
-                    LOG
-                            .error(value
-                                    + " does not have the form host:port or host:port:port");
+                    LOG.error(value
+                       + " does not have the form host:port or host:port:port");
                 }
                 InetSocketAddress addr = new InetSocketAddress(parts[0],
                         Integer.parseInt(parts[1]));

src/java/main/org/apache/zookeeper/server/quorum/SendAckRequestProcessor.java

@@ -42,7 +42,7 @@ public class SendAckRequestProcessor implements RequestProcessor {
             try {
                 follower.writePacket(qp);
             } catch (IOException e) {
-                LOG.error("FIXMSG",e);
+                LOG.warn("Ignoring unexpected exception during packet send", e);
             }
         }
     }

src/java/main/org/apache/zookeeper/server/upgrade/DataTreeV1.java

@@ -33,15 +33,15 @@ import org.apache.jute.Record;
 import org.apache.log4j.Logger;
 import org.apache.zookeeper.KeeperException;
 import org.apache.zookeeper.Watcher;
-import org.apache.zookeeper.Watcher.Event.EventType;
 import org.apache.zookeeper.KeeperException.Code;
+import org.apache.zookeeper.KeeperException.NoNodeException;
 import org.apache.zookeeper.Watcher.Event;
+import org.apache.zookeeper.Watcher.Event.EventType;
 import org.apache.zookeeper.ZooDefs.OpCode;
 import org.apache.zookeeper.data.ACL;
 import org.apache.zookeeper.data.Stat;
 import org.apache.zookeeper.data.StatPersistedV1;
 import org.apache.zookeeper.server.WatchManager;
-import org.apache.zookeeper.server.ZooTrace;
 import org.apache.zookeeper.txn.CreateTxn;
 import org.apache.zookeeper.txn.DeleteTxn;
 import org.apache.zookeeper.txn.ErrorTxn;
@@ -76,9 +76,6 @@ public class DataTreeV1 {
      */
     private Map<Long, HashSet<String>> ephemerals = new ConcurrentHashMap<Long, HashSet<String>>();
 
-    /** A debug string * */
-    private String debug = "debug";
-    
     /**
      * return the ephemerals for this tree
      * @return the ephemerals for this tree
@@ -391,6 +388,7 @@ public class DataTreeV1 {
     public ProcessTxnResult processTxn(TxnHeader header, Record txn) {
         ProcessTxnResult rc = new ProcessTxnResult();
 
+        String debug = "";
         try {
             rc.clientId = header.getClientId();
             rc.cxid = header.getCxid();
@@ -423,6 +421,7 @@ public class DataTreeV1 {
                 break;
             case OpCode.setACL:
                 SetACLTxn setACLTxn = (SetACLTxn) txn;
+                debug = "Set ACL for  transaction for " + setACLTxn.getPath();
                 rc.stat = setACL(setACLTxn.getPath(), setACLTxn.getAcl(),
                         setACLTxn.getVersion());
                 break;
@@ -439,8 +438,7 @@ public class DataTreeV1 {
             if (initialized
                     || (e.code() != Code.NONODE 
                             && e.code() != Code.NODEEXISTS)) {
-                LOG.warn(debug);
-                LOG.error("FIXMSG",e);
+                LOG.warn("Failed:" + debug, e);
             }
         }
         return rc;
@@ -458,13 +456,15 @@ public class DataTreeV1 {
             for (String path : list) {
                 try {
                     deleteNode(path);
-                    ZooTrace.logTraceMessage(LOG,
-                                             ZooTrace.SESSION_TRACE_MASK,
-                                             "Deleting ephemeral node "
-                                             + path + " for session 0x"
-                                             + Long.toHexString(session));
-                } catch (KeeperException e) {
-                    LOG.error("FIXMSG",e);
+                    if (LOG.isDebugEnabled()) {
+                        LOG.debug("Deleting ephemeral node " + path
+                                + " for session 0x"
+                                + Long.toHexString(session));
+                    }
+                } catch (NoNodeException e) {
+                    LOG.warn("Ignoring NoNodeException for path " + path
+                            + " while removing ephemeral for dead session 0x"
+                            + Long.toHexString(session));
                 }
             }
         }

src/java/main/org/apache/zookeeper/server/upgrade/UpgradeSnapShotV1.java

@@ -118,7 +118,7 @@ public class UpgradeSnapShotV1 implements UpgradeSnapShot {
                 Record txn = SerializeUtils.deserializeTxn(ia, hdr);
                 if (logStream.readByte("EOR") != 'B') {
                     LOG.warn("Last transaction was partial.");
-                    throw new EOFException();
+                    throw new EOFException("Last transaction was partial.");
                 }
                 if (hdr.getZxid() <= highestZxid && highestZxid != 0) {
                     LOG.error(highestZxid + "(higestZxid) >= "
@@ -175,7 +175,7 @@ public class UpgradeSnapShotV1 implements UpgradeSnapShot {
             File[] logFiles) throws IOException {
         long zxid = 0;
         for (File f: logFiles) { 
-            LOG.warn("Processing log file: " + f);
+            LOG.info("Processing log file: " + f);
             InputStream logIs = 
                 new BufferedInputStream(new FileInputStream(f));
             zxid = playLog(BinaryInputArchive.getArchive(logIs));

src/java/main/org/apache/zookeeper/server/util/Profiler.java

@@ -33,7 +33,7 @@ public class Profiler {
         T res = op.execute();
         long end = System.currentTimeMillis();
         if (end - start > timeout) {
-            LOG.warn("Elapsed "+(end - start) + " ms: " + message);
+            LOG.info("Elapsed "+(end - start) + " ms: " + message);
         }
         return res;
     }