AspectJ Load time weaver doesn't detect all classes

Question

I am using Spring's declarative transactions (the @Transactional annotation) in "aspectj" mode. It works in most cases exactly like it should, but for one it doesn't. We can call it Lang (because that's what it's actually called).

I have been able to pinpoint the problem to the load time weaver. By turning on debug and verbose logging in aop.xml, it lists all classes being woven. The problematic class Lang is indeed not mentioned in the logs at all.

Then I put a breakpoint at the top of Lang, causing Eclipse to suspend the thread when the Lang class is loaded. This breakpoint is hit while the LTW weaving other classes! So I am guessing it either tries to weave Lang and fails and doesn't output that, or some other class has a reference that forces it to load Lang before it actually gets a chance to weave it.

I am unsure however how to continue to debug this, since I am not able to reproduce it in smaller scale. Any suggestions on how to go on?

---

Update: Other clues are also welcome. For example, how does the LTW actually work? There appears to be a lot of magic happening. Are there any options to get even more debug output from the LTW? I currently have:

<weaver options="-XnoInline -Xreweavable -verbose -debug -showWeaveInfo">

---

I forgot tom mention it before: spring-agent is being used to allow LTW, i.e., the InstrumentationLoadTimeWeaver.

---

Based on the suggestions of Andy Clement I decided to inspect whether the AspectJ transformer is ever even passed the class. I put a breakpoint in ClassPreProcessorAgent.transform(..), and it seems that the Lang class never even reaches that method, despite it being loaded by the same class loader as other classes (an instance of Jetty's WebAppClassLoader).

I then went on to put a breakpoint in InstrumentationLoadTimeWeaver$FilteringClassFileTransformer.transform(..). Not even that one is hit for Lang. And I believe that method should be invoked for all loaded classes, regardless of what class loader they are using. This is starting to look like:

1. A problem with my debugging. Possibly Lang is not loaded at the time when Eclipse reports it is
2. Java bug? Far-fetched, but I suppose it does happen.

---

Next clue: I turned on -verbose:class and it appears as if Lang is being loaded prematurely - probably before the transformer is added to Instrumentation. Oddly, my Eclipse breakpoint does not catch this loading.

This means that Spring is new suspect. there appears to be some processing in ConfigurationClassPostProcessor that loads classes to inspect them. This could be related to my problem.

---

These lines in ConfigurationClassBeanDefinitionReader causes the Lang class to be read:

else if (metadata.isAnnotated(Component.class.getName()) ||
        metadata.hasAnnotatedMethods(Bean.class.getName())) {
    beanDef.setAttribute(CONFIGURATION_CLASS_ATTRIBUTE, CONFIGURATION_CLASS_LITE);
    return true;
}

In particular, metadata.hasAnnotatedMethods() calls getDeclaredMethods() on the class, which loads all parameter classes of all methods in that class. I am guessing that this might not be the end of the problem though, because I think the classes are supposed to be unloaded. Could the JVM be caching the class instance for unknowable reasons?

Answer 1

OK, I have solved the problem. Essentially, it is a Spring problem in conjunction with some custom extensions. If anyone comes across something similar, I will try to explain step by step what is happening.

First of all, we have a custom BeanDefintionParser in our project. This class had the following definition:

private static class ControllerBeanDefinitionParser extends AbstractSingleBeanDefinitionParser {

    protected Class<?> getBeanClass(Element element) {
        try {
            return Class.forName(element.getAttribute("class"));
        } catch (ClassNotFoundException e) {
            throw new RuntimeException("Class " + element.getAttribute("class") + "not found.", e);
        }
    }

// code to parse XML omitted for brevity

}

Now, the problem occurs after all bean definition have been read and BeanDefinitionRegistryPostProcessor begins to kick in. At this stage, a class called ConfigurationClassPostProcessor starts looking through all bean definitions, to search for bean classes annotated with @Configuration or that have methods with @Bean.

In the process of reading annotations for a bean, it uses the AnnotationMetadata interface. For most regular beans, a subclass called AnnotationMetadataVisitor is used. However, when parsing the bean definitions, if you have overriden the getBeanClass() method to return a class instance, like we had, instead a StandardAnnotationMetadata instance is used. When StandardAnnotationMetadata.hasAnnotatedMethods(..) is invoked, it calls Class.getDeclaredMethods(), which in turn causes the class loader to load all classes used as parameters in that class. Classes loaded this way are not correctly unloaded, and thus never weaved, since this happens before the AspectJ transformer registered.

Now, my problem was that I had a class like so:

public class Something {
    private Lang lang;
    public void setLang(Lang lang) {
        this.lang = lang;
    }
}

Then, I had a bean of class Something that was parsed using our custom ControllerBeanDefinitionParser. This triggered the wrong annotation detection procedure, which triggered unexpected class loading, which meant that AspectJ never got a chance to weave Lang.

The solution was to not override getBeanClass(..), but instead override getBeanClassName(..), which according to the documentation is preferable:

private static class ControllerBeanDefinitionParser extends AbstractSingleBeanDefinitionParser {

    protected String getBeanClassName(Element element) {
        return element.getAttribute("class");
    }

// code to parse XML omitted for brevity

}

Lesson of the day: Do not override getBeanClass unless you really mean it. Actually, don't try to write your own BeanDefinitionParser unless you know what you're doing.

Fin.

Answer 2

If your class is not mentioned in the -verbose/-debug output, that suggests to me it is not being loaded by the loader you think it is. Can you be 100% sure that 'Lang' isn't on the classpath of a classloader higher in the hierarchy? Which classloader is loading Lang at the point in time when you trigger your breakpoint?

Also, you don't mention AspectJ version - if you are on 1.6.7 that had issues with ltw for anything but a trivial aop.xml. You should be on 1.6.8 or 1.6.9.

How does ltw actually work?

Put simply, an AspectJ weaver is created for each classloader that may want to weave code. AspectJ is asked if it wants to modify the bytes for a class before it is defined to the VM. AspectJ looks at any aop.xml files it can 'see' (as resources) through the classloader in question and uses them to configure itself. Once configured it weaves the aspects as specified, taking into account all include/exclude clauses.

Andy Clement
AspectJ Project Lead

Answer 3

Option 1) Aspect J is open source. Crack it open and see what is going on.

Option 2) Rename your class to Bang, see if it starts working

I would not be surprised if there is hard coding to skip "lang' in there, though I can't say why.

Edit -

Seeing code like this in the source

        if (superclassnameIndex > 0) { // May be zero -> class is java.lang.Object
            superclassname = cpool.getConstantString(superclassnameIndex, Constants.CONSTANT_Class);
            superclassname = Utility.compactClassName(superclassname, false);

} else {
            superclassname = "java.lang.Object";
        }

Looks like they are trying to skip weaving of java.lang.stuff.... don't see anything for just "lang" but it may be there (or a bug)