Enterprise JavaJLog: A Java Logging Framework
- By Todd Lauinger
- July 17, 2000
I MUST ADMIT, I am a Smalltalk bigot. Working on my first Java project, I miss the elegance and simplicity of the language. Most of all, I miss the many frameworks we added to the already extensive Smalltalk base class library. Two of the most useful and pervasive were Kent Beck's testing framework and a logging framework. Kent Beck and Erich Gamma already ported their testing framework for you in JUnit.
1, 2 This article describes a framework for logging text information in an application. At the end of the article I reference a Web site where you can download all the source and class files, so you can easily add the framework to your application (or better yet, extend it, as you should be able to do with any good framework). But perhaps even more importantly, I explain the importance of developing a comprehensive error handling and logging strategy that, in combination with a logging framework, can help you detect and correct defects more quickly.
Need for Application Logging
What is an application log and why do you need one? An application log is a text history of notable events logged by your application. This log helps you to figure out what went wrong (and right) during the execution of your application. Of four very large projects I have been involved in, only one planned for an application log from the start. The other three had to create them in the testing phase, at great expense and delay. With the advent of n-tier architectures, Servlets, JSPs, and EJBs, application logging is particularly important to report errors that cannot or should not be surfaced to the UI.
If this is so important, why doesn't J2EE support this in its standards? Each application server I have worked does logging in a very different and proprietary manner. You would expect that to happen since J2EE doesn't provide a standard way to do it. Application servers typically capture all output to the standard output (System.out) and standard error (System.err) streams and send it to a file. Unfortunately, this is not nearly good enough to rapidly debug complex problems. There are two fundamental problems with putting debugging information to the standard error or output streams. First, you rarely remember to put the time of the event in your log entry. Second, you don't have a good mechanism to increase or decrease the volume of information logged at runtime. Either the event is logged or it isn't.
A good logging framework handles both of these problems with ease. Fortunately, Sun and IBM are aware of these problems. They have submitted a proposal for a logging specification in the J2SE platform.3 Unfortunately, it will take some time to construct and approve a specification and include it as a standard feature of the Java platform. Until then, you can use and customize JLog!
Logging Framework Goals
Every new framework you design should have a set of goals in mind. Otherwise, you tend to crank out a solution to the problem of the day without giving much thought to tomorrow's problems. Frameworks live and die by their elegance. They must be extremely easy to understand and use, yet powerful under the covers. Otherwise people will not take the time to learn and use them.
The overarching goal for the framework is to find and fix defects more quickly. More specifically, though, I had the following goals in mind when I designed JLog:
- Client code readability: It should be obvious from looking at a logging-code statement what log the information is going to, what severity the information is being logged at, and what information is being logged.
- Minimal client code to use the log: When logging information, the client should not need to write two or three statements with several method parameters to log an event—we want one simple method call.
- Granular logging: Different application functions should be able to have their own log so you can focus in on a particular application problem, without getting flooded with log messages from other parts of the application.
- Power under the hood: The framework should have a reasonable set of defaults for typical application logging, yet a wealth of configurable options to take advantage of the granular logging power in the previous goal.
- Extensibility: Every framework should be able to easily extend without modifying any base framework classes.
As we discuss the use of the framework, you should see elements to fulfill all of these goals.
Framework Use
A significant event happens in your Java code. That event could be any of several different types and conditions. Before you start using a logging framework, you must categorize and document your events so that all users of the framework will log events consistently.
System Event Categories. In the system I work on, I have six system event categories, shown in Table 1. To make JLog operate properly, more critical events must have lower event-level numbers than less critical events. That way, at runtime you can set the logging level of the log to increase or decrease the amount of information being logged. The most critical event category must be level 1. The next most critical event is level 2, and so on. Then at runtime, for example, you can set the log to a warning level (level 3 in Table 1), and it will log anything at levels 3, 2, and 1 (i.e., anything at a warning level or a level more critical).
| Table 1. Example system event categories. |
| LEVEL |
NAME |
PURPOSE |
| 1 |
CRITICAL_ERROR |
The system encountered a critical error at this logging level, which affects the accuracy, integrity, reliability, or capability of the system. Someone should be paged to address the error as soon as possible. |
| 2 |
ERROR |
The system encountered an unexpected error at this logging level, which means the code intercepted an error it cannot handle. This error is not of a critical nature and typically can be recovered from automatically. Future requests into the system should be able to be processed without error. Someone should be emailed to resolve the error in the near future to increase the reliability of the product. |
| 3 |
WARNING |
The system encountered an expected error situation. The system recovered from it, but the fact that it happened should be recorded to monitor frequency. |
| 4 |
INFORMATION |
Normal logging level. All interesting periodic events should be logged at this level so someone looking through the log can see the amount and kind of processing happening in the system. |
| 5 |
DETAIL |
Moderately detailed logging level to help debug typical problems in the system. Not so detailed that the big picture gets lost. |
| 6 |
TRACE |
Most detailed logging level. Everything sent to the log will be logged. Use this level to trace system execution for really nasty problems. At this level, the logging will typically be so verbose that the system performance will be affected. |
Logging Granularity. Once you have agreed on a set of event categories and documented them in your coding standards, you need to determine the granularity at which you will log those events. In my application we have a thread pool, a database connection pool, a request-processing framework, an SQL processing framework, and the application that uses all of the aforementioned services. When debugging a thread pool problem, I don't want the log to be cluttered with SQL log statements, so I have one log for the thread pool and another for the SQL processor. The application is still pretty small, so we only have one log for the entire application. However, I could see us splitting the log in the future as the application grows (and we want to be able to more easily debug a particular subsystem of the application). For now, Table 2 shows the logging granularity in my current application.
| Table 2. Example logging granularity. |
| LOG NAME |
PURPOSE |
| AppLog |
General application event logging. |
| SQLLog |
Logs all SQL-related processing activities. |
| ThreadLog |
Logs all events related to managing the thread pool. |
| RequestLog |
Logs all requests into the system, including the time to fulfill the request. |
| DbConnectLog |
Logs events related to managing the database connection pool. |
You will need to look over your application and decide how many logs you want and what information they will log. Next, document and enforce logging granularity standards for your application. If you do not take these steps, your logs will become inconsistent and you will not be able to debug your application as quickly.
Say you have an SQLLog and an AppLog in your application and someone logs an SQL statement to AppLog. Or maybe someone doesn't log the SQL statement at all. Either way, when you try to debug a problem querying the database, you look in the SQLLog to see what SQL statements your system is processing and not all the information is there. If the errant SQL statement is not logged according to your standards, you will not be able to find the problem as quickly.
Logging Framework Extension. After documenting your logging standards, you extend the logging framework to support those standards. My application is a multithreaded application (as most Java Server applications are), so I extend the class named log.MultiThreadLog for each of the logs in my system. Here is where I ran into several problems with Java. First, Java will not let you define an instance and a static method in the same class with the same name and parameters. Why would anyone want to do that? Coming back to goals one and two, we want logging to be very simple and readable. I use the Singleton pattern4 to make the logs well-known objects in the system (so they are easy to get at anywhere in the code). In the traditional form of the pattern, that would mean that all callers to a log, such as AppLog for an error event, would have to look like this:
AppLog.getInstance().error("This error occurred");
The
getInstance() method call gets in the way of readability for this statement. The code would be much better served by reading:
AppLog.error("This error occurred");
If you define the
error(String) method as a static method, you cannot define it as an instance method as well. You have to rename it and remember if you are using the static method or the instance method.
The second problem with Java is that Log should be an interface, but you cannot define static methods in interfaces. Without the static methods, there was little value in creating an interface. Finally, Smalltalk has this handy dandy thing called a class instance variable. It works wonders to easily define a Singleton abstract superclass. Then, with no additional code whatsoever, you can define any number of subclasses that are also Singletons. Very cool feature, but not available in Java. All of these factors made it very difficult to support the logging framework goals and good object design at the same time, so I sacrificed inheritance. AppLog does not extend MultiThreadLog, but rather it "wrappers" it and passes information through to an instance of it (see Listing 1). To conveniently access each log you define, you will have to do the same and duplicate the code in Listing 1.
Logging Events. Once you have a log that you can conveniently access, you need to add logging statements throughout your code. The log is only as useful as the information written to it. Three examples follow:
AppLog.criticalError("Caught unexpected exception: " + e);
SQLLog.info("Executing SQL query: " + statement);
AppLog.trace("Entering method getName()");
Notice that the code does not have any "if" logic in it to determine whether the event should be output. The log takes care of that automatically as the system runs.
One note for those overly concerned about performance (you know who you are): Using JLog, the application will construct the log messages and execute framework code even when logging is turned off. Without using a C/C++ type preprocessor, logging of this type will add a slight performance hit to your system. You can easily overdo logging. When I added method-level tracing (i.e., logging the entrance to each method) to my application, I saw a 12% performance hit when all logs were turned off (and the application slowed to a crawl when the logs were turned to trace level). However, the slight performance hit you take when doing judicious logging is well worth it when you debug a difficult production problem.
Configuring the Logs. Each log can output its information to one or more logging mechanisms. A logging mechanism is a separate class that abstracts the details of the particular logging destination (e.g., System.err, a local text file). Each log also registers itself with a log manager, so you see what logs are active in the system. See the UML class diagram in Figure 1 for a graphical layout of the framework classes.
Figure 1. Primary JLog classes and relationships.
I have implemented a few logging mechanisms for you, and you can easily extend the mechanism set through inheritance. The first, and default, mechanism logs to a standard error (System.err). The other mechanisms are variants of local text files. I can envision new mechanisms to log to a remote process via socket, RMI, or CORBA calls, to send pages or emails, and so on. You may log to more than one mechanism at a time (handy, but really slows down the system). The same information is written to all mechanisms you log to. You can set the mechanism(s) in your application properties file or programmatically at runtime with a statement such as:
ThreadLog.getInstance().
removeLoggingMechanism(Log.STANDARD_ERR_MECHANISM);
ThreadLog.getInstance().
addLoggingMechanism(Log.UNIQUE_FILE_MECHANISM);
You may also select the output logging level of the log. The default in the framework is the
INFO level. All events logged at a level less than or equal to the log's current logging level will be output to the logging mechanisms. Events logged at a numerically higher level (i.e., a less critical level) will be discarded. Here is where logging granularity becomes useful. At runtime, you can increase or decrease the logging level of any of your logs without affecting your other logs. If you are trying to debug a nasty problem with your thread pool, you can programmatically change the log at runtime with the following code:
ThreadLog.getInstance().setLoggingLevel(Log.TRACE_LEVEL);
There are other ways you can dynamically reset the logging level at runtime, depending on the environment in which you are running your JVM. If you are in a debugger, you can change the value of the log's
currentLoggingLevel variable (not very elegant, I know). If you are running under an application server, you can examine and manipulate log properties with some JSPs I wrote. You could also use RMI to manipulate the log properties of a remote JVM (I wrote JSPs as a sample interface to do this as well).
There are more options you can configure both programmatically and via a properties file. Refer to the JLog Javadoc for detailed information.
Reading the Logs. Logs do not do you any good, even when they contain useful information, if you cannot easily read them. Remember that the overall goal of the framework is to find and fix defects faster. The first problem is figuring out what time an event happened. All log entries have a compact but detailed time stamp to the millisecond. In a multithreaded system, the next problem you will find reading logs is that multiple threads of execution may potentially interleave their log entries. When using multithreaded logs, the logging framework will put the name of the thread that generated the event in every log entry. When necessary, you can filter the log based on the thread you want to concentrate. Another common problem is figuring out what severity the log event is. Each event logs its severity, with the lowest numbered events being the most critical. A final problem the framework addresses is logging to a shared log such as System.err. Each log outputs its name for every event, so that if you did not separate each log into its own file beforehand, you can always filter it in the future. Here are some sample entries from a shared log, where the default delimiter, a vertical bar ( | ), is used to delimit the various fields of log entries:
RequestLog|L4|09:32:23:769|ExecuteThread-5|Executing request number 4
SQLLog|L4|09:32:23:835|ExecuteThread-5|select * from Customer where id = 35
RequestLog|L4|09:32:23:969|ExecuteThread-5|Request 4 took 200 milliseconds
RequestLog|L4|09:32:48:234|ExecuteThread-2|Executing request number 5
SQLLog|L1|09:32:48:236|ExecuteThread-2|Error:Database "customerDb" not available
RequestLog|L1|09:32:48:249|ExecuteThread-2|Request 5 could not be completed
In these entries, the first field in a log entry is the name of the log. The second field is the logging level from Table 1. The third field is a time stamp of the event, showing hours, minutes, seconds, and milliseconds. No date is displayed because that would largely be redundant. The fourth field is present in multithreaded logs only, that being the name of the thread that generated the event. The last field is the text of the event. One final note: If this text is not as readable as you would like, you can easily import the log into a spreadsheet. If you do an ASCII text import with a vertical bar as a field delimiter, the spreadsheet will put the various fields into columns automatically and make the log even more readable. You can then sort or filter the log using various spreadsheet capabilities.
Conclusion
I have found that judicious use of logging in my applications greatly decreased the amount of time I needed to find and fix defects. I have taken many of the best features of the application logs I have worked with and bundled them up in the first version of JLog. My hope is to provide you with a useful and extensible framework for doing better logging in your application. Use it as-is, or better yet, change it to fit the precise needs of your application. Let me know how things go!
Acknowledgments
Special thanks to the partners at Catapult Technologies for reviewing the framework and hosting it at their Web site.
References
- Beck, K. and E. Gamma, "Test Infected: Programmers Love Writing Tests," Java Report, Vol. 3, No. 7, July 1998, pp. 37–50.
- Beck, K. and E. Gamma, "JUnit: A Cook's Tour," Java Report, Vol. 4, No. 5, May, 1999, pp. 27–38.
- Sun Microsystems Inc., "JSR-000047 Logging API Specification," http://www.jcp.org/aboutJava/communityprocess/review/jsr047/.
- Gamma, E. et al., Design Patterns: Elements of Reusable Object-Oriented Software, Addison–Wesley, 1995.