On 07/09/2011 3:48 PM, Joern Huxhorn wrote:

I will answer that one later today... But it could end TL;DR... ;) No, I'll read it for sure. -- Ceki

Joern Huxhorn wrote:

Ok, huge post is incoming... ;)

Huge post right back at you! I like the idea of using Message objects. Let me start by sharing ideas I have based on my proposal in bug 31, but then I'll come back and try to show that these are complimentary approaches. Goals: 1) Compatibility with legacy loggers 2) Provide supplementary logging information (Map<String, Object> or StructuredData) that appenders can add in some way to the log entry similar to NDC/MDC. 3) Support custom log formatters, such as java.util.formatting 4) A custom log formatter that can use #2 (your example of "{Foo} {Bar} {Foobar}") 5) Lazy & memoized formatting for performance. SUPPLEMENTAL DATA A key part of this is #2, providing "supplementary data" to a log method. For this, we could add the following methods to the Logger interface: public void trace(Map supplementalData); public void trace(Map supplementalData, String msg); public void trace(Map supplementalData, String format, Object... args); public void trace(Marker marker, Map supplementalData); public void trace(Marker marker, Map supplementalData, String msg); public void trace(Marker marker, Map supplementalData, String format, Object... args); and the same for other levels. The supplementalData argument may in fact be a StructuredData implements Map object. Message formatters and appenders can optionally use instanceof to treat StructuredData objects uniquely. This is for bug 148. Bug 31 AbstractLogger's abstract log method could take Map supplementalData as an argument, but see below. FORMATTING The idea in http://bugzilla.slf4j.org/show_bug.cgi?id=31#c94 provides custom formatting: Logger myLogger = LoggerFactory.getLogger(MyClass.class) .formatWith(SLF4JFormatters.JAVA_UTIL_FORMATTER); A new formatter that perfoms substitutions ("{foo}") could be specified this way. Ideally this new formatter would support supplementalData as well as NDC and MDC. COMPATIBILITY #1 Bug 31's style of adding methods to NamedLoggerBase would make it possible to add these features to most pre-existing loggers. Custom formatting would of course require delegating to the trace(String msg, Exception t) style methods which would hide the arg[] from the adapter. Aside from custom formatting, pre-existing loggers would ignore supplemental data. So far, we have #1, #2, #3, and #4, building on the current Logger interface, and providing decent compatibility. MESSAGE OBJECTS Now, to add Message Objects to the application facing API, we could add the following additional methods to the Logger interface (slight change to your proposal, but sticking with current trace/debug/etc. style methods): public void trace(Message message); public void trace(Marker marker, Message message); interface Message { String getFormattedMessage(); String getMessagePattern(); Object[] getParameters(); Throwable getThrowable(); Map getSupplementalData(); } This Message interface is similar your ParameterizedMessage class. Having more than just getFormattedMessage() in the base interface helps provide the adapter all interesting parts of the message. The Logging.formatWith(formatter) option described above would be ignored for logs made with a message parameter. The Message object would be responsible for formatting. The next step is to leverage Message objects in the AbstractLogger interface. Building on bug 31, we now have: protected abstract void log(Marker marker, Level level, Message message); which is very close to what you have, but includes the Throwable as part of the Message. AbstractLogger would wrap arguments to the non-Message Logger methods with a default Message implementation, and include the "formatWith" formatter. Actual adapter implementations would deal only with Message objects, regardless how the call was made. So, this finally gives us #4 - lazy formatting. COMPATIBILITY #2 Similar to COMPATIBILITY #1, we can enhance NamedLoggerBase to support Message objects. Old adapters will be supported. To head off future compatibility issues, all Message implementations should extend an AbstractMessage class. AbstractMessage will basically return nulls (or better, EMPTY_MAP, etc..) for each method. APPLICATION USAGE I think most application code will use the non-Message methods. Having to instantiate a message is a burden unless you really need it. Specifying a custom formatter is easier done one time when creating the logger. If adding supplemental data is required, it may already be available in the form of a Map, or if not, it may be easier to create a Map than a Message object. That being said, I think the ability to override the formatter once or twice in a class, handle specific requirements like the Hibernate issue you raised, or whatever else, makes a very compelling case to support Message objects in the application facing API. John -- View this message in context: http://slf4j.42922.n3.nabble.com/Benefits-of-Message-objects-tp3316674p33181... Sent from the slf4j - dev mailing list archive at Nabble.com.

