Announcement Announcement Module
Collapse
No announcement yet.
Ordering Aspect problem Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Ordering Aspect problem

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

  • #2
    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 ?

    Comment


    • #3
      Originally posted by Andrei
      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

      Comment


      • #4
        Aspects Ordering

        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

        Comment


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

          Comment


          • #6
            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

            Comment


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

              Comment


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

                Comment

                Working...
                X