Java and Spring development

Posts Tagged ‘Spring

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

Declaratively add enterprise functionality

with one comment

The goal with this tutorial is to explain how you can add enterprise functionality declaratively and how an application container does it.

Enterprise functionality like transaction handling and security are often handled by an application container. I will demonstrate how to add transactional handling with the Decorator pattern, an interceptor (AspectJ) and an interceptor configured with the Spring framework. All the alternatives works without adding boilerplate transaction logic to the business classes.

The decorator pattern can add behaviour to your business implementation without polluting the business implementation. The limitation with the decorator pattern compared to an interceptor is that the decorator must implement your business class’ interface. An interceptor implemented with the AspectJ technology modifies the class either at compile or load-time. A general practice is to add business functionality with decorators, while you add enterprise functionality like transaction handling and security logic with interceptors.

Example case for this tutorial

This tutorial consist of four examples all using the interfaces on the image below with transaction logic around the transferAmount(..) method. The sequence diagram illustrates a successful transaction that will be commited.

Transfer amount sequence diagram

The other case demonstrated is when the credit method fails. Then the amount transferred from the debit account must be cancelled with a roll back. The roll back is triggered with a RuntimeException. This is the default way with EJB as well as the lightweight containers like Spring and Google Juice.

All the examples except the last one uses stub implementations for the repository and the transaction logic. The last example with Spring uses an embedded database and a JDBC transaction manager.

Transaction handling with the decorator pattern

This decorator example consist of the interfaces on the sequence diagram above as well as implementations of them and a transaction decorator that also implements the AccountService.

The business interface:

public interface AccountService {

	public boolean transferAmount(final Amount amount, final Account debetAccount,
             final Account creditAccount);
}

The transferAmount() method in the business implementation:

@Transactional
public boolean transferAmount(final Amount amount,
		final Account debetAccount, final Account creditAccount) {
	final boolean transferred;

	final Amount debetAccountBalance = accountRepository
			.getBalance(debetAccount);

	logger.debug("Balance on debet account before transfer: {}", debetAccountBalance.getAmount());

	if (debetAccountBalance.isLargerThanOrEqualTo(amount)) {
		debetAmount(amount, debetAccount);
		creditAmount(amount, creditAccount);

		transferred = true;
		logger.debug("{} amount was transferred from {} to {}",
				new Object[] { amount, debetAccount, creditAccount });
	} else {
		transferred = false;
		logger.debug("The transfer amount: {} is higher than the balance available on the " +
                     "debet account", amount.getAmount());
	}

	return transferred;
}

The method doesn’t contain any transactional logic. Since this example doesn’t use any interceptors, the @Transactional annotation is ignored.

When I execute the method with sufficient balance on the debit account, the following line is printed to the log:

INFO  [com.redpill.linpro.service.impl.AccountServiceImpl] -

With the transaction decorator the output is:

DEBUG [com.redpill.linpro.service.impl.AccountTransactionDecorator] -
INFO  [com.redpill.linpro.service.impl.AccountServiceImpl] - <Amount [amount=50] was transferred from Account [accountNumber=1] to Account [accountNumber=2]>
DEBUG [com.redpill.linpro.service.impl.AccountTransactionDecorator] - <Commit transaction>

The transaction decorator stub implementation:

package com.redpill.linpro.service.impl;

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

import com.redpill.linpro.integration.Account;
import com.redpill.linpro.integration.Amount;
import com.redpill.linpro.service.AccountService;

public class AccountTransactionDecorator implements AccountService {

	private final AccountService accountService;

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

	private int commitCounter = 0;

	private int rollbackCounter = 0;

	public AccountTransactionDecorator(AccountService accountService) {
		this.accountService = accountService;
	}

	@Override
	public boolean transferAmount(Amount amount, Account debetAccount,
			Account creditAccount) {
		final boolean transferred;

		logger.debug("Begin transaction");

		try {
			transferred = accountService.transferAmount(amount, debetAccount, creditAccount);
			commitCounter++;
			logger.debug("Commit transaction");
		} catch (RuntimeException e) {
			rollbackCounter++;
			logger.debug("Rollback transaction");
			throw e;
		}
		return transferred;
	}

	public int getCommitCounter() {
		return commitCounter;
	}

	public int getRollbackCounter() {
		return rollbackCounter;
	}
}

