New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

InvocationTargetException with -Xshareclasses from Spring App #1244

Closed
stevewallin opened this Issue Feb 22, 2018 · 17 comments

Comments

Projects
None yet
5 participants
@stevewallin

stevewallin commented Feb 22, 2018

Running the petclinic sample spring app (https://github.com/spring-projects/spring-petclinic) with -Xscmx50M -Xshareclasses causes Exception in thread "main" java.lang.reflect.InvocationTargetException on second run.

Output:
2018-02-22 12:46:31.942 INFO 1 --- [ main] o.s.s.petclinic.PetClinicApplication : Starting PetClinicApplication v2.0.0 on 85de4731ae7f with PID 1 (/tmp/spring-petclinic-2.0.0.jar started by root in /) 2018-02-22 12:46:31.957 INFO 1 --- [ main] o.s.s.petclinic.PetClinicApplication : No active profile set, falling back to default profiles: default 2018-02-22 12:46:32.082 INFO 1 --- [ main] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@44fd0272: startup date [Thu Feb 22 12:46:32 UTC 2018]; root of context hierarchy 2018-02-22 12:46:35.192 INFO 1 --- [ main] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$1cb4efe6] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying) Exception in thread "main" java.lang.reflect.InvocationTargetException at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48) at org.springframework.boot.loader.Launcher.launch(Launcher.java:87) at org.springframework.boot.loader.Launcher.launch(Launcher.java:50) at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:51) Caused by: java.lang.NoClassDefFoundError: ch.qos.logback.classic.spi.ThrowableProxy at ch.qos.logback.classic.spi.LoggingEvent.<init>(LoggingEvent.java:119) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:419) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383) at ch.qos.logback.classic.Logger.log(Logger.java:765) at org.apache.logging.slf4j.SLF4JLogger.logMessage(SLF4JLogger.java:232) at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2163) at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2118) at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2101) at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1995) at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1967) at org.apache.commons.logging.LogFactory$Log4jLog.log(LogFactory.java:302) at org.apache.commons.logging.LogFactory$Log4jLog.error(LogFactory.java:254) at org.springframework.boot.SpringApplication.reportFailure(SpringApplication.java:833) at org.springframework.boot.SpringApplication.handleRunFailure(SpringApplication.java:807) at org.springframework.boot.SpringApplication.run(SpringApplication.java:338) at org.springframework.boot.SpringApplication.run(SpringApplication.java:1246) at org.springframework.boot.SpringApplication.run(SpringApplication.java:1234) at org.springframework.samples.petclinic.PetClinicApplication.main(PetClinicApplication.java:32) ... 8 more Caused by: java.lang.ClassNotFoundException: ch.qos.logback.classic.spi.ThrowableProxy at java.net.URLClassLoader.findClass(URLClassLoader.java:588) at java.lang.ClassLoader.loadClassHelper(ClassLoader.java:933) at java.lang.ClassLoader.loadClass(ClassLoader.java:878) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:338) at java.lang.ClassLoader.loadClass(ClassLoader.java:861) ... 26 more

@DanHeidinga

This comment has been minimized.

Contributor

DanHeidinga commented Feb 22, 2018

@stevewallin Can you supply the java -version output from the build you used?

@stevewallin

This comment has been minimized.

stevewallin commented Feb 22, 2018

Java 8 docker file from adopt: https://hub.docker.com/r/adoptopenjdk/openjdk8-openj9/

openjdk version "1.8.0-internal" OpenJDK Runtime Environment (build 1.8.0-internal-jenkins_2018_01_30_13_02-b00) Eclipse OpenJ9 VM (build 2.9, JRE 1.8.0 Linux amd64-64 Compressed References 20180130_57 (JIT enabled, AOT enabled) OpenJ9 - 8f03f71 OMR - f410d65 JCL - 687ce89 based on jdk8u152-b16)

@DanHeidinga

This comment has been minimized.

Contributor

DanHeidinga commented Feb 22, 2018

@hangshao0 Can you take a look at this?

@hangshao0

This comment has been minimized.

Contributor

hangshao0 commented Feb 22, 2018

