Revisit Commons Logging vs java.util.logging vs SLF4J vs Log4j 2 [SPR-14512]

[spring-projects-issues]

Juergen Hoeller opened SPR-14512 and commented

Following up on recent discussions about the good old Commons Logging vs SLF4J conflict (a manual exclusion needed in the POM etc) and the recent attractiveness of Log4J 2's logging API:

Let's revisit our logging API arrangement. A straight migration to SLF4J doesn't seem to be a worthwhile option from a 2017 perspective, in particular since Log4J 2 actually has a nicer API. However, a straight migration to Log4J 2 isn't ideal either since so many people use SLF4J at the moment. And of course, none of those "simple" migration options addresses the problem of backwards compatibility with Spring extensions which happen to use our exposed protected logger reference... which is a hard Commons Logging reference in pre-compiled binaries.

Beyond a straight migration, we may also introduce our own logging abstraction (sigh). Alternatively, we could ship a variant of the Commons Logging API in our own spring-core.jar, controlling the target binding through our own adaptive setup logic: This is essentially what the JCL-over-SLF4J adapter does, and it seems to work fine there. As long as we're able to bind to java.util.logging, SLF4J and Log4J 2 without too much hassle (ideally through autodetection in the classpath), it might be a sweet compromise for the backwards compatibility issue.

Of course, it would also be nice to have a richer logging API available for our internal purposes. Log4J 2 looks quite attractive there but we might not want to require it at runtime, in particular for SLF4J users or java.util.logging users in application server environments. We could also use a facade of our own internally or augment our variant of Commons Logging accordingly.

---

Affects: 5.0 M1

Issue Links:

• Revisit subsystem-oriented logging [SPR-8122] #12774 Revisit subsystem-oriented logging
• Migrate logger from commons-logging to slf4j (remove commons-logging dependency) [SPR-6607] #11273 Migrate logger from commons-logging to slf4j (remove commons-logging dependency)
• DATACMNS-1040 Remove exclusion for Commons Logging
• spring-core source jar contains two copies of source code [SPR-15462] #20022 spring-core source jar contains two copies of source code
• Consider migrating from Commons-Logging to SLF4j [SPR-5327] #10000 Consider migrating from Commons-Logging to SLF4j
• commons-logging LogFactory and String arguments [SPR-16226] #20774 commons-logging LogFactory and String arguments
• Fix compilation warning on JDK 9: use deprecated method LogRecord.setMillis [SPR-15453] #20014 Fix compilation warning on JDK 9: use deprecated method LogRecord.setMillis
• Remove duplicate commons logging classes from spring-jcl [SPR-16062] #20611 Remove duplicate commons logging classes from spring-jcl
• spring-jcl routes logging inefficiently against SLF4J with log4j-to-slf4j setup [SPR-17586] #22118 spring-jcl routes logging inefficiently against SLF4J with log4j-to-slf4j setup

0 votes, 11 watchers

[spring-projects-issues]

Marten Deinum commented

Related: #11273, #10000

I really hope Spring won't come up with YALA (Yet Another Logging Abstraction) as there are already many of those (this xkcd comic comes to mind). Also auto-detection of loggers isn't that what made a mess out of Commons Logging in the first place?!.

[spring-projects-issues]

Juergen Hoeller commented

From my perspective, Commons Logging just has a bad reputation due to its rather naive early versions, but also due to the personal agenda of SLF4J's original creator. Anyway, leaving history aside, Commons Logging actually works quite well in its later incarnations as long as its API as well as the logging provider are shipped with the application. Runtime detection is only an issue if the Commons Logging API itself is shipped in common class loaders (e.g. Tomcat level), with the actual logging provider living in a more specific class loader (e.g. WAR level). That wouldn't work with SLF4J either but nobody even attempted it there so nobody perceived it as a design flaw. In all other respects, Commons Logging is not really different from what many other frameworks do in terms of runtime detection, including us all over the place against so many third-party providers. I mean, take Boot...

As for this ticket, it is primarily about improving usage scenarios:

