Java and Spring development

SLF4J logging with Log4J and JCL

with 5 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

Declaratively add enterprise functionality

leave a 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

@AspectJ cheat sheet

with 9 comments

This cheat sheet uses AspectJ’s @AspectJ style. It’s also possible to use the original AspectJ syntax like this example demonstrates, but I prefer to use standard Java classes with the AspectJ logic inside annotations.

Pointcuts

The definition of a pointcut from the AspectJ homepage:

A pointcut is a program element that picks out join points and exposes data from the execution context of those join points. Pointcuts are used primarily by advice. They can be composed with boolean operators to build up other pointcuts.

A pointcut example:

Pointcut designators

A method pointcut:

@Pointcut("[method designator](* aspects.trace.demo.*.*(..))")
public void traceMethodsInDemoPackage() {}
  • call – The pointcut will find all methods that calls a method in the demo package.
  • execution – The pointcut will find all methods in the demo package.
  • withincode – All the statements inside the methods in the demo package.

A type pointcut:

@Pointcut("[type designator](*..*Test)")
public void inTestClass() {}
  • within – all statements inside the a class that ends with Test.

A field pointcut:

@Pointcut("[field designator](private org.springframework.jdbc.core.JdbcTemplate " +
       "integration.db.*.jdbcTemplate)")
public void jdbcTemplateGetField() {}
  • get – all reads to jdbcTemplate fields of type JdbcTemplate in the integration.db package. Includes all methods on this field if it’s an object.
  • set – when you set the jdbcTemplate field of type JdbcTemplate in the integration.db package to a new value.

Signature pointcuts

This chapter explains more advanced signature pointcuts than illustrated on the image above.

Support for sub packages is provided with “..”:

@Pointcut("within(*..*Test)")
public void inTestClass() {}

To find the joinpoints inside a type that ends with Test inside the ..demo package:

@Pointcut("within(com.redpill.linpro.demo..*Test)")
public void inDemoProjectTestClass() {}

All statements inside all classes except test classes in the ..demo package with the “!” before the designator:

@Pointcut("!within(com.redpill.linpro.demo..*Test)")
public void notInDemoProjectTestClass() {}

All methods in the Service class or a subtype of it:

@Pointcut("execution(void *..service.Service+.*(..))")
public void servicePointcut() {}

All getCoffeeType methods in a class that begins with CoffeeTypeRepository:

@Pointcut("execution(CoffeeType integration.db.CoffeeTypeRepository*.getCoffeeType(CoffeeTypeName))" +
    " && args(coffeeTypeName)")
public void getCoffeeTypePointcut(CoffeeTypeName coffeeTypeName) {}

Note that the pointcut also contains args(coffeeTypeName) and that the Java method has a method with a CoffeeTypeName as input parameter. An advice that advices this pointcut must also have this input parameter.

This field pointcut finds all the places in the integration package where a field named jdbcTemplate gets a new value of type JdbcOperations or a subtype of it like JdbTemplate.

@Pointcut("set(private org.springframework.jdbc.core.JdbcOperations+ " +
    "integration..*.jdbcTemplate)")
public void jdbcTemplateSetField() {}

Annotation pointcuts

A pointcut can declare an annotation before the signature pattern.

An example of an annotation used as a marker interface:

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface PerformanceLogable {}

All it does is to provide meta information to methods.

A pointcut that finds all methods marked with the @PerformanceLogable on the classpath:

@Pointcut("execution(@aspects.log.performance.PerformanceLogable * *(..))")
public void performanceLogableMethod() {}

The @Transactional annotation supports both method and type target. Which means it can be used with both method and type designators. The pointcut below is the same as the performanceLogableMethod pointcut, except it finds methods with Spring’s @Transactional annotation.

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

A pointcut that finds all constructors marked with @Inject and have an integer as input parameter:

@Pointcut("execution(@javax.inject.Inject *.new(Integer)) && args(integer)")
public void constructorAnnotatedWithInjectAndIndemoPackage(Integer integer) {}

The @Service annotation has target set to type and can therefore only annotate types. The pointcut below will find all statements in all types marked with @Service.

@Pointcut("within(@org.springframework.stereotype.Service *)")
public void serviceBean() {}

The joinpoint will be all statements inside a type marked with the @Component annotation or a specialization of it:

@Pointcut("within(@(@org.springframework.stereotype.Component *) *)")
public void beanAnnotatedWithComponentOrASpecializationOfIt() {}

Finds all statements that’s not inside a method marked with @Test:

@Pointcut("!withincode(@org.junit.Test * *(..))")
public void notInTestMethod() {}

