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/10 22:13:15 UTC
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...
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;
}