better logging than printf – using log4j – part I

The old way

Log files or debugging can be done using print statements.  It is a very rudimentary way to see some of your internal variables or to have a log of how the program run went.

This printf sample can turn off the debugging with a single variable.  It is not too difficult to set this value as a parameter to the program but it is really just too much effort for such simple control.  It is a all or nothing that is not so satisfying.

It is however, much better than not having any ability to log or debug the program in question.

public class Program  {

	boolean debug = true;
	public Program()
	{
	}
	public void performWork()
	{
		int index = 0;
		System.out.println("Interface 'Program' starting");

		for (index = 1; index <= 10; index++)
		{
			int square = index * index;
			if (debug == true)
				System.out.println(index + " x " + index + " = " + square);
			System.out.println("square is " + square);
		}
		System.out.println("Interface 'Program' finished");
	}
	public static void main(String args[])
	{
		Program helper = new Program();
		helper.performWork();
	}
}

“Printf” logfile output

This output may have been acceptable back in computer class but it really doesn’t measure up in a production environment.  True, we see the output, both the standard and debug output, however, this output could have been from version 1 of our program six months ago or version 3 yesterday.

Fortunately, better logging and debug output has been solved quite elegantly by the Log4j project at Apache.

The really clever thing about their solution is that all of the logging/debugging is controlled via a tiny configuration file.  Write your program to read in the configuration file and then use the log4j output methods.  Changing the configuration file changes the nature of the log output.

The object is “Logger” has a few methods each of which can be used in lieu of printf.

• debug
• info
• warn
• error
• fatal

Each of these are actually treated as a different level with each all inclusive of all levels before it.  The real beauty is Log4j allows you to filter which level of output you wish to see. Log4j supports date, displays debug level, class file and line number if you really need it.

This alone is more than enough reason to use log4j to help control logging but there is more.  It is possible to route the output to a file, the console or both.

# Root logger option
log4j.rootLogger=debug, terminal

# Redirect log messages 
log4j.appender.terminal=org.apache.log4j.ConsoleAppender
log4j.appender.terminal.Target=System.out
log4j.appender.terminal.layout=org.apache.log4j.PatternLayout
log4j.appender.terminal.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n

The highlighted lines set the output to the screen.  The last two lines allow for some customization how the output looks.   The rootLogger sets what level to filter at.  Simply edit the property file to the level of logging that you wish to see.  The filter is set to “debug” so all logging output (debug,info,warn, error and fatal) will be displayed.

The new way with log4j and property files

The next sample program is virtually no different than the printf version for outputting log details.

In the constructor, in this example, the PropertyConfigurator object is used to load the log4j.properties file from the current directory.  Log4j will be clever enough to do all the setup in the background after reading the property file.

ConfigFileLog4j.java

import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;

public class ConfigFileLog4j {

	Logger logfile = null;
	
	public ConfigFileLog4j()
	{
		// get a handle to "logger"
		PropertyConfigurator.configure("log4j.properties");
		logfile = Logger.getLogger(ConfigFileLog4j.class);
	}
	public void performWork()
	{
		int index = 0;
		logfile.info("Interface 'ConfigFileLog4j' starting");

		for (index = 1; index <= 10; index++)
		{
			int square = index * index;
			logfile.debug(index + " x " + index + " = " + square);
			logfile.info("square is " + square);
		}
		logfile.info("Interface 'ConfigFileLog4j' finished");
	}
	public static void main(String args[])
	{
		ConfigFileLog4j helper = new ConfigFileLog4j();
		helper.performWork();
	}
}

Log4j logfile output

This sample output is done with the filter set to “info” thus giving us the output that we probably want to see from a normal run.

This is probably the easiest way to use log4j.  Simply include the property file with the program, change the property file as necessary during development.

This is good because if an unruly client or IT department needs a different format or wishes to reduce the logging this can be achieved by simply modifying the configuration file not changing and recompiling the program itself.

It is possible to display the output purely to the console when running.

log4j.rootLogger=debug, terminal

# console setup
log4j.appender.terminal=org.apache.log4j.ConsoleAppender
log4j.appender.terminal.Target=System.out
log4j.appender.terminal.layout=org.apache.log4j.PatternLayout
log4j.appender.terminal.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n

However, once the program is fully bug free, you can ignore the console and simply write all output to the log file.

log4j.rootLogger=debug, file

# Redirect log messages to a log file
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.file=${LOGDIR}/${LOGFILE}
log4j.appender.file.MaxFileSize=10mb
log4j.appender.file.MaxBackupIndex=3 
log4j.appender.file.Append=true 
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n

There are actually a couple of nifty things that you can do when writing the output to log files.  The first is that you can decide on the maximum log file size as well as how many old copies of the logs to keep.  Once the logfile reaches this size it automatically moves the current logfile to logfile.1 – if necessary renaming all of the log files to a newer version until all the logs are renamed and then resumes writing the output to the log file.

In the above property file the output is set to Append.  This will simply append future program output to the end of the log file.  This is really handy to easily see the history of a given program at a glance.

In my opinion one of the more interesting things that you can do with log files is you can use values from the java virtual machine, in this case LOGDIR and LOGFILE, to determine some of the functionality.

This may not be necessary in most cases but perhaps for a situation where multiple related program s utilizes a single property file this might come in handy.

It is even possible to have a single log4j property file that is designed to output to both the screen and save to the log file.

log4j.rootLogger=debug, file, terminal

# console setup
log4j.appender.terminal=org.apache.log4j.ConsoleAppender
log4j.appender.terminal.Target=System.out
log4j.appender.terminal.layout=org.apache.log4j.PatternLayout
log4j.appender.terminal.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n

# file setup
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.file=${LOGDIR}/${LOGFILE}
log4j.appender.file.MaxFileSize=10mb
log4j.appender.file.MaxBackupIndex=3 
log4j.appender.file.Append=true 
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n

runProgram.sh

#!/bin/bash

CP=lib/log4j-1.2.17.jar:.
PGM=ConfigFileLog4j

mkdir log

CMD="java -DLOGFILE=custom.log -DLOGDIR=log -cp $CP $PGM"

echo $CMD
$CMD

Unfortunately this shouldn’t really be called the new way of doing things.  Just recently, in 2013, a newer better version of Log4j came out.  This will be the subject of part II of this article.

Note: This example was compiled with java 1.7 and uses log4j-1.2.17.jar

Note: This example was also compiled with java 1.8 and uses log4j-1.2.17.jar