HomeDigital EditionSys-Con RadioSearch Java Cd
Advanced Java AWT Book Reviews/Excerpts Client Server Corba Editorials Embedded Java Enterprise Java IDE's Industry Watch Integration Interviews Java Applet Java & Databases Java & Web Services Java Fundamentals Java Native Interface Java Servlets Java Beans J2ME Libraries .NET Object Orientation Observations/IMHO Product Reviews Scalability & Performance Security Server Side Source Code Straight Talking Swing Threads Using Java with others Wireless XML
 
Logging, by Vinay Aggarwal

During our last project we needed a logger but didn't want to develop our own, so we looked for third-party logging APIs. We found a few and experimented; one of them, log4j, far outshone the others. It helped us so much in tracing and debugging our problems that we recommended it for other projects, where it also got rave reviews.

This API was developed by IBM at their Zurich research lab (www.zurich.ibm.com). Initially, IBM posted it on its alphaWorks Web site ( www.alphaworks.ibm.com), but has since moved it to an open source organization, Source Forge (www.sourceforge.net). It can also be accessed at www.log4j.org.

The Need for Tracing and Logging
Two methods are widely used for debugging: you can either step through the code in a debug environment or you can add debug statements in your code, run the code, and analyze the log generated. The problem with the first method is that it can take a lot of time to step through the code, which can be done only as part of the development phase. In addition, it's difficult to get an overall view of the program execution as you only have the current state of the program at any given time. To get an overall view you have to record the values of the data as you step through the code, which is equivalent to adding debug and trace statements. The advantage of adding debug statements is that this mechanism is persistent. You can see the log anytime you wish (even after the system has been put into production), instead of stepping through the program every time.

Developers often use System.out.println statements to get desired values. Though this provides some quick help to developers, it's not a good solution in the long term. These statements aren't flexible (i.e., time, thread information is generally not logged, and the information to be logged is hard-coded).

If you want to change the format, you have to edit the entire code, and it can't be used in environments where console output isn't available (e.g., server-side components, EJBs, servlets, jsps). If performance is an issue, these statements have to be removed (or commented out) before the system goes into production. If there's a problem in production, the debug statements need to be inserted again, code needs to be compiled, and the application needs to be restarted. This obviously has its drawbacks.

Using a logging API solves these problems. Often these APIs are custom-made (leading to increased project costs), less flexible, unoptimized, and sometimes even unstable. I've used two such APIs and haven't been happy with them.

The Basic Stuff
The log4j API allows you to log text messages as well as exceptions. (It logs the passed message and then exception stack trace.) You can put logging statements in catch blocks, and the log generated can be very helpful in debugging.

Let's start with the concept of priorities (severities). Each logging message has to be put with a priority. Generally used priorities are DEBUG, INFO, WARN, and ERROR (four more priorities - NOTICE, CRIT, ALERT, EMERG - exist but they're discouraged as they get confusing and aren't really required). You can configure the log4j package so it only logs messages above a given priority.

Suppose you've configured the package with WARN priority. All messages with priority WARN and ERROR will be logged, and all messages with priority INFO and DEBUG will be ignored. During development you can configure it to log DEBUG messages, and during production all you have to do is configure it to log all messages with priority INFO or higher. These debug messages won't be logged. This obviously gives cleaner and less verbose logs and saves time in production.

Three functions are available to add debug messages:

  • debug(String message)
  • debug(Object message)
  • debug(String message, Throwable t)
These functions will log a message with debug priority. Similar convenience functions exist for INFO, WARN, and ERROR priorities. For other priorities (which are used less often) such functions don't exist. You can always use the following general functions to log a message:

log(Priority priority, String message)
log(Priority priority, String message, Throwable t)

Categories
Now that we're done with the simple concepts, let's talk about slightly more complex things like categories. The logging API supports multiple logs at the same time. This means you can log different messages into separate files, each with its own format, at the same time. Defining categories does this. Before any log statement you have to get the Category object. This is done by specifying the category you want to log to (e.g., employee, finance). I'll illustrate the usage with an example:

