Myšlenky dne otce Fura

Nice thing about Aspect Oriented Programming is that you can easily add piece of logic to several (possibly other way not connected) parts of your application. You’ll only write an Advice (piece of code that should be weaved into original code and executed at exactly specified point of time) and define Pointcut (an expression defining which classes and methods shall be advised). Please, keep in mind, that above description is somewhat simplyfying and that AOP could be much broader than this. Describing AOP is not the aim of this post – the aim lies in something else, and that is – testing. What’s the best approach to test application logic modified in runtime (or compile time) with AOP process?

We can quite easily test the Advice – it’s a plain piece of code, that could be decomposed to several methods that could be tested and verified one by one. But what about the other part of aspect? Pointcut is hard to test – often it’s only a matter of configuration (as in Spring). So the only choice to setup more expensive integration test. While writing integration test it could be hard to test advice itself (for example how can we verify that we’ve configured Spring’s TransactionInterceptor right and that it works well?) and maybe senseless when the advice has been unit tested (as I am sure TransactionInterceptor was). In such cases it would suffice only to test that advice is properly called. But even that you can achieve with difficulty.

Checking Spring Advised interface

In Spring there is a way how to find out whether you are working with object modified by weaving process. Such objects (or better proxies) are implementing org.springframework.aop.framework.Advised interface. This interface declares method getAdvisors() that returns a list of advisors, each holding reference to a single advice. You can take advantage from this Spring’s behaviour by checking you pointcut settings.

This is presented on following example. Method testAdvice will check all beans in map for weaved advice of testedAdviceClass.

private void testAdvice(Map beans, Class testedAdviceClass) {
	Iterator it = beans.keySet().iterator();
	while(it.hasNext()) {
		String beanName = (String)it.next();
		Object strg = beans.get(beanName);
		if(strg instanceof Advised) {
			Advised advised = ((Advised)strg);
			Advisor[] advisors = advised.getAdvisors();
			boolean transactionAdvice = false;
			for(int i = 0; i < advisors.length; i++) {
				Advisor advisor = advisors[i];
				if(testedAdviceClass.isAssignableFrom(advisor.getAdvice().getClass())) {
					transactionAdvice = true;
				}
			}
			assertTrue(beanName + " has no " + testedAdviceClass.getName() + " advice on it.", transactionAdvice);
		}
		else {
			fail(beanName + " is not Advised!");
		}
	}
}

This approach is valid only for Spring and cannot be used in other environments. Next disadvantage of this test logic is that you can verify only presence of advice on a object (class respectivelly). It cannot ensure you that advice will participate in a particular method call.

Using logging facility for verification of pointcuts

Other approach could be to use standard logging facility (such as Java Logging, SL4J or Log4J) for checking whether particular piece of code was executed or not. Assuming that every class has its internal log calls, we could check out if advice participated in our business object call. Beauty of this solution is that it doesn’t require special test setup – it could be part of standard integration test that you should have in anyway.

Let’s take Spring declarative transaction management as our example. We don’t have to test whether Spring’s TransactionInterceptor works well – it was tested by Rod Johnson and Juergen Hoeller. But we should test integration of this advice with our business logic. If we look into TransactionInterceptor code we can see that it calls TransactionAspectSupport when dealing with transaction. Examining further the code (or logging output) we can see that when opening transaction Spring logs:

Getting transaction for [className.methodName]

When completing transaction (commit or rollback – example in the same order) it logs:

Completing transaction for [className.methodName]
Completing transaction for [className.methodName] after exception

Easiest form of such test could be as follows (test uses custom appender implementation TestAppender, that just holds log events in memory):