Looks like it is caused by the following JCL code in java.net.URLClassLoader.findClass() :

           Class clazz = (Class)AccessController.doPrivileged(loader, acc);
           if (clazz == null) {                                  
                      throw new ClassNotFoundException(name);   

clazz is null here.

@pshipton

This comment has been minimized.

Contributor

pshipton commented Feb 22, 2018

I assume this is a preliminary comment, but to be clear, we need to figure out why using -Xshareclasses causes this behavior.

@hangshao0

This comment has been minimized.

Contributor

hangshao0 commented Feb 23, 2018

I've tried 10+ times, I can start up petclinic sample spring app successfully:


2018-02-23 20:06:33.554  INFO 591 --- [  restartedMain] o.s.s.petclinic.PetClinicApplication     : Starting PetClinicApplication on 304746d8cd8a with PID 591 (/root/spring-petclinic/target/classes started by root in /root/spring-petclinic)
2018-02-23 20:06:33.560  INFO 591 --- [  restartedMain] o.s.s.petclinic.PetClinicApplication     : The following profiles are active: production
2018-02-23 20:06:33.703  INFO 591 --- [  restartedMain] ConfigServletWebServerApplicationContext : Refreshing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@219e695c: startup date [Fri Feb 23 20:06:33 UTC 2018]; root of context hierarchy
2018-02-23 20:06:36.745  INFO 591 --- [  restartedMain] trationDelegate$BeanPostProcessorChecker : Bean 'org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration' of type [org.springframework.transaction.annotation.ProxyTransactionManagementConfiguration$$EnhancerBySpringCGLIB$$bfa711d4] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
...
...
2018-02-23 20:06:42.997  INFO 591 --- [  restartedMain] o.s.j.e.a.AnnotationMBeanExporter        : Registering beans for JMX exposure on startup
2018-02-23 20:06:42.999  INFO 591 --- [  restartedMain] o.s.j.e.a.AnnotationMBeanExporter        : Bean with name 'dataSource' has been autodetected for JMX exposure
2018-02-23 20:06:43.008  INFO 591 --- [  restartedMain] o.s.j.e.a.AnnotationMBeanExporter        : Located MBean 'dataSource': registering with JMX server as MBean [com.zaxxer.hikari:name=dataSource,type=HikariDataSource]
2018-02-23 20:06:43.065  INFO 591 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2018-02-23 20:06:43.070  INFO 591 --- [  restartedMain] o.s.s.petclinic.PetClinicApplication     : Started PetClinicApplication in 10.454 seconds (JVM running for 11.209)

I am using the following commands on https://github.com/spring-projects/spring-petclinic:
git clone https://github.com/spring-projects/spring-petclinic.git
cd spring-petclinic
./mvnw spring-boot:run

@hangshao0

This comment has been minimized.

Contributor

hangshao0 commented Feb 23, 2018

@stevewallin, Is the failure rate 100% on your side ? Does it fail if option "-Xscmx50M -Xshareclasses" is removed ?

@stevewallin

This comment has been minimized.

stevewallin commented Feb 23, 2018

It works fine without the cache and 100% failure rate (after first run)
I actually did a mvn install to get a jar file and run with jar -jar spring-petclinic-2.0.0.jar inside docker as I'm on mac.

@hangshao0

This comment has been minimized.

Contributor

hangshao0 commented Feb 26, 2018

The issue here is related to nested jars.
spring-petclinic-2.0.0.jar is a runnable jar that has its dependent jars/classes under spring-petclinic-2.0.0.jar!/BOOT-INF/. URLClassLoader itself does not support nested jar, so it is not able to find the classes inside nested jars. Spring-boot has its own classloader called LaunchedURLClassLoader that extends URLClassLoader and overrides methods like findResource() and loadClass() so that it is able to load classes inside nested jars.

LaunchedURLClassLoader sets AppClassLoader as its parent so it will delegate to AppClassLoader first when loading classes. ApplClassLoader will search in its class path (/path/spring-petclinic-2.0.0.jar) and it is not able to find any classes from nested jars inside spring-petclinic-2.0.0.jar, then LauchedURLClassLoader will load the class.

When running with -Xshareclasses on a cold cache, I see

class load: org.springframework.boot.SpringApplication from: jar:file:/path/spring-petclinic-2.0.0.jar!/BOOT-INF/lib/spring-boot-2.0.0.BUILD-SNAPSHOT.jar!/
Stored class org/springframework/boot/SpringApplication in shared cache for class-loader id 3 with URL /path/spring-petclinic-2.0.0.jar (index 78).

LauchedURLClassLoader (loader id 3) loads the class org/springframework/boot/SpringApplication and stores it to the shared cache, with the trimmed URL /path/spring-petclinic-2.0.0.jar (See SharedClassAbstractHelper.recursiveJarTrim()),

Things changed when running again with the same cache, where appClassLoader loads classes it should not load:

Failed to find class org/springframework/boot/SpringApplication in shared cache for class-loader id 0.
Failed to find class org/springframework/boot/SpringApplication in shared cache for class-loader id 1.
Found class org/springframework/boot/SpringApplication in shared cache for class-loader id 2.
class load: org.springframework.boot.SpringApplication from: file:/path/spring-petclinic-2.0.0.jar

LauchedURLClassLoader delegates to appClassLoader (loader id 2) whose URL is /path/spring-petclinic-2.0.0.jar. The shared cache checks the URL, finding it is the same one as it is stored, the class is returned. The classes that were loaded by LauchedURLClassLoader is now loaded by appClassLoader...

@hangshao0

This comment has been minimized.

Contributor

hangshao0 commented Feb 26, 2018

So -Xshareclasses is not compatible with nested jars now.

@mstoodle

This comment has been minimized.

Contributor

mstoodle commented Mar 7, 2018

@hangshao0 Ok, so it's not supported. At a minimum, we should probably do a better job reporting that to the user :) .

Is supporting nested jar files something we should also consider :) ?

