Holocron: Log4J2 Architecture, Configuration

Log4J2 Architecture

Extended diagram of architecture accord to the description and source code.

reference https://logging.apache.org/log4j/2.x/index.html

The original diagram that is on the official web page is

Why Log4j2

Alternatives: SLF4J, LogBack

Why Log4j2

1.- Log4J1 and Logback loss events while reconfigurating. Log4j2 Don’t.

Appenders can be configurated to allow exception

2.- Next generation Asyncronous Loggers based on LMAX Disruptor Library. Multi-threaded scenarios Asynchronous Logger have 10 times higher throughput, low latency.

3.- Log4j2 is garbage free.

4.- Plugin system for easy extend the framework by adding new Appenders, Filters, Layouts, Lookups.

6.- Support custom log levels.

7.- Support Lambd Expressions.

8.- Support Message object, for passing it though logging system. Message Types can be custom also the Layouts, Filters, Lookups to manipulate them.

9.- Support Filters can be configurated to process events before they are handled by a Logger. Or Appender.

10.- Appenders accept a Layout, allowing the data to be transported in any format desired.

11.- Layout always return a byte array, can by used on any Appender, not only those of OutputStream

12.- Syslog appender supports TCP, UDP

Architecture description

The diagram UML is self explanatory, following the relations and the cardinality.
Consider that exists also a AsyncAppender.

Configuration Example

The posibilities of configurations are so many, on diferent file formats like XML, JSON, YAML, properties. To Start in a Simple maner is described on next picture the flow control of logEvent generated on the Application.

The program to be used for test log4j2
Main App for Test

public class Scheduler {
    final static Logger logger = LogManager.getLogger();

    //final static Logger logger = LogManager.getLogger( Scheduler.class);   // same
    public static void main(String... args) {
        LoggerContext loggerContext = LoggerContext.getContext();

        System.out.println( String.format("logger.getName(), getLevel() = %s, %s", logger.getName(), logger.getLevel()));    //com.bext.Scheduler

        System.out.println( "loggerContext.getName(): " + loggerContext.getName()); // Default

        System.out.println( "Congifuration.toString(): " + LoggerContext.getContext().getConfiguration().toString());

        //Configurator.setRootLevel( Level.ALL);

        logger.trace("Scheduler  [...");

        if (!logger.isTraceEnabled()) System.out.println("Scheduler Trace is Disabled");

        if (!logger.isInfoEnabled()) System.out.println("Scheduler Info id Disabled");

        if (!logger.isDebugEnabled()) System.out.println("Scheduler Debug is Disabled");

        if (!logger.isWarnEnabled()) System.out.println("Scheduler Warn is Disabled");

        if (!logger.isErrorEnabled()) System.out.println("Scheduler Error is Disabled");

        if (!logger.isFatalEnabled()) System.out.println("Scheduler Fatal is Disabled");

        logger.debug("Scheduler logging debug");

        logger.info("Scheduler logging info");

        logger.warn("Scheduler logging warn ");

        logger.error("Scheduler logging error ");

        logger.fatal("Scheduler logging fatal ");
        ServiceA serviceA = new ServiceA();        serviceA.info();
        logger.trace("Scheduler  ...]");
    }
}

Auxiliar class ServiceA

public class ServiceA {
    final static Logger logger = LogManager.getLogger();

  //final static Logger logger = LogManager.getLogger( ServiceA.class);
    public String info() {
        System.out.println( String.format("logger.getName(), getLevel() = %s, %s", logger.getName(), logger.getLevel()));

        logger.trace("ServiceA.info()  [...");

        if (!logger.isTraceEnabled()) System.out.println("ServiceA Trace is Disabled");

        if (!logger.isInfoEnabled()) System.out.println("ServiceA Info id Disabled");

        if (!logger.isDebugEnabled()) System.out.println("ServiceA Debug is Disabled");

        if (!logger.isWarnEnabled()) System.out.println("ServiceA Warn is Disabled");

        if (!logger.isErrorEnabled()) System.out.println("ServiceA Error is Disabled");

        if (!logger.isFatalEnabled()) System.out.println("ServiceA Fatal is Disabled");

        logger.debug("logging debug");

        logger.info("logging info");

        logger.warn("logging warn ");

        logger.error("logging error ");

        logger.fatal("logging fatal ");

        logger.trace("ServiceA.info()  ...]");

   return "MessageSerivice.info Junit5";    }
}

Lets Start with a simle config file which generates an output of a simple scheduler that calls a simple service. this outpus goes to STDOUT

log4j2.xml

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

