Sawing through the Java Loggers
I know what your 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
- System.out/System.err
- java.util.logging (JUL)
- Apache commons jogging (aka Jakarta Commons Logging – JCL)
- Log4j
- SLF4j
- 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-slf4jdependency - Should exclude
commons-loggingdependencies from project
- Include
- Can intercept
java.util.logging- Include
jul-to-slf4jdependency - Requires registration of classes within the application
- See: Enterprise Spring Best Practices Blog
- Include
- Can intercept
System.out&System.err- Requires including dependencies
- Requires registration of classes within the application
- See: Enterprise Spring Best Practices Blog
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">
<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. See http://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 are wrapped with 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.outorSystem.err - Use SLF4j parameter placeholder
{}instead of string concatenation, this eliminates the need forisDebugEnabled()around our debug logging - Always define the
Loggerasprivate 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
- http://logback.qos.ch
- http://www.slf4j.org
- http://logging.apache.org/log4j/1.2
- Logging vs System.out Performance
- Enterprise Spring Best Practices Blog
- Janino