Get the Category object as follows:

Category cat = Category.getInstance(getClass().getName())

This returns a Category object that has all the methods used to log the messages.

The recommended use is to organize your code according to different modules and put them in separate packages (I guess most of us do this anyway). For instance, your employee-related classes would go in a package called com.mycompany.employee while your finance-related classes would go into com.mycompany.finance package. Now all the log statements in the code in employee packages will log into the category com.mycompany.employee, and similarly, all code in the finance package will log using category com.mycompany.finance.

Though you can configure the categories using various configuration functions in the API, a better option is to use a configuration file. Your settings can be specified in a property file and log4j can load it to configure the categories (see Listing 1). The first three lines show three categories: com.mycompany.employee, com.mycompany.finance, and ROOT. If you try to get a Category object for a nonexistent category (such as com.mycompany or foo.bar), it will be created and returned. This new category will inherit its properties from the hierarchy.

The Hierarchy Story
Does this mean you have to configure a different category for each package? No. A very powerful feature of the log4j is category hierarchy (much like a class hierarchy). Just define a category - com.mycompany - and all the logging messages logged with category names - com.mycompany.employee, com.mycompany.finance - will be logged to category com.mycompany. Now suppose you find some bug in the employee package. All you need to do is define another category, com.mycompany.employee, that logs to a different file with severity as DEBUG. All the debug output would go to a different file, which can be deleted after debugging.

The logging categories are hierarchical just like packages in the Java language. This means that if you have a category named com.mycompany and another one, com.mycompany.employee, the category com.mycompany.employee will inherit the properties of com.mycompany (including appenders), unless it's specifically configured to override inherited properties.

Does this mean that all the messages you log under com.mycompany.employee will also be logged under com.mycompany? Three rules determine this. They're well documented, with examples, in the Log4j documentation. I can't reproduce all of it here, but here are the rules:

  1. The chained priority for a given category C is equal to the first nonnull priority in the category hierarchy, starting at C.
  2. A log statement of priority p in a category with chained priority q will be printed if p >= q.
  3. The output of a log statement of category C will go to all the appenders in C and its parents. However, if a parent category of C has the additivity flag set to false, then appenders of that parent aren't used.
If you don't want to log com.mycompany.employee messages to com.mycompany category, use the additivity setting. Setting additivity to false for any category will cause it to stop sending its messages to its parent category. Look at line 4 of Listing 1; this tells us that for the category com.mycompany.finance, you shouldn't send the log messages to the ROOT category. But as nothing is mentioned for the category com.mycompany.employee, the messages from this category will be logged in the ROOT category as well. Listing 2 contains a sample code that uses Listing 1 to configure categories. You might need to experiment with it to get more comfortable with the package.

Appenders
For each category you can specify an appender - an object that will finally send messages to the required destination. There's a FileAppender, which will write the logs to a file, and the RollingFileAppender, which will roll over files beyond the specified size. It will rename the old file and start again in a fresh file. A SocketAppender, which will dump the logs to a socket, can be useful if you're building a distributed logger. An NTEventLogAppender will write the logs to the NT Event Log System. Note that NTEventLogAppender works only on Windows NT. Similarly, there's a SyslogAppender to log messages to a remote syslog daemon in unix environments. It also has a TextPaneAppender, which will add the log messages to a JTextPane.

As you can see in Listing 1, each appender comes with a list of appender-specific settings (for instance, the RollingFileAppender needs to know the file path and name, the maximum size of file, number of backup files, etc., and the SocketAppender needs to know the remote host, port number, etc.).

Now that the problem of where to log is solved, the appender also needs to know the layout in which it should log. Hence all appenders have a layout setting. There are different types of layouts, such as SimpleLayout, TTCCLayout (deprecated), and PatternLayout (the most flexible one). PatternLayout can log time (in various formats), thread name, priority, category, time elapsed from 1970 to creation of logging event, and message. This appender can also log the class name, filename, location (method + class name + line number), line number, and method name, but these should be used only during development as they're very slow.

