Return-Path: X-Original-To: apmail-zookeeper-commits-archive@www.apache.org Delivered-To: apmail-zookeeper-commits-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 6679110265 for ; Tue, 10 Sep 2013 20:13:44 +0000 (UTC) Received: (qmail 3778 invoked by uid 500); 10 Sep 2013 20:13:44 -0000 Delivered-To: apmail-zookeeper-commits-archive@zookeeper.apache.org Received: (qmail 1512 invoked by uid 500); 10 Sep 2013 20:13:39 -0000 Mailing-List: contact commits-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@ Delivered-To: mailing list commits@zookeeper.apache.org Received: (qmail 407 invoked by uid 99); 10 Sep 2013 20:13:37 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 10 Sep 2013 20:13:37 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=5.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; Tue, 10 Sep 2013 20:13:35 +0000 Received: from eris.apache.org (localhost [127.0.0.1]) by eris.apache.org (Postfix) with ESMTP id 89E4723888D7; Tue, 10 Sep 2013 20:13:15 +0000 (UTC) Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Subject: svn commit: r1521624 - in /zookeeper/bookkeeper/branches/branch-4.2: ./ bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/ bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ bookkeeper-server/src/main/java/org/apache/bookkeeper/pr... Date: Tue, 10 Sep 2013 20:13:15 -0000 To: commits@zookeeper.apache.org From: ivank@apache.org X-Mailer: svnmailer-1.0.9 Message-Id: <20130910201315.89E4723888D7@eris.apache.org> X-Virus-Checked: Checked by ClamAV on apache.org Author: ivank Date: Tue Sep 10 20:13:14 2013 New Revision: 1521624 URL: http://svn.apache.org/r1521624 Log: BOOKKEEPER-675: Log noise fixup before cutting 4.2.2 (ivank) Modified: zookeeper/bookkeeper/branches/branch-4.2/CHANGES.txt zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java Modified: zookeeper/bookkeeper/branches/branch-4.2/CHANGES.txt URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/CHANGES.txt?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/CHANGES.txt (original) +++ zookeeper/bookkeeper/branches/branch-4.2/CHANGES.txt Tue Sep 10 20:13:14 2013 @@ -78,6 +78,8 @@ Release 4.2.2 - Unreleased BOOKKEEPER-446: BookKeeper.createLedger(..) should not mask the error with ZKException (sijie via ivank) + BOOKKEEPER-675: Log noise fixup before cutting 4.2.2 (ivank) + hedwig-server: BOOKKEEPER-579: TestSubAfterCloseSub was put in a wrong package (sijie via ivank) Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java Tue Sep 10 20:13:14 2013 @@ -507,7 +507,7 @@ public class Bookie extends Thread { + BookKeeperConstants.INSTANCEID, false, null); instanceId = new String(data); } catch (KeeperException.NoNodeException e) { - LOG.warn("INSTANCEID not exists in zookeeper. Not considering it for data verification"); + LOG.info("INSTANCEID not exists in zookeeper. Not considering it for data verification"); } return instanceId; } @@ -624,6 +624,7 @@ public class Bookie extends Thread { shutdown(ExitCode.BOOKIE_EXCEPTION); return; } + LOG.info("Finished reading journal, starting bookie"); // start bookie thread super.start(); Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java Tue Sep 10 20:13:14 2013 @@ -570,7 +570,7 @@ public class GarbageCollectorThread exte continue; } - LOG.info("Extracting entry log meta from entryLogId: " + entryLogId); + LOG.info("Extracting entry log meta from entryLogId: {}", entryLogId); try { // Read through the entry log file and extract the entry log meta @@ -598,8 +598,8 @@ public class GarbageCollectorThread exte ExtractionScanner scanner = new ExtractionScanner(entryLogMeta); // Read through the entry log file and extract the entry log meta entryLogger.scanEntryLog(entryLogId, scanner); - LOG.info("Retrieved entry log meta data entryLogId: " - + entryLogId + ", meta: " + entryLogMeta); + LOG.debug("Retrieved entry log meta data entryLogId: {}, meta: {}", + entryLogId, entryLogMeta); return entryLogMeta; } } Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java Tue Sep 10 20:13:14 2013 @@ -433,6 +433,7 @@ class Journal extends Thread { if(id == markedLogId) { logPosition = lastLogMark.getTxnLogPosition(); } + LOG.info("Replaying journal {} from position {}", id, logPosition); scanJournal(id, logPosition, scanner); } } Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java Tue Sep 10 20:13:14 2013 @@ -803,8 +803,10 @@ public class LedgerCacheImpl implements synchronized (fileInfoCache) { if (openLedgers.size() > openFileLimit) { long ledgerToRemove = openLedgers.removeFirst(); - LOG.info("Ledger {} is evicted from file info cache.", - ledgerToRemove); + // TODO Add a statistic here, we don't care really which + // ledger is evicted, but the rate at which they get evicted + LOG.debug("Ledger {} is evicted from file info cache.", + ledgerToRemove); FileInfo fi = fileInfoCache.remove(ledgerToRemove); if (fi != null) { fi.close(true); Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java Tue Sep 10 20:13:14 2013 @@ -628,6 +628,7 @@ public class LedgerHandle { errorOutPendingAdds(rc); return; } + LOG.error("Closing ledger {} due to error {}", ledgerId, rc); asyncCloseInternal(NoopCloseCallback.instance, null, rc); } Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java Tue Sep 10 20:13:14 2013 @@ -143,15 +143,18 @@ class PendingAddOp implements WriteCallb // continue break; case BKException.Code.LedgerFencedException: - LOG.warn("Fencing exception on write: " + ledgerId + ", " + entryId); + LOG.warn("Fencing exception on write: L{} E{} on {}", + new Object[] { ledgerId, entryId, addr }); lh.handleUnrecoverableErrorDuringAdd(rc); return; case BKException.Code.UnauthorizedAccessException: - LOG.warn("Unauthorized access exception on write: " + ledgerId + ", " + entryId); + LOG.warn("Unauthorized access exception on write: L{} E{} on {}", + new Object[] { ledgerId, entryId, addr }); lh.handleUnrecoverableErrorDuringAdd(rc); return; default: - LOG.warn("Write did not succeed: " + ledgerId + ", " + entryId); + LOG.warn("Write did not succeed: L{} E{} on {}", + new Object[] { ledgerId, entryId, addr }); lh.handleBookieFailure(addr, bookieIndex); return; } @@ -172,6 +175,11 @@ class PendingAddOp implements WriteCallb } void submitCallback(final int rc) { + if (rc != BKException.Code.OK) { + LOG.error("Write of ledger entry to quorum failed: L{} E{}", + lh.getId(), entryId); + } + cb.addComplete(rc, lh, entryId, ctx); } Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java Tue Sep 10 20:13:14 2013 @@ -190,11 +190,11 @@ class PendingReadOp implements Enumerati } if (BKException.Code.NoSuchEntryException == rc) { ++numMissedEntryReads; - LOG.info("No such entry found on bookie. entry: {} ledgerId: {} bookie: {}", new Object[] { entryId, - lh.ledgerId, host }); + LOG.debug("No such entry found on bookie. L{} E{} bookie: {}", + new Object[] { lh.ledgerId, entryId, host }); } else { - LOG.error(errMsg + " while reading entry: " + entryId + " ledgerId: " + lh.ledgerId + " from bookie: " - + host); + LOG.debug(errMsg + " while reading L{} E{} from bookie: {}", + new Object[] { lh.ledgerId, entryId, host }); } int replica = getReplicaIndex(host); @@ -282,8 +282,8 @@ class PendingReadOp implements Enumerati } } if (x > 0) { - LOG.info("Send {} speculative reads for ledger {} ({}, {}). Hosts heard are {}.", - new Object[] { x, lh.getId(), startEntryId, endEntryId, heardFromHosts }); + LOG.debug("Send {} speculative reads for ledger {} ({}, {}). Hosts heard are {}.", + new Object[] { x, lh.getId(), startEntryId, endEntryId, heardFromHosts }); } } }, speculativeReadTimeout, speculativeReadTimeout, TimeUnit.MILLISECONDS); @@ -347,6 +347,17 @@ class PendingReadOp implements Enumerati speculativeTask.cancel(true); speculativeTask = null; } + if (code != BKException.Code.OK) { + long firstUnread = LedgerHandle.INVALID_ENTRY_ID; + for (LedgerEntryRequest req : seq) { + if (!req.isComplete()) { + firstUnread = req.getEntryId(); + break; + } + } + LOG.error("Read of ledger entry failed: L{} E{}-E{}, Heard from {}. First unread entry is {}", + new Object[] { lh.getId(), startEntryId, endEntryId, heardFromHosts, firstUnread }); + } cb.readComplete(code, lh, PendingReadOp.this, PendingReadOp.this.ctx); } public boolean hasMoreElements() { Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java Tue Sep 10 20:13:14 2013 @@ -84,8 +84,8 @@ class ReadOnlyLedgerHandle extends Ledge try { if (!metadata.currentEnsemble.get(bookieIndex).equals(addr)) { // ensemble has already changed, failure of this addr is immaterial - LOG.warn("Write did not succeed to {}, bookieIndex {}, but we have already fixed it.", - addr, bookieIndex); + LOG.debug("Write did not succeed to {}, bookieIndex {}," + +" but we have already fixed it.", addr, bookieIndex); blockAddCompletions.decrementAndGet(); return; } Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java Tue Sep 10 20:13:14 2013 @@ -203,6 +203,7 @@ public class BookieClient { for (PerChannelBookieClient channel: channels.values()) { channel.close(); } + channels.clear(); } finally { closeLock.writeLock().unlock(); } Modified: zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java?rev=1521624&r1=1521623&r2=1521624&view=diff ============================================================================== --- zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java (original) +++ zookeeper/bookkeeper/branches/branch-4.2/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java Tue Sep 10 20:13:14 2013 @@ -404,7 +404,7 @@ public class PerChannelBookieClient exte } if (readCompletion != null) { - LOG.error("Could not write request for reading entry: {}" + LOG.debug("Could not write request for reading entry: {}" + " ledger-id: {} bookie: {}", new Object[] { key.entryId, key.ledgerId, bAddress }); @@ -429,12 +429,12 @@ public class PerChannelBookieClient exte if(c != null) { bAddress = c.getRemoteAddress().toString(); } - LOG.error("Could not write request for adding entry: {} ledger-id: {} bookie: {}", + LOG.debug("Could not write request for adding entry: {} ledger-id: {} bookie: {}", new Object[] { key.entryId, key.ledgerId, bAddress }); addCompletion.cb.writeComplete(BKException.Code.BookieHandleNotAvailableException, key.ledgerId, key.entryId, addr, addCompletion.ctx); - LOG.error("Invoked callback method: " + key.entryId); + LOG.debug("Invoked callback method: {}", key.entryId); } } @@ -516,8 +516,8 @@ public class PerChannelBookieClient exte public void exceptionCaught(ChannelHandlerContext ctx, ExceptionEvent e) throws Exception { Throwable t = e.getCause(); if (t instanceof CorruptedFrameException || t instanceof TooLongFrameException) { - LOG.error("Corrupted fram received from bookie: " - + e.getChannel().getRemoteAddress()); + LOG.error("Corrupted frame received from bookie: {}", + e.getChannel().getRemoteAddress()); return; } if (t instanceof ReadTimeoutException) { @@ -541,7 +541,14 @@ public class PerChannelBookieClient exte return; } - LOG.error("Unexpected exception caught by bookie client channel handler", t); + synchronized (this) { + if (state == ConnectionState.CLOSED) { + LOG.debug("Unexpected exception caught by bookie client channel handler, " + + "but the client is closed, so it isn't important", t); + } else { + LOG.error("Unexpected exception caught by bookie client channel handler", t); + } + } // Since we are a library, cant terminate App here, can we? } @@ -590,8 +597,8 @@ public class PerChannelBookieClient exte void handleAddResponse(long ledgerId, long entryId, int rc) { if (LOG.isDebugEnabled()) { - LOG.debug("Got response for add request from bookie: " + addr + " for ledger: " + ledgerId + " entry: " - + entryId + " rc: " + rc); + LOG.debug("Got response for add request from bookie: {} for ledger: {} entry: {}" + + " rc: {}", new Object[] { addr, ledgerId, entryId, rc }); } // convert to BKException code because thats what the uppper @@ -614,8 +621,8 @@ public class PerChannelBookieClient exte rc = BKException.Code.WriteOnReadOnlyBookieException; break; default: - LOG.error("Add for ledger: " + ledgerId + ", entry: " + entryId + " failed on bookie: " + addr - + " with code: " + rc); + LOG.warn("Add for ledger: {}, entry: {} failed on bookie: {}" + + " with unknown code: {}", new Object[] { ledgerId, entryId, addr, rc }); rc = BKException.Code.WriteException; break; } @@ -623,8 +630,8 @@ public class PerChannelBookieClient exte AddCompletion ac; ac = addCompletions.remove(new CompletionKey(ledgerId, entryId)); if (ac == null) { - LOG.error("Unexpected add response received from bookie: " + addr + " for ledger: " + ledgerId - + ", entry: " + entryId + " , ignoring"); + LOG.debug("Unexpected add response received from bookie: {} for ledger: {}" + + ", entry: {}, ignoring", new Object[] { addr, ledgerId, entryId }); return; } @@ -636,8 +643,9 @@ public class PerChannelBookieClient exte void handleReadResponse(long ledgerId, long entryId, int rc, ChannelBuffer buffer) { if (LOG.isDebugEnabled()) { - LOG.debug("Got response for read request from bookie: " + addr + " for ledger: " + ledgerId + " entry: " - + entryId + " rc: " + rc + " entry length: " + buffer.readableBytes()); + LOG.debug("Got response for read request from bookie: {} for ledger: {} entry: {}" + + " rc: {} entry length: {}", + new Object[] { addr, ledgerId, entryId, rc, buffer.readableBytes() }); } // convert to BKException code because thats what the uppper @@ -652,8 +660,8 @@ public class PerChannelBookieClient exte } else if (rc == BookieProtocol.EUA) { rc = BKException.Code.UnauthorizedAccessException; } else { - LOG.error("Read for ledger: " + ledgerId + ", entry: " + entryId + " failed on bookie: " + addr - + " with code: " + rc); + LOG.warn("Read for ledger: {}, entry: {} failed on bookie: {}" + + " with unknown code: {}", new Object[] { ledgerId, entryId, addr, rc }); rc = BKException.Code.ReadException; } @@ -671,8 +679,8 @@ public class PerChannelBookieClient exte } if (readCompletion == null) { - LOG.error("Unexpected read response received from bookie: " + addr + " for ledger: " + ledgerId - + ", entry: " + entryId + " , ignoring"); + LOG.debug("Unexpected read response received from bookie: {} for ledger: {}" + + ", entry: {} , ignoring", new Object[] { addr, ledgerId, entryId }); return; }