<Configuration status="TRACE" strict="true" name="XMLConfigTest"               packages="">

     <Appenders>

       <Appender type="Console" name="STDOUT">

          <Layout type="PatternLayout" pattern="%d{HH:mm:ss.SSS} |%-5p | %-15c{1} | %m%n"/>

       </Appender>

     </Appenders>

     <Loggers>

        <Root level="TRACE">

           <AppenderRef ref="STDOUT"/>

        </Root>

     </Loggers>

 </Configuration>

We get lots of info, before and after the info we are interested on, that's because the Configuration status is on TRACE, So let filter to FATAL to discard the info related to the log4j2 framework.

...
2019-11-27 13:41:15,057 main TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=18b4aac2,component=Loggers,name=*,subtype=RingBuffer'
2019-11-27 13:41:15,057 main DEBUG Registering MBean org.apache.logging.log4j2:type=18b4aac2
2019-11-27 13:41:15,058 main DEBUG Registering MBean org.apache.logging.log4j2:type=18b4aac2,component=StatusLogger
2019-11-27 13:41:15,058 main DEBUG Registering MBean org.apache.logging.log4j2:type=18b4aac2,component=ContextSelector
2019-11-27 13:41:15,058 main DEBUG Registering MBean org.apache.logging.log4j2:type=18b4aac2,component=Loggers,name=
2019-11-27 13:41:15,058 main DEBUG Registering MBean org.apache.logging.log4j2:type=18b4aac2,component=Appenders,name=STDOUT
2019-11-27 13:41:15,058 main TRACE Using DummyNanoClock for nanosecond timestamps.
2019-11-27 13:41:15,059 main DEBUG Reconfiguration complete for context[name=Default] at URI D:\proy\junit5Log4j\target\classes\log4j2.xml (org.apache.logging.log4j.core.LoggerContext@3590fc5b) with optional ClassLoader: null
2019-11-27 13:41:15,059 main DEBUG Shutdown hook enabled. Registering a new one.
2019-11-27 13:41:15,059 main DEBUG LoggerContext[name=Default, org.apache.logging.log4j.core.LoggerContext@3590fc5b] started OK.
logger.getName(), getLevel() = com.bext.Scheduler, TRACE
loggerContext.getName(): Default
Congifuration.toString(): XmlConfiguration[location=D:\proy\junit5Log4j\target\classes\log4j2.xml]
13:41:15.061 |TRACE | Scheduler       | Scheduler [...
13:41:15.063 |DEBUG | Scheduler       | Scheduler logging debug
13:41:15.063 |INFO | Scheduler       | Scheduler logging info
13:41:15.063 |WARN | Scheduler       | Scheduler logging warn
13:41:15.063 |ERROR | Scheduler       | Scheduler logging error
13:41:15.063 |FATAL | Scheduler       | Scheduler logging fatal
logger.getName(), getLevel() = com.bext.ServiceA, TRACE
13:41:15.064 |TRACE | ServiceA        | ServiceA.info() [...
13:41:15.064 |DEBUG | ServiceA        | logging debug
13:41:15.064 |INFO | ServiceA        | logging info
13:41:15.064 |WARN | ServiceA        | logging warn
13:41:15.064 |ERROR | ServiceA        | logging error
13:41:15.064 |FATAL | ServiceA        | logging fatal
13:41:15.064 |TRACE | ServiceA        | ServiceA.info() ...]
13:41:15.064 |TRACE | Scheduler       | Scheduler ...]2019-11-27 13:41:15,065 pool-1-thread-1 DEBUG Stopping LoggerContext[name=18b4aac2, org.apache.logging.log4j.core.LoggerContext@689604d9]
2019-11-27 13:41:15,065 pool-1-thread-1 DEBUG Stopping LoggerContext[name=18b4aac2, org.apache.logging.log4j.core.LoggerContext@689604d9]...
2019-11-27 13:41:15,065 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=18b4aac2]
2019-11-27 13:41:15,065 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=18b4aac2,component=StatusLogger]
2019-11-27 13:41:15,066 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=18b4aac2,component=ContextSelector]
2019-11-27 13:41:15,066 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=18b4aac2,component=Loggers,name=]
2019-11-27 13:41:15,066 pool-1-thread-1 TRACE Unregistering 1 MBeans: [org.apache.logging.log4j2:type=18b4aac2,component=Appenders,name=STDOUT]
2019-11-27 13:41:15,067 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=18b4aac2,component=AsyncAppenders,name=*'
2019-11-27 13:41:15,067 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=18b4aac2,component=AsyncLoggerRingBuffer'
2019-11-27 13:41:15,067 pool-1-thread-1 TRACE Unregistering but no MBeans found matching 'org.apache.logging.log4j2:type=18b4aac2,component=Loggers,name=*,subtype=RingBuffer'
2019-11-27 13:41:15,067 pool-1-thread-1 TRACE Stopping XmlConfiguration[location=D:\proy\junit5Log4j\target\classes\log4j2.xml]...
...

