IB's Java World: Log4J configuration – controlling logging to multiple loggers

Tuesday, March 10, 2009

Log4J configuration – controlling logging to multiple loggers

I recently happened to read a blog about Apache Lo44J java logging API where the blogger mentioned that there is no clean good document/tutorial about using log4j, considering the fact that it is one of the most widely used open source java API. I felt that it is true to some extent, when I had to look for some help regarding a logging issue I encountered. Especially, I could not find one authentic manual/tutorial explaining the log4j configuration.

My requirement was to control the logging of messages to multiple appenders (targets) with different log priority. For example, I wanted to a log message to write log only to file if priority is debug but wanted to write to both console and log file if priority is set to info or above. With the help of some blogs and log4j javadocs, I found ways to do this. In this blog, I am explaining what I understood, assuming that it might help others looking for this info.

I used XML configuration for configuring log4j in my project, so I will use same in this article. I assume that you (reader of this blog) have basic understanding of Log4J configuration, if not please read this short manual at apache. I expect you to understand Log4J terms like Logger, Log Level and the XML tags like <category>, <appender>, <layout> etc., those appear in log4j configuration.

Note: wherever I mention “logger” (starting with lower case l), I referelement <category> in log4j configuration xml. I mean <root> wherever I mention root logger and tag <appender> wherever I mention “appender”.

As I mentioned above, my requirement was to log messages to multiple appenders (targets), console and a file, But I wanted to all messages (any level – level DEBUG or above) logged to file and only messages with log level ERROR or higher to the console. Following is my log4j.xml

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

</layout>

</appender>

</layout>

</appender>

<appender-ref ref="FILE"/>

</category>

<root>

<appender-ref ref="CONSOLE"/>

</root>

</log4j:configuration>

A simple class I used to test this:

package com.ibswings.loggertest;

import org.apache.log4j.Logger;

public class Test {

public static void main(String[] args) {

new Test();

}

public Test() {

Logger logger = Logger.getLogger(getClass());

logger.debug("Debug Message");

logger.info("Info Message");

logger.error("Error Message");

}

I was expecting this to print all three messages from code to be printed to the log TestLogFile.log and only error message to be printed to console, since I have set ‘error’ priority in <root>. However I noticed that all messages are printed to both log file and console like:

2009-03-07 19:32:00,893 DEBUG Test.java:14 - Debug Message

2009-03-07 19:32:00,893 INFO Test.java:15 - Info Message

2009-03-07 19:32:00,893 ERROR Test.java:16 - Error Message

Let’s look into this in detail. By default, when a message is logged, the message will go to the first logger () whose names closely matches the name of the Logger instance you created in Java code. From there, it is directed to the next matching logger up in the logger hierarchy until root logger. In each of these loggers, output is sent to all appenders indentified by definitions. In the above example, I had created logger in my code like:

Logger logger = Logger.getLogger(getClass());

Actually, this is equivalent of

Logger logger = Logger.getLogger(“com.ibswings.loggertest.Test”);

When following line is executed,

logger.debug("Debug Message");

The closest matching logger defined in config is <category name="com.ibswings". This logs output to TestLogFile.log through appender named “FILE” (Note that if I had a logger defined in log4j.xml with name "com.ibswings.loggertest", that would have been the first logger to get the message). Message directed to root logger from here, since there is no other logger matching the name in between. And, message is printed out to standard out by CONSOLE appender. Also, when message is logged by root, it is logged with priority of message it received it from previous logger. Hence all messages are printed to console in this case, even though we have set error priority in root. The priority set in root has two uses – first, it is the default priority of all other loggers without priorities set. Second, all messages which are only received by root logger (i.e. messages with no matching loggers in log4j.xml) will have this default priority enabled. In following section, let’s see how we can avoid duplicating messages in both log file and console.

How to log only my messages to log file and others to console?

As I mentioned above, output from each logger is directed to next logger above in the logger hierarchy, till root logger. To set behavior off, we need use “addictivity” attribute in . If addictivity is set to “false” in a particular logger, output will not be sent to next logger up in the hierarchy. Or, output is sent from logger to logger, until it reaches a logger (of course, before root) in which addictivity is set to false. By default (when not specified) addivity is set to true. That’s how in the previous case messages are printed to both file and console. Let’s use this in out log4j.xml to stop messages from printing in console.

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

</layout>

</appender>

</layout>

</appender>

<appender-ref ref="FILE"/>

</category>

<root>

<appender-ref ref="CONSOLE"/>

</root>

</log4j:configuration>

With this log4j.xml, all messages from the code are logged to file only. Since we set additivity="false" in the first logger, output is not directed to root logger. In this case, other Logger instances with name not matching “com.ibswings” and any System.out.printxx() calls go to console. In the following section, let’s see how to send all messages from our java code to file and some selected messages (based on priority) to console.

How to log all my messages to log file and selected (based on priority) my messages to console?

Coming to my original requirement, I want to send all my messages (printed from my java code) to log file. Also, I want to send all error messages from my code to console also. At the same time, I want to see all other messages (from other Logger instances and SOP calls) in console.

To achieve this, let’s assume we add appender-ref to console in our first logger. Now question is how to send only error messages, since whatever priority we set to in logger is applicable to all appenders. The solution is to use “Threshold” parameter in appender definition. If we specify a particular priority in appender using threshold, only messages with priority equal of higher to priority specified in ‘threshold’ are printed to the target. However, in this case, we cannot set ‘threshold’ to error in CONSOLE appender, since we need to print all messages (any level) not covered by our logger to console, in root logger. Let’s create a new appender CONSOLE_1 to log messages to console. The configuration is given below.

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

</layout>

</appender>

</layout>

</appender>

</layout>

</appender>

<appender-ref ref="FILE"/>

<appender-ref ref="CONSOLE_1"/>

</category>

<root>

<appender-ref ref="CONSOLE"/>

</root>

</log4j:configuration>

When I ran my test, I see all message logged to file and error message printed in console. Also, all other messages with any level and SOPs printed to console, since we have appender CONSOLE referenced in root logger. In following section, let’s see how to all my messages and all other error messages, only to log file. Following is the log4j.xml we can use to achieve this.

How to log all my messages and all other error messages, only to log file?

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

</layout>

</appender>

</layout>

</appender>

<appender-ref ref="FILE"/>

</category>

<root>

<appender-ref ref="FILE"/>

<!--

<appender-ref ref="CONSOLE"/>

-->

</root>

</log4j:configuration>

Note that I have commented appender-ref CONSOLE in root logger. With this log4j.xml, all messages logged from my java code are printed to log file. At the same time any other message with priority error is also printed to log file. All these will be logged only to the log file, not to console. However, we will still see SOPs in the logger (if we use this in an Application server, we will see lot of such messages in console/standard out or error log files).