Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Micronaut app fails with 20.3.0 Release but works with same version compiled from source code #2991

Closed
ilopmar opened this issue Nov 18, 2020 · 29 comments
Assignees

Comments

@ilopmar
Copy link

ilopmar commented Nov 18, 2020

Describe the issue

We've been continuously testing the release/graal-vm/20.3 branch for the last couple of weeks to make sure everything would work with Micronaut. All our test applications passed the build this morning at 7am using latest Micronaut snapshot and that mentioned release branch.

This morning I've switched to use the 20.3.0 version released yesterday and our Elasticsearch test application has started to fail to build the native image. It fails for both JDK 8 and 11.

I've been doing some tests locally and I've discovered that we were using and old version to build GraalVM: build 25.252-b09-jvmci-20.2-b01 vs build 25.272-b10-jvmci-20.3-b06. The latter is the one from 20.3.0 release.

I though that was the problem so I've compiled again GraalVM branch release/graal-vm/20.3 using that new java version, but I'm able to build the native image. Switching the jvm to 20.3.0 Release make it fail again.

So, I have a few questions:

  • Can you please confirm that the 20.3.0 release was created from this commit c5ff5a5.

  • This is what we do on CI. I've disabled pretty much everything because I'm only interested in native-image and I want the build to be as fast as possible.

mx --disable-polyglot --disable-libpolyglot --dynamicimports /substratevm --skip-libraries=true build

For local sometimes I use the following, which creates the agent and the diagnostics-agent:

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

Can you please share which options do you use to compile the release? I would like to use the same to have repeateble builds. Please keep in mind that I would like to disable all the things I don't need.

One final thing. I'm downloading the java releases to build GraalVM from https://github.com/graalvm/graal-jvmci-8/releases/ for Java 8 and https://github.com/graalvm/labs-openjdk-11/releases/ for Java 11. Are those the right versions I need to download?

Steps to reproduce the issue

  • git clone https://github.com/micronaut-graal-tests/micronaut-elasticsearch-graal
  • cd micronaut-elasticsearch-graal
  • git checkout 2.1.x
  • Use GraalVM 20.3.0 release for Java 8
  • ./build-native-image.sh
  • The build fails. See the error below.

Now Instead of using GraalVM 20.3.0 release, compile GraalVM from source code using release/graal-vm/20.3 branch and this java version.

  • The build works and the native-image is created.

Describe GraalVM and your environment:

  • GraalVM version: 20.3.0 release
  • JDK major version: 8 and 11
  • OS: Linux
  • Architecture: AMD64

More details

Error using 20.3.0 Release.

[elasticsearch:54453]    classlist:  16,058.37 ms,  1.83 GB
[elasticsearch:54453]        (cap):     977.72 ms,  1.83 GB
[elasticsearch:54453]        setup:   3,389.09 ms,  1.83 GB
[elasticsearch:54453]     analysis:  83,635.69 ms,  4.26 GB
Fatal error:com.oracle.graal.pointsto.util.AnalysisError$ParsingError: Error encountered while parsing org.graalvm.home.HomeFinder.getInstance() 
Parsing context:
	parsing org.graalvm.polyglot.Engine.getVersion(Engine.java:203)
	parsing com.oracle.truffle.js.scriptengine.GraalJSEngineFactory.getEngineVersion(GraalJSEngineFactory.java:132)
	parsing com.oracle.truffle.js.scriptengine.GraalJSEngineFactory.getParameter(GraalJSEngineFactory.java:168)
	parsing org.apache.logging.log4j.core.script.ScriptManager.<init>(ScriptManager.java:84)
	parsing org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:219)
	parsing org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
	parsing org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:618)
	parsing org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:691)
	parsing org.apache.logging.log4j.core.LoggerContext.setConfigLocation(LoggerContext.java:676)
	parsing org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.locateContext(ClassLoaderContextSelector.java:219)
	parsing org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.getContext(ClassLoaderContextSelector.java:131)
	parsing org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:228)
	parsing org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
	parsing org.apache.logging.log4j.LogManager.getContext(LogManager.java:174)
	parsing org.apache.logging.log4j.LogManager.getLogger(LogManager.java:669)
	parsing org.elasticsearch.rest.BytesRestResponse.<clinit>(BytesRestResponse.java:120)

	at com.oracle.graal.pointsto.util.AnalysisError.parsingError(AnalysisError.java:138)
	at com.oracle.graal.pointsto.flow.MethodTypeFlow.doParse(MethodTypeFlow.java:331)
	at com.oracle.graal.pointsto.flow.MethodTypeFlow.ensureParsed(MethodTypeFlow.java:302)
	at com.oracle.graal.pointsto.flow.MethodTypeFlow.addContext(MethodTypeFlow.java:103)
	at com.oracle.graal.pointsto.flow.StaticInvokeTypeFlow.update(InvokeTypeFlow.java:434)
	at com.oracle.graal.pointsto.BigBang$2.run(BigBang.java:547)
	at com.oracle.graal.pointsto.util.CompletionExecutor.lambda$execute$0(CompletionExecutor.java:173)
	at java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1402)
	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:175)
Caused by: com.oracle.svm.core.util.UserError$UserException: ImageSingletons do not contain key org.graalvm.home.HomeFinder
	at com.oracle.svm.core.util.UserError.abort(UserError.java:68)
	at com.oracle.svm.hosted.ImageSingletonsSupportImpl$HostedManagement.doLookup(ImageSingletonsSupportImpl.java:119)
	at com.oracle.svm.hosted.ImageSingletonsSupportImpl.lookup(ImageSingletonsSupportImpl.java:44)
	at org.graalvm.nativeimage.ImageSingletons.lookup(ImageSingletons.java:86)
	at com.oracle.svm.hosted.snippets.SubstrateGraphBuilderPlugins$43.apply(SubstrateGraphBuilderPlugins.java:1011)
	at org.graalvm.compiler.nodes.graphbuilderconf.InvocationPlugin.execute(InvocationPlugin.java:189)
	at org.graalvm.compiler.java.BytecodeParser.applyInvocationPlugin(BytecodeParser.java:2185)
	at org.graalvm.compiler.java.BytecodeParser.tryInvocationPlugin(BytecodeParser.java:2171)
	at com.oracle.svm.hosted.phases.AnalysisGraphBuilderPhase$AnalysisBytecodeParser.tryInvocationPlugin(AnalysisGraphBuilderPhase.java:67)
	at org.graalvm.compiler.java.BytecodeParser.appendInvoke(BytecodeParser.java:1876)
	at org.graalvm.compiler.java.BytecodeParser.genInvokeStatic(BytecodeParser.java:1637)
	at org.graalvm.compiler.java.BytecodeParser.genInvokeStatic(BytecodeParser.java:1617)
	at org.graalvm.compiler.java.BytecodeParser.processBytecode(BytecodeParser.java:5360)
	at org.graalvm.compiler.java.BytecodeParser.iterateBytecodesForBlock(BytecodeParser.java:3399)
	at org.graalvm.compiler.java.BytecodeParser.processBlock(BytecodeParser.java:3206)
	at org.graalvm.compiler.java.BytecodeParser.build(BytecodeParser.java:1092)
	at org.graalvm.compiler.java.BytecodeParser.buildRootMethod(BytecodeParser.java:986)
	at org.graalvm.compiler.java.GraphBuilderPhase$Instance.run(GraphBuilderPhase.java:84)
	at com.oracle.svm.hosted.phases.SharedGraphBuilderPhase.run(SharedGraphBuilderPhase.java:70)
	at org.graalvm.compiler.phases.Phase.run(Phase.java:49)
	at org.graalvm.compiler.phases.BasePhase.apply(BasePhase.java:212)
	at org.graalvm.compiler.phases.Phase.apply(Phase.java:42)
	at org.graalvm.compiler.phases.Phase.apply(Phase.java:38)
	at com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder.parse(MethodTypeFlowBuilder.java:223)
	at com.oracle.graal.pointsto.flow.MethodTypeFlowBuilder.apply(MethodTypeFlowBuilder.java:357)
	at com.oracle.graal.pointsto.flow.MethodTypeFlow.doParse(MethodTypeFlow.java:313)
	... 10 more