On 08.09.2011, at 21:11, John Vasileff wrote:

I put together the following examples to help net out benefits of supporting "Map supplementalData" arguments in Logger methods in addition to Message object support.

Support for supplementalData does not replace Message objects, but is perhaps more of a shortcut for common usage scenarios. In the end, a Message object is always created by either the application writer or SLF4J.

Scenario #1: Working with a domain object "posting" that implements java.util.Map. A 1.6.2 error log may look like:

logger.error("error parsing markdown '{}'", badString, e);

but we want to add all details of the "posting" domain object without including them in the message. Using the supplementalData log methods:

// just add the data Logger logger = LoggerFactory.getLogger(MyClass.class); logger.error(posting, "error parsing markdown '{}'", badString, e);

// add the data, but also allow named parameter formatting Logger logger = LoggerFactory.getLogger(MyClass.class).formatWith(NamedParamFormatter.getInstance()); logger.error(posting, "error parsing markdown for posting {id} '{}'", badString, e);

// just add the data, and format using java.util.formatter Logger logger = LoggerFactory.getLogger(MyClass.class).formatWith(JavaUtilFormatter.getInstance()); logger.error(posting, "error parsing markdown '%s'", badString, e);

One huge problem with this approach is that Logger, for a given name/class, has to be a singleton. You absolutely must not change its state, otherwise chaos will happen. I'll give you just one example: Suppose ThreadA is changing the Logger with formatWith. Then, before ThreadA executes its log statement, ThreadB is changing the same instance with a different formatWith call. This will cause ThreadA to log with a wrong formatting. A mutable Logger would automatically make it non-threadsafe. I firmly believe that default formatting must not be configurable. Doing so would just introduce a big pile of problems.

If we used Message objects:

Logger logger = LoggerFactory.getLogger(MyClass.class);

// just add the data logger.error(new DefaultMessage(posting, "error parsing markdown '{}'", badString, e));

// add the data, but also allow named parameter formatting logger.error(new NamedParamFormattingMessage(posting, "error parsing markdown for posting {id} {}", badString, e));

// just add the data, and format using java.util.formatter logger.error(new JavaUtilFormatterMessage(posting, "error parsing markdown for posting %s", badString, e));

Scenario #2: Support for StructuredData. The StructuredData object may augment a log message, or both augment the message and provide the message with toString().

Using SupplementalData methods, where SD implements Map

StructuredData sd = new StructuredData(...); logger.error(sd); logger.error(sd, "some log message");

Using Message object methods, where SD implements Message

StructuredData sd = new StructuredDataMessage(...); logger.error(sd); StructuredData sd = new StructuredDataMessage(..., "some log message"); logger.error(sd);

