[logback-dev] RFC: LoggingEvent redesign

[Ceki Gulcu]

Hello Joern,


I see your hammer and screwdriver analogy. However, while the
hammer-screwdriver analogy is reasonable and valid in the case of
extending slf4j/logback-classic for auditing purposes, it is not
*always* valid. Morre importantly, even if the analogy is valid, it
does not necessarily mean that Ralph usage is wrong. It may be
something that was not exactly foreseen when slf4j was designed, but
it is not wrong.

In abstract terms, allowing Object-typed argument arrays is intended
as a last ditch extension point.

There are many data points contained in a logging event. There are
fairly fixed and structured points such as the time, logger, level and
the exception. There are less structured data points such as the MDC,
and logger context properties. The logging event message is a special
case, in the sense that it can hold any string value and assuming a
object-to-string encoding mechanism, it can be used to transport
objects. (Logback does not provide any such encodings nor does it
explicitly support such a transport mechanism.) The only remaining
unstructured data point is the argument array, typed as Object[].

Assume you write applications for a supermarket chain called
SMart. Application deployed at SMart mostly deal with objects of type
Article. You can either create a new logback module called
logback-article which deals exclusively with objects of type Article,
or you can extend logback-classic with special appenders and
converters which can deal with arguments of type Article. If you chose
the latter, you will bve using argumentArray as an extension point to
support special use cases. Object typed argument arrays can be misused
and abused. They are an uncontrolled extension point which one can be
described as "eierlegende Wollmilchsau". Nevertheless, they allow
users to extend logback-classic to support special use cases. While
Object-typed argument array are dangerous, they are not senseless.

As for shouting all the way to Switzerland. The residency regulations
in Vaud the Canton where I reside, forbid loud noises between 10PM and
6AM. (I couldn't resist evoking the cliché.)

 > 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...

The prepareForDeferredProcessing() method in the LoggingEvent class
addresses that problem. Whenever a logging event is about to be
serialized or transferred to another thread, you, as an author of an
appender, are supposed to call loggingEvent.prepareForDeferredProcessing().

Caller data is pretty interesting because it is not and cannot be
covered by prepareForDeferredProcessing(). However, all is hope is not
lost. Assuming a logging event knows about the thread that created it,
and if a later time it is asked to compute caller data, it can refuse
to do so if the current thread is not the original thread. It's a
relatively easy check to add in LoggingEvent.



Joern Huxhorn wrote:
> 
> 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.
> 
> 
> _______________________________________________
> logback-dev mailing list
> logback-dev at qos.ch
> http://qos.ch/mailman/listinfo/logback-dev
> 

-- 
Ceki Gülcü
Logback: The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch