Openj9: shareclasses:enableBCI leads to ClassNotFoundException with 11.0.7

[htreu]

Java -version output

Output from java -version.
If the shas are not public, include equivalent public shas.

openjdk version "11.0.7" 2020-04-14
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.7+10)
Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.20.0, JRE 11 Linux amd64-64-Bit Compressed References 20200416_574 (JIT enabled, AOT enabled)
OpenJ9 - 05fa2d361
OMR - d4365f371
JCL - 838028fc9d based on jdk-11.0.7+10)

Summary of problem

The application is running on adoptopenjdk/openjdk11-openj9:alpine-jre base image.

We provide a javaagent doing byte code instrumentation. Our client is running the above mentioned JDK version and the following shared class cache settings:

-Xshareclasses:name=<name>
-XX:SharedCacheHardLimit=300m
-Xshareclasses:expire=240
-Xshareclasses:enableBCI
-Xshareclasses:persistent
-Xshareclasses:nonfatal
-Xshareclasses:groupAccess

However the the javaagent fails to start with the following exception:

Could not start Instana agent: java.com.instana.agent.log.v1.LogDispatcher
java.lang.NoClassDefFoundError: java.com.instana.agent.log.v1.LogDispatcher
at com.instana.agent.loader.v1_3_26.AgentLoader.setupAgent(AgentLoader.java:137)
at com.instana.agent.loader.v1_3_26.AgentLoader.agentmain(AgentLoader.java:73)
at com.instana.agent.loader.v1_3_26.AgentLoader.agentmain(AgentLoader.java:65)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.base/java.lang.reflect.Method.invoke(Unknown Source)
at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndStartAgent(Unknown Source)
at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndCallAgentmain(Unknown Source)
at java.base/openj9.internal.tools.attach.target.Attachment.loadAgentLibraryImpl(Native Method)
at java.base/openj9.internal.tools.attach.target.Attachment.loadAgentLibrary(Unknown Source)
at java.base/openj9.internal.tools.attach.target.Attachment.parseLoadAgent(Unknown Source)
at java.base/openj9.internal.tools.attach.target.Attachment.doCommand(Unknown Source)
at java.base/openj9.internal.tools.attach.target.Attachment.run(Unknown Source)
Caused by: java.lang.ClassNotFoundException: java.com.instana.agent.log.v1.LogDispatcher
at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(Unknown Source)
at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(Unknown Source)
at java.base/java.lang.ClassLoader.loadClass(Unknown Source)
... 14 more
Exception in thread "Attachment 41301" java.lang.reflect.InvocationTargetException
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.base/java.lang.reflect.Method.invoke(Unknown Source)
at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndStartAgent(Unknown Source)
at java.instrument/sun.instrument.InstrumentationImpl.loadClassAndCallAgentmain(Unknown Source)
at java.base/openj9.internal.tools.attach.target.Attachment.loadAgentLibraryImpl(Native Method)
at java.base/openj9.internal.tools.attach.target.Attachment.loadAgentLibrary(Unknown Source)
at java.base/openj9.internal.tools.attach.target.Attachment.parseLoadAgent(Unknown Source)
at java.base/openj9.internal.tools.attach.target.Attachment.doCommand(Unknown Source)
at java.base/openj9.internal.tools.attach.target.Attachment.run(Unknown Source)
Caused by: java.lang.RuntimeException: java.lang.NoClassDefFoundError: java.com.instana.agent.log.v1.LogDispatcher
at com.instana.agent.loader.v1_3_26.AgentLoader.setupAgent(AgentLoader.java:168)
at com.instana.agent.loader.v1_3_26.AgentLoader.agentmain(AgentLoader.java:73)
at com.instana.agent.loader.v1_3_26.AgentLoader.agentmain(AgentLoader.java:65)
... 11 more
Caused by: java.lang.NoClassDefFoundError: java.com.instana.agent.log.v1.LogDispatcher
at com.instana.agent.loader.v1_3_26.AgentLoader.setupAgent(AgentLoader.java:137)
... 13 more
Caused by: java.lang.ClassNotFoundException: java.com.instana.agent.log.v1.LogDispatcher
at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(Unknown Source)
at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(Unknown Source)
at java.base/java.lang.ClassLoader.loadClass(Unknown Source)
... 14 more
Agent failed to start!
JVMJ9TI064E Agent initialization function Agent_OnAttach failed for library instrument, return code 102

