Java and Spring development

SLF4J logging with Log4J and JCL

with 6 comments

More and more frameworks logs with the SLF4J framework. Many applications must relate to several different logging frameworks. This tutorial shows how one logger framework can handle log messages from other logging frameworks with SLF4J as the central part.

The demo application used in this tutorial logs with Log4J and have dependencies to Spring and Hibernate. Here’s the different loggers and where they are used:

  • JCL Spring
  • SLF4J Hibernate 3.3+
  • Log4J Demo application

Log4J integrates well with JCL, but can’t handle log messages from SLF4J. This forces the use of SLF4J to connect the different loggers together.

SLF4J

A description of SLF4J from their homepage:

The Simple Logging Facade for Java or (SLF4J) serves as a simple facade or abstraction for various logging frameworks, e.g. java.util.logging, log4j and logback, allowing the end user to plug in the desired logging framework at deployment time.

In addition to the extra flexibility, the API also contains a nice feature with support for arguments.

logger.debug("The date is: {}", date);

The old way with Log4J:

if (logger.isDebugEnabled()) {
	logger.debug("The date is: " + date);
}

Both examples prints:

 DEBUG [demo.Slf4jDemo] - <The date is: Sun Jun 06 11:34:11 CEST 2010>

The difference is that SLF4J doesn’t merge the dynamic and static data into a new string in the debug method, but sends the dynamic part(s) as argument(s). If the logger is configured to only log messages with info level or higher, the debug message above gets discarded without any string processing and without the need for an extra if sentence for performance reasons.

For information about SLF4J and its alternatives on a high level, Bruce Snyder has written a good post here.

Two scenarios that will support central log handling

The first option is to bind the SLF4J logger against Log4J. It works nice and enables management of JCL and SLF4J log messages from the Log4J configuration. In my case with the log4j.properties file.

The other alternative which is also recommended in the SLF4J’s manual is to log messages to the SLF4J framework and bind SLF4J to the new logback framework like this:

With the second solution, SLF4J’s binder framework will receive all the log messages.

SLF4J and and binding against a backend logger

You can only bind against one backend logging framework. With no binding framework on the classpath, the silent logger (NOP) will be used by default.

The frameworks supported by SLF4J:

  • Logback-classic
  • Log4J
  • java.util.logging (JUL)
  • Simple
  • NOP
  • Jakarta Commons Logging (JCL)

The preferred backend logging framework with SLF4J is Logback.

Logback

Logbac is written by the same people who have written SLF4J. It natively implements the SLF4J API.

Their description of the framework:

The logback-classic module can be assimilated to a significantly improved version of log4j

A nice feature with Logback is that you can see which jar file that contains a class in the stacktrace. And if the jar file contains an Implemented-Version property in the /META-INF/MANIFEST.MF file, then you can see the version number to the right for the jar file name.

org.springframework.beans.factory.NoSuchBeanDefinitionException: No bean named 'unkownBeanId'
        is defined
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeanDefinition
        (DefaultListableBeanFactory.java:510)
        ~[org.springframework.beans-3.0.2.RELEASE.jar:3.0.2.RELEASE]

You can find more reasons to upgrade from Log4J to Logback on their site here.

Logging with the SLF4J API

A simple example:

import java.util.Date;

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

public class Slf4jDemo {

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

	public void demo() {
		Date date = new Date();

		logger.debug("The date is: {}", date);
	}

	public static void main(String[] args) {
		new Slf4jDemo().demo();
	}
}

A basic logback.xml configuration file:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="stdout">
    <encoder>
      %-5p [%c] - <%m>%n
    </encoder>
  </appender>
  <logger name="demo" level="DEBUG"/>
  <root level="WARN">
    <appender-ref ref="stdout"/>
  </root>
</configuration>

Handle JCL log messages with SLF4J

With SLF4J’s JCL bridge implementation, you can program against the JCL API without adding the JCL jar file, since the bridge implementation contains the necessary classes to route the log messages to the SLF4J’s backend implementation.

An example that logs with the JCL API like the Spring framework does:

import java.util.Date;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

public class ApacheCommonsLoggerDemo {

	private final static Log logger = LogFactory.getLog(ApacheCommonsLoggerDemo.class);

	public void demo() {
		Date date = new Date();

		logger.debug("The date is: " + date);
	}