The idea was to put both the internal structure and the formatting in the respective Message implementation, with ParameterizedMessage being the implementation for the default SLF4J formatting. A shortcut exists for this type of messages, namely the foo(String pattern, Object... args) methods, since this is the message type encouraged by the logging framework. It is encouraged since it is a perfect mix of features (placeholder replacement) and speed (it is *much* faster than JUL and likely faster than most other implementation). It is also the type of formatting already documented by the API and accepted by its users. The 99% of the users will just keep on using the "normal" logging methods and ignore the newly defined ones. This is the main target we are developing for. The foo(Message message) type of methods, however, enable the 1% "pro users" to implement specific features they need - and the logging framework will be able to (optionally, you could filter on the Message class) cope with those arbitrary Message types in a default way or implement specialized handling if that is required. Take the StructuredDataMessage ( http://bugzilla.slf4j.org/show_bug.cgi?id=148 ) as an example. It does not just define a Message with key-value pairs in a Map<String, String>. Instead, it is more specific. It is used to create messages that conform to ( http://tools.ietf.org/html/rfc5424 ). This involves making sure that the keys must have a maximum length of 32 characters. Such a requirement can't be met by the abstract logging interface. It is an implementation detail of RFC5424 Syslog messages. In addition to the Map<String, String>, such a StructuredDataMessage could implement the whole range of the specification, e.g. it could bypass the normal logging levels and make use of the Syslog severities instead. One should not forget that someone implementing his own message type could also define a wrapper around the SLF4J Logger to support efficient creation of his handcrafted Messages. A special SyslogLogger implementation could automatically match the Syslog severity to a proper SLF4J level, for example, while still using the whole logging backend without any wheel-reinvention. Another example for specific needs would be end-user-facing localized messages. Why should I reinvent my own logging layer if I could just use SLF4J/<insert backend here> for that? Audit logging is another use case. See http://audit.qos.ch/manual/index.html and http://audit.qos.ch/apidocs/ch/qos/logback/audit/AuditEvent.html This could be implemented using a AuditMessage instead while still being able to use the full range of Logback-Classic appenders but with the ability to add specific appenders handcrafted for specific tasks like writing them into a special audit database. One small, additional thing is the possibility of immutable Message instances that could be kept and reused if there are no variables involved. Concerning "COMPATIBILITY #1" in your previous message: It is absolutely crucial that the original interface is left unchanged so that both use and implementations of that interface will keep on working as expected. It also needs to stay 1.4 compatible and logging frameworks that do not require 1.5 should still just implement the old SLF4J interface. The new interfaces will be available automatically via wrapper in that case. If the logging implementation requires Java >= 1.5 anyway (e.g. Logback) then it would be a good idea to implement the new interface instead, providing backwards-compatibility by means of a wrapper in the other direction. Concerning your Entry interface: The main idea of the very minimal Message interface is the absolute freedom it gives to the developer. A message does not have to have a pattern and parameters. Why should it? And why should I create an abstract base-class that returns null for all methods that are not applicable to that specific message/entry type? Isn't that enough evidence that the interface would be too specific? I did consider to add Throwable to the Message interface but ultimately decided against it for exactly that reason. It just doesn't make sense for every type of message imaginable. I'm also not a big fan of including either MDC or NDC in the Message since those belong to the LoggingEvent, similarly to the call-stack or the timestamp of the event. Neither of them are visible at the SLF4J interface level. To finish this wall of text: I can not stress enough that the Message interface would enable us to *filter* on the specific type of Message in the logging configuration and/or appender implementation. Granted, a better place for this argument would be the Logback mailing list but it IS a major feature and does indeed open a huge door of possibilities for future enhancements, all without touching the logging interfaces again. Joern

On 09.09.2011, at 19:11, John Vasileff wrote:

On Sep 9, 2011, at 6:23 AM, Joern Huxhorn wrote:

...

On 08.09.2011, at 21:11, John Vasileff wrote:

...

I put together the following examples to help net out benefits of supporting "Map supplementalData" arguments in Logger methods in addition to Message object support.

Support for supplementalData does not replace Message objects, but is perhaps more of a shortcut for common usage scenarios. In the end, a Message object is always created by either the application writer or SLF4J.

Scenario #1: Working with a domain object "posting" that implements java.util.Map. A 1.6.2 error log may look like:

logger.error("error parsing markdown '{}'", badString, e);

but we want to add all details of the "posting" domain object without including them in the message. Using the supplementalData log methods:

// just add the data Logger logger = LoggerFactory.getLogger(MyClass.class); logger.error(posting, "error parsing markdown '{}'", badString, e);

// add the data, but also allow named parameter formatting Logger logger = LoggerFactory.getLogger(MyClass.class).formatWith(NamedParamFormatter.getInstance()); logger.error(posting, "error parsing markdown for posting {id} '{}'", badString, e);

// just add the data, and format using java.util.formatter Logger logger = LoggerFactory.getLogger(MyClass.class).formatWith(JavaUtilFormatter.getInstance()); logger.error(posting, "error parsing markdown '%s'", badString, e);

One huge problem with this approach is that Logger, for a given name/class, has to be a singleton. You absolutely must not change its state, otherwise chaos will happen.

I'll give you just one example: Suppose ThreadA is changing the Logger with formatWith. Then, before ThreadA executes its log statement, ThreadB is changing the same instance with a different formatWith call. This will cause ThreadA to log with a wrong formatting. A mutable Logger would automatically make it non-threadsafe.

I firmly believe that default formatting must not be configurable. Doing so would just introduce a big pile of problems.

I agree 100% that formatting should never be changed once the logger is setup. And I also see that the same instance of Logger is returned for a given name in, for example, Log4jLoggerFactory. But if in the end the idea of formatWith() makes for a nice application facing API, I would hate to rule it out prematurely based on what may be implementation details.

I'm not saying that this would be impossible to implement. It just comes with an enormous cost that is actually threefold: - on the SLF4J implementation side, getLogger() would have to return a new instance for every call. That instance would need to contain an optional formatter that must be configurable on a per Thread base (there's a nasty classloader memory leak lurking in the dark at this point, btw). And what should happen in case of multiple calls to formatWith()? An Exception? - all of the above would have a serious impact on the performance. - you'd need to educate the users about all this. This task is actually entirely futile. ;)