Finds all methods with one or more parameters marked with the @MyParamAnnotation:

@Pointcut("execution(public * *(.., @aspects.MyParamAnnotation (*), ..))")
public void methodWithAnnotationOnAtLeastOneParameter() {}

For a full example with explanations, see this post.

A pointcut with a runtime condition and a required public static method:

@Pointcut("execution(* *.actionPerformed(java.awt.event.ActionEvent)) " +
		"&& args(actionEvent) && if()")
public static boolean button1Pointcut(ActionEvent actionEvent) {
	return (actionEvent.getSource() == j1);
}

More information can be found in this post

Combining pointcuts

Instead of having a large pointcut, it’s a much better approach to combine several pointcuts into one.

@Pointcut("traceMethodsInDemoPackage() && notInTestClass() && notSetMethodsInTraceDemoPackage()")
public void filteredTraceMethodsInDemoPackage() {}

Advices

The definition from the AspectJ homepage:

A piece of advice brings together a pointcut and a body of code to define aspect implementation that runs at join points picked out by the pointcut.

An advice can be executed before, after, after returning, after throwing or around the joinpoint.

The before advice below is executed before the target method specified in filteredTraceMethodsInDemoPackage pointcut:

@Before("filteredTraceMethodsInDemoPackage()")
public void beforeTraceMethods(JoinPoint joinPoint) {
	// trace logic ..
}

This after advice is executed after the target method.

@After("filteredTraceMethodsInDemoPackage()")
public void afterTraceMethods(JoinPoint joinPoint) {
	// trace logic ..
}

The afterThrowing advice will be executed if the method that matches the pointcut throws an exception. You can also declare the Exception and handle it like this:

@AfterThrowing(value="serviceMethodAfterExpcetionFromIntegrationLayerPointcut()", throwing="e")
public void serviceMethodAfterExceptionFromIntegrationLayer(JoinPoint joinPoint,
                RuntimeException e) {
	StringBuilder arguments = generateArgumentsString(joinPoint.getArgs());

	logger.error("Error in service " + joinPoint.getSignature() + " with the arguments: " +
			arguments, e);
}

The AfterReturning advice will only be executed if the adviced method returns successfully.

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

The around advice is quite powerful, but also consumes more resources and should only be used if you can’t make it work with other advices. The example below simulates some logic before and after the adviced method. The ProceedingJoinPoint extends the JoinPoint class and is required to call the adviced method with the proceed() method.

@Around("performanceLogablePointcut()")
public void aroundPerformanceLogableMethod(ProceedingJoinPoint point) {

    // Pre processing work..

    point.proceed();

    // Post processing work..
}

Note: You don’t need an around advice to monitor the execution time for a method. It’s just the simplest option and therefore used in this example.

The advice below combines two pointcuts and the last one has an integer object as input parameter. This requires the Java method to also have an integer parameter. It enables the advice logic to access the input parameter directly and in a type safe manner. A less elegant alternative is to access the parameter with the joinPoint’s getArgs() method.

@AfterReturning("beanAnnotatedWithComponentOrASpecializationOfIt() &&  " +
	"constructorAnnotatedWithInjectAndIndemoPackage(integer)")
public void afterReturningFromConstructorInSpringBeanWithIntegerParameter(
		JoinPoint joinPoint, Integer integer) {

	// Advice logic..
}

Summary

This cheat sheet consist of many simple pointcuts. Often you have to combine them to add value to your application. This example article combines pointcuts with a class marked with @Service and a constructor and method marked with @Inject. It also filters away the test method with the @Test annotation.

The code used in this article was developed in my work time at Redpill Linpro.


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

Written by Espen

March 20, 2010 at 18:28

Posted in Aspects

Tagged with , , ,

@AspectJ examples with pointcuts based on annotations

with 5 comments

This example demonstrates how to trace methods, constructors and fields annotated with @Inject and that’s inside a class annotated with @Component or a specialization of it like @Service. The aspect has three advices that combines different pointcuts. All the pointcuts uses primary marker interfaces (annotations) to determine where to place the adviced code. The annotations used in the pointcuts have target set to either method or type.

The example consist of a Demo class, a TraceAspect, a Spring configuration file and a JUnit test. The test starts the Spring container and the container injects all fields, methods and constructors in the Demo and DemoTest classes annotated with @Inject. It’s this dependency injection that the aspect will monitor and trace. The last part is when the test method calls the toString() method on the demo object and the toString() method reads the value in the text field. This get operation on the field is also monitored and traced by the aspect.

The Demo class

