The message comes in, the logger checks its level against its own (loggers use ALL as their default level), then passes the message to each handler for another check. A WARNING in this example would get output to both the file and console but a FINEST would go only to the file.

The log() Methods

The severe(), warning(), info(), and other methods are convenience methods. The Logger's log() method provides access to more advanced log features including custom levels, logging exceptions and errors, and variable substitution for more efficient logging. The log() method signatures look like this:

log(Level level, String msg);
log(Level level, String msg, Throwable t);
log(Level level, String msg, Object param);
log(Level level, String msg, Object[] params)

Every log() method accepts a level and a message. Beyond that you have the option to pass a Throwable to log an Exception (or an Error) or you can pass an Object or Object[] parameter set to support variable substitution. We'll talk about variable substitution in the internationalization section.

To demonstrate the use of the log() method, the following method call reports a RuntimeException:

logger.log(Level.SEVERE, "Error during build",
           new RuntimeException("oh oh"));

This call produces the following output on the console:

Jul 18, 2004 5:39:55 PM HelloLogger main
SEVERE: Error during build
java.lang.RuntimeException: oh oh
  at HelloLogger.main(HelloLogger.java:15)

Assuming the file handler's still registered, this also produces the following to a file:

<message>Error during build</message>
<exception>
  <message>java.lang.RuntimeException:
           oh oh</message>
  <frame>
    <class>HelloLogger</class>
    <method>main</method>
    <line>15</line>
  </frame>
</exception>

The XML format makes it easy to use languages like XSLT or XQuery to reformat the output however you like. The XML DTD for file output can be found at http://java.sun.com/dtd/logger.dtd.

Parentage

Each logger has a name, and it's customary for names to be either a package name or a class name that including the package. Logger hierarchies are inferred based on the name. The logger named "org.jdom" for example is considered the parent for the logger "org.jdom.Element". You never have to set the parentage, it's just assumed. At the top there's a root logger named the empty string, "".

A child inherits the properties of its parent, or its parents parent, going to the root for global default if necessary. Inheritance works a little differently than in object-oriented programs. The following code snippet demonstrates by showing how messages written to a class logger can have their level controlled by the package logger. The string being logged reports whether the log message is displayed or hidden.

base = Logger.getLogger("org.jdom");
elt =  Logger.getLogger("org.jdom.Element");
attr = Logger.getLogger("org.jdom.Attribute");
// base == elt.getParent()

elt.info("Displayed");
attr.info("Displayed");
base.setLevel(Level.SEVERE);
elt.info("Hidden");
attr.info("Hidden");
elt.setLevel(Level.INFO);
elt.info("Displayed");
attr.info("Hidden");

elt.setLevel(null);
elt.info("Hidden");

The tricky part of parentage is understanding that setting a parent property doesn't push the setting on its children. Child loggers have their own settings but at runtime look up the tree for a value if they ever have an unset property. That's why the elt.setLevel(null) calls causes the elt to start inheriting the base property value.

Behind the Scenes

You now know enough that you're ready to hear the full truth: Each logger doesn't actually have its own console handler. The logger named "" has that handler, and the child loggers write to their parents' handlers as well as their own. There's also a couple classes, Filter and LogRecord, that we've glossed over until now. Here's what really happens behind the scenes when a message is logged:

1. The Logger checks the message's level against its own.
2. If the message passes that quick test, the logger creates a LogRecord for that message.
3. If there's a registered Filter on the logger then the filter is applied.
4. If that passes, the logger pushes the record to each registered Handler.
5. Each handler applies its own level and filter.
6. The logger then passes control of the message to its parent's handlers, recursively up the tree. This allows, for example, attaching a file handler to the "org.jdom" logger to view all sublogger activity.

Filters allow for programmatic decision-making on whether a message should be logged. There are no standard Filter implementations. You write your own by implementing the Filter interface and returning a boolean "yea" or "nay" based on the LogRecord received and whatever logic you want to employ. Here's the process shown graphically:

The following Filter implementation removes any successive duplicate entries.

class UniqFilter implements Filter {
  String msg = null;