The decorator must implement the business interface like the business implementation above. Then it must have a reference to the interface. This enables the decorator to call the next decorator/service recursively. The decorator doesn’t know if the reference to the interface is to the implementation or to another decorator. Only the factory method knows that. This enables loose coupling and the ability to add behaviour to your service with only a configuration change. The decorator adds behaviour before and after the service is executed. And if a RuntimeException is throwed back, it will be catched and a roll back will be simulated. With normal execution, the decorator will simulate a commit like you can see in the log message above.

An implementation that uses the decorator pattern, should also use the factory pattern. In this example the factory logic is in the constructor of the test class. The important part in this factory method is that the accountService instance points to the transaction decorator object. And that the transaction decorator is instantiated with a reference to the business implementation.

private final AccountService accountService;

public AccountServiceWithTransactionDecoratorTest() {
	accountRepositoryStub = new AccountRepositoryStub();

	// Basic service
	AccountService basicAccountService = new AccountServiceImpl(accountRepositoryStub);

	// Decorator
	accountTransactionDecorator = new AccountTransactionDecorator(basicAccountService);

	// The decorated service
	accountService = accountTransactionDecorator;
}

If the accountService instance had pointed to the business implementation instead of the decorator, then no transaction logic would have been executed.

The last part of this decorator example is the JUnit test. As you can see from the highlighted code, the test doesn’t know about the implementation or any decorators. It just executes the transferAmount() method on the accountService instance. And this instance is declared to be of the interface type.

@Test
public void testTransferAmount() {
	Amount amount = new Amount(50);
	Account debetAccount = new Account("1");
	Account creditAccount = new Account("2");

	boolean transferred = accountService.transferAmount(amount, debetAccount, creditAccount);

	assertTrue(transferred);
	assertEquals(1, accountTransactionDecorator.getCommitCounter());
}

Transaction handling with aspect

Spring Aspects supports Spring AOP (Dynamic Objects and CGLIB) and AspectJ. Both alternatives support the AspectJ syntax. AspectJ is more powerful while Spring AOP is easier to use together with the Spring container. In this interceptor example I will use AspectJ. This is because it also works without the Spring container. I’m using compile-time weaving for simplicity, since STS will do the weaving for me with the AJDT plugin and an AspectJ nature on the project.

An aspect doesn’t need to know anything about the class it will modify. All that’s necessary is to know the joinpoint where the extra functionality should be added. In this example the pointcut will be the @Transactional annotation which is showed here:

@Transactional
public boolean transferAmount(final Amount amount,
		final Account debetAccount, final Account creditAccount) { .. }

To enable AspectJ functionality with Java annotations, the @Aspect annotation must be above the class name with the AspectJ logic. Further, you have to declare the pointcut in a new annotation like this:

@Pointcut("execution(@org.springframework.transaction.annotation.Transactional * *(..))")
public void transactionalMethod() {}

A pointcut doesn’t add anything without advices. The three advises below supports the transaction handling example:

@Before("transactionalMethod()")
public void beforeTransactionalMethod(JoinPoint joinPoint) {
	transactionService.beginTransaction();
}

@AfterReturning("transactionalMethod()")
public void afterTransactionalMethod(JoinPoint joinPoint) {
	transactionService.commit();
}

@AfterThrowing(pointcut = "transactionalMethod()")
public void afterThrowingFromTransactionalMethod(JoinPoint joinPoint) {
	transactionService.rollback();
}

All the advises delegates to an instance of TransactionService. The last advice doesn’t swallow the exception, but throws it further after the rollback functionality is executed. The link below shows the TransactionAspect:

package com.redpill.linpro.transaction;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;

import com.redpill.linpro.transaction.impl.TransactionServiceNull;

@Aspect
public class TransactionAspect {

	private TransactionService transactionService = new TransactionServiceNull();

	@Pointcut("execution(@org.springframework.transaction.annotation.Transactional * *(..))")
	public void transactionalMethod() {}

	@Before("transactionalMethod()")
	public void beforeTransactionalMethod(JoinPoint joinPoint) {
		transactionService.beginTransaction();
	}

	@AfterReturning("transactionalMethod()")
	public void afterTransactionalMethod(JoinPoint joinPoint) {
		transactionService.commit();
	}

	@AfterThrowing(pointcut = "transactionalMethod()", throwing = "e")
	public void afterThrowingFromTransactionalMethod(JoinPoint joinPoint, RuntimeException e) {
		transactionService.rollback();
	}

	public void setTransactionService(final TransactionService transactionService) {
		this.transactionService = transactionService;
	}
}