• no manual exclude of standard Commons Logging necessary for SLF4J users
• straightforward setup with Log4J 2 (ideally not requiring SLF4J or any special Commons Logging bridge on the classpath)
• automatic defaulting to java.util.logging if none of the above is present at runtime (primarily for app server deployments)

And as a bonus, we'd love a richer logging API available to us internally. Log4J 2's API looks most attractive there among the existing options. A custom Supplier-based arrangement for log messages, efficiently bound to Java 8 method references, looks quite attractive as well.

So with those goals taken into account, I'm not quite sure what the solution will be. The only friction-free outcome might be a logging arrangement of our own, possibly with variants of the Commons Logging API classes shipped in spring-core.jar for backwards-compatibility purposes (similar to how we do it for the AOP Alliance interfaces already) but with the logging provider logic implemented by ourselves, similar to how SLF4J does it.

[spring-projects-issues]

Juergen Hoeller commented

A related discussion, including what libraries should be doing: https://www.reddit.com/r/java/comments/5mqkq5/why_you_should_prefer_the_log4j2_api_to_slf4j_in/

[spring-projects-issues]

Phil Webb commented

One sensible step in 5.0 might be to make all Log log members private. We seem to remember that we have a few protected ones at the moment which causes binary compatibility issues. A major release would be a perfect time to hide those so that logging concerns don't leak.

[spring-projects-issues]

Juergen Hoeller commented

We don't accidentally expose protected Log fields, we do so across implementation hierarchies so that they always log under the concrete class name. So they automatically leak to custom subclasses as well, for plenty of class hierarchies in the core container as well as in the web framework... extended by other portfolio projects as well application-specific subclasses.

If we turned all Log fields private, we'd break binary compatibility for all such subclasses and make it unnecessarily hard to have a logging-under-concrete-class-name arrangement. It would help for future log library changes, but at this point I'm rather concerned about the immediate breakages for existing 4.x-based extensions, and about not logging under abstract base class categories.

[spring-projects-issues]

Juergen Hoeller commented

I've opted for the approach with an embedded org.apache.commons.logging.Log interface in spring-core, combined with a custom org.apache.commons.logging.LogFactory implementation with a detection switch between Log4J 2.x, SLF4J 1.7, and java.util.logging as a fallback. This means that any typical Commons Logging LogFactory.getLog(Class/String) keeps working fine in source and binary compatible form, with no need for an external jar.

This implementation does not support any of Commons Logging's flexible configuration. In that sense, it works as a replacement for the Log4j 2 Commons Logging bridge as well as the JCL-over-SLF4J bridge, both of which become irrelevant for Spring-based setups as a consequence (with no need for manual excludes of the standard Commons Logging API jar anymore either). Furthermore, for simple setups without an external logging provider, Spring does not require any extra jar on the classpath anymore since our embedded log factory automatically switches to java.util.logging in such a scenario.

The Log4j 2 and SLF4J bridges will still work when on the classpath, with either such an external bridge or our spring-core Commons Logging bridge being picked up depending on classpath order... but since they're leading to equivalent delegation at runtime, this doesn't really matter. Nevertheless, the whole point of this exercise is to remove the need for such external bridges (and the corresponding standard Commons Logging API exclude), so let's drop them wherever we can and streamline our project setups and application starters accordingly.

As a side note, our new java.util.logging adapter is more efficient than the good old Commons Logging Jdk14Logger implementation since it resolves the source location lazily (like the JBoss Logging JUL adapter does). This won't make a difference for default JUL setup which always includes that class and method location. However, if the log output is configured to avoid the source location, we skip its expensive resolution completely now, just like Log4J and SLF4J do.

This arrangement works fine for me locally, so I'll commit it to master tonight. Let's see what the platform integration tests say...

[spring-projects-issues]

Phil Webb commented

Will this cause classloader issues if an app server provide a version of the commons-logging jar? The problem I can see with this approach is there's now no way to exclude org.apache.commons.logging.Log. If the parent classloader provides org.apache.commons.logging.Log but we've got our own copy in spring-core I think we might end up with cast exceptions.

