Apache Jakarta and Beyond: A Java Programmeramp;#039;s Introduction [Electronic resources] نسخه متنی

11.1. The Java.util.logging Package

As of J2SE 1.4 logging facilities are provided as part of the standard Java libraries. Many of the ideas behind this package seem to have been inspired by log4j, which preceded 1.4 by over a year. Some of the features of log4j were omitted, leading to an API that is easier to use. Because this package is included in the Java standard, there is no need to download or distribute any additional jar files. However, many people believe that too many features were omitted from java.util.logging and that log4j is still a preferable solution.

In J2SE 1.4 all logging is done through a Logger object. A static method in Logger maps names to particular instances, and different instances can be given different properties. Therefore, a logging operation begins by obtaining the appropriate logger by name.

Logger logger =
Logger.getLogger("com.awl.toolbook.chapter11.sample");

The only points to note about logger names are that they must be valid Java identifiers and that they are hierarchical. This latter point means that logging properties can be assigned to the logger named com.awl.toolbook, and by default the logger used above will inherit these properties.

One obvious approach to naming is for each class in the project to have its own logger, and the name of the logger to match the full name of the class. Loggers are thread-safe, which means multiple instances of a class can all use the same logger without worrying about interfering with each other. This means that each class's logger can be obtained statically

import java.util.logging.*;
public class Sample {
private static Logger logger =
Logger.getLogger(Sample.class.getName());
}

Using this approach makes it easy to configure logging on a package-by-package level, with a logger at the top of the hierarchy having default values. The logger for each subpackage can override values and can be enabled or disabled as needed.

This is a valid and often useful approach, but it is certainly not the only one. Multiple classes throughout several packages might comprise a single logical unit, and in such a case the name of that unit might be used as the logger name. For example, a project designed along model/view/controller lines might have a logger named view and subloggers representing different kinds of views such as view.jsp, view.jsp.taglib, view.swing, and so on.

It is also possible for one class to play several different roles, in which case one class may need to obtain several Logger instances.

11.1.1. Logging Messages

Logging a message once a logger has been obtained is a simple matter. The simplest log method is called log(), and it takes a log level and a message to be logged. Levels are represented by final static values in the Level class, so the call to log some general information would look like

logger.log(Level.INFO, "New user logged in");

As a convenience Logger also provides methods that reflect the predefined log levels, so the preceding call could be replaced by logger.info("New user"). There are also versions of these methods that accept an exception as an additional argument.

The following log levels are defined in Level:

• NONE

• SEVERE

• WARNING

• INFO

• CONFIG

• FINE

• FINER

• FINEST

• ALL

Levels have an implied order that is maintained by static integer values assigned to each. Loggers also have an associated log level; when a message is logged, the logger checks whether the level of the message is less than its own level. If so, the message is discarded.

Because logger levels can be configured at run time, this makes it easy to filter messages. During development a logger might be set to the FINEST level so that all debug messages will be logged. When the system is put in production, the level might be changed to WARNING so that only serious and potentially serious problems will be reported.

Each of the predefined levels has a corresponding set of methods in Logger; there are methods called severe() and fine() and so on. The special value NONE means that no messages should be logged, and ALL means that every message should be logged. FINE, FINER, and FINEST are meant to represent different levels of debugging output, although the precise meaning is left to the developer. One possibility is that each method call could be logged at the FINE level, leaving FINER and FINEST to represent different amounts of detail as to what methods are doing.

It is possible to create new log levels by subclassing Level and adding new constants. Care must be taken not to conflict with values of the predefined levels, and for that reason and others, creating new levels is not recommended.

11.1.2. How Logging Is Handled

Once a message has been logged with a call to log() or a related method, several things happen. First, a new instance of LogRecord is created and populated with values including the message, log level, and the exception if one is provided. The LogRecord is also given the current time and the names of the class and method from where the logging call occurred. These last two pieces of data are inferred automatically by the logging system and may not always be accurate. For example, during dynamic optimization hotspot may change the way in which methods are called. When exact values are needed, there is an alternate set of log methods that allows them to be specified.

It is also possible for client code to create and log LogRecord objects manually, with code such as

LogRecord record = new LogRecord();
record.setLevel(Level.FINE);
record.setMessage("Test code entered");
record.setSourceClassName("com.awl.toolbook.chapter11.Test");
record.setSourceMethodName("manualLogRecord");
record.setThreadID(Thread.currentThread().hashCode());
logger.log(record);

Regardless of how the record is created, the logger passes the record to one or more Handler objects. The set of handlers to invoke are associated with the named logger, so it is possible to define different sets of handlers for different packages or parts of the system.

