[
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)
