Log4j2 + SVM + enabled assertions lead to exception in thread "Libgraal MBean Registration"

[repolevedavaj]

Describe the issue I use the library org.graalvm.nativeimage:svm to register resources (and other stuff) dynamically within my own feature implementation. Now I wanted to introduce Log4j2 in my application, but if I execute my tests with enabled assertions (JVM param -ea, activated in IntelliJ by default), an IllegalAccessError is thrown. Nevertheless, the logging works, so I am not sure if it has any other side effects.

Steps to reproduce the issue Please include both build steps as well as run steps

1. Download the attached example project graalvm-log4j-example.zip
2. Execute mvn test with an installed GraalVM

Describe GraalVM and your environment:

• GraalVM version: 21.1.0
• JDK major version: 11
• OS: macOS Big Sur
• Architecture: x64

More details

[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.example.ExampleTest
Exception in thread "Libgraal MBean Registration" java.lang.InternalError: java.lang.IllegalAccessError: superinterface check failed: class com.oracle.svm.core.SubstrateOptions_OptionDescriptors (in unnamed module @0x47fdb550) cannot access class org.graalvm.compiler.options.OptionDescriptors (in module jdk.internal.vm.compiler) because module jdk.internal.vm.compiler does not export org.graalvm.compiler.options to unnamed module @0x47fdb550
    at jdk.internal.vm.compiler/org.graalvm.libgraal.LibGraal.initializeLibgraal(LibGraal.java:122)
    at jdk.internal.vm.compiler/org.graalvm.libgraal.LibGraal.<clinit>(LibGraal.java:126)
    at jdk.internal.vm.compiler/org.graalvm.libgraal.LibGraalScope.<init>(LibGraalScope.java:128)
    at jdk.internal.vm.compiler.management/org.graalvm.compiler.hotspot.management.Factory.initializeNatives(Factory.java:202)
    at jdk.internal.vm.compiler.management/org.graalvm.compiler.hotspot.management.Factory.poll(Factory.java:175)
    at jdk.internal.vm.compiler.management/org.graalvm.compiler.hotspot.management.Factory.run(Factory.java:96)
Caused by: java.lang.IllegalAccessError: superinterface check failed: class com.oracle.svm.core.SubstrateOptions_OptionDescriptors (in unnamed module @0x47fdb550) cannot access class org.graalvm.compiler.options.OptionDescriptors (in module jdk.internal.vm.compiler) because module jdk.internal.vm.compiler does not export org.graalvm.compiler.options to unnamed module @0x47fdb550
    at java.base/java.lang.ClassLoader.defineClass1(Native Method)
    at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1017)
    at java.base/java.security.SecureClassLoader.defineClass(SecureClassLoader.java:174)
    at java.base/jdk.internal.loader.BuiltinClassLoader.defineClass(BuiltinClassLoader.java:800)
    at java.base/jdk.internal.loader.BuiltinClassLoader.findClassOnClassPathOrNull(BuiltinClassLoader.java:698)
    at java.base/jdk.internal.loader.BuiltinClassLoader.loadClassOrNull(BuiltinClassLoader.java:621)
    at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:579)
    at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:178)
    at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
    at java.base/java.lang.Class.forName0(Native Method)
    at java.base/java.lang.Class.forName(Class.java:398)
    at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.nextProviderClass(ServiceLoader.java:1210)
    at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNextService(ServiceLoader.java:1221)
    at java.base/java.util.ServiceLoader$LazyClassPathLookupIterator.hasNext(ServiceLoader.java:1265)
    at java.base/java.util.ServiceLoader$2.hasNext(ServiceLoader.java:1300)
    at java.base/java.util.ServiceLoader$3.hasNext(ServiceLoader.java:1385)
    at jdk.internal.vm.compiler/org.graalvm.compiler.options.OptionKey$Lazy.<clinit>(OptionKey.java:90)
    at jdk.internal.vm.compiler/org.graalvm.compiler.options.OptionKey.checkDescriptorExists(OptionKey.java:65)
    at jdk.internal.vm.compiler/org.graalvm.compiler.options.OptionKey.getValue(OptionKey.java:140)
    at jdk.internal.vm.compiler/org.graalvm.compiler.hotspot.HotSpotGraalCompilerFactory.initializeGraalCompilePolicyFields(HotSpotGraalCompilerFactory.java:111)
    at jdk.internal.vm.compiler/org.graalvm.compiler.hotspot.HotSpotGraalCompilerFactory.onSelection(HotSpotGraalCompilerFactory.java:94)
    at jdk.internal.vm.ci/jdk.vm.ci.hotspot.HotSpotJVMCICompilerConfig.getCompilerFactory(HotSpotJVMCICompilerConfig.java:133)
    at jdk.internal.vm.ci/jdk.vm.ci.hotspot.HotSpotJVMCIRuntime.<init>(HotSpotJVMCIRuntime.java:552)
    at jdk.internal.vm.ci/jdk.vm.ci.hotspot.HotSpotJVMCIRuntime.runtime(HotSpotJVMCIRuntime.java:176)
    at jdk.internal.vm.compiler/org.graalvm.libgraal.LibGraal.initializeLibgraal(LibGraal.java:113)
    ... 5 more
10:20:26.127 [main] INFO  org.example.ExampleTest - hello
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.722 s - in org.example.ExampleTest
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  5.220 s
[INFO] Finished at: 2021-06-16T10:20:26+02:00
[INFO] ------------------------------------------------------------------------

[repolevedavaj]

I have also tested it with https://github.com/graalvm/graalvm-ce-dev-builds/releases/download/21.2.0-dev-20210615_2020/graalvm-ce-java11-darwin-amd64-dev.tar.gz

[munishchouhan]

@repolevedavaj thanks for reporting the issue, we will look into it and get back to you

[munishchouhan]

@repolevedavaj please try GraalVM 21.2.0-dev |https://github.com/graalvm/graalvm-ce-dev-builds/releases/tag/21.2.0-dev-20210616_2034

[repolevedavaj]

@mcraj017 I tried, but got the same result.

[munishchouhan]

@repolevedavaj if you are using module, then please follow https://github.com/oracle/graal/issues/1962 as it is not implemented yet

[repolevedavaj]

@mcraj017 I am not using modules my project, neither in the example, or I am misunderstanding something? To be clear, everything in my application seems to be working fine. It is just a strange exception. It seems like that some library in the GraalVM misses the module information and is therefore not allowed the access the other class.

[munishchouhan]

@repolevedavaj thanks for the clarification, I will check the reproducer and get back to you

[christianwimmer]

@repolevedavaj The exception you are seeing is bad, and we are working out what is going on there. But that is not really the underlying problem. Because you should not have the GraalVM dependency on the class path anyway at run time - it is only needed at compile time when you need to compile your own Feature. At run time (when building a native image) all of these classes are provided by the native image generator.

So you need to switch the svm dependency to be a "provided" dependency:

        <dependency>
            <groupId>org.graalvm.nativeimage</groupId>
            <artifactId>svm</artifactId>
            <version>21.1.0</version>
            <scope>provided</scope>
        </dependency>

Unfortunately, Maven still adds "provided" dependencies when executing tests. So you also need to manually exclude the dependency in your test execution:

                <plugin>
                    <groupId>org.apache.maven.plugins</groupId>
                    <artifactId>maven-surefire-plugin</artifactId>
                    <version>3.0.0-M5</version>
                    <configuration>
                        <classpathDependencyExcludes>org.graalvm.nativeimage</classpathDependencyExcludes>
                        <argLine>-ea</argLine>
                    </configuration>
                </plugin>