Error: Image build request failed with exit status 1

@eregon
Copy link
Member

eregon commented Nov 18, 2020

Regarding building GraalVM:

You can use mx fetch-jdk to automatically get the correct JVMCI JDK to build GraalVM.

@eregon
Copy link
Member

eregon commented Nov 18, 2020

From the stacktrace:

Fatal error:com.oracle.graal.pointsto.util.AnalysisError$ParsingError: Error encountered while parsing org.graalvm.home.HomeFinder.getInstance() 
Parsing context:
	parsing org.graalvm.polyglot.Engine.getVersion(Engine.java:203)
	parsing com.oracle.truffle.js.scriptengine.GraalJSEngineFactory.getEngineVersion(GraalJSEngineFactory.java:132)
	parsing com.oracle.truffle.js.scriptengine.GraalJSEngineFactory.getParameter(GraalJSEngineFactory.java:168)
	parsing org.apache.logging.log4j.core.script.ScriptManager.<init>(ScriptManager.java:84)
	parsing org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:219)
	parsing org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
	parsing org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:618)
	parsing org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:691)

So that ends up initializing Graal.js through the org.apache.logging.log4j.core.script.ScriptManager here. That's probably unexpected that the native image generation process would end up loading JavaScript that way.

@graemerocher
Copy link
Member

@ilopmar why does this app have log4j on the classpath and not logback?

@ilopmar
Copy link
Author

ilopmar commented Nov 18, 2020

@eregon Thanks for the information regarding to build GraalVM. I'll take a closer look at do some tests.

Can you please explain why the output of the build is different?

@graemerocher I added this to make Elasticsearch logging work on the JVM and this to make it work as native-image.

@graemerocher
Copy link
Member

@ilopmar but the question is why? Why not use logback?

@ilopmar
Copy link
Author

ilopmar commented Nov 18, 2020

@graemerocher Because it didn't work when I created the test app sometime ago. Maybe I can try this approach I did for Liquibase https://micronaut-projects.github.io/micronaut-liquibase/latest/guide/index.html#_logging

In any case, none of this explains why the Graal.js is triggered and why the builds are not the same, which I think is the really important part because I would like to create the builds as close as possible as the GraalVM team does.

@ilopmar
Copy link
Author

ilopmar commented Nov 18, 2020

@eregon I think the issue migth be because I'm not building graal-js locally so maybe that javascript thing is not triggered when using my build. I've tried the following to build it locally (according to the docs you linked) but it fails:

mx --dynamicimports /graal-js build
Traceback (most recent call last):
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 17180, in <module>
    main()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 17065, in main
    primary = _discover_suites(primarySuiteMxDir, load=should_load_suites)
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3506, in _discover_suites
    _register_visit(primary)
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3502, in _register_visit
    _register_visit(discovered[_suite_import.name])
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3504, in _register_visit
    s._load()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 1604, in _load
    self._load_extensions()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 2026, in _load_extensions
    mod = __import__(extensionsName)
  File "/home/ivan/workspaces/misc/graal/graaljs/graal-js/mx.graal-js/mx_graal_js.py", line 360, in <module>

Adding /graal-js with or without any other dynamic imports fails.

Regarding the rest of the options for building I think I'm already doing what I want with:

mx --disable-polyglot --disable-libpolyglot --dynamicimports /substratevm

or

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

for building the extra agents.

To be honest there is a lot of libs, modules and names and I'm a little bit lost with this. I'd appreaciate any help on this to confirm that those build commands are the right ones.

