[slf4j-dev] Trace and/or Ignore.
Greg Wilkins
gregw at mortbay.com
Tue Jun 28 09:23:23 CEST 2005
Hi guys,
I'm moving a thread with Ceki from the Jetty lists to here - as a more appropriate forum.
I responded to the "Better printing methods" thread with a "yes - but" to Ceki. His response
is below with more comments from me:
Ceki Gülcü wrote:
> 1) Add debug(Throwable t) method because not all exceptions have a
> meaning to go with them. Moreover, a good exception should be self
> explanatory.
>
> While I quite agree with these two arguments, there are three opposing
> arguments which are also worth considering. First, many (but not all)
> exceptions have an accompanying message. Second, it is not difficult to
> imagine more or less generic messages, e.g. "Exception caught",
> "Exception follows", that can be used in the debug(String msg, Throwable
> t) invocations.
> Third, most log output formats display the message on a line, followed
> by the exception on a separate line. Thus, the message line would look
> inconsistent without a message.
>
> In short, if the user were allowed to log an exception without, it would
> be the job of the logging system to invent a message. This is actually
> what the throwing(String sourceClass, String sourceMethod, Throwable
> thrown) method [1] in java.util.logging package does. (It decides on its
> own that message is the string "THROW".)
>
> [1] http://tinyurl.com/cr9kg
>
> It may initially appear strange to require an accompanying message to
> log an exception. Nevertheless, this is common practice in *all* log4j
> derived systems such as java.util.logging, logkit, etc. and of course
> log4j itself. It seems to me that the current consensus considers that
> requiring an accompanying message is good a thing (TM).
OK - happy with that.
> 2) Add ignore(Throwable t) method for exceptions that one "thinks" will
> never happen - but they do. Ignore output can be turn on - as a higher
> level than debug or trace. Having this avoids that really nasty empty
> catch block and it clearly states
> how the exception is handled.
>
> Clearly, logging a caught exception is much better than an empty catch
> block. Note that in a sense, all logged exception are "ignored" -- they
> are merely logged and not propagated to the calling method. May I
> suggest the user of the WARN level for exceptions which are closely
> related to an earlier exception? As in
>
> OutputStream out = new SomeOutputStream();
> try {
> out.write(...);
> } catch(IOException ioe) {
> logger.error("Failed to write to stream.", ioe);
> } finally {
> try {
> out.close();
> } catch(IOException ioe) {
> logger.warn("Failed to close stream.", ioe);
> }
> }
>
> The WARN level may be more appropriate than ERROR assuming that the
> second exception (in the finally clause) is thrown in close relation to
> the initial exception thrown by the out.write() call. If the exception
> in the finally clause is unrelated, than maybe you should consider using
> the ERROR level instead.
>
> Exceptions that are deemed impossible by the developer should be logged
> at the ERROR level. I mean if they are truly impossible, then they will
> never occur. However, if they do occur, then don't they indicate an
> exceptional condition that the developer had not expected? In my mind at
> least, unexpected and exceptional conditions match the definition of an
> error.
In writing protocols or application containers, ( when you run code that is
supplied by others), I have often had the need for code like the following:
try
{
// invoke somebody elses code or do some protocol stuff
...
}
catch(IOException e)
{
if (log.isDebugEnabled())
{
if (log.isTraceEnabled()) // or similar verbosity level
log.debug("IGNORED "+e);
else
log.debug("IGNORED",e);
}
}
This is for exceptions that the programmer this will never occur. These
are for exceptions that are likely to occur, but that are ignored when
they do.
For example, in Jetty we get's lots of IOExceptions thrown when internet
exploder closes connections mid response. These are not errors or even warnings,
but simply normal operation.
I know from experience that it is not sufficient simply to have a log.debug("IGNORED",e)
that reveals the exception if debug level is on. 90% of programmers running with
debug on are incapable of seeing a stack trace without reacting to it. Many will
see the stack trace and simply will not see the IGNORED and start acting like there
is a problem. Even if a programmer does pay attention to the IGNORED, the sight
of stack traces scrolling by is distracting and can obscure valuable information.
It is not sufficient to have just log.debug("IGNORED "+e) as you are never 100%
certain that you don't need to see the stack trace.
Back to the IOException from IE example, with debug on I like to see that the
exception occured. If I have verbose debug on, then I'd like to see the full
stack trace.
I like to see this provided as
log.ignore(Throwable th);
But I can also do this is a support class like
LogSupport.ignore(Logger log, Throwable th);
but only if there is a verbose log level that support class can use to determine
when to reveal the full stack trace. However, I would really like to see
the ignore method as it is a very very strong encouragement to avoid the dreaded
catch(Exception e) {}
and it would become the standard to have
catch(Exception e) {log.ignore(e);}
> 3) Add a trace level.
>
> I tend to think that the trace level leads to bad practice by
> encouraging too much logging, but others, most notably App server
> developers, seem to disagree. :-)
I agree that trace is badly named and that the name can encourage
too much logging. I'm one that would like to have another level
of debugging, but I'd like to see it called verbose rather than trace.
This name communicates the reason for having the extra log level without
encouraging meanless "I was here" logging everywhere.
App container developers probably feel the need for the extra log level
because we have to deal with our own code, plus information from the
code that we contain. When I have had verbose/trace at my disposal,
I have used debug to log the actions of the container and then used
verbose to log the detail of the exceptions and objects being provided
to the container by the contained code.
Without an extra debug level, I think that encourages developers to
both log too much as normal debugging and to not log other detail that would
be useful in some situations.
> I intend to write a summary of these discussions in the SLF4J FAQ. In
> any case, thank you very much for your input. It is much appreceated.
Neither ignore or verbose are MUST-HAVES. However I do think that
ignore would be a significant contribution to code quality be helping
totally avoid empty catch blocks or exceptions that are logged without
stack traces.
Having a verbose log level would help with the implementation of ignore
and is desirable for many and harmless for those who don't wish to use it.
cheers
> At 12:15 AM 6/22/2005, Greg Wilkins wrote:
>
>> Ceki,
>>
>> I strongly approve of these changes - as it makes it much clearer what is
>> a format and what is a message.
>> However, I would still like to see
>>
>> debug(Throwable t)
>>
>> because I'm not really sure that all exceptions do have a meaning
>> message to go with them - as I would hope that a good exception would
>> be self explanitory as to the reason and location of the problem.
>>
>> I also like to have
>>
>>
>> ignore(Throwable t)
>>
>> as there are exceptions that you "think" will never happen - but they
>> little
>> bastards always do and if you have an empty catch block, then pain is
>> coming
>> your way!
>>
>> cheers
>>
>>
>> Ceki Gülcü wrote:
>> > Hello,
>> >
>> > The org.slf4j.Logger class currently contains the following methods
>> > per log level. For example, for the log level we have:
>> >
>> > debug(Object msg)
>> > debug(Object format, Object arg1)
>> > debug(Object msg, Throwable t)
>> > debug(String format, Object arg1, Object arg2)
>> >
>> > The second and third methods taking two methods can be little
>> > confusing since a Throwable is also an Object. Not every programmer
>> > knows the details of Java overloading rules.
>> >
>> > The fourth method's first parameter is a String while it is an Object
>> > for the first three methods.
>> >
>> > After some discussion [1], we have a proposal for alternate
>> > signatures.
>> >
>> > (1) debug(String msg);
>> > (2) debug(String msg, Throwable t);
>> > (3) debug(String format, Object arg1);
>> > (4) debug(String format, Object arg1, Object arg2);
>> >
>> > The rationale for this choice is explained in [2]. Here are some
>> > salient points.
>> >
>> > - The first enforces the fact that logging systems are about
>> > decorating logging messages of type String.
>> >
>> > A logging system is about decorating and handling String messages. A
>> > logging system is *not* about handling messages of arbitrary types.
>> >
>> > - The only way to log an exception is through the second method, which
>> > goes to enforce the idiom that every exception should have an
>> > accompanying explanatory message.
>> >
>> > - The parameterized printing methods (3) and (4) are present
>> > only for performance reasons.
>> >
>> > - In relatively rare cases where the message to be logged is the
>> > string form of an object, then (2) can be used, as in:
>> >
>> > logger.debug("{}", complexObject);
>> >
>> > The logging system will invoke complexObject.toString() only after
>> > it has established that the log statement was enabled. Otherwise,
>> > the cost of toString() conversion will not be incurred.
>> >
>> > Unfortunately, these changes are not backward compatible (because not
>> > every Object is a String). In the case of JettyExperimental, out of
>> > about 500 log statements, exactly 9 lines of code are affected by these
>> > changes.
>> >
>> > The affected lines that break fall into two categories. In the first
>> > category of affected lines, exceptions are logged using the
>> > debug(Object) method. For example,
>> >
>> > try {
>> > ...
>> > } catch(Exception e) {
>> > log.warn(e);
>> > }
>> >
>> > Exactly 5 lines of code follow this pattern. In the current
>> > implementation of slf4j-simple and nlog4j, this call will *not* print
>> > the stack trace of the exception, but only the message of the
>> > exception, i.e the value returned by e.toString().
>> >
>> > The suggested usage pattern is:
>> >
>> > try {
>> > ...
>> > } catch(Exception e) {
>> > log.warn("explenatory message for the exception", e);
>> > }
>> >
>> > If one is too lazy to write an explanatory message, you can use some
>> > standard text. For example,
>> >
>> > try {
>> > ...
>> > } catch(Exception e) {
>> > log.warn("Exception stack trace follows.", e);
>> > }
>> >
>> > The string "Exception stack trace follows." could also be made into a
>> > constant.
>> >
>> > In the second pattern, the debug(Object) method is invoked with a
>> > message of type other than String. For example,
>> >
>> > log.debug(request);
>> >
>> > where request is of type HttpServletRequest. Exactly 4 lines follow
>> > this pattern. These 4 lines can be transformed to use method 3, For
>> > example,
>> >
>> > log.debug(request);
>> >
>> > can be written as
>> >
>> > log.debug("{}", request);
>> >
>> > which is incidentally much faster for disabled log statements.
>> >
>> > Do you agree with the proposed changes? Comments?
>> >
>> > [1] http://www.slf4j.org/pipermail/dev/2005-June/thread.html
>> > [2] http://www.slf4j.org/pipermail/dev/2005-June/000120.html
>> >
>> >
>> >
>>
>>
>>
>> -------------------------------------------------------
>> SF.Net email is sponsored by: Discover Easy Linux Migration Strategies
>> from IBM. Find simple to follow Roadmaps, straightforward articles,
>> informative Webcasts and more! Get everything you need to get up to
>> speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click
>> _______________________________________________
>> Jetty-support mailing list
>> Jetty-support at lists.sourceforge.net
>> https://lists.sourceforge.net/lists/listinfo/jetty-support
>
>
More information about the slf4j-dev
mailing list