Cannot build native image for trivial app with SLF4J and Log4J2

[mipastgt]

For this trivial application

package hello;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Hello {
    
    private static Logger log = LoggerFactory.getLogger(Hello.class.getName());
    
    public static void main(String[] args) {
        log.info("Hello GraalVM");
        log.info("java.version: " + System.getProperty("java.version"));
    }  

}

the attempt to create a native image fails with an error message which is far too long to be shown here and I can't make any sense out of it. The idea was to first compile the application and then run it with the native-image-agent and after that build the native image based on the collected data.

This works if the build is configured to use the SLF4J simple binding but when I configure it to use LOG4J2 instead, the native build fails completely. The first two steps (copiling, running with agent) work in all cases.

Because native-image thinks there is something missing, I was asked to add the following options to it:

--allow-incomplete-classpath
--report-unsupported-elements-at-runtime

This should have worked because the app works nicely on the VM but it fails with native-image.
I have added a ZIP-file with the whole project to demonstrate the issue. It contains a build script and a Maven POM which exercise the above mentioned steps.

My tests where done on macOS 10.14.6 and GraalVM 19.3.0 (11) CE.

Hello.zip

[jgranduel]

Hi,

@mipastgt
as you've been compiling a trivial application as I tried on my side on Windows-10, I tested the compilation of your Hello.zip. My issue is that I'm not sure how to compile the application from the CLI with dependencies (#1939) (I want the most basic compilation to learn and share my experience, maven already is too high level! I don't do enough Java anymore to be fluent with it.). I deduced from your pom.xml the command line. Sorry if the post is out of topics, I do think is related, documentation-wise. Here's my test and the results:

javac -cp "path/to/.m2/repository/org/slf4j/slf4j-api/1.7.29/slf4j-api-1.7.29.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-api/2.13.0/log4j-api-2.13.0.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-core/2.13.0/log4j-core-2.13.0.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.0/log4j-slf4j-impl-2.13.0.jar;." hello/Hello.java
java -cp "path/to/.m2/repository/org/slf4j/slf4j-api/1.7.29/slf4j-api-1.7.29.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-api/2.13.0/log4j-api-2.13.0.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-core/2.13.0/log4j-core-2.13.0.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.0/log4j-slf4j-impl-2.13.0.jar;." hello.Hello

Works fine! Trying to compile with native-image.cmd now:

native-image.cmd -cp "path/to/.m2/repository/org/slf4j/slf4j-api/1.7.29/slf4j-api-1.7.29.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-api/2.13.0/log4j-api-2.13.0.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-core/2.13.0/log4j-core-2.13.0.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.0/log4j-slf4j-impl-2.13.0.jar;." --no-fallback --allow-incomplete-classpath --report-unsupported-elements-at-runtime "-H:Class=hello.Hello" "-H:Name=hello"
Warning: the '=' character in program arguments is not fully supported.
Make sure that command line arguments using it are wrapped in double quotes.
Example:
"--vm.Dfoo=bar"

Error: Unknown arguments: path/to/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.0/log4j-slf4j-impl-2.13.0.jar, ., hello.Hello, hello

Next trial

native-image.cmd -cp "path/to/.m2/repository/org/slf4j/slf4j-api/1.7.29/slf4j-api-1.7.29.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-api/2.13.0/log4j-api-2.13.0.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-core/2.13.0/log4j-core-2.13.0.jar;path/to/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.0/log4j-slf4j-impl-2.13.0.jar;." --no-fallback --allow-incomplete-classpath --report-unsupported-elements-at-runtime hello.Hello
Error: Unknown arguments: path/to/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.0/log4j-slf4j-impl-2.13.0.jar, ., hello.Hello

Is it really the canonical way to compile with native-image? Thx

[mipastgt]

@jgranduel On UNIX the command line would be:
native-image -cp path/to/.m2/repository/org/slf4j/slf4j-api/1.7.29/slf4j-api-1.7.29.jar:path/to/.m2/repository/org/apache/logging/log4j/log4j-api/2.13.0/log4j-api-2.13.0.jar:path/to/.m2/repository/org/apache/logging/log4j/log4j-core/2.13.0/log4j-core-2.13.0.jar:path/to/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.13.0/log4j-slf4j-impl-2.13.0.jar:/Users/mpaus/Projects/LocalEval/Hello/target/hello-1.0-SNAPSHOT.jar --no-fallback --allow-incomplete-classpath --report-unsupported-elements-at-runtime -H:Class=hello.Hello -H:Name=hello
On Windows the rules are a little bit different. You have to replace ':' with ';' and '/' with '' and maybe a few more things. (I don't use Windows)
But this is really not related to this issue here.

[jgranduel]

@mipastgt
Thank you very much. It was a way to confirm the syntax and also test on another platform (I've been able to compile code on Windows with GraalVM-19.3 very recently) and having issues with a HelloWorld class with dependencies, I first wanted to discard the syntax error possibility. I wasn't sure for -cp path/to/jar;.... In PowerShell, we can keep the "/" as path separators. Good luck with your issue.

[mipastgt]

I learned by now that the issue is probably caused by using MethodHandles which, according to https://github.com/oracle/graal/blob/master/substratevm/LIMITATIONS.md , are not supported in native images.

So what is the policy to deal with code which uses MethodHandles. Log4J2 is just one of these but maybe the most popular one. The error message All methods from java.lang.invoke should have been replaced during image building. suggests that these methods are somehow replaced automatically during the image build but that is probably just wishfull thinking. So what am I supposed to do? Rewrite Log4J2 or what?

Just for the record: The problem was introduced in Log4J 2.8
https://issues.apache.org/jira/browse/LOG4J2-1764 , so versions 2.7 and older don't have this problem. This issue was created based on version 2.13.0.

[eginez]

@mipastgt Currently the support the support for MethodHandles varies a lot depending in the use case (see #955). You are probably running into one of the unsupported cases in your example. As for a work around, the one I can think of is to downgrade your dependency to a version of log4j that does not use MethodHandles

[neomatrix369]

Any suggestion which version of log4j does not use MethodHandles - if someone has already found this out. It's also hard to do this once we have come to this point cause then the jar needs rebuilding and the whole cycle again.

[mipastgt]

@neomatrix369 I have mentioned that here: Link

[ericdallo]

GraalVM 21.0.0 now supports MethodHandles, isn't that fix the issue?

[mipastgt]

Maybe. I am not using Log4J2 anymore and so haven't tried it.

[muellerc]

I spend a lot of time to get it working with GraalVM 21.0.0 and log4j 2.10.0 (and optimize the reflect-config.json, to reduce the size of the native image from 28MB to 18MB):
https://github.com/muellerc/graalvm-sandbox/tree/main/log4j2-sandbox

[ericdallo]

Nice, I'll take a look on your config, thanks!

[mipastgt]

@muellerc Just a side note. If you really want to reduce the size of the native image, then have a look at UPX (https://upx.github.io/). I was able to reduce the size of my native images to about 30% of their original sizes with it.

[ericdallo]

Oh, so does it work for graalvm compiled binaries @mipastgt ?

[mipastgt]

Yes it does. Here is a little write-up of my experience (second half of the article): https://www.mpmediasoft.de/articles/JFX-Bundles/JFX-Bundles.html

[muellerc]

Small correction, here are my numbers:

native-image:

• size: 24MB
  time log4j2-sandbox
• 0.01s user
• 0.01s system
• 39% cpu
• 0.061 total

native-image compressed with UPX (using the --best option):

• size: 7.6MB
  time log4j2-sandbox-upx
• 0.10s user
• 0.02s system
• 95% cpu
• 0.121 total

[ericdallo]

Do you know why the CPI increased that much? probably related with unzipping during UPX executable startup?