java aop aspectj aspect load-time-weaving

AspectJ AOP LTW not working with dynamic loading of javaagent

It contains 2 modules:

aop-lib - Aspects used as lib. It contains the following classes
1. Wrap.java - It's the annotation used to attach advice
2. WrapDef.java - It is the definition of the above mentioned Wrap annotation.
aop-app - Uses the above aspect lib
1. DynamicLoad.java - class to load javaagent dynamically
2. Main.java - Main class which uses Wrap annotation.

Dir structure is as follows:

.
├── README.md
├── aop-app
│   ├── pom.xml
│   └── src
│       └── main
│           └── java
│               └── com
│                   └── aop
│                       └── app
│                           ├── DynamicLoad.java
│                           └── Main.java
└── aop-lib
    ├── pom.xml
    └── src
        └── main
            └── java
                └── com
                    └── aop
                        └── app
                            └── lib
                                ├── Wrap.java
                                └── WrapDef.java

I'm trying to use the aspect lib aop-lib (an AOP advice lib) inside aop-app through Load Time Weaving (LTW) by dynamically loading the javaagent as mentioned in the official docs. But it's not working.

Following are the contents of Wrap.java

@Target({ElementType.METHOD, ElementType.TYPE})
@Retention(value = RetentionPolicy.RUNTIME)
public @interface Wrap { }

Following are the contents of WrapDef.java

@Aspect
public class WrapDef {
    private static final Logger logger = LoggerFactory.getLogger(WrapDef.class);

    public static boolean loaded = false;

    @Around("@annotation( wrapAnnotation ) && execution(* *(..))")
    public Object processSystemRequest(final ProceedingJoinPoint pjp, Wrap wrapAnnotation)
            throws Throwable {
        logger.debug("before wrap");
        Object o = pjp.proceed();
        logger.debug("after wrap");
        return o;
    }

    static {
        System.out.println("Loading");
        WrapDef.loaded = true;
    }
    public static void reportLoaded() {
        System.out.println("loaded : " + loaded);
    }
}

Following are the contents of Main.java:

public class Main {

    private static final Logger logger = LoggerFactory.getLogger(Main.class);

    @Wrap
    public void myFunc(){
        logger.debug("inside myFunc");
    }

    public static void main(String[] args) throws NoSuchMethodException, IllegalAccessException, InvocationTargetException {

        boolean dynamicLoad = Boolean.getBoolean("dynamicLoad");
        if(dynamicLoad){
            Main.isAdviceClassLoaded();           //To see if WrapDef.java is loaded or not.
            if(!DynamicLoad.isAspectJAgentLoaded()) {
                logger.error("AspectJ Not Loaded. Existing.");
                System.exit(0);
            }
            Main.isAdviceClassLoaded();           //To see if WrapDef.java is loaded or not.
        }

        new Main().myFunc();
    }

    private static void isAdviceClassLoaded() throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {
        java.lang.reflect.Method m = ClassLoader.class.getDeclaredMethod("findLoadedClass", String.class);
        m.setAccessible(true);
        ClassLoader cl = ClassLoader.getSystemClassLoader();
        Object test1 = m.invoke(cl, "com.aop.app.lib.WrapDef");
        boolean loaded = test1 != null;
        System.out.println("com.aop.app.lib.WrapDef Loaded : " + loaded);
    }

}

With javaagent as cmd line arg, it works perfectly fine:

$ java -javaagent:deploy/lib/aspectjweaver-1.9.1.jar -classpath aop-app-1.0.jar:deploy/lib/* com.aop.app.Main
14:02:45.384 [main] DEBUG com.aop.app.lib.WrapDef - before wrap
14:02:45.391 [main] DEBUG com.aop.app.Main - inside myFunc
14:02:45.391 [main] DEBUG com.aop.app.lib.WrapDef - after wrap

But, with Dynamic loading of javaagent, it gives the following output:

$ java -DdynamicLoad=true -DAGENT_PATH=deploy/lib/aspectjweaver-1.9.1.jar -classpath aop-app-1.0.jar:deploy/lib/* com.aop.app.Main
com.aop.app.lib.WrapDef Loaded : false                   //The WrapDef is NOT loaded before JAVAAGENT is Loaded - which is correct
java.lang.UnsupportedOperationException: AspectJ weaving agent was neither started via '-javaagent' (preMain) nor attached via 'VirtualMachine.loadAgent' (agentMain)
loading javaAgent deploy/lib/aspectjweaver-1.9.1.jar
loaded javaAgent deploy/lib/aspectjweaver-1.9.1.jar      //The JAVAAGENT is Dynamically Loaded - which is correct
com.aop.app.lib.WrapDef Loaded : false                   //The WrapDef is STILL NOT loaded even AFTER JAVAAGENT is Loaded - THIS IS THE ISSUE
15:53:08.543 [main] DEBUG com.aop.app.Main - inside myFunc

The official docs does say that any classes loaded before attachment will not be woven. But, on the contrary as you can see in the above output, the WrapDef class is not loaded at all.

Also, note that I'm using aspectj-maven-plugin in my aop-lib/pom.xml, with the following options:

<outxml>true</outxml>                           //creates META-INF/aop-ajc.xml
<showWeaveInfo>true</showWeaveInfo>             //supposed to create <weaver options="-showWeaveInfo"/> BUT DOES NOT WORK
<verbose>true</verbose>                         //supposed to create <weaver options="-verbose"/> BUT DOES NOT WORK

So, it creates META-INF/aop-ajc.xml inside aop-lib-1.0.jar with the following content:

<aspectj>
<aspects>
<aspect name="com.aop.app.lib.WrapDef"/>
</aspects>
</aspectj>

but the other tags corresponding to showWeaveInfo & verbose are not created in META-INF/aop-ajc.xml. This is another thing that is not working here.

If you require any other info - I shall provide it.

Any help is appreciated.

Solution

The explanation is quite simple: You are testing the weaving agent directly in class Main which is already loaded before you attach that very agent from that class. So you have to avoid classes which you like to be woven to be loaded too early. I suggest you put method myFunc() (horrible name, by the way) into another class. How about that?

package com.aop.app;

import com.aop.app.lib.Wrap;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Application {
  private static final Logger logger = LoggerFactory.getLogger(Application.class);

  @Wrap
  public void myFunc(){
    logger.debug("inside myFunc");
  }

  public static void main(String[] args) {
    new Application().myFunc();
  }
}

Then in the last line of Main.main(..) you start the actual application you want woven:

Application.main(null);

This will yield the following output:

com.aop.app.lib.WrapDef Loaded : false
java.lang.UnsupportedOperationException: AspectJ weaving agent was neither started via '-javaagent' (preMain) nor attached via 'VirtualMachine.loadAgent' (agentMain)
loading javaAgent aop-app/target/deploy/lib/aspectjweaver-1.9.1.jar
loaded javaAgent aop-app/target/deploy/lib/aspectjweaver-1.9.1.jar
com.aop.app.lib.WrapDef Loaded : false
Loading
07:56:21.703 [main] DEBUG com.aop.app.lib.WrapDef - before wrap
07:56:21.716 [main] DEBUG com.aop.app.Application - inside myFunc
07:56:21.716 [main] DEBUG com.aop.app.lib.WrapDef - after wrap

P.S.: Do you really think it is easier for users of your aspect library to specify two properties on the JVM command line instead of just using -javaagent:/path/to/aspectweaver.jar? Anyway, you probably have your reasons to use dynamic weaver attachment. In a way I am kind of happy that someone uses the functionality I added to AspectJ myself a while ago. ;-)