[slf4j-dev] Benefits of Message objects?

[Joern Huxhorn]

On 10.09.2011, at 15:50, Ceki Gulcu wrote:

> 
> 
> By accepting argument of type String[] in its constructor [1], ParameterizedMessage trades immutability for typing information. However, the typing information is required for filtering. So losing typing information is a relatively important loss. Is ParameterizedMessage typical or an unfortunate counter example?
> 
> As for immutability, a careless/malicious developer can still modify the contents of the String[] array. Thus, there is a limit to the level of protection gained from converting Object[] to String[].
> 

I'm not trying to protect against malicious developers because this won't work anyway. (At least not if he is allowed to call AccessibleObject.setAccessible(boolean), i.e. "suppressAccessChecks" permission)
ParameterizedMessage is usually created using the static create-method, btw. This is not about protecting the array against concurrent changes but about preventing concurrent changes of the *content* of that array. And this doesn't have to be malicious but would simply happen in case of Hibernate because the transaction does not span over multiple threads.

> Let's work on a concrete example. Let's say we are working on airspace control system which needs to log flight records.
> 
> Here is a very minimal impl:
> FlightRecord {
>  public String flightCode; // SA 457
>  public long[] currentGPSCoordinates; // the GPS coordinate
> 
>  FlightRecord(String flightCode, long[] currentGPSCoordinates) { ... }
> }
> 
> So given a FlightRecord:
> 
> FlightRecord fr = new FlightRecord("SA 456", new long[] {1, 1, 1}}
> 
> using log4j we would write
> 
>  logger.info(fr);
> 
> and using SLF4J we would write
> 
>  logger.info("{}", fr);
> 
> In both approaches the FlightRecord instance is mutable.
> We could write a wrapper, say FlightRecordWrapper, to render
> FlightRecord immutable:
> 
> FlightRecordWrapper implements Message {
>  final String flightCode;
>  final long[] currentGPSCoordinates;
> 
>  FlightRecordWrapper(FlightRecord fr) {
>     flightCode = fr.flightCode;
>     currentGPSCoordinates = fr.currentGPSCoordinates.clone();
>  }
> }
> 
> If the Message interface were supported in SLF4J, we would write:
> 
>  logger.info(new FlightRecordWrapper(fr));
> 
> This is cleaner than
> 
>  logger.info("{}", new FlightRecordWrapper(fr));
> 
> I am still left with the feeling that the main inconvenience of the "{}" form is its ugliness.
> 

The point is that the default logging calls should definitely convert the arguments to String[] during the creation of the event so the casual user can't end up with lying logs. I'm pretty sure that 99% of all users will only use the "normal" methods without the Message - but the 1% will love you for the *possibility* of having custom Message implementations.

Using a custom Message assumes that you know what you are doing (the documentation of the Message interface should alert the user that he has to keep concurrency issues in mind) so your wrapper above would be a valid implementation (assuming that you'd add the required getFormattedMessage() method) since you take care about concurrent changes.

The Message methods have the additional benefit that they do NOT allow additional arguments. This shines less on the SLF4J side but it has significant benefits in frameworks implementing the API, as Ralph also observed.

Cheers,
Joern.

> --
> Ceki
> 
> [1] https://github.com/huxi/slf4j/blob/slf4j-redesign/slf4j-n-api/src/main/java/org/slf4j/n/messages/ParameterizedMessage.java
> 
> 
> 
> On 10.09.2011 14:02, Joern Huxhorn wrote:
>> 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
>> 
>> _______________________________________________
>> slf4j-dev mailing list
>> slf4j-dev at qos.ch
>> http://qos.ch/mailman/listinfo/slf4j-dev
> 
> 
> -- 
> QOS.ch, main sponsor of cal10n, logback and slf4j open source projects, is looking to hire talented software engineers. For further details, see http://logback.qos.ch/job.html
> _______________________________________________
> slf4j-dev mailing list
> slf4j-dev at qos.ch
> http://qos.ch/mailman/listinfo/slf4j-dev