AspectJ weaving logs nasty warnings on Spring Boot fat jar

[dsyer]

$ java  -javaagent:/home/dsyer/.m2/repository/org/aspectj/aspectjweaver/1.8.9/aspectjweaver-1.8.9.jar -jar target/demo-0.0.1-SNAPSHOT.jar 
Dec 07, 2016 11:32:04 AM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: register definition failed
java.lang.RuntimeException: Cannot register non aspect: com$example$Interceptor , com.example.Interceptor
	at org.aspectj.weaver.bcel.BcelWeaver.addLibraryAspect(BcelWeaver.java:219)
	at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.registerAspects(ClassLoaderWeavingAdaptor.java:485)
	at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.registerDefinitions(ClassLoaderWeavingAdaptor.java:304)
	at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.initialize(ClassLoaderWeavingAdaptor.java:171)
	at org.aspectj.weaver.loadtime.Aj$ExplicitlyInitializedClassLoaderWeavingAdaptor.initialize(Aj.java:340)
	at org.aspectj.weaver.loadtime.Aj$ExplicitlyInitializedClassLoaderWeavingAdaptor.getWeavingAdaptor(Aj.java:345)
	at org.aspectj.weaver.loadtime.Aj$WeaverContainer.getWeaver(Aj.java:319)
	at org.aspectj.weaver.loadtime.Aj.preProcess(Aj.java:113)
	at org.aspectj.weaver.loadtime.ClassPreProcessorAgentAdapter.transform(ClassPreProcessorAgentAdapter.java:54)
	at sun.instrument.TransformerManager.transform(TransformerManager.java:188)
	at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:428)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:763)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:467)
	at java.net.URLClassLoader.access$100(URLClassLoader.java:73)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:368)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:362)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:361)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:331)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
	at sun.launcher.LauncherHelper.checkAndLoadMain(LauncherHelper.java:495)

[AppClassLoader@18b4aac2] warning register definition failed -- (RuntimeException) Cannot register non aspect: com$example$Interceptor , com.example.Interceptor
Cannot register non aspect: com$example$Interceptor , com.example.Interceptor
java.lang.RuntimeException: Cannot register non aspect: com$example$Interceptor , com.example.Interceptor
	at org.aspectj.weaver.bcel.BcelWeaver.addLibraryAspect(BcelWeaver.java:219)
	at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.registerAspects(ClassLoaderWeavingAdaptor.java:485)
	at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.registerDefinitions(ClassLoaderWeavingAdaptor.java:304)
	at org.aspectj.weaver.loadtime.ClassLoaderWeavingAdaptor.initialize(ClassLoaderWeavingAdaptor.java:171)
	at org.aspectj.weaver.loadtime.Aj$ExplicitlyInitializedClassLoaderWeavingAdaptor.initialize(Aj.java:340)
	at org.aspectj.weaver.loadtime.Aj$ExplicitlyInitializedClassLoaderWeavingAdaptor.getWeavingAdaptor(Aj.java:345)
	at org.aspectj.weaver.loadtime.Aj$WeaverContainer.getWeaver(Aj.java:319)
	at org.aspectj.weaver.loadtime.Aj.preProcess(Aj.java:113)
	at org.aspectj.weaver.loadtime.ClassPreProcessorAgentAdapter.transform(ClassPreProcessorAgentAdapter.java:54)
	at sun.instrument.TransformerManager.transform(TransformerManager.java:188)
	at sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:428)
	at java.lang.ClassLoader.defineClass1(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:763)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:467)
	at java.net.URLClassLoader.access$100(URLClassLoader.java:73)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:368)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:362)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:361)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:331)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
	at sun.launcher.LauncherHelper.checkAndLoadMain(LauncherHelper.java:495)

