Introduction

Maybe I am just thick or something, I don't know, but the logging API that came with Java 1.4 just confused the hell out of me (and still does). I understand the concept of having a hierarchy of loggers but I have just never managed to get it to do what I wanted when I wanted it. Everytime I try I seem to end up with either everything or nothing coming out and the whole use parent loggers thing just adds to the confusion. I have decided therefore that it is about time I figured it out once and for all and this is what this page is about.

The Basics

The most important classes in the Java logging API are Logger and Handler as they deal with the hard work of getting a log message from your applicaiton to where ever you want it to be. Following closely in the wake though are the classes Fliter, Formatter and Level which between them divide up the work of deciding whether to publish the log message and how it will look when it is published. Finally there is the LogRecord class itself which, although a core class, isn't actually directly used that often and we will see why in a moment. Sort of out on its own is the LogManager class that looks after the Logging API and performs strange magic.

You application makes a call on a Logger object in order to log a message. There are numerous methods that can be used to log a message and we will look at some of them in more depth below. For the moment lets assume that the application calls the convenience method info on a Logger object called log (e.g. log.info( "message" );). This attempts to publish a log message at the info level (Level.INFO) which will be published if the Logger, Handler and any associated Filters all agree that it should be.

Slow down a bit! What's a Handler and Filter?

Each logger contains a list of Handlers that it will pass the log message (LogRecord) to, in turn, if the LogRecord Level is greater than or equal to the Level currently set on the Logger. So to get the message created above published we would need to first make sure that the Level set in the Logger is less than or equal to Level.INFO. If there is a Filter associated with the Logger this to must let the LogRecord through before it will get to see any Handlers. Filters can make arbitary choices about whether to pass the LogRecord on.

Assuming our Logger lets the LogRecord through it passes the LogRecord to each of the Handlers currently registered with it in turn (in technical parlence it publishes the LogRecord). The LogRecord now runs the gauntlet again in the Handler which can also discard the LogRecord based on its Level and an associated Filter. If the LogRecord gets though the level check and the filter it will be published. If the Handler has an associated Formatter the LogRecord is formatted prior to publishing.

After the Logger has passed the LogRecord to all of its Handlers it then by default passes the LogRecord to its parents Handlers which will then possibly also publish the LogRecord. This behaviour can be stopped by setting useParentHandlers to false. The diagram below shows this whole process except the calls to parent Handlers (SVG Version). Note that when the LogRecord gets passed to the parent loggers Handlers it doesn't matter what the Level of the parent Logger is only the Level of the Handlers.

Java Logging Flow Chart

