Spring AOP Logging Interceptor and JAXB issue

Question

I am trying to implement logging aspect into my application. This is the first time I am attempting AOP, so please let me know if I am missing something obvious. In order to achieve weaving external jars, I am trying to implement load time weaver. I did specify the load-time-weaver in my application context and mentioned TomcatInstrumentableClassLoader in my context.xml file along with the aop.xml. My application is a Spring MVC REST application and utilizes JAXB content negotiation as well. During the application startup, JAXB errors out with a null pointer exception while building the JAXBContext from the classes I mentioned. However, without the TomcatInstrumentableClassLoader JAXBContext is initialized normally and everything works ok. But, without the TomcatInstrumentableClassLoader load time weaving will not work. Is there something I can do to fix this issue? Any help is greatly appreciated.

My app context:

    ....
    <aop:aspectj-autoproxy/>
    <context:load-time-weaver aspectj-weaving="on" />
    .....
    <oxm:jaxb2-marshaller id="jaxb2Marshaller">
    <oxm:class-to-be-bound name="core.jaxb.DocPackage"/>
    <oxm:class-to-be-bound name="core.jaxb.life.Life"/>
    <oxm:class-to-be-bound name="core.jaxb.corr.Corr"/>
    <oxm:class-to-be-bound name="core.jaxb.ps.PS"/>
</oxm:jaxb2-marshaller>

Here is my context.xml:

    <?xml version="1.0" encoding="UTF-8"?>
    <Context>
<Loader loaderClass="org.springframework.instrument.classloading.tomcat.TomcatInstrumentableClassLoader" useSystemClassLoaderAsParent="false"/>
</Context>

My aop.xml:

     <!DOCTYPE aspectj PUBLIC
    "-//AspectJ//DTD//EN" "http://www.eclipse.org/aspectj/dtd/aspectj.dtd">
    <aspectj>
<weaver>
    <!-- only weave classes in our application-specific packages -->
    <include within="core.aspects.*"/>
</weaver>
<aspects>
    <!-- weave in just this aspect -->        
    <aspect name="core.aspects.LoggerAspect"/>
</aspects>

Here is the stack trace:

    Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'jaxb2Marshaller': Invocation of init method failed; nested exception is java.lang.NullPointerException
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1420)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:519)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:291)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:288)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:190)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.findAutowireCandidates(DefaultListableBeanFactory.java:844)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.doResolveDependency(DefaultListableBeanFactory.java:786)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveDependency(DefaultListableBeanFactory.java:703)
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanPostProcessor$AutowiredFieldElement.inject(AutowiredAnnotationBeanPostProcessor.java:478)
... 23 more
     Caused by: java.lang.NullPointerException
