Java Logging Made Easy

Not long ago I joined a friend of mine for lunch to discuss what we were both doing in our new jobs. My friend had recently started a job with a local IT training company teaching several topics including a few Java courses.

"So what kind of logging are you using?" I asked. After all, you need some kind of output to do quick and easy debugging. The debugger is nice but is sometimes more cumbersome than it is worth.

"We are just printing to standard out."

I quickly inquired why they couldn't use a standard logging utility like Log4J or the built in java.util.logging. I have always been a stickler for teaching students how to do things right the first time. So why teach them to log using System.out when that is the last thing you do in a real world application? To my friend it was a matter of time. They just didn't have the time to teach the students how to do proper logging and cover all the other topics in the class.

But I had a solution - a simple approach to logging that would be easy for novices to learn and would be easy to convert to more sophisticated logging in the future.

What I suggested was to use a logging wrapper. Have the students start out by creating a XYZAppLogger class that all their code calls when they need to log. Then have the XYZAppLogger dump everything to System.out or System.err.

What are the advantages of doing this?

• The XYZAppLogger, as you will see below, is a very simple class so it helps new students get started by teaching them to type in, compile and run a program. This is a trivial task for experienced Java programmers and a nice intro for beginners.
• By having all their code call XYZAppLogger, when a student is ready to start using a sophisticated logging utility, they only change one file - the XYZAppLogger.
• If a student decides they don't like the logging utility they choose, they can easily switch to something else. I had a programmer tell me once that they thought it was a waste of time to use a logging wrapper. "Just call the logging utility directly. You will never change your logging." Two months later I sat at my computer converting all my code from java.util.logging to Log4J. I knew better - so why did I listen to that other programmer? I use a logging wrapper for all my logging now, just in case. (Note, since about 2008 we have started using SLF4J which is a common logger wrapper and have it delegate to Log4J.)
• Turning logging off throughout the whole application is easy - you just comment out the System.out.println and System.err.println statements in the XYZAppLogger
• With a simple if/else in the XYZAppLogger you can turn logging on or off for certain classes. We will leave this one as an exercise for the instructor - yes we are giving you an exercise!
• You teach students that the logging is worth keeping in your application. Without this logging mechanism, students add the System.out, do their debugging, delete it (or comment it out), and then have to re-add (uncomment) it later if they need to do further debugging. Good God man! Don't delete it - that logging is valuable!

Below is a detailed approach I would recommend using to teach logging to a class learning Java, whether they are new to the language or experienced developers. It starts out simple with the intention of setting up a foundation for good logging without taking much classroom time.

After showing how to set up basic logging, I show you how to convert it into Log4J. This includes not only how to replace the System.out and System.err but also how to load your logging settings dynamically from your own custom properties files.

---

Logging for the Classroom

The essence of logging in your applications is that you want to give the programmer the power to send messages to the user when the user wants to see them. In order to give the user the power to dictate what messages they do and do not want to see, the experts have come up with concept of the logging level.

In Log4J, one of the most common logging utilities for Java, there are 6 logging levels:

• Fatal
• Error
• Warn
• Info
• Debug
• Trace

If you count ALL and OFF you get 8, but 6 is more than enough for beginners, maybe even too much. The order is important. If I turn Info logging on, I automatically turn on Warn, Error and Fatal. Anything at or above the setting I choose is on and anything below is off.

When I train programmers how to log, I first explain the 6 levels. When they ask, as the inevitably do, "How do I know which one to use?" I simply say, it's up to you, use your best judgment. The names of the logging levels are fairly self-explanatory. Beyond that, experience is going to be the best teacher. If they really want to know, I suggest digging through some of those open source projects like you find at apache.org.

OK, we spent one minute of the class, let's move forward, get the logging discussion done so we can cover the topics the students paid us to teach them.

