Native image build fails with 1.9.1.Final of Quarkus with Graal VM even though i have marked classes to be initialised during runtime.

[krayba]

[INFO] [io.quarkus.deployment.pkg.steps.JarResultBuildStep] Building native image source jar: /Users/kedarraybagkar/MyData/pbs/ice-store-workspace/ice-store/target/ice-store-0.1.0-native-image-source-jar/ice-store-0.1.0-runner.jar [INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Building native image from /Users/kedarraybagkar/MyData/pbs/ice-store-workspace/ice-store/target/ice-store-0.1.0-native-image-source-jar/ice-store-0.1.0-runner.jar [INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM Version 20.1.0 (Java Version 11.0.7) [INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] /Users/kedarraybagkar/.sdkman/candidates/java/20.1.0.r11-grl/bin/native-image -J-DCoordinatorEnvironmentBean.transactionStatusManagerEnable=false -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=1 -J-Duser.language=en -J-Dfile.encoding=UTF-8 --initialize-at-run-time=io.netty.buffer.PooledByteBufAllocator,io.netty.buffer.ByteBufUtil,io.netty.buffer.ByteBufAllocator,io.lettuce.core.metrics,io.quarkus.runner.AutoFeature.beforeAnalysis --initialize-at-build-time= -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -jar ice-store-0.1.0-runner.jar -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -H:-AddAllCharsets -H:EnableURLProtocols=http,https --enable-all-security-services --no-server -H:-UseServiceLoaderFeature -H:+StackTrace ice-store-0.1.0-runner [ice-store-0.1.0-runner:748] classlist: 13,891.85 ms, 1.69 GB [ice-store-0.1.0-runner:748] (cap): 5,486.16 ms, 1.69 GB [ice-store-0.1.0-runner:748] setup: 7,424.44 ms, 1.69 GB 17:15:15,328 INFO [io.und.web.jsr] UT026003: Adding annotated server endpoint class com.majesco.ice.store.WebSocketResource for path /ws/store/{client} [ice-store-0.1.0-runner:748] analysis: 14,721.13 ms, 2.30 GB Error: Classes that should be initialized at run time got initialized during image building: io.netty.buffer.PooledByteBufAllocator the class was requested to be initialized at run time (from the command line and from feature io.quarkus.runner.AutoFeature.beforeAnalysis). To see why io.netty.buffer.PooledByteBufAllocator got initialized use -H:+TraceClassInitialization

com.oracle.svm.core.util.UserError$UserException: Classes that should be initialized at run time got initialized during image building: io.netty.buffer.PooledByteBufAllocator the class was requested to be initialized at run time (from the command line and from feature io.quarkus.runner.AutoFeature.beforeAnalysis). To see why io.netty.buffer.PooledByteBufAllocator got initialized use -H:+TraceClassInitialization

at com.oracle.svm.core.util.UserError.abort(UserError.java:68)
at com.oracle.svm.hosted.classinitialization.ConfigurableClassInitialization.checkDelayedInitialization(ConfigurableClassInitialization.java:518)
at com.oracle.svm.hosted.classinitialization.ClassInitializationFeature.duringAnalysis(ClassInitializationFeature.java:187)
at com.oracle.svm.hosted.NativeImageGenerator.lambda$runPointsToAnalysis$8(NativeImageGenerator.java:720)
at com.oracle.svm.hosted.FeatureHandler.forEachFeature(FeatureHandler.java:70)
at com.oracle.svm.hosted.NativeImageGenerator.runPointsToAnalysis(NativeImageGenerator.java:720)
at com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:538)
at com.oracle.svm.hosted.NativeImageGenerator.lambda$run$0(NativeImageGenerator.java:451)
at java.base/java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1407)
at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)

