Openj9: java.lang.ClassNotFoundException: during object deserialization in openjdk11.06 with openj9

[mreuvers]

Hi there,

Below follows a reproduction case for a deserialization problem we have encountered in our software after an upgrade to the latest JDK (openjdk11.06 with openj9), we came from 11.05 openj9 previously. We would like to see this fixed, as we don't want to advise our customers to not use openjdk with openj9.

This occurs only at the 11.06 version with OpenJ9, it works fine on 11.05 with OpenJ9, it also works fine for 11.06 with hotspot.

If you have more questions please let me know. Thank you.

JDK version

openjdk version "11.0.6" 2020-01-14
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.6+10)
Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.18.0, JRE 11 Mac OS X amd64-64-Bit Compressed References 20200116_443 (JIT enabled, AOT enabled)
OpenJ9 - 6968c18d7
OMR - 7a1b0239a
JCL - 104cab2452 based on jdk-11.0.6+10)

This reproduces at linux too (did not test on windows but likely as well).

Reproduction case

Attached a simplified reproduction case using maven that reproduces the issue.

openjdk-cl-issue.zip

• Install maven, I used: 3.6.3
• Extract the attached .zip
• In a shell go the directory "openjdk-cl-issue", this contains the main pom.xml
• Set the JAVA_HOME environment variable: export JAVA_HOME=/path/to/openjdk11.06-openj9 (this is what maven will use)
• mvn clean package

That will clean and then package and run the Main.class (present in test project). It will fail with the exception further down.

You can debug through it all as well from e.g. IntelliJ. Start from the "Main" class.

Essentially this contains 3 projects, model1, model2 and test. Both model1 and model2 are only available on compile time, so _not_ on runtime.
The Main class creates 2 separate classloaders, ClassLoaderModel1 for model1 and ClassLoaderModel2 for model2 (this one has as parent ClassLoaderModel1).

It then reflectively loads "RunTest" using ClassLoaderModel2 and calls "doIt()". In there an instance of TestData is created, serialized to byte[] and then back to TestData. It's the latter (the deserialization) that fails.

Have a look in TestData and see how it has an IdentityHashMap where as Model1Object lives in model1 (so that ClassLoaderModel1).

During deserialization of this map, once that map is complete the ObjectInputStream's state is in:
cachedLudcl=ClassLoaderModel1
refreshLudcl=false
(note: IdentityHashMap has a custom readObject()).

Then the next field is about to be serialized (simpleObject), this one lives in model2 - but since the refreshLudcl=false, it will not refresh the classloader (normally that is done by calling latestUserDefinedLoader()), causing the ClassNotFoundException as it uses the wrong classloader.

Please have a look in Model1Object and read the comment I put there, the problem is related to custom read/write serialization methods as well as another dependent object there. Without those things are working as expected.

Additional notes

• We suspect this problem was introduced with https://github.com/eclipse/openj9/issues/8311
• Disabling classcaching (as that was enabled in 11.06):
  
  
  
  • MAVEN_OPTS='-Dcom.ibm.enableClassCaching=false' mvn clean package works
  
  
• openjdk11.05 openj9 works fine with or without caching enabled (same flag, in 11.05 the default is off).
• openjdk11.06 with hotspot works fine (previous versions too).

Exception

Caused by: java.lang.ClassNotFoundException: com.redwood.bug.reproduction.SimpleObject
    at java.lang.Class.forNameImpl (Native Method)
    at java.lang.Class.forName (Class.java:412)
    at java.io.ClassCache$FutureValue.get (ClassCache.java:190)
    at java.io.ClassCache.get (ClassCache.java:161)
    at java.io.ObjectInputStream.resolveClass (ObjectInputStream.java:831)
    at java.io.ObjectInputStream.readNonProxyDesc (ObjectInputStream.java:2046)
    at java.io.ObjectInputStream.readClassDesc (ObjectInputStream.java:1932)
    at java.io.ObjectInputStream.readOrdinaryObject (ObjectInputStream.java:2220)
    at java.io.ObjectInputStream.readObject0 (ObjectInputStream.java:1751)
    at java.io.ObjectInputStream.defaultReadFields (ObjectInputStream.java:2522)
    at java.io.ObjectInputStream.readSerialData (ObjectInputStream.java:2414)
    at java.io.ObjectInputStream.readOrdinaryObject (ObjectInputStream.java:2247)
    at java.io.ObjectInputStream.readObject0 (ObjectInputStream.java:1751)
    at java.io.ObjectInputStream.readObject (ObjectInputStream.java:544)
    at java.io.ObjectInputStream.readObject (ObjectInputStream.java:457)
    at com.redwood.bug.reproduction.SerializationUtil.deserialize (SerializationUtil.java:26)
    at com.redwood.bug.reproduction.RunTest.doIt (RunTest.java:11)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0 (Native Method)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke (NativeMethodAccessorImpl.java:62)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke (DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke (Method.java:566)
    at com.redwood.bug.reproduction.Main.main (Main.java:37)

[DanHeidinga]

@theresa-m Can you take a look at this? It sounds like an issue with the LUDCL optimization

[DanHeidinga]

@mreuvers Does the issue still occur with the LUDCL optimization disabled? Can you do a run with -Dcom.ibm.enableClassCaching=false?

[mreuvers]

@DanHeidinga

Yes that works, see also the "Additional notes" section for more details in my initial comment.

[DanHeidinga]

Thanks @mreuvers. I missed that in in the initial reading.

[theresa-m]

Yes looking to solve the issue.

[mreuvers]

No problem @DanHeidinga and thank you both for looking into it.

[theresa-m]

The problem with my original pull request https://github.com/ibmruntimes/openj9-openjdk-jdk11/pull/226 is that the ludcl should be refreshed for every new call to readObject not just when a user code is invoked during read object.

Running some further testing and perf benchmarks.

[theresa-m]

List of prs for this issue to help keep track:

Java 8: https://github.com/ibmruntimes/openj9-openjdk-jdk8/pull/370
Java 11: https://github.com/ibmruntimes/openj9-openjdk-jdk11/pull/260
Java 14: https://github.com/ibmruntimes/openj9-openjdk-jdk14/pull/10
Java next: https://github.com/ibmruntimes/openj9-openjdk-jdk/pull/166

[theresa-m]

@mreuvers if you are interested in trying out the fix with your product before it's made its way into the nightly builds I've linked a JDK11 linux build:
https://drive.google.com/open?id=1MRJi-vsDqFRxQ5-1Ph0KD9nr3da32AYH

[mreuvers]

@theresa-m thank you for the quick fix! I hope to test it this Monday, I'll let you know how things went.

[mreuvers]

@theresa-m I've tested with your linked jdk and it seems the issue has been resolved based on a quick test done on our product. Things work again as they did before.

Any idea when a patch release can be expected (roughly)?

Thank you again for the quick fix.

[theresa-m]

@mreuvers it is targeted for the 0.19 Java 14 release which will be coming out in mid March.

However it will be available in the nightly builds at AdoptOpenJDK the day after the pr is merged. https://adoptopenjdk.net/nightly.html?variant=openjdk11&jvmVariant=openj9

[pwagland]

@theresa-m will this also be available in java 11? At the moment we are in state that we can’t deploy the latest Java 11 OpenJ9, from there the question.

[theresa-m]

Ah yes. Sorry my answer is a bit misleading. The next OpenJ9 Java 11 refresh is actually 0.20 which is targeted for April.
It will be applied to the nightly build in Java 11 once merged.