Spring aop: Pointcut defined for subclasses but only one subclass is invoked

Question

I am defining a JobProcess with a method Object process( JobContext jobContext ); with an impl called JobProcessImpl. Whenever this JobProcessImpl.process method is executed, I want to spy with more than one subclass. I want all this subclasses to be executed.

The spy class is defined as base class Task to look for JobProcessImpl.process invocation.

In the output, I always see that only log from AnnotationTask and not from ReviewTask.

Please let me know, if it is possible and what is the issue.

I tried for 2 days on solving this by following various posts.

package com.spring.aspect.dynamicflow.activity;

import com.spring.aspect.dynamicflow.entity.JobContext;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
@Aspect
public abstract class Task {

    private static final Logger log = LoggerFactory.getLogger( Task.class );

    @Around ( "execution(public java.lang.Object com.spring.aspect.dynamicflow.process.JobProcessImpl.process(..)) " + "&& args(context)" )
    public Object task( JobContext context ) {
        log.info( "This is the base task and needs to overridden by the derived task for the job id: {} ", context.getJobId() );

        return  context;
    }
}

Base Classes: AnnotationTask

package com.spring.aspect.dynamicflow.activity;

import com.spring.aspect.dynamicflow.entity.JobContext;
import com.spring.aspect.dynamicflow.entity.TaskStatus;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
public class AnnotationTask extends Task {

    private static final Logger log = LoggerFactory.getLogger( AnnotationTask.class );

    @Override
    public Object task( JobContext context ) {
        log.info( "AnnotationTask's task" );

        /*
         * do some validation if annotation is completed or not
         */

        log.info( "Setting that the annotation is done." );
        context.setAnnotationTaskStatus( TaskStatus.COMPLETED );
        return "AnnotationTask Completed";
    }

ReviewTask

package com.spring.aspect.dynamicflow.activity;

import com.spring.aspect.dynamicflow.entity.JobContext;
import com.spring.aspect.dynamicflow.entity.TaskStatus;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
public class ReviewTask extends Task {

    private static final Logger log = LoggerFactory.getLogger( ReviewTask.class );

    @Override
    public Object task( JobContext context ) {
        log.info( "ReviewTask's task" );

        /*
         * do some validation if annotation is completed or not
         */
        log.info( "not completing the review task due to some reason" );
        context.setReviewTaskStatus( TaskStatus.IN_PROGRESS );
        return "ReviewTask Not Completed";
    }
}

I want these task execution by spying on them with TaskAspects.

package com.spring.aspect.dynamicflow.aspect;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
@Aspect
public class TaskAspects {

    private static final Logger log = LoggerFactory.getLogger( TaskAspects.class );

    @Around( "within(com.spring.aspect.dynamicflow.activity.Task+) ")
    public Object handleTask( ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        log.info( "Handling the task aspects." );
        log.info( "" + proceedingJoinPoint.getThis() );

        return proceedingJoinPoint.proceed();
    }

}

I have an enum classes as well (giving for the code completion)

package com.spring.aspect.dynamicflow.entity;

public enum TaskStatus {
    IN_PROGRESS, COMPLETED
}

JobProcess

package com.spring.aspect.dynamicflow.process;

import com.spring.aspect.dynamicflow.entity.JobContext;

public interface JobProcess {

    Object process( JobContext jobContext );
}

JobProcessImpl

package com.spring.aspect.dynamicflow.process;

import com.spring.aspect.dynamicflow.entity.JobContext;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
public class JobProcessImpl implements JobProcess {

    Logger logger = LoggerFactory.getLogger( JobProcessImpl.class );
    @Override
    public Object process( JobContext jobContext ) {
        logger.info( "Shouldn't get printed Processing the job with jobid {}", jobContext.getJobId() );
        return null;
    }
}

Answer 1

As soon as I posted this, I tried to change the ReviewTask and AnnotationTask with

@Override
    public Object task( ProceedingJoinPoint proceedingJoinPoint, JobContext context ) throws Throwable {
        log.info( "ReviewTask's task" );

        /*
         * do some validation if annotation is completed or not
         */
        log.info( "not completing the review task due to some reason" );
        context.setReviewTaskStatus( TaskStatus.IN_PROGRESS );
        return proceedingJoinPoint.proceed();
    }

and that solved my issue.

Answer 2

You are right, I just noticed that TaskAspects not get triggered at all. I do not see any logs from TaskAspects. Can I use AspectJ inside spring-boot without any spring-aop? Thanks for taking a look and notifying. Much appreaciated.

Basically you just remove the @Component annotations from the aspects you want use via AspectJ and add those aspects to file src/main/resources/org/aspectj/aop.xml (assuming you use Maven to build your project):

<!DOCTYPE aspectj PUBLIC "-//AspectJ//DTD//EN" "http://www.eclipse.org/aspectj/dtd/aspectj.dtd">
<aspectj>

