Advice is called twice with AOP auto-proxy configuration

[abiketov]

Hi,

I just started looking into Spring framework 2.0 AOP features and found strange behavior. If in applicationConfig.xml I define AOP using auto-proxy, advice is executed twice for the same service method call. If I set up AOP using schema is works as it supposed to. Below is my code, configuration and
log.

Service class with one method:

package com.xyz.spring2.demo.service.impl;

import org.apache.commons.logging.Log;
import org.apache.log4j.Logger;

import com.xyz.spring2.demo.model.Order;
import com.xyz.spring2.demo.service.OrderService;

public class OrderServiceImpl implements OrderService {

	Logger logger = Logger.getLogger(OrderServiceImpl.class);
	
	/* (non-Javadoc)
	 * @see com.xjet.spring2.demo.service.OrderService#submitOrder(com.xyz.spring2.demo.model.Order)
	 */
	public void submitOrder(Order order) {
		
		logger.debug(order.getId() + " "+ order.getName());
		logger.debug("Order submited");
		
	}

}

Advice class:

package com.xyz.spring2.demo.aop;

import org.apache.log4j.Logger;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;

import com.xyz.spring2.demo.model.Order;

@Aspect
public class LoggingAspect {
	
	Logger log = Logger.getLogger(LoggingAspect.class);
	
	@Before ( "execution (* com.xyz.spring2.demo.service.impl..*(..) )" )
	public void writeToLog(JoinPoint call){				
		log.info("Execute "+call.getSignature().getName());
	}
		
	
	//@Before ("com.xyz.spring2.demo.aop.LoggingAspect.validate(order)")		   
	@Before ("execution (public * com.xyz.spring2.demo.service.impl..*(..))   and args(order,..)  )")    
	public void validateOrder(Order order){				
			
		if (order.getId() == null){
			log.info("Order is invalid");
		}
		else {
			order.inc();
			log.info("Order is valid "+order.getCount());
		}			
	}
	
}

Config file. I have both auto-proxy and schema defintion. I use one or another:

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
		xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
		xmlns:aop="http://www.springframework.org/schema/aop"
		xsi:schemaLocation="http://www.springframework.org/schema/beans 
		http://www.springframework.org/schema/beans/spring-beans-2.0.xsd
		http://www.springframework.org/schema/aop 
		http://www.springframework.org/schema/aop/spring-aop-2.0.xsd">
	
	<!-- AOP Auto proxy config -->
	<aop:aspectj-autoproxy proxy-target-class="true"/>
	
	<bean class="org.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator" />
	
	<bean id="LoggingAspect" class="com.xyz.spring2.demo.aop.LoggingAspect">
	
	</bean>
	
	<!--  AOP Schema schema -->
	<!-- 
	<bean id="LoggingAspect" class="com.xyz.spring2.demo.aop.LoggingAspect"/>
	
	<aop:config>		
		<aop:pointcut id="id1" 
			expression="execution (* com.xyz.spring2.demo.service.impl..*(..) )"/>
		
		<aop:pointcut id="id2" 
			expression="execution (public * com.xyz.spring2.demo.service.impl..*(..))   and args(order,..)  )"/>
		
		<aop:aspect id="logAspect" ref="LoggingAspect">
			<aop:before pointcut-ref="id1" method="writeToLog"/>
			<aop:before pointcut-ref="id2" method="validateOrder"/>
		</aop:aspect>
	</aop:config>
	
	-->
	<bean id="OrderService" class="com.xyz.spring2.demo.service.impl.OrderServiceImpl">
	</bean>

</beans>

Now logs. First one for Auto-proxy config. You can see advice is called twice. I increment count on Order object in validation method to see that it's called twice.

