AOP Logging Advice ignored

[FreddyDaKing]

Hi,

currently I'm trying to use Spring's AOP for logging. I've written some simple test beans and a LoggingInterceptor. I configured everything in in my beans-config.xml. Then I've created the ApplicationContext and called an abitrary method in one of my test beans. The method is called successfully, but I can't see any logging in my console. It seems that my logging advice is completly ignored.

Here my LoggingInterceptor:

import java.lang.reflect.Method;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.springframework.aop.AfterReturningAdvice;
import org.springframework.aop.MethodBeforeAdvice;
import org.springframework.aop.ThrowsAdvice;

public class LoggingInterceptor implements MethodBeforeAdvice, AfterReturningAdvice, ThrowsAdvice {
  private static Log log = null;

  public LoggingInterceptor() {}

  public void before(Method arg0, Object[] arg1, Object arg2) throws Throwable {
    System.out.println("Entering method: " + arg0.getName());
    log = LogFactory.getLog(arg2.getClass());
    log.info("Entering method: " + arg0.getName());
  }

  public void afterReturning(Object arg0, Method arg1, Object[] arg2, Object arg3) throws Throwable {
    log = LogFactory.getLog(arg3.getClass());
    log.info("Leaving method: " + arg1.getName());
  }

  public void afterThrowing(Method m, Object[] args, Object target, Throwable ex) {
    log = LogFactory.getLog(target.getClass());
    log.info("Exception in method: " + m.getName() + " Exception is: " + ex.getMessage());
  }

}

My Spring configuration is as follows:

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

<bean id="loggingInterceptor" class="temp.LoggingInterceptor" />

<bean id="knightWithLogging"
class="org.springframework.aop.framework.ProxyFact oryBean">
<property name="proxyInterfaces">
<value>temp.Knight</value>
</property>
<property name="interceptorNames">
<list>
<value>loggingInterceptor</value>
</list>
</property>
<property name="target" ref="knight" />
</bean>

<bean id="quest" class="temp.HolyGrailQuest" />

<bean id="knight" class="temp.KnightImpl">
<constructor-arg>
<value>Belvidere</value>
</constructor-arg>
<property name="quest">
<ref bean="quest" />
</property>
</bean>

</beans>

Any ideas what the problem could be?

Thx a lot.

[Marten Deinum]

Pleaes use [ code][/code] tags when posting code, that way we can read your code.

How are you calling your bean...

[FreddyDaKing]

Thx for your quick answer.

I'm calling my bean as follows:

import org.springframework.context.ApplicationContext;
import org.springframework.context.support.FileSystemXmlApplicationContext;

public class KnightApp {
  private ApplicationContext _context;

  public void initTestApplicationContext() {
    _context = createApplicationContext("beans.config.xml");
  }

  public ApplicationContext getApplicationContext() {
    return _context;
  }

  private ApplicationContext createApplicationContext(String configFileName) {
    return new FileSystemXmlApplicationContext(configFileName);
  }

  public static void main(String[] args) {
    KnightApp app = new KnightApp();
    app.initTestApplicationContext();
    Knight k = (KnightImpl)app.getApplicationContext().getBean("knight");
    try {
      System.out.println(k.embarkOnQuest());
    }
    catch (Exception e) {
      // TODO Auto-generated catch block
      e.printStackTrace();
    }
  }
}

[Marten Deinum]

Knight k = (KnightImpl)app.getApplicationContext().getBean("knight");

'knight' is the unproxied/unadviced one, use the proxied instance (knightWithLogging).

[gregturn]

The bean you are fetching is the un-advised bean. If you getBean("knightWithLogging"), what happens?

[gregturn]

import org.springframework.context.ApplicationContext;
import org.springframework.context.support.ClassPathXmlApplicationContext;

public class KnightApp {

	private ApplicationContext _context;

	public void initTestApplicationContext() {
		_context = createApplicationContext("com/harris/spring/beans-config.xml");
	}

	public ApplicationContext getApplicationContext() {
		return _context;
	}

	private ApplicationContext createApplicationContext(String configFileName) {
		return new ClassPathXmlApplicationContext(configFileName);
	}

	public static void main(String[] args) {
		KnightApp app = new KnightApp();
		app.initTestApplicationContext();
		Knight k = (Knight)app.getApplicationContext().getBean("knightWithLogging");
		try {
			System.out.println(k.embarkOnQuest());
		}
		catch (Exception e) {
			// TODO Auto-generated catch block
			e.printStackTrace();
		}
	}

}

I tried to create this in Eclipse, and also discovered that when getting the ProxyFactoryBean bean, you should cast to the interface, not the concrete class. And yes, I put in ClassPathXmlApplicationContext.

This gave me...

2008/02/05 09:03:08 [ INFO] ClassPathXmlApplicationContext.prepareRefresh - Refreshing org.springframework.context.support.ClassPathXmlApplicationContext@ba6c83: display name [org.springframework.context.support.ClassPathXmlApplicationContext@ba6c83]; startup date [Tue Feb 05 09:03:08 EST 2008]; root of context hierarchy
2008/02/05 09:03:08 [ INFO] XmlBeanDefinitionReader.loadBeanDefinitions - Loading XML bean definitions from class path resource [com/harris/spring/beans-config.xml]
2008/02/05 09:03:09 [ INFO] ClassPathXmlApplicationContext.obtainFreshBeanFactory - Bean factory for application context [org.springframework.context.support.ClassPathXmlApplicationContext@ba6c83]: org.springframework.beans.factory.support.DefaultListableBeanFactory@d0af9b
2008/02/05 09:03:09 [ INFO] DefaultListableBeanFactory.preInstantiateSingletons - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@d0af9b: defining beans [loggingInterceptor,knightWithLogging,quest,knight]; root of factory hierarchy
Entering method: embarkOnQuest
2008/02/05 09:03:09 [ INFO] KnightImpl.before - Entering method: embarkOnQuest
2008/02/05 09:03:09 [ INFO] KnightImpl.afterReturning - Leaving method: embarkOnQuest
A quest we complete!

[FreddyDaKing]

Thx a lot for your help. Now everything works like a charm