Friday, 16 October 2015

Log4j2: Log level inheritance

Each Logger references the appropriate LoggerConfig, which in turn can reference its parent. If you don’t specify logging level to a LoggerConfig, then it gets the logging level from parent Logger Configuration.
log4j2.xml
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="DEBUG">
 <Appenders>
  <Console name="my_console_appender" target="SYSTEM_OUT">
   <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
  </Console>
 </Appenders>
 <Loggers>
  <Root level="info">
   <AppenderRef ref="my_console_appender" />
  </Root>
  <Logger name="x.y.z">
   <AppenderRef ref="my_console_appender" />
  </Logger>
 </Loggers>
</Configuration>


PrintDataUtil.java
package x.y.z;

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

public class PrintDataUtil {
 private static final Logger log = LogManager.getLogger();
 
 public static void printData(){
  log.trace("Trace Message!");
  log.debug("Debug Message!");
  log.info("Info Message!");
  log.warn("Warn Message!");
  log.error("Error Message!");
  log.fatal("Fatal Message!");
 }
}


HelloWorld.java

package log4j_tutorial;

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

import x.y.z.PrintDataUtil;

public class HelloWorld {
 private static final Logger log = LogManager.getLogger();

 public static void printData() {
  log.trace("Trace Message!");
  log.debug("Debug Message!");
  log.info("Info Message!");
  log.warn("Warn Message!");
  log.error("Error Message!");
  log.fatal("Fatal Message!");
 }

 public static void main(String args[]) {
  printData();
  PrintDataUtil.printData();
 }
}


When you ran HelloWorld application, you will get following statements in console.

15:05:36.935 [main] INFO  log4j_tutorial.HelloWorld - Info Message!
15:05:36.936 [main] WARN  log4j_tutorial.HelloWorld - Warn Message!
15:05:36.936 [main] ERROR log4j_tutorial.HelloWorld - Error Message!
15:05:36.936 [main] FATAL log4j_tutorial.HelloWorld - Fatal Message!
15:05:36.937 [main] INFO  x.y.z.PrintDataUtil - Info Message!
15:05:36.937 [main] INFO  x.y.z.PrintDataUtil - Info Message!
15:05:36.937 [main] WARN  x.y.z.PrintDataUtil - Warn Message!
15:05:36.937 [main] WARN  x.y.z.PrintDataUtil - Warn Message!
15:05:36.937 [main] ERROR x.y.z.PrintDataUtil - Error Message!
15:05:36.937 [main] ERROR x.y.z.PrintDataUtil - Error Message!
15:05:36.937 [main] FATAL x.y.z.PrintDataUtil - Fatal Message!
15:05:36.937 [main] FATAL x.y.z.PrintDataUtil - Fatal Message!


Notice the output, the log messages from ‘x.y.z’ repeated twice. This is because the appender associated with logger x.y.z is first used, which writes the first instance to the Console. Next, the parent of x.y.z, which in this case is the root logger, is referenced. The event is then passed to its appender, which is also writes to the Console, resulting in the second instance. This feature is known as additivity. But additivity some times makes you irritate by printing log messages twice to the console/file/or some external system.

Disable Additivity
You can disable additivity feature, by setting the attribute ‘additivity’ to false. Once an event reaches a logger with its additivity set to false, the event will not be passed to any of its parent loggers, regardless of their additivity setting.

<Logger name="x.y.z" additivity="false">
         <AppenderRef ref="my_console_appender" />
</Logger>

Complete log4j2.xml looks like below.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="DEBUG">
 <Appenders>
  <Console name="my_console_appender" target="SYSTEM_OUT">
   <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
  </Console>
 </Appenders>
 <Loggers>
  <Root level="info">
   <AppenderRef ref="my_console_appender" />
  </Root>
  <Logger name="x.y.z" additivity="false">
   <AppenderRef ref="my_console_appender" />
  </Logger>
 </Loggers>
</Configuration>


Re run HelloWorld application, by disabling additivity, you will get following output in console.

15:11:43.472 [main] INFO  log4j_tutorial.HelloWorld - Info Message!
15:11:43.472 [main] WARN  log4j_tutorial.HelloWorld - Warn Message!
15:11:43.472 [main] ERROR log4j_tutorial.HelloWorld - Error Message!
15:11:43.472 [main] FATAL log4j_tutorial.HelloWorld - Fatal Message!
15:11:43.473 [main] INFO  x.y.z.PrintDataUtil - Info Message!
15:11:43.473 [main] WARN  x.y.z.PrintDataUtil - Warn Message!
15:11:43.473 [main] ERROR x.y.z.PrintDataUtil - Error Message!
15:11:43.473 [main] FATAL x.y.z.PrintDataUtil - Fatal Message!