with the class java.com.instana.agent.log.v1.LogDispatcher injected into the boot classloader during javaagent initialisation.

This used to work for older versions of openJ9 and as a workaround this also works with -Xshareclasses:none on the above mentioned JDK version.

Diagnostic files

[DanHeidinga]

@hangshao0 @pshipton can you take a look at this?

@htreu Can you share the test case with us? It'll be easier to debug if we can directly run the agent.

[Donnerbart]

This happened on a system of a customer of us.
We still have to reproduce this locally.
I'll come back to you as soon as we can share a reproducer.

[hangshao0]

The application class loader should eventually delegate to bootstrap class loader to find classes. That should not be changed by the options here. We need a test case to figure out what is going on.

[pshipton]

No input from the raiser, deferring to the Backlog.

[gireeshpunathil]

I can reproduce this reliably in my system. Here is a recreate:

1. download and install Instana client agent for Java (as a sudoer user):

curl -o setup_agent.sh https://setup.instana.io/agent && chmod 700 ./setup_agent.sh && sudo ./setup_agent.sh -a <agent_key> -t dynamic -e ingress-orange-saas.instana.io:443

this will install and start a system service instana-agent.service which you can stop using systemctl stop instana-agent.service when not needed.

(I will separately send you the agent key)

1. Modify the agent configuration to enable Java instrumentation: uncomment the entire section titled com.instana.plugin.javatrace in the agent config (installation_root/instana/agent/etc/instana/configuration.yaml). Save and close. No need to restart the service.

2. Write, compile and run a trivial Java program that runs for couple of minutes:

$ cat Hello.java

public class Hello
{
    public static void main(String args[]) throws Exception
    {
        System.out.println("hello world!");
        Thread.currentThread().sleep(100000);
    }
}

$ java Hello // problem
$ java -Xshareclasses:none Hello // no problem

$ java -version

openjdk version "15.0.1" 2020-10-20
OpenJDK Runtime Environment AdoptOpenJDK (build 15.0.1+9)
Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.23.0, JRE 15 Linux amd64-64-Bit Compressed References 20201022_81 (JIT enabled, AOT enabled)
OpenJ9   - 0394ef754
OMR      - 582366ae5
JCL      - ad583de3b5 based on jdk-15.0.1+9)

Hope this helps.

[hangshao0]

Thanks for providing the test case. Will try it once I get some time.

[hangshao0]

I will separately send you the agent key

Can you send me the agent key ?

[gireeshpunathil]

key sent.

[hangshao0]

@gireeshpunathil , seems that I cannot startup the service with the reproducing steps here https://github.com/eclipse/openj9/issues/10073#issuecomment-765135401. Maybe something is missing ?

I am using the same Java 15 build as yours:

/root/CCM/JDK15/openj9-openjdk-jdk15/build/linux-x86_64-server-release/images/jdk/bin/java -version
openjdk version "15.0.1-internal" 2020-10-20
OpenJDK Runtime Environment (build 15.0.1-internal+0-adhoc.root.openj9-openjdk-jdk15)
Eclipse OpenJ9 VM (build openj9-0.23.0, JRE 15 Linux amd64-64-Bit Compressed References 20210127_000000 (JIT enabled, AOT enabled)
OpenJ9   - 0394ef7
OMR      - 582366a
JCL      - ad583de based on jdk-15.0.1+9)

Running sudo ./setup_agent.sh -a <agent_key> -t dynamic -e ingress-orange-saas.instana.io:443

Setting up the dynamic Instana agent for GNU/Linux
Are you sure? [y/N] y
Setting up Instana APT repository
Authentication for the packages.instana.io repository has been added to apt via the /etc/apt/auth.conf.d/instana-packages.conf file
Importing Instana GPG key
Updating apt metadata
Installing Instana agent 

It does not look like the serivce is started up. So I ran:

systemctl start instana-agent.service.

systemctl start instana-agent.service seems to be translated into the following command and it failed on BundleException there.