The aspect is actually woven and seems to work at runtime, but the stack trace is sort of distracting, and maybe signals a problem (or something I don't understand).

Sample project: https://github.com/scratches/spring-boot-ltw (you have to set -DskipTests when you build it).

[wilkinsona]

The problem is that the agent finds aop.xml which declares com.example.Interceptor very early on. It happens before the launcher has created LaunchedURLClassLoader so com.example.Interceptor can't be loaded (as it's in BOOT/INF/classes and, therefore, isn't on the class path of the system class loader).

[wilkinsona]

You can get rid of the distracting stack traces by moving aop.xml into src/main/resources/BOOT-INF/classes/META-INF/aop.xml so that it only becomes visible to the agent once LaunchedURLClassLoader has been created.

@aclement Is there a more pleasant way to deal with this?

[aclement]

Feels like if the classes were being moved into BOOT-INF/classes during jar packaging then the META-INF/aop.xml should have moved too, then it would all behave as expected. I can't think of a good reason to leave it behind (although it is a bit dirty as the folder is called 'classes', there is no BOOT-INF/resources is there).

It works for the reasons Andy describes, as we can see from the verbose output, the AppClassLoader can't find the aspect. But the LaunchedURLClassLoader can and so it will weave the necessary types:

[AppClassLoader@18b4aac2] info register classloader sun.misc.Launcher$AppClassLoader@18b4aac2
[AppClassLoader@18b4aac2] info using configuration file:/Users/aclement/gits/spring-boot-ltw/target/demo-0.0.1-SNAPSHOT.jar!/META-INF/aop.xml
[AppClassLoader@18b4aac2] info register aspect com.example.Interceptor
Dec 07, 2016 4:09:02 PM org.aspectj.weaver.tools.Jdk14Trace error
SEVERE: register definition failed
java.lang.RuntimeException: Cannot register non aspect: com$example$Interceptor , com.example.Interceptor

[LaunchedURLClassLoader@5fdef03a] info AspectJ Weaver Version 1.8.9 built on Monday Mar 14, 2016 at 21:18:16 GMT
[LaunchedURLClassLoader@5fdef03a] info register classloader org.springframework.boot.loader.LaunchedURLClassLoader@5fdef03a
[LaunchedURLClassLoader@5fdef03a] info using configuration file:/Users/aclement/gits/spring-boot-ltw/target/demo-0.0.1-SNAPSHOT.jar!/META-INF/aop.xml
[LaunchedURLClassLoader@5fdef03a] info using configuration file:/Users/aclement/gits/spring-boot-ltw/target/demo-0.0.1-SNAPSHOT.jar!/META-INF/aop.xml
[LaunchedURLClassLoader@5fdef03a] info register aspect com.example.Interceptor
[LaunchedURLClassLoader@5fdef03a] debug weaving 'com.example.InterceptorApplication'
...
[LaunchedURLClassLoader@5fdef03a] debug weaving 'org.springframework.boot.autoconfigure.condition.ConditionEvaluationReport$AncestorsMatchedCondition'
[LaunchedURLClassLoader@5fdef03a] weaveinfo Join point 'method-execution(boolean org.springframework.boot.autoconfigure.condition.ConditionEvaluationReport$AncestorsMatchedCondition.matches(org.springframework.context.annotation.ConditionContext, org.springframework.core.type.AnnotatedTypeMetadata))' in Type 'org.springframework.boot.autoconfigure.condition.ConditionEvaluationReport$AncestorsMatchedCondition' (ConditionEvaluationReport.java:273) advised by around advice from 'com.example.Interceptor' (Interceptor.java)

I might reduce that from a horrid exception to a regular message, for the AspectJ 1.8.10 I'm about to release.

Somewhat related, I don't know if this impacts the discussion in that other bug ( #739 ), but we do now support programmatic attachment of the AspectJ weaver to a running JVM: http://www.eclipse.org/aspectj/doc/released/README-187.html

[aclement]

OR we do this which I'd forgotten about. Instead of creating META-INF/aop.xml create org/aspectj/aop.xml in src/main/resources- same contents, just a different location. AspectJ will look for it at that location and the jar packaging for boot will place it in the BOOT-INF/classes folder.

[aclement]

Something I observed whilst testing this. It looks to me like getResources() on LaunchedURLClassLoader is returning double results? I added this to my main method:

		Enumeration<URL> resources = InterceptorApplication.class.getClassLoader().getResources("META-INF/aop.xml");
		while (resources.hasMoreElements()) {
			URL url = resources.nextElement();
			System.out.println("URL: "+url);
		}
		String s = "org/springframework/boot/loader/JarLauncher.class";
		resources = InterceptorApplication.class.getClassLoader().getResources(s);
		while (resources.hasMoreElements()) {
			URL url = resources.nextElement();
			System.out.println(": "+url);
		}

when I launched the jar, it prints two identical references for each:

URL: jar:file:/Users/aclement/gits/spring-boot-ltw/target/demo-0.0.1-SNAPSHOT.jar!/META-INF/aop.xml
URL: jar:file:/Users/aclement/gits/spring-boot-ltw/target/demo-0.0.1-SNAPSHOT.jar!/META-INF/aop.xml
: jar:file:/Users/aclement/gits/spring-boot-ltw/target/demo-0.0.1-SNAPSHOT.jar!/org/springframework/boot/loader/JarLauncher.class
: jar:file:/Users/aclement/gits/spring-boot-ltw/target/demo-0.0.1-SNAPSHOT.jar!/org/springframework/boot/loader/JarLauncher.class

Is that intended? Am I crazy?

[wilkinsona]

Thanks, @aclement.

Feels like if the classes were being moved into BOOT-INF/classes during jar packaging then the META-INF/aop.xml should have moved too, then it would all behave as expected. I can't think of a good reason to leave it behind

We deliberately leave META-INF in the root of the jar as some things needs to stay there (META-INF/MANIFEST.MF, for example). We could probably be a bit smarter and about it, though. You'd have to be doing some special, custom packaging for it to make sense for META-INF/aop.xml to stay in the jar's root.

Is that intended? Am I crazy?

Nope and nope. It's a bug in JarLauncher. It adds the root archive to the class path of LaunchedURLClassLoader when it does not need to as the archive is already on the class path of its parent. I've opened #7595 to fix it.