Logging verbosity

Larry O'Leary loleary at redhat.com
Wed Dec 18 14:59:30 UTC 2013


On Wed, 2013-12-18 at 00:17 +0100, Lukas Krejci wrote:
> I'm not sure I can agree with that..
> 
> Customer: We have this issue, our server doesn't work.
> Support: What does the log say?
> Customer: [ERROR] - Failed to collect important stuff because of: null (this 
> is just to exacerbate the change in logging I started this thread with).
> Support: Oh, could you please go back to your server and replicate the issue 
> with debug logging on? We need to see the stacktraces.
> Customer: You mean reconfiguring a production server? Why didn't include 
> enough info in the message so that you can diagnose the error?

Right. Which is in itself a bug. If we have to do this because a message
provides no value or lacks enough context to understand the problem, a
bug is logged. But keep in mind that even with a stack trace, it doesn't
help if we don't know what was happening at the time of the message. In
most cases we don't know what resource is generating the error or even
if it relates to the issue that is being investigated. In those cases,
DEBUG logging is required to get enough log context around the error to
figure out what resource or component is the area of focus.

> Or a slightly different conversation:
> ... start off the same as above ...
> Support: We can't diagnose the issue unless we send you a diagnostic patch.
> Customer: What kind of muppets are you, seriously?

This is actually easier then you would think. First off, we very rarely
have to use an actual diagnostic patch. Instead, we use JBoss Byteman
which allows us to add the missing logging or insert context around the
issue.

Again, such situations would normally result in a bug being logged for
the lack of information but in the end, it was a logging bug -- due to
improper handling of an exception.

> What you say is correct, but not sufficient IMHO - the information the log 
> message provides should be digestable by non-developers. But at the same time,  
> it should also provide the developer with enough info to diagnose the 
> underlying issue. And the more severe the log message is, the more it applies. 
> 
> This of course doesn't mean that the stacktrace has to be provided - if there 
> is only one way an exception could be raised, we don't have to necessarily log 
> it (and the change that started this thread seems to be in that category). 
> Unfortunately our code contains quite a lot of "catch (Exception e)" or even 
> "catch  (Throwable t)". These catch-all blocks don't lend themselves to that 
> approach too well. 

I mostly agree with what you are saying here. I don't think stack traces
should be "logged" at levels less then DEBUG. However, in cases of
improperly handled or unhandled exceptions, it makes more sense. But
even then, this can be done in an enterprise way -- without dumping a
giant stack trace to the log. 

Many projects I have worked with in the past handled this by storing
such developer oriented data in a separate place with an index or other
key that relates it back to a specific log message from the log file. 

In general, the error should be meaningful to the user and provide
enough context to simply know what the issue is. In cases that unhandled
exceptions occur, they should be logged as such; "An unexpected error
has occurred..." If debug logging is necessary to identify the
environment and conditions surrounding the unknown error, then let it be
so. As a result, logging bugs would most likely be identified.
-- 
Larry O'Leary
https://plus.google.com/+LarryOLeary


> On Tuesday, December 17, 2013 13:47:45 Larry O'Leary wrote:
> > On Tue, 2013-12-17 at 20:38 +0100, Heiko W.Rupp wrote:
> > > Am 17.12.2013 um 19:00 schrieb Lukas Krejci <lkrejci at redhat.com>:
> > > > I am personally very much FOR having stacktraces in the log messages,
> > > > especially in erroneous conditions like this one (i.e. IMHO almost> 
> > > If our stacktraces would only contain relevant information I would agree.
> > > 
> > > Spitting out the same 30 lines over and over again does not add any value.
> > > A lot of what is written is stuff inside java.* . Also for above case, the
> > > trace is always the same, and leads to the place you pointed out. That
> > > trace does not tell anything about the cause, which is what we would want
> > > in reality.
> > > 
> > > We may log the traces at a different level that is off by default though.
> > 
> > I would only expect to see stack traces at DEBUG level. At any log level
> > below that, I would expect the log message to provide me with the most
> > relevant information in a non-Java or non-developer context.
> _______________________________________________
> rhq-devel mailing list
> rhq-devel at lists.fedorahosted.org
> https://lists.fedorahosted.org/mailman/listinfo/rhq-devel



More information about the rhq-devel mailing list