  public boolean isLoggable(LogRecord record) {
    String newMsg = record.getMessage();
    if (msg != null && msg.equals(newMsg)) {
      return false;  // duplicate
    }
    else {
      msg = newMsg;
      return true;   // new message
    }
  }
}

The isLoggable(LogRecord) method returns true if the message is new and false if it's the same as the previous message.

You can set filters on a Logger or on a Handler or both. There's just one per Logger or Handler though. If you want two filters applied, you need to write a meta-filter. This code uses the UniqFilter to demonstrate applying a filter:

core.setFilter(new UniqFilter());

core.info("1");
core.info("1");  // suppressed
core.info("2");
core.info("3");
core.info("3");  // suppressed

Odd fact: filters aren't inherited. Only properties and (in a way) handlers have that distinction. So applying a filter on "org.jdom" doesn't affect "org.jdom.Element" output.

Handlers

Handlers act as the output channels for the Logging API. Each logger can have any number of handlers associated with it.

In java.util.logging you'll find four standard handlers for writing to the console, files, sockets, or to a circular array in memory. You can also write your own handler by extending the Handler class. Let's take a look at the four standard handlers.

ConsoleHandler

The ConsoleHandler prints to the console (technically, System.err). The root logger (that is, the empty string logger) has a single ConsoleHandler set by default. We saw the output from this console handler in our initial example. Here's a little code to tinker with console handlers:

Logger logger = Logger.getLogger("Console");
Handler console = new ConsoleHandler();
logger.addHandler(console);
logger.info("test");  // prints TWICE

logger.setUseParentHandlers(false);
logger.info("once");  // prints ONCE

The first line constructs a logger named "Console" whose parent is the root handler. The next two construct and add a ConsoleHandler to the logger. That results in info() calls producing double output, once for each handler. By turning off the "use parent handlers" feature, a later test prints only once. Feel free to disable the "use parent handlers" feature if it gets in your way.

FileHandler

The FileHandler naturally writes to a file. You can choose which file via its constructor. If you specify a simple file name like "file.log" the output goes to a new file by that name placed in the current working directory. A second argument lets you specify that you want appending. Here's an example:

// Specified name, appending
file = new FileHandler("file.log", true);

You can also specify the name using the following filename patterns:

%t = a temporary directory
%h = the user's home directory
%g = generation number (for log rotation)
%u = a unique number

For example:

file = new FileHandler("%t/java%g.log");

If no file name is given, the default file name is "%h/java%u.log". Following the filename pattern substitution rules that produces a file under the home directory with a name like "java12.log".

The FileHandler also supports log rotation. Log rotation solves a common problem that occurs with any long-running server producing a large amount of log output: Eventually the log file gets too large. Log rotation helps by changing out the log file periodically, either after some time period or when some file size limit is reached. The rotated out file can then be compressed and moved offline.

Log rotation can be difficult without server support due to file access concurrency concerns. The FileHandler class conveniently includes built-in size-based log rotation support. The following constructor creates a FileHandler that rotates between 10 log files, switching when they reach approximately 1MB:

file = new FileHandler("%t/java%g.log", 1000000, 10, true);

You can use %g to specify the log generation number.

SocketHandler

SocketHandler is designed to send log messages across the network. It's a surprisingly powerful capability. Just construct a SocketHandler with a named host and port, and your log messages jump across the network. For example:

Logger logger = Logger.getLogger("Socket");
Handler socket = 
  new SocketHandler("localhost", 5044);
logger.addHandler(socket);

The SocketHandler defaults to the ALL level and XML formatter. The constructor throws an IOException if the socket won't open, so watch for that.

MemoryHandler

The MemoryHandler holds the title as coolest and most convenient handler. How many times have you stumbled upon an error but not had enough debugging context to fix it? How many hours have you wasted trying to reproduce the bug after you turned on tracing? The MemoryHandler solves this problem. It holds log messages in a circular buffer in memory. On certain triggers, the handler outputs its buffer to another handler for output. Triggers include: an entry above a certain level, an explicit push() call, or a handler subclass overriding log() and choosing when to call push(). The default is to buffer up to 1000 entries at ALL levels with a push on any SEVERE entry.