2007-02-05 20:04:04,609 DEBUG [org.springframework.aop.support.AopUtils] - <Candidate advisor [InstantiationModelAwarePointcutAdvisor: expr='execution (public * com.xyz.spring2.demo.service.impl..*(..))   and args(order,..)  )' advice method=public void com.xyz.spring2.demo.aop.LoggingAspect.validateOrder(com.xyz.spring2.demo.model.Order); perClauseKind=SINGLETON; instantiationCount=0] accepted for class [com.xyz.spring2.demo.service.impl.OrderServiceImpl$$EnhancerByCGLIB$$f9b05bcf]>
2007-02-05 20:04:04,609 DEBUG [org.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator] - <Creating implicit proxy for bean 'OrderService' with 0 common interceptors and 3 specific interceptors>
2007-02-05 20:04:04,609 DEBUG [org.springframework.aop.framework.ProxyFactory] - <Added new aspect interface: com.xyz.spring2.demo.service.OrderService>
2007-02-05 20:04:04,609 DEBUG [org.springframework.aop.framework.ProxyFactory] - <Added new aspect interface: net.sf.cglib.proxy.Factory>
2007-02-05 20:04:04,609 DEBUG [org.springframework.aop.framework.ProxyFactory] - <Added new aspect interface: org.springframework.aop.framework.Advised>
2007-02-05 20:04:04,609 DEBUG [org.springframework.aop.framework.JdkDynamicAopProxy] - <Creating JDK dynamic proxy for [com.xyz.spring2.demo.service.impl.OrderServiceImpl$$EnhancerByCGLIB$$f9b05bcf]>
2007-02-05 20:04:04,625 INFO [com.xyz.spring2.demo.aop.LoggingAspect] - <Execute submitOrder>
2007-02-05 20:04:04,625 INFO [com.xyz.spring2.demo.aop.LoggingAspect] - <Order is valid 1>
2007-02-05 20:04:04,640 INFO [com.xyz.spring2.demo.aop.LoggingAspect] - <Execute submitOrder>
2007-02-05 20:04:04,640 INFO [com.xyz.spring2.demo.aop.LoggingAspect] - <Order is valid 2>
2007-02-05 20:04:04,640 DEBUG [com.xyz.spring2.demo.service.impl.OrderServiceImpl] - <37283782 First Order>
2007-02-05 20:04:04,640 DEBUG [com.xyz.spring2.demo.service.impl.OrderServiceImpl] - <Order submited>

Now log for AOP schema config:

2007-02-05 20:37:26,812 DEBUG [org.springframework.aop.support.AopUtils] - <Candidate advisor [org.springframework.aop.aspectj.AspectJPointcutAdvisor: pointcut [AspectJExpressionPointcut: (com.xyz.spring2.demo.model.Order order) execution (public * com.xyz.spring2.demo.service.impl..*(..))   and args(order,..)  )]; advice [org.springframework.aop.aspectj.AspectJMethodBeforeAdvice: adviceMethod=public void com.xyz.spring2.demo.aop.LoggingAspect.validateOrder(com.xyz.spring2.demo.model.Order); aspectName='LoggingAspect']] accepted for class [com.xyz.spring2.demo.service.impl.OrderServiceImpl]>
2007-02-05 20:37:26,812 DEBUG [org.springframework.aop.aspectj.autoproxy.AspectJInvocationContextExposingAdvisorAutoProxyCreator] - <Creating implicit proxy for bean 'OrderService' with 0 common interceptors and 3 specific interceptors>
2007-02-05 20:37:26,812 DEBUG [org.springframework.aop.framework.ProxyFactory] - <Added new aspect interface: com.xyz.spring2.demo.service.OrderService>
2007-02-05 20:37:26,812 DEBUG [org.springframework.aop.framework.JdkDynamicAopProxy] - <Creating JDK dynamic proxy for [com.xyz.spring2.demo.service.impl.OrderServiceImpl]>
2007-02-05 20:37:26,828 INFO [com.xyz.spring2.demo.aop.LoggingAspect] - <Execute submitOrder>
2007-02-05 20:37:26,828 INFO [com.xyz.spring2.demo.aop.LoggingAspect] - <Order is valid 1>
2007-02-05 20:37:26,828 DEBUG [com.xyz.spring2.demo.service.impl.OrderServiceImpl] - <37283782 First Order>
2007-02-05 20:37:26,828 DEBUG [com.xyz.spring2.demo.service.impl.OrderServiceImpl] - <Order submited>

Sorry for making it too long.Any ideas why this happens?
Thanks.

[ramnivas]

Take out either the definition of aspect in annotations or XML -- you don't need both.

-Ramnivas

[abiketov]

Hi,

As you can see in applicationConfig.xml aspect definition is commented if I use AOP auto-proxy. So this can't be the reason. I know that I don't need them both, but originally I used AOP auto-proxy and got advice called twice, then I switch to AOP schema config. That is why I have advice defined through annotation and in the config file.

[zarar]

Was there a resolution to this problem? I'm encountering the exact same problem and am using AnnotationAwareAspectJAutoProxyCreator with annotations.

Here's my setup:

Aspects:

@Aspect
public class SystemArchitecture {

    @Pointcut("execution(* com.company.dao.*.*(..))")
    public void daoOperation() {}
}

@Aspect
public class TierLogger {

    @Around("com.company.SystemArchitecture.daoOperation()")
    public Object doLogging(ProceedingJoinPoint pjp) throws Throwable {
        System.out.println("printed twice");
    	return pjp.proceed();
    }
}

Configuration:

<bean
    id="tierLogger"
    class="com.company.TierLogger"
>

<bean class="org.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator" />

[zarar]

OK, I've fixed my own problem.

@Pointcut("execution(* com.xyz.someapp.dao.*.*(..))") should really be

@Pointcut("execution(* com.xyz.someapp.dao.impl.*.*(..))")

on this page:

http://www.springframework.org/docs/reference/aop.html

Otherwise the advice gets called twice. Somebody with more expertise can probably elaborate more.