I think these are good points all around. Can any of these anti-patterns be flagged by a checkstyle rule? Static analysis would make the infractions easier to track down.
One more point of my own: I’m of the opinion that we log too much in general. Info level should not describe the details of operations as normal. I’m also not a fan of logging data structure “status”messages, as we do, for example, from the block cache. It’s enough to expose these as metrics. Thanks for speaking up! If you’re feeling ambitious, please ping me on any PRs and we’ll get things cleaned up. Thanks, Nick On Tue, Dec 3, 2019 at 21:02 Stack <[email protected]> wrote: > Thanks for the helpful note David. Appreciated. > S > > On Tue, Nov 26, 2019 at 1:44 PM David Mollitor <[email protected]> wrote: > > > Hello Team, > > > > I am one of many people responsible for supporting the Hadoop products > out > > in the field. Error handling and logging are crucial to my success. > I've > > been reading over the code and I see many of the same mistakes again and > > again. I just wanted to bring some of these things to your attention so > > that moving forward, we can make these products better. > > > > The general best-practice is: > > > > public class TestExceptionLogging > > { > > private static final Logger LOG = > > LoggerFactory.getLogger(TestExceptionLogging.class); > > > > public static void main(String[] args) { > > try { > > processData(); > > } catch (Exception e) { > > LOG.error("Application failed", e); > > } > > } > > > > public static void processData() throws Exception { > > try { > > readData(); > > } catch (Exception e) { > > throw new Exception("Failed to process data", e); > > } > > } > > > > public static byte[] readData() throws Exception { > > throw new IOException("Failed to read device"); > > } > > } > > > > Produces: > > > > [main] ERROR TestExceptionLogging - Application failed > > java.lang.Exception: Failed to process data > > at TestExceptionLogging.processData(TestExceptionLogging.java:22) > > at TestExceptionLogging.main(TestExceptionLogging.java:12) > > Caused by: java.io.IOException: Failed to read device > > at TestExceptionLogging.readData(TestExceptionLogging.java:27) > > at TestExceptionLogging.processData(TestExceptionLogging.java:20) > > ... 1 more > > > > > > > > Please notice that when an exception is thrown, and caught, it is wrapped > > at each level and each level adds some more context to describe what was > > happening when the error occurred. It also produces a complete stack > trace > > that pinpoints the issue. For Hive folks, it is rarely the case that a > > method consuming a HMS API call should itself throw a MetaException. The > > MetaException has no way of wrapping an underlying Exception and helpful > > data is often loss. A method may chooses to wrap a MetaException, but it > > should not be throwing them around as the default behavior. > > > > Also important to note is that there is exactly one place that is doing > the > > logging. There does not need to be any logging at the lower levels. A > > catch block should throw or log, not both. This is an anti-pattern and > > annoying as the end user: having to deal with multiple stack traces at > > different log levels for the same error condition. The log message > should > > be at the highest level only. > > > > https://community.oracle.com/docs/DOC-983543#logAndThrow > > > > Both projects use SLF4J as the logging framework (facade anyway). Please > > familiarize yourself with how to correctly log an Exception. There is no > > need to log a thread name, a time stamp, a class name, or a stack trace. > > The logging framework will do that all for you. > > > > http://www.slf4j.org/faq.html#paramException > > > > Again, there is no need to 'stringify' an exception. For example, do not > > use this: > > > > > > > https://github.com/apache/hadoop/blob/trunk/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/StringUtils.java#L86 > > > > > > If you do however want to dump a stack trace for debugging (or trace) > > purposes, consider performing the following: > > > > if (LOG.isDebugEnabled()) { > > LOG.debug("Dump Thread Stack", new Exception("Thread Stack Trace (Not > an > > Error)")); > > } > > > > Finally, I've seen it a couple of times in Apache project that enabling > > debug-level logging causes the application to emit logs at other levels, > > for example: > > > > LOG.warn("Some error occurred: {}", e.getMessage()); > > if (LOG.isDebugEnabled()) { > > LOG. warn("Dump Warning Thread Stack", e); > > } > > > > Please refrain from doing this. The inner log statement should be at > DEBUG > > level to match the check. Otherwise, when I enable DEBUG logging in the > > application, the expectation that I have is that I will have the exact > > logging as the INFO level, but I will also have additional DEBUG details > as > > well. I am going to be using 'grep' to find DEBUG and I will miss this > > additional logging. I will then be peeved when I say "ah ha! It's a WARN > > log message, I don't need DEBUG enabled to get this logging when the > issue > > happens again!"... but then I restart the application and discover I do > in > > fact need DEBUG logging enabled. > > > > Finally, finally, do not pass server-generated stack traces to a client > > application. When a client dumps a stack trace, it is not always trivial > > to decide if the stack trace is in regards to the client or the server. > > This can also be a security issue as it may hint to the client which > > libraries and (based on line numbers) which versions of the libraries are > > being used. If the server is going to generate an error in response to a > > client API call, the server should log the exception (right before > > returning the response to the client) and it should only pass a helpful > > error message to the client. The operator/administrator can look in the > > server logs for the details. > > > > Thanks! > > >
