Graal: Regression: All Micronaut apps fail with JDK11

[ilopmar]

Describe the issue

Last Friday night our CI started to fail building GraalVM from source using JDK11. See https://gitlab.com/micronaut-projects/micronaut-graal-tests/-/jobs/822485895#L529

Building gu.image... [dependency INSTALLER updated]
[gu:4099]    classlist:   4,314.15 ms,  0.96 GB
[gu:4099]        setup:     301.20 ms,  0.96 GB
Error: Could not find target method: long com.oracle.svm.core.jdk.JavaAWTSubstitutions$Target_sun_font_FileFontStrike._getGlyphImageFromWindows(java.lang.String,int,int,int,boolean,int)
Error: Use -H:+ReportExceptionStackTraces to print stacktrace of underlying exception
Error: Image build request failed with exit status 1

We were using labsjdk-ce-11.0.7+10-jvmci-20.2-b01 and this morning I've updated it to labsjdk-ce-11.0.9+10-jvmci-20.3-b04 and now we were able to build again GraalVM from source. Not sure if this is the JDK we are supposed to use now or not.

See https://gitlab.com/micronaut-projects/micronaut-graal-tests/-/commit/8bef91656ea2d34c97535d885c69b0166e9b08b5

After that change ALL the test applications fails to build with GraalVM JDK 11 with the error:

Fatal error:com.oracle.svm.core.util.VMError$HostedError: com.oracle.svm.core.util.UserError$UserException: Image heap writing found a class not seen during static analysis. Did a static field or an object referenced from a static field change during native image generation? For example, a lazily initialized cache could have been initialized during image generation, in which case you need to force eager initialization of the cache before static analysis or reset the cache using a field value recomputation.

CI pipeline execution and detailed error log.

Steps to reproduce the issue

• git clone https://github.com/micronaut-graal-tests/micronaut-basic-app
• cd micronaut-basic-app
• git checkout 2.1.x
• Use GraalVM for JDK11 compiled from master branch.
• ./build-native-image.sh

Describe GraalVM and your environment:

• GraalVM version: 843532ee1762301df2eea24c482a19f3f73be9d1. Probably happened before this, but not really sure.
• JDK major version: 11
• OS: Linux
• Architecture: AMD64

More details