Having said that, I don't really have a strong need for formatWith(...) - java.util.Formatter seems unnecessary to me, so it would just be an added convenience for NamedParameter style formatting. But I do feel that whether in 2.0, 3.0, or whenever, the ability to add this type of feature without breaking binary compatibility is very valuable. So I think it is worth netting out, even if the consensus is that the particular feature of overriding the formatter isn't necessary or desired for 2.0.

...

...

If we used Message objects:

Logger logger = LoggerFactory.getLogger(MyClass.class);

// just add the data logger.error(new DefaultMessage(posting, "error parsing markdown '{}'", badString, e));

// add the data, but also allow named parameter formatting logger.error(new NamedParamFormattingMessage(posting, "error parsing markdown for posting {id} {}", badString, e));

// just add the data, and format using java.util.formatter logger.error(new JavaUtilFormatterMessage(posting, "error parsing markdown for posting %s", badString, e));

Scenario #2: Support for StructuredData. The StructuredData object may augment a log message, or both augment the message and provide the message with toString().

Using SupplementalData methods, where SD implements Map

StructuredData sd = new StructuredData(...); logger.error(sd); logger.error(sd, "some log message");

Using Message object methods, where SD implements Message

StructuredData sd = new StructuredDataMessage(...); logger.error(sd); StructuredData sd = new StructuredDataMessage(..., "some log message"); logger.error(sd);

The idea was to put both the internal structure and the formatting in the respective Message implementation, with ParameterizedMessage being the implementation for the default SLF4J formatting. A shortcut exists for this type of messages, namely the foo(String pattern, Object... args) methods, since this is the message type encouraged by the logging framework.

It is encouraged since it is a perfect mix of features (placeholder replacement) and speed (it is *much* faster than JUL and likely faster than most other implementation). It is also the type of formatting already documented by the API and accepted by its users.

The 99% of the users will just keep on using the "normal" logging methods and ignore the newly defined ones. This is the main target we are developing for.

The foo(Message message) type of methods, however, enable the 1% "pro users" to implement specific features they need - and the logging framework will be able to (optionally, you could filter on the Message class) cope with those arbitrary Message types in a default way or implement specialized handling if that is required.