Example 2
Whenever application requests a logger with specific name from the LogManager, LogManager locate the appropriate LoggerContext, next obtain the Logger from it. LoggerConfig objects are created from Logger declarations in the configuration.

If the Logger must be created it will be associated with the LoggerConfig that contains either
a) the same name as the Logger,
b) the name of a parent package,
c) the root LoggerConfig.

For example,
Logger Name
Assigned LoggerConfig
LoggerConfig Level
Level
root
root
DEBUG
DEBUG
x
x
ERROR
ERROR
x.y
x
ERROR
ERROR
x.y.z
x.y.z
WARN
WARN

As shown in above table, the loggers root, x and x.y.z each have a configured LoggerConfig with the same name. The Logger x.y does not have a configured LoggerConfig with a matching name so uses the configuration of LoggerConfig x (x is the parent of x.y), since that is the LoggerConfig whose name has the longest match to the start of the Logger's name.

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="DEBUG" monitorInterval="30">
 <Appenders>
  <Console name="my_console_appender" target="SYSTEM_OUT">
   <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
  </Console>
 </Appenders>
 <Loggers>
  <Root level="debug">
   <AppenderRef ref="my_console_appender" />
  </Root>
  <Logger name="x" level="error" />
  <Logger name="x.y.z" level="warn" />

 </Loggers>
</Configuration>


package x;

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

public class PrintDataUtil1 {
 private static final Logger log = LogManager.getLogger();

 public static void printData() {
  log.trace("Trace Message!");
  log.debug("Debug Message!");
  log.info("Info Message!");
  log.warn("Warn Message!");
  log.error("Error Message!");
  log.fatal("Fatal Message!");
 }
}


package x.y;

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

public class PrintDataUtil2 {
 private static final Logger log = LogManager.getLogger();

 public static void printData() {
  log.trace("Trace Message!");
  log.debug("Debug Message!");
  log.info("Info Message!");
  log.warn("Warn Message!");
  log.error("Error Message!");
  log.fatal("Fatal Message!");
 }
}


package x.y.z;

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

public class PrintDataUtil3 {
 private static final Logger log = LogManager.getLogger();
 
 public static void printData(){
  log.trace("Trace Message!");
  log.debug("Debug Message!");
  log.info("Info Message!");
  log.warn("Warn Message!");
  log.error("Error Message!");
  log.fatal("Fatal Message!");
 }
}


package log4j_tutorial;

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

import x.PrintDataUtil1;
import x.y.PrintDataUtil2;
import x.y.z.PrintDataUtil3;

public class HelloWorld {
 private static final Logger log = LogManager.getLogger();

 public static void printData() {
  log.trace("Trace Message!");
  log.debug("Debug Message!");
  log.info("Info Message!");
  log.warn("Warn Message!");
  log.error("Error Message!");
  log.fatal("Fatal Message!");
 }

 public static void main(String args[]) throws InterruptedException {
  printData();
  PrintDataUtil1.printData();
  PrintDataUtil2.printData();
  PrintDataUtil3.printData();
 }
}


Run HelloWorld application, you will get following output.

16:19:58.450 [main] DEBUG log4j_tutorial.HelloWorld - Debug Message!
16:19:58.451 [main] INFO  log4j_tutorial.HelloWorld - Info Message!
16:19:58.451 [main] WARN  log4j_tutorial.HelloWorld - Warn Message!
16:19:58.451 [main] ERROR log4j_tutorial.HelloWorld - Error Message!
16:19:58.451 [main] FATAL log4j_tutorial.HelloWorld - Fatal Message!
16:19:58.451 [main] ERROR x.PrintDataUtil1 - Error Message!
16:19:58.451 [main] FATAL x.PrintDataUtil1 - Fatal Message!
16:19:58.452 [main] ERROR x.y.PrintDataUtil2 - Error Message!
16:19:58.452 [main] FATAL x.y.PrintDataUtil2 - Fatal Message!
16:19:58.452 [main] WARN  x.y.z.PrintDataUtil3 - Warn Message!
16:19:58.452 [main] ERROR x.y.z.PrintDataUtil3 - Error Message!
16:19:58.452 [main] FATAL x.y.z.PrintDataUtil3 - Fatal Message!


As you observe the output, log level error is assigned to x.y. PrintDataUtil2 class.





Prevoius                                                 Next                                                 Home

No comments:

Post a Comment