Logging Service

Some Introduction for Logging Service.

6.4 Building the Logging Service

Logging is perhaps the most important service along with the Configuration Service. Logging is needed in almost all cases ranging from logging debug messages to logging error messages. Traditionally Java applications have relied on System.out.println for logging. System.out.printlns are expensive however. Each call to this statement requires the JVM to perform I/O operation. The method call is synchronized, which significantly slows down the throughput and results in poor performance. In addition, they aren't guaranteed to show up in the production system, because system administrators can map System.outs and System.errs to ' ' on NT and dev/null on UNIX. Moreover, if you're running the J2EE app server as an NT service, you won't even have a console. Also, you would want to turn off debug messages in production without any code changes. System.out.println is just not capable of handling these requirements. When it comes to logging, two choices stand out. One is the Log4J API and the other is the JDK1.4 Logging API. In this section we start with an overview of both followed by logging requirements in any enterprise and compare how both the frameworks fare. Then we will illustrate using JMX with Log4J with an example to switch the logging on and off even when the application server is running. This is followed by a discussion of using Nested Diagnostic Contexts in Log4J. Then we show how Commons Logging acts as an adapter for both of these implementations. Finally we develop a “J2EE Ready” extension for the Commons Logging and end the section with an example of using the “J2EEReady” Commons Logging.

6.4.1 JDK 1.4 Logging crash course

Starting with 1.4 release the JDK also ships with its own version of logging API. Of late most of other APIs in Java domain have been following the Service-Service Provider relationship, i.e. the JDK ships with the interfaces and perhaps a reference implementation and other vendors follow suite with their implementations. JDBC is a classic example. However this has not been the case with logging. JDK ships with complete implementation without any opportunity for pluggablity. Due to reasons cited in Section 6.4.3, we will be using Log4J in this book but a short discussion of JDK1.4 Logging is included for the purpose of completeness.

JDK1.4 Logging is initialized using one of the following mechanisms.

§ Via logging.properties in JRE/lib by default

§ By specifying the location of the properties file as “java.util.logging.config.file” system property or

§ By Specifying a class name as “java.util.logging.config.class” system property

§ Programatically by reading from an InputStream as follows

LogManager.getLogManager().readConfiguration(is);

In JDK Logging, all the logging occurs through the Logger class in java.util.logging package. The Logger class supports seven levels for logging defined in the Level class. They are SEVERE, WARNING, INFO, CONFIG, FINE, FINER, and FINEST. The following code shows a message logged to DEBUG level.

Logger logger = Logger.getLogger (“foo.bar”);

logger.debug (“This is a debug message”);

The destination of the log message is specified using the Handler. The format of the output message is specified using Formatters. The Handlers and Formatters can be set programmatically or through the configuration file. In thefollowing code, the log messages are written to a file named foobar.txt by adding the FileHandler to the Logger.

FileHandler fileHandler = new FileHandler("foobar.txt");

logger.addHandler(fileHandler);

A host of information on JDK Logging is freely available online at Sun’s website. Any more elaboration will be merely a repetition of that material.

6.4.2 Log4J crash course

Log4J is the logging implementation available from Apache’s Jakarta project and has been around long before JDK Logging appeared and quite naturally has a larger developer base. As with any Logging mechanisms, this library provides powerful capabilities to declaratively control logging and the level of logging. The declarative control mechanisms are many in Log4J and are initialized during the startup. Log4J provides a lot of choices for initialization. Here is a summary of the initialization procedure.

1. It looks for “log4j.configuration” system property whose default value is log4j.properties.

2. It tries to load the “log4j.configuration” system property value as a url.

3. When the approach 2 fails (If log4j.properties is used, then loading it as an url will definitely fail), it searches some locations within for the resource with the name as specified by the system property.

4. Log4J can also be configured manually using the PropertyConfigurator or DOMConfigurator. The former is used to configure from a properties file, while the latter to configure from XML.

In Log4J, all the logging occurs through the Logger class in org.apache.log4j package. The Logger class supports five levels for logging defined in the Priority class. They are FATAL, ERROR, WARNING, INFO, DEBUG. The code below shows a message logged to DEBUG level.

Logger logger = Logger.getLogger (“foo.bar”);

logger.debug (“This is a debug message”);

The destination of the log message is specified using the Appender. For instance an appender can point to a file, console, email address or as exotic as a JMS channel. If you need a destination that is not supported by the classes out of the box, just write a new class that implements the Appender interface. A sample appender looks as follows.

