[logback-dev] RFC: LoggingEvent redesign

[Joern Huxhorn]

Ceki Gulcu wrote:
>
>
> 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.
I wasn't trying to say that Ralph is doing anything wrong and I
sincerely hope that he does not have that impression. I have no idea
about audit logging at all so both Ralph and you will probably know very
well what you are doing.
He is using undocumented behavior, though, if I'm not entirely mistaken.
> 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[].
I disagree. I just implemented an enhanced version of the log4j NDC
myself as you suggested on the SLF4J mailinglist. It's implemented quite
similar to the logback MDC but isn't serialized/used by any standard
appender. My multiplex-appenders, on the other hand, *are* evaluating
it, thus adding an additional data point to the LoggingEvent.
Wouldn't a similar extension be possible in Ralphs case?
> 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.
I never said they are senseless, in fact I absolutely see that there
*could* be a very valid use case - even though I can't think of one
right now. In the above case, I'd simply use the "normal" logger and
live with it.

I just say that the LoggingEvent should (and I would even say must) be
completely initialized at the time of the log statement execution to
prevent  mayhem like false log statements or even worse situations.

Perhaps an additional hook in Logger is needed to support pluggable
behavior (like Processor in addition to Appender - but this is just a
spontaneous idea) but that, too, would have to be executed synchronously
because asynchronous behavior is simply undefined in most cases.
> 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é.)
LOL, I'll try to time it properly :D
>
> > 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.
While all that sounds reasonable it is way more complex than deciding
globally if thread name and/or caller data should be evaluated or not.
There are just less surprises for everyone involved. It's also
guaranteed to have the same performance as the more flexible version.
If someone enabled caller data and isn't actually using it in any
appender then it will be slower but this would essentially be a
misconfiguration, wouldn't it?

Ok, I see a downside.

It's currently possible to evaluate caller data only on a small subset
of the events, depending on the attached appender... that wouldn't be
possible anymore... hmmmm...

I'm wondering how others are using Logback... I've always enabled caller
data and can live with the fact that it's somewhat slower if actually
logging something but very fast if no log event is actually generated...

I'll think about that some more...

Joern.