You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@zookeeper.apache.org by iv...@apache.org on 2013/09/11 00:34:07 UTC

svn commit: r1521667 - in /zookeeper/bookkeeper/trunk: ./ 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/proto/

Author: ivank
Date: Tue Sep 10 22:34:06 2013
New Revision: 1521667

URL: http://svn.apache.org/r1521667
Log:
BOOKKEEPER-675: Log noise fixup before cutting 4.2.2 (ivank)

Modified:
    zookeeper/bookkeeper/trunk/CHANGES.txt
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieRequestHandler.java
    zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java

Modified: zookeeper/bookkeeper/trunk/CHANGES.txt
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/CHANGES.txt?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/CHANGES.txt (original)
+++ zookeeper/bookkeeper/trunk/CHANGES.txt Tue Sep 10 22:34:06 2013
@@ -100,6 +100,8 @@ Trunk (unreleased changes)
 
         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-601: readahead cache size isn't updated correctly (sijie via fpj)

Modified: zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Bookie.java Tue Sep 10 22:34:06 2013
@@ -377,7 +377,7 @@ public class Bookie extends Thread {
                     + BookKeeperConstants.INSTANCEID, false, null);
             instanceId = new String(data, UTF_8);
         } 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;
     }
@@ -498,6 +498,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/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/GarbageCollectorThread.java Tue Sep 10 22:34:06 2013
@@ -542,7 +542,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
@@ -570,8 +570,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/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/Journal.java Tue Sep 10 22:34:06 2013
@@ -438,6 +438,7 @@ class Journal extends Thread implements 
             if(id == markedLog.getLogFileId()) {
                 logPosition = markedLog.getLogFileOffset();
             }
+            LOG.info("Replaying journal {} from position {}", id, logPosition);
             scanJournal(id, logPosition, scanner);
         }
     }

Modified: zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/bookie/LedgerCacheImpl.java Tue Sep 10 22:34:06 2013
@@ -800,8 +800,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);
                 fileInfoCache.remove(ledgerToRemove).close(true);
             }
         }

Modified: zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/LedgerHandle.java Tue Sep 10 22:34:06 2013
@@ -624,6 +624,7 @@ public class LedgerHandle {
             errorOutPendingAdds(rc);
             return;
         }
+        LOG.error("Closing ledger {} due to error {}", ledgerId, rc);
         asyncCloseInternal(NoopCloseCallback.instance, null, rc);
     }
 

Modified: zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingAddOp.java Tue Sep 10 22:34:06 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/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/PendingReadOp.java Tue Sep 10 22:34:06 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/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/client/ReadOnlyLedgerHandle.java Tue Sep 10 22:34:06 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/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieClient.java Tue Sep 10 22:34:06 2013
@@ -205,6 +205,7 @@ public class BookieClient {
             for (PerChannelBookieClient channel: channels.values()) {
                 channel.close();
             }
+            channels.clear();
         } finally {
             closeLock.writeLock().unlock();
         }

Modified: zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieRequestHandler.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieRequestHandler.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieRequestHandler.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/BookieRequestHandler.java Tue Sep 10 22:34:06 2013
@@ -23,6 +23,7 @@ package org.apache.bookkeeper.proto;
 import java.io.IOException;
 import java.net.InetSocketAddress;
 import java.nio.ByteBuffer;
+import java.nio.channels.ClosedChannelException;
 
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.Future;
@@ -74,6 +75,10 @@ class BookieRequestHandler extends Simpl
     @Override
     public void exceptionCaught(ChannelHandlerContext ctx, ExceptionEvent e) throws Exception {
         Throwable throwable = e.getCause();
+        if (throwable instanceof ClosedChannelException) {
+            LOG.debug("Client died before request could be completed", throwable);
+            return;
+        }
         LOG.error("Unhandled exception occurred in I/O thread or handler", throwable);
     }
 

Modified: zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java
URL: http://svn.apache.org/viewvc/zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java?rev=1521667&r1=1521666&r2=1521667&view=diff
==============================================================================
--- zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java (original)
+++ zookeeper/bookkeeper/trunk/bookkeeper-server/src/main/java/org/apache/bookkeeper/proto/PerChannelBookieClient.java Tue Sep 10 22:34:06 2013
@@ -372,7 +372,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 });
 
@@ -397,12 +397,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);
                 }
             }
 
@@ -489,8 +489,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) {
@@ -514,7 +514,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?
     }
 
@@ -574,7 +581,7 @@ public class PerChannelBookieClient exte
             rc = BKException.Code.WriteOnReadOnlyBookieException;
             break;
         default:
-            LOG.error("Add failed {}", a);
+            LOG.warn("Add failed {}", a);
             rc = BKException.Code.WriteException;
             break;
         }
@@ -583,7 +590,7 @@ public class PerChannelBookieClient exte
         ac = addCompletions.remove(new CompletionKey(a.getLedgerId(),
                                                      a.getEntryId()));
         if (ac == null) {
-            LOG.error("Unexpected add response from bookie {} for {}", addr, a);
+            LOG.debug("Unexpected add response from bookie {} for {}", addr, a);
             return;
         }
 
@@ -615,7 +622,7 @@ public class PerChannelBookieClient exte
             rc = BKException.Code.UnauthorizedAccessException;
             break;
         default:
-            LOG.error("Read error for {}", rr);
+            LOG.warn("Read error for {}", rr);
             rc = BKException.Code.ReadException;
             break;
         }
@@ -635,7 +642,7 @@ public class PerChannelBookieClient exte
         }
 
         if (readCompletion == null) {
-            LOG.error("Unexpected read response received from bookie: {} for {}", addr, rr);
+            LOG.debug("Unexpected read response received from bookie: {} for {}", addr, rr);
             return;
         }