[aspectj-users] Can this problem be solved using an aspect?

["Gopinathan,Sekar" <Sekar.Gopinathan@xxxxxxxxxx>]

Problem:

 

Background:

Class "ServiceA" calls "execute" method on Class "ServiceB" which in turn calls "execute" method on Class "ServiceC".    A stateless session ejb "ClassEJB" calls "execute" method on Class "ServiceA".    ServiceA,ServiceB,ServiceC extend AbstractBusinessService and provide business service whereas stateless session ejb exists to provide remoting/threading/transaction handling, so it simply passes the call to business service layer.   Log4j is the logging library used by all these components.  

 

Problem:

In a multithreaded environment, the logging is obscured by all the threads crossing each other in the logs.

A typical output could have information like....

Call to "ServiceA"

Call to "ServiceB"

Call to "ServiceA"

Call to "ServiceA"

Call to "ServiceB"

Call to "ServiceB"

Call to "SerivceC"

This leads to confusion in identifying the requests and tracking them through its entire length.   The default %t option of log4j is not uniform and is not sufficient for us .   

We need a way to stamp each line with say a "request ID".    This can be accomplished by putting a unique identifier into log4j NDC by using NDC.push() method for every new request and pop it when we finish servicing that request.    This will result in logs such that:

"request1":Call to "ServiceA"

"request1":Call to "ServiceB"

"request2":Call to "ServiceA"

"request3":Call to "ServiceA"

"request3":Call to "ServiceB"

"request3":Call to "ServiceB"

"request1":Call to "SerivceC"

 

While at it find a way to specify the level of nesting we like to have....for example I may want to trace two levels....which means I could get,

"request1":Call to "ServiceA"

"request1:request1.1":Call to "ServiceB"

 

Note that I don't necessarily care about the "ClassEJB"

 

Solution:

Write an aspect to handle this.    Considering that this is my first aspect please bear with me as you go through this scenario.

 

public aspect DoLog {

    String callID=null;
  

    pointcut DoLog(AbstractBusinessService businessService) :execution(* execute(..)) && this(businessService);
   
    before (AbstractBusinessService businessService) : DoLog(businessService) {
           System.out.println("Entering service="+businessService.getClass().getName()+" NDC_MAXDEPTH="+ApplicationProperties.getProperty("NDC_MAXDEPTH")+ " CurrentDepth="+NDC.getDepth());
            if (NDC.getDepth()<(new Integer(ApplicationProperties.getProperty("NDC_MAXDEPTH")).intValue())){
                  callID=ApplicationProperties.getProperty("NDC_PREFIX")+System.currentTimeMillis();
                  NDC.push(callID);
                  System.out.println("Pushed Context for service="+businessService.getClass().getName()+" CallId="+callID);
            }
    }

  after (AbstractBusinessService businessService) : DoLog(businessService) {
    if (callID!=null){
    System.out.println("Popping Context for service="+businessService.getClass().getName()+" CallId="+callID);
          NDC.pop();
          if (NDC.getDepth()==0){
             NDC.remove();
             System.out.println("Removed contexts");
          }
      }
   System.out.println("Exiting service="+businessService.getClass().getName()+ApplicationProperties.getProperty("NDC_MAXDEPTH")+" current depth="+NDC.getDepth());
  }
    
}

There is one problem with this aspect.   It is very unpredictable as it remembers the state in the callID variable.   I think what I intended to do (and struggling to understand how to do this in aspectj) is that I declare a variable callID inside the "execute" method of the ServiceA, ServiceB,ServiceC classes and use a NDC.push() and pop.   For example I had not used aspect, I would have written it like...

public class ServiceA{

......

public ..execute(...){

String callID=null;

           System.out.println("Entering service="+this.getClass().getName()+" NDC_MAXDEPTH="+ApplicationProperties.getProperty("NDC_MAXDEPTH")+ " CurrentDepth="+NDC.getDepth());
            if (NDC.getDepth()<(new Integer(ApplicationProperties.getProperty("NDC_MAXDEPTH")).intValue())){
                  callID=ApplicationProperties.getProperty("NDC_PREFIX")+System.currentTimeMillis();
                  NDC.push(callID);
                  System.out.println("Pushed Context for service="+businessService.getClass().getName()+" CallId="+callID);
            }

.............

    if (callID!=null){
    System.out.println("Popping Context for service="+this.getClass().getName()+" CallId="+callID);
          NDC.pop();
          if (NDC.getDepth()==0){
             NDC.remove();
             System.out.println("Removed contexts");
          }
      }
   System.out.println("Exiting service="+businessService.getClass().getName()+ApplicationProperties.getProperty("NDC_MAXDEPTH")+" current depth="+NDC.getDepth());
  }

}

and Service B would be like

 

public class ServiceB{

......

public ..execute(...){

String callID=null;

           System.out.println("Entering service="+this.getClass().getName()+" NDC_MAXDEPTH="+ApplicationProperties.getProperty("NDC_MAXDEPTH")+ " CurrentDepth="+NDC.getDepth());
            if (NDC.getDepth()<(new Integer(ApplicationProperties.getProperty("NDC_MAXDEPTH")).intValue())){
                  callID=ApplicationProperties.getProperty("NDC_PREFIX")+System.currentTimeMillis();
                  NDC.push(callID);
                  System.out.println("Pushed Context for service="+businessService.getClass().getName()+" CallId="+callID);
            }

.............

    if (callID!=null){
    System.out.println("Popping Context for service="+businessService.getClass().getName()+" CallId="+callID);
          NDC.pop();
          if (NDC.getDepth()==0){
             NDC.remove();
             System.out.println("Removed contexts");
          }
      }
   System.out.println("Exiting service="+businessService.getClass().getName()+ApplicationProperties.getProperty("NDC_MAXDEPTH")+" current depth="+NDC.getDepth());
  }

}

and serviceC would be...

 

public class ServiceC{

......

public ..execute(...){

String callID=null;

           System.out.println("Entering service="+this.getClass().getName()+" NDC_MAXDEPTH="+ApplicationProperties.getProperty("NDC_MAXDEPTH")+ " CurrentDepth="+NDC.getDepth());
            if (NDC.getDepth()<(new Integer(ApplicationProperties.getProperty("NDC_MAXDEPTH")).intValue())){
                  callID=ApplicationProperties.getProperty("NDC_PREFIX")+System.currentTimeMillis();
                  NDC.push(callID);
                  System.out.println("Pushed Context for service="+businessService.getClass().getName()+" CallId="+callID);
            }

.............

    if (callID!=null){
    System.out.println("Popping Context for service="+businessService.getClass().getName()+" CallId="+callID);
          NDC.pop();
          if (NDC.getDepth()==0){
             NDC.remove();
             System.out.println("Removed contexts");
          }
      }
   System.out.println("Exiting service="+businessService.getClass().getName()+ApplicationProperties.getProperty("NDC_MAXDEPTH")+" current depth="+NDC.getDepth());
  }

}

 

May be I am missing something fundamental about AspectJ.    I would appreciate if you can share with me your approach to this problem using aspectj.

 

Many Thanks

Sekar

Confidentiality Notice: The information contained in this e-mail and any attachments (including, but not limited to, any attached e-mails) may be legally privileged and confidential. If you are not an intended recipient, you are hereby notified that any dissemination, distribution or copying of this e-mail is strictly prohibited. If you have received this e-mail in error, please notify the sender and permanently delete the e-mail and any attachments immediately. You should not retain, copy or use this e-mail or any attachment for any purpose, nor disclose all or any part of the contents to any other person. Thank you.