In JDK 1.4, which was made public in February 2002, Sun introduced a logging API. Until then developers could use one of the many open source logging systems, like Log4J, or implement their own logging mechanism. You'll find many fine articles on the web describing the new Sun Logging API--see the Resources section at the end of my article--so I'll only give you the most important details as a start. We'll then dig down into a few topics which I haven't seen described yet on the web.
But first:
The answer is really quite simple: it's a way for your application to tell IT people (developers, administrators, supporters, maintainers, the performance staff, etc.) what's going on inside the Java code. The developers need information during development an debugging. The support staff needs data when the application hits an error. Production people need performance data in order to make best use of computer resources and improve performance. Here are some of the things that could be logged:
For most applications you don't have to worry about any negative performance impact caused by the logging code. In production you'd typically switch most logging off, and the JDK 1.4 logging API--and most other popular logging APIs--are designed to be cheap if you don't send much data to the logs. The day you need more logging data--e.g. when a bug has appeared or when you need to measure performance--you can switch logging on for the modules you need.
I hope this'll motivate you for our journey into the design and usage of the JDK 1.4 Logging API.
When using the JDK 1.4 Logging API in your applications you work with Logger objects when sending a message to a log. It's wonderfully simple to work with a logger:
// Define the logger
Logger logger = Logger.getLogger("hansen.Game");
. . .
// Use the logger
logger.info("Game started");
Couldn't be much simpler.
But where does the message end? This is where the Handlers come into the picture. A handler defines the target for logging. It could be the console, a file, or the Windows NT event log, to name a few possibilities. So every logger needs at least one handler in order for the messages to have a place to go. The JDK defines 5 handlers:
The ConsoleHandler and the FileHandler are probably the most popular ones, covering most applications basic needs.
Finally we have the Formatters. As their name imply they determine the layout of the messages. Sun has defined two formatters:
Every handler has an associated formatter.
In this example we have defined two loggers. Logger1 has a single ConsoleHandler that uses the SimpleFormatter. Logger2 also has a ConsoleHandler (maybe with other properties) but also has a FileHandler that writes messages in XML format.
It's possible to define your own handlers and formatters.
The default set-up which you get if you don't do anything special is a ConsoleHandler using the SimpleFormatter. If you place the code fragment found at the beginning of this article in a main method and run it, you'll get this written to System.err:
11-08-2002 18:57:37 hansen.playground.logging.LogDef main INFO: Game started
Every logger and every message has an associated logging Level. If a logger receives a message for logging and the message has a level lower than what the logger is set up to log, then the logger discards the message. The following levels are pre-defined: SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST.
Handlers also have levels, and they're used in the same way as for loggers.
Loggers are placed in a hierarchy. Given are two loggers: the root logger (with no name) and the global logger, which has the root logger as its parent. If you define two loggers:
Logger logger1 = Logger.getLogger("abc.def");
Logger logger2 = Logger.getLogger("abc.def.Game");
then you'll get this hierarchy:
The consequences of having this hierarchy are:
There are some rules regarding "sending messages up the tree" that should be observed:
If, for example, no handlers are explicitly specified for "abc.def.Game" and "abc.def" then it's only the handler for the root logger that will produce any output. A logger may however choose to break this chain by calling its setUseParentHandlers method with the value false.
I'll not use time on Filters, but just mention that a handler also checks it's filter (if one is defined) to see if logging should be done. A filter is a class that can inspect all the data that goes into the message and then determine if the message should be logged. See the resources section if you'd like to read more about filters.
The Logging API allows you to define the logging configuration in detail. The default logging configuration comes from the logging.properties file, which you find in the JDK's jre/lib directory. In this file you define the handlers for the root logger:
One handler:
handlers= java.util.logging.ConsoleHandler
Two handlers:
handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler
You may also define the default properties for the handlers, e.g.:
java.util.logging.ConsoleHandler.level = INFO java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
These default properties apply to any logger that uses these handlers.
Finally you may define the level for any named logger like this:
The root logger:
.level= INFO
Other loggers:
com.xyz.foo.level = SEVERE
If you want to use for example FileHandlers with different properties, then the logging.properties file can't be used, but the logging API has plenty of methods that you may use to accomplish the tasks. A pair of examples:
A logger with a ConsoleHandler with low priority level:
Logger logger1 = Logger.getLogger("abc.def");
logger1.setLevel(Level.FINEST);
ConsoleHandler c1 = new ConsoleHandler();
c1.setLevel(Level.FINEST);
logger1.addHandler(c1);
A logger with a FileHandler using a home made formatter:
Logger logger2 = Logger.getLogger("abc.def.ghi");
logger2.setLevel(Level.CONFIG);
FileHandler f2 = new FileHandler("%h/mylog.txt", 10000, 2, false);
f2.setFormatter(new MyFormatter());
f2.setLevel(Level.CONFIG);
logger2.addHandler(f2);
First we'll code a helper class that can reveal any application's use of loggers, handlers and formatters. To get this information we use a singleton class from the logging API--the LogManager--which administers all the active loggers. The helper class is called LoggerInformation , and if you click on the link, you will see the Java source code in a separate window.
The LoggerInformation class works like this:
LoggerInformation simply writes the information to System.out. The tryLevels method at the bottom of the class can be used to send all the standard message types to a given logger.
First we'll use the LoggerInformation class to show us the default logging setup. For this purpose we simply use a program that doesn't define any loggers explicitly:
package hansen.playground.logging;
import java.util.*;
import java.util.logging.*;
public class Log0 {
public static void main(String[] args) {
// Show info for default loggers
LoggerInformation.getInfo();
}
} |
If we run this program we get this written to the console:
***Begin Logger Information ----------------------- Logger name: >global< Logger level: null No filter used No handlers defined Parent: >< ----------------------- Logger name: >< Logger level: INFO No filter used Handlers: java.util.logging.ConsoleHandler using formatter: java.util.logging.SimpleFormatter using level: INFO no filter No parent *** End Logger Information |
What we can see is this:
Now let's add a single logger to our program:
package hansen.playground.logging;
import java.util.*;
import java.util.logging.*;
public class Log1 {
private static Logger logger1 =
Logger.getLogger(Log1.class.getName());
public static void main(String[] args) {
LoggerInformation.getInfo();
LoggerInformation.tryLevels(logger1);
}
} |
Note, that I've added a call to tryLevels. This time we'll get this on the console:
***Begin Logger Information ----------------------- Logger name: >global< Logger level: null No filter used No handlers defined Parent: >< ----------------------- Logger name: >hansen.playground.logging.Log1< Logger level: null No filter used No handlers defined Parent: >< ----------------------- Logger name: >< Logger level: INFO No filter used Handlers: java.util.logging.ConsoleHandler using formatter: java.util.logging.SimpleFormatter using level: INFO no filter No parent *** End Logger Information 11-08-2002 11:30:04 hansen.playground.logging.LoggerInformation tryLevels SEVERE: severe message 11-08-2002 11:30:05 hansen.playground.logging.LoggerInformation tryLevels WARNING: warning message 11-08-2002 11:30:05 hansen.playground.logging.LoggerInformation tryLevels INFO: info message |
This time our own logger--hansen.playground.logging.Log1--has been added to the list. Since we haven't defined anything for the logger it inherits its level and uses the handler from the "root" logger--as "global" did.
The messages with a level of at least "INFO" are the only ones written to the console.
Every handler must have a formatter defined, and the API has pre-defined a SimpleFormatter and an XMLFormatter which both extend the abstract class Formatter. You may define your own formatter if you like, and it's actually quite simple. You only have to implement the format method. This method receives an instance of the LogRecord class which contains several properties. format returns a string with the data that should be logged. In the next example I've made a formatter that returns the most important properties from the LogRecord:
package hansen.playground.logging;
import java.util.*;
import java.util.logging.*;
public class MyFormatter extends Formatter {
public String format(LogRecord record) {
return
"LogRecord info:\n" +
"Level: " + record.getLevel() + '\n' +
"LoggerName: " + record.getLoggerName() + '\n' +
"Message: " + record.getMessage() + '\n' +
"Millis: " + record.getMillis() + '\n' +
"Sequence Number: " + record.getSequenceNumber() + '\n' +
"SourceClassName: " + record.getSourceClassName() + '\n' +
"SourceMethodName: " + record.getSourceMethodName() + '\n' +
"ThreadID: " + record.getThreadID() + '\n';
}
} |
The simplest way to try this formatter is to put its name in the logging.properties file. So we replace
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
with
java.util.logging.ConsoleHandler.formatter = hansen.playground.logging.MyFormatter
If we run program Log1 we get this written out to the console:
LogRecord info: Level: SEVERE LoggerName: hansen.playground.logging.Log1 Message: severe message Millis: 1028657842830 Sequence Number: 0 SourceClassName: hansen.playground.logging.LoggerInformation SourceMethodName: tryLevels ThreadID: 10 LogRecord info: Level: WARNING LoggerName: hansen.playground.logging.Log1 Message: warning message Millis: 1028657842830 Sequence Number: 1 SourceClassName: hansen.playground.logging.LoggerInformation SourceMethodName: tryLevels ThreadID: 10 LogRecord info: Level: INFO LoggerName: hansen.playground.logging.Log1 Message: info message Millis: 1028657842830 Sequence Number: 2 SourceClassName: hansen.playground.logging.LoggerInformation SourceMethodName: tryLevels ThreadID: 10 |
If you compare it to the output from the SimpleFormatter:
11-08-2002 19:49:10 hansen.playground.logging.LoggerInformation tryLevels SEVERE: severe message
then you can see that this format contains: a timestamp, SourceClassName, SourceMethodName, Level, and Message. In most cases this format is sufficient.
A very nice feature in the FileHandler is the option to use a set of rotating files. If you define your FileHandler like this:
FileHandler filehandler =
new FileHandler("%h/mylog%g.txt", 100000, 2);
then the file is placed in the "user.home" directory (the "%h"), it can hold 100000 bytes of data, and it'll switch between two files called mylog0.txt and mylog1.txt. The generation numbers comes from the "%g" notation. A small example will illustrate this. We'll write 10 lines to two very small log-files (300 bytes each):
package hansen.playground.logging;
import java.util.*;
import java.util.logging.*;
public class CyclicFiles {
private static Logger logger1 =
Logger.getLogger("hansen.playground.logging.CyclicFiles");
public static void main(String[] args)
throws java.io.IOException {
FileHandler filehandler =
new FileHandler("%h/mylog%g.txt", 300, 2);
logger1.addHandler(filehandler);
filehandler.setFormatter(new SimpleFormatter());
for (int i = 0; i < 10; i++) {
logger1.info("Line " + i);
}
}
} |
When we run this program we'll first of all see 10 lines written to the console (System.err), but in the user.home directory--which is C:\WINDOWS on my Win98 computer--we find two files: mylog0.txt contains this:
11-08-2002 13:07:48 hansen.playground.logging.CyclicFiles main INFO: Line 8 11-08-2002 13:07:48 hansen.playground.logging.CyclicFiles main INFO: Line 9 |
and mylog1.txt this:
11-08-2002 13:07:48 hansen.playground.logging.CyclicFiles main INFO: Line 4 11-08-2002 13:07:48 hansen.playground.logging.CyclicFiles main INFO: Line 5 11-08-2002 13:07:48 hansen.playground.logging.CyclicFiles main INFO: Line 6 11-08-2002 13:07:48 hansen.playground.logging.CyclicFiles main INFO: Line 7 |
A total of 10 messages have been logged. The first 4 were logged to mylog0.txt, which then was full (as defined by the maximum allowable size of 300 bytes). The following 4 were logged to mylog1.txt which then was also full. Then the cyclic logging mechanism started over with the first file (mylog0.txt), which it completely overwrites and thereby only leaves the last 2 messages in the file.
If you have ever tried to empty a log file on a web server without success, because the file was being used by the server, then you'll appreciate this feature.
Instead of logging to a file we can also log to a network address where we for example can have a Swing client listening. To do this we'll use the SocketHandler:
package hansen.playground.logging;
import java.util.logging.*;
public class TrySocket {
public static void main(String argv[])
throws java.io.IOException // just a demo app
{
// Set-up
Logger logger = Logger.getLogger("hansen.socket");
// Send message to ourselves on port 4444
SocketHandler sh = new SocketHandler("127.0.0.1",4444);
sh.setFormatter(new SimpleFormatter());
logger.addHandler(sh);
// Allow all messages
logger.setLevel(Level.ALL);
// Try some logging
logger.severe("Sample severe entry");
logger.warning("Sample warning entry");
logger.info("Sample info entry");
logger.config("Sample config entry");
logger.fine("Sample fine entry");
logger.finer("Sample finer entry");
logger.finest("Sample finest entry");
}
} |
Now we only need someone to listen on port 4444. A small Swing application can do this for us. Click on the link to see the source code. If we run the LogListener Swing program we'll see this window popping up:
When we now run the TrySocket program the LogListener displays the messages:
Since we have set level ALL we receive messages of any priority. The Reset button clears the text area.
A good, basic set-up is to define a logger for every class--"class" loggers--like it was done in Log1 above:
private static Logger logger1 = Logger.getLogger(Log1.class.getName());
This logger will use the root logger's handler as defined in the logging.properties file. By setting the class logger's level in the same file you can control the amount of logging output from every class. A class logger could among other things be used to log every entry and exit from a method. The Logging class has the entering and exiting methods for this purpose.
To these loggers you could add loggers for specific purposes. Some ideas for such loggers in an application could be (most of them probably best implemented as FileHandlers):
These loggers and their set-up should be defined at application start-up time.
If you haven't moved to JDK 1.4 yet, you might be interested in knowing that the API has been ported to JDK 1.2 and 1.3--see the the Lumberjack project.
Many older logging API's--e.g. Log4J--have obtained a lot of popularity, and some of them have more features than the current JDK 1.4 Logging API. It can be therefore be difficult to choose the right API for your application. In favor of using Sun's way of logging is the simple fact that the API is part of the JDK. If you use APIs outside Sun's JDK, you'll have to keep track of the jars and help files that go with the API. On the other hand you shouldn't forget that bugs are often fixed more promptly in open source projects. Bugs in the JDK might have to wait for the next release to be fixed.