When To Use Diagnostic Logging

Diagnostic logging is intended only to be used when debugging a problematic configuration. It should be switched off for production.

How To Use Diagnostic logging

Diagnostic logging is controlled through the system property org.apache.commons.logging.diagnostics.dest. Setting the property value to the special strings STDOUT or STDERR (case-sensitive) will output messages to System.out and System.err respectively. Setting the property value to a valid file name will result in the messages being logged to that file.

OIDs

Diagnostics uses the concept of an Object ID (OID). This allows the identity of objects to be tracked without relying on useful toString implementations. These are of the form:

classname@system identity hash code

The system identity hash code is found by calling System.identityHashCode() which should uniquely identify a particular instance. The classname is usually the fully qualified class name though in a few cases, org.apache.commons.logging.impl.LogFactoryImpl may be shortened to LogFactoryImpl to increase ease of reading. For example:

sun.misc.Launcher$AppClassLoader@20120943
LogFactoryImpl@1671711

OIDs are intended to be used to cross-reference. They allow particular instances of classloaders and JCL classes to be tracked in different contexts. This plays a vital role in building up the understanding of the classloader environment required to diagnose JCL problems.

Diagnostic Message Prefix

Each diagnostic message is prefixed with details of the relevant class in a standard format. This takes the form:

[class-identifier from ClassLoader OID]

ClassLoader OID is the OID of a classloader which loaded the class issuing the message. class-identifier identifies the object issuing the message.

In the case of LogFactory, this is just LogFactory. For example (line split):

[LogFactory 
   from sun.misc.Launcher$AppClassLoader@20120943] BOOTSTRAP COMPLETED

In the case of LogFactoryImpl, the prefix is the instance OID. This can be cross referenced to discover the details of the TCCL used to manage this instance. For example (line split):

[LogFactoryImpl@1671711 
   from sun.misc.Launcher$AppClassLoader@20120943] Instance created.

ClassLoader Hierarchy Tree

Understanding the relationships between classloaders is vital when debugging JCL. At various points, JCL will print to the diagnostic log the hierarchy for important classloaders. This is obtained by walking the tree using getParent. Each classloader is represented (visually) by an OID (to allow cross referencing) and the relationship indicated in child --> parent fashion. For example (line split for easy reading):

ClassLoader tree:java.net.URLClassLoader@3526198  
      --> sun.misc.Launcher$AppClassLoader@20120943 (SYSTEM) 
      --> sun.misc.Launcher$ExtClassLoader@11126876 
      --> BOOT

Represents a hierarchy with four elements ending in the boot classloader.

LogFactory Class Bootstrap

Whenever the LogFactory class is initialized, diagnostic messages about the classloader environment are logged. The content of each of these messages is prefixed by [ENV] to help distinguish them. The extension directories, application classpath, details of the classloader (including the OID and toString value) used to load LogFactory and the classloader tree for that classloader are logged.

Many Sun classloaders have confusing toString values. For example, the OID may be

sun.misc.Launcher$AppClassLoader@20120943

with a toString value of

sun.misc.Launcher$AppClassLoader@133056f

Other classloader implementations may give very useful information (such as the local classpath).

Finally, once initialization is complete a BOOTSTRAP COMPLETED message is issued.

Construction Of LogFactoryImpl Instances

LogFactoryImpl is the standard and default LogFactory implementation. This section obviously only applies to configurations using this implementation.

Before assigning a Log instance, LogFactory loads a LogFactory implementation. The content is prefixed by [LOOKUP] for each diagnostic message logged by this process.

The implementation used can vary per Thread context classloader (TCCL). If this is the first time that a Log has been requested for a particular TCCL a new instance will be created.

Information of particular interest is logged at this stage. Details of the TCCL are logged allowing the OID later to be cross-referenced to the toString value and the classloader tree. For example, the following log snippet details the TCCL (lines split):

[LogFactory from sun.misc.Launcher$AppClassLoader@20120943] 
    [LOOKUP] LogFactory implementation requested for the first time for context 
        classloader java.net.URLClassLoader@3526198
[LogFactory from sun.misc.Launcher$AppClassLoader@20120943] 
    [LOOKUP] java.net.URLClassLoader@3526198 == 'java.net.URLClassLoader@35ce36'
[LogFactory from sun.misc.Launcher$AppClassLoader@20120943] 
    [LOOKUP] ClassLoader tree:java.net.URLClassLoader@3526198 
        --> sun.misc.Launcher$AppClassLoader@20120943 (SYSTEM)  
          --> sun.misc.Launcher$ExtClassLoader@11126876 
            --> BOOT

Log Discovery Diagnostics

The standard LogFactoryImpl issues many diagnostic messages when discovering the Log implementation to be used.

During discovery, environment variables are loaded and values set. This content is prefixed by [ENV] to make it easier to distinguish this material.

The possible messages issued during discovery are numerous. To understand them, the source should be consulted. Attention should be paid to the classloader hierarchy trees for the classloader used to load LogFactory and to the TCCL.

The Incompatible LogFactory Issue

Symptoms

