Ordering Aspect problem

[seldrick]

Hi,

I have got problems ordering some aspect with Spring 2.0.5 (probably me not using correctly Spring but I can't figure out where is the problem).

What is my goal ?
My goal is to intercepts all methods call of my service layer to do 2 things in that order :
1 - report to the supervision system a service call
2 - log the service call (method name, parameters, return value and exception).

This implies to execute first the supervision service interception.

How I have done things ?
I have developped the 2 aspects (a SupervisionInterceptor and a LoggerInterceptor) and they work correctly except that LoggerInterceptor is called before SupervisionInterceptor !

My problem is that I'm not able to tell Spring to execute SupervisionInterceptor before LoggerInterceptor

I have implemented Ordered interface for my advice class but it does seem to change anything.

Here's my config :

<bean id="loggerInterceptor" class="fr.anpe.sapiens.transverse.utils.LoggerInterceptor">
      <property name="logExecutionTime" value="true" />
      <property name="logExceptionStackTrace" value="false" />
</bean>

<bean id="serviceSupervisionInterceptor" class="fr.anpe.sapiens.transverse.utils.ServiceSupervisorInterceptor"/>

<aop:config>
  <aop:pointcut id="serviceOperation" expression="execution(* fr.anpe.sapiens.bas.service.*.*(..))" />
  <aop:aspect ref="serviceSupervisionInterceptor">
    <aop:before pointcut-ref="serviceOperation" method="superviseService" />
  </aop:aspect>
  <aop:aspect ref="loggerInterceptor">
    <aop:around pointcut-ref="serviceOperation" method="logMethodCall" />
  </aop:aspect>
</aop:config>

Here's my advice beans implementation :

public class ServiceSupervisorInterceptor
{
   private static Logger logger = Logger.getLogger(ServiceSupervisorInterceptor.class);
   
   public void superviseService(JoinPoint joinPoint) {
      MethodSignature signature = (MethodSignature) joinPoint.getSignature();
      String serviceName = signature.getMethod().getName();
      // on récupère le logger de la classe appelée pour faire une trace Log4j pertinente
      Object[] arguments = joinPoint.getArgs();
      if (ArrayUtils.isEmpty(arguments)) {
         logger.error("Le service <" + serviceName + "> ne respecte pas les préconisations d'architectures : un service doit avoir un unique paramètre héritant de la classe AbstractDemande !");
         return;
      }
      try {
         AbstractDemande demande = (AbstractDemande) arguments[0];
         logger.info("Appel du service <" + serviceName + "> par [" + demande.getInfoConsumer() + "]");
      } catch (Exception e) {
         logger.error("Le service <" + serviceName + "> ne respecte pas les préconisations d'architectures : un service doit avoir un unique paramètre héritant de la classe AbstractDemande !");
         return;
      }      
   }

   public int getOrder() {
      return 1;
   }
}

public class LoggerInterceptor implements Ordered
{

   private static final String EMPTY_STRING = "";
   private static final String PARAMETER_SEPARATOR = ", ";
   private boolean logExecutionTime = false;
   private boolean logExceptionStackTrace = true;

   /**
    * Print information on logger about the method execution.
    */
   public Object logMethodCall(ProceedingJoinPoint joinPoint) throws Throwable
   {
      long time = System.currentTimeMillis();
      MethodSignature signature = (MethodSignature) joinPoint.getSignature();
      Class declaringType = signature.getDeclaringType();
      Logger logger = Logger.getLogger(declaringType);;
      String methodName = signature.getMethod().getName();
      try
      {
         StringBuffer methodNameLog = new StringBuffer(200);
         if (logger.isInfoEnabled())
         {
            System.out.println(EMPTY_STRING);
         }
         methodNameLog.append("Appel de la méthode ").append(methodName).append("(");
         Object[] arguments = joinPoint.getArgs();
         if (arguments != null && arguments.length > 0)
         {
            for (int i = 0; i < arguments.length; i++)
            {
               methodNameLog.append(objectToString(arguments[i]));
               boolean notLastParameter = i < arguments.length - 1;
               if (notLastParameter)
               {
                  methodNameLog.append(PARAMETER_SEPARATOR);
               }               
            }
         }
         methodNameLog.append(")");
         logger.info(methodNameLog);
         Object o = joinPoint.proceed();
         if (signature.getReturnType().equals(Void.TYPE) == false)
         {
            logger.info("> " + methodName + "() a retourné --> " + objectToString(o));
         }
         return o;
      }
      catch (Throwable t)
      {
         logger.error("> " + methodName + "() a levé l'exception " + StringUtils.getClassNameWithoutPackage(t.getClass()) + " avec comme message : " + t.getMessage());
         if (logExceptionStackTrace) {
            logger.error("stack trace exception : ", t);
         }         
         throw t;
      }
      finally
      {
         if (logExecutionTime)
         {
            double executionTime = (System.currentTimeMillis() - time);
            logger.info("> " + methodName + "() executée en " + executionTime + " ms.");
         }         
      }
   }

   /**
    * return a string description of o.
    * <p>
    * better than toString because it manages array !
    * 
    * @param o
    *           object to describe
    * @return string description of o
    */
   private String objectToString(Object o)
   {
      if (null == o)
      {
         return null;
      }
      if (o.getClass().isArray())
      {
         return ArrayUtils.toString(o);
      }
      return o.toString();
   }

   public void setLogExecutionTime(boolean logExecutionTime)
   {
      this.logExecutionTime = logExecutionTime;
   }

   public void setLogExceptionStackTrace(boolean logExceptionStackTrace) {
      this.logExceptionStackTrace = logExceptionStackTrace;
   }

   public int getOrder() {
      return 0;
   }   
}

I have switched the getOrdered return value in case of ... but no change !

Here's an extract of somme logging trace :

INFO [bas.service.ObjTrouveService] - Appel de la méthode findObjTrouves(CritereRechercheObjTrouveDemande)
INFO [transverse.utils.ServiceSupervisorInterceptor] - Appel du service <findObjTrouves> par [testFindObjetParClee consumer]
INFO [bas.service.ObjTrouveService] - > findObjTrouves() a retourné --> fr.anpe.sapiens.transverse.paquets.ObjTrouveRepons e@108f8e0
INFO [bas.service.ObjTrouveService] - > findObjTrouves() executée en 1391.0 ms.

Do you have any clue or suggestion to solve this problem ?

Regards,

Joel

[Andrei Stefan]

http://www.springframework.org/docs/...html#getOrder() :

Higher value can be interpreted as lower priority, consequently the first object has highest priority (somewhat analogous to Servlet "load-on-startup" values).

Your interceptors have wrong order values, imho.
Also, ServiceSupervisorInterceptor doesn't implement Ordered :-), or your example missed that part ?

[seldrick]

Your interceptors have wrong order values, imho.
Also, ServiceSupervisorInterceptor doesn't implement Ordered :-), or your example missed that part ?

You're right on both !

silly me ! it's time for me to go to bed

Thanks for spotting the 2 mistakes (and for the quick answer) and sorry for bothering with stupid question,

Joel

[nallan.j2ee]

Problem:

1) I am not able to control the order of aspects executing on a Join Point.
2) getOrder() method is not getting called, as I can see no output in the output console.( I think, if I solve this problem, I should see the expected results).