If you have enabled AspectJ nature on the Eclipse project, then you should see an orange arrow to the left of the transferAmount(..) method name.

transfer-amount-ajdt-support

In the factory method in the JUnit test, the difference between this method and the decorator test is that the accountService instance doesn’t know about the aspect and the aspect doesn’t know about the AccountService implementation. In this case, the transaction logic will be weaved in at compile-time with the AspectJ compiler.

public AccountServiceWithTransactionAspectTest() {
	accountRepositoryStub = new AccountRepositoryStub();

	accountService = new AccountServiceImpl(accountRepositoryStub);

	transactionServiceStub = new TransactionServiceStub();
	TransactionAspect transactionAspect = Aspects.aspectOf(TransactionAspect.class);
	transactionAspect.setTransactionService(transactionServiceStub);
}

The test class consist of two test methods. The first test method asserts that the normal flow works and the output from the log can be seen here:

DEBUG [com.redpill.linpro.transaction.impl.TransactionServiceStub] - <Begin transaction>
INFO  [com.redpill.linpro.service.impl.AccountServiceImpl] - <Amount [amount=50] was transferred from Account [accountNumber=1] to Account [accountNumber=2]>
DEBUG [com.redpill.linpro.transaction.impl.TransactionServiceStub] - <Commit transaction>

The other test try to transfer to an invalid account which should cause an exception. The after throwing advice should roll back the transaction which the log indicates:

DEBUG [com.redpill.linpro.transaction.impl.TransactionServiceStub] - <Begin transaction>
DEBUG [com.redpill.linpro.transaction.impl.TransactionServiceStub] - <Rollback transaction>

Transaction handling with Spring

With Spring it’s possible to add declarative transaction handling with Spring AOP and AspectJ. This example will use the default Spring AOP, since it’s the simplest and most used alternative.

The default way to add transaction support with Spring and Java 5 or better is to annotate the transactional methods with @Transactional. This alternative requires the element in the configuration. It’s higlighted below. This element requires a transaction manager that implements Spring’s PlatformTransactionManager interface. The example uses just a stub implementation. The component-scan elements below finds all the Spring beans annotated with a specialization of the @Component annotation.

<context:component-scan base-package="com.redpill.linpro.service" />
<context:component-scan base-package="com.redpill.linpro.integration.stub" />

<tx:annotation-driven />

<bean id="transactionManager" class="com.redpill.linpro.transaction.impl.PlatformTransactionManagerStub" />

The most used implementations of the PlatformTransactionManager is DataSourceTransactionManager for JDBC, JpaTransactionManager, HibernateTransactionManager and JtaTransactionManager. The stub implementation used in this example just counts and logs every time a method in the interface are executed. Below are the overriden interface methods in the stub implementation:

@Repository
public class PlatformTransactionManagerStub implements PlatformTransactionManager {

	@Override
	public void commit(TransactionStatus status) throws TransactionException {
		commitTransactionCounter++;
		logger.debug("Commit transaction");
	}

	@Override
	public TransactionStatus getTransaction(TransactionDefinition definition)
                        throws TransactionException {
		beginTransactionCounter++;
		logger.debug("Begin transaction");
		return new SimpleTransactionStatus();
	}

	@Override
	public void rollback(TransactionStatus status) throws TransactionException {
		rollbackTransactionCounter++;
		logger.debug("Rollback transaction");
	}
}

The test below demonstrates how to instantiate the Spring container with annotations and how to inject Spring beans into class variables. Further it executes the transferAmount(..) method on the accountService instance. This instance is of AccountServiceImpl type because the component-scan element in the configuration found the @Service annotation above that class and the class implements the AccountService interface. It doesn’t know about any aspects. And in this case with Spring AOP, the transaction logic will be added at runtime. No extra compiler or JVM agent is required.

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration("stub-config.xml")
public class AccountServiceWithTransactionManagerStubTest {

@Inject
private AccountService accountService;

@Inject
private PlatformTransactionManagerStub platformTransactionManagerStub;

@Test
public void testTransferAmount() {
Amount amount = new Amount(50);
Account debitAccount = new Account("1");
Account creditAccount = new Account("2");

boolean transferred = accountService.transferAmount(amount, debitAccount, creditAccount);

assertTrue(transferred);
assertEquals(1, platformTransactionManagerStub.getBeginTransactionCounter());
assertEquals(0, platformTransactionManagerStub.getRollbackTransactionCounter());
assertEquals(1, platformTransactionManagerStub.getCommitTransactionCounter());
}

@Test
public void testTransferAmountThatShouldRollback() {..}
}

