DevOps Zone is brought to you in partnership with:

Gordon Dickens is an instructor, mentor & consultant. Gordon is currently architecting and teaching several official SpringSource courses and actively tweets about open source technology at http://twitter.com/gdickens. Gordon is active within the Spring Framework community focussed on: Spring training, Spring Roo, Spring Integration, Spring Batch and Eclipse Virgo OSGi projects. Gordon is a DZone MVB and is not an employee of DZone and has posted 39 posts at DZone. You can read more from them at their website. View Full User Profile

Sawing through the Java Loggers

03.29.2013
| 8394 views |
  • submit to reddit

Sawing through the Java Loggers

It's Log!

I know what you're thinking: “It’s just logging!” This small, yet common part of our applications, provides developers, QA and troubleshooters with information to help in determining code execution sequences, inspecting data values and trouble spots within our applications. The reality is that without robust logging implementations we would lose a significant troubleshooting tool.

Java Logging Choices

  1. System.out/System.err
  2. java.util.logging (JUL)
  3. Apache commons jogging (aka Jakarta Commons Logging – JCL)
  4. Log4j
  5. SLF4j
  6. Logback

System.out & System.err

In the early days (hopefully not now) we used to use the old System.out.println()method of logging. We would quickly discover using them is NOT good.

Reasons to avoid System methods

  • We can not disable in production, affecting performance and potentially compromising data security. Oh we do have System.err.println() but still not good enough
  • We can not configure how much or little information is reported (logging levels)
  • In a clustered environment, we can not configure a central location for information
  • System.out performs poorly… see Logging vs System.out Performance
  • Metadata is unavailable and must be coded for each System.out, which is inevitably not going to be done or very inconsistent at the least

*** DO NOT USE System.out or System.err anywhere, ever! ***

java.util.logging (JUL)

Java provides a logging option which is a step forward in logging. However, it is not widely used as it came late to the party. Not many open source frameworks use JUL. Typically you will find this in com.sun or com.oracle projects such as Jersey.

Log4j

Log4j is an Apache project that has been around for some time and is widely used by open source projects. Log4j provides a flexible logging framework but is a bit dated at this point.

SLF4j – Logging API

We have many options for logging, and with our open source projects we typically include projects that might implement JCL and JUL.

SLF4j (Simple Logging Facade for Java) provides a common logging interface for our projects. Most respectable open source projects now use SLF4j for the configurability and flexibility to change logging implementation. Think of SLF4j as the common interface (API) for our logging implementation choice.

All of our logging code should use the same SLF4j API. For example:

import org.slf4j.Logger; 
import org.slf4j.LoggerFactory; 
…




public class MyClass {
private static final Logger logger = LoggerFactory.getLogger(MyClass.class);
…




public void someMethod() {
logger.debug("something is happening");
}




}

Basic SLF4j Maven Dependencies

<properties>
<slf4j.version>1.7.5</slf4j.version>
<logback.version>1.0.11</logback.version>
</properties>




<dependencies>
<!-- SLF4J - logging api -->
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>${slf4j.version}</version>
</dependency>




<!-- Logback - logging impl -->
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>${logback.version}</version>
</dependency>
</dependencies>

Advanced SLF4j Maven Dependencies

<properties>
<slf4j.version>1.7.5</slf4j.version>
<logback.version>1.0.11</logback.version>
</properties>




<dependencies>
<!-- SLF4J - logging api -->
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>${slf4j.version}</version>
</dependency>
<!-- Interceptor for Commons-logging -->
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jcl-over-slf4j</artifactId>
<version>${slf4j.version}</version>
</dependency>
<!-- Interceptor for java.util.logging -->
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jul-to-slf4j</artifactId>
<version>${slf4j.version}</version>
</dependency>




<!-- Logback - logging impl -->
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>${logback.version}</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-core</artifactId>
<version>${logback.version}</version>
</dependency>
</dependencies>

SLF4j Advantages

  • One logging strategy for all
  • String placeholders
    • logger.debug(“The value of {} is {}”, myVar, myValue);
  • Intercepts commons-logging
    • Include jcl-over-slf4j dependency
    • Should exclude commons-logging dependencies from project
  • Can intercept java.util.logging
  • Can intercept System.out & System.err

Logback – Smarter Logging

Logback is a project from the creator of Log4j and SLF4j, Ceki Gülcü (pronounced Jacky Guldju).

The first article to read is: Logback: Reasons to Switch

Simple logback.xml File

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" scan="true" scanPeriod="30 seconds">




<!-- Handle JUL -->
<contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator">
<resetJUL>true</resetJUL>
</contextListener>




<!-- To enable JMX Management -->
<jmxConfigurator/>




<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%-5level %logger{0} - %msg%n</pattern>
</encoder>
</appender>




<logger name="com.gordondickens.demo" level="debug" />
<logger name="org.springframework.beans" level="trace" />




<root level="warn">
<appender-ref ref="console" />
</root>
</configuration>

File Appenders

In addition to the console appender, there are File and RollingFile. The Rolling file appender allows time-based and size-based options, with the ability to specify how many files to keep and optional compression (zip).
See: Logback Appenders

Speaks Native SLF4j

We saw above that simply replacing Log4j with Logback, we now have logging through SLF4j. Actually, its one dependency less, as we no longer would include the slf4j-log4j12 dependency.

RESTful & Web Access Logging

We can use logback-access to provide server access logging. This can prove to be very helpful when troubleshooting RESTful web services as well as for web applications. In our application’s src/main/resources directory create the file logback-access.xml.