NATIVE_IMAGES/FORCE_BASH_LAUNCHERS can be used to control what gets built as native images or Bash launchers, but most likely in your case you want native images always, except maybe for native-image itself.

What do you mean with this? Why I don't want a native image for native-image?

Can you please also explain what are "bash launchers"?

@ilopmar
Copy link
Author

ilopmar commented Nov 18, 2020

@graemerocher I've tried adding implementation("org.slf4j:log4j-over-slf4j:1.7.30") but unless I add log4j in implementation scope, the native image fails at runtime when sending a request with:

Caused by: org.apache.commons.logging.LogConfigurationException: No suitable Log implementation
	at org.apache.commons.logging.impl.LogFactoryImpl.discoverLogImplementation(LogFactoryImpl.java:848)
	at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:541)
	at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:292)
	at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:269)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:657)
	at org.elasticsearch.client.RestClient.<clinit>(RestClient.java:99)
	at com.oracle.svm.core.classinitialization.ClassInitializationInfo.invokeClassInitializer(ClassInitializationInfo.java:351)
	at com.oracle.svm.core.classinitialization.ClassInitializationInfo.initialize(ClassInitializationInfo.java:271)
	... 101 common frames omitted

@gilles-duboscq
Copy link
Member

Can you please confirm that the 20.3.0 release was created from this commit c5ff5a5.

Yes

Can you please share which options do you use to compile the release?

The build job is actually this one:

${vm_java_8} ${full_vm_build_linux} ${linux-deploy} ${deploy_vm_linux} {
run: [
${mx_vm_installables} [--dynamicimports, ${vm_extra_suites}, "--exclude-components="${non-product-vm-components}, build]
${mx_vm_installables} [--dynamicimports, ${vm_extra_suites}, "--exclude-components="${non-product-vm-components}] ${maven_deploy_sdk_components}
] ${collect_profiles} [
${mx_vm_common} ${vm_profiles} [build]
${mx_vm_common} ${vm_profiles} ${maven_deploy_sdk_base}
${notify-nexus-deploy}
[set-export, GRAALVM_HOME, ${mx_vm_common} [--no-warning, graalvm-home]]
]
logs: ${common_vm.logs}
timelimit: "1:30:00"
name: deploy-vm-java8-linux-amd64
}

After all the hocon expansion this is the result: https://gist.github.com/gilles-duboscq/7828de2147bc3e9a436b08980ea700b0
I think mostly it's:

mx --strip-jars --sources=sdk:GRAAL_SDK,truffle:TRUFFLE_API,compiler:GRAAL,substratevm:SVM --with-debuginfo --env ce  --force-bash-launchers=env.FORCE_BASH_LAUNCHERS,RMain build

One final thing. I'm downloading the java releases to build GraalVM from https://github.com/graalvm/graal-jvmci-8/releases/ for Java 8 and https://github.com/graalvm/labs-openjdk-11/releases/ for Java 11. Are those the right versions I need to download?

Yes, you can use the command mentioned by Benoit to automatically download the right one. common.json at the root of the repo have the reference to the exact versions used for building.

Regarding your issue with mx --dynamicimports /graal-js build, the stack trace you cited seems to be truncated, it's missing the actual error (python stack traces are printed in the opposite direction to the way it's done for Java).

"bash launchers" are the launcher script that get generated instead of a native-image if you prevent some launchers from being built as native-images using NATIVE_IMAGES or FORCE_BASH_LAUNCHERS.

@eregon
Copy link
Member

eregon commented Nov 19, 2020

My guess is org.apache.logging.log4j.core.script.ScriptManager iterates all ScriptEngine's. Since GraalVM releases always include Graal.js, this happens, but the commands above do not include Graal.js so it does not.

