Sawing through the Java Loggers

Sawing through the Java Loggers

It's Log!

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

  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">

  <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.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

About Gordon

Technology enthusiast primarily focused on Java and Open Source projects. Spring Certified Professional and Trainer. http://twitter.com/gdickens http://linkedin.com/in/gordondickens http://github.com/gordonad
This entry was posted in Jakarta Commons Logging, Java Util Logging, LogBack, Logging, SLF4J and tagged , , , , , . Bookmark the permalink.

4 Responses to Sawing through the Java Loggers

  1. Christian says:

    Hi,

    nice article, but you are wrong on your log4j impression. There is a log4j 2.0 in the making and its already pretty good:
    http://logging.apache.org/log4j/2.x

    Also see:
    http://logging.apache.org/log4j/2.x

    Cheers,
    Christian

  2. Frisian says:

    In the first paragraph you talk about applications, yet you look at the logging choices from a library author’s perspective. For libraries, SL4J and commons.logging are a reasonable choice, because one never knows, which logging framework is used inside the application that includes the library.
    With an application, things are a bit different, though: especially with web applications you want to have isolated per-application settings. Surprisingly, JDK logging is your friend here. Look at the Tomcat LogManager implementation for an example on how to achieve this without hassle. Besides, x4juli provides most of the stuff log4j offers and JDK logging misses.

  3. Gordon says:

    Unless you are including closed-source projects, you can find out what the internal logging framework. I have not found an issue with this yet.

    Using Maven you can determine the dependencies via mvn dependency:tree. This is an essential tool in Maven for determining and managing transitive dependencies.

    As for Tomcat, See the links for my Enterprise Spring Best Practices blog for code samples on how to use SLF4j and Logback with the Maven plugin. If you want to know how to configure Tomcat standalone, I can provide detail on that also.

    Regards,
    Gordon

  4. Pingback: Übersicht über Java Logging-Frameworks | neuesausfreaktown

Leave a Reply

Your email address will not be published. Required fields are marked *


*

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>