Log4j and additivity

When running large applications you definitely will have a big amount of logging related code. With log4j Java developers can extremely simplify the adding of log outputs via creating a static member that gets the logger and simply put something like „logger.info(…)“ into the relevant locations of some methods. That’s where the main work of the application developer ends and some magic overtakes the part of writing those information to some files where they can be picked up by testers and maintainers. Unfortunately those log outputs are not everytime helpful within problem handling as in large applications you will get multiple logs and often different logfiles that have at lease a small subset of duplicated entries. This is because of uncertain handling of log4j appenders.
In this post I try to summarize (even for myself) understanding of connection between appenders, loggers and the magic „additivity“ flag.
The project:
projectoverview
with its pom:

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
	<modelVersion>4.0.0</modelVersion>
	<groupId>eu.christophburmeister.playground</groupId>
	<artifactId>log4j-example</artifactId>
	<version>0.0.1-SNAPSHOT</version>

	<dependencies>
		<dependency>
			<groupId>log4j</groupId>
			<artifactId>log4j</artifactId>
			<version>1.2.17</version>
		</dependency>
	</dependencies>
</project>

As we can see here, this example consists of three stupid classes and a log4j configuration:

package eu.christophburmeister.playground.log4jexample;

import org.apache.log4j.Logger;

import eu.christophburmeister.playground.log4jexample.helpers.Helper;

public class MyApplication {
	
	private static Logger logger = Logger.getLogger(MyApplication.class);
	
	public static void main(String[] args) {
		logger.info("entered main method"); 
		Helper helper = new Helper();
		helper.doSomething();
		logger.info("left main method");
	}

}
package eu.christophburmeister.playground.log4jexample.helpers;

import org.apache.log4j.Logger;

import eu.christophburmeister.playground.log4jexample.helpers.common.CommonHelper;

public class Helper {

	private static Logger logger = Logger.getLogger(Helper.class);
	
	public void doSomething() {
		logger.info("entered doSomething method"); 
		CommonHelper commonHelper = new CommonHelper();
		commonHelper.giveCommonHelp();
		logger.info("left doSomething method");
	}

}
package eu.christophburmeister.playground.log4jexample.helpers.common;

import org.apache.log4j.Logger;

public class CommonHelper {

	private static Logger logger = Logger.getLogger(CommonHelper.class);
	
	public void giveCommonHelp() {
		logger.info("entered giveCommonHelp method");
		try {
			logger.debug("sleeping");
			Thread.sleep(1000);
		} catch (InterruptedException e) {
			// nop, just for presentation
		}
		logger.info("left giveCommonHelp method");
	}

}
# the loggers
# logger0: root logger that uses "appender0" with DEBUG
log4j.rootLogger=DEBUG, appender0
# logger1: package based logger for "eu.christophburmeister.playground.log4jexample" that uses "appender1" with INFO
log4j.logger.eu.christophburmeister.playground.log4jexample = INFO, appender1
# logger2: package based logger for "eu.christophburmeister.playground.log4jexample.helpers" that uses "appender2" with INFO
log4j.logger.eu.christophburmeister.playground.log4jexample.helpers = INFO, appender2
# logger3: package based logger for "eu.christophburmeister.playground.log4jexample.helpers.common" that uses "appender3" with INFO
log4j.logger.eu.christophburmeister.playground.log4jexample.helpers.common = INFO, appender3
 
# the appender:
# appender0: console appender: 
log4j.appender.appender0=org.apache.log4j.ConsoleAppender
log4j.appender.appender0.layout=org.apache.log4j.PatternLayout
log4j.appender.appender0.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

# appender1: file appender: 
log4j.appender.appender1=org.apache.log4j.FileAppender
log4j.appender.appender1.File=logs/file.log
log4j.appender.appender1.layout=org.apache.log4j.PatternLayout
log4j.appender.appender1.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

# appender2: file appender: 
log4j.appender.appender2=org.apache.log4j.FileAppender
log4j.appender.appender2.File=logs/file_helpers.log
log4j.appender.appender2.layout=org.apache.log4j.PatternLayout
log4j.appender.appender2.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

# appender3: file appender: 
log4j.appender.appender3=org.apache.log4j.FileAppender
log4j.appender.appender3.File=logs/file_helpers.common.log
log4j.appender.appender3.layout=org.apache.log4j.PatternLayout
log4j.appender.appender3.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