	public static void main(String[] args) {
		new ApacheCommonsLoggerDemo().demo();
	}
}

Log4J messages and SLF4J

Many applications logs with Log4J. These log messages can also be handled by SLF4J’s backend logger with adding the log4j-over-slf4j library to your build path. This library works similar to the JCL bridge implementation described above. The important class is the org.apache.log4j.Logger and is instantiated like this:

private final Logger logger = Logger.getLogger(Log4jDemo.class);

Summary

SLF4J is the new common logging API for new open-source projects. With its facade pattern implementation, it’s a very flexible framework that let you easily integrate different logging frameworks used by the application’s dependencies. It’s also modular by nature with a loose coupling between the SLF4J API and the backend logger framework.

In addition to the modularity, I like the enhanced stacktrace that’s printed with the configuration illustrated in the second scenario without changing a single line of code!

If you in the future wants to standardize logging with SLF4J, then you can use this migrator that’s bundled with the SLF4J distribution and migrate your log4j.properties file to a logback.xml file with this online translator.

Written by Espen

June 6, 2010 at 21:02

Posted in Logging

Tagged with , , , , ,

Pitfalls with aspect technologies

with 3 comments

Even though aspect technologies are very powerful. Especially to address cross-cutting concerns like transactions, it shouldn’t be used everywhere it’s possible.

The first part of this post consists of a simple example that uses AspectJ to return an unexpected value. The last part is about where aspects fits and where you should consider to avoid it.

A quote from the Spider-Man movie:

With great power comes great responsibility

This applies to some degree to aspect technologies too. Since it can change the behaviour of an application at compilation, startup or at runtime. Even without leaving a trace in the source code.

An aspect that changes the return value of String’s toLowerCase()

To demonstrate an unexpected result from a method, I have created a StringAspect with AspectJ that returns the opposite of what the method name says.

When some code calls on String‘s toLowerCase() method, the StringAspect below reroutes the call to String‘s toUpperCase() method instead:

@Aspect
public class StringAspect {

	@Pointcut("call(* String.toLowerCase())")
	public void toLowerCasePointcut() {}

	@Around("toLowerCasePointcut()")
	public String toLowerCaseAroundAdvice(ProceedingJoinPoint joinPoint) throws Throwable {

//		String text = (String) joinPoint.proceed();
		String text = ((String) joinPoint.getTarget()).toUpperCase();

		return text;
	}
}

To get the expected result, you can remove the comment on the line with joinPoint.proceed() and remove the line below. Eventually remove the AspectJ compiler or the JVM agent to avoid weaving in the advice.

The test class that asserts that the String‘s toLowerCase() method works as expected:

public class StringTest {

	@Test
	public void testAroundAdvice() {
		String demoText = "tHiS iS a TeSt";

		assertEquals("this is a test", demoText.toLowerCase());
	}
}

Without AspectJ weaving, the test finishes successfully, but with weaving the result is:

org.junit.ComparisonFailure: expected:<[this is a test]> but was:<[THIS IS A TEST]>

Best practice from enterprise frameworks

Features like transaction handling, security and concurrency support are good candidates to be done with aspects. Spring, Guice and EJB implementations all use aspects to provide such enterprise capabilities without cluttering the application’s source code with infrastructure logic.

You can see this post for a good example. Best practice with Java 5 and later is to add an annotation on methods that will be intercepted.

Annotations that says this method should be executed asynchronously in a transaction:

@Async
@Transactional
public void demoMethod() {
	// logic ..
}

These annotations are excellent pointcuts for enterprise frameworks.

Cases where aspects should be avoided

To change the target method like the StringAspect above should be avoided. You can replace an instance with a mock/stub object with AspectJ. In situations where the called instance is an object of a final class that doesn’t implement any interfaces, then an aspect is your only choice. It mocks away the dependency, but refactoring the code and use a mocking framework should be the preferred choice. It makes the code much more readable.

Especially without a tool like AJDT that visualizes the joinpoints in the source code. Here’s an example with the AJDT Eclipse plugin.

You should be really careful about adding or changing any data inside an advice. Such modifications makes the code almost impossible to read and the chance for bugs are higher.

Else, if many of the developers in a team isn’t familiar with aspects, you should also limit the use since it adds “magic” to the application that only a few developers on the team can understand.

Written by Espen

June 5, 2010 at 17:11

Posted in Aspects

Tagged with