It is the Handler objects that make the LogRecords available to end users. There are predefined handlers that write log messages to System.out, System.err, or files. There are also handlers that hold log messages in memory where they can be programmatically examined. There are even handlers that send log messages through a socket. It is also possible to define new handlers that perform custom actions such as storing log events in a database or sending them to a system administrator's pager. This later handler could be tied to SEVERE events such as the system experiencing a critical failure in order to provide an immediate alert.

Many of the preceding handlers use classes called Formatters to process the LogRecord data into a human-readable or machine-readable format. Two formatters are provided: SimpleFormatter, which writes a short, easy to read summary such as

Aug 9, 2003 4:03:35 PM com.awl.toolbook.chapter11.Sample
INFO: New user logged in

and XMLFormatter, which creates an XML structure

<?xml version="1.0" encoding="ISO-8859-1" standalone="no"?>
<!DOCTYPE log SYSTEM "logger.dtd">
<log>
<record>
<date>2003-08-09T16:13:23</date>
<millis>1060460003493</millis>
<sequence>1</sequence>
<logger>com.awl.toolbook.chapter11.manual</logger>
<level>INFO</level>
<class>com.awl.toolbook.chapter11.LogSample</class>
<method>manual</method>
<thread>10</thread>
<message>New user logged in</message>
</record>
</log>

Sometimes assigning a level to a logger is insufficient, such as cases where it is desirable to send error messages and debugging messages to different files. If a logger is configured at the WARNING level, the debug messages will be ignored, but if the logger is set to the FINEST level, all messages will be sent to the handlers, and both kinds of messages will end up jumbled together in both of the target files. One way around this would be to use two different loggers with different names and different levels, but this means that extra logging code must be added to the application.

For this reason, handlers also have associated levels. If a handler's level is set to WARNING, it will only log events at the WARNING and SEVERE levels. Note, however, that if the logger's level is set to NONE, then the log records will not be sent to the handlers at all.

11.1.3. Filtering

Some situations require more fine-grained control over logging than can be provided by a level. For example, a handler designed to page an administrator with error messages might only need to run after normal business hours. Therefore, the Java logging API provides a general mechanism by which handlers and loggers can determine whether to log particular messages. These are called

filters. A filter is a class with a method called isLoggable() that is passed the LogRecord before the logger or handler handles it. The isLoggable() method returns a boolean indicating whether the record should be processed. Listing 11.1 shows a simple filter that recreates the existing level-based test by checking whether the LogRecord is at an appropriate level.

Listing 11.1. A simple filter

package com.awl.toolbook.chapter11;
import java.util.logging.*;public class LevelFilter implements Filter {
private Level minLevel = Level.FINEST;
public LevelFilter() {}
public LevelFilter(Level minLevel) {
this.minLevel = minLevel;
}
public boolean isLoggable(LogRecord record) {
return
minLevel.intValue() >= record.getLevel().intValue();
}
}

This class could be used as follows:

handler.setFilter(new LevelFilter(Level.WARNING));

There is no limit to what can be done in the isLoggable() method. A filter could do different things based on the time of day, the exact format of the message, the presence or absence of a THRowable with the log message, and so on. It is even possible to alter fields in the LogRecord, although this is not recommended.

Note that each logger and handler may have at most one filter each; there is no addFilter() method. However, it is possible to create a "master filter" that itself contains many other filters that will be checked in turn. It is difficult to imagine a filtering situation that would need such complex logic, but the facility is there if needed.

11.1.4. Configuring Logging through the API

To review: Loggers are named; each logger has a level and a set of handlers; and some handlers use formatters to prepare output. All of these steps can be controlled programmatically, as illustrated in following example:

public void manual() throws Exception {
Logger logger       =
Logger.getLogger(
"com.awl.toolbook.chapter11.manual");
FileHandler handler = new FileHandler("logdata.xml");
handler.setFormatter(new XMLFormatter());
logger.addHandler(handler);
logger.setLevel(Level.ALL);
logger.info("New user logged in");
}

This example creates a new FileHandler that is configured to send its data to logdata.xml and to format the data with a FileHandler. The handler is then added to the Logger obtained in the first line, and that Logger's level is set to ALL. Then an info-level log message is generated. It is not surprising that after this example is run, logdata.xml will contain a message much like the XML sample just shown. What may be surprising is that a message formated by the SimpleFormatter is also sent to the console. This is because the new handler is added to the logger, and the default root logger already has the console handler.

Due to the hierarchical nature of logger, if another logger is constructed with a name beneath the previous one in the hierarchy, it will have the same properties. After executing