@stevewallin

This comment has been minimized.

stevewallin commented Mar 7, 2018

I think Spring fat jars are going to be a prime target for shared cache so support would be good there... but I guess I'm just not expecting a runtime exception after enabling the cache ;)

@pshipton

This comment has been minimized.

Contributor

pshipton commented Mar 7, 2018

We could investigate some way to detect a subclass of URLClassLoader which is incompatible with class sharing, and disable sharing for that subclass. It will be tricky to tell the difference between subclasses which are compatible and those which are not. The heiristic might end up disabling sharing for some subclass which is compatible.

I had suggested in person to Hang to update the Spring classloader to support sharing, and see if we can contribute that update to the project.

@hangshao0

This comment has been minimized.

Contributor

hangshao0 commented Mar 7, 2018

We patched java.net.URLClassLoader with some shared classes APIs so that it woks with -Xshareclasses. URLClassLoader itself does not support nested jars, I guess it is one of the reasons why we do not support nested jars.

We can consider supporting nested jars. There is no shared classes APIs that works with nested jars for the time being, but we can add them. Then the custom class loader (that deals with nested jars) needs to be patched with these shared classes APIs to work with -Xshareclasses.

About the error reporting, probably we could detect the nested jar and disable appClassLoader from finding class from shared cache and report the error.

@hangshao0

This comment has been minimized.

Contributor

hangshao0 commented Mar 9, 2018

This is a new feature request. @DanHeidinga , are you fine with moving forward to support nested jar ?

@DanHeidinga

This comment has been minimized.

Contributor

DanHeidinga commented Mar 11, 2018

Steve is right - enabling the SCC shouldn't result in an exception being thrown.

There appears to be several ways to make / use nested jars:

  • WAR files are nested jars. Many (most?) appservers unpack them and run the unpacked version. Existing SCC support is fine for this case.
  • Shaded classes: Jars are combined and classes may be renamed to be a single jar. Existing SCC support is fine.
  • Embedding jars in existing Jars and running them without unpacking.

It's the last case that SCC has issues with. At a minimum, we should write something up to help users that run into this issue know to unpack Spring's fat jar and run the unpacked version. The Spring doc [1] suggests running using the appropriate launcher such as:

$ unzip -q myapp.jar
$ java org.springframework.boot.loader.JarLauncher

[1] provides some great documentation on the structure of Spring's fat jars that can be used to detect them and may allow us to either enable/disable SCC support as needed.

It also lists a number of other projects that provide fat jar / one jar / uber jar support. A quick survey of them to find the common usage patterns, jar layout designs, ways to detect their use, etc would give us a good basis to design SCC fat jar support.

I'd suggest the following:

  1. Attempt to detect fat jars that are run without unpacking and disable SCC support for the embedded jars. Classes in the outer jar should be supportable..
  2. Determine the common capabilities / layouts / etc to find the right set of APIs to add to the SCC implementation to support the most common fat jar use cases.
  3. Work with projects - Spring, others? - to provide patches to use / support SCC.
  4. Investigate whether to provide an OpenJ9-specific fat jar library. This may be interesting if there are SCC capabilities that we can exploit by building a better fat jar loader.

@hangshao0 Is this the kind of approach you were thinking?

[1] https://docs.spring.io/spring-boot/docs/current/reference/html/executable-jar.html

@hangshao0

This comment has been minimized.

Contributor

hangshao0 commented Mar 12, 2018

Is this the kind of approach you were thinking?

It was something that I was thinking last week.

But we might do even better, on my second thought. Instead of dealing with the nested jars in the java level, we might be able to move the code change inside to the VM. It might be possible to detect and handle nested jars in the shared classes C code so that we do not need to add shared classes Java level APIs and patch them to the custom class loader. I guess this is a more preferable solution. I will try hacking the code and see how it goes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment