You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@karaf.apache.org by "Christian Brüssow (Jira)" <ji...@apache.org> on 2020/06/25 12:11:00 UTC
[jira] [Commented] (KARAF-6439) Service fails to start under AIX
with OpenJDK J9 Java 11: --patch-module error
[ https://issues.apache.org/jira/browse/KARAF-6439?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17144877#comment-17144877 ]
Christian Brüssow commented on KARAF-6439:
------------------------------------------
I have an update for Karaf 4.2.6 and Java 11 (J9 variant) on AIX 7.2:
When commenting out the line "set.JDK_JAVA_OPTIONS=..." in the service's wrapper configuration file, the service starts, but the application is not stable. The idea to disable this line came into my mind, when looking into the wrapper log, which contains the following entry when failing to start the service:
{noformat}
STATUS | wrapper | 2020/06/25 08:25:41 | --> Wrapper Started as Daemon
STATUS | wrapper | 2020/06/25 08:25:41 | Launching a JVM...
INFO | jvm 1 | 2020/06/25 08:25:41 | NOTE: Picked up JDK_JAVA_OPTIONS: --add-reads=java.xml=java.logging --add-exports=java.base/org.apache.karaf.specs.locator=java.xml,ALL-UNNAMED --patch-mod
ule java.base=lib/endorsed/org.apache.karaf.specs.locator-4.2.6.jar --patch-module java.xml=lib/endorsed/org.apache.karaf.specs.java.xml-4.2.6.jar --add-opens java.base/java.security=ALL-UNNAMED --
add-opens java.base/java.net=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.naming/javax.naming.spi=ALL-UNNAMED --add-opens jav
a.rmi/sun.rmi.transport.tcp=ALL-UNNAMED --add-exports=java.base/sun.net.www.protocol.http=ALL-UNNAMED --add-exports=java.base/sun.net.www.protocol.https=ALL-UNNAMED --add-exports=java.base/sun.net.
www.protocol.jar=ALL-UNNAMED --add-exports=jdk.xml.dom/org.w3c.dom.html=ALL-UNNAMED --add-exports=jdk.naming.rmi/com.sun.jndi.url.rmi=ALL-UNNAMED
INFO | jvm 1 | 2020/06/25 08:25:41 | NOTE: Picked up JDK_JAVA_OPTIONS: --add-reads=java.xml=java.logging --add-exports=java.base/org.apache.karaf.specs.locator=java.xml,ALL-UNNAMED --patch-mod
ule java.base=lib/endorsed/org.apache.karaf.specs.locator-4.2.6.jar --patch-module java.xml=lib/endorsed/org.apache.karaf.specs.java.xml-4.2.6.jar --add-opens java.base/java.security=ALL-UNNAMED --
add-opens java.base/java.net=ALL-UNNAMED --add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.util=ALL-UNNAMED --add-opens java.naming/javax.naming.spi=ALL-UNNAMED --add-opens jav
a.rmi/sun.rmi.transport.tcp=ALL-UNNAMED --add-exports=java.base/sun.net.www.protocol.http=ALL-UNNAMED --add-exports=java.base/sun.net.www.protocol.https=ALL-UNNAMED --add-exports=java.base/sun.net.
www.protocol.jar=ALL-UNNAMED --add-exports=jdk.xml.dom/org.w3c.dom.html=ALL-UNNAMED --add-exports=jdk.naming.rmi/com.sun.jndi.url.rmi=ALL-UNNAMED
ERROR | wrapper | 2020/06/25 08:25:42 | JVM exited while loading the application.
INFO | jvm 1 | 2020/06/25 08:25:42 | Exception in thread "main" java/lang/ExceptionInInitializerError
INFO | jvm 1 | 2020/06/25 08:25:42 | at java/lang/J9VMInternals.ensureError (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at java/lang/J9VMInternals.recordInitializationFailure (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at java/lang/ClassLoader.initializeClassLoaders (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at java/lang/Thread.initialize (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at java/lang/Thread.<init> (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | java/lang/RuntimeException: java.base specified more than once to --patch-module
INFO | jvm 1 | 2020/06/25 08:25:42 | at jdk/internal/module/ModuleBootstrap.fail (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at jdk/internal/module/ModuleBootstrap.decode (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at jdk/internal/module/ModuleBootstrap.initModulePatcher (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at jdk/internal/module/ModuleBootstrap.<clinit> (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at java/lang/ClassLoader.initializeClassLoaders (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at java/lang/Thread.initialize (java.base@9/Unknown Source:4294967295)
INFO | jvm 1 | 2020/06/25 08:25:42 | at java/lang/Thread.<init> (java.base@9/Unknown Source:4294967295){noformat}
The entry "*NOTE: Picked up JDK_JAVA_OPTIONS: ..." comes twice on AIX*, but only once on Linux (Intel x64). For AIX and Linux the wrapper configuration was created the same. The file also lokks the same for both here. The JDK_JAVA_OPTIONS is only set once in the configuration.
The environment also does not contain any JDK_JAVA_OPTIONS settings, have double checked this. No other file in karaf/bin and karaf/etc than the wrapper configuration contains a line with JDK_JAVA_OPTIONS in it.
Commenting the setting in the wrapper configuration, the wrapper log looks like this:
{noformat}
STATUS | wrapper | 2020/06/25 12:41:49 | Launching a JVM...
INFO | jvm 1 | 2020/06/25 12:41:51 | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
INFO | jvm 1 | 2020/06/25 12:41:51 | Copyright 1999-2006 Tanuki Software, Inc. All Rights Reserved.
INFO | jvm 1 | 2020/06/25 12:41:51 |
INFO | jvm 1 | 2020/06/25 12:42:08 | WARNING: An illegal reflective access operation has occurred
INFO | jvm 1 | 2020/06/25 12:42:08 | WARNING: Illegal reflective access by org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender (file:/data/agent/karaf/system/org/apache/felix/org.apache.felix.framework/5.6.12/org.apache.felix.framework-5.6.12.jar) to method java.net.URLClassLoader.addURL(java.net.URL)
INFO | jvm 1 | 2020/06/25 12:42:08 | WARNING: Please consider reporting this to the maintainers of org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender
INFO | jvm 1 | 2020/06/25 12:42:08 | WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
INFO | jvm 1 | 2020/06/25 12:42:08 | WARNING: All illegal access operations will be denied in a future release{noformat}
From the commandline used to start the application one can see, the parameters set in JDK_JAVA_OPTIONS are missing - as expected. It looks like the wrapper then starts the JVM similar to the start-script.
{noformat}
root 18546960 20251024 10 12:41:49 - 1:15 /data/testapp/agent_testappAgt/karaf/../jre/bin/java -Dkaraf.instances=/data/testapp/agent_testappAgt/karaf/instances -Dkaraf.home=/data/testapp/agent_testappAgt/karaf -Dkaraf.base=/data/testapp/agent_testappAgt/karaf -Dkaraf.data=/data/testapp/agent_testappAgt/karaf/data -Dkaraf.etc=/data/testapp/agent_testappAgt/karaf/etc -Dkaraf.log=/data/testapp/agent_testappAgt/karaf/data/log -Dkaraf.restart.jvm.supported=true -Djava.io.tmpdir=/data/testapp/agent_testappAgt/karaf/data/tmp -Djava.util.logging.config.file=/data/testapp/agent_testappAgt/karaf/etc/java.util.logging.properties -Dcom.sun.management.jmxremote -Dkaraf.startLocalConsole=false -Dkaraf.startRemoteShell=true -Xmx512m -Djava.library.path=/data/testapp/agent_testappAgt/karaf/lib/wrapper/ -classpath /data/testapp/agent_testappAgt/karaf/lib/boot/org.apache.karaf.diagnostic.boot-4.2.6.jar:/data/testapp/agent_testappAgt/karaf/lib/boot/org.apache.karaf.jaas.boot-4.2.6.jar:/data/testapp/agent_testappAgt/karaf/lib/boot/org.apache.karaf.main-4.2.6.jar:/data/testapp/agent_testappAgt/karaf/lib/boot/org.apache.karaf.specs.activator-4.2.6.jar:/data/testapp/agent_testappAgt/karaf/lib/boot/org.osgi.core-6.0.0.jar:/data/testapp/agent_testappAgt/karaf/lib/jdk9plus/istack-commons-runtime-3.0.8.jar:/data/testapp/agent_testappAgt/karaf/lib/jdk9plus/jakarta.xml.bind-api-2.3.2.jar:/data/testapp/agent_testappAgt/karaf/lib/jdk9plus/javax.activation-1.2.0.jar:/data/testapp/agent_testappAgt/karaf/lib/jdk9plus/javax.annotation-api-1.3.jar:/data/testapp/agent_testappAgt/karaf/lib/jdk9plus/jaxb-runtime-2.3.2.jar:/data/testapp/agent_testappAgt/karaf/lib/jdk9plus/txw2-2.3.2.jar:/data/testapp/agent_testappAgt/karaf/lib/wrapper/karaf-wrapper-main.jar:/data/testapp/agent_testappAgt/karaf/lib/wrapper/karaf-wrapper.jar -Dwrapper.key=YNKB3ZdhoS40QxGR -Dwrapper.port=32000 -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999 -Dwrapper.pid=20251024 -Dwrapper.version=3.2.3 -Dwrapper.native_library=wrapper -Dwrapper.service=TRUE -Dwrapper.cpu.timeout=10 -Dwrapper.jvmid=1 org.apache.karaf.wrapper.internal.service.Main
root 20251024 1 0 12:41:48 - 0:00 /data/testapp/agent_testappAgt/karaf/bin/testapp_testappAgt-wrapper /data/testapp/agent_testappAgt/karaf/etc/testapp_testappAgt-wrapper.conf wrapper.syslog.ident=testapp_testappAgt wrapper.pidfile=/data/testapp/agent_testappAgt/karaf/testapp_testappAgt.wrapper.pid wrapper.daemonize=TRUE{noformat}
And Linux, with the JDK_JAVA_OPTIONS set in the wrapper configuration file:
{noformat}
root 1228 1 0 10:32 ? 00:00:07 /opt/testapp/Agent/karaf/bin/testapp_Server-Agent-wrapper /opt/testapp/Agent/karaf/etc/testapp_Server-Agent-wrapper.conf wrapper.syslog.ident=testapp_Server-Agent wrapper.pidfile=/opt/testapp/Agent/karaf/testapp_Server-Agent.wrapper.pid wrapper.daemonize=TRUE wrapper.lockfile=/var/lock/subsys/testapp_Server-Agent
root 1246 1228 2 10:32 ? 00:04:23 /opt/testapp/Agent/karaf/../jre/bin/java -Dkaraf.instances=/opt/testapp/Agent/karaf/instances -Dkaraf.home=/opt/testapp/Agent/karaf -Dkaraf.base=/opt/testapp/Agent/karaf -Dkaraf.data=/opt/testapp/Agent/karaf/data -Dkaraf.etc=/opt/testapp/Agent/karaf/etc -Dkaraf.log=/opt/testapp/Agent/karaf/data/log -Dkaraf.restart.jvm.supported=true -Djava.io.tmpdir=/opt/testapp/Agent/karaf/data/tmp -Djava.util.logging.config.file=/opt/testapp/Agent/karaf/etc/java.util.logging.properties -Dcom.sun.management.jmxremote -Dkaraf.startLocalConsole=false -Dkaraf.startRemoteShell=true -Xmx512m -Djava.library.path=/opt/testapp/Agent/karaf/lib/wrapper/ -classpath /opt/testapp/Agent/karaf/lib/boot/org.apache.karaf.diagnostic.boot-4.2.6.jar:/opt/testapp/Agent/karaf/lib/boot/org.osgi.core-6.0.0.jar:/opt/testapp/Agent/karaf/lib/boot/org.apache.karaf.jaas.boot-4.2.6.jar:/opt/testapp/Agent/karaf/lib/boot/org.apache.karaf.specs.activator-4.2.6.jar:/opt/testapp/Agent/karaf/lib/boot/org.apache.karaf.main-4.2.6.jar:/opt/testapp/Agent/karaf/lib/jdk9plus/istack-commons-runtime-3.0.8.jar:/opt/testapp/Agent/karaf/lib/jdk9plus/javax.annotation-api-1.3.jar:/opt/testapp/Agent/karaf/lib/jdk9plus/jaxb-runtime-2.3.2.jar:/opt/testapp/Agent/karaf/lib/jdk9plus/javax.activation-1.2.0.jar:/opt/testapp/Agent/karaf/lib/jdk9plus/jakarta.xml.bind-api-2.3.2.jar:/opt/testapp/Agent/karaf/lib/jdk9plus/txw2-2.3.2.jar:/opt/testapp/Agent/karaf/lib/wrapper/karaf-wrapper.jar:/opt/testapp/Agent/karaf/lib/wrapper/karaf-wrapper-main.jar -Dwrapper.key=AEt0nt4XEv0s7n1G -Dwrapper.port=32000 -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999 -Dwrapper.pid=1228 -Dwrapper.version=3.2.3 -Dwrapper.native_library=wrapper -Dwrapper.service=TRUE -Dwrapper.cpu.timeout=10 -Dwrapper.jvmid=1 org.apache.karaf.wrapper.internal.service.Main{noformat}
The result looks more or less identical for both.
So my workaround is to remove the JDK_JAVA_OPTIONS line from the wrapper configuration when on AIX with Java 11. Although I have no idea what is the reason the setting is found used twice in a row.
For completeness here the java -version output on both platforms:
AIX 7.2:
{noformat}
./java -version
openjdk version "11.0.2" 2019-01-15
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.2+9)
Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.12.1, JRE 11 AIX ppc64-64-Bit Compressed References 20190204_121 (JIT enabled, AOT enabled)
OpenJ9 - 90dd8cb
OMR - d2f4534
JCL - 289c70b based on jdk-11.0.2+9){noformat}
Linux:
{noformat}
./java -version
openjdk version "11.0.2" 2019-01-15
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.2+9)
Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.12.1, JRE 11 Linux amd64-64-Bit Compressed References 20190204_127 (JIT enabled, AOT enabled)
OpenJ9 - 90dd8cb40
OMR - d2f4534b
JCL - 289c70b6844 based on jdk-11.0.2+9){noformat}
> Service fails to start under AIX with OpenJDK J9 Java 11: --patch-module error
> ------------------------------------------------------------------------------
>
> Key: KARAF-6439
> URL: https://issues.apache.org/jira/browse/KARAF-6439
> Project: Karaf
> Issue Type: Bug
> Components: karaf
> Affects Versions: 4.2.3
> Environment: *OS:* IBM AIX 7.2
> *Java:* openjdk version "11.0.4" 2019-07-16
> OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.4+11)
> Eclipse OpenJ9 VM AdoptOpenJDK (build openj9-0.15.1, JRE 11 AIX ppc64-64-Bit Compressed References 20190717_292 (JIT enabled, AOT enabled)
> OpenJ9 - 0f66c64
> OMR - ec782f2
> JCL - fa49279 based on jdk-11.0.4+11)
> Reporter: Christian Brüssow
> Assignee: Freeman Yue Fang
> Priority: Major
> Attachments: NN_MyAgnet1-wrapper.conf, java-version.out, wrapper.log
>
>
> Under AIX 7.2 I have used the service wrapper. It creates the correct entry in /etc/inittab and also creates a wrapper.conf that looks fine (see attachement). Here the entry from the inittab:
> {quote}{{NN_MyAgent1:2:once:/data/MyService/karaf/bin/NN_MyAgent1-service start}}
> {quote}
> Starting karaf via the start-script from karaf/bin/ works as expected.
> But when starting karaf via the service wrapper, the start fails with the following error shown in the wrapper.log (loglevel DEBUG):
> {quote}{{DEBUG | wrapper | 2019/09/30 11:30:38 | Signal trapped. Details:DEBUG | wrapper | 2019/09/30 11:30:38 | Signal trapped. Details:DEBUG | wrapper | 2019/09/30 11:30:38 | signal number=20 (SIGCHLD), source="unknown"DEBUG | wrapper | 2019/09/30 11:30:38 | Received SIGCHLD, checking JVM process status.DEBUG | wrapper | 2019/09/30 11:30:38 | JVM process exited with a code of 1, setting the wrapper exit code to 1.ERROR | wrapper | 2019/09/30 11:30:38 | JVM exited while loading the application.INFO | jvm 1 | 2019/09/30 11:30:38 | Exception in thread "main" java/lang/ExceptionInInitializerErrorINFO | jvm 1 | 2019/09/30 11:30:38 | at java/lang/J9VMInternals.ensureError (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at java/lang/J9VMInternals.recordInitializationFailure (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at java/lang/ClassLoader.initializeClassLoaders (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at java/lang/Thread.initialize (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at java/lang/Thread.<init> (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | java/lang/RuntimeException: java.base specified more than once to --patch-moduleINFO | jvm 1 | 2019/09/30 11:30:38 | at jdk/internal/module/ModuleBootstrap.fail (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at jdk/internal/module/ModuleBootstrap.decode (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at jdk/internal/module/ModuleBootstrap.initModulePatcher (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at jdk/internal/module/ModuleBootstrap.<clinit> (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at java/lang/ClassLoader.initializeClassLoaders (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at java/lang/Thread.initialize (java.base@9/Unknown Source:4294967295)INFO | jvm 1 | 2019/09/30 11:30:38 | at java/lang/Thread.<init> (java.base@9/Unknown Source:4294967295)DEBUG | wrapper | 2019/09/30 11:30:38 | JVM was only running for 0 seconds leading to a failed restart count of 1.}}
> {quote}
> The entries in the wrapper.conf are looking ok for me, see attachement.
> The Java used is an OpenJDK OpenJ9 Java 11 from AdoptJDK.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)