at java.util.EnumMap.<init>(EnumMap.java:113)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeEnumLeafInfoImpl.<init>(RuntimeEnumLeafInfoImpl.java:72)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.createEnumLeafInfo(RuntimeModelBuilder.java:94)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.createEnumLeafInfo(RuntimeModelBuilder.java:70)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getClassInfo(ModelBuilder.java:213)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:89)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:70)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getClassInfo(ModelBuilder.java:198)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:84)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:70)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getTypeInfo(ModelBuilder.java:304)
at com.sun.xml.internal.bind.v2.model.impl.SingleTypePropertyInfoImpl.getTarget(SingleTypePropertyInfoImpl.java:79)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeValuePropertyInfoImpl.getTarget(RuntimeValuePropertyInfoImpl.java:55)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeValuePropertyInfoImpl.getTarget(RuntimeValuePropertyInfoImpl.java:39)
at com.sun.xml.internal.bind.v2.model.impl.SingleTypePropertyInfoImpl.ref(SingleTypePropertyInfoImpl.java:73)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeValuePropertyInfoImpl.ref(RuntimeValuePropertyInfoImpl.java:59)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeValuePropertyInfoImpl.ref(RuntimeValuePropertyInfoImpl.java:39)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getClassInfo(ModelBuilder.java:244)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:89)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:70)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getClassInfo(ModelBuilder.java:198)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:84)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:70)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getTypeInfo(ModelBuilder.java:304)
at com.sun.xml.internal.bind.v2.model.impl.TypeRefImpl.calcRef(TypeRefImpl.java:81)
at com.sun.xml.internal.bind.v2.model.impl.TypeRefImpl.getTarget(TypeRefImpl.java:58)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeTypeRefImpl.getTarget(RuntimeTypeRefImpl.java:47)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeTypeRefImpl.getTarget(RuntimeTypeRefImpl.java:40)
at com.sun.xml.internal.bind.v2.model.impl.ElementPropertyInfoImpl$1.get(ElementPropertyInfoImpl.java:63)
at com.sun.xml.internal.bind.v2.model.impl.ElementPropertyInfoImpl$1.get(ElementPropertyInfoImpl.java:61)
at java.util.AbstractList$Itr.next(AbstractList.java:345)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getClassInfo(ModelBuilder.java:244)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:89)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:70)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getClassInfo(ModelBuilder.java:198)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:84)
at com.sun.xml.internal.bind.v2.model.impl.RuntimeModelBuilder.getClassInfo(RuntimeModelBuilder.java:70)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getTypeInfo(ModelBuilder.java:304)
at com.sun.xml.internal.bind.v2.model.impl.ModelBuilder.getTypeInfo(ModelBuilder.java:319)
at com.sun.xml.internal.bind.v2.runtime.JAXBContextImpl.getTypeInfoSet(JAXBContextImpl.java:430)
at com.sun.xml.internal.bind.v2.runtime.JAXBContextImpl.<init>(JAXBContextImpl.java:277)
at com.sun.xml.internal.bind.v2.runtime.JAXBContextImpl$JAXBContextBuilder.build(JAXBContextImpl.java:1100)
at com.sun.xml.internal.bind.v2.ContextFactory.createContext(ContextFactory.java:143)
at com.sun.xml.internal.bind.v2.ContextFactory.createContext(ContextFactory.java:110)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at javax.xml.bind.ContextFinder.newInstance(ContextFinder.java:202)
at javax.xml.bind.ContextFinder.find(ContextFinder.java:376)
at javax.xml.bind.JAXBContext.newInstance(JAXBContext.java:574)
at javax.xml.bind.JAXBContext.newInstance(JAXBContext.java:522)
at org.springframework.oxm.jaxb.Jaxb2Marshaller.createJaxbContextFromClasses(Jaxb2Marshaller.java:372)
at org.springframework.oxm.jaxb.Jaxb2Marshaller.getJaxbContext(Jaxb2Marshaller.java:331)
at org.springframework.oxm.jaxb.Jaxb2Marshaller.afterPropertiesSet(Jaxb2Marshaller.java:317)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1477)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1417)
... 33 more

Ics

Answer 1

Whoa - lot's of implementation for logging! Here's a strategy I have used to great success:

1. Create an aspect annotated with the AspectJ @Aspect annotation, and the Spring @Component annotation, as one makes it an aspect, the latter makes it a Spring bean
2. Enable aspects in your app by configuring the Speing AOP namespace, then setting <aop:aspectj-autoproxy>
3. Create a method in the aspect, annotated with @Around so that it runs before and after the handler method execution. Configure the method to run only for classes in your Controller package, like so:@Around("execution(* com.mycontrollerpackage.(.*(..))")

Now you have an aspect that runs before and after method execution, allowing you to log information about requests, from what was passed in to how long it took to take. You can also perform security checks, set ThreadLocal variables to guide execution, etc. All kinds of good stuff.

Drusie

Thanks and I am doing the same thing. I am not having an issue running the aspect in the same module, but when I try to weave the external jars - my application uses multiple sub-modules and they are not being woven. To weave external jars, I need to use TomcatInstrumentalbleClassLoader; this is when I am having the issue I mentioned above. – Ics

Here's another thread here which might help; the accepted answer seems to rely on not using annotations, but XML config: #5956990 – Drusie