The Demo class has a text field that’s impossible to advice when the field gets set, since the Spring container injects the value with reflection and it’s no places in the code that sets this field. But it’s possible to advice the toString() method that reads this field. The constructor and method annotated with @Inject are adviced after they have returned successfully.

package demo;

import javax.inject.Inject;
import javax.inject.Named;

import org.springframework.stereotype.Service;

@Service
public class Demo {

	@Inject
	private String text;

	private final Integer integerOne;

	private Integer integerTwo;

	@Inject
	@Named("integerOne")
	public Demo(final Integer integerOne) {
		this.integerOne = integerOne;
	}

	@Inject
	@Named("integerTwo")
	public void setintegerTwo(final Integer integerTwo) {
		this.integerTwo = integerTwo;
	}

	@Override
	public String toString() {
		return "Demo [integerOne=" + integerOne + ", integerTwo=" + integerTwo
				+ ", text=" + text + "]";
	}
}

A screenshot from STS with AspectJ nature enabled:

adviced-demo-class

The first two orange arrows shows the joinpoint for two afterReturn advices, while the last one show the joinpoint for an around advice.

The TraceAspect class

Briefly summarized, the aspect below traces all methods and constructors in the demo package annotated with @Inject and that’s inside a type annotated with @Component or a specialization of it. Further, it demonstrates how to declare a pointcut with or without @args(..). The last advice is an around advice that traces all String fields annotated with @Inject in the demo package. It also prints out the return value.

package demo;

import javax.inject.Inject;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.junit.Test;
import org.springframework.stereotype.Component;
import org.springframework.stereotype.Repository;
import org.springframework.stereotype.Service;

/**
 * An example aspect that shows how to write pointcuts for annotated fields, methods and
 * types and how to advice those aspects.
 *
 * <p>
 * <ul>
 * 	<li>annotation target set to method</li>
 *
<ul>
	<li>{@link Inject @Inject}, {@link Test @Test}</li>
</ul>
 *  <li>annotation target set to type</li>
 *
<ul>
	<li>{@link Component @Component} or a specialization of it</li>
</ul>
 *  	({@link Service @Service}, {@link Repository @Repository})
 * </ul>
 *
 * @author Espen Berntsen
 * @see Demo
 */
@Aspect
public class TraceAspect {

	// Trace injected methods and constructors -->
	@Pointcut("within(@(@org.springframework.stereotype.Component *) *)")
	public void beanAnnotatedWithComponentOrASpecializationOfIt() {}

	@Pointcut("execution(@javax.inject.Inject * demo.*.*(..))")
	public void methodAnnotatedWithInjectAndInDemoPackage() {}

	@Pointcut("execution(@javax.inject.Inject demo.*.new(Integer)) && args(integer)")
	public void constructorAnnotatedWithInjectAndIndemoPackage(
			Integer integer) {}

	// With args(integer).
	@AfterReturning("beanAnnotatedWithComponentOrASpecializationOfIt() &&  " +
			"constructorAnnotatedWithInjectAndIndemoPackage(integer)")
	public void afterReturningFromConstructorInSpringBeanWithIntegerParameter(
			JoinPoint joinPoint, Integer integer) {
		System.out.println("Executed @Injected constructor: "
				+ joinPoint.getSignature() + " with the integer: " + integer);

	}

	// Using joinPoint.getArgs() to show arguments.
	@AfterReturning("beanAnnotatedWithComponentOrASpecializationOfIt() &&  " +
			"methodAnnotatedWithInjectAndInDemoPackage()")
	public void afterReturningFromMethodInSpringBean(JoinPoint joinPoint) {
		System.out.print("Executed the @Injected method: "
				+ joinPoint.getSignature() + " with value(s): ");

		for (Object object : joinPoint.getArgs()) {
			System.out.print(object);
		}
		System.out.println();
	}
	// Trace injected methods and constructors <--

	// Trace get on String fields annotated with @Inject -->
	@Pointcut("get(@javax.inject.Inject java.lang.String demo..*.*)")
	public void getStringFieldAnnotatedWithInjectInTheDemoPackage() {}

	@Pointcut("!withincode(@org.junit.Test * demo..*(..))")
	public void notInTestMethod() {}

	@Pointcut("getStringFieldAnnotatedWithInjectInTheDemoPackage() && notInTestMethod()")
	public void getStringFieldAnnotatedWithInjectInTheDemoPackageAndNotInTestMethod() {}