Logger logger2 =
Logger.getLogger(
"com.awl.toolbook.chapter11.manual.sublogger");
logger2.info("Hello");

the "Hello" message will end up in the same logdata.xml file. However, logger2 is a distinct Logger instance, so if its level or set of handlers were altered programmatically, the changes would not automatically propagate up to logger.

While an entire hierarchy could be defined in this way, it is clearly tedious, and hard-coding such configuration within a program is never a good idea. It is much more common and efficient to use a configuration file.

11.1.5. Using Configuration Files

Logging is configured through a set of name/value pairs rather than through XML. This makes configuration very simple but implies some limitations, as will be seen shortly.

Typically configuration starts by setting properties for the root logger, the one at the top of the hierarchy. As all loggers are descendants of the root, setting properties for the root logger effectively sets defaults for the entire logging system. The root logger is named "" (the empty string), which can make relevant definitions look a little strange such as the level definition in the following example, which begins with a dot:

handlers = java.util.logging.ConsoleHandler,java.util.logging.FileHandler
.level = ALL

This will log all messages to both the console and a default file, using simple formatting. When the system is placed in production, the value of ALL might be changed to WARNING. Note that the level here is associated with the root logger, not the individual handlers that the logger is using.

Each handler can also be given a level and formatter, and some handlers have additional properties that can be set:

java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.FileHandler.level = FINEST
java.util.logging.FileHandler.pattern = debuglog.xml
java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter

these lines indicate that log messages at the information and higher levels should be sent to the console and that all debugging and higher messages should be saved to a file. The file is configured to use the XMLFormatter and to save its output in debuglog.xml The reason the file name property is called "pattern" instead of "name" is that it accepts a number of special characters that will be resolved by the logging system to form the file name. For example "%h" indicates the current user's home directory, and "%t" represents the system location for temporary files (typically/tmp on Unix and C:\temp for Windows).

It is possible to create an arbitrary number of additional loggers, each with its own level:

com.awl.toolbook.level = NONE
com.awl.toolbook.chapter12.level = INFO
com.awl.toolbook.chapter11.sample.level = ALL

This turns off logging for the book, enables information messages for most of the Chapter 11 examples, but it allows all messages for the "sample" logger within Chapter 11.

While each logger may have its own level, the handlers property is global, as are the attributes of each handler. This means there is no way to send the output for chapter 11 code to a separate file or to send it only to the console. There are a few workarounds for this, but they all involve doing some manipulation in Java code. This would split the configuration between two places, which in turn makes it more difficult to maintain. Log4j has a more flexible configuration system, as will be seen in the next section.

The logging system may be told to use a particular configuration file by specifying it on the command line:

java -Djava.util.logging.config.file=logconfig.properties classToRun

11.1.6. Creating New Handlers

Handlers are defined by an abstract class, so creating a new handler is just a matter of extending this class and providing implementations of the abstract methods.

A handler that might be useful is one that saves log messages to a database. This is not particularly useful for debugging messages or even for errors and warnings, but it may be very useful for informative messages about how a system is being used. Therefore, this kind of handler might be used in conjunction with a custom filter that only passes through messages at the INFO level, instead of INFO and above.

Conceptually writing a log message to a database using straight JDBC calls would not be difficult, but there is an even easier possibility. Because the LogRecord class largely adheres to the bean-naming convention, records can be saved to a database directly using OJB, as discussed in Chapter 10. To do this, a table definition and mapping will be needed. The table simply has fields for the properties of interest:

create table log (
millis      int,
message     varchar(200),
class_name  varchar(80),
method_name varchar(20)
);

Likewise the mapping is straightforward:

<class-descriptor
table="LOG">
<field-descriptor
name="millis"
column="ATIST_ID"
jdbc-type="INTEGER"
/>
<field-descriptor
name="name"
column="NAME"
jdbc-type="VARCHAR"
/>
<field-descriptor
name="name"
column="NAME"
jdbc-type="VARCHAR"
/>
<field-descriptor
name="name"
column="NAME"
jdbc-type="VARCHAR"
/>
</class-descriptor>

These definitions do not include all of the fields in LogRecord. Some fields are not useful in a database context. Other fields, like the log level, are useful but are not directly obtainable from LogRecord. This is because getLevel() returns a Level object, not an integer or other type that can be mapped to a JDBC type. Similarly, the time in LogRecord is stored in milliseconds, whereas JDBC needs a Timestamp.

With these definitions properly installed, the handler itself is fairly simple and is shown in Listing 11.2.

Listing 11.2. A handler that logs to a database

