Announcement Announcement Module
Collapse
No announcement yet.
Advice is called twice with AOP auto-proxy configuration Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Advice is called twice with AOP auto-proxy configuration

    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:
    Code:
    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:

    Code:
    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:
    Code:
    <?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.
    Code:
    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:
    Code:
    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.

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

    -Ramnivas

    Comment


    • #3
      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.

      Comment


      • #4
        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:

        Code:
        @Aspect
        public class SystemArchitecture {
        
            @Pointcut("execution(* com.company.dao.*.*(..))")
            public void daoOperation() {}
        }
        Code:
        @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:

        Code:
        <bean
            id="tierLogger"
            class="com.company.TierLogger"
        >
        
        <bean class="org.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator" />

        Comment


        • #5
          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.

          Comment

          Working...
          X