Error: Image build request failed with exit status 1 [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE [INFO] ------------------------------------------------------------------------ [INFO] Total time: 44.898 s [INFO] Finished at: 2020-11-04T17:15:29+05:30 [INFO] ------------------------------------------------------------------------ [ERROR] Failed to execute goal io.quarkus:quarkus-maven-plugin:1.9.1.Final:build (default) on project ice-store: Failed to build quarkus application: io.quarkus.builder.BuildException: Build failure: Build failed due to errors [ERROR] [error]: Build step io.quarkus.deployment.pkg.steps.NativeImageBuildStep#build threw an exception: java.lang.RuntimeException: Failed to build native image [ERROR] at io.quarkus.deployment.pkg.steps.NativeImageBuildStep.build(NativeImageBuildStep.java:307) [ERROR] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [ERROR] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [ERROR] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [ERROR] at java.base/java.lang.reflect.Method.invoke(Method.java:566) [ERROR] at io.quarkus.deployment.ExtensionLoader$2.execute(ExtensionLoader.java:936) [ERROR] at io.quarkus.builder.BuildContext.run(BuildContext.java:277) [ERROR] at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) [ERROR] at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2046) [ERROR] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1578) [ERROR] at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452) [ERROR] at java.base/java.lang.Thread.run(Thread.java:834) [ERROR] at org.jboss.threads.JBossThread.run(JBossThread.java:479) [ERROR] Caused by: java.lang.RuntimeException: Image generation failed. Exit code: 1 [ERROR] at io.quarkus.deployment.pkg.steps.NativeImageBuildStep.imageGenerationFailed(NativeImageBuildStep.java:520) [ERROR] at io.quarkus.deployment.pkg.steps.NativeImageBuildStep.build(NativeImageBuildStep.java:276) [ERROR] ... 12 more [ERROR] -> [Help 1] [ERROR] [ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch. [ERROR] Re-run Maven using the -X switch to enable full debug logging. [ERROR] [ERROR] For more information about the errors and possible solutions, please read the following articles: [ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoExecutionException

[ctron]

I just ran into the same issue. Is there any solution to this?

[gsmet]

@ctron without a reproducer, there's not much we can do to understand what's going on. The first thing would be to follow the instructions GraalVM gives you and use -H:+TraceClassInitialization to better understand what's going on.

[ctron]

@gsmet I already tried that, I think I understand why it initialized that class, but I don't know why that should cause a problem. I also tried to work around this using @TargetClass and @Substitute without any success.

Error: Classes that should be initialized at run time got initialized during image building:
 io.netty.buffer.PooledByteBufAllocator the class was requested to be initialized at run time (from the command line and from feature io.quarkus.runner.AutoFeature.beforeAnalysis). org.eclipse.milo.opcua.stack.core.util.BufferUtil caused initialization of this class with the following trace: 
        at io.netty.buffer.PooledByteBufAllocator.<clinit>(PooledByteBufAllocator.java:38)
        at org.eclipse.milo.opcua.stack.core.util.BufferUtil.<clinit>(BufferUtil.java:20)

The code to all of that is here: https://github.com/drogue-iot/drogue-agent-opcua/

[geoand]

@ctron is this still an issue?

[ctron]

I am not sure, didn't test for a while. I will try to see if I can reproduce that.

[ctron]

Looks like:

[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildStep] Running Quarkus native-image plugin on GraalVM 21.3.0 Java 11 CE (Java Version 11.0.13+7-jvmci-21.3-b05)
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] podman run --env LANG=C --rm --user 110147:110147 --userns=keep-id -v /home/jreimann/git/drogue-agent-opcua/target/opcua-agent-1.0.0-SNAPSHOT-native-image-source-jar:/project:z --name build-native-tYONp quay.io/quarkus/ubi-quarkus-native-image:21.3-java11 -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=IE -J-Dfile.encoding=UTF-8 -H:-ParseOnce -J--add-exports=java.security.jgss/sun.security.krb5=ALL-UNNAMED -J--add-opens=java.base/java.text=ALL-UNNAMED --trace-class-initialization=io.netty.buffer.PooledByteBufAllocator -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy\$BySpaceAndTime -H:+JNI -H:+AllowFoldMethods -J-Djava.awt.headless=true -H:FallbackThreshold=0 -H:+ReportExceptionStackTraces -H:-AddAllCharsets -H:EnableURLProtocols=http,https -H:NativeLinkerOption=-no-pie -H:-UseServiceLoaderFeature -H:+StackTrace opcua-agent-1.0.0-SNAPSHOT-runner -jar opcua-agent-1.0.0-SNAPSHOT-runner.jar
[opcua-agent-1.0.0-SNAPSHOT-runner:21]    classlist:   2,288.78 ms,  1.68 GB
[opcua-agent-1.0.0-SNAPSHOT-runner:21]        (cap):     399.51 ms,  1.68 GB
[opcua-agent-1.0.0-SNAPSHOT-runner:21]        setup:   1,552.88 ms,  1.68 GB
09:16:05,963 INFO  [org.ecl.mil.opc.sdk.cli.OpcUaClient] Eclipse Milo OPC UA Stack version: 0.6.3
09:16:05,967 INFO  [org.ecl.mil.opc.sdk.cli.OpcUaClient] Eclipse Milo OPC UA Client SDK version: 0.6.3
09:16:06,651 INFO  [org.ecl.mil.opc.sta.cor.uti.NonceUtil] SecureRandom seeded in 0ms.
09:16:12,827 INFO  [org.jbo.threads] JBoss Threads version 3.4.2.Final
[opcua-agent-1.0.0-SNAPSHOT-runner:21]     analysis:  14,532.59 ms,  5.93 GB
Error: Classes that should be initialized at run time got initialized during image building:
 io.netty.buffer.PooledByteBufAllocator the class was requested to be initialized at run time (from jar:file:///project/lib/io.netty.netty-buffer-4.1.72.Final.jar!/META-INF/native-image/io.netty/buffer/native-image.properties with 'io.netty.buffer.PooledByteBufAllocator' and from feature io.quarkus.runner.AutoFeature.beforeAnalysis with 'PooledByteBufAllocator.class'). org.eclipse.milo.opcua.stack.core.util.BufferUtil caused initialization of this class with the following trace: 
        at io.netty.buffer.PooledByteBufAllocator.<clinit>(PooledByteBufAllocator.java:38)
        at org.eclipse.milo.opcua.stack.core.util.BufferUtil.<clinit>(BufferUtil.java:20)

com.oracle.svm.core.util.UserError$UserException: Classes that should be initialized at run time got initialized during image building:
 io.netty.buffer.PooledByteBufAllocator the class was requested to be initialized at run time (from jar:file:///project/lib/io.netty.netty-buffer-4.1.72.Final.jar!/META-INF/native-image/io.netty/buffer/native-image.properties with 'io.netty.buffer.PooledByteBufAllocator' and from feature io.quarkus.runner.AutoFeature.beforeAnalysis with 'PooledByteBufAllocator.class'). org.eclipse.milo.opcua.stack.core.util.BufferUtil caused initialization of this class with the following trace: 
        at io.netty.buffer.PooledByteBufAllocator.<clinit>(PooledByteBufAllocator.java:38)
        at org.eclipse.milo.opcua.stack.core.util.BufferUtil.<clinit>(BufferUtil.java:20)

        at com.oracle.svm.core.util.UserError.abort(UserError.java:73)
        at com.oracle.svm.hosted.classinitialization.ConfigurableClassInitialization.checkDelayedInitialization(ConfigurableClassInitialization.java:555)
        at com.oracle.svm.hosted.classinitialization.ClassInitializationFeature.duringAnalysis(ClassInitializationFeature.java:168)
        at com.oracle.svm.hosted.NativeImageGenerator.lambda$runPointsToAnalysis$12(NativeImageGenerator.java:727)
        at com.oracle.svm.hosted.FeatureHandler.forEachFeature(FeatureHandler.java:73)
        at com.oracle.svm.hosted.NativeImageGenerator.runPointsToAnalysis(NativeImageGenerator.java:727)
        at com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:529)
        at com.oracle.svm.hosted.NativeImageGenerator.run(NativeImageGenerator.java:488)
        at com.oracle.svm.hosted.NativeImageGeneratorRunner.buildImage(NativeImageGeneratorRunner.java:403)
        at com.oracle.svm.hosted.NativeImageGeneratorRunner.build(NativeImageGeneratorRunner.java:569)
        at com.oracle.svm.hosted.NativeImageGeneratorRunner.main(NativeImageGeneratorRunner.java:122)
        at com.oracle.svm.hosted.NativeImageGeneratorRunner$JDK9Plus.main(NativeImageGeneratorRunner.java:599)
[opcua-agent-1.0.0-SNAPSHOT-runner:21]      [total]:  18,588.86 ms,  5.93 GB
# Printing build artifacts to: /project/opcua-agent-1.0.0-SNAPSHOT-runner.build_artifacts.txt
Error: Image build request failed with exit status 1

[ctron]

I would still expect that the following override fixes the issue. However, it does not:

@TargetClass(org.eclipse.milo.opcua.stack.core.util.BufferUtil.class)
@Substitute
public final class Target_org_eclipse_milo_opcua_stack_core_util_BufferUtil {

    @Substitute
    public static CompositeByteBuf compositeBuffer() {
        return new CompositeByteBuf(ByteBufAllocator.DEFAULT, false, 16);
    }

    @Substitute
    public static ByteBuf pooledBuffer() {
        return Unpooled.buffer();
    }

    @Substitute
    public static ByteBuf pooledBuffer(int initialCapacity) {
        return Unpooled.buffer(initialCapacity);
    }

}

[geoand]

Are you trying to remove the static-init of BufferUtil? Because thar substitution does not accomplish that

[ctron]

Yes. I think that is necessary. On the documentation of the @Substitute I think I read that if you put it on the class level, it replaces whole class. Which should also drop the static init section?!

Anyway, I did try to add @Delete to the allocator field. Which didn't work either:

@Delete
private static ByteBufAllocator allocator = PooledByteBufAllocator.DEFAULT;

I had to drop the final as the build complained that this was useless.

[geoand]

For reference, the initial class looks like this:

package org.eclipse.milo.opcua.stack.core.util;

public class BufferUtil {

    private static final ByteBufAllocator allocator = PooledByteBufAllocator.DEFAULT;

    /**
     * @return a pooled {@link CompositeByteBuf}.
     */
    public static CompositeByteBuf compositeBuffer() {
        return allocator.compositeBuffer();
    }

    /**
     * @return a pooled {@link ByteBuf} in <b>BIG ENDIAN</b> byte order.
     */
    public static ByteBuf pooledBuffer() {
        return allocator.buffer();
    }

    /**
     * @return a pooled {@link ByteBuf} in <b>BIG ENDIAN</b> byte order, with an initial capacity of
     * {@code initialCapacity}.
     */
    public static ByteBuf pooledBuffer(int initialCapacity) {
        return allocator.buffer(initialCapacity);
    }

}

Can you try:

@TargetClass(org.eclipse.milo.opcua.stack.core.util.BufferUtil.class)
public final class Target_org_eclipse_milo_opcua_stack_core_util_BufferUtil {

    @Alias
    @RecomputeFieldValue(kind = RecomputeFieldValue.Kind.Reset)
    private static final ByteBufAllocator allocator;
}

please?

[ctron]

I had to drop the final, as there was no value assigned. However, this didn't make a difference.

[geoand]

How about with the final but set to null?

[ctron]

No, that doesn't work either.

I also tried:

    @Alias
    @RecomputeFieldValue(kind = RecomputeFieldValue.Kind.Reset)
    private static final ByteBufAllocator allocator;

    static {
        allocator = null;
    }

Trying to explicitly add a static init section.

[geoand]

@zakkak any tips on this?

[zakkak]

I am having a hard time getting over this with substitutions just like you :confused:. I will try to create a reproducer and see what's going on. In the meantime you can work around the issue with:

mvn package -Pnative -Dquarkus.native.additional-build-args=--initialize-at-run-time=org.eclipse.milo.opcua.stack.core.util.BufferUtil\\,org.eclipse.milo.opcua.stack.core.util.NonceUtil

[ctron]

That still fails with:

Error: com.oracle.graal.pointsto.constraints.UnsupportedFeatureException: Detected an instance of Random/SplittableRandom class in the image heap. Instances created during image generation have cached seed values and don't behave as expected.  To see how this object got instantiated use --trace-object-instantiation=java.util.Random. The object was probably created by a class initializer and is reachable from a static field. You can request class initialization at image runtime by using the option --initialize-at-run-time=<class-name>. Or you can write your own initialization methods and call them explicitly from your main entry point.
Detailed message:
Trace: 
        at parsing com.google.common.cache.Striped64.retryUpdate(Striped64.java:184)
Call path from entry point to com.google.common.cache.Striped64.retryUpdate(long, int[], boolean): 
        at com.google.common.cache.Striped64.retryUpdate(Striped64.java:182)
        at com.google.common.cache.LongAdder.add(LongAdder.java:73)
        at com.google.common.cache.AbstractCache$SimpleStatsCounter.recordLoadException(AbstractCache.java:230)
        at com.google.common.cache.LocalCache$Segment.getAndRecordStats(LocalCache.java:2322)
        at com.google.common.cache.LocalCache$Segment$1.run(LocalCache.java:2293)
        at java.lang.Thread.run(Thread.java:829)
        at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:600)
        at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:192)
        at com.oracle.svm.core.code.IsolateEnterStub.PosixJavaThreads_pthreadStartRoutine_e1f4a8c0039f8337338252cd8734f63a79b5e3df(generated:0)

[zakkak]

@ctron are you sure you don't have any local changes in your working directory?

cd /tmp
git clone https://github.com/drogue-iot/drogue-agent-opcua/
cd drogue-agent-opcua
mvn clean package -Pnative -Dquarkus.native.additional-build-args=--initialize-at-run-time=org.eclipse.milo.opcua.stack.core.util.BufferUtil\\,org.eclipse.milo.opcua.stack.core.util.NonceUtil

Works for me

[ctron]

Indeed I had. Mainly the upgrade to Quarkus 2.x.

I also was using the quarkus.native.additional-build-args from the pom.xml instead of command line arguments. Which caused me a few headaches, especially when the IDE re-formats the XML file, and adds line breaks to the property.

I pushed the changes now. But using command line arguments of properties, doesn't seem to make a difference.

[zakkak]

OK, so now it's failing due to guava's LocalCache. Like you initially did for BufferUtil you would need to find what's causing this initializations and possibly substitute it or request it to be runtime initialized. @geoand it looks like guava is supported in Quarkus though, so maybe this should be fixed on the Quarkus side instead?

[geoand]

Guava is most definitely not supported :).

What gived you the impressions it is?

[zakkak]

What gived you the impressions it is?

Hmmm, interesting. I was sure I saw it listed under https://github.com/quarkusio/quarkus/blob/main/bom/application/pom.xml, but it is not :confused:. Sorry for the confusion.

