The Tale of JBoss and the 7 Little Logging Frameworks

At Synyx we’re currently taking care of a rather large legacy project for one of our customers in the course of our Code Clinic services. The project comprises several components such as a fat client implemented with a custom UI framework on top of Swing, a bulky web application using a mixture of custom and obsolete frameworks, and a lot of asynchronously running jobs to process input from other systems involving custom XSL transformations and a heap of stored procedures in a Oracle 9i database. You get the picture, it’s the prototype of a legacy system.

The original developers of the system suffered a serious case of the well-known NIH syndrome and thus a lot of technical debt has been piled up over the course of its development.

One peculiar case was the use of about 7 different logging abstractions scattered over the whole code base. While some (well, just one) of the implementations provide a certain added value, the other ones were just plain wrappers around the eventually used logging frameworks. They literally just added a bad API on top of the other. There were also at least three different logging frameworks in use, namely Apache Commons Logging, SLF4J and Log4j.
In order to consolidate the code base, to reduce the dependencies on external frameworks and to prevent conflicts induced by the use of generic class names like Log or Logger we decided to clean up this mess and use SLF4J with its Log4j back end as our authoritative logging framework in this project. We chose SLF4J for several (hopefully good) reasons, e. g. the low number of dependencies, the ability to plug in the logging framework of choice at deployment time, the clean API and the good support for legacy logging frameworks. Also read the articles My Soapbox for SLF4J and Thoughts on Java logging and SLF4J for a more detailed discussion of SLF4J’s features. Did I mention SLF4J also works on Android?
SLF4J thankfully makes it easy to bridge legacy logging frameworks so that you don’t have to refactor all your code at once but could incrementally migrate your code base while still using SLF4J under the hood.
As you might have already guessed from the title of this blog post, the project uses the established JBoss Application Server. Unfortunately it’s currently stuck at version 4.0.3.SP1 but that’s another topic.
After deciding on which framework to use we started refactoring our code base. At first this wasn’t a problem. Deleting the legacy logging classes and then replacing their calls with our authoritative SLF4J Logger was straight forward. Since the logging classes were scattered across the whole code base we sometimes missed a dependency in another component of the project, but that’s what a Continuous Integration system is for after all.

We also adapted the dependencies in the components’ POM files to use SLF4J’s commons-logging bridge instead of commons-logging itself. Pro tip from the trenches: Don’t confuse jcl-over-slf4j.jar with slf4j-jcl.jar! The former is the API bridge we wanted to use, the latter is a SLF4J backend implementation using commons-logging. In order to get the dependencies straight we used Maven’s dependency management feature and added the following declarations in the parent POM for the project’s components:

<dependencyManagement>
  <dependency>
    <groupId>commons-logging</groupId>
    <artifactId>commons-logging</artifactId>
    <version>1.1.1</version>
    <scope>provided</scope>
  </dependency>
  <dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jcl-over-slf4j</artifactId>
    <version>1.6.1</version>
  </dependency>
</dependencyManagement>

By setting the scope of commons-logging to “provided” we made sure that it would not be pulled in accidentally. Unfortunately this scope is not transitive and we had to explicitly exclude commons-logging (and other artifacts) from some of our dependencies:

<dependency>
  <groupId>org.apache.ws.commons.axiom</groupId>
  <artifactId>axiom-api</artifactId>
  <version>1.2</version>
  <exclusions>
    <exclusion>
      <artifactId>commons-logging</artifactId>
      <groupId>commons-logging</groupId>
    </exclusion>
  </exclusions>
</dependency>

In order to analyze the dependency trees of our components the Maven dependency plugin turned out to be very useful, especially the dependency:tree mojo which will produce a view of the project’s dependency tree including transitive dependencies. Of course a good IDE will also support you with graphical views of the dependency tree. Here’s the output of mvn dependency:tree for the aforementioned Swing application:

[INFO] [dependency:tree {execution: default-cli}]
[INFO] com.example:swing-client:jar:1.1.0-SNAPSHOT
[INFO] +- org.slf4j:slf4j-log4j12:jar:1.6.1:compile
[INFO] |  \- log4j:log4j:jar:1.2.16:compile
[INFO] +- jgoodies:plastic:jar:1.2.0:compile
[INFO] +- com.toedter:jcalendar:jar:1.3.2:compile
[INFO] +- com.example:jms:jar:1.0.1-SNAPSHOT:compile
[INFO] |  +- jboss:jboss-system:jar:4.0.2:compile
[INFO] |  +- jms:jms:jar:1.0.2:compile
[INFO] |  +- org.quartz-scheduler:quartz:jar:1.2.3:compile
[INFO] |  +- jboss:jbossmq-client:jar:4.0.2:compile
[INFO] |  +- jboss:jboss-jmx:jar:4.0.2:compile
[INFO] |  \- javax.ejb:ejb:jar:2.1:compile
[INFO] +- flex:flex-messaging-common:jar:1.0.0:compile
[INFO] +- flex:flex-messaging-core:jar:1.0.0:compile
[INFO] +- flex:flex-messaging-opt:jar:1.0.0:compile
[INFO] +- flex:flex-messaging-proxy:jar:1.0.0:compile
[INFO] +- flex:flex-messaging-remoting:jar:1.0.0:compile
[INFO] +- poi:poi-2.5.1-final:jar:20040804:compile
[INFO] +- com.example:docengine:jar:1.0.0-SNAPSHOT:compile
[INFO] |  +- com.example:webfw:jar:1.0.2-SNAPSHOT:compile
[INFO] |  |  +- com.example:dms_client:jar:1.0.2:compile
[INFO] |  |  |  \- org.apache.axis2:axis2:jar:1.1.1:compile
[INFO] |  |  |     +- org.apache.ws.commons.axiom:axiom-dom:jar:1.2:compile
[INFO] |  |  |     +- org.apache.ws.commons.axiom:axiom-impl:jar:1.2:compile
[INFO] |  |  |     +- ant:ant:jar:1.6.5:compile
[INFO] |  |  |     +- woodstox:wstx-asl:jar:3.0.1:compile
[INFO] |  |  |     +- org.apache.ws.commons.schema:XmlSchema:jar:1.2:compile
[INFO] |  |  |     +- annogen:annogen:jar:0.1.0:compile
[INFO] |  |  |     +- commons-httpclient:commons-httpclient:jar:3.0.1:compile
[INFO] |  |  |     |  \- commons-codec:commons-codec:jar:1.2:compile
[INFO] |  |  |     +- org.apache.httpcomponents:jakarta-httpcore:jar:4.0-alpha2:compile
[INFO] |  |  |     +- wsdl4j:wsdl4j:jar:1.6.1:compile
[INFO] |  |  |     +- backport-util-concurrent:backport-util-concurrent:jar:2.2:compile
[INFO] |  |  |     +- org.apache.ws.commons.neethi:neethi:jar:2.0:compile
[INFO] |  |  |     \- org.apache.woden:woden-impl-om:jar:1.0M8:compile
[INFO] |  |  |        +- org.apache.woden:woden-api:jar:1.0M8:compile
[INFO] |  |  |        +- org.apache.ant:ant:jar:1.7.0:compile
[INFO] |  |  |        |  \- org.apache.ant:ant-launcher:jar:1.7.0:compile
[INFO] |  |  |        +- xerces:xmlParserAPIs:jar:2.6.0:compile
[INFO] |  |  |        \- org.codehaus.woodstox:wstx-asl:jar:3.2.4:runtime
[INFO] |  |  +- org.apache.ws.commons.axiom:axiom-api:jar:1.2:compile
[INFO] |  |  |  +- jaxen:jaxen:jar:1.1-beta-9:compile
[INFO] |  |  |  +- xml-apis:xml-apis:jar:1.3.03:compile
[INFO] |  |  |  \- stax:stax-api:jar:1.0.1:compile
[INFO] |  |  +- org.slf4j:jcl-over-slf4j:jar:1.6.1:compile
[INFO] |  |  +- org.apache.struts:struts-core:jar:1.3.8:compile
[INFO] |  |  |  \- commons-chain:commons-chain:jar:1.1:compile
[INFO] |  |  +- com.sun.xml:xml:jar:0.8.0:compile
[INFO] |  |  +- xmlc:xmlc-all-runtime:jar:2.2.8.1:compile
[INFO] |  |  +- xalan:xalan:jar:2.7.1:compile
[INFO] |  |  |  \- xalan:serializer:jar:2.7.1:compile
[INFO] |  |  \- com.lowagie:itext:jar:2.0.7:compile
[INFO] |  |     +- bouncycastle:bcmail-jdk14:jar:138:compile
[INFO] |  |     \- bouncycastle:bcprov-jdk14:jar:138:compile
[INFO] |  +- org.apache.xmlgraphics:fop:jar:0.95-1:compile
[INFO] |  |  +- org.apache.xmlgraphics:xmlgraphics-commons:jar:1.3.1:compile
[INFO] |  |  +- org.apache.xmlgraphics:batik-svg-dom:jar:1.7:compile
[INFO] |  |  |  +- org.apache.xmlgraphics:batik-anim:jar:1.7:compile
[INFO] |  |  |  +- org.apache.xmlgraphics:batik-css:jar:1.7:compile
[INFO] |  |  |  +- org.apache.xmlgraphics:batik-dom:jar:1.7:compile
[INFO] |  |  |  +- org.apache.xmlgraphics:batik-parser:jar:1.7:compile
[INFO] |  |  |  +- org.apache.xmlgraphics:batik-util:jar:1.7:compile
[INFO] |  |  |  \- xml-apis:xml-apis-ext:jar:1.3.04:compile
[INFO] |  |  +- org.apache.xmlgraphics:batik-bridge:jar:1.7:compile
[INFO] |  |  |  +- org.apache.xmlgraphics:batik-script:jar:1.7:compile
[INFO] |  |  |  \- org.apache.xmlgraphics:batik-xml:jar:1.7:compile
[INFO] |  |  +- org.apache.xmlgraphics:batik-awt-util:jar:1.7:compile
[INFO] |  |  +- org.apache.xmlgraphics:batik-gvt:jar:1.7:compile
[INFO] |  |  +- org.apache.xmlgraphics:batik-transcoder:jar:1.7:compile
[INFO] |  |  |  \- org.apache.xmlgraphics:batik-svggen:jar:1.7:compile
[INFO] |  |  +- org.apache.xmlgraphics:batik-extension:jar:1.7:compile
[INFO] |  |  +- org.apache.xmlgraphics:batik-ext:jar:1.7:compile
[INFO] |  |  +- commons-io:commons-io:jar:1.3.1:compile
[INFO] |  |  \- org.apache.avalon.framework:avalon-framework-impl:jar:4.3.1:compile
[INFO] |  +- org.apache.avalon.framework:avalon-framework-api:jar:4.3.1:compile
[INFO] |  +- poi:poi:jar:2.5.1-final-20040804:compile
[INFO] |  +- javax.servlet:servlet-api:jar:2.5:compile
[INFO] |  +- javax.mail:mail:jar:1.4.1:compile
[INFO] |  |  \- javax.activation:activation:jar:1.1.1:compile
[INFO] |  +- org.openoffice:jurt:jar:3.2.1:compile
[INFO] |  |  \- org.openoffice:ridl:jar:3.2.1:compile
[INFO] |  +- org.openoffice:unoil:jar:3.1.0:compile
[INFO] |  +- org.openoffice:juh:jar:3.1.0:compile
[INFO] |  \- ru.novosoft.dc:rtf2fo:jar:eval:compile
[INFO] +- com.jgoodies:forms:jar:1.0.7:compile
[INFO] +- xerces:xercesImpl:jar:2.4.0:compile
[INFO] +- com.oracle:ojdbc5:jar:11.1.0.6.0:compile
[INFO] +- javax.help:javahelp:jar:2.0.02:compile
[INFO] +- com.example:custom-swing-framework:jar:1.1.2-SNAPSHOT:compile
[INFO] |  +- com.whirlycott:whirlycache:jar:0.7.1:compile
[INFO] |  |  +- commons-collections:commons-collections:jar:3.1:compile
[INFO] |  |  +- jdom:jdom:jar:1.0:compile
[INFO] |  |  \- concurrent:concurrent:jar:1.3.4:compile
[INFO] |  +- ehcache:ehcache:jar:0.9:compile
[INFO] |  +- org.enhydra.xmlc:xmlc:jar:2.2.7.1:compile
[INFO] |  +- com.jgoodies:looks:jar:2.2.2:compile
[INFO] |  +- org.swinglabs:swingx:jar:1.6.1:compile
[INFO] |  |  +- com.jhlabs:filters:jar:2.0.235:compile
[INFO] |  |  \- org.swinglabs:swing-worker:jar:1.1:compile
[INFO] |  \- struts:struts:jar:1.2.9:compile
[INFO] |     +- commons-beanutils:commons-beanutils:jar:1.7.0:compile
[INFO] |     +- commons-digester:commons-digester:jar:1.6:compile
[INFO] |     +- commons-fileupload:commons-fileupload:jar:1.0:compile
[INFO] |     +- commons-validator:commons-validator:jar:1.1.4:compile
[INFO] |     +- oro:oro:jar:2.0.7:compile
[INFO] |     \- antlr:antlr:jar:2.7.2:compile
[INFO] +- junit:junit:jar:4.8.2:test
[INFO] \- org.slf4j:slf4j-api:jar:1.6.1:compile
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESSFUL
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 2 seconds
[INFO] Finished at: Tue Jun 28 14:10:29 CEST 2011
[INFO] Final Memory: 22M/257M
[INFO] ------------------------------------------------------------------------

As described before the elimination of the “rogue” logging class wasn’t a big problem. But we hadn’t reached the finish line yet.
The final application is being assembled into one big EAR file which contains a lot of EJBs, SAR files (JBoss Service Archives), and three WARs (web applications). By default JBoss uses its unified class loader (well described in the JBoss Admin Guide in section 2.2.2.4. Inside the JBoss Class Loading Architecture) which is for several reasons not suitable for the architecture of this legacy application (using incompatible versions of the same library in different components for example). Thus we wanted to utilize Apache Tomcat’s class loading mechanism, described in the Apache Tomcat 5.5 Class Loader HOW-TO, which basically isolates the deployed web applications from each other. The wiki article on Advanced JBoss Class Loading is also very informative in this context.
Since JBoss 4.0.3.SP1 is using Apache Tomcat 5.5 as servlet container it provides a simple configuration setting to achieve exactly the above described behaviour. Unfortunately we encountered a lot of class loading problems when we first deployed the application after the log framework refactoring. We checked the dependencies for each component but everything seemed to be correct. So we started what we do best: set logging to DEBUG and engage!
In the end some knee-deep class loader debugging hinted us in the right direction: It’s not advisable to have more than one instance of the SLF4J JARs in your class path. Basically the class loader was complaining that the classes it was trying to load (e. g. org.slf4j.spi.LoggerFactoryBinder) had already been loaded from another repository. If you recall the details of Apache Tomcat’s class loader this makes perfect sense but we thought that it was intelligent enough to actually share these classes. As it turns out there’s a (somewhat undocumented) configuration option which will exactly do this for us: FilteredPackages.
After adding the SLF4J package prefix to our jbossweb-tomcat.sar/META-INF/jboss-service.xml file as shown below, the application magically started working again.

      <!-- The list of package prefixes that should not be loaded without
         delegating to the parent class loader before trying the web app
         class loader. The packages listed here are those tha are used by
         the web container implementation and cannot be overriden. The format
         is a comma separated list of the package names. There cannot be any
         whitespace between the package prefixes.
         This setting only applies when UseJBossWebLoader=false.
      -->
      <attribute name="FilteredPackages">javax.servlet,org.slf4j</attribute>

Lessons learned

• If you’re starting a new project choose exactly one logging framework and stick with it. I recommend using SLF4J for its stable API and Logback as backend at the moment.
• Don’t create log wrappers if they provide no additional value and if you really, really need to implement your own, use the logging framework’s API instead of thinking up your own.
• Dependencies over a lot of distinct components which should be assembled into a single EAR can be quite hairy. Think very well about how to partition your application and which components have common dependencies which can be separated into a parent POM.
• The one configuration option that might solve all of your problems is not documented very well. Scan through your (commented) configuration files once in a while.
• Use the tools your IDE provides. It makes refactoring so much easier if you know what your IDE is capable of.
• Never underestimate the grief that class loading issues can cause you. Really, read up on it!
• Continuous integration the way we do it is nice but it doesn’t help you with class loading issues appearing in your JEE application server.

How about you? Did you experience similar stories with large legacy applications? What did you take from it? We’re thrilled to hear your “Development War Stories” in the comments!

Attributions

• Seven Dwarves “Homeward Bound” statue by Jim Shore as soon from the China Closet on Main Street by Loren Javier, CC BY-ND 2.0