The next level of control for the user over what is and is not logged revolves on what part of the program is generating the output. Since Java is loaded with lots of small class files (we won't debate whether that is a good or bad thing here), the class is a great way to control logging. Log4J also allows package level control but let's not burden the students with that for now.

So what does our XYZAppLogger look like? First it will need a method for each logging level:

• public void fatal(String message)
• public void error(String message)
• public void warn(String message)
• public void info(String message)
• public void debug(String message)
• public void trace(String message)

Then I throw in a few more so we can print out the stack trace of our errors:

• public void fatal(String message, Throwable t)
• public void error(String message, Throwable t)
• public void warn(String message, Throwable t)

Second we need a way to identify what class the logger is logging message for:

• public static XYZAppLogger getLogger(Class c)

We put all this together and get this:

public class XYZAppLogger {
	private String name;
	
	private XYZAppLogger(String name) {
		this.name = name;
	}
	
	public static XYZAppLogger getLogger(Class c) {
		return new XYZAppLogger(c.getName());
	}
	
	public void fatal(String message) {
		System.err.println(name + ": " + message);
		System.err.flush();
	}
	
	public void fatal(String message, Throwable t) {
		System.err.println(name + ": " + message);
		t.printStackTrace();
		System.err.flush();
	}
	
	public void error(String message) {
		System.err.println(name + ": " + message);
		System.err.flush();
	}
	
	public void error(String message, Throwable t) {
		System.err.println(name + ": " + message);
		t.printStackTrace();
		System.err.flush();
	}
	
	public void warn(String message) {
		System.err.println(name + ": " + message);
		System.err.flush();
	}
	
	public void warn(String message, Throwable t) {
		System.err.println(name + ": " + message);
		t.printStackTrace();
		System.err.flush();
	}
	
	public void info(String message) {
		System.out.println(name + ": " + message);
		System.out.flush();
	}
	
	public void debug(String message) {
		System.out.println(name + ": " + message);
		System.out.flush();
	}
	
	public void trace(String message) {
		System.out.println(name + ": " + message);
		System.out.flush();
	}
	
	public static void main(String[] args) {
		XYZAppLogger logger = XYZAppLogger.getLogger(XYZAppLogger.class);
		logger.fatal("Test fatal");
		logger.error("Test error");
		logger.warn("Test warn");
		logger.info("Test info");
		logger.debug("Test debug");
		logger.trace("Test trace");
	}
}

If you think this is too much for your students, no problem. Start with just the error(String message, Throwable t) and debug(String message) methods. They can add the others later. You can also omit the flush() if all the methods use only System.out (or only System.err) but if you mix System.out and System.err, your logging may look odd because System.out and System.err tend to flush their output asyncronously causing your messages to be mixed together and hard to read.

Now your students can build, compile, run and test their new logging utility. And they see an example of how to use the logging in the main method.

Excellent!

---

Switching to Log4J

When converting your logging over to Log4J, all you really need to do is replace the System.err and System.out statements, right? Well, almost. We will want to add a caching mechanism so we create fewer XYZAppLogger objects. We will also add methods to ask the logger if logging for that level is enabled or not.

First lets get the Log4J logger added. To do that we replace

private String name;

with

private Logger logger = null;

Oh, yea, what am I thinking! You should download the Log4J library from http://logging.apache.org/log4j/docs/download.html. Whew, can't forget that. Now where was I...

The constructor becomes

private XYZAppLogger(Class c) {
	this.logger = Logger.getLogger(c);
}

Now get rid of the ".getName()" from the getLogger method. With that we also need to replace all the System.out and System.err statements.

Next we want to add caching. We want to make sure that if the same class is passed into getLogger that the same XYZAppLogger is returned and that we do NOT create another XYZAppLogger. I added private static final Map loggers = new HashMap(); and modified the getLogger method (see below) to get good synchronized management of the loggers.

Now sprinkle in some isFatalLoggable(), isErrorLoggable(), etc methods (again,see below).

And one last thing... you need to set the Log4J settings. In the next section I show you how to load the properties from an external file.

The result...

import java.util.HashMap;
import java.util.Map;
import java.util.Properties;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;

public class XYZAppLogger {
	private Logger logger = null;
	
	private static final Map loggers = new HashMap();
	
	private XYZAppLogger(Class c) {
		this.logger = Logger.getLogger(c);
	}
	
	public static XYZAppLogger getLogger(Class c) {
		String className = c.getName();
		XYZAppLogger logger = (XYZAppLogger) loggers.get(className);
		if (logger == null) {
			synchronized (XYZAppLogger.class) {
				logger = (XYZAppLogger) loggers.get(className);
				if (logger == null) {
					logger = new XYZAppLogger(c);
					loggers.put(className, logger);
				}
			}
		}
		return logger;
	}
	
	public boolean isFatalLoggable() {
		return logger.isEnabledFor(Level.FATAL);
	}
	
	public boolean isErrorLoggable() {
		return logger.isEnabledFor(Level.ERROR);
	}
	
	public boolean isWarnLoggable() {
		return logger.isEnabledFor(Level.WARN);
	}
	
	public boolean isInfoLoggable() {
		return logger.isEnabledFor(Level.INFO);
	}
	
	public boolean isDebugLoggable() {
		return logger.isEnabledFor(Level.DEBUG);
	}
	
	public void fatal(String message) {
		logger.fatal(message);
	}
	
	public void fatal(String message, Throwable t) {
		logger.fatal(message, t);
	}
	
	public void error(String message) {
		logger.error(message);
	}
	
	public void error(String message, Throwable t) {
		logger.error(message, t);
	}
	
	public void warn(String message) {
		logger.warn(message);
	}
	
	public void warn(String message, Throwable t) {
		logger.warn(message, t);
	}
	
	public void info(String message) {
		logger.info(message);
	}
	
	public void debug(String message) {
		logger.debug(message);
	}
	
	private static void setUpLogger() {
		Properties properties = new Properties();
		properties.put("log4j.rootLogger", "INFO, Console");
		properties.put("log4j.appender.Console", "org.apache.log4j.ConsoleAppender");
		properties.put("log4j.appender.Console.layout", "org.apache.log4j.PatternLayout");
		properties.put("log4j.appender.Console.layout.ConversionPattern", "%-4r [%t] %-5p %c %x - %m%n");
		PropertyConfigurator.configure(properties);
	}
	
	public static void main(String[] args) {
		setUpLogger();
		XYZAppLogger logger = XYZAppLogger.getLogger(XYZAppLogger.class);
		Exception testException = new RuntimeException("This is a test exception");
		logger.fatal("Test fatal");
		logger.fatal("Test fatal", testException);
		logger.error("Test error");
		logger.error("Test error", testException);
		logger.warn("Test warn");
		logger.warn("Test warn", testException);
		logger.info("Test info");
		logger.debug("Test debug");
	}
}

---

Loading Log4J Configuration Files

Next I am going to show you how to load your logging configuration from an external file. We will call this file LogConfig.properties.

OK, I know what some people who are familiar with Log4J are going to say: you are supposed to call the file log4j.properties and put it in the classpath so it is loaded on startup. Well, you can do that, but I run multiple web sites that each have their own log settings. Each needs to load the settings into its own classloader separate from the others. I can't put the logging into a global logging file - it would be unmanageable. And what if you are on a shared server and have no control over the main log4j.properties file?

*steps off soap box*

(Note that since the writing of this article we have switched to using the log4j.properties file and no longer use a custom named configuration file.)

Put this LogConfig.properties file into your classpath. For web apps, that would be the WEB-INF/classes directory. Here is what the contents of the file looks like:

log4j.rootLogger=INFO, Console
log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.layout=org.apache.log4j.PatternLayout
log4j.appender.Console.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n

Finally change the setUpLogger method to read this properties file:

import java.io.IOException;
import java.util.HashMap;
import java.util.Map;
import java.util.Properties;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;

public class XYZAppLogger {
	private Logger logger = null;
	private static final Map loggers = new HashMap();
	
	private XYZAppLogger(Class c) {
		this.logger = Logger.getLogger(c);
	}
	
	public static XYZAppLogger getLogger(Class c) {
		String className = c.getName();
		XYZAppLogger logger = (XYZAppLogger) loggers.get(className);
		if (logger == null) {
			synchronized (XYZAppLogger.class) {
				logger = (XYZAppLogger) loggers.get(className);
				if (logger == null) {
					logger = new XYZAppLogger(c);
					loggers.put(className, logger);
				}
			}
		}
		return logger;
	}
	
	public boolean isFatalLoggable() {
		return logger.isEnabledFor(Level.FATAL);
	}
	
	public boolean isErrorLoggable() {
		return logger.isEnabledFor(Level.ERROR);
	}
	
	public boolean isWarnLoggable() {
		return logger.isEnabledFor(Level.WARN);
	}
	
	public boolean isInfoLoggable() {
		return logger.isEnabledFor(Level.INFO);
	}
	
	public boolean isDebugLoggable() {
		return logger.isEnabledFor(Level.DEBUG);
	}
	
	public void fatal(String message) {
		logger.fatal(message);
	}
	
	public void fatal(String message, Throwable t) {
		logger.fatal(message, t);
	}
	
	public void error(String message) {
		logger.error(message);
	}
	
	public void error(String message, Throwable t) {
		logger.error(message, t);
	}
	
	public void warn(String message) {
		logger.warn(message);
	}
	
	public void warn(String message, Throwable t) {
		logger.warn(message, t);
	}
	
	public void info(String message) {
		logger.info(message);
	}
	
	public void debug(String message) {
		logger.debug(message);
	}
	
	private static void setUpLogger() throws IOException {
		String path = "LogConfig.properties";
		Properties properties = new Properties();
		properties.load(XYZAppLogger.class.getClassLoader().getResourceAsStream(path));
		synchronized (XYZAppLogger.class) {
			PropertyConfigurator.configure(properties);
			loggers.clear();
		}
		XYZAppLogger logger = XYZAppLogger.getLogger(XYZAppLogger.class);
		logger.info("Properties loaded: " + path);
	}
	
	public static void main(String[] args) throws Exception {
		setUpLogger();
		XYZAppLogger logger = XYZAppLogger.getLogger(XYZAppLogger.class);
		Exception testException = new RuntimeException("This is a test exception");
		logger.fatal("Test fatal");
		logger.fatal("Test fatal", testException);
		logger.error("Test error");
		logger.error("Test error", testException);
		logger.warn("Test warn");
		logger.warn("Test warn", testException);
		logger.info("Test info");
		logger.debug("Test debug");
	}
}

This is evolving quite nicely...

So why Log4J when Sun has recently added java.util.logging to the core JDK? Why should you use Log4J when that requires downloading and configuring additional libraries?

First of all, a lot of open source products use Log4J so it is good to understand how it works and how to configure it. That also means there are a lot of discussions and resources out there that help you learn the best way to use it.

Secondly, I have found the java.util.logging to be less than perfect.

For example, the following code will be a problem if this class is loaded by the classloader before the logging configuration is read from your logging configuration file:

package com.mysite.test;
import XYZAppLogger;

public class MyClass {
	private static XYZAppLogger logger = XYZAppLogger.getLogger(MyClass.class);
}

Log4J handles this well. However, java.util.logging falls short. If I configure Log4J to set the com.mysite log level (a setting for everything under the com.mysite package) the MyClass logger is updated properly. But java.util.logging will NOT alter the log level for MyClass's logger because the logger has already been initialized.

The problem with java.util.logging is that, when you ask for MyClass's logger,java.util.logging creates a log configuration search chain that searches up the package and puts that search chain into the newly created logger. It will first check com.mysite.test.MyClass, then com.mysite.test, then com.mysite, then com and finally the root log settings. The first log settings it finds it uses. The problem is, in order to use less memory, if there is no log configuration for com.mysite when the logger is obtained (before the logging properties are loaded) the com.mysite is not included in the search chain. So when the log configuration is loaded, your logger has already been created and it is missing the com.mysite check point so those settings are skipped. Let me tell you, it took days of digging through source code to get to the bottom of this bug. Of course I found this in JDK 1.4 and never checked it in JDK 1.5. It may be fixed, if you try it out, I would love to know.

All in all, I hope you spread the word about logging. I believe, no matter what level a programmer is at, there is no excuse for using System.out or System.err for their logging. Frankly, unless you are writing a console application, I would recommend acting like System.out and System.err don't even exist.