[geoand]

Sorry for the confusion.

No problem :)

[geoand]

Is this still an issue or can we close?

[ctron]

In general this is still an issue. I am still unable to build the OPC UA server. However, it looks like it fails later on now.

I am not sure what to do with this TBH.

[ctron]

I retried, and:

[INFO] BUILD SUCCESS

I guess these are the versions involved:

Checking image status quay.io/quarkus/ubi-quarkus-native-image:22.2-java17
Running Quarkus native-image plugin on GraalVM 22.2.0 Java 17 CE (Java Version 17.0.4+8-jvmci-22.2-b06)

Which, like before, suggest to use "trace" and "initialize at runtime" arguments. So ended up with:

<quarkus.native.additional-build-args>--initialize-at-run-time=org.eclipse.milo.opcua.stack.core.util.BufferUtil,--initialize-at-run-time=org.eclipse.milo.opcua.stack.core.util.NonceUtil</quarkus.native.additional-build-args>

And that let me compile successfully. I didn't check yet if it actually works. But at least, I am definitely one step closer.

[ctron]

I had to add a few classes for registration, but it looks good now. I would consider it closed.

[geoand]

Thanks a lot of checking!

[ThoSap]

If someone needs an up-to-date guide on how to run Eclipse Milo with GraalVM native-image (+Quarkus), I've been running this setup since November 11th, 2021. This configuration works with all the latest versions as of today (tested with Quarkus 3.10.0, Java 21, Eclipse Milo 0.6.12). https://github.com/eclipse/milo/issues/1267#issuecomment-2092745795