	@Around("getStringFieldAnnotatedWithInjectInTheDemoPackageAndNotInTestMethod()")
	public String aroundGetStringFieldAnnotatedWithInjectInTheDemoPackageAndNotInTestMethod(
			ProceedingJoinPoint joinPoint) throws Throwable {

		String fieldValue = (String) joinPoint.proceed();
		System.out.println("Get on @Inject String field: "
				+ joinPoint.getSignature() + " with value: " + fieldValue);
		return fieldValue;
	}
	// Trace get on String fields annotated with @Inject <--
}

The Spring configuration file

The configuration file below contains a component-scan element that finds the Demo class because it’s annotated with @Service. The three other beans are injected into the demo bean’s field, constructor and method marked with @Inject. This is enabled with the component-scan or annotation-config element in the context namespace. Since it’s two integers, the method and constructor in the Demo class also have an @Named(..) annotation with a value equal to the bean id that’s injected.

<?xml version="1.0" encoding="UTF-8"?>
xmlns="http://www.springframework.org/schema/beans"
	xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xmlns:context="http://www.springframework.org/schema/context"
	xsi:schemaLocation="http://www.springframework.org/schema/beans

http://www.springframework.org/schema/beans/spring-beans-3.0.xsd


http://www.springframework.org/schema/context


http://www.springframework.org/schema/context/spring-context-3.0.xsd">

	<context:component-scan base-package="demo" />

	<bean id="a" class="java.lang.String" factory-method="valueOf">
		<constructor-arg value="test" />
	</bean>

	<bean id="integerOne" class="java.lang.Integer" factory-method="valueOf">
		<constructor-arg value="1" />
	</bean>

	<bean id="integerTwo" class="java.lang.Integer" factory-method="valueOf">
		<constructor-arg value="2" />
	</bean>
</beans>

The test class

Finally, the test class that instantiates the Spring container executes the toString() method on the demo object. If you’re not familiar with Spring, you can replace the Spring configuration with a factory method in the test class instead as long as you’re setting the @Inject field, constructor and method.

package demo;

import javax.inject.Inject;

import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;

/**
 * Should have been a main method, but I use the
 * {@link Test} annotation to demonstrate withincode designator
 * {@link TraceAspect#beanAnnotatedWithComponentOrASpecializationOfIt()}
 *
 * @author Espen Berntsen
 *
 */
@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(&quot;config.xml&quot;)
public class DemoTest {

	@Inject
	private Demo demo;

	@Test
	public void testToString() {
		System.out.println(&quot;demo.toString(): &quot; + demo.toString());
	}
}

The console output after executing the test class:

Executed @Injected constructor: demo.Demo(Integer) with the integer: 1
Executed the @Injected method: void demo.Demo.setintegerTwo(Integer) with value(s): 2
Get on @Inject String field: String demo.Demo.text with value: test
demo.toString(): Demo [integerOne=1, integerTwo=2, text=test]

Summary

Annotations are very good pointcuts and are frequently used by application containers to add enterprise features. See also this cheat sheet for more information about how to write aspects with @AspectJ style.

The code used in this article was developed in my work time at Redpill Linpro.


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

Written by Espen

March 18, 2010 at 22:28

Posted in Aspects

Tagged with , , , ,

Monitoring a web application with tcServer developer edition

with 8 comments

The tcServer developer edition is a Tomcat server with monitor support. The monitor support is provided through a tcServer template called Spring insight. The template is a web application. The monitor data from your application are gathered with AspectJ load-time weaving, stored in memory and presented on the Spring insight web site deployed on the tcServer developer edition server. For local monitoring, you can find the insight application here: http://localhost:8080/insight.

The screenshot shows all the recent traffic to the demo application’s servlets. A click on one of the bars gives you access to detailed information about the requests processed in that time period.

The other view is application health. The screenshot below shows the application health for the “findBalance” web service.

The service monitored above behave quite well and Spring insight claims its health is excellent.

If you click on one of the bars, you can drill down to each response and see details for that response:

The example is from a web service and shows which parameters and return types my monitored beans are invoked with. Almost all the execution time for this request was used in the repository and you can see that the repository throwed an exception back. You can even read the exception message. If you’re using the WEB browser inside Spring Tool Suite (STS), you can also jump directly into the source code through the “Go to STS” link.

For a full introduction into monitoring with tcServer and Spring insight, you should see this presentation. It shows that you can see all the SQLs sent to the database and all the HTTP request and response messages handled by your application’s servlets.

How it works

The Spring insight application uses load-time weaving to monitor your application. Out of the box, Spring insight monitors the SQLs and HTTP request/response messages. To monitor your own classes, you have to add an @Component annotation above your class or preferably a specification like @Controller, @Service or @Repository. For Spring insight, these annotations are just marker annotations that tells AspectJ which classes to weave.