Setting the Configuration status ="FATAL" only get the log info of our interest. also lets filter the logger root to ALL.

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

<Configuration status="FATAL" strict="true" name="XMLConfigTest"               packages="">

    <Appenders>

       <Appender type="Console" name="STDOUT">

             <Layout type="PatternLayout" pattern="%d{HH:mm:ss.SSS} |%-5p | %-15c{1} | %m%n"/>

       </Appender>

    </Appenders>

    <Loggers>

       <Root level="ALL">

            <AppenderRef ref="STDOUT"/>

       </Root>

    </Loggers>

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

 <Configuration status="FATAL" strict="true" name="XMLConfigTest"  packages="">

 <Properties>

    <Property name="filename">target/test.log</Property>

 </Properties>

 <!-- <Filter type="ThresholdFilter" level="ERROR"/> -->

 <Appenders>

    <Appender type="Console" name="STDOUT">

       <Layout type="PatternLayout" pattern="%d{HH:mm:ss.SSS} |%-5p | %-15c{1} | %m%n"/>

    </Appender>

    <Appender type="File" name="File" fileName="${filename}" append="false">

       <Layout type="PatternLayout">

           <Pattern>%d{HH:mm:ss.SSS}| %-5p | %-15c{1} | %m%n</Pattern>

       </Layout>

    </Appender>

</Appenders>

<Loggers>

    <Logger name="com.bext.Scheduler"  >

       <AppenderRef ref="STDOUT"/>

    </Logger>

    <Logger name="com.bext.ServiceA"   >

       <AppenderRef ref="File"/>

    </Logger>
    <Root level="ERROR">

       <!--  <AppenderRef ref="STDOUT"/>  -->

       <!--  <AppenderRef ref="File"/> -->

    </Root>

 </Loggers>

</Configuration>

Observe the events are filtered at ERROR level by Logger Root over the others to loggers, so we get

STDOUT
logger.getName(), getLevel() = com.bext.Scheduler, ERROR
loggerContext.getName(): Default
Congifuration.toString(): XmlConfiguration[location=D:\proy\junit5Log4j\target\classes\log4j2.xml]
Scheduler Trace is Disabled
Scheduler Info id Disabled
Scheduler Debug is Disabled
Scheduler Warn is Disabled
14:07:53.900 |ERROR | Scheduler | Scheduler logging error
14:07:53.902 |FATAL | Scheduler | Scheduler logging fatal
logger.getName(), getLevel() = com.bext.ServiceA, ERROR
ServiceA Trace is Disabled
ServiceA Info id Disabled
ServiceA Debug is Disabled
ServiceA Warn is Disabled

FILE log

14:07:53.903| ERROR | ServiceA        | logging error 
14:07:53.903| FATAL | ServiceA        | logging fatal

We adjust the logger STDOUT to trace the events of com.bext.*, this will include Schedurer and ServiceA class.

<Loggers>

   <Logger name="com.bext"  >

      <AppenderRef ref="STDOUT"/>

   </Logger>

   <Logger name="com.bext.ServiceA"   >

      <AppenderRef ref="File"/>

   </Logger>

We get from ERROR .. FATAL
STDOUT
logger.getName(), getLevel() = com.bext.Scheduler, ERROR
loggerContext.getName(): Default
Congifuration.toString(): XmlConfiguration[location=D:\proy\junit5Log4j\target\classes\log4j2.xml]
Scheduler Trace is Disabled
Scheduler Info id Disabled
Scheduler Debug is Disabled
Scheduler Warn is Disabled
14:17:39.724 |ERROR | Scheduler       | Scheduler logging error
14:17:39.726 |FATAL | Scheduler       | Scheduler logging fatal
logger.getName(), getLevel() = com.bext.ServiceA, ERROR
ServiceA Trace is Disabled
ServiceA Info id Disabled
ServiceA Debug is Disabled
ServiceA Warn is Disabled
14:17:39.727 |ERROR | ServiceA        | logging error
14:17:39.727 |FATAL | ServiceA        | logging fatal

Now override the filter ERROR on logger root, to specific lever on Schedure logger, and ServiceA logger.

<Loggers>

   <Logger name="com.bext.Scheduler" level="TRACE"  >

      <AppenderRef ref="STDOUT"/>

   </Logger>

   <Logger name="com.bext.ServiceA" level="DEBUG"  >

     <AppenderRef ref="File"/>

   </Logger>
     <Root level="ERROR">

     <!--  <AppenderRef ref="STDOUT"/>  -->

     <!--  <AppenderRef ref="File"/> -->

     </Root>
</Loggers>