public void testCreateUserWithProperties() throws Exception {
	if(log.isInfoEnabled()) {
		log.info("***************************************************************");
		log.info("      SWITCHING TO TEST CONTROLLED LOGGING ENVIRONMENT         ");
		log.info("***************************************************************");
	}
	LogManager.resetConfiguration();
	Logger logger = LogManager.getLogger(TransactionInterceptor.class.getName());
	logger.setLevel(Level.TRACE);
	logger.addAppender(testAppender);

	//this executes real integration test
	super.testCreateUserWithProperties();
        //there we just verify that expected logs have been recorded
	assertTrue(testAppender.containsLogRecord("Getting transaction for [cz.novoj.business.UserManager.createUserWithProperties]"));
	assertTrue(testAppender.containsLogRecord("Completing transaction for [cz.novoj.business.UserManager.createUserWithProperties]"));
}

This example represents the idea (I hope) in quite understandable way, but for real usage I would recommend different test implementation. We have to consider, that logging certainly isn’t part of class API but it belongs to class internals that could be changed any time without notice. So if we would create dozens of tests of this type, it could costs us a lot of time to adapt tests when log messages change. Keeping object oriented approach I would recommend creating special Appender implementation for each Advice that encapsulates log checking logic.

Let’s create base class that will contain all common test logic:

/**
 * Base test appender used to capture logging events for test purposes.
 *
 * @author Jan Novotný
 * @version $Id: $
 */
public class TestAppender extends AppenderSkeleton {
	private static Log log = LogFactory.getLog(TestAppender.class);
	private final Class[] monitoredClasses;
	private final LoggerInfo[] backedUpLoggers;
	private final List<LoggingEvent> events = new ArrayList<LoggingEvent>();

	public TestAppender(Class monitoredClass) {
		this(new Class[] {monitoredClass});
	}

	public TestAppender(Class[] monitoredClasses) {
		super();
		this.monitoredClasses = monitoredClasses;
		if(log.isInfoEnabled()) {
			log.info("***************************************************************");
			log.info("        APPENDING TEST CONTROLLED LOGGING ENVIRONMENT          ");
			log.info("***************************************************************");
		}
		backedUpLoggers = new LoggerInfo[monitoredClasses.length];
		for(int i = 0; i < monitoredClasses.length; i++) {
			Class monitoredClass = monitoredClasses[i];
			Logger logger = LogManager.getLogger(monitoredClass);
			backedUpLoggers[i] = new LoggerInfo(logger.getLevel(), logger.getAdditivity());
			logger.setLevel(Level.TRACE);
			logger.addAppender(this);
			logger.setAdditivity(true);
		}
	}

	public void clearLogChanges() {
		for(int i = 0; i < monitoredClasses.length; i++) {
			Class monitoredClass = monitoredClasses[i];
			Logger logger = LogManager.getLogger(monitoredClass);
			logger.setLevel(backedUpLoggers[i].getOriginalLevel());
			logger.setAdditivity(backedUpLoggers[i].isOriginalAdditivity());
			logger.removeAppender(this);
		}
		if(log.isInfoEnabled()) {
			log.info("***************************************************************");
			log.info("         REMOVED TEST CONTROLLED LOGGING ENVIRONMENT           ");
			log.info("***************************************************************");
		}
	}

	protected void append(LoggingEvent event) {
		synchronized(events) {
			events.add(event);
			System.out.println(">>> Capturing : " + event.getMessage());
		}
	}

	public int countLogRecord(String messagePart) {
		int counter = 0;
		for(LoggingEvent event : events) {
			String message = (String)event.getMessage();
			if(message != null && message.indexOf(messagePart) > -1) {
				counter ++;
			}
		}
		return counter;
	}

	public int countExactLogRecord(String comparedMessage) {
		int counter = 0;
		for(LoggingEvent event : events) {
			String message = (String)event.getMessage();
			if(message != null && message.equals(comparedMessage)) {
				counter ++;
			}
		}
		return counter;
	}

	public boolean containsLogRecord(String messagePart) {
		return countLogRecord(messagePart) > 0;
	}

	public boolean containsSingleLogRecord(String messagePart) {
		return countLogRecord(messagePart) == 1;
	}

	public boolean containsExactLogRecord(String completeMessage) {
		return countExactLogRecord(completeMessage) > 0;
	}

	public boolean containsExactSingleLogRecord(String completeMessage) {
		return countExactLogRecord(completeMessage) == 1;
	}

