Native Image build fails with --docker-image=false

[idiotwithalaptop]

Hi,

First of all, my apologies if this has already been raised.

Now, I have recently been trying to build native images using quarkus inside of my own docker container. To do this, I opted to set the --docker-image flag to false to avoid the quarkus toolset creating a docker container within a docker container and dealing with the issues that come from that. To my surprise though, this lead to a weird error. To show this I have added a docker-container to the quarkus-quickstart/getting-started codebase which is available at https://github.com/idiotwithalaptop/quarkus-quickstarts/tree/master/getting-started.

Note: In case it helps, all examples below were run on a Macbook Pro running OSX Mojave 10.14.4 and docker 18.09.2, build 6247962

Here's what happens when I run a native build using gradle:

docker-compose run builder ./gradlew clean build buildNative --docker-build=false --info
Initialized native services in: /root/.gradle/native
Removing 0 daemon stop events from registry
Previous Daemon (47) stopped at Mon May 13 01:55:58 GMT 2019 by user or operating system
Previous Daemon (44) stopped at Mon May 13 02:01:32 GMT 2019 by user or operating system
Starting a Gradle Daemon, 1 busy and 2 stopped Daemons could not be reused, use --status for details
Starting process 'Gradle build daemon'. Working directory: /root/.gradle/daemon/5.3 Command: /opt/graalvm-ce-1.0.0-rc16/bin/java -XX:MaxMetaspaceSize=256m -XX:+HeapDumpOnOutOfMemoryError -Xms256m -Xmx512m -Dfile.encoding=UTF-8 -Duser.country=US -Duser.language=en -Duser.variant -cp /root/.gradle/wrapper/dists/gradle-5.3-bin/9tevgwefmd5lgaxkzkt5jgvch/gradle-5.3/lib/gradle-launcher-5.3.jar org.gradle.launcher.daemon.bootstrap.GradleDaemon 5.3
Successfully started process 'Gradle build daemon'
An attempt to start the daemon took 4.336 secs.
The client will now receive all logging from the daemon (pid: 43). The daemon log file: /root/.gradle/daemon/5.3/daemon-43.out.log
Starting build in new daemon [memory: 477.6 MB]
Using 6 worker leases.
Starting Build
Settings evaluated using settings file '/opt/app/settings.gradle'.
Projects loaded. Root project using build file '/opt/app/build.gradle'.
Included projects: [root project 'app']

> Configure project :
Evaluating root project 'app' using build file '/opt/app/build.gradle'.
All projects evaluated.
Selected primary task 'clean' from project :
Selected primary task 'build' from project :
Selected primary task 'buildNative' from project :
Tasks to be executed: [task ':clean', task ':compileJava', task ':processResources', task ':classes', task ':jar', task ':quarkusBuild', task ':assemble', task ':compileTestJava', task ':processTestResources', task ':testClasses', task ':test', task ':check', task ':build', task ':buildNative']
:clean (Thread[Execution worker for ':',5,main]) started.

> Task :clean
Task ':clean' is not up-to-date because:
  Task has not declared any outputs despite executing actions.
:clean (Thread[Execution worker for ':',5,main]) completed. Took 0.384 secs.
:compileJava (Thread[Execution worker for ':',5,main]) started.

> Task :compileJava
Task ':compileJava' is not up-to-date because:
  Output property 'destinationDir' file /opt/app/build/classes/java/main has been removed.
  Output property 'destinationDir' file /opt/app/build/classes/java/main/org has been removed.
  Output property 'destinationDir' file /opt/app/build/classes/java/main/org/acme has been removed.
