Return-Path: Delivered-To: apmail-hadoop-zookeeper-commits-archive@locus.apache.org Received: (qmail 34454 invoked from network); 15 Jan 2009 23:49:03 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.2) by minotaur.apache.org with SMTP; 15 Jan 2009 23:49:03 -0000 Received: (qmail 61281 invoked by uid 500); 15 Jan 2009 23:49:02 -0000 Delivered-To: apmail-hadoop-zookeeper-commits-archive@hadoop.apache.org Received: (qmail 61264 invoked by uid 500); 15 Jan 2009 23:49:02 -0000 Mailing-List: contact zookeeper-commits-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: zookeeper-dev@ Delivered-To: mailing list zookeeper-commits@hadoop.apache.org Received: (qmail 61253 invoked by uid 99); 15 Jan 2009 23:49:02 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 15 Jan 2009 15:49:02 -0800 X-ASF-Spam-Status: No, hits=-2000.0 required=10.0 tests=ALL_TRUSTED X-Spam-Check-By: apache.org Received: from [140.211.11.4] (HELO eris.apache.org) (140.211.11.4) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 15 Jan 2009 23:48:47 +0000 Received: by eris.apache.org (Postfix, from userid 65534) id 1C63F2388A30; Thu, 15 Jan 2009 15:48:26 -0800 (PST) Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Subject: svn commit: r734857 - in /hadoop/zookeeper/trunk: ./ src/c/src/ src/java/main/org/apache/zookeeper/ src/java/main/org/apache/zookeeper/server/ src/java/main/org/apache/zookeeper/server/quorum/ src/java/main/org/apache/zookeeper/server/upgrade/ src/java... Date: Thu, 15 Jan 2009 23:48:24 -0000 To: zookeeper-commits@hadoop.apache.org From: breed@apache.org X-Mailer: svnmailer-1.0.8 Message-Id: <20090115234826.1C63F2388A30@eris.apache.org> X-Virus-Checked: Checked by ClamAV on apache.org Author: breed Date: Thu Jan 15 15:48:24 2009 New Revision: 734857 URL: http://svn.apache.org/viewvc?rev=734857&view=rev Log: ZOOKEEPER-259. cleanup the logging levels used (use the correct level) and messages generated. (phunt via breed) Modified: hadoop/zookeeper/trunk/CHANGES.txt hadoop/zookeeper/trunk/src/c/src/zk_adaptor.h hadoop/zookeeper/trunk/src/c/src/zookeeper.c hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ClientCnxn.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ZooKeeper.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/DataTree.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/FinalRequestProcessor.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/LogFormatter.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SessionTrackerImpl.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SyncRequestProcessor.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/AuthFastLeaderElection.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/CommitProcessor.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FastLeaderElection.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Follower.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerHandler.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerRequestProcessor.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerZooKeeperServer.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Leader.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/LeaderElection.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumCnxManager.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumPeerConfig.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/SendAckRequestProcessor.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/DataTreeV1.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/UpgradeSnapShotV1.java hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/util/Profiler.java Modified: hadoop/zookeeper/trunk/CHANGES.txt URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/CHANGES.txt?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/CHANGES.txt (original) +++ hadoop/zookeeper/trunk/CHANGES.txt Thu Jan 15 15:48:24 2009 @@ -105,6 +105,8 @@ 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 Modified: hadoop/zookeeper/trunk/src/c/src/zk_adaptor.h URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/c/src/zk_adaptor.h?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/c/src/zk_adaptor.h (original) +++ hadoop/zookeeper/trunk/src/c/src/zk_adaptor.h Thu Jan 15 15:48:24 2009 @@ -166,6 +166,7 @@ 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 */ Modified: hadoop/zookeeper/trunk/src/c/src/zookeeper.c URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/c/src/zookeeper.c?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/c/src/zookeeper.c (original) +++ hadoop/zookeeper/trunk/src/c/src/zookeeper.c Thu Jan 15 15:48:24 2009 @@ -1060,6 +1060,7 @@ 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 @@ *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 @@ // 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 @@ 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 @@ 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 @@ 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 @@ 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 @@ } 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 @@ } 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 @@ } 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 @@ } 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 @@ } 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); Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ClientCnxn.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ClientCnxn.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ClientCnxn.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ClientCnxn.java Thu Jan 15 15:48:24 2009 @@ -211,7 +211,7 @@ 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 @@ } } } 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 @@ boolean initialized; + private long lastPingSentNs; + void readLength() throws IOException { int len = incomingBuffer.getInt(); if (len < 0 || len >= 4096 * 1024) { @@ -524,16 +526,19 @@ 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 @@ } private void sendPing() { + lastPingSentNs = System.nanoTime(); RequestHeader h = new RequestHeader(-2, OpCode.ping); queuePacket(h, null, null, null, null, null, null, null); } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ZooKeeper.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ZooKeeper.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ZooKeeper.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/ZooKeeper.java Thu Jan 15 15:48:24 2009 @@ -420,7 +420,7 @@ 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"); Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/DataTree.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/DataTree.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/DataTree.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/DataTree.java Thu Jan 15 15:48:24 2009 @@ -37,6 +37,7 @@ 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.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 @@ */ protected long aclIndex = 0; - /** A debug string * */ - private String debug = "debug"; - @SuppressWarnings("unchecked") public HashSet getEphemerals(long sessionId) { HashSet retv = ephemerals.get(sessionId); @@ -521,10 +520,10 @@ 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 @@ 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 @@ 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 @@ 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 list = ephemerals.remove(session); @@ -592,13 +591,15 @@ 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)); } } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/FinalRequestProcessor.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/FinalRequestProcessor.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/FinalRequestProcessor.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/FinalRequestProcessor.java Thu Jan 15 15:48:24 2009 @@ -238,15 +238,16 @@ } 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 = Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/LogFormatter.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/LogFormatter.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/LogFormatter.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/LogFormatter.java Thu Jan 15 15:48:24 2009 @@ -65,7 +65,7 @@ + " " + 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."); } } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java Thu Jan 15 15:48:24 2009 @@ -164,14 +164,11 @@ } 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 @@ 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 @@ 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 @@ 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 @@ } } } 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 @@ 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 @@ .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 @@ 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 @@ 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 @@ 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 @@ 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 @@ enableRecv(); } } catch (Exception e) { - LOG.error("FIXMSG",e); + LOG.warn("Exception while establishing session, closing", e); close(); } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/PrepRequestProcessor.java Thu Jan 15 15:48:24 2009 @@ -99,10 +99,9 @@ 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 @@ 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()); Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SessionTrackerImpl.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SessionTrackerImpl.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SessionTrackerImpl.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SessionTrackerImpl.java Thu Jan 15 15:48:24 2009 @@ -129,7 +129,7 @@ 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 @@ 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) { Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SyncRequestProcessor.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SyncRequestProcessor.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SyncRequestProcessor.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/SyncRequestProcessor.java Thu Jan 15 15:48:24 2009 @@ -110,15 +110,13 @@ } } } - } 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 toFlush) throws IOException { if (toFlush.size() == 0) return; Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/ZooKeeperServer.java Thu Jan 15 15:48:24 2009 @@ -242,8 +242,7 @@ } 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 @@ 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 @@ 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 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 void closeSession(ServerCnxn cnxn, RequestHeader requestHeader) - throws InterruptedException { + public void closeSession(ServerCnxn cnxn, RequestHeader requestHeader) { closeSession(cnxn.getSessionId()); } @@ -531,7 +525,7 @@ 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 @@ } } 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); } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/AuthFastLeaderElection.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/AuthFastLeaderElection.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/AuthFastLeaderElection.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/AuthFastLeaderElection.java Thu Jan 15 15:48:24 2009 @@ -234,7 +234,7 @@ 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 @@ break; // Default case default: - LOG.warn("Received message of incorrect type"); + LOG.warn("Received message of incorrect type " + type); break; } } @@ -459,8 +459,7 @@ 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 @@ 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 @@ .containsKey(m.tag); } } catch (InterruptedException e) { - LOG.warn("Challenge request exception: " - + e.toString()); + LOG.warn("Challenge request exception: ", e); } } @@ -574,8 +571,7 @@ 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 @@ } } } catch (IOException e) { - LOG.warn("Sending exception: " - + e.toString()); + LOG.warn("Sending exception: ", e); /* * Do nothing, just try again */ @@ -639,8 +634,7 @@ 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 @@ proposedLeader = self.getId(); proposedZxid = self.getLastLoggedZxid(); - LOG.warn("Election tally"); + LOG.info("Election tally"); sendNotifications(); /* @@ -838,7 +832,7 @@ } 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(); Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/CommitProcessor.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/CommitProcessor.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/CommitProcessor.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/CommitProcessor.java Thu Jan 15 15:48:24 2009 @@ -144,10 +144,9 @@ } } } 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) { Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FastLeaderElection.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FastLeaderElection.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FastLeaderElection.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FastLeaderElection.java Thu Jan 15 15:48:24 2009 @@ -514,7 +514,7 @@ updateProposal(self.getId(), self.getLastLoggedZxid()); } - LOG.warn("New election: " + proposedZxid); + LOG.info("New election: " + proposedZxid); sendNotifications(); /* Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Follower.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Follower.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Follower.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Follower.java Thu Jan 15 15:48:24 2009 @@ -154,7 +154,7 @@ 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 @@ 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 @@ 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 @@ zk.shutdown(); } - LOG.error("FIXMSG",new Exception("shutdown Follower")); + LOG.info("shutdown called", new Exception("shutdown Follower")); } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerHandler.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerHandler.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerHandler.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerHandler.java Thu Jan 15 15:48:24 2009 @@ -280,7 +280,7 @@ try { sendPackets(); } catch (InterruptedException e) { - LOG.warn("Interrupted",e); + LOG.warn("Unexpected interruption",e); } } }.start(); @@ -353,10 +353,11 @@ } } 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() : "") @@ -365,7 +366,7 @@ try { queuedPackets.put(proposalOfDeath); } catch (InterruptedException e) { - LOG.error("FIXMSG",e); + LOG.warn("Ignoring unexpected exception", e); } shutdown(); } @@ -377,7 +378,7 @@ sock.close(); } } catch (IOException e) { - LOG.error("FIXMSG",e); + LOG.warn("Ignoring unexpected exception during socket close", e); } leader.removeFollowerHandler(this); } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerRequestProcessor.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerRequestProcessor.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerRequestProcessor.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerRequestProcessor.java Thu Jan 15 15:48:24 2009 @@ -85,10 +85,9 @@ } } } 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) { Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerZooKeeperServer.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerZooKeeperServer.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerZooKeeperServer.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/FollowerZooKeeperServer.java Thu Jan 15 15:48:24 2009 @@ -129,7 +129,7 @@ } 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 @@ 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); } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Leader.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Leader.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Leader.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/Leader.java Thu Jan 15 15:48:24 2009 @@ -113,7 +113,7 @@ 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 @@ 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 @@ try { ss.close(); } catch (IOException e) { - LOG.error("FIXMSG",e); + LOG.warn("Ignoring unexpected exception during close",e); } synchronized (followers) { for (Iterator it = followers.iterator(); it Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/LeaderElection.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/LeaderElection.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/LeaderElection.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/LeaderElection.java Thu Jan 15 15:48:24 2009 @@ -97,13 +97,13 @@ } } result.winningCount = 0; - LOG.warn("Election tally: "); + LOG.info("Election tally: "); for (Entry 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 @@ HashSet heardFrom = new HashSet(); 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 @@ 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); Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumCnxManager.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumCnxManager.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumCnxManager.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumCnxManager.java Thu Jan 15 15:48:24 2009 @@ -21,14 +21,15 @@ 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 @@ 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 @@ 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 @@ 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 @@ 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 @@ 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 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 @@ 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 @@ * 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 @@ 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 @@ * 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 @@ } } } - LOG.warn("Leaving thread"); + LOG.warn("Send worker leaving thread"); } } @@ -569,12 +564,11 @@ } } 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); } } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumPeerConfig.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumPeerConfig.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumPeerConfig.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/QuorumPeerConfig.java Thu Jan 15 15:48:24 2009 @@ -96,9 +96,8 @@ 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])); Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/SendAckRequestProcessor.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/SendAckRequestProcessor.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/SendAckRequestProcessor.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/quorum/SendAckRequestProcessor.java Thu Jan 15 15:48:24 2009 @@ -42,7 +42,7 @@ try { follower.writePacket(qp); } catch (IOException e) { - LOG.error("FIXMSG",e); + LOG.warn("Ignoring unexpected exception during packet send", e); } } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/DataTreeV1.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/DataTreeV1.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/DataTreeV1.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/DataTreeV1.java Thu Jan 15 15:48:24 2009 @@ -33,15 +33,15 @@ 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 @@ */ private Map> ephemerals = new ConcurrentHashMap>(); - /** A debug string * */ - private String debug = "debug"; - /** * return the ephemerals for this tree * @return the ephemerals for this tree @@ -391,6 +388,7 @@ 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 @@ 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 @@ 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 @@ 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)); } } } Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/UpgradeSnapShotV1.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/UpgradeSnapShotV1.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/UpgradeSnapShotV1.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/upgrade/UpgradeSnapShotV1.java Thu Jan 15 15:48:24 2009 @@ -118,7 +118,7 @@ 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 @@ 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)); Modified: hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/util/Profiler.java URL: http://svn.apache.org/viewvc/hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/util/Profiler.java?rev=734857&r1=734856&r2=734857&view=diff ============================================================================== --- hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/util/Profiler.java (original) +++ hadoop/zookeeper/trunk/src/java/main/org/apache/zookeeper/server/util/Profiler.java Thu Jan 15 15:48:24 2009 @@ -33,7 +33,7 @@ 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; }