Take the StructuredDataMessage ( http://bugzilla.slf4j.org/show_bug.cgi?id=148 ) as an example. It does not just define a Message with key-value pairs in a Map<String, String>. Instead, it is more specific. It is used to create messages that conform to ( http://tools.ietf.org/html/rfc5424 ). This involves making sure that the keys must have a maximum length of 32 characters. Such a requirement can't be met by the abstract logging interface. It is an implementation detail of RFC5424 Syslog messages. In addition to the Map<String, String>, such a StructuredDataMessage could implement the whole range of the specification, e.g. it could bypass the normal logging levels and make use of the Syslog severities instead.

In the 99% group, there are some (me!) that would really like to keep everything as is, but also be able to quickly and conveniently add some key/value pair data to the log entry.

But you already have this ability using the MDC. What Ralph requested in #148 was specific support for the Syslog format as specified by RFC5424

I was trying to show that this also supports bug 148. StructuredData could implement Map<String,Object>. Loggers that understand only Map<String,Object> would at least handle the parts that are exposed by the Map interface. Loggers that understand StructuredData could provide 100% custom handling, such as creating a Log4j2 StructuredDataMessage from the StructuredData object. In either case, key length validation, etc. would be handled by the StructuredData class.

But when would it be handled and what happens if the key is too long? Would the Logger throw an exception in case of Log4J2 but work in case of Logback? Or would the key-length be truncated to 32 chars? This could result in duplicates that overwrite each other. Using Syslog with RFC5424 is a rather specific requirement. I never heard of it before Ralph issued that bug report. I have serious doubt that lots of users know about it. And what happens if the RFC is superseded by a new one that suddenly allows 64 chars? How would you implement this supporting both the 32 and the 64 version? If all of this is logic is contained in specific Message implementations then it would be a no-brainer to support either one. The documentation of the requirements could reside in the Javadoc of the respective Message and everyone is happy. It wouldn't be a very good idea to directly implement the Map interface as this interface does not impose any of those restrictions. It would be technically possible but semantically not entirely correct.

I think it would be valuable to introduce supplementalData/namedParameters to the masses, while also providing things like StructuredData to advanced users.

Having messages with placeholders like {variableName} come at a cost. Would you really like to use it regularly even if it imposes worse performance and also forces you to write bigger logging statements? Are you really sure? ;) I know that it *sounds* nice, initially, but is there really a use-case beside "Oh, that would be neat."? The statement logger.info("User {}", user); would (minimally, using an absolutely awfully hacky interface (we'd never implement it that way)) look like this: logger.info("User {user}", "user", user); A more reasonable implementation would even look like this: Map<String, Object> parameters = new HashMap<String, Object>(); parameters.add("user", user); logger.info("User {user}", parameters); It just creates more noise in the code, IMHO.

To be clear: I am not suggesting we avoid Message/Entry in favor of supplementalData/namedParameters. I think the Message concept is great and think we should have both. Use supplementalData/namedParameters as a quick way to add data to an entry, or use Message/Entry to "take over" all data and formatting of the log entry.

...

One should not forget that someone implementing his own message type could also define a wrapper around the SLF4J Logger to support efficient creation of his handcrafted Messages. A special SyslogLogger implementation could automatically match the Syslog severity to a proper SLF4J level, for example, while still using the whole logging backend without any wheel-reinvention.

Another example for specific needs would be end-user-facing localized messages. Why should I reinvent my own logging layer if I could just use SLF4J/<insert backend here> for that?

Audit logging is another use case. See http://audit.qos.ch/manual/index.html and http://audit.qos.ch/apidocs/ch/qos/logback/audit/AuditEvent.html This could be implemented using a AuditMessage instead while still being able to use the full range of Logback-Classic appenders but with the ability to add specific appenders handcrafted for specific tasks like writing them into a special audit database.

One small, additional thing is the possibility of immutable Message instances that could be kept and reused if there are no variables involved.

I think all of these would be supported - I am trying to build on your proposal.

For localized messages specifically, there may be a really nice way to handle this with "formatWith(...)" - I'll have to give it some thought. But in any case, Message/Entry objects could always be used. In any case, I agree 100% that SLF4J should handle localization, otherwise we would be breaking pluggability of back end loggers.

It wouldn't have to, at least not initially. Putting that logic into other Message implementations would mean that we don't have to implement it in SLF4J, at least not initially. This could be added conveniently in, say, SLF4J 2.1 or 2.2. Whenever we have an implementation ready that we deem good, stable and mature enough to add it to the general API.

...

Concerning "COMPATIBILITY #1" in your previous message: It is absolutely crucial that the original interface is left unchanged so that both use and implementations of that interface will keep on working as expected. It also needs to stay 1.4 compatible and logging frameworks that do not require 1.5 should still just implement the old SLF4J interface. The new interfaces will be available automatically via wrapper in that case.

If the logging implementation requires Java >= 1.5 anyway (e.g. Logback) then it would be a good idea to implement the new interface instead, providing backwards-compatibility by means of a wrapper in the other direction.

I think we are in agreement here, and we definitely cannot break < 2.0 Logger implementations. In 2.0, I think we can enhance org.slf4j.Logger, maintain compatibility, and even provide many of the new features to 2.0 api users that choose to use a < 2.0 logger.

But you can not enhance org.slf4j.Logger without breaking compatibility in at least the implementations of that interface. Further, if you enhance org.slf4j.Logger with JDK 1.5 features then it would be impossible to use in applications that are still using something else (not only JDK 1.4 but probably also Android, I'm not sure). Leaving the original interface untouched and redefining a new interface in a different package is the only way that is really safe, allowing both implementations to exist side by side. Apache enhanced their commons-lang module the same way. See http://java.dzone.com/articles/first-look-at-commons-lang-3 This is the only chance of guaranteeing compatibility in both directions. And this is crucial if you take into consideration the amount of third-party libraries that depend on the current SLF4J. They would simply eat us alive if we fail on this. (both scenarios are already tested in my redesign-branch)

If I am right, I think this is a huge advantage, both in improving the feature set for older Logger users, and in sticking with only one interface rather than making users move to a different one (and for new users, avoid confusion about two Loggers, etc.)

Yes, a new package is an annoyance. People are accustomed to this, though. JUnit did it. commons-lang did it, lots of others did it, too. In contrast to some of the mentioned frameworks, our change could *really* be done by a global search & destroy...err....replace over the whole source tree. The old API calls will translate perfectly to the new ones. This is not binary compatibility *but* semi-source-compatibility (i.e. the package must be replaced).

I'll provide more detail on this soon.

...

Concerning your Entry interface: The main idea of the very minimal Message interface is the absolute freedom it gives to the developer. A message does not have to have a pattern and parameters. Why should it? And why should I create an abstract base-class that returns null for all methods that are not applicable to that specific message/entry type? Isn't that enough evidence that the interface would be too specific? I did consider to add Throwable to the Message interface but ultimately decided against it for exactly that reason. It just doesn't make sense for every type of message imaginable.

My idea is to encapsulate all data and formatting for a log entry, and simplify all interfaces. The Entry interface basically defines the fundamental data components we are providing to Logger implementations. There aren't that many methods, and having them all here provides the ability for Entry classes to handle all data aspects of an entry, and clarity that this can be done. I'll add more thoughts on this later.

There simply isn't necessarily anything in common for such entries. An AccessLogger is logging an entirely different type of event than a classic LoggingEvent. The same is the case for AuditLogging.

...

I'm also not a big fan of including either MDC or NDC in the Message since those belong to the LoggingEvent, similarly to the call-stack or the timestamp of the event. Neither of them are visible at the SLF4J interface level.

I haven't spent much time looking at MDC/NDC, but if (somewhere) there is support for named parameters, it might be nice to do:

("user {mdcUserId} had a problem with {}", problemString)

A problem I have had with NDC before is that I have disabled logging NDC info to cut down on noise. This would provide a mechanism to force a particular value into a message when it is relevant. Just a thought.

Yes. It would be kind of nice, I agree. But it would also result in a significantly slower message formatting simply because the formatter would have to be a lot more complex. The default formatter is deliberately "dumb". It does not support reordering of arguments as JUL does, for example. Neither are localized messages supported. This results in a way better performance - and we are not talking about 1 ns. (Perhaps Ceki can share some numbers on this, if he is still with us ;)) We don't want to degrade the performance of the whole system for everyone simply because there is a use-case for messages like this. If someone wants this functionality then he can implement a Message supporting this style of formatting. We could (and probably should) implement a Message that provides this functionality in SLF4J at some point. But we should do so with great care. I'd imagine an implementation with a fluent interface, i.e. something like new MappedMessage("User {user} just entered {method}.").add("user", "Foouser").add("method","Barmethod") Keep in mind that those messages won't be localizable, either. Adding localized messages is not trivial at all if you want to do it properly. Simply using the system locale would not be sufficient, for example, since different locales for different users of a web-application isn't a very far-fetched scenario. We actually really considered building a special (Logback) appender that puts logging events (e.g. the last ten) into the session for consumption in the view. Right now those would all have the same locale but a special Message implementation that would also contain the requested output locale could provide such a functionality. This implementation would use the JUL-Messagestyle that is referring to arguments using {0} {1:format} and so on since the functionality is already available in the JDK and translations must be able to reorder and replace arguments..

...

To finish this wall of text: I can not stress enough that the Message interface would enable us to *filter* on the specific type of Message in the logging configuration and/or appender implementation. Granted, a better place for this argument would be the Logback mailing list but it IS a major feature and does indeed open a huge door of possibilities for future enhancements, all without touching the logging interfaces again.

Joern _______________________________________________ slf4j-dev mailing list slf4j-dev@qos.ch http://qos.ch/mailman/listinfo/slf4j-dev

Additional thoughts on StructuredData: mapping to Syslog severities raises an interesting question. Perhaps Event should also encapsulate Level and Marker. I know you are suggesting a more simple Message object, and this pulls in the opposite direction, but it would really provide a clean design whereby an application could specify _only_ the syslog severity, and the StructuredData class could handle mapping to trace/debug/etc. levels. The interface would simply be:

public log(Entry entry);

Entry would provide full power and encapsulation over individual log events. If I had time I would try to rework some of my above comments with this in mind, but we are just sharing ideas, right?

Yes, I'm indeed pulling into the opposite direction. ;) The LoggingEvent is indeed as much implementation detail as it can get in a logging framework. And they indeed differ significantly in the different implementations (JUL vs. Log4J vs. Logback vs. Lilith that is supporting a union of all information contained in any of them). The purpose of SLF4J is to shield the user from all of this by means of a common interface that is as simple as possible but not simpler. This is also one of the reasons why I defined a BaseLogger interface that is even simpler than the Logger interface we are accustomed to. One could work with just that simple interface, but at the cost of convenience. You could indeed implement a separate SyslogLogger interface that would specifically support exactly this. But the implementation of that interface should wrap a SLF4J-Logger, not implement its interface. Otherwise you'd still be able to create Syslog-Messages that are logged with the wrong level (compared to the severity) by mistake/user-error. And if we can prevent user-errors, we should. I really hope that all this does not come across arrogantly or that you feel bashed by me. I appreciate this discussion very much! It's just that I have given that whole issue a rather big amount of thought in the last years. I stumbled into several dead-ends in the process (extending the original Logger interface was one of those) but I'm also pretty confident that my latest proposal was pretty win-win concerning the requirements & features. The fact that I still like it more than a year later is also a good sign. :D Cheers, Joern.

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@qos.ch http://qos.ch/mailman/listinfo/slf4j-dev

On Sep 10, 2011, at 6:50 AM, Ceki Gulcu wrote:

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.

Not just its ugliness. Logback always formats the message when creating the event which will convert FlightRecordWrapper. I can imagine a use case where I filter FlightRecordMessages to a particular Appender and then serialize them using Avro, Hession or something similar so generating the formatted message is unnecessary. It is also much easier to write Appenders or Layouts that simply do if (message instanceOf MyMessage) { MyMessage myMsg = (MyMessage) message; // do stuff to my message } else { // do something else } rather than MyMessage myMsg = null; for (Object obj : event.getArgumentArray()) { If (obj instanceOf MyMessage) { myMsg = (MyMessage) obj; break; } } if (myMsg != null) { // Do stuff to my message } else { // do something else. } I should also note that at some point LocationAwareLogger wasn't even passing the argument array so EventLogger had to convert the EventData to an XML String. When you added the argument array to LocationAwareLogger you modified EventLogger to pass a null, not the EventData object. So using EventLogger is very expensive. Ralph

On Sep 10, 2011, at 12:50 PM, Ceki Gülcü wrote:

...

I should also note that at some point LocationAwareLogger wasn't even passing the argument array so EventLogger had to convert the EventData to an XML String. When you added the argument array to LocationAwareLogger you modified EventLogger to pass a null, not the EventData object. So using EventLogger is very expensive.

It would be trivial to correct EventLogger wouldn't it?

It would have before you switched to git :- ) - I lost my commit privs when you did that. Ralph

On Sep 10, 2011, at 3:31 PM, Ceki Gülcü wrote:

On 10/09/2011 10:47 PM, Ralph Goers wrote:

...

On Sep 10, 2011, at 12:50 PM, Ceki Gülcü wrote:

...

...

I should also note that at some point LocationAwareLogger wasn't even passing the argument array so EventLogger had to convert the EventData to an XML String. When you added the argument array to LocationAwareLogger you modified EventLogger to pass a null, not the EventData object. So using EventLogger is very expensive.

It would be trivial to correct EventLogger wouldn't it?

It would have before you switched to git :- ) - I lost my commit privs when you did that.

I am sorry about for offhandedly taking away your commit privileges to slf4j-ext during the move to git. I incorrectly assumed git's features, i.e. forking and sending pull requests, were a substitute for svn commit privileges. I meant no offense.

It wasn't a matter of being offended - I knew it wasn't personal. But it was/is a significant barrier to participation. It meant that, in effect, I had/have to get your permission to commit anything. I'm not a big fan of Review-Then-Commit so I'm even less a fan of commit and hope its promoted. In effect, this is exactly why I think it has taken the ASF so long to incorporate git as an alternate source control system. Ralph

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

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@qos.ch http://qos.ch/mailman/listinfo/slf4j-dev

_______________________________________________ slf4j-dev mailing list slf4j-dev@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@qos.ch http://qos.ch/mailman/listinfo/slf4j-dev

On 07.09.2011 21:47, Joern Huxhorn wrote:

Ok, huge post is incoming... ;)

