Loggerheadache

I decide to play around with the Java logging facility. I write a simple test program:

import java.util.logging.*;

public class LoggingTest {
    public static void main(String[] args) {
	Logger log = Logger.getLogger("com.stuartsierra");
	log.entering("LoggingTest", "main");
	log.info("Info Message");
	log.warning("Warning Message");
	log.exiting("LoggingTest", "main");
    }
}

Compile, run, and I get this:

Aug 30, 2006 10:48:45 AM LoggingTest main
INFO: Info Message
Aug 30, 2006 10:48:45 AM LoggingTest main
WARNING: Warning Message

Hmm. Not quite what I expected. Two out of my four log messages don’t appear. Back to the API docs. Ah, yes, I need to set the logging level if I want to get finer-grained messages like “entering” and “exiting.” So I add the line,

log.setLevel(Level.FINEST);

just after getLogger(), compile, and run again. Same exact result — the “entering” and “exiting” messages don’t appear. I look at the API docs again. Nothing strikes me. The Java (TM) Logging Overview doesn’t enlighten me either. I try Level.ALL, just to make sure. Nope, Java doesn’t want to print those messages.

Now if I were on a deadline, I would say screw it and go do some real work. But I want to understand why this doesn’t work. After three or four web searches I find An Introduction to the Java Logging API. As it turns out, I need to set the level not just of my Logger, but also of each of the Handlers receiving messages from it. The article suggests this code:

Handler[] handlers =
   Logger.getLogger( "" ).getHandlers();
for ( int index = 0; index < handlers.length; index++ ) {
   handlers[index].setLevel( Level.FINE );
}

I insert that into my test code, and lo and behold, it works:

Aug 31, 2006 11:05:53 AM LoggingTest main
FINER: ENTRY
Aug 31, 2006 11:05:53 AM LoggingTest main
INFO: Info Message
Aug 31, 2006 11:05:53 AM LoggingTest main
WARNING: Warning Message
Aug 31, 2006 11:05:53 AM LoggingTest main
FINER: RETURN

So what's the lesson of all this? It's easy just to say "Java's logging API is weird." But I'm sure those Handlers are in there for a reason. I can imagine wanting to send the same stream of log messages to a file and a window at the same time. I can even imagine wanting to send different levels of log detail to different outputs. I do think it is a mistake to have the level-setting code duplicated in both Logger and Handler, as it means more work for me, the client programmer who gets frustrated when his code doesn't do what he expects it to. At the least, the API documentation for Logger.setLevel() should mention that you need to set the level on all the Handlers too.

More generally, I think this is an example of how a library can be too customizable. Picture the feature list: "Custom logging levels per-logger and per-output." Sounds great, until you have to remember to set them both to the same value to get what you want.