An exception is thrown by JCL with a message similar to:

  The chosen LogFactory implementation does not extend LogFactory. Please check your configuration. 
  (Caused by java.lang.ClassCastException: The application has specified that a custom LogFactory 
  implementation should be used but Class 'com.ibm.ws.commons.logging.TrLogFactory' cannot be converted 
  to 'org.apache.commons.logging.LogFactory'. The conflict is caused by the presence of multiple 
  LogFactory classes in incompatible classloaders. Background can be found in 
  https//commons.apache.org/logging/tech.html. If you have not explicitly specified a custom
  LogFactory then it is likely that the container has set one without your knowledge. 
  In this case, consider using the commons-logging-adapters.jar file or specifying the standard 
  LogFactory from the command line. Help can be found @https//commons.apache.org/logging.
  

This is a WebSphere example so the name of the custom LogFactory is com.ibm.ws.commons.logging.TrLogFactory. For other containers, this class name will differ.

Explanation

A custom LogFactory implementation can only be used if the implementation class loaded dynamically at runtime can be cast to the LogFactory class that loaded it. There are several ways in which this cast can fail. The most obvious is that the source code may not actually extend LogFactory. The source may be compatible but if the LogFactory class against which the source is compiled is not binary compatible then the cast will also fail.

There is also another more unusual way in which this cast can fail: even when the binary is compatible, the implementation class loaded at runtime may be linked to a different instance of the LogFactory class. For more information, see the tech guide.

This situation may be encountered in containers which use a custom LogFactory implementation. The implementation will typically be provided in a shared, high level classloader together with JCL. When an application classloader contains LogFactory, the implementation will be loaded from that higher level classloader. The implementation class will be linked to the LogFactory class loaded by the higher level classloader. Even if the LogFactory implementations are binary compatible, since they are loaded by different classloaders the two LogFactory Class instances are not equal and so the cast must fail.

The policy adopted by JCL in this situation is to re-throw this exception. Additional information is included in the message to help diagnosis. The reasoning behind this choice is that a particular LogFactory implementation has been actively specified and this choice should not be ignored. This policy has unfortunate consequences when running in containers which have custom implementations: the above runtime exception may be thrown under certain classloading policies without the user knowingly specifying a custom implementation.

Fixes

There are various ways to fix this problem. Which fix is right depends on the circumstances.

If you are happy using another classloading policy for the application, select a classloading policy which ensures that LogFactory will be loaded from the shared classloader containing the custom implementation.

If you want to bypass the container adaption mechanism then set the appropriate system property to the default value when the container is started:

 -Dorg.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl
 

If you want to continue to use the default container mechanism then:

• Find and replace the commons-logging implementation used by the container with the most modern release
• Replace the commons-logging jar in the application with the commons-logging-adapters jar. This will ensure that application classloader will delegate to it's parent when loading LogFactory.

If you encounter difficulties when applying the fixes recommended, please turn on diagnostics and consult the logs.

Apache Tomcat

At the current date, Tomcat 5.5.16 is the current release. All releases from version 4.1.x through 5.5.16 have a startup process that places jarfile ${tomcat.home}/bin/commons-logging-api.jar in the system classpath and then prevents any webapp from overriding the classes in that jarfile. Effectively, all webapps behave as if "parent-first" classloading were enabled for those classes.

This has some benefits; in particular it means that there are no problems in these Tomcat versions with having multiple copies of the commons-logging Log interface in the classpath (which avoids the "Log does not implement Log" problem described elsewhere).

However it also means that no webapp can override the core commons-logging classes by including an updated commons-logging jarfile in WEB-INF/lib; any class already loaded via the container takes priority. In particular, as Tomcat bundles logging 1.0.4 only, the new diagnostics and memory-leak-prevention features of the 1.1 release will not be available unless the container's library version is updated.

Because the commons-logging-api.jar in the container does not contain any log-library-adapter classes, updated behavior for these will be seen when logging 1.1 is bundled in WEB-INF/lib. In particular, the support for Log4j's TRACE level will take effect without having to update the container.

If you do wish to update Tomcat's version of commons-logging, then you must use the commons-logging-1.1-api jar only, not the full jar. Classes in the webapp cannot override classes loaded from the system classpath set up during Tomcat's startup process, and logging adapters can only see their matching concrete logging library if that library is available in the same classpath. Bundling the full commons-logging jarfile (with adapters) into the system classpath therefore means that logging libraries (eg Log4j) within WEB-INF/lib are not accessible.

Note that the behavior described here only applies if the standard Tomcat startup process is run. When Tomcat is embedded in a larger framework (eg run embedded within an IDE) this may not apply.

JBoss Application Server

The JBoss Application Server can be configured to prevent deployed code from overriding classes higher in the hierarchy, effectively forcing "parent-first" behavior for selected classes. By default, commons-logging is in this list (at least for some JBoss versions starting with 4.0.2), and therefore including an updated version of commons-logging in WEB-INF/lib or similar will have no effect. See the JBoss classloading documentation for more details.

Other Containers

As more information becomes available on this topic, it may be added to the commons-logging wiki site.