<appender name="ABCBank-Warn" class="org.apache.log4j.FileAppender">

<param name="Threshold" value="WARN" />

<param name="File" value="./logs/abcbank-warnings.log" />

<param name="Append" value="false" />

<layout class="org.apache.log4j.PatternLayout">

<param name="ConversionPattern"

value="%d [%x][%t] %-5p %c{2} - %m%n"/>

</layout>

</appender>

This appender works for messages with a threshold of WARN or above and writes the messages to an out put file abcbank-warnings.log. The format of the output message is specified using Layout. Standard classes for specifying the layout like PatternLayout are used most of the times and the format is declaratively specified using symbols like %d which instructs Log4J to include date time in the log and %m – the actual message itself and so on.

As seen earlier, the logging is done by obtaining a named Logger instance. Sow how is the Appender linked to a name Logger? This connection is established in the same configuration using the Category. The foo.bar category connecting the foo.bar Logger to the “ABCBank-Warn” FileAppender is done as follows.

<category name="foo.bar" additivity="false">

<appender-ref ref="ABCBank-Warn" />

<appender-ref ref="Developer-Console" />

</category>

In the category definition, you will see that the “foo.bar” category has more than one appenders associated with it. One of them is the ABCBank-Warn appender. There is also another Developer-Console appender. So, whenever you log to the “foo.bar” Logger, the message is written to both of these destinations.

Log4J has been around longer than JDK1.4 logging and is mature and supports more log destinations (Appenders) and Layouts. Although a detailed treatment of Log4J is within the scope of this book, we have held back from such a discussion, as a lot of material is freely available online if you want to dig deeper. We will be rather discussing more on the realistic usage, implications and potential improvements to the Log4J from an enterprise project perspective. In the next section, we will compare JDK1.4 Logging and Log4J to substantiate the usage of Log4J as the logging provider for the application developed in this book.

6.4.3 Enterprise logging requirements and JDK1.4 Logging vs. Log4J

In Table 6.2, you can find a feature matrix comparing JDK1.4 Logging and Log4J. Of all the features, what is most concerning is the J2EE affinity, or the lack thereof. JDK1.4 Logging is initialized using system properties. While this is fine in a J2SE environment, it affects every deployed application in a J2EE platform. The whole idea behind having WARs and EARs is to have a self contained executable module without dependencies on external setup. Consequences of using system properties to set system wide logging destinations and formats are mixing up of messages from multiple applications, lack of control over the use of logging format etc. To solve the latter problem you will have to provide the formatter (layout) classes in the system classpath because, JDK1.4 logging essentially resides there and cannot use Formatting classes provided in your WARs and EARs.

Table 6.2 JDK1.4 and Log4J Feature Matrix

	Out of the box Features	JDK Logging	Log4J
1	Simple Console, Socket, File Logging	Yes	Yes
2	Multiple Log destination support – SysLog, NT Event Log, JMS Channel	No	Yes
3	Comprehensive File rotation by date, size etc.	No	Yes
4	Logging Format (Layout) Support	Less	More
5	Logging with Diagnostic Context	No	Yes
6	System property based Initialization (File or class as a system property)	Yes	Yes
7	XML based in initializationConfiguration Format	NoProperties	YesXML
8	J2EE Affinity [By setting a system property, all the web applications in a JVM are affected. However, since you can bundle Log4J in your web application, it is local and change in configuration does not affect system wide)	Less	More
9	JMX MBeans	No	Yes

Another requirement in enterprise systems is the capability to turn logging on and off on demand. Suppose that your J2EE application is in production and all of a sudden you start seeing error messages. Since the application was deployed with the logging turned off, you cannot turn on the logging without stopping the server. Most of the times that is not an option at all. If you have deployed your web application in exploded format (i.e. not as a WAR, but as a directory in a vendor specified location), Log4J comes with a “configureAndWatch” facility. In this scenario a thread with a configurable delay runs and checks if the configuration file for changes since last load and reloads if necessary. Again this is not an option when you have deployed web applications as WAR. Enter JMX.

JMX is SNMP equivalent for the Java platform. Using JMX, you can expose application components and attributes to external management tools by creating Java classes called MBeans (managed beans). Figure 6.10 shows the JMX environment. Management tools access MBeans through JMX agents. JMX Agents have protocol adapters that make the MBeans available to SNMP, HTTP etc. Notice that the management tools never hold direct reference to MBeans. J2EE application servers also ship with MBean support and do a good job in letting administrators edit the MBean properties from their admin consoles. We will take this route to control logging, since demonstrating the effective use of JMX in enterprise environment is what we want to stress.

