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

DSL

I've been an AT&T DSL customer since 2001. At that time it was with SBC in the Kansas City area. I have a @swbell.net email address to this day. When it was initially rolled out it was $49.95 1 year contact for 1.5 Mbps down. Over time that price went down. I think it took 3 years to get a price break.

Now, it's $43 for existing customers on 6 Mbps no contract. They've raised the price the past couple of year's a dollar here and two dollars there. The reason they give is the same. Something to do with keeping up with market conditions.

To be fair they do include WI-FI at Starbucks, McDonald's, etc for when you use a laptop. For me though that doesn't happen often enough to pay for it included in the $43. Further, you can't separate the two  features.  I suppose that's because most people would separate the two and no one would pay for it.  Then they'd have to drop the feature.

I'm leaving you, AT&T, for Comcast.  I can't ignore the short term deals and the chance to compete for my business with deal negotiation.  I found a two-year contract @ $39.99 for the first 12 months and $56.99 for the second 12 months for phone and internet.  In the end, with taxes, I'll still end up paying less for faster internet (max 20 Mbps!) and the same phone features.  Install is on 7/10.  My wife has put me in charge of this task to switch over.  Which means that not only do I have to monitor the install and make sure everything works just as it does currently, I'll also be the complaint department when it doesn't work right.

iPhone and Gmail

I use my iPhone to manage personal appointments much as one would use their corporate mail server to manage meetings.

My wife and I have Gmail accounts. Our phones are both set to use gmail as an Outlook Exchange server. What that extra distinction allows for is the ability to send and receive calendar entries and accept or deny them as you would within an outlook client on your computer.

When my wife has an appointment she invites me to it and it appears in my calendar after I accept it, for example.

The limitations are that 1) your mail server (e.g. Hotmail, Yahoo, etc) has to support Microsoft Exchange and 2) the scheduler has to know that ahead of time. It's works really well with my wife and I though.

Log4j dynamic log level changes

Recently, I've been working with a colleague on implementing a solution to use Spring JMS to pass messages to other JVMs in a clustered environment for the purpose of setting log4j logging levels to something else.  For example, by configuration file, I've got 'org.foo.bar' logger set to level INFO.  I've found that during some production issue I need to set 'org.foo.bar' to level DEBUG.  Without redeploying the application, I want to set that level for every JVM in my cluster.  I don't want to have to go to each JVM and set that level I want to go to one and let the application handle the rest.

We're using WebSphere 7.0 for z/OS and taking advantage of the included SIBUS. SIBUS is an all java implementation of MQ. I don't believe it is as robust as MQ, but for this purpose it is good enough.

This solution was chosen over others because it can all be implemented within our application except for the SIBUS configuration. We discussed using JMX, but found that we would have potential security limitations. Further we could switch out SIBUS for MQ if need be without application changes.

The solution includes a JSP page to display and set the different log levels for each logger defined. The page reads the loggers that are defined at runtime and code time. The server processes requests from the JSP and builds the message to be processed. A listener processes the message in each JVM to update the logger.

A challenge we ran across was that in WAS z/OS the messaging bus runs as a parallel task (adjunct) to the application  server (servant).  Those tasks start in parallel when a bounce of the server is performed.  We discussed with IBM the possibility of existing implementation to serialize those start ups such that the adjunct starts before the servant.  They didn't have that as a current implementation and suggested that we open an enhancement request.  The challenge is that Spring JMS is looking for the messaging bus to be active during startup.  If the messaging bus is not active, Spring JMS will try to refresh the connection at intervals that you set.  The key to all of this is that Spring JMS run in a separate thread than the thread that is used to start the application context.  If they run in the same thread and the messaging bus is not found on a bounce, the application will fail to start.  IBM recommended some code that is part of their documentation to search for the messaging bus and delay further processing until it is found.  The logic is WebSphere specific and we wanted to remain platform agnostic.

Follow the information in this developerWorks article to a tee and you should have no issues.

http://www.ibm.com/developerworks/websphere/techjournal/0609_alcott/0609_alcott.html

Credit to Srini Ivaturi for this solution. It was his design. I helped with the implementation.