Return-Path: X-Original-To: apmail-hadoop-common-commits-archive@www.apache.org Delivered-To: apmail-hadoop-common-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 A699F1937A for ; Wed, 9 Mar 2016 07:33:37 +0000 (UTC) Received: (qmail 92742 invoked by uid 500); 9 Mar 2016 07:33:37 -0000 Delivered-To: apmail-hadoop-common-commits-archive@hadoop.apache.org Received: (qmail 92572 invoked by uid 500); 9 Mar 2016 07:33:37 -0000 Mailing-List: contact common-commits-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: common-dev@hadoop.apache.org Delivered-To: mailing list common-commits@hadoop.apache.org Received: (qmail 92422 invoked by uid 99); 9 Mar 2016 07:33:36 -0000 Received: from git1-us-west.apache.org (HELO git1-us-west.apache.org) (140.211.11.23) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 09 Mar 2016 07:33:36 +0000 Received: by git1-us-west.apache.org (ASF Mail Server at git1-us-west.apache.org, from userid 33) id BFF47DFC6D; Wed, 9 Mar 2016 07:33:36 +0000 (UTC) Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit From: arp@apache.org To: common-commits@hadoop.apache.org Date: Wed, 09 Mar 2016 07:33:37 -0000 Message-Id: In-Reply-To: <13b20edf30184cd99406ddacc9c6e6f3@git.apache.org> References: <13b20edf30184cd99406ddacc9c6e6f3@git.apache.org> X-Mailer: ASF-Git Admin Mailer Subject: [2/3] hadoop git commit: HADOOP-12903. IPC Server should allow suppressing exception logging by type, not log 'server too busy' messages. (Arpit Agarwal) HADOOP-12903. IPC Server should allow suppressing exception logging by type, not log 'server too busy' messages. (Arpit Agarwal) Project: http://git-wip-us.apache.org/repos/asf/hadoop/repo Commit: http://git-wip-us.apache.org/repos/asf/hadoop/commit/a06ecb08 Tree: http://git-wip-us.apache.org/repos/asf/hadoop/tree/a06ecb08 Diff: http://git-wip-us.apache.org/repos/asf/hadoop/diff/a06ecb08 Branch: refs/heads/branch-2 Commit: a06ecb085eae85fc7bfd6de4b0a05036a6527b94 Parents: 0d8ad99 Author: Arpit Agarwal Authored: Tue Mar 8 23:29:43 2016 -0800 Committer: Arpit Agarwal Committed: Tue Mar 8 23:30:36 2016 -0800 ---------------------------------------------------------------------- .../main/java/org/apache/hadoop/ipc/Server.java | 134 ++++++++++++++----- .../java/org/apache/hadoop/ipc/TestServer.java | 71 +++++++++- 2 files changed, 163 insertions(+), 42 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/hadoop/blob/a06ecb08/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/ipc/Server.java ---------------------------------------------------------------------- diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/ipc/Server.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/ipc/Server.java index 20c993b..8ae2ef9 100644 --- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/ipc/Server.java +++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/ipc/Server.java @@ -139,8 +139,22 @@ public abstract class Server { private ExceptionsHandler exceptionsHandler = new ExceptionsHandler(); private Tracer tracer; + /** + * Add exception classes for which server won't log stack traces. + * + * @param exceptionClass exception classes + */ public void addTerseExceptions(Class... exceptionClass) { - exceptionsHandler.addTerseExceptions(exceptionClass); + exceptionsHandler.addTerseLoggingExceptions(exceptionClass); + } + + /** + * Add exception classes which server won't log at all. + * + * @param exceptionClass exception classes + */ + public void addSuppressedLoggingExceptions(Class... exceptionClass) { + exceptionsHandler.addSuppressedLoggingExceptions(exceptionClass); } /** @@ -148,29 +162,54 @@ public abstract class Server { * e.g., terse exception group for concise logging messages */ static class ExceptionsHandler { - private volatile Set terseExceptions = new HashSet(); + private volatile Set terseExceptions = new HashSet<>(); + private volatile Set suppressedExceptions = new HashSet<>(); /** - * Add exception class so server won't log its stack trace. - * Modifying the terseException through this method is thread safe. - * + * Add exception classes for which server won't log stack traces. + * Optimized for infrequent invocation. * @param exceptionClass exception classes */ - void addTerseExceptions(Class... exceptionClass) { + void addTerseLoggingExceptions(Class... exceptionClass) { + // Thread-safe replacement of terseExceptions. + terseExceptions = addExceptions(terseExceptions, exceptionClass); + } + + /** + * Add exception classes which server won't log at all. + * Optimized for infrequent invocation. + * @param exceptionClass exception classes + */ + void addSuppressedLoggingExceptions(Class... exceptionClass) { + // Thread-safe replacement of suppressedExceptions. + suppressedExceptions = addExceptions( + suppressedExceptions, exceptionClass); + } + + boolean isTerseLog(Class t) { + return terseExceptions.contains(t.toString()); + } + + boolean isSuppressedLog(Class t) { + return suppressedExceptions.contains(t.toString()); + } - // Make a copy of terseException for performing modification - final HashSet newSet = new HashSet(terseExceptions); + /** + * Return a new set containing all the exceptions in exceptionsSet + * and exceptionClass. + * @return + */ + private static Set addExceptions( + final Set exceptionsSet, Class[] exceptionClass) { + // Make a copy of the exceptionSet for performing modification + final HashSet newSet = new HashSet<>(exceptionsSet); // Add all class names into the HashSet for (Class name : exceptionClass) { newSet.add(name.toString()); } - // Replace terseException set - terseExceptions = Collections.unmodifiableSet(newSet); - } - boolean isTerse(Class t) { - return terseExceptions.contains(t.toString()); + return Collections.unmodifiableSet(newSet); } } @@ -878,7 +917,7 @@ public abstract class Server { } void doRead(SelectionKey key) throws InterruptedException { - int count = 0; + int count; Connection c = (Connection)key.attachment(); if (c == null) { return; @@ -891,13 +930,17 @@ public abstract class Server { LOG.info(Thread.currentThread().getName() + ": readAndProcess caught InterruptedException", ieo); throw ieo; } catch (Exception e) { - // a WrappedRpcServerException is an exception that has been sent - // to the client, so the stacktrace is unnecessary; any other - // exceptions are unexpected internal server errors and thus the - // stacktrace should be logged - LOG.info(Thread.currentThread().getName() + ": readAndProcess from client " + - c.getHostAddress() + " threw exception [" + e + "]", - (e instanceof WrappedRpcServerException) ? null : e); + // Do not log WrappedRpcServerExceptionSuppressed. + if (!(e instanceof WrappedRpcServerExceptionSuppressed)) { + // A WrappedRpcServerException is an exception that has been sent + // to the client, so the stacktrace is unnecessary; any other + // exceptions are unexpected internal server errors and thus the + // stacktrace should be logged. + LOG.info(Thread.currentThread().getName() + + ": readAndProcess from client " + c.getHostAddress() + + " threw exception [" + e + "]", + (e instanceof WrappedRpcServerException) ? null : e); + } count = -1; //so that the (count < 0) block is executed } if (count < 0) { @@ -1240,6 +1283,18 @@ public abstract class Server { } } + /** + * A WrappedRpcServerException that is suppressed altogether + * for the purposes of logging. + */ + private static class WrappedRpcServerExceptionSuppressed + extends WrappedRpcServerException { + public WrappedRpcServerExceptionSuppressed( + RpcErrorCodeProto errCode, IOException ioe) { + super(errCode, ioe); + } + } + /** Reads calls from a connection and queues them for handling. */ public class Connection { private boolean connectionHeaderRead = false; // connection header is read? @@ -2032,7 +2087,7 @@ public abstract class Server { rpcMetrics.incrClientBackoff(); RetriableException retriableException = new RetriableException("Server is too busy."); - throw new WrappedRpcServerException( + throw new WrappedRpcServerExceptionSuppressed( RpcErrorCodeProto.ERROR_RPC_SERVER, retriableException); } } @@ -2227,18 +2282,7 @@ public abstract class Server { if (e instanceof UndeclaredThrowableException) { e = e.getCause(); } - String logMsg = Thread.currentThread().getName() + ", call " + call; - if (exceptionsHandler.isTerse(e.getClass())) { - // Don't log the whole stack trace. Way too noisy! - LOG.info(logMsg + ": " + e); - } else if (e instanceof RuntimeException || e instanceof Error) { - // These exception types indicate something is probably wrong - // on the server side, as opposed to just a normal exceptional - // result. - LOG.warn(logMsg, e); - } else { - LOG.info(logMsg, e); - } + logException(LOG, e, call); if (e instanceof RpcServerException) { RpcServerException rse = ((RpcServerException)e); returnStatus = rse.getRpcStatusProto(); @@ -2291,6 +2335,26 @@ public abstract class Server { } } + + @VisibleForTesting + void logException(Log logger, Throwable e, Call call) { + if (exceptionsHandler.isSuppressedLog(e.getClass())) { + return; // Log nothing. + } + + final String logMsg = Thread.currentThread().getName() + ", call " + call; + if (exceptionsHandler.isTerseLog(e.getClass())) { + // Don't log the whole stack trace. Way too noisy! + logger.info(logMsg + ": " + e); + } else if (e instanceof RuntimeException || e instanceof Error) { + // These exception types indicate something is probably wrong + // on the server side, as opposed to just a normal exceptional + // result. + logger.warn(logMsg, e); + } else { + logger.info(logMsg, e); + } + } protected Server(String bindAddress, int port, Class paramClass, int handlerCount, @@ -2396,7 +2460,7 @@ public abstract class Server { saslPropsResolver = SaslPropertiesResolver.getInstance(conf); } - this.exceptionsHandler.addTerseExceptions(StandbyException.class); + this.exceptionsHandler.addTerseLoggingExceptions(StandbyException.class); } private RpcSaslProto buildNegotiateResponse(List authMethods) http://git-wip-us.apache.org/repos/asf/hadoop/blob/a06ecb08/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/ipc/TestServer.java ---------------------------------------------------------------------- diff --git a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/ipc/TestServer.java b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/ipc/TestServer.java index 64dc4d4..afda535 100644 --- a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/ipc/TestServer.java +++ b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/ipc/TestServer.java @@ -19,13 +19,19 @@ package org.apache.hadoop.ipc; import static org.junit.Assert.*; +import static org.mockito.Matchers.*; +import static org.mockito.Mockito.*; import java.io.IOException; import java.net.BindException; import java.net.InetSocketAddress; import java.net.ServerSocket; +import org.apache.commons.logging.Log; import org.apache.hadoop.conf.Configuration; +import org.apache.hadoop.io.LongWritable; +import org.apache.hadoop.io.Writable; +import org.apache.hadoop.ipc.Server.Call; import org.junit.Test; /** @@ -117,15 +123,66 @@ public class TestServer { } } + static class TestException1 extends Exception { + } + + static class TestException2 extends Exception { + } + + static class TestException3 extends Exception { + } + + @Test (timeout=300000) + public void testLogExceptions() throws Exception { + final Configuration conf = new Configuration(); + final Call dummyCall = new Call(0, 0, null, null); + Log logger = mock(Log.class); + Server server = new Server("0.0.0.0", 0, LongWritable.class, 1, conf) { + @Override + public Writable call( + RPC.RpcKind rpcKind, String protocol, Writable param, + long receiveTime) throws Exception { + return null; + } + }; + server.addSuppressedLoggingExceptions(TestException1.class); + server.addTerseExceptions(TestException2.class); + + // Nothing should be logged for a suppressed exception. + server.logException(logger, new TestException1(), dummyCall); + verifyZeroInteractions(logger); + + // No stack trace should be logged for a terse exception. + server.logException(logger, new TestException2(), dummyCall); + verify(logger, times(1)).info(anyObject()); + + // Full stack trace should be logged for other exceptions. + final Throwable te3 = new TestException3(); + server.logException(logger, te3, dummyCall); + verify(logger, times(1)).info(anyObject(), eq(te3)); + } + + @Test + public void testExceptionsHandlerTerse() { + Server.ExceptionsHandler handler = new Server.ExceptionsHandler(); + handler.addTerseLoggingExceptions(IOException.class); + handler.addTerseLoggingExceptions(RpcServerException.class, IpcException.class); + + assertTrue(handler.isTerseLog(IOException.class)); + assertTrue(handler.isTerseLog(RpcServerException.class)); + assertTrue(handler.isTerseLog(IpcException.class)); + assertFalse(handler.isTerseLog(RpcClientException.class)); + } + @Test - public void testExceptionsHandler() { + public void testExceptionsHandlerSuppressed() { Server.ExceptionsHandler handler = new Server.ExceptionsHandler(); - handler.addTerseExceptions(IOException.class); - handler.addTerseExceptions(RpcServerException.class, IpcException.class); + handler.addSuppressedLoggingExceptions(IOException.class); + handler.addSuppressedLoggingExceptions(RpcServerException.class, IpcException.class); - assertTrue(handler.isTerse(IOException.class)); - assertTrue(handler.isTerse(RpcServerException.class)); - assertTrue(handler.isTerse(IpcException.class)); - assertFalse(handler.isTerse(RpcClientException.class)); + assertTrue(handler.isSuppressedLog(IOException.class)); + assertTrue(handler.isSuppressedLog(RpcServerException.class)); + assertTrue(handler.isSuppressedLog(IpcException.class)); + assertFalse(handler.isSuppressedLog(RpcClientException.class)); } }