[basic-app:173]    classlist:  12,603.18 ms,  0.96 GB
[basic-app:173]        (cap):   1,474.76 ms,  0.96 GB
[basic-app:173]        setup:   5,958.30 ms,  0.96 GB
[basic-app:173]     (clinit):   2,536.41 ms,  1.96 GB
[basic-app:173]   (typeflow): 103,602.14 ms,  1.96 GB
[basic-app:173]    (objects): 171,973.57 ms,  1.96 GB
[basic-app:173]   (features):   5,138.84 ms,  1.96 GB
[basic-app:173]     analysis: 286,031.92 ms,  1.96 GB
[basic-app:173]     universe:   9,613.23 ms,  1.96 GB
[basic-app:173]      (parse):  40,048.46 ms,  2.26 GB
[basic-app:173]     (inline):  44,076.18 ms,  2.59 GB
[basic-app:173]    (compile): 180,756.25 ms,  2.74 GB
[basic-app:173]      compile: 273,747.14 ms,  2.74 GB
[basic-app:173]        image:   2,307.95 ms,  2.74 GB
Fatal error:com.oracle.svm.core.util.VMError$HostedError: com.oracle.svm.core.util.UserError$UserException: Image heap writing found a class not seen during static analysis. Did a static field or an object referenced from a static field change during native image generation? For example, a lazily initialized cache could have been initialized during image generation, in which case you need to force eager initialization of the cache before static analysis or reset the cache using a field value recomputation.
    object: sun.awt.resources.awt@570a73d6  of class: sun.awt.resources.awt
  reachable through:
    object: java.util.ResourceBundle$BundleReference@4dd35098  of class: java.util.ResourceBundle$BundleReference
    object: CacheKey[sun.awt.resources.awt, locale="", module=module java.desktop, callerModule=module java.desktop, format=java.class]=java.util.ResourceBundle$BundleReference@4dd35098  of class: java.util.concurrent.ConcurrentHashMap$Node
    object: [Ljava.util.concurrent.ConcurrentHashMap$Node;@20c1b561  of class: java.util.concurrent.ConcurrentHashMap$Node[]
    object: {CacheKey[sun.util.logging.resources.logging, locale=en, module=module java.logging, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@305fec2, CacheKey[sun.util.resources.TimeZoneNames, locale=en_US, module=module java.base, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@4528241f, CacheKey[com.sun.org.apache.xerces.internal.impl.xpath.regex.message, locale=en, module=module java.xml, callerModule=module java.xml, format=java.properties]=java.util.ResourceBundle$BundleReference@6c840468, CacheKey[sun.awt.resources.awt, locale=en_US, module=module java.desktop, callerModule=module java.desktop, format=java.class]=java.util.ResourceBundle$BundleReference@37d7c3d, CacheKey[sun.awt.resources.awt, locale="", module=module java.desktop, callerModule=module java.desktop, format=java.class]=java.util.ResourceBundle$BundleReference@4dd35098, CacheKey[sun.util.resources.TimeZoneNames, locale="", module=module java.base, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@524c8e80, CacheKey[sun.awt.resources.awt, locale=en, module=module java.desktop, callerModule=module java.desktop, format=java.class]=java.util.ResourceBundle$BundleReference@4060e87d, CacheKey[sun.util.logging.resources.logging, locale=en_US, module=module java.logging, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@4bc8809e, CacheKey[sun.util.resources.TimeZoneNames, locale=en, module=module java.base, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@1d6d925e, CacheKey[com.sun.org.apache.xerces.internal.impl.xpath.regex.message, locale=en_US, module=module java.xml, callerModule=module java.xml, format=java.properties]=java.util.ResourceBundle$BundleReference@6232206e, CacheKey[sun.util.logging.resources.logging, locale="", module=module java.logging, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@60473757, CacheKey[com.sun.org.apache.xerces.internal.impl.xpath.regex.message, locale="", module=module java.xml, callerModule=module java.xml, format=java.properties]=java.util.ResourceBundle$BundleReference@6f114e67}  of class: java.util.concurrent.ConcurrentHashMap
    root: java.util.ResourceBundle.putBundleInCache(ResourceBundle$CacheKey, ResourceBundle, ResourceBundle$Control)
    at com.oracle.svm.core.util.VMError.shouldNotReachHere(VMError.java:72)
    at com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:664)
    at com.oracle.svm.hosted.NativeImageGenerator.lambda$run$0(NativeImageGenerator.java:471)
    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:183)
Caused by: com.oracle.svm.core.util.UserError$UserException: Image heap writing found a class not seen during static analysis. Did a static field or an object referenced from a static field change during native image generation? For example, a lazily initialized cache could have been initialized during image generation, in which case you need to force eager initialization of the cache before static analysis or reset the cache using a field value recomputation.
    object: sun.awt.resources.awt@570a73d6  of class: sun.awt.resources.awt
  reachable through:
    object: java.util.ResourceBundle$BundleReference@4dd35098  of class: java.util.ResourceBundle$BundleReference
    object: CacheKey[sun.awt.resources.awt, locale="", module=module java.desktop, callerModule=module java.desktop, format=java.class]=java.util.ResourceBundle$BundleReference@4dd35098  of class: java.util.concurrent.ConcurrentHashMap$Node
    object: [Ljava.util.concurrent.ConcurrentHashMap$Node;@20c1b561  of class: java.util.concurrent.ConcurrentHashMap$Node[]
    object: {CacheKey[sun.util.logging.resources.logging, locale=en, module=module java.logging, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@305fec2, CacheKey[sun.util.resources.TimeZoneNames, locale=en_US, module=module java.base, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@4528241f, CacheKey[com.sun.org.apache.xerces.internal.impl.xpath.regex.message, locale=en, module=module java.xml, callerModule=module java.xml, format=java.properties]=java.util.ResourceBundle$BundleReference@6c840468, CacheKey[sun.awt.resources.awt, locale=en_US, module=module java.desktop, callerModule=module java.desktop, format=java.class]=java.util.ResourceBundle$BundleReference@37d7c3d, CacheKey[sun.awt.resources.awt, locale="", module=module java.desktop, callerModule=module java.desktop, format=java.class]=java.util.ResourceBundle$BundleReference@4dd35098, CacheKey[sun.util.resources.TimeZoneNames, locale="", module=module java.base, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@524c8e80, CacheKey[sun.awt.resources.awt, locale=en, module=module java.desktop, callerModule=module java.desktop, format=java.class]=java.util.ResourceBundle$BundleReference@4060e87d, CacheKey[sun.util.logging.resources.logging, locale=en_US, module=module java.logging, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@4bc8809e, CacheKey[sun.util.resources.TimeZoneNames, locale=en, module=module java.base, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@1d6d925e, CacheKey[com.sun.org.apache.xerces.internal.impl.xpath.regex.message, locale=en_US, module=module java.xml, callerModule=module java.xml, format=java.properties]=java.util.ResourceBundle$BundleReference@6232206e, CacheKey[sun.util.logging.resources.logging, locale="", module=module java.logging, callerModule=unnamed module @2f7a2457, format=java.class]=java.util.ResourceBundle$BundleReference@60473757, CacheKey[com.sun.org.apache.xerces.internal.impl.xpath.regex.message, locale="", module=module java.xml, callerModule=module java.xml, format=java.properties]=java.util.ResourceBundle$BundleReference@6f114e67}  of class: java.util.concurrent.ConcurrentHashMap
    root: java.util.ResourceBundle.putBundleInCache(ResourceBundle$CacheKey, ResourceBundle, ResourceBundle$Control)
    at com.oracle.svm.core.util.UserError.abort(UserError.java:68)
    at com.oracle.svm.hosted.image.NativeImageHeap.reportIllegalType(NativeImageHeap.java:535)
    at com.oracle.svm.hosted.image.NativeImageHeap.requireType(NativeImageHeap.java:514)
    at com.oracle.svm.hosted.image.NativeImageHeap.addObjectToBootImageHeap(NativeImageHeap.java:378)
    at com.oracle.svm.hosted.image.NativeImageHeap.addObject(NativeImageHeap.java:305)
    at com.oracle.svm.hosted.image.NativeImageHeap.processAddObjectWorklist(NativeImageHeap.java:619)
    at com.oracle.svm.hosted.image.NativeImageHeap.addTrailingObjects(NativeImageHeap.java:198)
    at com.oracle.svm.hosted.NativeImageGenerator.doRun(NativeImageGenerator.java:647)
    ... 7 more
Error: Image build request failed with exit status 1

[gradinac]

Hey @ilopmar, thank you for reporting this issue!
I've managed to reproduce it locally with the sample you've posted. This appears to have been triggered by the recent AWT/Swing support changes. I'll let you know as soon as there's progress on this.

[ilopmar]

I've realized that the code that broke this is included in master branch (currently 21.0-dev) but not in release/graal-vm/20.3 branch so, as long it's not merged before the 20.3 release, then we should be good and you have plenty of time to fix it.

[gradinac]

It's still a nasty bug for master! :)
Could you try and see if the fix works with the following revision (or later): https://github.com/oracle/graal/commit/7853fc41fb4f90ae87505fa3c7eae7d43825a93b?

There's one caveat, however - now that the AWT/Swing support has been added, you might need to rework the class initialization configuration. While building your demo app, I've noticed that javax package is marked for build-time initialization - this causes javax.swing.text.html.HTMLEditorKit to be initialized at build-time, which in turn initializes java.awt.Toolkit at build-time. This leads to an error during the image build.

The responsible native-image.properties file that sets this initialization policy seems to be https://github.com/micronaut-projects/micronaut-core/blob/2.1.x/runtime/src/main/resources/META-INF/native-image/io.micronaut/runtime-graal/native-image.properties
Would removing javax initialization from those arguments work for you, or is there a different problem to which this was the workaround for?

[ilopmar]

I've tried with latest changes from master and after removing javax from the file you mentioned, the application fails to build with this error:

$ native-image -cp basic-app-0.1-all.jar
[basic-app:21100]    classlist:   1,731.48 ms,  0.94 GB
[basic-app:21100]        (cap):     451.72 ms,  0.94 GB
[basic-app:21100]        setup:   1,558.78 ms,  0.94 GB
To see how the classes got initialized, use --trace-class-initialization=javax.xml.parsers.FactoryFinder
[basic-app:21100]     analysis:  26,818.07 ms,  2.73 GB
Error: Classes that should be initialized at run time got initialized during image building:
 javax.xml.parsers.FactoryFinder was unintentionally initialized at build time. To see why javax.xml.parsers.FactoryFinder got initialized use --trace-class-initialization=javax.xml.parsers.FactoryFinder

Adding the suggested flag --trace-class-initialization=javax.xml.parsers.FactoryFinder doesn't work:

$ native-image -cp basic-app-0.1-all.jar
Error occurred during initialization of VM
Could not find agent library native-image-diagnostics-agent on the library path, with error: libnative-image-diagnostics-agent.so: cannot open shared object file: No such file or directory
Error: Image build request failed with exit status 1

I don't know if something has changed, and probably now I'm building GraalVM with some missing option. This is what I've been using for a long time:

LIBGRAAL=true mx --disable-polyglot --disable-libpolyglot --dynamicimports /substratevm build

Can you please tell me how to build graalvm with the right options so I can use --trace-class-initialization?

[gradinac]

At some point, class initialization tracing had been moved to a separate JVMTI agent. There's an mx env variable which affects which native-images get built called NATIVE_IMAGES. It's value should be a comma separated list of native-images which you'd like to build. For libraries, their names should be prefixed with lib:.
For this case, you'd need the following command:

NATIVE_IMAGES=lib:native-image-diagnostics-agent LIBGRAAL=true mx --disable-polyglot --disable-libpolyglot --dynamicimports /substratevm build

If you wanted to build a native image of both the diagnostics agent (which is a library), and native-image driver itself, you would set NATIVE_IMAGES to the following:

NATIVE_IMAGES=lib:native-image-diagnostics-agent,native-image ...

[ilopmar]

Thank you very much for the explanation.

The "culprit" was io.micronaut.runtime.Micronaut that I think needs the some xml classes for parsing logback.xml. I've changed the build time initialization of the whole javax package to initialize only javax.xml and this basic-app works again.

I think it should be good enough for now. I'm going to make those changes in Micronaut and I'll let our CI to test all the other apps.

[gradinac]

No problem at all! :)

I'm glad that you got it working again!

I'll leave this issue open for a bit more just in case something goes wrong with other apps.

[gradinac]

I'll close the issue as nothing new seems to have been broken :)
Thank you once more for reporting this!