[aspectj-users] I have changed my logger aspect and not it displays some

[Mark <mark.kharitonov@xxxxxxxxx>]

Hi,
These are my logger aspects, the working edition:

LoggerAspect:
==================================================
public abstract aspect LoggerAspect {
  // This declaration is never used by the aspect itself. It simply provides
the default implementation
  // of the ILoggable.getLogger() method.
  public Logger ILoggable.getLogger() {
    return LoggerAspect.getLogger(this.getClass());
  }
  
  public static Logger getLogger(@SuppressWarnings("rawtypes") Class clazz)
{
    LoggerHolderAspect holder = LoggerHolderAspect.aspectOf(clazz);
    return holder.getLogger();
  }

  public abstract pointcut loggedScope();
  public abstract pointcut loggedMethodScope();
  public abstract pointcut loggedMethods();
  pointcut caughtException(Exception e) : handler(Exception+) && args(e);
  
  private static Logger getLogger(JoinPoint.StaticPart jp) {
    return getLoggerHolder(jp).getLogger();
  }

  private static LoggerHolderAspect getLoggerHolder(JoinPoint.StaticPart jp)
{
    return
LoggerHolderAspect.aspectOf(jp.getSignature().getDeclaringType());
  }
  
  before(): staticinitialization(!LoggerAspect+) && loggedScope() {
    getLoggerHolder(thisJoinPointStaticPart).initLogger();
  }

  before(): loggedScope() && loggedMethods() {
    logBefore(getLogger(thisJoinPointStaticPart), thisJoinPoint);
  }

  after() returning (Object result): loggedScope() && loggedMethods() {
    logAfterReturning(getLogger(thisJoinPointStaticPart), thisJoinPoint,
result);
  }
  
  after() throwing (Exception e): loggedScope() && loggedMethods() &&
!cflowbelow(loggedMethods()) {
    logAfterThrowing(getLogger(thisJoinPointStaticPart), thisJoinPoint, e);
  }

  before(Exception e) : caughtException(e) && loggedScope() &&
loggedMethodScope() {
    logCaughtException(getLogger(thisJoinPointStaticPart),
thisEnclosingJoinPointStaticPart, thisJoinPoint, e);
  }
  ...  
}
==================================================

ResourceHandlerLoggerAspect:
==================================================
public aspect ResourceHandlerLoggerAspect extends LoggerAspect {
  declare @type : @Path * : @LogMe;
  declare parents: (@Path *) implements ILoggable;
  
  public pointcut loggedScope() : within(@Path *);
  public pointcut loggedMethodScope() : withincode(@(GET || PUT || POST ||
DELETE) public * *.*(..));
  public pointcut loggedMethods() : execution(@(GET || PUT || POST ||
DELETE) public * *.*(..));
}
==================================================

ServiceLoggerAspect:
==================================================
public aspect ServiceLoggerAspect extends LoggerAspect {
  declare @type : com.shunra.poc..*Service : @LogMe;
  declare parents: com.shunra.poc..*Service implements ILoggable;

  public pointcut loggedScope() : within(com.shunra.poc..*Service);
  public pointcut loggedMethodScope() : withincode(public * *.*(..));
  public pointcut loggedMethods() : execution(public * *.*(..));
}
==================================================

Now, these work fine. When I execute a post request, I get the following
output:
==================================================
2011-12-15 20:59:23,297 null[Dispatcher-0] DEBUG
com.shunra.poc.handlers.UserHandler - postUser(entity: User [Id=1,
FirstName=Maayan, LastName=Kharitonov, Age=6])
2011-12-15 20:59:24,104 null[Dispatcher-0] DEBUG com.shunra.poc.UserService
- post(entity: User [Id=0, FirstName=Maayan, LastName=Kharitonov, Age=6])
2011-12-15 20:59:24,108 null[Dispatcher-0] TRACE com.shunra.poc.UserService
- post(entity: User [Id=3, FirstName=Maayan, LastName=Kharitonov, Age=6])
DONE
2011-12-15 20:59:24,120 null[Dispatcher-0] TRACE
com.shunra.poc.handlers.UserHandler - postUser(entity: User [Id=3,
FirstName=Maayan, LastName=Kharitonov, Age=6]) = EntityPostResult [Id=3]
==================================================


