after-returning AOP advice is getting called twice

[subodhnatu]

Hi

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

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

	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

		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:

			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!

[spring_2009]

I've found the Spring 3.0.5 AfterReturningAdviceInterceptor source code here
Can you put a break point in the invoke method:

    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

[subodhnatu]

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:

	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!!!!

[amiladomingo]

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