Thursday, July 27, 2017

Logging in Java - Log4j2 over SLF4J

When it comes to logging in Java applications, it is common practice to go with one of many available logging frameworks. As frameworks evolve and address recurring logging needs of applications, it could be cumbersome to switch from an existing framework to a new one. For this reason, it is recommended to program to a common logging interface and change the underlying implementation as needed. SLF4J is a commonly used logging interface, and Log4j is a good example of the work involved in upgrading from one version to another.

In this blog, I will highlight a Log4j2 over SLF4J approach to application logging.

Logging Levels

Using the following log levels are recommended as best practice. Logging approach will adhere to SLF4J Interface and only use log levels available in SLF4J (see http://www.slf4j.org/api/org/apache/commons/logging/Log.html).

Trace
This level should be used when capturing very detailed information about the system. Logging every step of the execution and capturing state of the code. Trace is useful to detect obscure behavior. By default it should be OFF, as IO operations are expensive.

Debug
This level should be used to report detailed information about the behavior and state of the code. It can be used to diagnose specifics or record user/application behavior. By default it should be OFF, as IO operations are expensive.

Info
Use this level to capture useful information about the system, record diagnostics info,  and report normal behavior. It should be used to indicate that the system is correctly initialized and started, and that connections are made successfully. This level can be set to ON.

Warning
Use this level to report issues with the system, such as running low in resources [e.g.,db connections], accessing information that should not be accessed again, retry limits reached, normal timeouts, etc... This level should be used to log messages that need to be flagged and attended to by responsible parties. This level must be ON.

Error
Use this level to record exception and errors with the system. Examples are network problems, resource availability. Messages logged at this level should be handled and responsible parties should be alerted. This level must be ON.

Fatal
Most serious messages should be logged at this level. Information such as why system was stopped should be logged and report immediately. This level must be ON.

Working with Log4j2
Assuming maven is used to build the application, to start programming with Log4j2, include the required dependencies in your pom.xm

<properties>
    ...
    <org.slf4j.version>1.7.21</org.slf4j-version>
    <log4j2.version>2.6.2</log4j2.version>
    ...
</properties>
 
<dependencies>
    ...
    <!-- SLF4J Logging -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>${org.slf4j.version}</version>
    </dependency>
 
    <!-- Log4j2 -->
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>${log4j2.version}</version>
    </dependency>
    <!-- Log4j2 Binding to SLF4J -->
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-slf4j-impl</artifactId>
        <version>${log4j2.version}</version>
    </dependency>
    <!-- you need the following jar files if planning to use Log4j2 Client GUI with jconsole  -->
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-api</artifactId>
        <version>${log4j2.version}</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-jmx-gui</artifactId>
        <version>${log4j2.version}</version>
    </dependency>
    ...
</dependencies>

In your java code, import the following packages

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
And add the following to Java classes requiring logging

private static final Logger logger = LoggerFactory.getLogger(YourClassName.class);

Configuration
Typically log4j2 configuration file (log4j2.xml) can be placed on the classpath. Several points related to the location of the config file:
  • To make it available on classpath,  place it in src/main/resources
  • To load it as an external file, use -Dlog4j.configurationFile="/path/to/config/log4j2.xml"
  • To load it only for testing, place log4j2-test.xml in src/test/resources
  • To specify the location in a web application, use a servlet context parameter. See Set the Configuration Path.
Here is an example of log4j2.xml:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <File name="MyAppLog" fileName="/opt/myapp/logs/myapp.log">
            <PatternLayout>
                <Pattern>%d [%p] %c{1.} : %m%n</Pattern>
            </PatternLayout>
        </File>
        <Console name="STDOUT" target="SYSTEM_OUT">
            <PatternLayout>
                <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
            </PatternLayout>
        </Console>
    </Appenders>

    <Loggers>
        <Root level="WARN">
            <AppenderRef ref="MyAppLog" level="WARN" />
            <AppenderRef ref="STDOUT" level="WARN" />
        </Root>
        <Logger name="org.springframework" level="WARN">
            <AppenderRef ref="STDOUT" level="WARN" />
        </Logger>
        <Logger name="org.apache.cxf" level="WARN">
            <AppenderRef ref="STDOUT" />
        </Logger>
    </Loggers>
</Configuration>

Notes
  • In general, writing messages to a log file is expensive, so use logging levels wisely.
  • In version 1 of Log4j, it was recommended to guard log operations with is[LogLeve]Enabled checks. Here is a great blog on how to overcome inefficiency of logging when log levels not requiring logging.
  • You can add 3rd party tools logging to your configuration
    • For CXF, add the following to src/main/resources/META-INF/org.apache.cxf.Logger
    • org.apache.cxf.common.logging.Slf4jLogger
  • You can configure log files periodically rotate based on certain criteria. Here is an example of rotating log files:
  • <?xml version="1.0" encoding="UTF-8"?>
    <Configuration>
            <Properties>
                    <property name="name">myapp-rolling</property>
                    <property name="pattern">%d{yyyy-MM-dd HH:mm:ss.SSS} | %-5.5p | %-10.10t | %-20.20C:%-5.5L | %msg%n</property>
    <!--
    It will look like that:
    2013-04-03 07:37:51.993 | WARN  | main       | myserver.Server:56    | My app is logging stuff
    -->
            </Properties>
            <Appenders>
                    <RollingFile name="RollingCdspLog" fileName="/path/to/my/logs/${name}.log"
                                 filePattern="/path/to/my/logs/$${date:yyyy-MM}/${name}-%d{yyyy-MM-dd}-%i.log.gz">
                            <PatternLayout>
                                    <pattern>${pattern}</pattern>
                            </PatternLayout>
                            <Policies>
                                    <TimeBasedTriggeringPolicy /><!-- Rotated everyday -->
                                    <SizeBasedTriggeringPolicy size="1 MB"/> <!-- Or every 100 MB -->
                            </Policies>
                    </RollingFile>
                    <File name="CDSPLog" fileName="/path/to/my/logs/override-myapp.log">
                            <PatternLayout>
                                    <Pattern>%d [%p] %c{1.} : %m%n</Pattern>
                            </PatternLayout>
                    </File>
                    <Console name="STDOUT" target="SYSTEM_OUT">
                            <PatternLayout>
                                    <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
                            </PatternLayout>
                    </Console>
            </Appenders>
    
            <Loggers>
                    <Root level="DEBUG">
                            <AppenderRef ref="CDSPLog" level="INFO" />
                            <AppenderRef ref="RollingCdspLog" level="DEBUG" />
                            <AppenderRef ref="STDOUT" level="WARN" />
                    </Root>
                    <Logger name="org.springframework" level="WARN">
                            <AppenderRef ref="STDOUT" level="WARN" />
                    </Logger>
                    <Logger name="org.apache.cxf" level="WARN">
                            <AppenderRef ref="STDOUT" />
                    </Logger>
            </Loggers>
    </Configuration>
Log4j2 JMX

Log4j 2 has built-in support for JMX. The StatusLogger, ContextSelector, and all LoggerContexts, LoggerConfigs and Appenders are instrumented with MBeans and can be remotely monitored and controlled.

To configure Log4j2 at runtime, a client GUI plugin can be used with jconsole. The following steps will demonstrate how to attach jconsole to a running Junit process. This Junit process will start logging messages.
  1. Download  log4j-core-2.6.2.jar, log4j-api-2.6.2.jar, log4j-jmx-gui-2.6.2.jar (see pom.xml)
  2. Run jconsole -pluginpath ./log4j-core-2.6.2.jar:./log4j-api-2.6.2.jar:./log4j-jmx-gui-2.6.2.jar
  3. Select a local process that is running your app. For example, if you are junit testing in eclipse, select: org.eclipse.jdt.internal.junit.runner.RemoteTestRunner from Local Process list, and press connect. Select Log4j2 tab.
  4. You can change the configuration and select the appropriate Reconfigure button