[slf4j-dev] [Bug 70] " logging a stack trace along with a parameterized string" solution proposal

[bugzilla-daemon at pixie.qos.ch]

http://bugzilla.slf4j.org/show_bug.cgi?id=70





------- Comment #5 from joern at huxhorn.de  2008-01-30 12:26 -------
This patch does not introduce any change in behavior because superfluous
arguments are already omitted without further notice in the current
implementation. *If* the omitted argument is a Throwable it would be used as
the throwable of the event which is most likely the expected behavior in that
case - I really can't imagine another reason beside a missing {} in the
messagePattern, but even in that case a stack trace in the log event would be
better than omitting the exception altogether.

The big plus of this change would be enhanced consistency, especially if bug
#31 is eventually reconsidered.

If we consider log.xxx(msg) a plain message, log.xxx(msg, throwable) a message
incl. an exception and log.xxx(messagePattern, Object[] args) a parameterized
message then I think the expected signature for a parameterized log message
would be log.xxx(messagePattern, Object[] args, Throwable t).*

This would pose a problem for a future varargs enhancement so the signature
should/must be log.xxx(messagePattern, Object[] argsAndPossiblyException)
instead.

After having a good night of sleep I realized that the
MessageFormatter.format(...)-methods would also have to be deprecated because
the behavior would only be consistent if a call to log.xxx(messagePattern,
Object args1, Object arg2) would behave the same as log.xxx(messagePattern,
Object[] args, Throwable t), i.e. evaluate arg2 as a throwable if it's not used
in the messagePattern and instanceof Throwable. A call to log.xxx(msg,
throwable) would then behave exactly the same as a call to log.xxx(msg,
(Object)throwable) which is IMHO a very good thing.

As you said: "However, the latter form causes the exception to be lost, which
is pretty bad."
This is exactly what it's all about. I've seen this in our code base several
times simply because people naturally *expect* the behavior described above and
this really is *the* common slf4j pitfall.

I even wrote lines like that myself despite the fact that I *know* that it's
wrong.

It also has the downside that you can't simply add an exception to an already
existing method call because you have to change the message to concatenation
before you can add the Throwable.

On a side-note, I tend to write log-messages like log.debug("msg", new
Throwable()) to have the stack-trace at this point of code without having to
enable the call stack for the whole application. I'd consider this a good
practice because the Throwable won't be created if there is an
if(log.isDebugEnabled()) prefix and the impact is much lower than creating call
stacks for *all* log-messages. This is also one of the situations were I
sometimes just want to add a Throwable to an existing message without having to
reformat it.

So the only difference in behavior that will happen with my patch in place (if
the implementing modules use the new methods instead of the old) would be that
previously ignored exceptions - most likely because of an error - will show up.

I'm not really after this feature because of performance. I'm more interested
in a consistent way to write log messages.

The parameterized version of log messages is much more readable than one that
includes concatenation because the message and the parameters are properly
separated. It just feels a bit like a kludge to always use parameterized
messages except for logs that include an exception, e.g. you can't establish a
coding-guideline like "Always use parameterized log messages instead of String
concatenation".

And if you plan to bump the slf4j version to 1.5 then it would be an ideal time
to define this new/extended behavior and deprecate all the previous
MessageFormatter methods. Modules implementing the slf4j-api should then change
their implementation accordingly while switching to 1.5. If they don't fix the
deprecation warnings nothing would explode but the exception would just be
swallowed exactly as before.

As you have probably realized by now, I'm a *big* fan of both slf4j and
logback. That's why I try to streamline it as much as possible or, let's say,
remove the last remaining wrinkles.

In my opinion, slf4j has only two downsides:
a) no varargs (bug #31)**
b) no parameterized messages incl. exceptions (bug #70)

They can both be fixed in ways that wouldn't change anything for current users
except that stuff that *didn't* work before, but was nevertheless tried, will
suddenly work. I really can't imagine a situation where something bad/wrong
could happen - I wouldn't have suggested this, otherwise, because I'm pretty
paranoid about such changes myself. My change would just introduce *additional*
behavior in cases were the behavior was most likely already expected.

Instead of writing bug detectors for a common pitfall, why not just fix the
pitfall altogether?


* That's at least the signature that people always expected while writing a
wrong log message like the one in your example that swallows the exception.
** Did you have a chance to look at my second proposal concerning bug #31? I
consider it *much* better than my previous version number hack...


-- 
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.