You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hbase.apache.org by Stack <st...@duboce.net> on 2019/12/04 05:02:23 UTC
Re: Error Handling and Logging
Thanks for the helpful note David. Appreciated.
S
On Tue, Nov 26, 2019 at 1:44 PM David Mollitor <da...@gmail.com> 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!
>
Re: Error Handling and Logging
Posted by XU Qinghui <qi...@polytechnique.edu>.
Thanks for sharing, I think indeed loggings should be taken more seriously
in this project.
Le ven. 6 déc. 2019 à 18:53, David Mollitor <da...@gmail.com> a écrit :
> ---------- Forwarded message ---------
> From: David Mollitor <da...@gmail.com>
> Date: Fri, Dec 6, 2019 at 12:52 PM
> Subject: Re: Error Handling and Logging
> To: <de...@hbase.apache.org>
>
>
> Hell Team,
>
> I'm not sure how to automate this, but as I scan through the log
> statements, another thing I am observing is the following:
>
> 1// Lots of punctuation. There is no need to yell (!!!) or to try to be
> proper (.). Please be concise and most log messages do not end with a
> period
> 2// Contractions. Please do not use contractions (can't, won't we're)
> these are harder words for our international friends
> 3// Use strong words. Avoid phases like "couldn't complete the action" and
> instead consider using something like "failed to complete action". The
> word "fail" is trained into me much more than the word "couldn't"
>
> Thanks so much for all the positive feedback I've received from the HBase
> team here and in private conversations.
>
>
>
> On Thu, Dec 5, 2019 at 1:10 PM Nick Dimiduk <nd...@apache.org> wrote:
>
> > 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 <st...@duboce.net> wrote:
> >
> > > Thanks for the helpful note David. Appreciated.
> > > S
> > >
> > > On Tue, Nov 26, 2019 at 1:44 PM David Mollitor <da...@gmail.com>
> > 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!
> > > >
> > >
> >
>
Fwd: Error Handling and Logging
Posted by David Mollitor <da...@gmail.com>.
---------- Forwarded message ---------
From: David Mollitor <da...@gmail.com>
Date: Fri, Dec 6, 2019 at 12:52 PM
Subject: Re: Error Handling and Logging
To: <de...@hbase.apache.org>
Hell Team,
I'm not sure how to automate this, but as I scan through the log
statements, another thing I am observing is the following:
1// Lots of punctuation. There is no need to yell (!!!) or to try to be
proper (.). Please be concise and most log messages do not end with a
period
2// Contractions. Please do not use contractions (can't, won't we're)
these are harder words for our international friends
3// Use strong words. Avoid phases like "couldn't complete the action" and
instead consider using something like "failed to complete action". The
word "fail" is trained into me much more than the word "couldn't"
Thanks so much for all the positive feedback I've received from the HBase
team here and in private conversations.
On Thu, Dec 5, 2019 at 1:10 PM Nick Dimiduk <nd...@apache.org> wrote:
> 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 <st...@duboce.net> wrote:
>
> > Thanks for the helpful note David. Appreciated.
> > S
> >
> > On Tue, Nov 26, 2019 at 1:44 PM David Mollitor <da...@gmail.com>
> 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!
> > >
> >
>
Re: Error Handling and Logging
Posted by David Mollitor <da...@gmail.com>.
Pedro,
Yes. It is almost entirely subjective. I'm just trying to share with you
my personal experiences of having to administer and troubleshoot these
projects (and all Java projects in particular). Please share some of your
experiences in working with the projects as it relates to logging. I'd
greatly appreciate the feedback.
Thanks!
On Fri, Dec 6, 2019 at 1:25 PM Pedro Boado <pe...@gmail.com> wrote:
> Wow that's one of the most subjective opinions I've read in a very long
> time.
>
> On Fri, 6 Dec 2019, 17:52 David Mollitor, <da...@gmail.com> wrote:
>
> > Hell Team,
> >
> > I'm not sure how to automate this, but as I scan through the log
> > statements, another thing I am observing is the following:
> >
> > 1// Lots of punctuation. There is no need to yell (!!!) or to try to be
> > proper (.). Please be concise and most log messages do not end with a
> > period
> > 2// Contractions. Please do not use contractions (can't, won't we're)
> > these are harder words for our international friends
> > 3// Use strong words. Avoid phases like "couldn't complete the action"
> and
> > instead consider using something like "failed to complete action". The
> > word "fail" is trained into me much more than the word "couldn't"
> >
> > Thanks so much for all the positive feedback I've received from the HBase
> > team here and in private conversations.
> >
> >
> >
> > On Thu, Dec 5, 2019 at 1:10 PM Nick Dimiduk <nd...@apache.org> wrote:
> >
> > > 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 <st...@duboce.net> wrote:
> > >
> > > > Thanks for the helpful note David. Appreciated.
> > > > S
> > > >
> > > > On Tue, Nov 26, 2019 at 1:44 PM David Mollitor <da...@gmail.com>
> > > 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!
> > > > >
> > > >
> > >
> >
>
Re: Error Handling and Logging
Posted by Pedro Boado <pe...@gmail.com>.
Wow that's one of the most subjective opinions I've read in a very long
time.
On Fri, 6 Dec 2019, 17:52 David Mollitor, <da...@gmail.com> wrote:
> Hell Team,
>
> I'm not sure how to automate this, but as I scan through the log
> statements, another thing I am observing is the following:
>
> 1// Lots of punctuation. There is no need to yell (!!!) or to try to be
> proper (.). Please be concise and most log messages do not end with a
> period
> 2// Contractions. Please do not use contractions (can't, won't we're)
> these are harder words for our international friends
> 3// Use strong words. Avoid phases like "couldn't complete the action" and
> instead consider using something like "failed to complete action". The
> word "fail" is trained into me much more than the word "couldn't"
>
> Thanks so much for all the positive feedback I've received from the HBase
> team here and in private conversations.
>
>
>
> On Thu, Dec 5, 2019 at 1:10 PM Nick Dimiduk <nd...@apache.org> wrote:
>
> > 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 <st...@duboce.net> wrote:
> >
> > > Thanks for the helpful note David. Appreciated.
> > > S
> > >
> > > On Tue, Nov 26, 2019 at 1:44 PM David Mollitor <da...@gmail.com>
> > 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!
> > > >
> > >
> >
>
Re: Error Handling and Logging
Posted by David Mollitor <da...@gmail.com>.
Hell Team,
I'm not sure how to automate this, but as I scan through the log
statements, another thing I am observing is the following:
1// Lots of punctuation. There is no need to yell (!!!) or to try to be
proper (.). Please be concise and most log messages do not end with a
period
2// Contractions. Please do not use contractions (can't, won't we're)
these are harder words for our international friends
3// Use strong words. Avoid phases like "couldn't complete the action" and
instead consider using something like "failed to complete action". The
word "fail" is trained into me much more than the word "couldn't"
Thanks so much for all the positive feedback I've received from the HBase
team here and in private conversations.
On Thu, Dec 5, 2019 at 1:10 PM Nick Dimiduk <nd...@apache.org> wrote:
> 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 <st...@duboce.net> wrote:
>
> > Thanks for the helpful note David. Appreciated.
> > S
> >
> > On Tue, Nov 26, 2019 at 1:44 PM David Mollitor <da...@gmail.com>
> 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!
> > >
> >
>
Re: Error Handling and Logging
Posted by Nick Dimiduk <nd...@apache.org>.
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 <st...@duboce.net> wrote:
> Thanks for the helpful note David. Appreciated.
> S
>
> On Tue, Nov 26, 2019 at 1:44 PM David Mollitor <da...@gmail.com> 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!
> >
>