logback-access.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />




<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${user.dir}/logs/app-access.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${user.dir}/logs/app-access.%d{yyyy-MM-dd}.log.zip</fileNamePattern>
</rollingPolicy>
<encoder>
<pattern>combined</pattern>
</encoder>
</appender>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%n%n%fullRequest%n%n%fullResponse%n%n</pattern>
</encoder>
</appender>




<appender-ref ref="FILE" />
<appender-ref ref="STDOUT" />
</configuration>

web.xml

The “TeeFilter” handles the access logging. See http://logback.qos.ch/access.html
The optional “ViewStatusMessagesServlet” allows us to browse the log back configuration via the url /logbackstatus. Seehttp://logback.qos.ch/manual/configuration.html

<filter>
<filter-name>TeeFilter</filter-name>
<filter-class>ch.qos.logback.access.servlet.TeeFilter</filter-class>
</filter>




<filter-mapping>
<filter-name>TeeFilter</filter-name>
<url-pattern>/*</url-pattern>
</filter-mapping>




<servlet>
<servlet-name>ViewStatusMessages</servlet-name>
<servlet-class>ch.qos.logback.classic.ViewStatusMessagesServlet</servlet-class>
</servlet>




<servlet-mapping>
<servlet-name>ViewStatusMessages</servlet-name>
<url-pattern>/logbackStatus</url-pattern>
</servlet-mapping>

Test Specific Configuration

In our project’s src/main/resources we define a logback.xml file.
In our project’s src/test/resources we define a logback-test.xml file.

Conditional Configuration

Logback uses Janino allowing the ability to perform conditional configuration.

Janino Maven Dependency

<dependency>
<groupId>org.codehaus.janino</groupId>
<artifactId>janino</artifactId>
<version>2.6.1</version>
</dependency>

Conditional Operations

  • boolean isDefined(String prop);
  • boolean isNull(String prop);
  • String p(String prop);
  • String property(String prop);


See: PropertyWrapperForScripts JavaDoc

<if condition='isDefined("catalina.home")'>
<then>
<property name="log.dir" value="${catalina.home}"/>
</then>
<else>
<property name="log.dir" value="${user.dir}/logs"/>
</else>
</if>

The cool thing is that we can use Spring 3 environment profiles spring.profiles.active. In the example below, the method property() or p() returns a String, so we can use String functions such as contains().

<if condition='property("spring.profiles.active").contains("dev")'>
<then>
<property name="log.dir" value="${catalina.home}"/>
</then>
<else>
<property name="log.dir" value="${user.dir}/logs"/>
</else>
</if>

Note: For testing, with Maven via the Jetty or Tomcat plugins, ${user.dir} resolves to the project home.

Modular Configuration

We can configure multiple configuration files, effectively segmenting our configuration. We could use a more detailed logging configuration for testing and a more conservative logging for production.

logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" scan="true" scanPeriod="5 seconds">
<property resource="logconfig/logback.properties"/>




<include resource="logconfig/headerconfig.xml"/>




<if condition='property("spring.profiles.active").contains("dev")'>
<then>
<include resource="logconfig/springbeans.xml"/>
<include resource="logconfig/hibernatefile.xml"/>
</then>
<else>
<include resource="logconfig/productionfile.xml"/>
</else>
</if>




<include resource="logconfig/consolelog.xml"/>




<root level="warn">
<appender-ref ref="console"/>
</root>
</configuration>

hibernatefile.xml

Included files use the are within the include tag.

<?xml version="1.0" encoding="UTF-8"?>
<included>
<appender name="hibernatefile"
class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${log.dir}/${hibernate.logfile}.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
<fileNamePattern>${log.dir}/${hibernate.logfile}.%i.log.zip</fileNamePattern>
<minIndex>1</minIndex>
<maxIndex>6</maxIndex>
</rollingPolicy>
<triggeringPolicy
class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<maxFileSize>50MB</maxFileSize>
</triggeringPolicy>
<encoder>
<pattern>%date %level - %msg%n</pattern>
</encoder>
</appender>




<logger name="org.springframework.orm" level="debug">
<appender-ref ref="hibernatefile" />
</logger>
<logger name="org.springframework.jdbc" level="debug">
<appender-ref ref="hibernatefile" />
</logger>
<logger name="org.springframework.transaction" level="debug">
<appender-ref ref="hibernatefile" />
</logger>
<logger name="org.hibernate.ejb" level="debug">
<appender-ref ref="hibernatefile" />
</logger>
<logger name="org.hibernate.sql" level="debug">
<appender-ref ref="hibernatefile" />
</logger>
<logger name="org.hibernate.tool.hbm2ddl" level="debug">
<appender-ref ref="hibernatefile" />
</logger>
</included>

Summary

  • Do NOT use System.out or System.err
  • Use SLF4j parameter placeholder {} instead of string concatenation, this eliminates the need for isDebugEnabled() around our debug logging
  • Always define the Logger as private static final
  • Using SLF4j and Logback provides flexible, smart logging. We have tools that provide rich logging options for enterprise application development
    • Logback speaks natively to SLF4j
    • Java and Groovy configuration
    • Conditional Logging
    • Modular configuration
    • Access logging
    • Message filtering
    • Compression of rolled log files
    • Sifting Appenders by runtime attributes

Further Reading

Sources

Published at DZone with permission of Gordon Dickens, author and DZone MVB. (source)

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)