Code Flow: LetsRun -> Before Aspects*->CoolTask.cool();

Before Aspects* : JumpingAspect, LoggingAspect.

Expected Result: Jumping Aspects to be executed before LoggingAspect (Jump before Logging). getOrder() method output statements should be printed to console.

CheckList: I have taken care of

1)getOrder() method of Jumping Aspect returns 0, and that of Logging Aspect returns 1;
2) Both aspects implement Ordered interface's getOrder() method.

Here are the classes.

LetsRun.java
-------------
public class LetsRun {

public static void main(String a[]) throws Exception
{
CoolTask task = new CoolTask();
task.cool();
}
}

CoolTask.java
-----------------

public class CoolTask {

public void cool(){

System.out.println(" This is a cool method");
}

public void superCool(){

System.out.println(" This is a Super cool method");
}
}

LoggingAspect.aj
-----------------

@Aspect
public class LoggingAspect implements Ordered{

@Before("com.abc.aop.common.GenericPointCut.anyCoo lMethod()")
public void logBeforeCoolMethod(){
System.out.println(" I am logging (1)BEFORE cool Method execution");
}

public int getOrder() {
System.out.println(":Get Order: cool Aspect: called");
return 1;
}

}

JumpingAspect.aj:
-----------------

@Aspect
public class JumpingAspect implements Ordered {

@Before("com.abc.aop.common.GenericPointCut.anyCoo lMethod()")
public void jumpingBeforeCoolMethod(){
System.out.println(" I am Jumping(0) BEFORE cool Method execution");
}

public int getOrder() {
System.out.println(":Get Order: Another-cool Aspect: called");
return 0;
}
}

Test Results on running LetsRun.java
--------------------------------------
I am logging (1)BEFORE cool Method execution
I am Jumping(0) BEFORE cool Method execution
This is a cool method

[johras]

I am not seeing any spring wiring? Unfortunately I am not an Aspectj pro but for the ordering to work you have to wire your beans and aspects in an application context.

[denis.zhdanov]

Your example works fine for me:

Output:

DEBUG DefaultListableBeanFactory - Returning cached instance of singleton bean 'coolTask'
DEBUG DefaultListableBeanFactory - Returning cached instance of singleton bean 'jumpingAspect'
I am Jumping(0) BEFORE cool Method execution
DEBUG DefaultListableBeanFactory - Returning cached instance of singleton bean 'loggingAspect'
I am logging (1)BEFORE cool Method execution
This is a cool method

[nallan.j2ee]

hi Denis,

Thanks for the efforts. I am at least clear that the concept works the way I expect. However, I want to know these things

1) Why is the System.out.println statements of getOrder() method not seen in mine/your output ? What should we infer by this, is the method not getting called ? or the method output is consumed by spring framework ?

2) Did you do any wiring as stated by Johras ? if so, can u paste that here?

Thanks

[denis.zhdanov]

The order of aspects processing is configured during bean proxy construction, i.e. you can find that getOrder() is called during context initialization.

About configuration - I just used @AspectJ (enabled via <aop:aspectj-autoproxy/> config element presence) and @Component annotation with <context:component-scan base-package="com.spring.aop"/> element defined at config. Read more about automatic beans scanning and instantiations at the reference - 3.12. Classpath scanning for managed components.