Figure 6.10 High Level view of the JMX Agent

Log4J ships with several Dynamic MBeans of which LoggerDynamicMBean and AppenderDynamicMBean are of particular interest to us. LoggerDynamicMBean attributes include the logging Level (Priority) that can be changed on the fly from ERROR to DEBUG level even when the application server is running. AppenderDynamicMBean has a editable attribute for Layout which again can be changed on the fly.

Another essential requirement in enterprise applications is “context aware” logging for diagnostics. Let us assume that the debug was turned on in production and the resulting file has the logs from all users. If you want to track the activity of a specified user, you will easily get lost. Using different loggers for different users is simply not feasible. Log4J has a facility called Nested Diagnostic Context (NDC for short). With NDC, you can uniquely stamp each user’s request by “pushing” user specific data into NDC. When you want to track the user’s activity, all you have to do is search in the log file based on the unique stamp. In a J2EE environment, a http session id (and hence its hash code), or a user principal are unique and qualify as candidates. NDC is essentially a Stack for every java.lang.ThreadLocal.

In summary, Log4J is more enterprise ready and mature to develop J2EE applications than JDK1.4 logging.

6.4.4 Developing a JMX Configurator for Log4J

After glossing over JMX and its usage for setting dynamic log control mechanism, it is time to configure the Log4J MBeans. In this section, you will develop JMXConfigurator, a utility class that configures Log4J using the XML file and then creates the MBeans and registers them with the MBeanServer (the MBean registry). This class will be application server specific. However, the Log4J initialization and configuration should not affect your core application logic. At the time of this writing, Tomcat 4.1.x support for custom MBeans was weak and hence we have developed the JMXConfigurator for WebLogic7.0. You will find that the code can be ported to other application servers with minor changes.

Listing 6.6 JMXConfigurator’s configure() method.

public void configure(InputStream log4JconfigStream)