14:21:52.149| DEBUG | ServiceA        | logging debug
14:21:52.149| INFO  | ServiceA        | logging info
14:21:52.150| WARN  | ServiceA        | logging warn 
14:21:52.150| ERROR | ServiceA        | logging error 
14:21:52.150| FATAL | ServiceA        | logging fatal

Now on the logger to STDOUT change name from com.bext.Scheduler to com.bext, we get

<Loggers>    <Logger name="com.bext" level="TRACE"  >        <AppenderRef ref="STDOUT"/>    </Logger>    <Logger name="com.bext.ServiceA" level="DEBUG"  >        <AppenderRef ref="File"/>    </Logger>
    <Root level="ERROR">

 <!-- <AppenderRef ref="STDOUT"/> -->

 <!--  <AppenderRef ref="File"/> -->

 </Root>

 </Loggers>

<Loggers>

   <Logger name="com.bext.Scheduler" level="TRACE"  >

     <AppenderRef ref="STDOUT"/>

   </Logger>

   <Logger name="com.bext.ServiceA" level="DEBUG"  >

     <AppenderRef ref="File"/>

   </Logger>

   <Root level="ERROR">

      <AppenderRef ref="STDOUT"/>

<!--  <AppenderRef ref="File"/> -->

}  </Root>

</Loggers>

<Loggers>

   <Logger name="com.bext.Scheduler" level="TRACE" additivity="false" >

     <AppenderRef ref="STDOUT"/>

   </Logger>

   <Logger name="com.bext.ServiceA" level="DEBUG"  >

     <AppenderRef ref="File"/>

   </Logger>

   <Root level="ERROR">

      <AppenderRef ref="STDOUT"/>

 <!--  <AppenderRef ref="File"/> -->

   </Root>

</Loggers>

<Loggers>

   <Logger name="com.bext.Scheduler" level="TRACE" additivity="false" >

      <AppenderRef ref="STDOUT"/>

   </Logger>

   <Logger name="com.bext.ServiceA" level="DEBUG"  >

     <AppenderRef ref="File"/>

   </Logger>

   <Root level="ERROR">

     <AppenderRef ref="STDOUT"/>

     <AppenderRef ref="File"/>

     </Root>

</Loggers>

13:33:05.936| DEBUG | ServiceA        | logging debug
13:33:05.936| DEBUG | ServiceA        | logging debug
13:33:05.936| INFO  | ServiceA        | logging info
13:33:05.936| INFO  | ServiceA        | logging info
13:33:05.936| WARN  | ServiceA        | logging warn 
13:33:05.936| WARN  | ServiceA        | logging warn 
13:33:05.936| ERROR | ServiceA        | logging error 
13:33:05.936| ERROR | ServiceA        | logging error 
13:33:05.937| FATAL | ServiceA        | logging fatal 
13:33:05.937| FATAL | ServiceA        | logging fatal

Create a Rolling File

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="ERROR" strict="true" name="XMLConfigTest"
               packages="">
    <Properties>
        <Property name="filename">target/test.log</Property>
        <Property name="rollingfilename">target/logs/app.log</Property>
    </Properties>
    
    <Appenders>
        <Appender type="Console" name="STDOUT">
            <Layout type="PatternLayout" pattern="%d{HH:mm:ss.SSS} |%-5p | %-15c{1} | %m%n"/>
        </Appender>
        <Appender type="File" name="File" fileName="${filename}" append="false">
            <Layout type="PatternLayout">
                <Pattern>%d{HH:mm:ss.SSS}| %-5p | %-15c{1} | %m%n</Pattern>
            </Layout>
        </Appender>
        <RollingFile name="RollingFile" fileName="${rollingfilename}"
                     filePattern="target/logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz">
            <PatternLayout>
                <pattern>%d %p %c{1.} [%t] %m%n</pattern>
            </PatternLayout>
            <Policies>
               
               <TimeBasedTriggeringPolicy/>
               <SizeBasedTriggeringPolicy size="1KB"/>
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Logger name="com.bext.Scheduler" level="TRACE" additivity="false">
            <AppenderRef ref="STDOUT"/>
        </Logger>
        <Logger name="com.bext.Scheduler" level="TRACE" additivity="false">
            <AppenderRef ref="RollingFile"/>
        </Logger>
        <Logger name="com.bext.ServiceA" level="DEBUG" additivity="false">
            <AppenderRef ref="File"/>
        </Logger>
        <Root level="ERROR">
            
        </Root>
    </Loggers>
</Configuration>

File structure generated after tree runs.

eot

Holocron

Navegación

lunes, 25 de noviembre de 2019

Log4J2 Architecture, Configuration

Log4J2 Architecture

Why Log4j2

Architecture description

Configuration Example

No hay comentarios:

Publicar un comentario