By using a MemoryHandler during development you can capture all log output but not write it anywhere until a certain trigger such as a SEVERE problem. The MemoryHandler essentially lets you jump back in time to see the last 1000 messages. Tie it together with a SocketHandler and you're quickly sending detailed error reports from client machines across the network. Here's the code:

// Send the last 1000 messages to the socket handler
// whenever you see message with a SEVERE log level
Logger logger = Logger.getLogger("Memory");
Handler socket = new SocketHandler("localhost", 5044);
Handler memory = new MemoryHandler(socket, 1000, Level.SEVERE);
logger.addHandler(memory);

Formatter

The Logger and Handler classes control the "what" and "where" for logging. The Formatter class controls the how. Each formatter takes a LogRecord and formats it into a String for writing. J2SE 1.4 provides two standard formatters, SimpleFormatter (as you saw with the console) and XMLFormatter (as you saw with the file). The following code accesses the handlers for the root logger, finds the ConsoleHandler, and changes its formatter:

Logger root = Logger.getLogger("");
handlers = root.getHandlers();  // returns 1

for (int i = 0; i < handlers.length; i++) {
  if (handlers[i] instanceof ConsoleHandler) {
    ((ConsoleHandler)handlers[i])
        .setFormatter(new XMLFormatter());
  }
}

To write a custom formatter, extend Formatter and implement format(LogRecord). The following ShortFormatter produces one-liner output, an easier to read format than the SimpleFormatter's two lines:

class ShortFormatter extends Formatter {
  // inefficient implementation
  public String format(LogRecord record) {
     return record.getLevel() + " [" +
         record.getSourceClassName() + ":" +
         record.getSourceMethodName() + "] " +
         record.getMessage() + "\n";
  }
}

After you set this formatter for the console (using the code shown earlier), the console output changes to look like this:

SEVERE [Formatting:main] Major issue
WARNING [Formatting:main] Potential problem

The Everything Diagram

Now you're learned about loggers, levels, filters, handlers, formatters, and parentage. The following diagram puts everything together.

The flow starts at the bottom left where the log message first comes in from the application. It's quickly-checked against the logger's level. If the message fails the fast level check, it's rejected and no more time is wasted on the message.

If the message passes the level check, the logger creates a LogRecord and passes it to the logger's filter (if any). If it passes the filter, it goes on to each of the logger's registered handlers in turn. Each handler checks its level, applies its filter, and if it passes both then sends the message through the formatter to be written by the handler.

Finally, if "use parent filters" is true, the logger passes control to its parent logger whose handlers get applied. The logger level isn't checked again, but if the initial logger didn't have its own level set, it would inherit the level from its parent.

Localization

Localization is the process of presenting interfaces and writing output in a manner and language appropriate for the locale in which a program executes. Somewhat surprisingly, most log messages don't need to be localized. If you look at the four use cases listed earlier, only use case #1 (problem diagnosis by end users and system administrators) requires localization. The other messages can be left localized for the developer's locale.

Loggers have built-in support for localization using the logrb() method. The "rb" stands for "resource bundle". This log method takes as an extra argument the name of a resource bundle for use in localizing the output message. Here are the method signatures:

logrb(Level level, String srcClass,
      String srcMethod, String bundleName,
      String msg);
logrb(Level level, String srcClass,
      String srcMethod, String bundleName,
      String msg, Object param);
logrb(Level level, String srcClass,
      String srcMethod, String bundleName,
      String msg, Object[] params);

When using logrb() the message string is a lookup key rather than text to output. The system locates the named resource bundle as appropriate for the current locale and looks within it for the phrase corresponding to the lookup key. Variable substitution occurs if necessary. For example, the following warns the user that a file has the wrong size:

logger.logrb(Level.INFO, "Fmt", "main",
             "demobundle", "warning.badsize",
             new Integer(-1));

The demobundle_en.properties file (the appropriate resource bundle for English) might contain:

warning.badsize=Your file was {0} bytes long

The output then is:

Jun 18, 2002 10:21:21 PM Fmt main
INFO: Your file was -1 bytes long

A different system locale would produce a different message and place the -1 value wherever appropriate.

