[Bug 70] New: " logging a stack trace along with a parameterized string" solution proposal

20 messages Options
Embed this post
Permalink
Bugzilla from bugzilla-daemon@pixie.qos.ch

[Bug 70] New: " logging a stack trace along with a parameterized string" solution proposal

Reply Threaded More More options
Print post
Permalink
http://bugzilla.slf4j.org/show_bug.cgi?id=70

           Summary: " logging a stack trace along with a parameterized
                    string" solution proposal
           Product: SLF4J
           Version: 1.4.x
          Platform: All
        OS/Version: All
            Status: NEW
          Severity: enhancement
          Priority: P1
         Component: Core API
        AssignedTo: [hidden email]
        ReportedBy: [hidden email]


I have an idea how to solve the problem of logging both a parameterized message
as well as a Throwable.

Please take a look at my patch.

I think the 1.5 version bump would be the ideal time to introduce this change.


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
http://bugzilla.slf4j.org/show_bug.cgi?id=70





------- Comment #1 from [hidden email]  2008-01-27 17:05 -------
Created an attachment (id=24)
 --> (http://bugzilla.slf4j.org/attachment.cgi?id=24&action=view)
A solution proposal.

I introduced a new method throwableAwareArrayFormat to replace the method
arrayFormat. This method returns a MessageFormat.Result containing both the
formatted message and, optionally, an exception.

The MessageFormat.Result.getThrowable() is only non-null if
- the last argument is of type Throwable and is not used while formatting the
message
- the last argument is of type Throwable and the messagePattern contains
invalid parameters. This is done so that the stack-trace is still available
even if the message contains an error. I thought this is ok because otherwise
you could probably miss an important exception because the pattern is wrong in
case of a very rare log statement...

This means that the Throwable is NOT returned if it's used in the message and
guarantees that no unexpected stack-traces will show up.

I deprecated arrayFormat so implementing projects can easily find the new
replacement method.
I also added test cases for the different scenarios.

This change should not produce any incompatibilities to prior versions because
superfluous arguments were previously just ignored.


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





------- Comment #2 from [hidden email]  2008-01-28 12:28 -------
Created an attachment (id=25)
 --> (http://bugzilla.slf4j.org/attachment.cgi?id=25&action=view)
Previous proposal + fix for bug #61.

I included a fix for bug #61 incl. tests.


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70


[hidden email] changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
  Attachment #24 is|0                           |1
           obsolete|                            |




--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





------- Comment #3 from [hidden email]  2008-01-28 12:47 -------
btw, I'm not proud about the method-name throwableAwareArrayFormat. Feel free
to change it to your liking ;)


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70


[hidden email] changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |REMIND




------- Comment #4 from [hidden email]  2008-01-29 20:48 -------
I am inclined to decline this patch for the sake of simplicity.

Considering that message formatting is just a trick to improve performance,
there is no real performance loss in writing:

} catch(Exception e) {
 logger.error("Problem saying hello to " + name, e);
}

instead of

} catch(Exception e) {
 logger.error("Problem saying hello to {}", name, e);
}

However, the latter form causes the exception to be lost, which is pretty bad.
I think this can be dealt with by style correctors such as Checkstyle or PMD.
It should also be possible to write our own IDE plugin.

In short, I am wary of introducing a new behaviour to the org.slf4j.Logger
interface even if the method signatures remain the same.


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





------- Comment #5 from [hidden email]  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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70


[hidden email] changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |REOPENED
         Resolution|REMIND                      |




------- Comment #6 from [hidden email]  2008-01-31 14:48 -------
Thank you for these comments. I intend to reconsider.


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70


[hidden email] changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|REOPENED                    |ASSIGNED




--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





------- Comment #7 from [hidden email]  2008-02-08 15:07 -------
(In reply to comment #4)

> Considering that message formatting is just a trick to improve performance,
> there is no real performance loss in writing:
>
> } catch(Exception e) {
>  logger.error("Problem saying hello to " + name, e);
> }
>
> instead of
>
> } catch(Exception e) {
>  logger.error("Problem saying hello to {}", name, e);
> }

