WebSphere and Logging

I've recently had some experience configuring WebSphere to use logging other than Jakarta Commons Logging (JCL) that is natively included in WAS.  I found a lot of blogs, forum posts, and tech write ups from IBM on the subject.  None were very satisfactory to me.  Therefore, I set out to find out how it worked.  I created an EAR with three different WARs in it.  Each WAR contained different types of logging that you might use in your application.

Environment
WAS 7.0.0.0 (it's actually WAS for Developers although that shouldn't matter)
Windows 7 64bit
Eclipse Java EE Indigo
Maven 2
Spring 3.0.0

Project Setup
was-logger
-> was-logger-ear
-> was-logger-jcl-war
-> was-logger-log4j-war
-> was-logger-slf4j-war (with log4j as the implementing logger)

I used the Maven project/module model to help build my resulting EAR file and dependency management.

was-logger-jcl-war
This WAR contains only the applicationContext.xml, web.xml, and Spring JARs.
I created a class called LogEvent.  The class is loaded by Spring as a bean and performs a simple loop to display 10 messages.  The point of the loop was to easily find those messages amongst others.


package org.foo.bar.jcl;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

public class LogEvent {

private static final Log log = LogFactory.getLog(LogEvent.class);

public void initialize() {

for (int i = 0; i < 10; i++) {
log.info("Testing commons logging #" + i);
}
}

}


The resulting log records will appear in the SystemOut.log file.  Like this:

[7/8/12 8:12:14:701 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #0
[7/8/12 8:12:14:701 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #1
[7/8/12 8:12:14:716 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #2
[7/8/12 8:12:14:716 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #3
[7/8/12 8:12:14:716 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #4
[7/8/12 8:12:14:716 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #5
[7/8/12 8:12:14:732 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #6
[7/8/12 8:12:14:732 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #7
[7/8/12 8:12:14:732 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #8
[7/8/12 8:12:14:732 CDT] 0000000a LogEvent      I org.foo.bar.jcl.LogEvent initialize Testing commons logging #9


If you have one application in the environment this might be ok. If you want to customize or use different and better loggers, then you'll want to read further.

was-logger-log4j-war
This WAR contains the log4j.xml, commons-logging.properties, applicationContext.xml, web.xml, log4j JAR, and Spring JARs.  I basically created this WAR with the same class, LogEvent, but backed it up with log4j Logger instead of the commons-logging Log class.


commons-logging.properties file contains some information to route commons logging over to log4j.  In other words, Spring uses JCL and the point of the properties file in my WAR is get Spring to use log4j instead.  However, it didn't work from a Spring perspective.  The messages from LogEvent were routed to the file specified in my appender.


2012-07-07 22:04:13,712 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #0
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #1
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #2
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #3
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #4
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #5
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #6
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #7
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #8
2012-07-07 22:04:13,715 [WebContainer : 3] INFO  (LogEvent)  - Testing log4j logging #9


So why didn't it work?  I'm not sure. I think one thing that happens is that Spring attaches to the JCL logger before it gets a chance to hook up with log4j.  There is a part of the ContextLoaderListener to load log4j.  There is also a defined listener to load you log4j configuration.  I haven't played with that, but I fear that it is only really going to apply to Spring.  What about other frameworks (like CXF) that use JCL as well?  Read on.

was-logger-slf4j-war
This WAR contains the log4j.xml, commons-logging.properties, applicationContext.xml, web.xml, log4j JAR, slf4j JARs and Spring JARs.  There is also another JAR that seems to be key, jcl-over-slf4j-1.6.6.jar.


When the slf4j logging facade is used on top of log4j, Spring and my application information are routed to the file defined in my log4j.xml file.

2012-07-07 22:04:14,143 [WebContainer : 3] INFO  (ContextLoader)  - Root WebApplicationContext: initialization started
2012-07-07 22:04:14,291 [WebContainer : 3] INFO  (XmlWebApplicationContext)  - Refreshing Root WebApplicationContext: startup date [Sat Jul 07 22:04:14 CDT 2012]; root of context hierarchy
2012-07-07 22:04:14,486 [WebContainer : 3] INFO  (XmlBeanDefinitionReader)  - Loading XML bean definitions from class path resource [applicationContext.xml]
2012-07-07 22:04:14,778 [WebContainer : 3] INFO  (DefaultListableBeanFactory)  - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@56c556c5: defining beans [logEvent]; root of factory hierarchy
2012-07-07 22:04:14,863 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #0
2012-07-07 22:04:14,863 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #1
2012-07-07 22:04:14,863 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #2
2012-07-07 22:04:14,864 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #3
2012-07-07 22:04:14,864 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #4
2012-07-07 22:04:14,864 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #5
2012-07-07 22:04:14,864 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #6
2012-07-07 22:04:14,864 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #7
2012-07-07 22:04:14,864 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #8
2012-07-07 22:04:14,864 [WebContainer : 3] INFO  (LogEvent)  - Testing slf4j logging #9
2012-07-07 22:04:14,886 [WebContainer : 3] INFO  (ContextLoader)  - Root WebApplicationContext: initialization completed in 740 ms


Conclusions
I like my logging configurable outside of the WAS Admin Console.  In most production environments, you're not going to have any kind of permissions to change items in the Admin Console.  Then you would have to engage someone in a support area who does have access and they might not be as up to date on your application and what your request is.  Log4j and slf4j give you greater flexibility in defining your logging solution.  I like the slf4js ability to route any framework over to the log4j configuration.

Appendix - Class Loading
This discussion wouldn't be complete with some mention of class loading.  A lot of posts I saw mentioned that setting the class loader to PARENT_LAST,  I have done that for another application for the purposes of CXF, but for this test application, I did not.  Therefore, you can get different logging without changing the classloading order.

I've posted the code at the following link. was-logger