  <weaver options="-verbose -showWeaveInfo">
    <!-- only weave classes in our application-specific packages -->
    <include within="com.spring.aspect.dynamicflow..*"/>
  </weaver>

  <aspects>
    <aspect name="com.spring.aspect.dynamicflow.aspect.TaskAspects"/>
    <aspect name="com.spring.aspect.dynamicflow.activity.AnnotationTask"/>
    <aspect name="com.spring.aspect.dynamicflow.activity.ReviewTask"/>
  </aspects>

</aspectj>

Then you start your application with -javaagent:/path/to/aspectjweaver.jar, e.g.something like:

-javaagent:"c:\Users\me\.m2\repository\org\aspectj\aspectjweaver\1.9.4\aspectjweaver-1.9.4.jar"

You can also use both agents, AspectJ Weaver and Spring Instrument, together on the Java command line, e.g.

-javaagent:"c:\Users\me\.m2\repository\org\aspectj\aspectjweaver\1.9.4\aspectjweaver-1.9.4.jar" -javaagent:"c:\Program Files\Java\spring-framework-5.1.9.RELEASE\libs\spring-instrument-5.1.9.RELEASE.jar"

For your convenience and in order to have a example project for myself, I shared my working example in a GitHub repository. There is a branch for Spring AOP and another branch for AspectJ LTW. The diff between those branches looks like this:

diff --git a/src/main/java/com/spring/aspect/dynamicflow/Application.java b/src/main/java/com/spring/aspect/dynamicflow/Application.java
index 2a7021e..3a7636f 100644
--- a/src/main/java/com/spring/aspect/dynamicflow/Application.java
+++ b/src/main/java/com/spring/aspect/dynamicflow/Application.java
@@ -8,6 +8,16 @@ import org.springframework.boot.SpringApplication;
 import org.springframework.boot.autoconfigure.SpringBootApplication;
 import org.springframework.context.ConfigurableApplicationContext;
 
+/**
+ * Run this from your IDE with
+ *
+ * a) either just -javaagent:/path/to/aspectjweaver.jar and without @EnableLoadTimeWeaving
+ *
+ * b) or with both -javaagent:/path/to/aspectjweaver.jar -javaagent:/path/to/spring-instrument.jar,
+ * either with or without @EnableLoadTimeWeaving. What benefit this has, I don't know.
+ *
+ * See also my extensive comment in Application class.
+ */
 @SpringBootApplication
 public class Application {
   private static final Logger log = LoggerFactory.getLogger(Application.class);
diff --git a/src/main/java/com/spring/aspect/dynamicflow/ApplicationConfig.java b/src/main/java/com/spring/aspect/dynamicflow/ApplicationConfig.java
index b4698e1..649a6ca 100644
--- a/src/main/java/com/spring/aspect/dynamicflow/ApplicationConfig.java
+++ b/src/main/java/com/spring/aspect/dynamicflow/ApplicationConfig.java
@@ -3,8 +3,34 @@ package com.spring.aspect.dynamicflow;
 import org.springframework.context.annotation.ComponentScan;
 import org.springframework.context.annotation.Configuration;
 import org.springframework.context.annotation.EnableAspectJAutoProxy;
+import org.springframework.context.annotation.EnableLoadTimeWeaving;
 
+import static org.springframework.context.annotation.EnableLoadTimeWeaving.AspectJWeaving.ENABLED;
+
+/**
+ * Remarks about AspectJ load-time weaving(LTW) in Spring:
+ *
+ * According to the Spring manual it should be enough to put spring-instrument.jar is on the JVM command line
+ * in combination with @EnableLoadTimeWeaving. Actually this does help Spring detect the AspectJ weaver,
+ * I can see the aspects loaded. But obviously this happens too late after the application classes are
+ * already loaded, so the aspects do not have any effect. I even added a static block
+ * static { logger.info("JobProcessImpl class was loaded"); } to JobProcessImpl in order to check it an
+ * the log output occurs right before the aspects are being activated, which of course is too late.
+ *
+ * LTW works if
+ *
+ * a) either I have both Java agents aspectjweaver.jar and spring-instrument.jar on JVM command line
+ * in combination with @EnableLoadTimeWeaving (but then it tries to weave twice, I can see errors in the log)
+ * or without @EnableLoadTimeWeaving (no errors in the log)
+ *
+ * b) or if I only use aspectjweaver.jar without @EnableLoadTimeWeaving.
+ *
+ * The latter is no surprise because AspectJ is independent of Spring and of course works even if Spring is
+ * unaware of its presence. But if I want to advertise its presence via @EnableLoadTimeWeaving, I do not
+ * understand why spring-instrument.jar is not enough, as described in the Spring manual.
+ */
 @Configuration
 @EnableAspectJAutoProxy
 @ComponentScan("com.spring.aspect.dynamicflow")
+//@EnableLoadTimeWeaving(aspectjWeaving = ENABLED)
 public class ApplicationConfig {}
diff --git a/src/main/java/com/spring/aspect/dynamicflow/activity/AnnotationTask.java b/src/main/java/com/spring/aspect/dynamicflow/activity/AnnotationTask.java
index 3c6d5c4..bbdd5b1 100644
--- a/src/main/java/com/spring/aspect/dynamicflow/activity/AnnotationTask.java
+++ b/src/main/java/com/spring/aspect/dynamicflow/activity/AnnotationTask.java
@@ -6,9 +6,7 @@ import org.aspectj.lang.ProceedingJoinPoint;
 import org.aspectj.lang.annotation.Aspect;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
-import org.springframework.stereotype.Component;
 
-@Component
 @Aspect
 public class AnnotationTask extends Task {
   private static final Logger log = LoggerFactory.getLogger(AnnotationTask.class);
diff --git a/src/main/java/com/spring/aspect/dynamicflow/activity/ReviewTask.java b/src/main/java/com/spring/aspect/dynamicflow/activity/ReviewTask.java
index ece0ff6..f364da2 100644
--- a/src/main/java/com/spring/aspect/dynamicflow/activity/ReviewTask.java
+++ b/src/main/java/com/spring/aspect/dynamicflow/activity/ReviewTask.java
@@ -6,9 +6,7 @@ import org.aspectj.lang.ProceedingJoinPoint;
 import org.aspectj.lang.annotation.Aspect;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
-import org.springframework.stereotype.Component;
 
-@Component
 @Aspect
 public class ReviewTask extends Task {
   private static final Logger log = LoggerFactory.getLogger(ReviewTask.class);
diff --git a/src/main/java/com/spring/aspect/dynamicflow/activity/Task.java b/src/main/java/com/spring/aspect/dynamicflow/activity/Task.java
index 3f1f9ce..93b3b73 100644
--- a/src/main/java/com/spring/aspect/dynamicflow/activity/Task.java
+++ b/src/main/java/com/spring/aspect/dynamicflow/activity/Task.java
@@ -6,9 +6,7 @@ import org.aspectj.lang.annotation.Around;
 import org.aspectj.lang.annotation.Aspect;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
-import org.springframework.stereotype.Component;
 
-@Component
 @Aspect
 public abstract class Task {
   private static final Logger log = LoggerFactory.getLogger(Task.class);
diff --git a/src/main/java/com/spring/aspect/dynamicflow/aspect/TaskAspects.java b/src/main/java/com/spring/aspect/dynamicflow/aspect/TaskAspects.java
index 3bff7b5..a09d9d6 100644
--- a/src/main/java/com/spring/aspect/dynamicflow/aspect/TaskAspects.java
+++ b/src/main/java/com/spring/aspect/dynamicflow/aspect/TaskAspects.java
@@ -5,9 +5,7 @@ import org.aspectj.lang.annotation.Around;
 import org.aspectj.lang.annotation.Aspect;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
-import org.springframework.stereotype.Component;
 
-@Component
 @Aspect
 public class TaskAspects {
   private static final Logger log = LoggerFactory.getLogger(TaskAspects.class);
diff --git a/src/main/resources/org/aspectj/aop.xml b/src/main/resources/org/aspectj/aop.xml
new file mode 100644
index 0000000..56342b4
--- /dev/null
+++ b/src/main/resources/org/aspectj/aop.xml
@@ -0,0 +1,15 @@
+<!DOCTYPE aspectj PUBLIC "-//AspectJ//DTD//EN" "http://www.eclipse.org/aspectj/dtd/aspectj.dtd">
+<aspectj>
+
+  <weaver options="-verbose -showWeaveInfo">
+    <!-- only weave classes in our application-specific packages -->
+    <include within="com.spring.aspect.dynamicflow..*"/>
+  </weaver>
+
+  <aspects>
+    <aspect name="com.spring.aspect.dynamicflow.aspect.TaskAspects"/>
+    <aspect name="com.spring.aspect.dynamicflow.activity.AnnotationTask"/>
+    <aspect name="com.spring.aspect.dynamicflow.activity.ReviewTask"/>
+  </aspects>
+
+</aspectj>

BTW, I also quickly tried to get a combination of Spring AOP aspects (Task subclasses) and AspectJ aspect (TaskAspects, really a horrible name, why not TasksAspect or TaskInterceptor?). Even though the Spring manual and many users on mailing lists say, it is easy to combine both approaches even without extra configuration, I could not make it run the way I wanted. So for now I have no solution for that. Probably I just made a small mistake. I am an AspectJ expert, but actually never use Spring or Spring AOP, sorry.

---

Update: I forgot to mention that in my repository I also solved this problem I mentioned in my comment before:

If you really use AspectJ LTW scenario, your TaskAspects aspect gets triggered too often because within(com.spring.aspect.dynamicflow.activity.Task+) in AspectJ not only intercepts method executions but also object and class initialisation, field access, method calls to other classes etc. So either you use AspectJ LTW and it prints too much or (...)

This is really true if you use that pointcut. The log output (time stamps, log channel info etc. cut off from log output) would be:

Handling the task aspects.
  staticinitialization(com.spring.aspect.dynamicflow.activity.Task.<clinit>)
Handling the task aspects.
  call(Logger org.slf4j.LoggerFactory.getLogger(Class))
Handling the task aspects.
  set(Logger com.spring.aspect.dynamicflow.activity.Task.log)
Handling the task aspects.
  staticinitialization(com.spring.aspect.dynamicflow.activity.AnnotationTask.<clinit>)
Handling the task aspects.
  call(Logger org.slf4j.LoggerFactory.getLogger(Class))
Handling the task aspects.
  set(Logger com.spring.aspect.dynamicflow.activity.AnnotationTask.log)
Handling the task aspects.
  execution(com.spring.aspect.dynamicflow.activity.Task())
Handling the task aspects.
  execution(com.spring.aspect.dynamicflow.activity.AnnotationTask())
Handling the task aspects.
  execution(Object com.spring.aspect.dynamicflow.activity.AnnotationTask.task(ProceedingJoinPoint, JobContext))
Handling the task aspects.
  get(Logger com.spring.aspect.dynamicflow.activity.AnnotationTask.log)
Handling the task aspects.
  call(void org.slf4j.Logger.info(String))
AnnotationTask's task
Handling the task aspects.
  get(Logger com.spring.aspect.dynamicflow.activity.AnnotationTask.log)
Handling the task aspects.
  call(void org.slf4j.Logger.info(String))
  Setting that the annotation is done.
Handling the task aspects.
  get(TaskStatus com.spring.aspect.dynamicflow.entity.TaskStatus.COMPLETED)
Handling the task aspects.
  call(void com.spring.aspect.dynamicflow.entity.JobContext.setAnnotationTaskStatus(TaskStatus))
Handling the task aspects.
  call(Object org.aspectj.lang.ProceedingJoinPoint.proceed())
Handling the task aspects.
  staticinitialization(com.spring.aspect.dynamicflow.activity.ReviewTask.<clinit>)
Handling the task aspects.
  call(Logger org.slf4j.LoggerFactory.getLogger(Class))
Handling the task aspects.
  set(Logger com.spring.aspect.dynamicflow.activity.ReviewTask.log)
Handling the task aspects.
  execution(com.spring.aspect.dynamicflow.activity.Task())
Handling the task aspects.
  execution(com.spring.aspect.dynamicflow.activity.ReviewTask())
Handling the task aspects.
  execution(Object com.spring.aspect.dynamicflow.activity.ReviewTask.task(ProceedingJoinPoint, JobContext))
Handling the task aspects.
  get(Logger com.spring.aspect.dynamicflow.activity.ReviewTask.log)
Handling the task aspects.
  call(void org.slf4j.Logger.info(String))
ReviewTask's task
Handling the task aspects.
  get(Logger com.spring.aspect.dynamicflow.activity.ReviewTask.log)
Handling the task aspects.
  call(void org.slf4j.Logger.info(String))
  Setting that the review is done.
Handling the task aspects.
  get(TaskStatus com.spring.aspect.dynamicflow.entity.TaskStatus.IN_PROGRESS)
Handling the task aspects.
  call(void com.spring.aspect.dynamicflow.entity.JobContext.setReviewTaskStatus(TaskStatus))
Handling the task aspects.
  call(Object org.aspectj.lang.ProceedingJoinPoint.proceed())
Processing the job with jobid 11

I also cut out AspectJ weaver log messages (some of them errors) from in between the log lines. You see 29x "Handling the task aspects" instead of only 2x, which is why I changed the pointcut to within(com.spring.aspect.dynamicflow.activity.Task+) && execution(* task(..)) for you. Now the log output looks as expected:

Handling the task aspects.
  execution(Object com.spring.aspect.dynamicflow.activity.AnnotationTask.task(ProceedingJoinPoint, JobContext))
AnnotationTask's task
  Setting that the annotation is done.
Handling the task aspects.
  execution(Object com.spring.aspect.dynamicflow.activity.ReviewTask.task(ProceedingJoinPoint, JobContext))
ReviewTask's task
  Setting that the review is done.
Processing the job with jobid 11