[logback-dev] RFC: LoggingEvent redesign

[Joern Huxhorn]

Hi Ceki

On 24.02.2009, at 20:00, Ceki Gulcu wrote:

>
> Joern,
>
> Accepting parameters of type Object instead of String opens the door  
> for nasty bugs as you point out. At the same time, it also  
> constitutes an important extension point for logback within the  
> limits imposed by the SLF4J API.
>

At this point I'm wondering if such an extension is really a good idea  
at all.

Don't use a hammer to screw a screw. Ok, it would kind of work, but  
you'd be better of using a screwdriver instead.

The hammer is slf4j/logback, a magnificent framework for application  
logging. The screwdriver would be an auditing framework (see http://audit.qos.ch/apidocs/index.html 
  :D).
A pretty good indicator that slf4j is, in fact, the wrong tool for the  
job, is that log levels are mostly meaningless in an audit context.

> I think that the org.slf4j.Logger class should contain a waring (in  
> red) about the arguments being evaluated asynchronously.

But, uhm, don't get me wrong but... isn't the SLF4J concept of  
parameterized logging kind of pointless with that warning in place?

What am I supposed to do about that warning? I mean as the user of  
slf4j?

I'd like to log the state of an object so I call logger.debug("{}",  
object). With the warning above I have not the slightest idea when the  
event will actually be handled. It could happen synchronously or in  
two days (rhetoric exaggeration). In the next line of my own code I  
change something in that object and log it again in the same way.

Essentially 4 things can happen at this point:
1.) everything works as *I* would expect it to, i.e. synchronous  
logging with the two different states of the object.
2.) two events are created, both containing the state of the object  
after my second change.
3.) neither 1.) nor 2.) but *some* other state is logged because I'll  
keep changing my object and the events are handled *much* later.
4.) the events would contain some senseless garbage because my object  
(as most) isn't thread-safe and the evaluation of toString() would  
happen while the object is being changed in my thread.

I'd seriously go nuts in the cases 2.) to 4.) and you could probably  
hear my scream in Switzerland ;)
(You know, I'm a bit touchy about debugging tools that lie to me...  
The Codewarrior debugger once lied to me about the content of  
variables and I had a screenshot to prove it but, unfortunately, I  
lost it while leaving the company...)

My only chance to prevent this uncertainty would be logger.debug("{}",  
object.toString()) which isn't much better than the log4j methods,  
right?

I'm really wondering why nobody else panics about those scenarios.  
Such a change could potentially break lots of existing code!

> At present time, we serialize stringified version of the arguments.  
> However, we could imagine that certain types, such as maps and  
> collections, or other well-defined types be serialized as is  
> (without transformation into String). Thus, not only would be it  
> possible to take advantage of specific object types locally but also  
> remotely.

This would complicate logback. A lot.

It also has the real risk of creating what we call "eierlegende  
Wollmilchsau" in Germany. That's a fantasy animal that produces eggs,  
wool, milk and ham. There just isn't any suitable translation for it  
that does the original justice. dict.leo.org translates it to "all-in- 
one device suitable for every purpose" but it's just not the same. The  
idea is that you simply won't be able to create such a thing and,  
therefore, would inevitably fail trying.

Instead of trying to be everything for everyone just stay focused on  
the main topic.

> Regarding the lazy evaluation of LoggingEvent fields such as caller  
> data and others, the current approach is highly dynamic. For  
> example, if an appender named A requires caller data but is not on  
> the processing path of the current logging event, then caller data  
> will not be evaluated. Setting caller data evaluation as an option  
> at the level of the logger context is not as flexible.

It's not as flexible but also more deterministic. I'd know, for sure,  
what data will be obtained. If I'm not interested in caller data then  
no appender will be able to force it on me. The appender would be  
required to be able to cope with missing information instead.

> Moreover, if any single appender performs the computation of a given  
> field in logging event, that field become available for all  
> subsequent appenders.

In my case, the field will be available to all appenders if it is  
enabled in the logger context. It would simplify a lot. It would, for  
example, prevent the comment in AsynchronousAppenderBase that  
ThreadName and CallerData must be obtained synchronously if required ;)
Appenders would just use the events as they receive them - without any  
worries...

> I tend to think that the way logging event does lazy evaluation of  
> fields works quite well.

That's correct with the current appenders but asynchronous appenders  
would fail horribly with the current implementation because both  
caller data and thread name would be wrong. Both would return the data  
of the thread executing the respective getter method instead of the  
correct data from the originating thread...
If the lazy initialization of those fields would be done synchronously  
while the event is created, the event would have a real chance to be a  
candidate for immutability (see my previous mail).

I'm not talking about the lazy formatting of messagePattern +  
arguments to message because that wouldn't be a problem since the  
worst case is formatting more than once in case of threading chaos.  
Since both messagePattern and arguments won't change nothing bad can  
and will happen. It would just be less efficient but nobody would get  
"hurt" in the process...

Joern.