{

// Parse the input XML stream and configure Log4J

DocumentBuilderFactory dbf = DocumentBuilderFactory.

newInstance();

DocumentBuilder db = dbf.newDocumentBuilder();

Document document = db.parse(new InputSource(

log4jConfigStream));

Element xmlDocRoot = document.getDocumentElement();

// Log4J class for XML configuration

DOMConfigurator.configure(xmlDocRoot);

// Create Initial Context

Properties h = new Properties();

h.put(Context.INITIAL_CONTEXT_FACTORY,

"weblogic.jndi.WLInitialContextFactory");

h.put(Context.PROVIDER_URL, "t3://localhost:7001");

h.put(Context.SECURITY_PRINCIPAL,"system");

h.put(Context.SECURITY_CREDENTIALS, "weblogic");

Context context = new InitialContext(h);

// Lookup the MBeanServer

MBeanHome mbh = (MBeanHome)context.lookup(

"weblogic.management.adminhome");

MbeanServer mbs = mbh.getMBeanServer();

// Create and Register the top level Log4J MBean

HierarchyDynamicMBean hdm = new HierarchyDynamicMBean();

ObjectName mbo = new ObjectName("log4j:hiearchy=default");

mbs.registerMBean(hdm, mbo);

// Add the root logger to the Hierarchy MBean

Logger rootLogger = Logger.getRootLogger();

hdm.addLoggerMBean(rootLogger.getName());

// Get each logger from the Log4J Repository and add it to

// the Hierarchy MBean created above.

LoggerRepository r = LogManager.getLoggerRepository();

java.util.Enumeration enum = r.getCurrentLoggers();

Logger logger = null;

while (enum.hasMoreElements())

{

logger = (Logger) enum.nextElement();

hdm.addLoggerMBean(logger.getName());

}

Listing 6.6 shows the JMXConfigurator’s configure method. This method takes a InputStream as parameter. The stream contains the XML based configuration for Log4J, from a file input. First we acquire a Parser using JAXP and configure the Log4J using the DOMConfigurator class from org.apache.log4j.xml package. In Weblogic, MBeanServer is available through JNDI lookup. Hence we get the JNDI InitialContext and use it to lookup the MBeanServer. Then we create an instance of HierarchyDynamicMBean and register it with the MBeanServer. HierarchyDynamicMBean is the top level MBean representing the Hierarchy class in Log4J. Then we add the RootLogger, the topmost Log4J logger into the HierarchyDynamicMBean followed by individual Loggers. Recall that the logging message level (or priority) is set on each Logger. By adding each Logger into the MBean, we are actually creating a MBean for each Logger, represented by the LoggerDynamicMBean class.

Figure 6.11 Exploring MBeans in WebLogic7.0 using BeJMX.

Once the Logger MBean is added, the logging message level can be manipulated through any JMX compatible management tool. However for the sake of this book, we will demonstrate this capability through an open source JMX editor called BeJMX. It is a WebLogic7.0 admin console extension, meaning it is viewable within the browser based WebLogic7.0 administration console like any other proprietary administration component. BeJMX is an open source product developed at SourceForge(1). Figure 6.11 shows the BeJMX in the left frame and the Log4J MBeans in the right side. Of particular interest to us is the MBean whose name is “logger=jmx-demo”.

Figure 6.12 Logger MBean Edit View

Figure 6.12 shows the jmx-demo Logger MBean selected for editing. In this page, you can change the value of the priority from INFO to DEBUG and you will start seeing all messages with priority higher than DEBUG. Pretty cool huh!

6.4.5 Developing a Scheduler for Log4J JMX

In the previous section, you saw how to effectively use JMX in conjunction with Log4J to dynamically set the logging level – an invaluable option in production. However, remember that as each class acquires a named Logger, the corresponding MBeans are not created. What this means is that, you can dynamically control only those Loggers created at the outset. That can be a handicap at times. Suppose you want to turn on the logging only for “com.foo.bar” classes, and such a Logger was not defined in the log4j config XML file, the only option is to turn on the logging on Log4J Root Logger (which will turn on logging for all the named loggers which do not have a defined level or an ancestor in the hierarchy). If this will result in tons of undesired logging messages in the rest of the system, its time to look at what we are discussing now. As mentioned earlier, Log4J ships with classes called as WatchDogs which monitor for changes to the XML config file when the application is configured from the file system (using the configureAndWatch method). We will develop a simple utility called JMXWatchDog, which will compare the Logger hierarchy and with the MBeans hierarchy and create those MBeans which do not exist. Listing 6.7 shows the JMXWatchDog. It can be invoked from JMXConfigurator. The constructor sets the WatchDog as a Daemon thread It will run forever until the J2EE application is undeployed or the server is restarted. Everytime the thread wakes up and runs, checkForNewLoggers method is called. In that method, we check for all the Loggers and try to add them to the HierarchyMBean. Since we are trying to add the previously existing Mbeans too, we will get a InstanceAlreadyExistsException, which we ignore and continue with the next Logger. Whenever the thread is interrupted, the interrupt flag is set on the thread. Sleep() method throws a InterruptedException under these circumstances. When you catch the InterruptedException, the flag is reset.

Listing 6.7 Periodic checking for new Loggers

public class JMXWatchDog extends Thread {

private long delay;

private HierarchyMBean hdm;

public JMXWatchDog(long delay, HierarchyDynamicMBean hdm) {

this.delay = delay;

this.hdm = hdm;

setDaemon(true);

checkForNewLoggers();

}

private void checkForNewLoggers() {

LoggerRepository r = LogManager.getLoggerRepository();

java.util.Enumeration enum = r.getCurrentLoggers();

Logger logger = null;

while (enum.hasMoreElements()) {

try {

logger = (Logger) enum.nextElement();

hdm.addLoggerMBean(logger.getName());

} catch (InstanceAlreadyExistsException) { }

}

}

public void run() {

while(!interruptedtrue) {

try {

Thread.currentThread().sleep();

Thread.sleep(delay);

} catch(InterruptedException e) { }

checkForNewLoggers();

}

}

}

6.4.5 Log4J Nested Diagnostic context using a Filter

As discussed earlier in section 6.4.3, Log4J supports context aware logging for diagnostics through NDC. The NDC is an object that Log4J managed manages per thread, as a stack of contextual information. It is similar to ThreadLocal in java. All methods of the org.apache.log4j.NDC class are static. By using the static methods in NDC, you can associate a stack with every executing thread. You can push and pop objects into this thread specific stack.

As you know, the J2EE application server maintains a collection of threads to service the user requests. The terminology used to describe this is vendor specific. For instance, this is called Execute Queue in WebLogic. The application server assign a thread from the execute queue for every incoming request. The request is associated with that thread until the response is sent back to the caller. You can push the user’s unique identifier into the thread specific NDC stack when the request processing begins and pop just before the response is sent. You will immediately notice that we are trying to use a Decorator pattern (Gof). This decorator can be easily implemented by using a Servlet Filter. We know that a servlet Filter gets invoked once when entering the J2EE domain and/or exiting it. While entering you can call a NDC.push(String.valueOf(httpsession.getId().hashCode())).Now, the hashcode of the HttpSession Id is pushed into the stack associated with the ThreadLocal. On the way out you can call NDC.pop()and the value is popped out the ThreadLocal stack. In the log4j config file, you can add a %x to the appender’s log pattern (PatternLayout) which tells the Log4J to peek at the stack and print out the ThreadLocal Stack.

6.4.7 Jakarta Commons Logging

Our decision to go with Log4J for ABC Bank is based on the current state of affairs. As with any other adapters developed in previous sections, our goal is also to protect the application coding investment. We want to isolate the application code if for whatever reason; we decide to change the logging provider in future. One has often heard arguments that such a change when moving to new provider is a matter of search and replace. Hence there is no need to develop a wrapper API. There are two factors to consider.

1. The APIs might diverge significantly in future that a simple search and replace may not be feasible.

2. When using vendor API directly in the code, it is very easy to use the proprietary features. By mandating the use of a wrapper, a separation is built at the architectural level. If value additions like Log4J specific NDC has to be used, they can be plugged in an external module (like a filter for e.g.) without affecting the core application logic.

Fortunately such a wrapper for Logging exists in the form of Commons Logging API developed as part of the Jakarta open source initiative from Apache Software Foundation. As a result we will not get into reinventing the wheel, but rather use it.

At the beginning of the chapter we showed you how to use Commons Logging. The Log interface is the central point. For every logging provider, there has to be a concrete implementation of this class. For e.g. there is a Log4JLogger class for Log4J. Commons Logging itself has six levels: trace, debug, info, warn, error, fatal. It is up to the Log implementer to map this to the logging provider levels. For e.g. Log4JLogger maps both trace and debug from Commons Logging to DEBUG in Log4J. You can acquire a Log from LogFactory class. LogFactory is an abstract class. It has to be “adapted” to the service provider by subclassing. For e.g. there is a Log4Jfactory class for Log4J. The LogFactory itself will discover the appropriate Factory to be used and hence appropriate subclass of Log to be instantiated by using the component discovery mechanism illustrated in section 6.1.3, with the exception of JNDI based discovery. Listing 6.8 shows the usage pattern for Commons Logging. Each of the debug(), error() methods are overloaded to take a Throwable parameter. Logging as we know affects performance. The cost of parameter (String or Object) construction for logging can be heavy and applications should not pay that price if they are not logging. Hence checking if a particular level is enabled before actually logging to that level is recommended.

Listing 6.8 Using Commons Logging in your application.

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

public void logMessages()

{

Log log = LogFactory.getLog(this.getClass());

if (log.isDebugEnabled())

{

log.debug(“This is debug message”);

}

if (log.isErrorEnabled())

{

log.error(“This is error message”);

log.error(this, exception);

}

}

As with any other wrappers we have developed, Commons Logging does not assume responsibility to initialization the service provider underneath. The service provider initialization is the responsibility of your code. However, since the initialization itself can occur outside the code containing business logic, this should not be a problem. In our case, we will initialize Log4J using a Servlet and use Commons Logging in the application code.

6.4.8 A “J2EE Ready” Commons Logging Factory

Now that you know how the LogFactory works, its time to use it in the J2EE environment. Of the component discovery mechanism in listed in section 6.1.4, LogFactory implements only the first three. In this section, we will develop extension to the LogFactory to lookup JNDI with a predefined name. We will lookup the same name as it is looking for in the system property.

Listing 6.9 J2EELogFactory class.

public class J2EELogFactory extends LogFactory

{

protected static String factoryClassName;

public static void initialize (Context aContext)

throws NamingException

{

factoryClassName = (String)

aContext.lookup(LogFactory.FACTORY_PROPERTY); |#1

}

public static LogFactory getFactory()

throws LogConfigurationException

{

LogFactory factory = LogFactory.getFactory(); |#2

if (factory == null || factory instanceof org.apache.commons.logging.impl.LogFactoryImpl)

{

factory = newFactory(factoryClassName,

Thread.currentThread().getContextClassLoader());

if (factory != null)

{