Now Engine.getVersion() should probably work there (it needs the HomeFinderFeature, but that should automatically be picked up if graal-sdk.jar is on the classpath, maybe an issue given that's on the bootclasspath?). OTOH, if any of that code is reachable at runtime it wouldn't work because the JavaScript language is not included in the native image (would need --language:js but seems unlikely to be what you want here).

It seems a bit surprising that log4j reaches into ScriptEngine's like this, maybe there is some configuration to disable that behavior?

@ilopmar
Copy link
Author

ilopmar commented Nov 19, 2020

Thank you @gilles-duboscq @eregon and @loicottet for the detailed explanations. I really appreciate it!

I think I'm missing some config or environment variable defined because the instructions you have provided don't work for me:

export PATH=/home/ivan/workspaces/misc/graal/mx:$PATH
export JAVA_HOME=/home/ivan/workspaces/misc/graal/openjdk1.8.0_272-jvmci-20.3-b06

ivan@nobita:~/workspaces/misc/graal/graal/vm$ mx --strip-jars --sources=sdk:GRAAL_SDK,truffle:TRUFFLE_API,compiler:GRAAL,substratevm:SVM --with-debuginfo --env ce  --force-bash-launchers=env.FORCE_BASH_LAUNCHERS,RMain build
Traceback (most recent call last):
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 17180, in <module>
    main()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 17065, in main
    primary = _discover_suites(primarySuiteMxDir, load=should_load_suites)
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3506, in _discover_suites
    _register_visit(primary)
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3502, in _register_visit
    _register_visit(discovered[_suite_import.name])
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3502, in _register_visit
    _register_visit(discovered[_suite_import.name])
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3504, in _register_visit
    s._load()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 1604, in _load
    self._load_extensions()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 2026, in _load_extensions
    mod = __import__(extensionsName)
  File "/home/ivan/workspaces/misc/graal/graaljs/graal-js/mx.graal-js/mx_graal_js.py", line 360, in <module>
    build_args=['--language:js']
TypeError: __init__() takes at least 6 arguments (5 given)

Then I've realized that maybe it's because of python, so I've defined this:

export DEFAULT_VM=server
export MX_PYTHON=python3

But now it fails with other error message:

ivan@nobita:~/workspaces/misc/graal/graal/vm$ mx --strip-jars --sources=sdk:GRAAL_SDK,truffle:TRUFFLE_API,compiler:GRAAL,substratevm:SVM --with-debuginfo --env ce  --force-bash-launchers=env.FORCE_BASH_LAUNCHERS,RMain build
Traceback (most recent call last):
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 17180, in <module>
    main()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 17065, in main
    primary = _discover_suites(primarySuiteMxDir, load=should_load_suites)
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3506, in _discover_suites
    _register_visit(primary)
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3502, in _register_visit
    _register_visit(discovered[_suite_import.name])
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3502, in _register_visit
    _register_visit(discovered[_suite_import.name])
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 3504, in _register_visit
    s._load()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 1604, in _load
    self._load_extensions()
  File "/home/ivan/workspaces/misc/graal/mx/mx.py", line 2026, in _load_extensions
    mod = __import__(extensionsName)
  File "/home/ivan/workspaces/misc/graal/graaljs/graal-js/mx.graal-js/mx_graal_js.py", line 356, in <module>
    mx_sdk.LanguageLauncherConfig(
TypeError: __init__() missing 1 required positional argument: 'language'

Any hints on how to fix this?

@loicottet the workaround of adding HomeFinderFeature works perfect, thanks!

@ilopmar
Copy link
Author

ilopmar commented Nov 19, 2020

I'm sorry, I've realized that graal-js is in another repository. I've cloned that repo, followed the instructions, and I was able to build Graalvm locally with graal-js and reproduce the error.

Again, thank you very much!

@gilles-duboscq
Copy link
Member

Given

  File "/home/ivan/workspaces/misc/graal/graaljs/graal-js/mx.graal-js/mx_graal_js.py", line 360, in <module>
    build_args=['--language:js']
TypeError: __init__() takes at least 6 arguments (5 given)

It looks like you already had JS cloned at /home/ivan/workspaces/misc/graal/graaljs but in a version that was incompatible.
Maybe check your /home/ivan/workspaces/misc/graal directory to check that you have only one copy of the JS repo in there.

@ilopmar
Copy link
Author

ilopmar commented Nov 19, 2020

Yeah, I already fixed it. It looks like I had a really old clone of graaljs. I deleted it and cloned again and everything worked!

ilopmar added a commit to micronaut-graal-tests/micronaut-elasticsearch-graal that referenced this issue Nov 19, 2020
ilopmar added a commit to micronaut-graal-tests/micronaut-elasticsearch-graal that referenced this issue Nov 19, 2020
@ilopmar
Copy link
Author

ilopmar commented Nov 20, 2020

I've found another issue. With the workaround provided I can build the native image, but then some javascript code is still there when running the app.

 in 20ms. Server Running: http://localhost:8080
Failed to clear engine names [Oracle Nashorn]
java.lang.NoSuchFieldException: names
	at java.lang.Class.getDeclaredField(DynamicHub.java:2070)
	at com.oracle.truffle.js.scriptengine.GraalJSEngineFactory.clearEngineFactory(GraalJSEngineFactory.java:235)
	at com.oracle.truffle.js.scriptengine.GraalJSEngineFactory.<clinit>(GraalJSEngineFactory.java:85)
	at com.oracle.svm.core.classinitialization.ClassInitializationInfo.invokeClassInitializer(ClassInitializationInfo.java:351)
	at com.oracle.svm.core.classinitialization.ClassInitializationInfo.initialize(ClassInitializationInfo.java:271)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(DynamicHub.java:920)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)
	at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
	at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
	at javax.script.ScriptEngineManager.initEngines(ScriptEngineManager.java:122)
	at javax.script.ScriptEngineManager.init(ScriptEngineManager.java:84)
	at javax.script.ScriptEngineManager.<init>(ScriptEngineManager.java:61)
	at org.apache.logging.log4j.core.script.ScriptManager.<init>(ScriptManager.java:70)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:219)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:618)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:691)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:708)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:263)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:153)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:194)
	at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:602)
	at org.elasticsearch.search.builder.SearchSourceBuilder.<clinit>(SearchSourceBuilder.java:84)
	at com.oracle.svm.core.classinitialization.ClassInitializationInfo.invokeClassInitializer(ClassInitializationInfo.java:351)
	at com.oracle.svm.core.classinitialization.ClassInitializationInfo.initialize(ClassInitializationInfo.java:271)
	at org.elasticsearch.action.search.SearchRequest.<init>(SearchRequest.java:122)
	at micronaut.example.service.MovieServiceImpl.searchMovies(MovieServiceImpl.java:63)
	at micronaut.example.controller.MovieController.searchMovies(MovieController.java:42)
	at micronaut.example.controller.$MovieControllerDefinition$$exec2.invokeInternal(Unknown Source)
	at io.micronaut.context.AbstractExecutableMethod.invoke(AbstractExecutableMethod.java:146)
	at io.micronaut.context.DefaultBeanContext$4.invoke(DefaultBeanContext.java:474)
