better logging than printf – using log4j – part II

However, Just like with computers, cars and women there is always a faster, bigger, or better model on the horizon.

Version 1.2 of log4j has reached its end of life on August 5th 2015 but there is a version 2 to take it place. There is a lot of things to like about the new version of log4j with some of the benefits being.

Improved performance
Support for multiple API’s
Plugin architecture
Java 8 lambda support
Custom log levels

Some of the basics of log4j was explained in part I.

Log4j version 1.2

Using version 1.2 of log4j it is really easy to send our output to either the screen or to a file.

Property file

log4j.rootLogger=INFO, stdout, pgmlogfile

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d; %-5p; (%F:%L); %m%n

log4j.appender.pgmlogfile=org.apache.log4j.FileAppender
log4j.appender.pgmlogfile.file=${LOGDIR}/${LOGFILE}
log4j.appender.pgmlogfile.Append=true
log4j.appender.pgmlogfile.layout=org.apache.log4j.PatternLayout
log4j.appender.pgmlogfile.layout.ConversionPattern=%d %-5p; (%F:%L); %m%n

This log4j property file will display the output to both the console and save it to a log file. In this example the output file is determined at runtime by evaluating the LOGDIR and the LOGFILE environment variables.

The configuration format of log4j2 can still support the old properties file style format, however, the contents of that file would be slightly different for version 2.

Rather than trying to keep these two incompatible configuration files separate it is just as easy to switch over to the xml format that is supported by version 2.0 of log4j2.

Note: XML isn’t really new as it was possible to have xml configuration files with version 1.2 of log4j.

Log4j version 2

Log4j2 will load its configuration from a file, but now it supports so many possible formats there is a specific order that it will go through in an attempt to find the configuration file when one isn’t presented to it. The first place it looks is if the log4j.configurationFile property is set in your virtual machine. When this is defined it will be used regardless how the file is named.

When this property is not defined, then log4j will look for the config file in the classpath. The default configuration file to use will be searched for using the following names in this order.

log4j2-test.properties

log4j2-test.yaml or log4j2-test.yml

log4j2-test.json or log4j2-test.jsn

log4j2-test.xml

log4j2.properties

log4j2.yaml or log4j2.yml

log4j2.json or log4j2.jsn

log4j2.xml

If no configuration file could be located the DefaultConfiguration will be used. This will cause logging output to go to the console. The default configuration is not bad but by default it will only display errors or higher and only to the screen.

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/config">
	<Properties>
		<Property name="LOG_NAME">logfile.log</Property>
		<Property name="LOG_DIR">${sys:LOGDIRECTORY}</Property>
		<Property name="LOG_ARCHIVE">${sys:LOGARCHIVE}</Property>
		<Property name="ROLL_NAME">logfile-%d-%i.log</Property>
		<Property name="FILEPATTERN">%-5p | %d{yyyy-MM-dd HH:mm:ss} | [%t] %C (%F:%L) - %m%n</Property>
		<Property name="PATTERN">%-5p | %C{2} (%F:%L) - %m%n</Property>
	</Properties>
	<Appenders>
		<RollingFile name="ROLLINGFILE" fileName="${LOG_DIR}/${LOG_NAME}" filePattern="${LOG_ARCHIVE}/${ROLL_NAME}" append="true">
		<PatternLayout pattern="${FILEPATTERN}"/>
		<Policies>
			<SizeBasedTriggeringPolicy size="1 KB" />
		</Policies>
		<DefaultRolloverStrategy max="4"/>
	</RollingFile>
	<Console name="STDOUT" target="SYSTEM_OUT">
		<PatternLayout pattern="${PATTERN}"/>
	</Console>
	</Appenders>

	<Loggers>
		<!-- add this line to get debug output for this particular class -->
		<Logger name="de.companyname.utility.Mymath" level="debug"/>

		<Root level="info">
			<AppenderRef ref="STDOUT"/>
			<AppenderRef ref="ROLLINGFILE"/>
		</Root>
	</Loggers>
</Configuration>

This configuration file is similar to the old log4j property file listed above. The output from level info or above will be output to both the screen and saved to a file. The format of the two different types of output can either use the same or a different format. In this case, the log file contains an extra date and time stamp per line.

One other slight difference is that the log file will contain the full package and class name (%C) while the console output will only display a portion (%C{2}) of the package name. When the log file reaches 1 kilobyte, it will be renamed keeping up to four log files. Beyond that the oldest will be deleted. This can obviously be changed to more realistic sizes in the megabytes.

