An introduction to the Logging framework (a.k.a. System.out.println is evil)

Motivation

One of the first lines a programmer will write in a new language is surely “Hello World”. In Java you can write to the console or to the error stream quite easy with a simple System.out.println("Hello World") or System.err.println("Hello Error"). Great! When the code grows, bugs creep into the code and make live a bit harder. At this point programmers should definately start a deep and loving relationship with the debugger that is delivered with the IDE instead of using System.out/err.println() as debug method. Nevertheless – there are at cases, where a Debugger cannot (or hardly) be applied:

1. The code runs in the IDE but not if startet directly. – What the hell’s going wrong?
2. Handling of exceptions. An exception indicates a state that should not have happened and therefore it might be considered to be logged.
3. The code is deployed to someone else and you cannot attach the debugger to his/her machine.

At either point, beginners tend to use System.out/err.println() to trace the execution path. While this might be okay if the onlyone that is using the code is the programmer alone, this can be very annoying if you are working in a team: If you forget to remove the debug messages, you’re polluting someone elses console output. Even worse: if the code is deployed to a client which reports an error, you cannot raise/lower debug levels or just enable/disable debugging. Do you really want to send a “debug version”? (No you wouldn’t.)

At this point a lot of people start introducing a logging variable and write their own loggin framework because it seems easier to write  if(DEBUG.flag) { System.out.println("step1"); } than to introduce oneself with a logging framework. And of course it’s also cooler to write an own framework than to get used with a foreign API. But beware that you start reinventing the wheel at this point and follow the NIH-syndrome! You’re starting to waste time that could be better invested in your code.

When I was reviewing my students’ code I often came across such debug statements and asked them why they wouldn’t use a standard logging framework. The answers: “Too complicated, isn’t it?”, “What is Logging?”, “I’ll comment it out later!”, “Isn’t a logging framework overkill?”. Well – and as I’ve heard (and seen) that stuff ways too often, I want to give a brief introduction to java util.logging. There are plenty of logging frameworks out there and java.util.logging might not be the one fitting ALL needs – but it’s simple and it is already included in each JRE. So it’s okay for just getting started.

A simple logging example

For a simple example, you need just 3 things: A logging configuration, a Logger and well the logging itself.

Config:

Logging can be configured globally, in the console or locally via a properties file. To keep things simple I’ll just show the properties file solution.
Just place a logging.properties file in the src/ folder of your project with the following content:

# Define the logging handlers
handlers= java.util.logging.ConsoleHandler

# Default global logging level.
.level = FINE

# configure the console handler
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.ConsoleHandler.level = FINEST

# now configure the loglevel on package/class level
a.level = SEVERE
a.AA.level = WARNING
b.level = FINEST

That’s not really complicated, is it?

Loading config

Okay, the properties file is created and filled. Now let the program make use of it. I usually prefer to do that in the first lines of my main method:

InputStream is = Main.class.getClass().getResourceAsStream("/logging.properties");
LogManager.getLogManager().readConfiguration(is);

And that’s it! The logger is now configured.

Logging

Whenever I come across a logging statement in a class I add a logger-field to the class. In case of A.class, this will look like this:

private transient static final Logger log = Logger.getLogger(A.class.getName());

Of course you could also use an anonymous logger but by calling getLogger(A.class.getName()) you can define the log level on a package AND class level (as seen above) in the properties file. If you want to debug just a single class, you can simply set the default level to OFF and thus suppress all output and override the level for just this single class.

Logging itself is the pretty easy:
log.info("this is an info statement");

If this statement is called in the method A#foo(), the output is formated in the following way:
Jan 27, 2012 12:21:25 PM A foo
Information: this is an info statement

And that’s it!

Formatting output

Okay, you possibly don’t like (or want) the 2line statements fo the logging stuff, right? Not a problem! Just extend/override/copy SimpleFormatter do fit your needs and replace the line
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
in the properties file with your implementation:
java.util.logging.ConsoleHandler.formatter = myFormatter.OneLineFormatter

Conclusion

As you see, using the logging framework is really(!) easy. And redirecting logging to files and/or console, formatting the output and class-/package cotrol of loglevel is REALLY just a subset of features that are provided by a logging framework. I don’t wat to cover all that right in this post as this should just motivate to switch from system.*.println to logging.

So – do you REALLY want to reinvent the wheel or get back to your code and write great programs? 😉

Links

• A little demo project including the properties file with some more documentation and some demo classes.
• java.util.logging
• Log Level, Logger,  Formatter
• Another Logging tutorial