This completes the discussion about the log4j features. Let's talk a bit about performance. Look at this code:

if(cat.isDebugEnabled()
{
cat.debug("The account number is " + accountNumber);
}

isDebugEnabled will return true only if this category's debug messages will actually be logged. If not, it doesn't enter the if block, thus avoiding the cost of argument building. According to the documentation, on a 233 MHz ThinkPad running JDK 1.1.7B, it takes about 46 nanoseconds to determine if that statement should be logged or not. Actual logging is also fast, ranging from 79 microseconds using the SimpleLayout, to 164 ms using the TTCCLayout, and about a millisecond when printing exceptions. The performance of the PatternLayout is almost as good as the dedicated patterns, but with added flexibility.

How We Used It
We added a few of our own ideas to make it more effective. We derived our own exception class from RuntimeException to represent various exceptions in the system. The main feature of this class was that we put a log statement in the constructor to log the exception, the stack trace, and any nested exception. This logged every exception thrown in the system at any place, at any time with stack trace, and proved to be a very powerful tool.

Additionally, though PatternLayout provides facilities to log the class name and method name, it's supposed to be slow, so we mention these details in the message itself. For example:

Category cat = Category.getInstance(getClass().getName());
cat.log("Account.getBalance: Total balance in account is " + accountBalance);

Here, when the message will be logged, we know that the class is com.mycompany.finance.Account and the method is getBalance.

Another helpful thing for database-specific applications is to create a wrapper around java.sql.Statement and log all the SQL statements fired. This is handy when the SQL statements are being dynamically generated.

We also had a unique requirement. In our system the same code was running for different companies. Think of it as if the accounting is being done for 10 companies. We wanted to be able to separate the log files when desired. But with the category named com.mycompany.finance, we couldn't do it. So we did a little modification and prepended the company name to the package name to get the category name. Our log statements looked like:

Category category = Category.getInstance(company + ".com.mycompany.finance");
category.log("Account.getBalance: Total balance in account is " + accountBalance);

Now we not only know the company name for which this log statement is being executed, but we also have the ability to separate the log files by company name.

(A similar functionality can be achieved using Nested Diagnostic Contexts. The log4j provides a class called NDC for this purpose.)

One important and helpful thing we found was excellent support. Not only have bugs been fixed within hours of the first report, but suggestions have been received with an open mind. (By the time you read this article, however, the log4j package will be owned and maintained by Ceki Glc, the author of log4j package.)

Shortcomings?
There are a few shortcomings, but they're not limiting factors. One is that you can't remove a category once it's created. This was done to keep the API simple to use. Also, the appenders don't support JMS, XML, Database, or others. In the near future, more appenders like JMSAppender, XMLAppender, IRCAppender, JDBCAppender, and JtableAppender are planned.

Conclusion
Though other loggers are out there, we preferred log4j because it's powerful yet simple. However, this isn't a solution for everyone. You might want to check out other loggers such as Chris Barlock's Jlog (formerly called JRAS; it offers more in terms of filtering capability but at the cost of much higher complexity) and GraceLog by Chris Bladon (it enables you to inspect objects and log their contents).

Acknowledgments
I'd like to thank Ceki Gülcü, the author of log4j, for his invaluable input, and my friend Sumit Garg for helping me put this article together. I'd also like to thank Impetus Computing Systems and Info-One, whose resources I used to research and write this article.

Author Bio
Vinay Aggarwal, an integration consultant at Trilogy in Austin, Texas, has extensive experience in Java and Web tecnologies. He received his degree in mechanical engineering from PEC in Chandigrha, India. [email protected]

	


Listing 1

log4j.rootCategory=WARN, ROOT_Appender
log4j.category.com.mycompany.employee=ERROR, EMP_Appender
log4j.category.com.mycompany.finance=INFO, FIN_Appender
log4j.additivity.com.mycompany.finance=false

# Set appender specific options.
log4j.appender.EMP_Appender=org.log4j.RollingFileAppender
log4j.appender.EMP_Appender.File=e:\\jdj\\employee.log
log4j.appender.EMP_Appender.Append=true
log4j.appender.EMP_Appender.MaxFileSize=10kb
log4j.appender.EMP_Appender.MaxBackupIndex=2
log4j.appender.EMP_Appender.layout=org.log4j.SimpleLayout

log4j.appender.FIN_Appender=org.log4j.RollingFileAppender
log4j.appender.FIN_Appender.File=e:\\jdj\\finance.log
log4j.appender.FIN_Appender.Append=true
log4j.appender.FIN_Appender.MaxFileSize=10kb
log4j.appender.FIN_Appender.MaxBackupIndex=9
log4j.appender.FIN_Appender.layout=org.log4j.PatternLayout
log4j.appender.FIN_Appender.layout.ConversionPattern=%d
{dd MMM yyyy HH:mm:ss,SSS} %-15.15t %-8.8p %-30.30c %x - %m\n

log4j.appender.ROOT_Appender=org.log4j.RollingFileAppender
log4j.appender.ROOT_Appender.File=e:\\jdj\\project.log
log4j.appender.ROOT_Appender.Append=true
log4j.appender.ROOT_Appender.MaxFileSize=10kb
log4j.appender.ROOT_Appender.MaxBackupIndex=9
log4j.appender.ROOT_Appender.layout=org.log4j.PatternLayout
log4j.appender.ROOT_Appender.layout.ConversionPattern=%d
{dd MMM yyyy HH:mm:ss,SSS} %-15.15t %-8.8p %-30.30c %x %C %F %l %L %M - %m\n

Listing 2

import org.log4j.*;

public class LogDemo
{
	public static void main(String args[])
	{
		// Configure the logger using properties file.
		PropertyConfigurator.configure("e:\\jdj\\log.conf");

		// Get the logger for package "com.mycompany.hr"
		// as this is not exclusively configured, we will get
		// a new category inheriting the properties of the ROOT
		// category. The ROOT category is configured to
		// log messages with priority "WARN" or higher. Hence
		// "DEBUG" and "INFO" messages will not be logged.
		Category logger = Category.getInstance("com.mycompany.hr");

		if(logger.isDebugEnabled())
			logger.debug("A debug message");
		if(logger.isInfoEnabled())
			logger.info("A info message");

		logger.warn("A warning message");
		logger.error("An error message");

		// Get the category for package "com.mycompany.finance".
		// This package is configured to log messages with priority
		// "INFO" or higher, hence "DEBUG" messages will not be
		// logged.
		logger = Category.getInstance("com.mycompany.finance");
		if(logger.isDebugEnabled())
			logger.debug("A debug message");
		if(logger.isInfoEnabled())
			logger.info("A info message");

		logger.warn("A warning message");
		logger.error("An error message");

		// Get the category for package "com.mycompany.employee"
		// This package is configured to log messages with priority
		// "ERROR" or higher, hence "DEBUG", "INFO" and "WARN"
		// messages will not be logged. But also note that the
		// additivity flag for this package is true (default setting).
		// Hence the log requests will also go to the root package.
		// So the "ERROR" message will also be logged in the "ROOT"
		// category.
		logger = Category.getInstance("com.mycompany.employee");
		if(logger.isDebugEnabled())
			logger.debug("A debug message");
		if(logger.isInfoEnabled())
			logger.info("A info message");

		logger.warn("A warning message");
		logger.error("An error message");
	}
}

  
 
 

All Rights Reserved
Copyright ©  2004 SYS-CON Media, Inc.
  E-mail: [email protected]

Java and Java-based marks are trademarks or registered trademarks of Sun Microsystems, Inc. in the United States and other countries. SYS-CON Publications, Inc. is independent of Sun Microsystems, Inc.