...

To reproduce this new problem:

  • git clone https://github.com/micronaut-graal-tests/micronaut-elasticsearch-graal
  • cd micronaut-elasticsearch-graal
  • git checkout 2.2.x
  • Use GraalVM 20.3.0 release for Java 8
  • ./build-native-image.sh
  • The native image is built because I've added the workaround.
  • Start elasticsearch using Docker (see README for more info): docker run -it --rm -p 9200:9200 -p 9300:9300 -e "discovery.type=single-node" docker.elastic.co/elasticsearch/elasticsearch:7.9.3
  • ./elasticsearch
  • curl "localhost:8080/api/movies?title=matrix"

@loicottet
Copy link
Member

The whole situation is caused by the fact that services declared by modules are automatically included in the reflection configuration since 20.3 (see 678354c). In particular, GraalJSEngineFactory is registered as a ScriptEngineFactory by org.graalvm.js.scriptengine, which is present in the base Graal distribution. This new problem makes me think that this service should not be registered in the first place when JS is not needed, I'll ask and confirm it.

@loicottet
Copy link
Member

-H:ServiceLoaderFeatureExcludeServiceProviders=com.oracle.truffle.js.scriptengine.GraalJSEngineFactory should be a sturdier workaround until we fix this.

@sdeleuze
Copy link
Collaborator