We're also very likely to end up in the situation where two copies of org.apache.commons.logging.* classes end up on the classpath. It's highly likely that jcl-over-slf4j ends up on the classpath.

I know the existing commons-logging dependency isn't ideal, but I'm worried that copies of classes in spring-core might cause more issues. The current situation is at least well understood and for Boot most users not even something they need to worry about.

[spring-projects-issues]

Phil Webb commented

/cc Andy Wilkinson since he's been involved in the Spring Boot LogggingSystem pain.

[spring-projects-issues]

Juergen Hoeller commented

As I was hinting at above, the Log4j 2 and SLF4J bridges will still work when on the classpath: It's then just a matter of classpath order, but since our own bridge and their bridges lead to the same end delegate, the outcome doesn't really matter. And in the end, the whole point is that those bridges shouldn't be on the classpath anymore. Since no libraries bring those bridges onto the classpath themselves, this is something Boot 2.0 can control in its project starter setups.

As for application server scenarios, application-local classes always override server-level classes. From our perspective, we always want our delegate to be used, never the application server's. There can't be any cast exceptions either if our local variant is consistently used. It's certainly worse if somebody forgets to declare a Commons Logging dependency and unintentionally ends up using a server-level Commons Logging API with a locally embedded logging provider; that leads to exactly the class-cast pain that Commons Logging is so famous for. As far as I can see, our embedded setup avoids any such potential.

That said, let's see what we encounter in integration tests. I'd at least like to try this approach and see how far we get in our CI builds.

[spring-projects-issues]

Andy Wilkinson commented

As I was reading the description of the changes, the same concern that Phil's described came to mind. I'm not sure that we'll end up with class cast exceptions as the parent class loader's version should be preferred, but it does sound like the new arrangement will be very sensitive to a second copy of the org.apache.commons.logging.* classes appearing on the class path (either in a parent class loader or in the same class loader) and the order in which they appear. If spring-core appears first then its version should be preferred and its detection logic will be used, but if the other copy appears first then its detection logic will be used instead. That could lead to an unexpected change in logging back end when a new dependency is added that happens to pull in commons logging.

[spring-projects-issues]

Juergen Hoeller commented

Talking to Phil on Skype, I'll push this tonight and we can see how it goes, rolling it back if necessary.

Andy, I've been spending quite a bit of time looking at third-party projects around us, and as far as I'm aware, as of Spring 5, we do not support any that bring in Commons Logging anymore (e.g. no Velocity anymore). So this shouldn't be a problem in practice, and if it is for some esoteric case, we can work out a solution for those affected.

My take is simply that we need to first-class align with Log4J 2 as well as SLF4J out there, and equally well with java.util.logging. Requiring extra bridge jars for those, even with a manual exclude necessary, is unnecessary pain for the 99% of users out there falling into those three categories. That's what need to address.

At least, Log4J 1.x is EOL now, as are other historic Commons Logging backends. We literally only have three logging API targets to deal with in 2017.

[spring-projects-issues]

Juergen Hoeller commented

A deep-dive brought forward that we technically still got three supported optional dependencies which depend on Commons Logging:

• Apache HttpClient
• Castor XML
• HtmlUnit

All of them seem to work fine against our embedded variant, but of course all three declare a dependency on Commons Logging in their POM and therefore require an explicit exclude in order to arrive at a clean classpath. That's no different from using them with the regular Log4J 2 Commons Logging adapter or with JCL-over-SLF4J, of course, in which case they require the same exclude. And for java.util.logging, both our adapter and the standard Commons Logging factory fall back to it at runtime anyway, so it doesn't really matter which one gets picked up. We should document the recommended exclude for those three libraries though.

[spring-projects-issues]

Andy Wilkinson commented