Performance Trick In Java we first saw variable substitution used for internationalization and localization, because in those cases simple string concatentation isn't possible. With simple log() methods you could rely on string concatentation like this: logger.log(Level.INFO, "Your file was " + size + " bytes long"); The problem with this approach is that the runtime must perform the string concatentation before executing the log() method call. That wastes CPU cycles and memory when the logger's going to reject the message for being at too low a level. The solution is to use variable substitution and avoid all concatentation: logger.log(Level.INFO, "Your file was {0} bytes long", size); This call executes directly and the substitution only happens after the message has passed the logger's quick level check.

Error Handling

Error handling in a logging system poses an interesting challenge, and the solution used by the Logging API is one worth pointing out and utilizing in our own projects. The challenge comes from the fact that when there's a problem during the log() call, the caller isn't likely to know what to do about it and may not even care. The caller is simply a user of the logging subsystem. Making the user handle subsystem errors — putting try/catch blocks around calls to log() — is not a viable solution.

The solution is to register an ErrorManager instance with each handler that should get notified in case of problems. The error manager encapsulates and isolates error management rather than spreading it among all its callers. It's a similar solution to the SAX ErrorHandler that handles warnings, errors, and fatal conditions encountered during XML processing. In SAX you can't pop the stack to report recoverable warnings, but neither can you wait until processing is complete to find out if a warning should have halted processing. The error manager/handler pattern solves this problem elegantly.

The default logging error manager prints a message the first time and suppresses later duplicate reports. The following code changes that behavior to suppress all error reports (probably a bad idea):

  Logger logger = Logger.getLogger("");
  Handler h = new FileHandler();
  h.setErrorManager(new EmptyErrorManager());
  logger.addHandler(h);

class EmptyErrorManager extends ErrorManager {
  public void error(String msg, Exception ex,
                    int code) { }
}

Configuration Files

Throughout this article I've told you about many default values and behaviors. In reality many of these aren't hard-coded defaults but are set in a global configuration file under the "jre/lib" directory in the file "logging.properties".

An example path location would be /jdk1.4.0/jre/lib/logging.properties; this file dictates the logger subsystem defaults. Here are some pertinent lines extracted from the file:

# "handlers" specifies a comma separated list of log Handler
# classes.  These handlers will be installed during VM startup.
# Note that these classes must be on the system classpath.
# By default we only configure a ConsoleHandler, which will only
# show messages at the INFO and above levels.
handlers= java.util.logging.ConsoleHandler

# Default global logging level.
# This specifies which kinds of events are logged across
# all loggers.  For any given facility this global level
# can be overriden by a facility specific level
# Note that the ConsoleHandler also has a separate level
# setting to limit messages printed to the console.
.level= INFO

# default file output is in user's home directory.
java.util.logging.FileHandler.pattern = %h/java%u.log
java.util.logging.FileHandler.limit = 50000
java.util.logging.FileHandler.count = 1
java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter

# Limit the message that are printed on the console to INFO and above.
java.util.logging.ConsoleHandler.level = INFO
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

You can override the global values by editing this file, but I don't recommend changing Java's global defaults. It's better to make changes locally by setting the java.util.logging.config.file system property to point at a properties file of your own choosing like this:

java -Djava.util.logging.config.file=mylogging.properties Main

You can use the logging.properties global file as a starting point for your own.

Conclusion

The Logging API introduced in J2SE 1.4 provides both a standard and convenient way to report end-user problems, write profiling information, dump error states, or observe program activity. With all the configuration options between levels, filters, handler, and formatters it's possible to accomplish practically anything, often in more than one way.

As J2SE 1.4 becomes commonplace, its logging features will provide a uniform mechanism to observe and capture program output. For those using J2SE 1.3 still, try Apache log4j. You might even want to try it if you're using J2SE 1.4.

If your log message isn't showing up and you can't figure out why, check:

• The logger level and filter
• The handler level and filter
• Any intermediate (i.e. memory) handler level and filter
• If there are any inherited parent logger settings.

If all those fail, write your own handler and possibly formatter and see how far the message makes it before it disappears.

You've now had the full overview of logging, and with this series a full overview of J2SE 1.4's useful features for enterprise developers. Best of luck, and now on to J2SE 1.5!