sdeleuze commented Dec 18, 2020

@loicottet -H:ServiceLoaderFeatureExcludeServiceProviders=com.oracle.truffle.js.scriptengine.GraalJSEngineFactory does not seems to fix the issue based on my use case (using Log4j2 in Spring Boot) and the workaround used on Micronaut example side (--features=org.graalvm.home.HomeFinderFeature) is not usable for us since it will disable other required parts. How could we move forward on fixing this?

@loicottet
Copy link
Member

@d-kozak can you help with this? This looks like further service loader shenanigans.

@d-kozak
Copy link
Contributor

d-kozak commented Jan 13, 2021

Hello. I apologize for taking so long to reply.

@ilopmar ServiceLoaderFeatureExcludeServiceProviders is the recommended option for your use case now. I'm currently looking into how we could handle this internally. In the future, it might not be necessary, but for now please go with the flag.

@sdeleuze Could you please provide me with a reproducer so that I can debug why the option is not working for you?

@sdeleuze
Copy link
Collaborator

@d-kozak Sure, run ./build.sh in https://github.com/sdeleuze/spring-native/tree/log4j2/spring-native-samples/commandlinerunner. I have a GraalJSEngineFactory related error despite using -H:ServiceLoaderFeatureExcludeServiceProviders=com.oracle.truffle.js.scriptengine.GraalJSEngineFactory.

Error: Classes that should be initialized at run time got initialized during image building:
 com.oracle.truffle.js.scriptengine.GraalJSEngineFactory was unintentionally initialized at build time. org.springframework.boot.SpringBootFactories caused initialization of this class with the following trace: 
	at com.oracle.truffle.js.scriptengine.GraalJSEngineFactory.<clinit>(GraalJSEngineFactory.java:57)
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Unknown Source)
	at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:490)
	at java.util.ServiceLoader$ProviderImpl.newInstance(ServiceLoader.java:779)
	at java.util.ServiceLoader$ProviderImpl.get(ServiceLoader.java:721)
	at java.util.ServiceLoader$3.next(ServiceLoader.java:1394)
	at javax.script.ScriptEngineManager.initEngines(ScriptEngineManager.java:125)
	at javax.script.ScriptEngineManager.init(ScriptEngineManager.java:87)
	at javax.script.ScriptEngineManager.<init>(ScriptEngineManager.java:62)
	at org.apache.logging.log4j.core.script.ScriptManager.<init>(ScriptManager.java:70)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:219)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:288)
	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:618)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:691)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:708)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:263)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:153)
	at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:45)
	at org.apache.logging.log4j.LogManager.getContext(LogManager.java:194)
	at org.apache.commons.logging.LogAdapter$Log4jLog.<clinit>(LogAdapter.java:155)
	at org.apache.commons.logging.LogAdapter$Log4jAdapter.createLog(LogAdapter.java:122)
	at org.apache.commons.logging.LogAdapter.createLog(LogAdapter.java:89)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:67)
	at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:59)
	at org.springframework.boot.context.ConfigurationWarningsApplicationContextInitializer.<clinit>(ConfigurationWarningsApplicationContextInitializer.java:55)
	at org.springframework.boot.SpringBootFactories.<clinit>(SpringBootFactories.java:115)

@d-kozak
Copy link
Contributor

d-kozak commented Jan 19, 2021