Basically the MyApplication is calling the Helper and the Helper in turn calls the CommonHelper. This small setup was chosen to demonstrate following log4j’s best practice, naming the loggers after Java package names. As this includes a kind of hierarchy (with ancestors and predecessor), this is often the reason for duplicate log entries (and the reason for this blogposts).
In log4j.properties, 4 loggers are created that can be referenced in code:

  • logger0: log4j.rootLogger
  • logger1: log4j.logger.eu.christophburmeister.playground.log4jexample
  • logger2: log4j.logger.eu.christophburmeister.playground.log4jexample.helpers
  • logger3: log4j.logger.eu.christophburmeister.playground.log4jexample.helpers.common

Where the rootLogger is the basic logger that can be called when there is no other logger relevant. The other three loggers build up a hierarchy by their names: log4j.logger.eu.christophburmeister.playground.log4jexample is ancestor of log4j.logger.eu.christophburmeister.playground.log4jexample.helpers that is in turn ancestor of log4j.logger.eu.christophburmeister.playground.log4jexample.helpers.common. This understanding of ancestors is essential for understanding the problem of duplicate log entries by several loggers.

So when getting the logger in MyApplication via logger = Logger.getLogger(MyApplication.class) it is transformed by Java internally to logger = Logger.getLogger(„eu.christophburmeister.playground.log4jexample.MyApplication“). With that information log4j framework goes to configuration (log4j.properties) and finds matching loggers by name. This is on the one hand in each case the rootlogger (logger0) and on the other hand the logger1 because it matches the package structure:

eu.christophburmeister.playground.log4jexample.MyApplication
eu.christophburmeister.playground.log4jexample

Logger2 and logger3 are omitted because they are not in hierarchy, means not ancestors of the requested logger:
eu.christophburmeister.playground.log4jexample.MyApplication
eu.christophburmeister.playground.log4jexample.helpers
eu.christophburmeister.playground.log4jexample.MyApplication
eu.christophburmeister.playground.log4jexample.helpers.common

So that means, that every log output from MyApplication class goes to logger0 and logger1
(By the way: a non so common way to define loggers is to configure them at class level and not on package level.)

Same is done for Helper and CommonHelper, where Helper is resolved to logger0, logger1 and logger2 and CommonHelper is resolved to logger1, logger2, logger3 and logger4.

class logger0 logger1 logger2 logger3
MyApplication yes yes no no
Helper yes yes yes no
CommonHelper yes yes yes yes

With this table in mind, let’s have a look at the appenders: there is one console appender that simply puts all the stuff to stdout. Additionally there are three file appenders. In logger section of log4j.properties you have to connect logger to at least one existing appender. In this example there is following connection:

  • logger0 (rootlogger) goes to appender0 (console)
  • logger1 (eu.christophburmeister.playground.log4jexample) goes to appender1 (logs/file.log)
  • logger2 (eu.christophburmeister.playground.log4jexample.helpers) goes to appender2 (logs/file_helpers.log)
  • logger3 (eu.christophburmeister.playground.log4jexample.helpers.common) goes to appender3 (logs/file_helpers.common.log)

And if we now connect the table above to our logger-appender configuration, we can guess, what will happen:

class console logs/file.log logs/file_helpers.log logs/file_helpers.common.log
MyApplication yes yes no no
Helper yes yes yes no
CommonHelper yes yes yes yes

That means, everything is logged to console. That’s ok so far. But the file.log that is originally related to the MyApplication class will get input from MyApplication, Helper and CommonHelper. The file_helper.log will get input from Helper and CommonHelper. So there will be much duplicated stuff across those logfiles. In the end, everything that was pushed to file_helpers.log and file_helpers.common.log is also written to the file.log And everything that was pushed to file_helpers.common.log is also part of file_helpers.log. Lets have a look:

02:22:14 INFO  MyApplication:12 - entered main method
02:22:14 INFO  Helper:12 - entered doSomething method
02:22:14 INFO  CommonHelper:10 - entered giveCommonHelp method
02:22:15 INFO  CommonHelper:17 - left giveCommonHelp method
02:22:15 INFO  Helper:15 - left doSomething method
02:22:15 INFO  MyApplication:15 - left main method
02:22:14 INFO  MyApplication:12 - entered main method
02:22:14 INFO  Helper:12 - entered doSomething method
02:22:14 INFO  CommonHelper:10 - entered giveCommonHelp method
02:22:15 INFO  CommonHelper:17 - left giveCommonHelp method
02:22:15 INFO  Helper:15 - left doSomething method
02:22:15 INFO  MyApplication:15 - left main method
02:22:14 INFO  Helper:12 - entered doSomething method
02:22:14 INFO  CommonHelper:10 - entered giveCommonHelp method
02:22:15 INFO  CommonHelper:17 - left giveCommonHelp method
02:22:15 INFO  Helper:15 - left doSomething method
2015-06-13 16:22:14 INFO  CommonHelper:10 - entered giveCommonHelp method
2015-06-13 16:22:15 INFO  CommonHelper:17 - left giveCommonHelp method

This scenario you’ll find in a lot of legacy application where over the years more and more loggers have been added to with no regard to existing log infrastructure. To avoid this there’s a small but valuable flag that can simply be added to a log4j configuration afterwards: additivity. This is set for a logger and the effect is, that a hierarchy lookup is suppressed. Being more precise: The log output is not given to any ancestors of the logger.

In our example from a log call in Helper the output would be logged by logger2, logger1 and logger0 because logger2 is a predecessor of logger1 that is a predeseccor of logger0 (every logger is predecessor of rootlogger!).

After changing the log4j configuration in the following way (note the last lines that are new, everything else is unchanged), logger2 that is used by Helper and logger3 that is used by CommonHelper are exclusively logging their stuff into their own files. To demonstrate missing additivity logger1 still logs into his appender but also forwards the log input to its ancestor logger0. That’s the reason why we still get the log message in stdout:

# the loggers
# logger0: root logger that uses "appender0" with DEBUG
log4j.rootLogger=DEBUG, appender0
# logger1: package based logger for "eu.christophburmeister.playground.log4jexample" that uses "appender1" with INFO
log4j.logger.eu.christophburmeister.playground.log4jexample = INFO, appender1
# logger2: package based logger for "eu.christophburmeister.playground.log4jexample.helpers" that uses "appender2" with INFO
log4j.logger.eu.christophburmeister.playground.log4jexample.helpers = INFO, appender2
# logger3: package based logger for "eu.christophburmeister.playground.log4jexample.helpers.common" that uses "appender3" with INFO
log4j.logger.eu.christophburmeister.playground.log4jexample.helpers.common = INFO, appender3
 
# the appender:
# appender0: console appender: 
log4j.appender.appender0=org.apache.log4j.ConsoleAppender
log4j.appender.appender0.layout=org.apache.log4j.PatternLayout
log4j.appender.appender0.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

# appender1: file appender: 
log4j.appender.appender1=org.apache.log4j.FileAppender
log4j.appender.appender1.File=logs/file.log
log4j.appender.appender1.layout=org.apache.log4j.PatternLayout
log4j.appender.appender1.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

# appender2: file appender: 
log4j.appender.appender2=org.apache.log4j.FileAppender
log4j.appender.appender2.File=logs/file_helpers.log
log4j.appender.appender2.layout=org.apache.log4j.PatternLayout
log4j.appender.appender2.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

# appender3: file appender: 
log4j.appender.appender3=org.apache.log4j.FileAppender
log4j.appender.appender3.File=logs/file_helpers.common.log
log4j.appender.appender3.layout=org.apache.log4j.PatternLayout
log4j.appender.appender3.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

# suppress redundant log entries of helpers
log4j.additivity.eu.christophburmeister.playground.log4jexample.helpers=false
# suppress redundant log entries of helpers.common
log4j.additivity.eu.christophburmeister.playground.log4jexample.helpers.common=false
02:25:36 INFO  MyApplication:12 - entered main method
02:25:37 INFO  MyApplication:15 - left main method
02:25:36 INFO  MyApplication:12 - entered main method
02:25:37 INFO  MyApplication:15 - left main method
02:25:36 INFO  Helper:12 - entered doSomething method
02:25:37 INFO  Helper:15 - left doSomething method
02:25:36 INFO  CommonHelper:10 - entered giveCommonHelp method
02:25:37 INFO  CommonHelper:17 - left giveCommonHelp method