Announcement Announcement Module
Collapse
No announcement yet.
after-returning AOP advice is getting called twice Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • after-returning AOP advice is getting called twice

    Hi

    I am new to spring AOP. I am trying to use the "after-returning" advice which is configured as below:

    HTML Code:
    	<bean id="actimizeAspect" class="com.s1.pso.common.aspects.ActimizeAspect"/>
    	<aop:config>
    		<aop:aspect ref="actimizeAspect">
    			<aop:pointcut id="transactionModify" expression="execution(* com.s1.app.disbursements.corpach.common.CorpAchService.modify(..))"/>
    			<aop:pointcut id="trackCreate" expression="execution(* com.s1.app.disbursements.corpach.common.CorpAchService.create(..))"/>
    			<aop:after-returning pointcut-ref="transactionModify" returning="retVal" method="doLogging"/>
    			<aop:after-returning pointcut-ref="trackCreate" returning="retVal" method="logPaymentCreateEvent"/>
    		</aop:aspect>
    	</aop:config>	
    The aspect class has the simple method with just some SystemOuts:

    Code:
    	public void doLogging(CorpAchTransactionValue retVal){
    		System.out.println("#### after-returning: Transaction status: " + retVal.getStatus());
    		System.out.println("#### after-returning: LastUpdateDate: " + retVal.getLastUpdateDate());
    		System.out.println("#### after-returning: LastUpdateUser: " + retVal.getLastUpdateUser());
    	}
    The modify method on bean "CorpAchService" is getting called only once but the after-returning advice is getting called twice.

    I did debug the code and here's the stack trace when I put a breakpoint in the after-returning advice

    Code:
    		Daemon Thread [WebContainer : 3] (Suspended at breakpoint (ActimizeAspect [line: 22] - doLogging(CorpAchTransactionValue)))	
    			ActimizeAspect.doLogging(CorpAchTransactionValue) line: 22	
    			NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]	
    			NativeMethodAccessorImpl.invoke(Object, Object[]) line: 60	
    			DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 37	
    			Method.invoke(Object, Object...) line: 611	
    			AspectJAfterReturningAdvice(AbstractAspectJAdvice).invokeAdviceMethodWithGivenArgs(Object[]) line: 627	
    			AspectJAfterReturningAdvice(AbstractAspectJAdvice).invokeAdviceMethod(JoinPointMatch, Object, Throwable) line: 609	
    			AspectJAfterReturningAdvice.afterReturning(Object, Method, Object[], Object) line: 57	
    			AfterReturningAdviceInterceptor.invoke(MethodInvocation) line: 51	
    			ReflectiveMethodInvocation.proceed() line: 171	
    			AfterReturningAdviceInterceptor.invoke(MethodInvocation) line: 50	
    			ReflectiveMethodInvocation.proceed() line: 171	
    			TransactionInterceptor$1.doInTransaction(TransactionStatus) line: 128	
    			WebSphereUowTransactionManager$UOWActionAdapter.run() line: 306	
    			UOWManagerImpl.runUnderNewUOW(int, UOWAction) line: 1067	
    			UOWManagerImpl.runUnderUOW(int, boolean, UOWAction) line: 628	
    			WebSphereUowTransactionManager.execute(TransactionDefinition, TransactionCallback) line: 252	
    			TransactionInterceptor.invoke(MethodInvocation) line: 123	
    			ReflectiveMethodInvocation.proceed() line: 171	
    			ExposeInvocationInterceptor.invoke(MethodInvocation) line: 89	
    			ReflectiveMethodInvocation.proceed() line: 171	
    			JdkDynamicAopProxy.invoke(Object, Method, Object[]) line: 204	
    			$Proxy120.modify(CorpAchTransactionValue, CustomerValue) line: not available	
    			ModifyAchSubmitAction.execute(ActionMapping, ActionForm, HttpServletRequest, HttpServletResponse) line: 205	
    			CustomRequestProcessor.processActionPerform(HttpServletRequest, HttpServletResponse, Action, ActionForm, ActionMapping) line: 217
    I think the below lines from the stack trace are causing the code to be executed twice:
    Code:
    			AfterReturningAdviceInterceptor.invoke(MethodInvocation) line: 51	
    			ReflectiveMethodInvocation.proceed() line: 171	
    			AfterReturningAdviceInterceptor.invoke(MethodInvocation) line: 50	
    			ReflectiveMethodInvocation.proceed() line: 171

    Any pointers what might be wrong or how I can get more information as to why this happening? Any help would be highly appreciated!
    Last edited by subodhnatu; Mar 14th, 2012, 09:00 PM.

  • #2
    after-returning AOP advice is getting called twice

    I've found the Spring 3.0.5 AfterReturningAdviceInterceptor source code here
    Can you put a break point in the invoke method:
    Code:
        public Object invoke(MethodInvocation mi) throws Throwable {
            Object retVal = mi.proceed(); //line 50 => break point here
            this.advice.afterReturning(retVal, mi.getMethod(), mi.getArguments(), mi.getThis());//line 51 => break point here
            return retVal;
        }
    I think it's either you code which is calling twice the logging method or it's Spring AOP bug.

    To make sure, try to grab the spring jars source code. If you are using maven you can use -DdownloadSource=true parameter.
    You can then debug easily your code to figure out the root cause.

    btw, the code shown here is from Spring 3.0.5 which may not be the version you are using

    Comment


    • #3
      I also tried the around advice, hoping that it would surely work, but I have the most strange behavior there as well!!

      Here's how my around advice looks:

      Code:
      	public Object doAroundLogging(ProceedingJoinPoint pjp) throws Throwable {
      		System.out.println("#### Around-Advice: Before");
      		Object retVal = pjp.proceed();
      		System.out.println("#### Around-Advice: After");
      		return retVal;
      	}
      I see the "Before" system.out twice and then the "after" system.out twice on the console, but the original method only executes ONCE!!
      Not sure how that can happen, unless there is some intelligent coding in the [pjp.proceed();] which doesn't let the method execute twice!!!!

      Comment


      • #4
        @subodhnatu, have you defined your aspect twice, in xmls or annotations (@Component or @Service) ?

        Comment

        Working...
        X