Now, I decided that the loggedScope pointcut does not have to be abstract
and so I made several changes:

LoggerAspect patch:
==================================================
@@ -20,7 +20,7 @@
     return holder.getLogger();
   }
 
-  public abstract pointcut loggedScope();
+  public pointcut loggedScope() : within(@LogMe *);
   public abstract pointcut loggedMethodScope();
   public abstract pointcut loggedMethods();
   public pointcut methodWoutArgs() : execution(* *.*()); 
@@ -39,7 +39,7 @@
   //pointcut staticContext() : !this(Object);
   //pointcut nonStaticContext(Object obj) : this(obj);
   //pointcut excluded() : within(LoggerAspect+);
-  pointcut caughtException(Exception e) : handler(Exception+) && args(e);
+  public pointcut caughtException(Exception e) : handler(Exception+) &&
args(e);
   
   private static Logger getLogger(JoinPoint.StaticPart jp) {
     return getLoggerHolder(jp).getLogger();
==================================================

ResourceHandlerLoggerAspect patch:
==================================================
@@ -18,7 +18,6 @@
   // In any case, the logger is available from the static
LoggerAspect.getLogger(Class) method.
   declare parents: (@Path *) implements ILoggable;
   
-  public pointcut loggedScope() : within(@Path *);
   public pointcut loggedMethodScope() : withincode(@(GET || PUT || POST ||
DELETE) public * *.*(..));
   public pointcut loggedMethods() : execution(@(GET || PUT || POST ||
DELETE) public * *.*(..));
==================================================

ServiceLoggerAspect patch:
==================================================
@@ -6,7 +6,6 @@
   declare @type : com.shunra.poc..*Service : @LogMe;
   declare parents: com.shunra.poc..*Service implements ILoggable;
 
-  public pointcut loggedScope() : within(com.shunra.poc..*Service);
   public pointcut loggedMethodScope() : withincode(public * *.*(..));
   public pointcut loggedMethods() : execution(public * *.*(..));
 }
=================================================

Innocent, right? But observe what outputs:
=================================================
2011-12-15 21:09:51,814 null[Dispatcher-0] DEBUG
com.shunra.poc.handlers.UserHandler - postUser(entity: User [Id=1,
FirstName=Maayan, LastName=Kharitonov, Age=6])
2011-12-15 21:09:52,926 null[Dispatcher-0] DEBUG
com.shunra.poc.handlers.UserHandler - postUser(entity: User [Id=1,
FirstName=Maayan, LastName=Kharitonov, Age=6])
2011-12-15 21:10:00,373 null[Dispatcher-0] DEBUG com.shunra.poc.UserService
- post(entity: User [Id=0, FirstName=Maayan, LastName=Kharitonov, Age=6])
2011-12-15 21:10:00,375 null[Dispatcher-0] TRACE com.shunra.poc.UserService
- post(entity: User [Id=3, FirstName=Maayan, LastName=Kharitonov, Age=6])
DONE
2011-12-15 21:10:00,386 null[Dispatcher-0] TRACE
com.shunra.poc.handlers.UserHandler - postUser(entity: User [Id=3,
FirstName=Maayan, LastName=Kharitonov, Age=6]) = EntityPostResult [Id=3]
2011-12-15 21:10:00,386 null[Dispatcher-0] TRACE
com.shunra.poc.handlers.UserHandler - postUser(entity: User [Id=3,
FirstName=Maayan, LastName=Kharitonov, Age=6]) = EntityPostResult [Id=3]
=================================================

Note how every UserHandler log message appears twice, while those of
UserService show up just once. How is it possible?

Thanks.

--
View this message in context: http://aspectj.2085585.n4.nabble.com/I-have-changed-my-logger-aspect-and-not-it-displays-some-messages-twice-how-come-tp4202008p4202008.html
Sent from the AspectJ - users mailing list archive at Nabble.com.