Jamie's Blog

Lessons from a life of startups, coding, countryside, and kids

Java Logging tips and problems

If you use System.out.println-style statements and the default java.util.logging.Logger class, you’ll often find that the printed statements don’t align with the logged output. For example,

Logger.info("Start something...");
System.out.println("Finished it");
can produce,
Finished it
Start something...
which is obvously wrong. This is because the Logger is using System.err and your print statements are using System.out, and hence they’re not synchronised together. It probably occurs most often when unit testing a logged class and using System.out.println() within the unit tests.

There are several ways around this (all fairly obvious, when you realise what the problem is) and they basically boil down to ensuring that the printed and logged statements use the same PrintStream. You could either: make the streams the same, System.setErr(System.out) change the print statements to System.err.println() or even change the appropriate Logger handler which uses System.out instead. The first is probably the easiest way. This situation shouldn’t occur too often in production applications, since any app that makes use of j.u.l probably shouldn’t be using print statements too.

I’m also rather disappointed to hear the Logger.global is being deprecated in future versions of the JDK. I was on the Expert Group for JSR-47 (java.util.logging) and fought for its inclusion. My rationale at the time was that logging should be as easy to accomplish as println()-ing, and certainly others have found it useful in this respect. Unfortunately, I never got to seriously employ the j.u.l API until it was released in Java 1.4 and I’ve now discovered several rather annoying deficiancies
  • Logger.severe() should take a Throwable parameter. Often, a severe problem occurs because of an error so you’ll often have to type logger.log(Level.SEVERE, "Message", exception) when logger.severe("Message", exception) would be much cleaner. I can’t remember if this came up but I imagine it wasn’t included to limit the number of method variations
  • By default, the Console Logger only logs INFO messages and above. This means that calls to logger.setLevel(Level.ALL) have no effect because, although the messages are logged, the handler which is responsible for outputting them to the console doesn’t actually print them. This is hugely frustrating and confusing for just about everyone. The default level for all handlers should have been Level.ALL. StreamHandler also suffers from this problem
  • The default formatting is a space-waster. By default the logging framework using the ConsoleHandler and SimpleFormatter outputs 1 line for the date, time, fully-qualified classname and method name THEN it follows with the logged level and message on a new line. For example,
    28-Sep-2006 16:35:06 com.ideasasylum.collocation.association.ClusterFeatureTree splitLeaf
    INFO: Splitting Leaf 17682935 into 5488661
    In hindsight, my preference would have a more concise format along the lines of
    [INFO  ] c.i.c.a.ClusterFeatureTree splitLeaf: Splitting Leaf 17682935 into 5488661

    Of course, you can write your own formatter (which I’ve done) but a more sensible default would have been better
  • Configuration is too difficult. The configuration of logging should have been simply and easily done from within the application and only make use of a properties file to override programmatic options. At the moment there are just too many things required to configure logging and the properties file format was not the ideal mechanism

Overall, most of my problems with the API aren’t with the API itself but the implementation shipped with Java. Despite the alternative logging APIs, I’ll continue to use j.u.l because it’s shipped with Java (Apache log4j might be nicer for some developers but the build-in j.u.l is better for users).