package com.awl.toolbook.chapter11;
import org.apache.ojb.broker.PersistenceBroker;
import org.apache.ojb.broker.PersistenceBrokerFactory;
import org.apache.ojb.broker.PersistenceBrokerException;
import java.util.logging.*;
class OJBHandler extends Handler   {
private PersistenceBroker broker_ = null;
private Logger logger =
Logger.getLogger("com.awl.toolbook.db");
public OJBHandler() {
try {
broker_ =
PersistenceBrokerFactory.
defaultPersistenceBroker();
} catch (Throwable t) {
t.printStackTrace();
}
}
public void publish(LogRecord record)  {
if(!isLoggable(record)) {
return;
}
try {
broker_.beginTransaction();
broker_.store(record);
broker_.commitTransaction();
} catch (PersistenceBrokerException e) {
broker_.abortTransaction();
logger.severe("Unable to log to database");
logger.log(record);
}
}
public void flush() {}
public void close() {}
}

The flush() and close() methods are declared abstract in the base class and so must be provided. They are meant to store all accumulated log messages and close the connection to the log repository, respectively.

All the action takes place in the publish() method. First, the isLoggable() method, which is defined in the base class, is called. This ensures that the level of the record is appropriate and that any installed filters will be checked. Then the record is stored using the standard OJB calls. It is almost as simple as that, but there is a serious danger lurking in this code.

This handler uses the logging system to report on problems it may encounter when writing to the database. In itself there is nothing wrong with a handler or other logging-related class using the logging API. In this case if the logger being used happens to be configured to use the OJBHandler, an infinite loop will occur. If the database write fails, then a log message will be generated, which will result in an attempt to write a record to the database, which will fail, and so on endlessly. There are a number of ways around this problem. The easiest is to call System.err.println() instead of using the log system. Alternately the logger could be manually configured within the constructor to ensure that it is only using safe handlers. Code could also be added to publish() to ignore messages from OJBHandler or a check that the level is INFO could be done in publish() instead of relying on it being configured in isLoggable().

Incidentally, note that the name of the logger is com.awl.toolbook.db, which does not exactly reflect the package name but instead suggests that all database-related activity will be logged to the same place.

There is a more subtle problem than the infinite loop lurking in Listing 11.2, which is that database access tends to be slow. Logging should be so fast that the addition of logging statements will have no noticeable effect on a program.

One fix to this problem would be to save log messages to the database asynchronously. In this model publish() would save the LogRecord to a Vector or ArrayList and a separate thread would periodically save all of the accumulated records to the database.

11.1.7. More on Formatting

The Java logging package has sophisticated, if somewhat convoluted, facilities for internationalizing log messages. The process relies on the Java platform's built-in internationalization features.

The process of internationzalizing logging messages starts by associating the name of a ResourceBundle with a logger. In Java code this can be done by providing the name as a second argument to getLogger().

Logger logger =
Logger.getLogger("com.awl.toolbook.chapter11.sample",
"logMessages");

Regrettably this information cannot be specified in the configuration file, so in normal use the resource bundle name must be specified in every call to getLogger(). Since resource bundle names are inherited hierarchically, the impact of this can be minimized by attaching a resource bundle to the root logger in initialization code:

Logger.getLogger(","logMessages");

The resource bundle should contain every message that the program will log, and there should be a version of the bundle for every locale that will be supported. By associating the bundle name with the root logger a single file would contain all of a program's messages. If this file is too large or unwieldy, it may make sense to split it into several bundles, but the cost is that now the program will need to keep track of different bundle names when calling getLogger().

A typical file for English-speaking countries would be called logMessage_en.properties and would contain lines such as

startMessage=Started successfully
infoMessage=New user {0}   entered at {1,date} {1,time}
errorMessage1=Unable to save data: {0}
errorMessage2=Something terrible happened

while a file for German-speaking countries would be called logMessages_de.properties and would contain

startMessage=richtig begonnen
infoMessage=Neues Benutzer{0}   kam bei {1,date} {1,time}
errorMessage1=Nicht imstande, Daten zu speichern: {0}
errorMessage2=Schreckliches etwas ist geschehen

Each entry is a string suitable for use with MessageFormat from the java.text package.

With such a resource bundle in place logging calls will no longer pass a message to be logged but rather the name of a key within the bundle to use for formatting plus an array of objects, which will be used as parameters. For the preceding definitions, any of the following calls might be used in the program:

logger.log(Level.INFO,"startMessage",new Object[] {});
logger.log(Level.INFO,"infoMessage",
new Object[] {username, new Date()});
logger.log(Level.WARNING,"errorMessage1",
new Object[] {theException});
logger.log(Level.SEVER,"startMessage",new Object[] {});