In aligning Spring Boot with this change, it's become apparent that we also need to consider dependencies upon org.slf4j:jcl-over-slf4j. It is quite widely used, including all of our Spring Data projects. The build for Spring Boot's starters is configured to fail when there are multiple copies of the same class on the classpath. The build for every Spring Data-related starter failed due to transitive dependencies upon jcl-over-slf4j and spring-core. Given Spring Data Kay's Spring Framework 5 base, it would seem to be reasonable for the Spring Data projects to drop their dependency upon org.slf4j:jcl-over-slf4j in the Kay release train.

[spring-projects-issues]

Juergen Hoeller commented

Oliver Drotbohm, since you've been the original trigger for this change, I suppose dropping jcl-over-slf4j (and the corresponding Commons Logging exclude) from Spring Data Kay is ok with you?

[spring-projects-issues]

Andy Wilkinson commented

This change has caused an interesting failure in Spring Boot's Maven plugin (it depends upon spring-core) when using Maven 3.2. The failure is:

Caused by: java.lang.NoClassDefFoundError: org/slf4j/spi/LocationAwareLogger
	at org.apache.commons.logging.LogFactory$Slf4jLog.<init>(LogFactory.java:274)
	at org.apache.commons.logging.LogFactory$Slf4jDelegate.createLog(LogFactory.java:150)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:95)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:83)
	at org.springframework.core.io.support.SpringFactoriesLoader.<clinit>(SpringFactoriesLoader.java:59)
	at org.springframework.boot.loader.tools.Repackager.getLayoutFactory(Repackager.java:207)
	at org.springframework.boot.loader.tools.Repackager.repackage(Repackager.java:173)
	at org.springframework.boot.maven.RepackageMojo.repackage(RepackageMojo.java:212)
	at org.springframework.boot.maven.RepackageMojo.execute(RepackageMojo.java:199)
	at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:132)
	... 20 more
Caused by: java.lang.ClassNotFoundException: org.slf4j.spi.LocationAwareLogger
	at org.codehaus.plexus.classworlds.strategy.SelfFirstStrategy.loadClass(SelfFirstStrategy.java:50)
	at org.codehaus.plexus.classworlds.realm.ClassRealm.unsynchronizedLoadClass(ClassRealm.java:259)
	at org.codehaus.plexus.classworlds.realm.ClassRealm.loadClass(ClassRealm.java:235)
	at org.codehaus.plexus.classworlds.realm.ClassRealm.loadClass(ClassRealm.java:227)
	... 30 more

As far as I can tell, the Plexus class loader allows org.slf4j.LoggerFactory to be loaded, but prevents access to org.slf4j.spi.LocationAwareLogger. I think that's what's signified by this debug output:

[DEBUG]   Imported: org.slf4j.* < plexus.core

Could the check in LogFactory for SLF4J being on the classpath be tightened up a bit?

[spring-projects-issues]

Oliver Drotbohm commented

I am happy to remove the dependency to jcl-via-slf4j for the Kay release.

[spring-projects-issues]

Juergen Hoeller commented

org.slf4j.spi.LocationAwareLogger is a "richer" variant of org.slf4j.Logger that we're conditionally using (through an instanceof check) to pass in extra information, namely to declare the logger adapter's class name in order to properly filter out the application-lvel source location within SLF4J. The regular jcl-over-slf4j does essentially the same thing.

We could differentiate between LocationAwareLogger vs regular Logger presence and have two distinct log adapters for each. JBoss Logging seems to the same, as far as I can see, so such a scenario with non-spi presence of SLF4J seems to be common enough.

[spring-projects-issues]

Juergen Hoeller commented

I've pushed a revision which differentiates between LocationAwareLogger and plain Logger presence for SLF4J.

[spring-projects-issues]

Oliver Drotbohm commented

Bringing this up to the team today we've wondered: if our jcl-to-slf4j dependency is causing problems, what does that mean to anyone pulling in a JCL like JAR into their projects by accident. Doesn't that make everything blow up then as well? If so, that sounds like a risky move.

[spring-projects-issues]

Juergen Hoeller commented