@sdeleuze I've experimented with this issue and noticed that this error is not related to the ServiceLoaderFeature, that's why the flag is not working. As described in the discussions above, the problem here stems from the fact that log4j in its ScriptManager instantiates all ScriptEngineFactories via javax.script.ScriptEngineManager. GraalJSEngineFactory is one of those, which causes that class to be initialized at build time unintentionally. I'm currently trying to see whether we could prevent the engine from being accessible unless graaljs is configured or at least initialize it at build time intentionally ourselves. The error in HomeFinder could probably be fixed quite easily - There is an 'if in native image' check, which causes the problem, but actually does not seem necessary and when removed, initialization succeeded. Of course, more testing will have to be necessary to ensure that it is not there for another reason.

Regarding how to fix it from the client-side, at least temporarily:
One way to fix it would be not to use logging in classes that should be initialized at build time. But this is of course way too restrictive. Another way would be to use a different logging library, but that's probably again too restrictive. As was already described above, it would be great if the log4j could be configured not to instantiate these script factories. If the option is not there, a substitution could be made to switch this off. But of course, library-level substitutions come with maintenance overhead, so it's not ideal either. Best would be to configure the library accordingly if possible.

Useful links:
org.apache.logging.log4j.core.script.ScriptManager
javax.script.ScriptEngineManager
org.graalvm.home.HomeFinder

@sdeleuze
Copy link
Collaborator

Ok thanks for your feedback I will see what we could do for the short term option.

@AndersClausen
Copy link

Hi @d-kozak
Any idea when you think you'll have a fix to the problem?
Many thanks for your hard work.

@d-kozak
Copy link
Contributor

d-kozak commented Feb 6, 2021

An update of HomeFinder is about to be merged, which seems to work as a 'fix' both for the Micronaut and Spring issue. I'll let you know once it is merged, so you can give it a try yourself. However, it is not a proper solution in the sense that it only erases a symptom instead of fixing the core issue, which is essentially a combination of three things:

  1. Instantiating script engine factories including graaljs in log4j's ScriptManager.
  2. GraalJSEngineFactory is reachable even without --language:js option.
  3. We don't have proper means to control ServiceLoaders at image build time.

For 1) - This is a third-party library issue, which is unfortunately outside of the scope of the Native Image team to fix.
For 2) - Graaljs is included with the GraalVM distribution automatically. However, the fact that the GraalJSEngineFactory is accessible even though the rest of the graaljs infrastructure is not is a bug that will have to be fixed, which is a work in progress.
For 3) - We keep having various ServiceLoader issues, whose impact ranges from image size problems all the way to build failures, but unfortunately, there is not a clean way to fully control the ServiceLoader lookup as far as I am aware of.

To sum it up, a quickfix will be merged soon. It should allow the GraalJSEngineFactory to be safely initialized at build time, which should consequently allow the log4j to be initialized assuming it will not actually use graaljs to evaluate some javascript code. Full exclusion of that library from native image build unless given flag is set is a work in progress.

@loicottet loicottet assigned d-kozak and unassigned loicottet Feb 8, 2021
@AndersClausen
Copy link

Hi @d-kozak - did the quickfix get merged and if so, in what version? Thank you

@d-kozak
Copy link
Contributor

d-kozak commented Mar 1, 2021

Hello @AndersClausen,

The quickfix was merged last week - 1b92af4 so it should be available in 21.1 and I also made a backport request for the next 20.3 release.

I've also been looking into whether GraalJSEngineFactory can be excluded if --language:js is not set and unfortunately, there does not seem to be a clean way to do it. It is bundled tightly within the GraalVM, which makes it hard to conditionally exclude it. However, there is an effort to make service loading more controllable in general, so if there is an advance in that area, this issue might be revisited and solved in a better way afterwards.

@sdeleuze
Copy link
Collaborator

@d-kozak Any chance that GraalJSEngineFactory could be excluded if --language:js is not set in GraalVM 21.2.0?

@d-kozak
Copy link
Contributor

d-kozak commented Dec 6, 2023

By now, with Truffle Unchained, I believe this issue should no longer occur. If you still have issues, please reopen with a reproducer.

@d-kozak d-kozak closed this as completed Dec 6, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants