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.