Logging in Websphere Application Server using Apache commons-logging and Log4j
Logging should be simple and straightforward. It is an essential part of everyday administrative operations and it provides vital information for debugging production incidents. Adequate logging saves time and money. When hosting a number of applications, say 10+, you will want to separate application logs from each other and from platform logs and traces. Logging frameworks like the jdk logger and log4j, cooperating with the j2ee container provide the means to do this, using configuration files. So far, so good.
At some point (from 5.0 on I believe) IBM decided to include jakarta/apache commons-logging (JCL) in their Websphere Application Server product. This is a well known open source product that provides an abstraction below which any logging implementation can in theory be used. The inclusion in WAS implicated that applications using the same framework might see the logging behavior changed. This is because the logging classes will by default be loaded by a different classloader. This classloader will have to be able to find the log4j.jar as well as its configuration file.
There´s another problem: JCL needs to be told that it has to use log4j. By default the JDK logger is used and every line ends up in SystemOut.log. The IBM documentation on this is clear: simply put a file called META-INF/services/org.apache.commons.logging.LogFactory on the classpath and you´re ready. The contents of this file turned out to be the puzzling part for me. I wrongly assumed that the file should be the same as the commons-logging.properties:
I did what (I thought) the documentation told me, redeployed my application and everything seemed fine. Until I changed classloading mode to PARENT_FIRST. Websphere applications can have this setting or APPLICATION_FIRST. In the latter mode jar files bundled with the application will be used first, before loading standard websphere libraries.
When you´re dealing with an application you did not write and cannot change (say you´re the deployer), PARENT_FIRST is your friend in the face of evil developers. I mean evil as in: including j2ee.jar in the earfile. It happens!! And not just this file, but anything you can find in a Maven repository today, containing lowlevel functionality (like xml processing, or j2ee api’s ). They should not be in the earfile!! Using PARENT_FIRST all correct versions of the platform classes will be loaded from the right location. Use this option and then nag the developers.
Actually the logging behavior in my case was very inconsistent. Sometimes APPLICATION_FIRST didn´t work either. And sometimes a server restart changed the logging. It was a frustrating experience, and in those moments, you´re happy to fall back on java decompiling using good old JAD.
The source for org.apache.commons.LogFactory.class made it clear that the above configuration line is wrong, and that you will NEVER get a warning if you fail to do it right. The class loads the file and the complete line is then interpreted as the classname for the LogFactoryImpl. So it´s not a properties file, and the correct contents for META-INF/services/ org.apache.commons.logging.LogFactory are:
And that´s all there is to it. Thanks Apache, for swallowing the ClassNotFoundException !
Actually after some searching I came across a less well known part of the official SUN jarfile specification which states that service interfaces can have certain implementation classes, which are specified in a file that has the name of the interface. It´s a really rudimentary IOC implementation, that must have been fashionable back in the days of jdk 1.3.
I really didn´t know all this. It turned out to be a learning experience after all.