To illustrate the effect of passing the messaget to parent Handlers see the diagram below (SVG Version). LogRecord-1 passed into Logger-1 will be handled by Handler-1 and Handler-2 (I'm assuming everything is set to process all LogRecords. LogRecord-2, passed into Logger-3, will be handled by all five Handlers.

Java Logging Hierarchy Flow Chart

Well that seems simple enough

Well that is just nto quite the whole story but it is certainly enough to get you going. The Jave Runtime comes with one Logger implimentation and a few Handlers that will publish LogRecords to various useful places. There is only one Logger because quite frankly there isn't a lot else you can do with a Logger but you might want to write a new handler. One that is missing is a JDBCHandler that will send LogRecords to a database. I assume that it is "missing" because there is just to much variability in the way you might want to store the LogRecord.

Only the MemoryHandler is a little strange out of the basic Handlers supplied. It accepts another Handler as an argument to one of its constructors that performs the actual publishing and formatting of LogRecords (any Formatter passed to a MemoryHander isn't used). The FileHandler is the most difficult to construct as it also does file rotation as well for which it requires a file name pattern.

Logger Names and the Hierarchy

This is the one area where I firmly believe Sun have screwed up the API. While having a hierarchy of Loggers is a good thing the way that hierarchy is defined, IMHO, leaves a lot to be desired. I would have liked to have had an explicit hierachy but what we have is a heirarchy built using magic string processing. The final root of all Logger hierarchies is the "" (yes that's an empty string) root logger. Loggers are generally given names that match the package that they are logging for. For instance the Logger called "com.crazysquirrel.foo" would log for the package with the same name but if there was a subpackage called bar it may well log for that as well. I, personally, create a Logger for each packageas it keeps the organization simple. A Loggers parent is determined by processing the name of the Logger and building a hierachy that way such that "com.crazysquirrel" would be the parent logger for "com.crazysquirrel.foo" which would in turn be the parent of "com.crazysquirrel.foo.bar". If you create an anonymous logger it has its parent set to the root logger.

Logger Inheritance

Loggers inherit certain characteristics from their parents when they are created, Typically a Logger will inherit the following:

Logging Convenience Methods

The default Logger implimentation has numerous convenience logging methods that can save a great deal of time when adding log messages to code. The convenience methods take one of two forms. Either "void info( String message )" or "void info( String sourceClass, String sourceMethod, String message )". The first version is sold to developers that want quick logging the second is to developers that want accurate logging. The second is more "accurate" because it explicitly names the source class and method, information that may be lost when the class is JITed. In reality I have never seen the first version turn out the wrong result (or no result which is more likely).

Logging Configuration

This section will have a bit of a Tomcat twist to it towards the end because most of my work is done with Tomcat. This is another area where Sun seem to have dropped the ball a little. There is no way using the basic Java logging framework to distinguish between different web applications in the same container if they use the same Logger. This means that if you had the same code deployed twice you wouldn't be able to tell where the log messages were coming from. Log4j solves that problem but for now we will stick to the default Java logging API and later I will show you a way round the problem.

Configuring Java Logging

Logging can be configured in three different ways: you can supply a properties file that describes the logging setup (by default this is called logging.properties and lives in JRE/lib/), you can provide a class that can be instantiated at VM initialisation that will configure the logging or you can roll your own logging configuration. I include rolling you own because I don't like either of the other two solutions much. The first means you have to play with a file that lives in one of hte VM distribution directories which, to my mind, is a bad thing. The second means adding another argument to the invocation of the VM which, IMHO, leads to screw ups. Either way, those are your options. I will focus mostly on the properties file as that is more commonly used. The class configuration technique is useful of you need to configure loggers from a database or other source but if you need something that complex you probably have enough time to "do it right".

The logging.properties file simply defines a number of Loggers, Handlers, Formatters and Filters that are constructed and ready to go shortly after the VM has loaded. Normally the top portion of the file is devoted to setting up Handlers for the root logger. The set up for the root Logger is a little different to the other Loggers because it doesn't have a name. To add handlers to the root logger include a line that begins handlers and then lists the handlers to add to the root logger. For instance this

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

will add a ConsoleHandler and FileHandler to the root logger. Next set the logging level of the root logger which is done with the name .level. To set it to all use

.level = ALL

To set the logging levels for the two handlers created add lines like this

java.util.logging.ConsoleHandler.level = INFO
java.util.logging.FileHandler.level = ALL

and finally to set a formatter simply specify its name like this

java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

It is possible to set any of the instance variables on the Loggers, Handlers, Formatters and Filters in a similar manner by specifying its name followed by the property name you want to set. To set handlers on other loggers use the syntax loggerName.handlers=list_of_handler_class_names.

You can probably see the limitation in the default Java logging setup now. There is no way to separatly configure the handlers for different loggers because you have no way to seperate the names of the handlers - you have to refer to them by their class name.

Configuring Java Logging in Tomcat

As stated above the default logging supplied by the Java packages does not have the ability to distinguish between different web applications because all the configuration is done at the VM level. For this reason Tomcat 5.5.9 replaces the default LogManager with a more web application friendly implimentation called JULI (Note: on the Tomcat site it implies that all 5.5.x versions include JULI but it wasn't actually included until 5.5.9). To configure JULI you can place a file called logging.properties in the the directory $CATALINA_HOME/common/classes or in your web applications WEB-INF/classes directory. The format of the file is very similar to that of the default Java configuration but it has some additional options that allow it to set up logging on a per-web application basis.

The most important extenstion is to the handler definitions. Each handler can take an optional prefix which takes the form of a numeral followed by any alphanumerics and ends with a ".". For instance a valid perfix would be "7foo.". This lets you define different handlers for different loggers and configure them separatly. Loggers are still shared at the VM level but you can at least now turn sections of logging on and off. For instance to define handlers for the logger "com.crazysquirrel" you might place a file such as this in the WEB-INF/class directory of your web application

handlers = org.apache.juli.FileHandler, java.util.logging.ConsoleHandler

org.apache.juli.FileHandler.level=ALL
org.apache.juli.FileHandler.directory=${catalina.base}/logs
org.apache.juli.FileHandler.prefix=cs-logging-test-

java.util.logging.ConsoleHandler.level=FINE
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

com.crazysquirrel.level=ALL

However I prefer not to have handlers associated with the root logger unless I actually want them to be there. The above configuration defines two handlers and associates both handlers with the root logger. This can be seen in the output below which comes from a little utility class I wrote to output logger information (I have removed the Catalina logger information for readability).

LOGGER NAME: "com.crazysquirrel"     Level: ALL     Use Parents Handlers: yes
        Parent Path: "com.crazysquirrel" --> ""
....
Catalina Logger Information
....
LOGGER NAME: ""     Level: null     Use Parents Handlers: yes
        Parent Path: ""
        Handler Type: class org.apache.juli.FileHandler Level: ALL
        Handler Type: class java.util.logging.ConsoleHandler Level: FINE

In order to use a handler you have to specify it in the handlers line. For instance this log configuration file

com.crazysquirrel.level=ALL
com.crazysquirrel.handlers=org.apache.juli.FileHandler

org.apache.juli.FileHandler.level=ALL
org.apache.juli.FileHandler.directory=${catalina.base}/logs
org.apache.juli.FileHandler.prefix=cs-logging-test-

java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

produces the following actual configuration

LOGGER NAME: "com.crazysquirrel"     Level: ALL     Use Parents Handlers: no
        Parent Path: "com.crazysquirrel" --> ""
....
Catalina Logger Information
....
LOGGER NAME: ""     Level: null     Use Parents Handlers: yes
        Parent Path: ""

which as you can see doesn't have either of the loggers we tried to define in the configuration file. At first glance then it would seem that there is no way to avoid having all the handlers associated with the root handler but that isn't the case. If don't have a .handlers line then all the handlers become associated with the root handler. If you do have a .handlers line then only those handlers specified become associated with the root handler. Not behaviour that I particularly like, feels like a side effect, but at least you can get round it. The configuration file shown below produces a more pleasing configuration.

handlers=java.util.logging.ConsoleHandler, org.apache.juli.FileHandler

.handlers=java.util.logging.ConsoleHandler

com.crazysquirrel.level=ALL
com.crazysquirrel.handlers=org.apache.juli.FileHandler

org.apache.juli.FileHandler.level=ALL
org.apache.juli.FileHandler.directory=${catalina.base}/logs
org.apache.juli.FileHandler.prefix=cs-logging-test-

java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

like this

LOGGER NAME: "com.crazysquirrel"     Level: ALL     Use Parents Handlers: no
        Parent Path: "com.crazysquirrel" --> ""
        Handler Type: class org.apache.juli.FileHandler Level: ALL
....
Catalina Logger Information
....
LOGGER NAME: ""     Level: null     Use Parents Handlers: yes
        Parent Path: ""
        Handler Type: class java.util.logging.ConsoleHandler Level: ALL

As you can see the ConsoleHandler is associted with the root logger and the FileHandler is associated with the com.crazysquirrel logger (the highest logger for this website).

There are a few other small differences between JULI and the default implimentation. One that could come as a supprise is the handling of use parent loggers. With JULI, by default, loggers don't use parent handlers unless they have no handlers of their own. When you think about it this means that most of the time you will probably get exactly the same behaviour that you had before because most configurations only have handlers on the loggers near the root. The other notable difference is that you can use system porperties in the configuration file and they will be automatically expanded. See the official documentation for more information.

Resources