This only fails if there is some explicit validation for overlapping packages on the classpath in the build process, like with Boot's starters - which is a good thing.

In a lenient runtime arrangement, it's simply first-one-wins on the classpath. Since either adapter eventually delegates to SLF4J there, it won't make a difference.

[spring-projects-issues]

Andy Wilkinson commented

I've identified this change as the cause of a problem in Spring Boot. The root cause is a call to LogManager.getContext(). By contrast, Log4J2's SLF4J binding calls LogManager.getContext(ClassLoader, boolean). Crucially, the boolean is false whereas the no-args variant defaults to true.

[spring-projects-issues]

Juergen Hoeller commented

As per my concurrent comment on the Boot issue, this is aligned in our LogFactory in master now.

[spring-projects-issues]

Juergen Hoeller commented

I've revisited a simple but noteworthy part of the Commons Logging API: It accepts messages of type Object, like Log4J 2 but unlike SLF4J. The main benefit here is lazy resolution of the toString() result for non-Strings, which we we've been honoring for Log4J 2 and JUL already but not for SLF4J yet: I've revised this now, with String messages passed through to SLF4J directly whereas non-Strings are guarded by an explicit log level check within the adapter.

This means that callers of our Commons Logging bridge (in particular: our own framework code) can rely on lazy resolution of log message objects now, without extra isXxxEnabled guards. Commons Logging may not have direct support for SLF4J-style message arguments or Log4J-2-style message supplier callbacks (also appearing in Java 8's JUL version) but it does allow for lazy resolution of any kind of log message object. I quite like the simplicity-vs-power ratio here: Passing in a simple object wrapping a formatted message or a Supplier callback with a corresponding toString() implementation is trivial, and we could even provide such a thing out of the box if we'd like to commonly use it ourselves as an alternative to isDebugEnabled + debug blocks.

From that perspective, I see no need for a logging SPI to have native message argument support or Supplier support. An Object message is entirely sufficient, with possibly LogMessage.of(Supplier<String>) and LogMessage.of(String msg, Object... args) utilities provided separately. This radically reduces the number of overloaded methods on the log target itself and provides consistent rendering across different log providers as well as the flexibility to implement custom message formats, at the expense of a short-lived message object that a modern-day JVM will very efficiently garbage-collect. It's almost worth inventing such a minimal but powerful logging abstraction in 2017; fortunately, we have it in the form of Commons Logging already :-)

[spring-projects-issues]

Juergen Hoeller commented

Since WebSphere traditionally ships its own variant of Commons Logging, I've researched the impact of our embedding on Spring-on-WebSphere deployment:
https://www.ibm.com/support/knowledgecenter/en/SSAW57_9.0.0/com.ibm.websphere.nd.multiplatform.doc/ae/ctrb_classload_jcl_conf.html
https://www.ibm.com/support/knowledgecenter/SSAW57_9.0.0/com.ibm.websphere.nd.multiplatform.doc/ae/ctrb_classload_jcl.html#ctrb_classload_jcl__jsr47_classes

In "Parent First" mode, it's always WebSphere's own version of Commons Logging getting picked up. It does not make a difference whether the application contains a variant of Commons Logging itself: an application-level variant is always being ignored. Therefore it doesn't make a difference whether we embed our own variant versus JCL-over-X bridges or the standard Commons Logging jar.

In "Parent Last" mode (which we generally recommend for Spring applications on WebSphere), our embedded bridge will be picked up, just like JCL-over-X bridges before. The only option not available anymore is "Parent Last" with no Commons Logging API in the application but this doesn't make much of a difference: Our embedded bridge will delegate to java.util.logging by default, which is exactly what WebSphere's own default Commons Logging setup does... since WebSphere's actual logging subsystem is implemented as a JUL provider.

That said, there is one specific feature of WebSphere's Commons Logging variant that we can easily adopt: support for JUL LogRecord as a message object, bringing our bridge even closer to WebSphere's own provider. And if this still turns out to be insufficient for a particular application for any reason, there's always the option to stick with "Parent First" and enforce delegation to WebSphere's own Commons Logging variant.

The most important limitation of our embedded bridge is that - like the JCL-over-SLF4J and JCL-over-Log4J bridges - it doesn't support custom LogFactory implementations, i.e. no commons-logging.properties file and no META-INF/services/org.apache.commons.logging.LogFactory manifest entry. If this turns out to be an issue (which is highly unlikely in 2017+), there are a few ways out:

• Putting the standard commons-logging jar onto the classpath first (might be unreliable to enforce in a container environment).
• Switching an application's custom LogFactory implementation to a custom SLF4J binding (which any such application probably has already in order to redirect other libraries' SLF4J logging, in which case we would pick it up by default anyway, leading to the same runtime outcome).
• Asking us to support commons-logging.properties and META-INF/services/org.apache.commons.logging.LogFactory in our embedded bridge. This is straightforward enough to do but I'd rather wait for this to be raised for a concrete scenario since it is highly unlikely that it will ever be needed.