The test prints the following to the log:

DEBUG [com.redpill.linpro.transaction.impl.PlatformTransactionManagerStub] - <Begin transaction>
INFO  [com.redpill.linpro.service.impl.AccountServiceImpl] - <Amount [amount=50] was transferred from Account [accountNumber=1] to Account [accountNumber=2]>
DEBUG [com.redpill.linpro.transaction.impl.PlatformTransactionManagerStub] - <Commit transaction>

Transaction handling with Spring and database

In all the examples so far in this tutorial, I have used stub implementations for the transaction handling and only simulated a repository with another stub. In this last example, I will use plain JDBC against HSQL database and a DataSourceTransactionManager.

First, the respository stub is replaced with this:

@Repository
public class AccountRepositoryImpl implements AccountRepository {

	@Inject
	private SimpleJdbcTemplate jdbcTemplate;

	private final String GET_BALANCE_SQL =
                "select BALANCE from ACCOUNT where ACCOUNT_NUMBER = ?";

	private final String UPDATE_AMOUNT_SQL =
                "update ACCOUNT set BALANCE = BALANCE + ? where ACCOUNT_NUMBER = ?";

	private final String VALIDATE_ACCOUNT_EXIST_SQL =
                "select count(*) from ACCOUNT where ACCOUNT_NUMBER = ?";

	@Override
	public Amount getBalance(Account account) {
		int balance = jdbcTemplate.queryForInt(GET_BALANCE_SQL, account.getAccountNumber());
		return new Amount(balance);
	}

	@Override
	public void updateBalance(Amount balance, Account account) {
		jdbcTemplate.update(UPDATE_AMOUNT_SQL, balance.getAmount(), account.getAccountNumber());
	}

	public boolean isAccountExisting(final Account account) {
		int accountsWithAccountNumber = jdbcTemplate.queryForInt(VALIDATE_ACCOUNT_EXIST_SQL,
                         account.getAccountNumber());
		return (accountsWithAccountNumber == 1 ? true : false);
	}
}

Second, the configuration must contain a DataSourceTransactionManager, a data source and the AccountRepository implementation above.

<context:component-scan base-package="com.redpill.linpro.service" />
<context:component-scan base-package="com.redpill.linpro.integration.db" />

<tx:annotation-driven />

<bean id="transactionManager"
	class="org.springframework.jdbc.datasource.DataSourceTransactionManager">
	<property name="dataSource" ref="dataSource" />
</bean>

jdbc.core.simple.SimpleJdbcTemplate">
	<constructor-arg ref="dataSource" />
</bean>

<jdbc:embedded-database id="dataSource" type="HSQL">
 	<jdbc:script location="classpath:com/redpill/linpro/integration/db/schema.sql"/>
 	<jdbc:script location="classpath:com/redpill/linpro/integration/db/data.sql"/>
 </jdbc:embedded-database>

The test below asserts that the balance on the debit account is the same after the roll back as it was before the transaction

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration({"config.xml", "../integration/db/database-config.xml"})
public class AccountServiceWithSpringTest {

	@Inject
	private AccountService accountService;

	@Inject
	private AccountRepository accountRepository;

	@Test
	public void testTransfer() {..}

	@Test
	public void testTransferWithInvalidCreditAccount() {
		Amount amount = new Amount(100);
		Account debetAccount = new Account("789");
		Account creditAccount = new Account("INVALID");

		try {
			accountService.transferAmount(amount, debetAccount, creditAccount);
			fail("transferAmount() should have throwed exception.");
		} catch (IllegalArgumentException e) {
			Amount debetBalanceAfterTransfer = accountRepository.getBalance(debetAccount);
			assertEquals(new Amount(100), debetBalanceAfterTransfer);
		}
	}
}

Summary

The Decorator pattern and aspect technologies enables enterprise functionality without an application container and boilerplate code in your business logic.The simplest solution if you’re already are familiar with an application container is to delegate the enterprise functionality to the container like the last two examples in this tutorial.

The coded used in this article was developed in my work time at Redpill Linpro. It can be downloaded from: http://samplecode-espenberntsen.googlecode.com/svn/enterprise.functionality/trunk/


Redpill Linpro is the leading provider of Professional Open Source services and products in the Nordic region.

Written by Espen

April 1, 2010 at 15:21