Spring AOP Logging twice

[Sanjay Patil]

Hi,

I am using Spring AOP to log the entry and exit of methods for my application on WAS 6.1 but for some reason, I can see my advise is printing the stmts twice. Please can anyone suggest me a reason.

Here is my code for Pointcut

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;


@Aspect
public class JJSSLF4JLoggingAspect {

	private Logger logger;
	
	@Before("com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inPresentationTier() || " +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inServiceTier() || " +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inBusinessTier() || " +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inDomainTier() || " +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inDAOTier()|| " + 
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inJJS2()")					

	public void beforeLogging(JoinPoint aJoinPoint) {	
			
		logger = LoggerFactory.getLogger(aJoinPoint.getTarget().getClass());
		
		if (logger.isDebugEnabled()) {	
						
			StringBuilder logString = new StringBuilder();	
			
			logString.append("Entering >>>> ").append(getShortClassName(aJoinPoint)).append(".").append(aJoinPoint.getStaticPart().getSignature().toShortString()).append("(");		
			Object[] argArray = aJoinPoint.getArgs();
			
			int argumentIndex=1;
			for (Object argument : argArray) {
				logString.append(" Argument" + argumentIndex + "=");
				logString.append(argument);
				argumentIndex++;
			}
			logString.append(")");
			
			logger.debug(logString.toString());
		}
	}

	@AfterReturning(pointcut="com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inPresentationTier() || " +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inServiceTier() || " +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inBusinessTier() || " +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inDomainTier() || " +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inDAOTier() ||" +
			"com.johnlewis.jjs2develop.common.logging.aspect.JJSSLF4JLoggingPointcut.inJJS2()",
			returning="aReturnValue")
	public void afterLogging(JoinPoint aJoinPoint, Object aReturnValue) {	
			
		logger = LoggerFactory.getLogger(aJoinPoint.getTarget().getClass());
		
		if (logger.isDebugEnabled()) {	
						
			StringBuilder logString = new StringBuilder();			
			logString.append("Returning <<<< ").append(getShortClassName(aJoinPoint)).append(".").append(aJoinPoint.getStaticPart().getSignature().toShortString()).append(". Return value = ").append(aReturnValue);		
			
			logger.debug(logString.toString());
		}
	}
	
	public String getShortClassName(JoinPoint aJoinPoint) {
		String className = aJoinPoint.getTarget().getClass().getCanonicalName();
		int nameIndex = className.lastIndexOf('.');
		return className.substring(nameIndex + 1);
	}

}

I get below output on my console.


[12/09/08 15:14:12:184 BST] 0000002a SystemOut O DEBUG JJS: WebContainer : 2 Entering >>>> FindStoresCommand.findStores() from: com.johnlewis.tra.glasshire.service.internal.FindS toresCommand
[12/09/08 15:14:12:184 BST] 0000002a SystemOut O 63001 [WebContainer : 2] DEBUG com.johnlewis.tra.glasshire.service.internal.FindS toresCommand - Entering >>>> FindStoresCommand.findStores()
[12/09/08 15:14:12:184 BST] 0000002a SystemOut O DEBUG JJS: WebContainer : 2 Entering >>>> StoreDMgrFacade.findStores() from: com.johnlewis.tra.glasshire.dmgr.store.internal.St oreDMgrFacade
[12/09/08 15:14:12:184 BST] 0000002a SystemOut O 63001 [WebContainer : 2] DEBUG com.johnlewis.tra.glasshire.dmgr.store.internal.St oreDMgrFacade - Entering >>>> StoreDMgrFacade.findStores()
[12/09/08 15:14:12:184 BST] 0000002a SystemOut O DEBUG JJS: WebContainer : 2 Entering >>>> StoreDAO.findCOfStore() from: com.johnlewis.tra.glasshire.dmgr.store.internal.da o.jdbc.StoreDAO
[12/09/08 15:14:12:184 BST] 0000002a SystemOut O 63001 [WebContainer : 2] DEBUG com.johnlewis.tra.glasshire.dmgr.store.internal.da o.jdbc.StoreDAO - Entering >>>> StoreDAO.findCOfStore()