[spring-projects-issues]

Juergen Hoeller commented

I've revised our logging chapter in the reference documentation accordingly: including setup instructions for Log4j 2.x, SLF4J with Logback, java.util.logging, and an explicit discussion of Commons Logging on WebSphere. Since some of our previous notes there were a bit misleading, I'll also do a mild revision of that chapter for 4.3.8.

[spring-projects-issues]

Juergen Hoeller commented

On a related note, here's a summary of our optional third-party libraries and their hard logging dependencies:

SLF4J (still requiring an extra log4j-slf4j-impl setup for Log4j 2.x but no jcl-over-slf4j jar anymore when used with Spring 5):

• Apache Tiles
• EhCache
• JsonPath
• Rome (RSS/Atom)
• Quartz
• WebJars Locator

Commons Logging (requiring a manual commons-logging exclude for use with Spring 5, just like with JCL-over-SLF4J right now):

• Apache HttpClient
• Castor XML
• HtmlUnit

JBoss Logging (with Log4j and SLF4J detected at runtime plus a fallback to JUL, without extra bridge jars - just like in Spring 5):

• Hibernate ORM
• Hibernate Validator
• Undertow

It's noticeable that our most relevant companion is actually JBoss Logging now... which we are very nicely aligned with. SLF4J isn't as common as a primary API choice as the community at large seems to believe: For our purposes, it is Logback's API, with a side job as the logging facade for a couple of second-tier libraries.

[spring-projects-issues]

Juergen Hoeller commented

I'm considering to move our Log/LogFactory variant, which is completely self-contained, to a separate spring-jcl.jar. This would be the very same code but then an independent and excludable fork of Commons Logging that we declare a dependency on in spring-core: as fine in terms of addressing the usability problems that triggered this ticket (first-class support for Log4j 2 and also for SLF4J without any excludes or manual adding of bridges, while retaining out-of-the-box support for JUL), at the expense of an extra artifact on the classpath... with the latter being totally transparent at least, since spring-core would transitively bring it in and nobody would ever need to exclude it (unless somebody really insisted on traditional Commons Logging with its support for the EOL'ed Avalon logger and the EOL'ed Log4j 1.2).

[spring-projects-issues]

Sam Brannen commented

I think spring-jcl.jar is a good idea, especially since it gives users the option to exclude it if such a need should arise. (y)

[spring-projects-issues]

Rob Winch commented

Juergen Hoeller I've come up with another use case for spring-jcl.

At the moment Spring Session's only required dependency is commons-logging. As I see it, there are two options for it:

Have a compile time dependency on commons-logging and require spring-core users to exclude commons-logging. This is probably a majority of our users, so is probably not ideal.

Have an optional dependency on commons-logging and require non spring-core users to add commons-logging as a dependency.

An even better option might be to have the spring-jcl module which Spring Session could depend on. This would solve both scenarios for users.

Thoughts?

[spring-projects-issues]

Juergen Hoeller commented

Good point, Rob. We'll extract a spring-jcl jar before 5.0 RC1 still.