To properly explain the reason for Message I should start with my redefinition of the Logger interfaces.

## core.BasicLogger

I created a BasicLogger interface ( https://github.com/huxi/slf4j/blob/slf4j-redesign/slf4j-n-api/src/main/java/... ) that merely defines the following methods: boolean isEnabled(T level); void log(T level, Message message); void log(T level, Message message, Throwable throwable);

As you can see, Message is already used in this interface. The idea is that several different Logger systems can be created extending it, e.g. Classic, Access or your Audit logger.

Access does not have use for Level nor Throwable. Audit has no use for Level. Logback-audit has quite a different API than logback-classic. For example, exceptions thrown during audit logging are rethrown to the user as AuditExceptions. It is not obvious that merging developer (classic) logging, access logging and audit logging into a single API makes sense. Cheers, -- 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

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

On 07.09.2011 21:47, Joern Huxhorn wrote:

...

Ok, huge post is incoming... ;)

To properly explain the reason for Message I should start with my redefinition of the Logger interfaces.

## core.BasicLogger

I created a BasicLogger interface ( https://github.com/huxi/slf4j/blob/slf4j-redesign/slf4j-n-api/src/main/java/... ) that merely defines the following methods: boolean isEnabled(T level); void log(T level, Message message); void log(T level, Message message, Throwable throwable);

As you can see, Message is already used in this interface. The idea is that several different Logger systems can be created extending it, e.g. Classic, Access or your Audit logger.

Access does not have use for Level nor Throwable. Audit has no use for Level. Logback-audit has quite a different API than logback-classic. For example, exceptions thrown during audit logging are rethrown to the user as AuditExceptions. It is not obvious that merging developer (classic) logging, access logging and audit logging into a single API makes sense.

The idea here was to use https://github.com/huxi/slf4j/blob/slf4j-redesign/slf4j-n-api/src/main/java/... as the "Level" for AccessLogging. I assumed that such a general category exists for most cases. I'm not sure about Audit logging but I assume that it also contains events of different importance/kind. (I don't think that this package should end up in the final version of this jar. It is only there as an example.) In case of access logging it would make sense to just log 4xx and 5xx, only 5xx or to log those events into different files. This general support for categories is implemented to support guarding with the isEnabled method. Level is probably a bad name for the variable in that signature. It is there for historic reasons. ;) Cheers, Joern.