	public void close() {
		events.clear();
		clearLogChanges();
	}

	public boolean requiresLayout() {
		return false;
	}

	private class LoggerInfo {
		Level originalLevel;
		boolean originalAdditivity;

		public LoggerInfo(Level originalLevel, boolean originalAdditivity) {
			this.originalLevel = originalLevel;
			this.originalAdditivity = originalAdditivity;
		}

		public Level getOriginalLevel() {
			return originalLevel;
		}

		public boolean isOriginalAdditivity() {
			return originalAdditivity;
		}
	}

}

Then we will create specialized descendants testing log output of particular interceptors. This one for example checks output of standard Spring TransactionInterceptor advice (as we discussed above):

/**
 * Log4J appender optimalized to check Spring transaction operations being processed.
 *
 * @author Jan Novotný, FG Forrest a.s. (c) 2007
 * @version $Id: $
 */
public class SpringTransactionTestAppender extends TestAppender {

	public SpringTransactionTestAppender() {
		super(TransactionInterceptor.class);
	}

	public boolean isTransactionOpened(Class forClass, String forMethod) {
		return containsExactSingleLogRecord("Getting transaction for [" + forClass.getName() + "." + forMethod + "]");
	}

	public boolean isTransactionCommited(Class forClass, String forMethod) {
		return containsExactSingleLogRecord("Completing transaction for [" + forClass.getName() + "." + forMethod + "]");
	}

	public boolean isTransactionRollbacked(Class forClass, String forMethod) {
		return containsSingleLogRecord("Completing transaction for [" + forClass.getName() + "." + forMethod + "] after exception");
	}

}

Our test then will look like this (can you see the simplicity?!):

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(
		locations = {
				"classpath:spring/spring-datasource.xml",
				"classpath:spring/spring-dao.xml",
				"classpath:spring/spring-business.xml",
				"classpath:spring/spring-transaction.xml"
				},
		loader = HostConfigurableContextLoader.class
)
@Transactional
public class UserManagerIntegrationTest extends UserManagerTest {
	@Autowired(required = true)
	UserManager userManager;
	SpringTransactionTestAppender transactionTestAppender;

	@Before
	public void initLogger() {
		transactionTestAppender = new SpringTransactionTestAppender();
	}

	@After
	public void closeLogger() {
		transactionTestAppender.close();
	}

	@Test
	public void testCreateUserWithPropertiesTransaction() throws Exception {
                //again we run our integration test
		super.testCreateUserWithProperties();

                //and now we verify, that opening and closing transaction operations were made by the TransactionInterceptor
		String methodName = "createUserWithProperties";
		assertTrue(transactionTestAppender.isTransactionOpened(UserManager.class, methodName));
		assertTrue(transactionTestAppender.isTransactionCommited(UserManager.class, methodName));
		assertFalse(transactionTestAppender.isTransactionRollbacked(UserManager.class, methodName));
	}

}

You can see that when Rod or Juergen decide to change log output it will mean for us only to change few lines in SpringTransactionTestAppender to adapt (ok, we are relying that they will log somenting meaningful in such moments as open, commit and rollback transaction). When you test your own advices it’s even simplier – you have everything in your hands.

Even I thought that this idea is my own (or ours own, because it was invented on way back home from CZJUG meeting in discussion with my friend Pavel Jetenský) I found out that NetBeans guys were the first. In their article Test patterns they recommend logging for testing parallel execution problems (such as deadlock, race conditions and so) in chapters Analyzing Random Failures, Advanced usage of Logging, Execution Flow Control using Logging. It’s hard to be the first these times …

Examples shown in this article are available to download. So you can examine them more properly in your IDE and even run the tests.

Example sources

Související články:

1. Podcast: Basics of Unit Testing with Spring
2. Mock testing – Potěmkinovy vesnice
3. Jak se zbavit nepříjemných závislostí v testech
4. Jak na rychlé integrační testy ve Springu
5. Spring CgLib Dynamic AOP Proxies – proper Pointcut equals method is simply essential