/root/CCM/JDK15/openj9-openjdk-jdk15/build/linux-x86_64-server-release/images/jdk/bin/java -Xms64m -Xmx160m -XX:+UnlockDiagnosticVMOptions -XX:+UseSerialGC -Xmn32m -Xss512k -XX:InitialCodeCacheSize=8m -XX:CodeCacheExpansionSize=64k -XX:ReservedCodeCacheSize=16m -XX:-TieredCompilation -XX:CICompilerCount=1 -XX:CompressedClassSpaceSize=24m -XX:MinMetaspaceExpansion=1M -XX:MaxMetaspaceExpansion=8M -XX:MaxMetaspaceSize=128m -XX:MaxDirectMemorySize=256m -XX:+PerfDisableSharedMem -noverify --add-reads=java.xml=java.logging --add-exports=java.base/org.apache.karaf.specs.locator=java.xml,ALL-UNNAMED --patch-module java.base=lib/endorsed/org.apache.karaf.specs.locator-4.2.9.jar --patch-module java.xml=lib/endorsed/org.apache.karaf.specs.java.xml-4.2.9.jar --add-opens java.base/java.security=ALL-UNNAMED --add-opens java.base/java.net=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.naming/javax.naming.spi=ALL-UNNAMED --add-opens java.rmi/sun.rmi.transport.tcp=ALL-UNNAMED --add-exports=java.base/sun.net.www.protocol.http=ALL-UNNAMED --add-exports=java.base/sun.net.www.protocol.https=ALL-UNNAMED --add-exports=java.base/sun.net.www.protocol.jar=ALL-UNNAMED --add-exports=jdk.xml.dom/org.w3c.dom.html=ALL-UNNAMED --add-exports=jdk.naming.rmi/com.sun.jndi.url.rmi=ALL-UNNAMED -Dkaraf.instances=/opt/instana/agent/instances -Dkaraf.home=/opt/instana/agent -Dkaraf.base=/opt/instana/agent -Dkaraf.data=/opt/instana/agent/data -Dkaraf.etc=/opt/instana/agent/etc -Dkaraf.log=/opt/instana/agent/data/log -Dkaraf.restart.jvm.supported=true -Djava.io.tmpdir=/opt/instana/agent/data/tmp -Djava.util.logging.config.file=/opt/instana/agent/etc/java.util.logging.properties -Dkaraf.startLocalConsole=false -Dkaraf.startRemoteShell=false -classpath /root/CCM/JDK15/openj9-openjdk-jdk15/build/linux-x86_64-server-release/images/jdk/lib/tools.jar:/opt/instana/agent/lib/boot/org.apache.karaf.jaas.boot-4.2.9.jar:/opt/instana/agent/lib/boot/org.apache.karaf.main-4.2.9.jar:/opt/instana/agent/lib/boot/org.apache.karaf.specs.activator-4.2.9.jar:/opt/instana/agent/lib/boot/osgi.core-6.0.0.jar:/opt/instana/agent/lib/jdk9plus/istack-commons-runtime-3.0.10.jar:/opt/instana/agent/lib/jdk9plus/jakarta.xml.bind-api-2.3.3.jar:/opt/instana/agent/lib/jdk9plus/javax.activation-1.2.0.jar:/opt/instana/agent/lib/jdk9plus/javax.annotation-api-1.3.1.jar:/opt/instana/agent/lib/jdk9plus/jaxb-runtime-2.3.3.jar:/opt/instana/agent/lib/jdk9plus/txw2-2.3.3.jar:/opt/instana/agent/lib/ext/bcpg-jdk15on-1.64.jar:/opt/instana/agent/lib/ext/bcpkix-jdk15on-1.64.jar:/opt/instana/agent/lib/ext/bcprov-jdk15on-1.64.jar org.apache.karaf.main.Main
JVMJ9VM193W Since Java 13 -Xverify:none and -noverify were deprecated for removal and may not be accepted options in the future.
WARNING: package org.apache.karaf.specs.locator not in java.base
ERROR: Error parsing system bundle export statement: org.osgi.dto;version="1.0",org.osgi.resource;version="1.0",org.osgi.resource.dto;version="1.0";uses:="org.osgi.dto",org.osgi.framework;version="1.8",org.osgi.framework.dto;version="1.8";uses:="org.osgi.dto",org.osgi.framework.hooks.bundle;version="1.1";uses:="org.osgi.framework",org.osgi.framework.hooks.resolver;version="1.0";uses:="org.osgi.framework.wiring",org.osgi.framework.hooks.service;version="1.1";uses:="org.osgi.framework",org.osgi.framework.hooks.weaving;version="1.1";uses:="org.osgi.framework.wiring",org.osgi.framework.launch;version="1.2";uses:="org.osgi.framework",org.osgi.framework.namespace;version="1.1";uses:="org.osgi.resource",org.osgi.framework.startlevel;version="1.0";uses:="org.osgi.framework",org.osgi.framework.startlevel.dto;version="1.0";uses:="org.osgi.dto",org.osgi.framework.wiring;version="1.2";uses:="org.osgi.framework,org.osgi.resource",org.osgi.framework.wiring.dto;version="1.2";uses:="org.osgi.dto,org.osgi.resource.dto",org.osgi.service.condpermadmin;version="1.1.1";uses:="org.osgi.framework,org.osgi.service.permissionadmin",org.osgi.service.packageadmin;version="1.2";uses:="org.osgi.framework",org.osgi.service.permissionadmin;version="1.2",org.osgi.service.resolver;version="1.0";uses:="org.osgi.resource",org.osgi.service.startlevel;version="1.1";uses:="org.osgi.framework",org.osgi.service.url;version="1.0",org.osgi.util.tracker;version="1.5.1";uses:="org.osgi.framework",org.apache.karaf.version;version="4.2.9",org.apache.karaf.jaas.boot.principal;uses:=javax.security.auth;version="4.2.9",org.apache.karaf.jaas.boot;uses:="javax.security.auth,javax.security.auth.callback,javax.security.auth.login,javax.security.auth.spi,org.osgi.framework";version="4.2.9",org.apache.karaf.info;version="4.2.9",,org.hyperic.sigar, org.hyperic.sigar.ptql, com.ibm.tools.attach, com.ibm.tools.attach.javaSE, com.sun.misc, com.sun.tools.attach, sun.misc, sun.jvmstat.monitor, sun.jvmstat.perfdata.monitor, sun.jvmstat.perfdata.monitor.v1_0, sun.jvmstat.perfdata.monitor.v2_0, sun.jvmstat.perfdata.monitor.protocol.file, sun.jvmstat.perfdata.monitor.protocol.local, org.apache.karaf.branding, org.apache.karaf.jaas.boot;uses:="javax.security.auth,javax.security.auth.callback,javax.security.auth.login,javax.security.auth.spi,org.osgi.framework";version=4.2.9, org.apache.karaf.jaas.boot.principal;uses:=javax.security.auth;version=4.2.9
org.osgi.framework.BundleException: Exported package names cannot be zero length.
        at org.apache.felix.framework.util.manifestparser.ManifestParser.normalizeExportClauses(ManifestParser.java:876)
        at org.apache.felix.framework.util.manifestparser.ManifestParser.<init>(ManifestParser.java:215)
        at org.apache.felix.framework.ExtensionManager.<init>(ExtensionManager.java:261)
        at org.apache.felix.framework.Felix.<init>(Felix.java:429)
        at org.apache.felix.framework.FrameworkFactory.newFramework(FrameworkFactory.java:28)
        at org.apache.karaf.main.Main.launch(Main.java:256)
        at org.apache.karaf.main.Main.main(Main.java:178)
Error installing bundle listed in startup.properties with url: mvn:org.apache.karaf.features/org.apache.karaf.features.extension/4.2.9 and startlevel: 1

[htreu]

Exported package names cannot be zero length. results from Karaf trying to resolve ${jre-${java.specification.version}} during startup, but fails. The resulting MANIFEST then contains org.apache.karaf.info;version="4.2.9",,org.hyperic.sigar (note the double ,,) which is illegal.
Our karaf distribution currently fails with Java15, please run the agent with Java8 ands the target JVM with the openJ9 15.

[hangshao0]

please run the agent with Java8 ...

Now I can reproduce this error after switching to Java 8.

[hangshao0]

Seems related to storing unsafe classes in the shared cache. The error goes away if I destroy the existing cache that has unsafe classes and turn on -XX:-ShareUnsafeClasses in subsequent runs. After removing -XX:-ShareUnsafeClasses, the error comes back in a few runs.

I noticed that class java.com.instana.agent.log.v1.LogDispatcher is created by Unsafe.defineClass()

[hangshao0]

Unsafe classes should be stored as orphan in the SCC. However, they are incorrectly stored as normal romclasses here. With the change in https://github.com/eclipse/openj9/pull/11864, the error in this issue goes away.