I think its more about writability and readability of the code:

} catch(Exception e) {
    log.error("No row with id '{}' found", e, id);
}

} catch(Exception e) {
    log.error("No row with id '" + id + "' found", e, id);
}


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





------- Comment #8 from [hidden email]  2008-02-10 14:52 -------
(In reply to comment #7)

> (In reply to comment #4)
> > Considering that message formatting is just a trick to improve performance,
> > there is no real performance loss in writing:
> >
> > } catch(Exception e) {
> >  logger.error("Problem saying hello to " + name, e);
> > }
> >
> > instead of
> >
> > } catch(Exception e) {
> >  logger.error("Problem saying hello to {}", name, e);
> > }
>
> I think its more about writability and readability of the code:
>
> } catch(Exception e) {
>     log.error("No row with id '{}' found", e, id);
> }
>
> } catch(Exception e) {
>     log.error("No row with id '" + id + "' found", e, id);
> }
>

Should the above code look like this

} catch(Exception e) {
    log.error("No row with id '{}' found", id, e);
}

} catch(Exception e) {
    log.error("No row with id '" + id + "' found", e);
}

or are you suggesting that the Exception should be put before the parameters? I
wouldn't like that at all, especially because I know people expect it the other
way around...


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





------- Comment #9 from [hidden email]  2008-02-11 08:43 -------
(In reply to comment #8)
> or are you suggesting that the Exception should be put before the parameters?

In that example I was thinking about a varargs case, i.e. error(String msg,
Throwable t, Object... params), with just one parameter. However, that doesn't
mean I'm suggesting such version of the method to be introduced.


--
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.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70


Thorbjørn Ravn Andersen <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[hidden email]




--- Comment #10 from Thorbjørn Ravn Andersen <[hidden email]>  2008-09-14 15:19:05 ---
(In reply to comment #8)

> (In reply to comment #7)
> > (In reply to comment #4)
> > > Considering that message formatting is just a trick to improve performance,
> > > there is no real performance loss in writing:
> > >
> > > } catch(Exception e) {
> > >  logger.error("Problem saying hello to " + name, e);
> > > }
> > >
> > > instead of
> > >
> > > } catch(Exception e) {
> > >  logger.error("Problem saying hello to {}", name, e);
> > > }
> >
> > I think its more about writability and readability of the code:
> >
> > } catch(Exception e) {
> >     log.error("No row with id '{}' found", e, id);
> > }
> >
> > } catch(Exception e) {
> >     log.error("No row with id '" + id + "' found", e, id);
> > }
> >
>
> Should the above code look like this
>
> } catch(Exception e) {
>     log.error("No row with id '{}' found", id, e);
> }
>
> } catch(Exception e) {
>     log.error("No row with id '" + id + "' found", e);
> }
>
> or are you suggesting that the Exception should be put before the parameters? I
> wouldn't like that at all, especially because I know people expect it the other
> way around...
>

Ceki brought my attention to the debate here in
http://www.qos.ch/pipermail/logback-user/2008-September/000579.html

The basic problem here as I see it is that we have a traditional log4j approach
of logging a string with an optional exception tagged at the end, which has
then be found to work strangely with the Javac 1.5 varargs construction which
has been introduced to work nicely with the {} construction.

If we keep using varargs it will not work without having to analyze the runtime
types of the passed arguments _somewhere_ at runtime instead of letting the
java compiler sort this out at compile time.  I don't like that.

Instead I suggest dumping varargs in the slf4j layer altogether and simply
create the many methods for having up to X arguments with and without an
exception.  Currently X is two (these kind of things you learn when you work in
1.4 world) which is a bit low.  I suggest raising X to e.g. 5 which covers most
cases I have met.  If you need more than that you must create an Object[]
yourself.


--
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





--- Comment #11 from Joern Huxhorn <[hidden email]>  2008-09-14 19:53:09 ---
I can only argue that *every* person (I think about seven already) that talked
to me about this shortcoming of slf4j/logback was *always* assuming that the
exception was the last of the given arguments.

I even received some Lilith bug reports that guessed that it was a Lilith
problem that the exceptions wouldn't show up. That's one of the reasons why I
implemented a "fix" in my own appenders.

I'm also using the unformatted message in serialized events so my code is
essentially counting the placeholders to find out if a Throwable is supposed to
be used as a Throwable or just as a String for the given message.
Therefore it should be even faster during creation of the actual logging event.
(Please take a look at
http://lilith.svn.sourceforge.net/viewvc/lilith/trunk/lilith-data/logging/src/main/java/de/huxhorn/lilith/data/logging/MessageFormatter.java?view=markup
and
http://lilith.svn.sourceforge.net/viewvc/lilith/trunk/lilith-data/logging/src/main/java/de/huxhorn/lilith/data/logging/LoggingEvent.java?view=markup
if you are interested. The code doesn't reflect Cekis latest changes concerning
parameterized logging, yet)

I wouldn't consider this a hacky at all, either, since RTTI is available in
Java anyway - at a very moderate cost - and in other languages, e.g. printf in
C, something like that is also very common.
I don't remember the exact syntax so please don't hit me if I get it partially
wrong but essentially printf("%d", aTimestamp) in C does just assume that
aTimestamp is a date.

On the other hand, I don't think it would be very wise to add lots of new
method signatures to the Logger interface even though it's absolutely possible,
without any compatibility impact, to support the requested functionality in a
very transparent manner.

With "without any compatibility impact" I mean that the only change in behavior
will be that logging events with previously erroneously superfluous Throwables
will suddenly show them as most likely expected by the developer.

While compile-time type safety is something very nice, it shouldn't impact the
design of an API in a way that makes it *much* more complex.
What, exactly, would be the benefit of type safety at this specific location?

What would be the way to actually use the throwable.toString() in a
parameterized logging message? Would you expect to manually use ""+throwable in
that case? Otherwise the method with Throwable as the first parameter would be
used.

I disagree that this would be a valid solution.


--
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





--- Comment #12 from Thorbjørn Ravn Andersen <[hidden email]>  2008-09-15 14:49:22 ---
(In reply to comment #11)
> I can only argue that *every* person (I think about seven already) that talked
> to me about this shortcoming of slf4j/logback was *always* assuming that the
> exception was the last of the given arguments.

This I would too (and I don't think I said otherwise above).

I thought it some more over, and it just dawned on me that my suggestion with
replacing varargs with explicit methods is source compatible but not binary
compatible (I would still like them, as you need to write new Object[] {a, b,
c....} already with more than two arguments, and varargs is just AFAIK syntatic
sugar on the Object[] argument).

> I even received some Lilith bug reports that guessed that it was a Lilith
> problem that the exceptions wouldn't show up. That's one of the reasons why I
> implemented a "fix" in my own appenders.

I think that the approach with simply defining the semantics of the arguments
leftover after the formatting is sound, and I suggest the following (which  can
later be expanded):

==
"If there are more arguments supplied than placeholders in the message strings,
the following rules apply after the message string has been formatted:

*  If and only if  there is exactly one unused argument object AND "object
instanceof java.lang.Exception" is true, then the stack trace from the object
is logged with the formatted message

* All other situations are undefined
"

There should probably be a reference to the method used to log the stack trace
:)

> What would be the way to actually use the throwable.toString() in a
> parameterized logging message? Would you expect to manually use ""+throwable in

I understand that per default the String.valueOf(object) is used.  I cannot
remember right now if and where user supplied toStringgers can be supplied.
This would apply to all parameters used for formatting.

I would strongly suggest to keep the rules simple - otherwise it WILL bite some
day :)


--
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70


Joern Huxhorn <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[hidden email]




--- Comment #13 from Joern Huxhorn <[hidden email]>  2008-09-28 21:22:50 ---
The code referenced in comment #11 does now reflect Cekis latest changes
concerning parameterized logging.
Thanks, Ceki, this approach is much cleaner and simpler than before. I could
throw away quite a bit of code and thats always Nice(tm).

My code does the following:
1.) Counting of placeholders in the message pattern (very cheap)
2.) Conversion of argument array into an ArgumentResult, containing the
arguments converted to String as well as an optional Throwable if available
(relatively cheap, but needs to be done)
3.) Replacement of placeholders in a message pattern with arguments given as
String[]. (most expensive)

Only step 1 and 2 are performed during construction of a LoggingEvent. The
actual formatting of the message is done lazily on demand.

The current implementation in Logback performs the formatting of the message in
the c'tor of LoggingEvent, i.e. every time even if it's not really necessary
(e.g. if just sent and not written to a logfile).
The formatted message also isn't transient so it will be serialized even though
it could be regenerated on demand after deserialization (both messagePattern
and arguments are still available).

The code above, if included that way or another in slf4j, would increase
logging performance significantly but it won't do so right now because Lilith
works on Logback events that already formatted the message in the c'tor
beforehand.

Concerning step 2, the rules are the following:
- If all arguments are used up, simply convert them to String[].
- Otherwise, if the *last* argument is a Throwable use that as a the Throwable
and convert *all* other arguments to String[], i.e. resulting args.length ==
originalArgs.length-1.

I have a rationale for that behavior:
Given that we still have the unformatted message pattern we could use it as a
translation id. The translated message could then contain a message like
"{1}{0}{2}" to be able to reorder the original arguments. Furthermore, it could
contain more arguments than the original message. I wouldn't consider this very
good style but I didn't want to prevent it explicitly.

@Thorbjørn: Sorry, I didn't mean to imply that you wanted to put the Throwable
before the arguments, although it reads like it.
I think I assumed something like that because you asked for compile time type
safety which, in combination with varargs, implies the Throwable before the
arguments.
My fault...

Real 1.5 varargs in slf4j are, btw, discussed in bug #31


--
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70


Stephen Duncan Jr <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[hidden email]




--
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





--- Comment #14 from Joern Huxhorn <[hidden email]>  2008-11-12 17:10:50 ---
Just wanted to mention that my code is reflecting the latest formatting changes
for a while now:

http://lilith.svn.sourceforge.net/viewvc/lilith/trunk/lilith-data/logging/src/main/java/de/huxhorn/lilith/data/logging/MessageFormatter.java?view=markup
http://lilith.svn.sourceforge.net/viewvc/lilith/trunk/lilith-data/logging/src/main/java/de/huxhorn/lilith/data/logging/LoggingEvent.java?view=markup


--
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70





--- Comment #15 from Joern Huxhorn <[hidden email]>  2009-03-30 14:12:03 ---
FYI, I've further enhanced my code in the meantime.

logger.debug("Argument {}", new String[]{"Foo", "Bar"});

will now result in the message

Argument [Foo, Bar]

instead of

Argument Foo

This means that there is special handling of a single placeholder.
If the last argument is *not* a Throwable *and* there is only a single
placeholder, the first argument will be the array itself and not the first
entry of the array.

Otherwise it would be necessary to write the above as
logger.debug("Argument {}", new Object[]{new String[]{"Foo", "Bar"}});
to get the desired result...

See also bug #112.

Comments?


--
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev
Bugzilla from bugzilla-daemon@pixie.qos.ch

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

Reply Threaded More More options
Print post
Permalink
In reply to this post by Bugzilla from bugzilla-daemon@pixie.qos.ch
http://bugzilla.slf4j.org/show_bug.cgi?id=70


Nicolas Lalevée <[hidden email]> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[hidden email]




--
Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
_______________________________________________
dev mailing list
[hidden email]
http://www.slf4j.org/mailman/listinfo/dev