All input files are considered out-of-date for incremental task ':compileJava'.
Full recompilation is required because no incremental change information is available. This is usually caused by clean builds or changing compiler arguments.
Compiling with JDK Java compiler API.
Created classpath snapshot for incremental compilation in 0.123 secs. 111 duplicate classes found in classpath (see all with --debug).
:compileJava (Thread[Execution worker for ':',5,main]) completed. Took 2.209 secs.
:processResources (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :processResources
Task ':processResources' is not up-to-date because:
  Output property 'destinationDir' file /opt/app/build/resources/main has been removed.
  Output property 'destinationDir' file /opt/app/build/resources/main/META-INF has been removed.
  Output property 'destinationDir' file /opt/app/build/resources/main/META-INF/resources has been removed.
:processResources (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 0.138 secs.
:classes (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :classes
Skipping task ':classes' as it has no actions.
:classes (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 0.002 secs.
:jar (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :jar
Task ':jar' is not up-to-date because:
  Output property 'archiveFile' file /opt/app/build/libs/app.jar has been removed.
:jar (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 0.124 secs.
:quarkusBuild (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :quarkusBuild
Task ':quarkusBuild' is not up-to-date because:
  Task has not declared any outputs despite executing actions.
building quarkus runner
Beginning quarkus augmentation
JBoss Threads version 3.0.0.Alpha4
Quarkus augmentation completed in 1990ms
Building jar: /opt/app/build/app-runner.jar
:quarkusBuild (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 3.775 secs.
:assemble (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :assemble
Skipping task ':assemble' as it has no actions.
:assemble (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 0.0 secs.
:compileTestJava (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :compileTestJava
Task ':compileTestJava' is not up-to-date because:
  Output property 'destinationDir' file /opt/app/build/classes/java/test has been removed.
  Output property 'destinationDir' file /opt/app/build/classes/java/test/org has been removed.
  Output property 'destinationDir' file /opt/app/build/classes/java/test/org/acme has been removed.
All input files are considered out-of-date for incremental task ':compileTestJava'.
Full recompilation is required because no incremental change information is available. This is usually caused by clean builds or changing compiler arguments.
Compiling with JDK Java compiler API.
Created classpath snapshot for incremental compilation in 0.115 secs. 258 duplicate classes found in classpath (see all with --debug).
:compileTestJava (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 2.336 secs.
:processTestResources (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :processTestResources NO-SOURCE
file or directory '/opt/app/src/test/resources', not found
Skipping task ':processTestResources' as it has no source files and no previous output files.
:processTestResources (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 0.005 secs.
:testClasses (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :testClasses
Skipping task ':testClasses' as it has no actions.
:testClasses (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 0.0 secs.
:test (Thread[Execution worker for ':' Thread 5,5,main]) started.

> Task :test
Task ':test' is not up-to-date because:
  Output property 'binResultsDir' file /opt/app/build/test-results/test/binary has been removed.
  Output property 'binResultsDir' file /opt/app/build/test-results/test/binary/output.bin has been removed.
  Output property 'binResultsDir' file /opt/app/build/test-results/test/binary/output.bin.idx has been removed.
Finished generating test XML results (0.037 secs) into: /opt/app/build/test-results/test
Generating HTML test report...
Finished generating test html results (0.062 secs) into: /opt/app/build/reports/tests/test
:test (Thread[Execution worker for ':' Thread 5,5,main]) completed. Took 1.043 secs.
:check (Thread[Execution worker for ':' Thread 4,5,main]) started.

> Task :check
Skipping task ':check' as it has no actions.
:check (Thread[Execution worker for ':' Thread 4,5,main]) completed. Took 0.001 secs.
:build (Thread[Execution worker for ':' Thread 4,5,main]) started.

> Task :build
Skipping task ':build' as it has no actions.
:build (Thread[Execution worker for ':' Thread 4,5,main]) completed. Took 0.0 secs.
:buildNative (Thread[Execution worker for ':' Thread 4,5,main]) started.

> Task :buildNative
Task ':buildNative' is not up-to-date because:
  Task has not declared any outputs despite executing actions.
building native image
Running Quarkus native-image plugin on OpenJDK GraalVM CE 1.0.0-rc16
/opt/graalvm-ce-1.0.0-rc16//bin/native-image -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy$BySpaceAndTime -jar app-runner.jar -J-Djava.util.concurrent.ForkJoinPool.common.parallelism=1 -H:FallbackThreshold=0 -H:+PrintAnalysisCallTree -H:-AddAllCharsets -H:-SpawnIsolates -H:-JNI --no-server -H:-UseServiceLoaderFeature -H:+StackTrace

Error: Image build request failed with exit status 137

> Task :buildNative FAILED
:buildNative (Thread[Execution worker for ':' Thread 4,5,main]) completed. Took 4 mins 31.139 secs.

FAILURE: Build failed with an exception.

* What went wrong:
Execution failed for task ':buildNative'.
> Failed to generate a native image

* Try:
Run with --stacktrace option to get the stack trace. Run with --debug option to get more log output. Run with --scan to get full insights.

* Get more help at https://help.gradle.org

BUILD FAILED in 4m 56s
8 actionable tasks: 8 executed

If I try to run the native-image using the same arguments in the output above, it shows that it can't initialise the class specified in -H:InitialCollectionPolicy:

docker-compose run builder /opt/graalvm-ce-1.0.0-rc16//bin/native-image -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -H:InitialCollectionPolicy=com.oracle.svm.core.genscavenge.CollectionPolicy$BySpaceAndTime -jar build/app-runner.jar -J-Djava.util.concurrent.ForkJoinPool.common.parallelism=1 -H:FallbackThreshold=0 -H:+PrintAnalysisCallTree -H:-AddAllCharsets -H:EnableURLProtocols=http -H:-SpawnIsolates -H:-JNI --no-server -H:-UseServiceLoaderFeature -H:+StackTrace -H:+ReportExceptionStackTraces
[app-runner:7]    classlist:  10,416.03 ms
[app-runner:7]        setup:      59.24 ms
Error: policy com.oracle.svm.core.genscavenge.CollectionPolicy cannot be instantiated.
com.oracle.svm.core.util.UserError$UserException: policy com.oracle.svm.core.genscavenge.CollectionPolicy cannot be instantiated.
	at com.oracle.svm.core.util.UserError.abort(UserError.java:65)
	at com.oracle.svm.core.genscavenge.HeapPolicy.instantiatePolicy(HeapPolicy.java:85)
	at com.oracle.svm.core.genscavenge.CollectionPolicy.getInitialPolicy(CollectionPolicy.java:59)
	at com.oracle.svm.core.genscavenge.GCImpl.<init>(GCImpl.java:162)
	at com.oracle.svm.core.genscavenge.HeapImpl.<init>(HeapImpl.java:111)
	at com.oracle.svm.core.genscavenge.graal.HeapFeature.afterRegistration(HeapFeature.java:66)
	at com.oracle.svm.hosted.NativeImageGenerator.lambda$setupNativeImage$11(NativeImageGenerator.java:807)
	at com.oracle.svm.hosted.FeatureHandler.forEachFeature(FeatureHandler.java:65)
	at com.oracle.svm.hosted.NativeImageGenerator.setupNativeImage(NativeImageGenerator.java:807)
	at com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:522)
	at com.oracle.svm.hosted.NativeImageGenerator.lambda$run$0(NativeImageGenerator.java:442)
	at java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1386)
	at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
	at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
	at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
	at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)
Error: Image build request failed with exit status 1

But, it has removed the embedded class BySpaceAndTime from the instantiation because the dollar sign $ is being interpolated. To test this, I run the same command again but wrapped with single quotes to avoid interpolation and it works perfectly:

docker-compose run builder /opt/graalvm-ce-1.0.0-rc16//bin/native-image -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -H:InitialCollectionPolicy='com.oracle.svm.core.genscavenge.CollectionPolicy$BySpaceAndTime' -jar build/app-runner.jar -J-Djava.util.concurrent.ForkJoinPool.common.parallelism=1 -H:FallbackThreshold=0 -H:+PrintAnalysisCallTree -H:-AddAllCharsets -H:EnableURLProtocols=http -H:-SpawnIsolates -H:-JNI --no-server -H:-UseServiceLoaderFeature -H:+StackTrace -H:+ReportExceptionStackTraces


[app-runner:6]    classlist:  10,236.13 ms
[app-runner:6]        (cap):   1,317.99 ms
[app-runner:6]        setup:   3,292.46 ms
02:42:28,567 INFO  [org.jbo.threads] JBoss Threads version 3.0.0.Alpha4
02:42:29,057 INFO  [org.xnio] XNIO version 3.7.0.Final
02:42:29,202 INFO  [org.xni.nio] XNIO NIO Implementation Version 3.7.0.Final
[app-runner:6]   (typeflow):  14,227.41 ms
[app-runner:6]    (objects):  11,530.14 ms
[app-runner:6]   (features):     700.86 ms
[app-runner:6]     analysis:  27,153.68 ms
Printing call tree to /opt/app/reports/call_tree_app-runner_20190513_024255.txt
Printing list of used classes to /opt/app/reports/used_classes_app-runner_20190513_024258.txt
Printing list of used packages to /opt/app/reports/used_packages_app-runner_20190513_024258.txt
[app-runner:6]     universe:     722.57 ms
[app-runner:6]      (parse):   2,573.98 ms
[app-runner:6]     (inline):   5,915.24 ms
[app-runner:6]    (compile):  21,167.43 ms
[app-runner:6]      compile:  31,127.77 ms
[app-runner:6]        image:   2,610.32 ms
[app-runner:6]        write:   1,149.19 ms
[app-runner:6]      [total]:  81,677.63 ms

A quick search through the quarkus codebase and I think I found the culprit. I think https://github.com/quarkusio/quarkus/blob/master/core/creator/src/main/java/io/quarkus/creator/phase/nativeimage/NativeImagePhase.java#L403 should wrap the classname with single quotations:
command.add("-H:InitialCollectionPolicy='com.oracle.svm.core.genscavenge.CollectionPolicy$BySpaceAndTime'");

Thoughts?

[gsmet]

@idiotwithalaptop I think it makes perfect sense to wrap the value. We already had a similar report.

Could you make the change, check it fixes your issue and submit a PR soon for inclusion in the next release (it should be released tomorrow or the day after)?

Thanks!

[ghost]

Sure, i'll sort that out today

[stuartwdouglas]

I don't think this is correct. There should be no escaping going on as it is a ProcessBuilder.

I am not really sure where docker actually comes into the gradle build? It looks like the build that fails is not using docker, then you do a different build with docker that has an escapting problem that then works after you fix it? I don't think this is actually related to the original failure.

I am not sure why the gradle build is not giving more details as to the cause of the original failure.

[gsmet]

Closing for now. Let's revisit if somebody else encounters the issue in recent versions.

[jaikiran]

I am not sure why the gradle build is not giving more details as to the cause of the original failure.

This appears to be an issue in GraalVM's native-image generation itself, where it doesn't report the original cause. I've opened oracle/graal#2241 to improve that.

[piyushwadhwani]

encountering same issue with ubuntu 18.04 and graal VM

Error: policy com.oracle.svm.core.genscavenge.CollectionPolicy cannot be instantiated.
com.oracle.svm.core.util.UserError$UserException: policy com.oracle.svm.core.genscavenge.CollectionPolicy cannot be instantiated.
at com.oracle.svm.core.util.UserError.abort(UserError.java:68)
at com.oracle.svm.core.genscavenge.HeapPolicy.instantiatePolicy(HeapPolicy.java:88)
at com.oracle.svm.core.genscavenge.CollectionPolicy.getInitialPolicy(CollectionPolicy.java:59)
at com.oracle.svm.core.genscavenge.GCImpl.(GCImpl.java:147)
java -version
openjdk version "11.0.6" 2020-01-14
OpenJDK Runtime Environment GraalVM CE 20.0.0 (build 11.0.6+9-jvmci-20.0-b02)
OpenJDK 64-Bit Server VM GraalVM CE 20.0.0 (build 11.0.6+9-jvmci-20.0-b02, mixed mode, sharing)