[slf4j-dev] Benefits of Message objects?

[Joern Huxhorn]

Hi Ceki,

You are right, the perceived behavior is the same in case of, say, a console appender.

But the lazy evaluation is actually one of the issues that I'm trying to resolve.

I'd like to prevent an issue like this at all costs:
http://techblog.appnexus.com/2011/webkit-chrome-safari-console-log-bug/

If the arguments are kept as Object[] instead of converting them to Strings in the same Thread and at the time of the logger call then stuff like this can happen in case of asynchronous appenders. Hibernate can also throw LazyInitializationException if lazy members are accessed outside of the surrounding transaction. My example of an appender that serves events to the view of a webapp in my previous mail would be one example of that. If a member of one of it's arguments is changed before the message is created then it would behave like the webkit bug above. 

Because of this, I convert all arguments to their String representation while creating the ParameterizedMessage (only after the checks have determined that the call should actually emit an event, obviously). This, in turn, means that the types/original objects are lost in the process, making it impossible to filter on them.

Something similar must be done regardless of the existance of a Message interface/implementation. (I remember that we discussed this in the past but I don't know if I was able to convince you about how crucial I consider this - nothing is worse than a lying logging framework. Other than a logging framework crashing the application, of course, but I think we nailed that already in the MessageFormatter.)

Since the creation of a Message instance is rather expensive I assume that a performance-conscious person will surround it with a isXxxEnabled() guard. I further assume that Message implementations take care of transforming critical/mutable Objects into String or some other thread-safe/immutable type during creation. Otherwise I'd consider that a bug in the Message implementation. I thought about adding a prepareForDeferredProcessing() method to the Message interface but decided against it. I'd instead document this necessity in the Message interface.

In #148 Ralph requested the ability to log StructuredData without having to parse the String representation. This could be done using a StructuredDataMessage that contains the key/value pairs in a Map<String, String>, meaning it would still contain the Map but wouldn't contain any mutable instances anymore, making it thread-safe.

Beside all this I really do like the expressiveness gained compared to the "workaround" of info("{}", sd).
info(Message) is like an info(Object) method, but with a "type-safe documentation" attached by means of the Message interface.
I'd, personally, consider it bad style to just dump any object in a log message. So I wouldn't allow or encourage this and therefore wouldn't want to add an info(Object) signature to the logger.

Hope this explains the difference sufficiently,
Joern.

On 09.09.2011, at 23:54, Ceki Gülcü wrote:

> Hi everyone,
> 
> After reading this thread, I am still trying to establish whether the
> Message interface is needed especially compared to the following
> approach:
> 
> StructuredData sd = new StructuredData(..., aMap, ...);
> logger.info("{}", sd);
> 
> Granted, the above is not intuitive but other than that:
> 
> 1) it allows filtering on parameter type
> 
> 2) formatting of StructuredData is done lazily using the toString
> method of StructuredData
> 
> 3) it requires no changes to SLF4J
> 
> I do not wish to be obtuse and I apologize if this question was asked
> previously. Unfortunately, I don't recall the answer. Seriously, what
> is wrong with logger.info("{}", sd) ?
> 
> Cheers,
> -- 
> Ceki
> _______________________________________________
> slf4j-dev mailing list
> slf4j-dev at qos.ch
> http://qos.ch/mailman/listinfo/slf4j-dev