It might not be be obvious at the first glance but there is a neat little trick you can do as part of the rolling appender setup. If we use a different directory as part of the filepattern then we are actually not only renaming the old files but moving them to a different directory when the file size reaches the maximum size.

The only thing not fully explained is the following line.

<!-- add this line to get debug 
output for this particular class -->
<Logger name="de.companyname.utility.Mymath" level="debug"/>

The comment does rather give it away. Adding this line to our log4j2 properties actually will allow us to easily see the debug output for that particular class without turning on debugging for the entire program.

One final difference between the old and new version of log4j is how properties inside of the configuration file are treated. To access the JVM values it is necessary to prefix them with “sys:”.

It is not necessary to define everything as a property as is done in this example. However, doing so does show the contrast between the JVM values and standard properties.

Sample program

Program.java

package de.companyname.utility;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class Program {

	static Logger logfile = LogManager.getLogger(Program.class.getName());
	
	public static void main(String[] args) 
	{
		logfile.info("Program starting at " + "");
		logfile.trace("add a trace to log output");
		
		for (int index = 1; index <= 5; index++)
		{
			try {
				int square = 
de.companyname.utility.Mymath.square(index);
				logfile.info(index + " x " + index + " = " + 
square);
			}
			catch (Exception ex)
			{
				logfile.fatal(" while processing value " + 
index);
				logfile.fatal(ex.getMessage());
			}
		}
		
		logfile.debug("add some additional debug to output");
		logfile.info("Program finishing at " + "");
	}
}

Mymath.java

package de.companyname.utility;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class Mymath {

	/*
	 * will return the square of the value input.
	 * this method will only be for the range of positive numbers.
	 */
	static public int square (int value) throws Exception
	{
		Logger logfile = LogManager.getLogger(Mymath.class.getName());
		
		logfile.debug("entering square");
		logfile.debug("parameter is " + value);
		int retval = 0;
		
		if (value > 0)
			retval = value * value;
		else
		{
			logfile.debug("invalid value of " + value + " given");
		}
		
		logfile.debug("leaving square");
		return retval;
	}
}

runProgram.sh

#!/bin/bash

VMARGS="-DLOGDIRECTORY=log -DLOGARCHIVE=archive -Dlog4j.configurationFile=resources/log4j2.xml -DLOGARCHIVE=archive -DLOGDIRECTORY=log"
CP=lib/log4j-api-2.6.2.jar:lib/log4j-core-2.6.2.jar:.
PGM=de.companyname.utility.Program

mkdir log
mkdir archive

CMD="java -cp $CP $VMARGS $PGM"

echo $CMD
$CMD

Output

With no debugging enabled, the program simply outputs the information messages from the main program.

It is possible to see the debug output from square method in the Mymath class by adding this to the log4j2 xml file.

<Logger name="de.companyname.utility.Mymath" level="debug"/>

…

If the goal was to see either all debug output in the entire program or to reduce the output to only errors and above then simply change the root level (ie. debug or error).

	<Root level="info">
		<AppenderRef ref="STDOUT"/>
		<AppenderRef ref="ROLLINGFILE"/>
	</Root>

All of this is standard log4j2 which is both easy to use and easy to understand. It is also possible to create new log levels and filter using them as well. That will be covered in part III on log4j2.

Apache Log4j2 documentation
logging.apache.org/log4j/2.0/log4j-users-guide.pdf

Note: The example was compiled with java 1.8 and uses log4j-api-2.6.2.jar and log4j-core-2.6.2.jar.

better logging than printf – using log4j – part II

Log4j version 1.2

Property file

Log4j version 2

log4j2.xml

Sample program

Output

…

Apache Log4j2 documentation
logging.apache.org/log4j/2.0/log4j-users-guide.pdf

Recent Posts

Categories

Archives

Meta

Subscribe to RSS Feed

better logging than printf – using log4j – part II

Log4j version 1.2

Property file

Log4j version 2

log4j2.xml

Sample program

Output

…

Apache Log4j2 documentation logging.apache.org/log4j/2.0/log4j-users-guide.pdf

Recent Posts

Categories

Archives

Meta

Tags

Apache Log4j2 documentation
logging.apache.org/log4j/2.0/log4j-users-guide.pdf