These annotations can also be used to define your Spring beans with component scanning. But it’s not related to the way Spring insight uses them since Spring insight uses them at load-time, which is before the Spring container is started (runtime).

A class that will be monitored because of the @Service annotation:

@Service
public class AccountServiceImpl implements AccountService {

Some examples

The screenshot below shows a server that increases the load with ten clients every fifth second. In the beginning, the throughput increases with a low increase in response time. With more clients the throughput still improves, but the average response time increases much more.

The last image shows the same application with the number of clients doubled every fifth second. After a while it results in bad and unstable response time. The graph isn’t 100% correct since I run the clients on the same machine as the server. But the tests indicates quite clear that this application shouldn’t have unlimited number of server threads.

You can see the response time is very unstable and Spring insight claims the application has bad health. With less server threads the application health improves.

Summary

The tcServer developer edition is an excellent choice for monitoring web applications that can run on Tomcat. With an annotation over all the classes you’re interested in monitoring, you get access to detailed information like execution time, parameters, exceptions and return types. And you’re only a click away from inspecting the code you find something interesting.

The code used in this article was developed in my work time at Redpill Linpro.


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

Written by Espen

March 9, 2010 at 19:52

Spring asynchronous support

with 3 comments

Spring 3 supports declarative concurrency support. At its simplest, you only need to specify in the Spring configuration file and add an @Async annotation above the method that you want to execute in an asynchronous process.

@Async
public void findBalanceAsync(final Account account) {
	accountRepository.findBalance(account);
}

See also this blog for step by step guide on how to execute a void method asynchronously.

In many cases you also want the response message from a method executed asynchronously. To achieve this, Spring returns a java.util.concurrent.Future object. All that’s required from the implementation is to create and return a new AsyncResult object like this:

@Async
public Future<Balance> findBalanceAsync(final Account account) {
	Balance balance = accountRepository.findBalance(account);
	return new AsyncResult<Balance>(balance);
}

Further, to retrieve the balance from this future object:

Balance balance = future.get();

If the method that’s executed asynchronously throws an exception, it will be wrapped inside an ExecutionException and throwed when the Future’s get method gets called.

Java EE 6 specification support

If you prefer to use the Java EE 6 specification, then you can replace Spring’s Async and AsyncResult classes with the corresponding classes in the javax.ejb package in the commons annotations 1.1 specification.

@javax.ejb.Asynchronous
public Future<Balance> findBalanceAsync(final Account account) {
	Balance balance = accountRepository.findBalance(account);
	return new javax.ejb.AsyncResult<Balance>(balance);
}

Configuring the task elements

The Spring container understand the javax.ejb classes without any configuration changes. You only need to add the commons annotation API on the classpath.

Spring’s task support can be configured with values like the thread pool and wich implementation you prefer to use. The easiest approach is to use the task namespace’s executor element. This element instantiates a ThreadPoolTaskExecutor object. This class implements the java.util.concurrent.Executor interface. Another option is declare your own bean like the ExecutorService bean below and let the annotation-driven task element reference to it. See example below:

<bean id="executorService" class="java.util.concurrent.Executors"
	factory-method="newFixedThreadPool">
	<constructor-arg value="10" />
</bean>

<task:executor id="threadPoolTaskExecutor" pool-size="10" />

<task:annotation-driven executor="executorService" />

Work with the underlying ExecutorService implementation

If you want to configure the ExecutorService object used by the Spring container after it’s initialized, then you can to do it programmatically as long as it’s a singleton bean. The first step is to retrieve the object with dependency injection like this:

@Inject
ExecutorService executorService;

Then cast it to a TreadPoolExecutor object and adjust the settings like the pool size showed below:

ThreadPoolExecutor threadPoolExecutor = (ThreadPoolExecutor) executorService;
threadPoolExecutor.setMaximumPoolSize(poolSize);
threadPoolExecutor.setCorePoolSize(poolSize);

An another example it can be useful to handle the underlying implementation is if you want to abort all work in the ExecutorService or ThreadPoolTaskExecutor’s queue. Then you can execute the shutdown method like this:

executorService.shutdown();

Conclusion

Spring’s asynchronous support abstracts away most of the complex threading logic for you and still provides full access to the implementation behind. It also supports the new async API in Java EE 6 without any configuration changes.

The code used in this article was developed in my work time at Redpill Linpro.


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

Written by Espen

March 8, 2010 at 00:44

Posted in Concurrency

Tagged with , , ,

Follow

Get every new post delivered to your Inbox.

Join 35 other followers