LogManager classloading problem prevents Wildfly from running (Wildfly 10.1, IBM JDK8, yajsw)

[milspec]

Hi all,

[A caveat. I posted this on the 'wildfly-dev' mailing list (as well as a few other places). Someone suggested 'post here', i.e. people reading this forum have the knowledge to untangle this know ]

Problem

I've run into a classloading problem that prevents wildfly 10.1 from running with the following stack:

-Wildfly 10.1

-IBM JDK 8 (the latest, 8.0-3.12)

-YAJSW ("Yet Another Java Service Wrapper")

-Ubuntu 14.04 linux AMD 64

LogManager Classloader check fails with IBMJDK8 and YAJSW

This stack fails because wildfly/jboss thinks the logManager is not loaded properly.

Wildfly concludes as such because this check returns true:
     if (LogManager.getLogManager().getClass() == LogManager.class) {

To clarify:  with this tech stack, the system classloader loads both LogManager.getLogManager() and LogManager.class. Thus the two classes are identical, i.e. "=="

I'll call this stack:
Stack1) IBMJDK8 and Yajsw

Log Manager Classloader check succeeds with other stacks

The  'class==' check succeeds (returns false) in all other stacks I've tested with Wildfly 10.1

Stack2) IBMJDK8 from the command line (no yasw)
Stack3) Oracle JDK8 with yajsw
Stack4) Oracle JDK8 from the command line (no yajsw)

With stacks 2-4, the jboss-module-classloader loads "LogManager.getLogManager()", whereas the system classloader loads "LogManager.class"

I have no idea why the difference, i.e. why "ibmjdk8 and yajsw" uses "system classloader" to load LogManager.getLogManager and why the difference for the other stacks.

Note that between "Stack1" and "Stack2", I only changed "which java command". All other configurations are identical.

Code Details: Where this check occurs

I've searched the wildfly code and found this check in two places:
   jboss-modules: Main.java
   wildfly-core: LoggingExtension.java

I may have missed something. (I checked the versions in the shipped-with-wildfly-10.1 jar, cloned the various git repos and checked out the corresponding versions for jboss-modules and wildlfy-core)

Xref, Xpost
As this problem has several components, I've posted it in a few places: yajsw forums, ibm jdk forums etc.

Yeah, I know cross-posting is bad form. Mea culpa. But as user, I did not know (and still don't) if the problem lies in "yajsw code" or "wildfly/jboss code" or in the IBM JDK. This is "low-level stuff"

Other posts (same information):
https://www.ibm.com/developerworks/community/forums/html/topic?id=8e9e4ae2-53a7-42e8-8086-6208b80e2910&ps=25

https://sourceforge.net/p/yajsw/discussion/810311/thread/e730451b/?limit=25

Questions

-Any workarounds? (i've tried all sorts of tweaks, all dead end)

-Any idea why the difference, i.e. why would systemclassloader load "LogManager.getLogManager()" with "Stack1" vs "Stacks2-4"

thanks in advance!

[milspec]

An update on this. It looks like the issue is as follows:

• YAJSW Instantiates MemoryMXBean

   final MemoryMXBean memoryBean = **ManagementFactory.getMemoryMXBean();

• IBM's implementaiton of MemoryMXBean (or a class it refers to ) instantiates,via System classloader, a logging manager: either default implementation,  or the  class identified by -Djava.util.logging.manager. Oracle's MemoryMXBean does not seem to instantiate a logging manager.
• JBoss code presupposes it gets "first dibs" on instantiating logging manager. It throws an exception if upstream code instantiated it (ii.e. and has a different classloader)

No xbootclasspath/p,  no -Djava.util.logging.manager=org.jboss.logmanager.LogManager

Without setting any extra properties in (xbootclasspath /p or -Djava.util.loggingmanager),

IBM JVM loads the default logging manager. Jboss complains downstream

No xbootclasspath/p, yes -Djava.util.logging.manager=org.jboss.logmanager.LogManager

Leaving off 'xbootclasspath/p' but adding -Djava.util.logging.manager=org.jboss.logmanager.LogManager, we find  the system classloader cannot load  org.jboss.logmanager.LogManager.

Here's a stack trace

Could not load Logmanager "org.jboss.logmanager.LogManager"

java.lang.ClassNotFoundException: org.jboss.logmanager.LogManager

  at java.net.URLClassLoader.findClass(URLClassLoader.java:607)

  at java.lang.ClassLoader.loadClassHelper(ClassLoader.java:797)

  at java.lang.ClassLoader.loadClass(ClassLoader.java:771)

  at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:325)

  at java.lang.ClassLoader.loadClass(ClassLoader.java:752)

  at java.util.logging.LogManager$1.run(LogManager.java:206)

  at java.util.logging.LogManager$1.run(LogManager.java:192)

  at java.security.AccessController.doPrivileged(AccessController.java:503)

  at java.util.logging.LogManager.<clinit>(LogManager.java:192)

  at java.util.logging.Logger.demandLogger(Logger.java:459)

  at java.util.logging.Logger.getLogger(Logger.java:513)

** at com.sun.jmx.remote.util.ClassLogger.<init>(ClassLogger.java:67)

Yes xbootclasspath/p, yes -Djava.util.logging.manager=org.jboss.logmanager.LogManager

Adding this line allows the system classloader to find org.jboss.logmanager.LogManager

-Xbootclasspath/p:${module_base}/system/layers/base/org/jboss/logmanager/main/jboss-logmanager-2.0.4.Final.jar

However, downstream jboss complains because the system classloader, not the jboss module classloader, loaded org.jboss.logmanager.LogManager

Xref

As i'm not sure whose presuppositions are off and where the error lies, I've written it up here and here

Yet Another Java Service Wrapper / Discussion / Help:java.util.logging and jboss10 (wildfly)

dW:Java:IBM Java Runtimes and SDKs:ibm jdk fails, oracle succeeds, running windows service (yajsw): due to java.util.lo…

[jamezp]

You'll need to set the -Djava.util.logging.manager=org.jboss.logmanager.LogManager system property and use the -Xbootclassplath/p: like you were doing. The next step will be to add org.jboss.logmanager to the JBOSS_MODULES_SYSTEM_PKGS system property.

If you're using the standalone.conf to set these properties it would look something like this.

## -*- shell-script -*- ######################################################
##                                                                          ##
##  WildFly bootstrap Script Configuration                                    ##
##                                                                          ##
##############################################################################


#
# This file is optional; it may be removed if not needed.
#


#
# Specify the maximum file descriptor limit, use "max" or "maximum" to use
# the default, as queried by the system.
#
# Defaults to "maximum"
#
#MAX_FD="maximum"


#
# Specify the profiler configuration file to load.
#
# Default is to not load profiler configuration file.
#
#PROFILER=""


#
# Specify the location of the Java home directory.  If set then $JAVA will
# be defined to $JAVA_HOME/bin/java, else $JAVA will be "java".
#
#JAVA_HOME="/opt/java/jdk"


#
# Specify the exact Java VM executable to use.
#
#JAVA=""


if [ "x$JBOSS_MODULES_SYSTEM_PKGS" = "x" ]; then
   JBOSS_MODULES_SYSTEM_PKGS="org.jboss.byteman"
fi
JBOSS_MODULES_SYSTEM_PKGS="$JBOSS_MODULES_SYSTEM_PKGS,org.jboss.logmanager"


# Uncomment the following line to prevent manipulation of JVM options
# by shell scripts.
#
#PRESERVE_JAVA_OPTS=true


#
# Specify options to pass to the Java VM.
#
if [ "x$JAVA_OPTS" = "x" ]; then
   JAVA_OPTS="-Xms64m -Xmx512m -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m -Djava.net.preferIPv4Stack=true"
   JAVA_OPTS="$JAVA_OPTS -Djboss.modules.system.pkgs=$JBOSS_MODULES_SYSTEM_PKGS -Djava.awt.headless=true"
else
   echo "JAVA_OPTS already set in environment; overriding default settings with values: $JAVA_OPTS"
fi


# Sample JPDA settings for remote socket debugging
#JAVA_OPTS="$JAVA_OPTS -agentlib:jdwp=transport=dt_socket,address=8787,server=y,suspend=n"


# Sample JPDA settings for shared memory debugging
#JAVA_OPTS="$JAVA_OPTS -agentlib:jdwp=transport=dt_shmem,server=y,suspend=n,address=jboss"


# Uncomment to not use JBoss Modules lockless mode
#JAVA_OPTS="$JAVA_OPTS -Djboss.modules.lockless=false"


# Uncomment to gather JBoss Modules metrics
#JAVA_OPTS="$JAVA_OPTS -Djboss.modules.metrics=true"


# Uncomment this to run with a security manager enabled
# SECMGR="true"


# Uncomment this in order to be able to run WildFly on FreeBSD
# when you get "epoll_create function not implemented" message in dmesg output
#JAVA_OPTS="$JAVA_OPTS -Djava.nio.channels.spi.SelectorProvider=sun.nio.ch.PollSelectorProvider"


# Uncomment this out to control garbage collection logging
# GC_LOG="true"


# Find the path to jboss-logmanager*.jar
lmPath=$(find $JBOSS_HOME/modules -name "jboss-logmanager*.jar" | xargs -I {} readlink -m "{}")
JAVA_OPTS="-Djava.util.logging.manager=org.jboss.logmanager.LogManager -Xbootclasspath/p:$lmPath $JAVA_OPTS"

Lines 46, 96 and 97 are the important changes.

--

James R. Perkins

[nuno.godinhomatos]

Hi,

I am also facing this problem while developing in eclipse.

I am having really mixed/inconsistent behavior from the eclipse startup of a wildfly domain.

Sometimes wildfly startups goes fine.

Othertimes, it blows up with an exception stating that the system property:

-Djava.util.logging.manager=org.jboss.logmanager.LogManager

Should be added.

When I do add the:

-Djava.util.logging.manager=org.jboss.logmanager.LogManager

I can startup again.

Other times is the opposite.

So you leave your eclipse configuration in the last used state, say with:

-Djava.util.logging.manager=org.jboss.logmanager.LogManager

excplicitely added in.

And than you get a startup exception for a class not found exception.

This clearly looks like an issue on class loading order.

In fact what I can see is that my local behavior indicates that:

-Djava.util.logging.manager=org.jboss.logmanager.LogManager

is in fact not needed, and should not be provided at all, but some times due to class loading issues you must add it or you can start the jboss logging subsystems.

And the work around for these times is to the property in: -Djava.util.logging.manager=org.jboss.logmanager.LogManager.

Other times you will get the problem that logManager cannot initialzie because of class not found and you must take it off.

Souns like the jboss logging subsystem should probably the the first subsystem that must be started up, whenever it is present, and that this subsystem must ensure it initializes the needed system proeprties on its own.

Right now, I am either adding the system property as an eclipse launch paramater or taking it away, depending on whether I get a class not found exception or log manager system proeprty needed exception.

Thanks.

[jamezp]

This sounds more like an eclipse issue to me. How are you launching it from eclipse?

--

James R. Perkins

[nuno.godinhomatos]

After creating the domain, I typically find the launch settings to give more heap and enable GC log dumping. After that .... Simple. I right click the wildfly 10 domain I was using 10.0.0.Final until today I will now be using 10.1.0Final, and I let the serve run. And then typically, I would say 90 percent of the time no problem... Launches just fine. Other times, it immediately fails asking me to add the log manager system property. If I try again, some times the log manager complaint goes away and launches normally sometimes not. If not, I then have two approaches. One instead of starting in run mode I start in debug mode to switch around the star mode ( note the issue can happen both in run and in debug mode) or instead I add the requested log manager property. Then it starts. Otherwise, if I found myself being forced to add the log manager property sometimes when I right click the domain and Daystar, I will instead of get the exception asking for the system property get the exception that the log manager class is not gone found in the class party. To me this means that the wildfly startup does not follow a deterministic order of loading the subsystems, I suppose ..., or something of the sort and if we are not lucky components that depend on the logging subsytem being initialized will fail likewise the logging subsystems   may fail to initialize if the log manager is not yet added to the class path.  I must say I have never seen the error happening when starting a domain via standalone.bat or maven plugin. But would expect that this should not play a role since the core is the wildfly main class that is put to run, and the system property configurations from eclipse are give or take similar to those of the Java opts Inthe stand alone bat.

[jamezp]

Are you using a Java agent or anything? JBoss Modules should be finding the log manager and configuring it. It sounds to me like an environmental thing.

--

James R. Perkins

[nuno.godinhomatos]

The situation just happened to me again.

I was triggering some system tests, and I had to restart the app server because a rest service on the backend was telling the system test it should connect via jndi to my Hostname that translates into a real network addres and port 8080, and operating system was not accepting connections on my ip for port 8080.

So while the server was running, I manually hammered on the standalone.xml file to add the inet configuration to listen on 0.0.0.0.

Press save.

Hit the wildfly restart button on eclipse and:

{panel}

WARNING: Failed to load the specified log manager class org.jboss.logmanager.LogManager

Aug 11, 2017 8:39:57 PM org.jboss.msc.service.ServiceContainerImpl <clinit>

INFO: JBoss MSC version 1.2.6.Final

Aug 11, 2017 8:39:57 PM org.jboss.as.server.ApplicationServerService start

INFO: WFLYSRV0049: WildFly Full 10.1.0.Final (WildFly Core 2.2.0.Final) starting

Aug 11, 2017 8:39:59 PM org.jboss.as.controller.AbstractOperationContext executeStep

ERROR: WFLYCTL0013: Operation ("parallel-extension-add") failed - address: ([])

java.lang.RuntimeException: WFLYCTL0079: Failed initializing module org.jboss.as.logging

at org.jboss.as.controller.extension.ParallelExtensionAddHandler$1.execute(ParallelExtensionAddHandler.java:115)

at org.jboss.as.controller.AbstractOperationContext.executeStep(AbstractOperationContext.java:890)

at org.jboss.as.controller.AbstractOperationContext.processStages(AbstractOperationContext.java:659)

at org.jboss.as.controller.AbstractOperationContext.executeOperation(AbstractOperationContext.java:370)

at org.jboss.as.controller.OperationContextImpl.executeOperation(OperationContextImpl.java:1329)

at org.jboss.as.controller.ModelControllerImpl.boot(ModelControllerImpl.java:467)

at org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:387)

at org.jboss.as.controller.AbstractControllerService.boot(AbstractControllerService.java:349)

at org.jboss.as.server.ServerService.boot(ServerService.java:397)

at org.jboss.as.server.ServerService.boot(ServerService.java:366)

at org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:299)

at java.lang.Thread.run(Thread.java:745)

Caused by: java.util.concurrent.ExecutionException: java.lang.IllegalStateException: WFLYLOG0078: The logging subsystem requires the log manager to be org.jboss.logmanager.LogManager. The subsystem has not be initialized and cannot be used. To use JBoss Log Manager you must add the system property "java.util.logging.manager" and set it to "org.jboss.logmanager.LogManager"

at java.util.concurrent.FutureTask.report(FutureTask.java:122)

at java.util.concurrent.FutureTask.get(FutureTask.java:192)

at org.jboss.as.controller.extension.ParallelExtensionAddHandler$1.execute(ParallelExtensionAddHandler.java:107)

... 11 more

Caused by: java.lang.IllegalStateException: WFLYLOG0078: The logging subsystem requires the log manager to be org.jboss.logmanager.LogManager. The subsystem has not be initialized and cannot be used. To use JBoss Log Manager you must add the system property "java.util.logging.manager" and set it to "org.jboss.logmanager.LogManager"

at org.jboss.as.logging.LoggingExtension.initialize(LoggingExtension.java:147)

at org.jboss.as.controller.extension.ExtensionAddHandler.initializeExtension(ExtensionAddHandler.java:131)

at org.jboss.as.controller.extension.ExtensionAddHandler.initializeExtension(ExtensionAddHandler.java:104)

at org.jboss.as.controller.extension.ParallelExtensionAddHandler$ExtensionInitializeTask.call(ParallelExtensionAddHandler.java:144)

at org.jboss.as.controller.extension.ParallelExtensionAddHandler$ExtensionInitializeTask.call(ParallelExtensionAddHandler.java:127)

at java.util.concurrent.FutureTask.run(FutureTask.java:266)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

at java.lang.Thread.run(Thread.java:745)

at org.jboss.threads.JBossThread.run(JBossThread.java:320)

Aug 11, 2017 8:39:59 PM org.jboss.as.server.ServerService$4 logExit

FATAL: WFLYSRV0056: Server boot has failed in an unrecoverable manner; exiting. See previous messages for details.

{panel}

I now press the start button after typing all of the above and the server is launching properly.

My eclipse launch configurations look as follows:

{panel}

"-Dprogram.name=JBossTools: techlab_trunk_oracle" -server -Dorg.jboss.resolver.warning=true -Djava.net.preferIPv4Stack=true -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true "-Dorg.jboss.boot.log.file=C:/dev/Widlfly10/wildfly-10.1.0.Final/user_projects/domains/techlabTrunkOracle/log/boot.log" "-Dlogging.configuration=file:/C:/dev/Widlfly10/wildfly-10.1.0.Final/user_projects/domains/myDomainTrunkOracle/configuration/logging.properties" "-Djboss.home.dir=C:/dev/Widlfly10/wildfly-10.1.0.Final" -Dorg.jboss.logmanager.nocolor=true -Djboss.bind.address.management=localhost -Xmx1786M -XX:MaxMetaspaceSize=256m -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10000K -XX:-HeapDumpOnOutOfMemoryError -Djava.awt.headless=true -Dactivemq.artemis.client.global.scheduled.thread.pool.core.size=5 -Dactivemq.artemis.client.global.thread.pool.max.size=40

{panel}

It is for sure a strange error.

Was working all day and it is the first time it happens to me today.

[jamezp]

A bit OT but you shouldn't make changes to the XML files while the server is running.

Anyway this looks like a bug in the tooling possibly. I don't know what the "restart button in eclipse" does, but maybe it's loading the log manager twice which could be an issue. It's definitely not an issue with the WildFly.

--

James R. Perkins

[nuno.godinhomatos]

Ok.
I will postback agian if I find something on my behavior that has some sort of correlation to this event taking place.

It does happen quite seldom and not obvious steps to reproduce.

I will try to be gentle with the standalone.xml configuration .

But when you create the full domain configuration automatically ... you might end up having tendencies to be a bit brutal with it when you need a tiny change that is not scripted yet. Domains are cheap and fast to recreate.

Kindest regards.

[jamezp]

Using CLI or the web console is really the best way. In some cases you may not even need to restart the server at all. If you edit the XML you'll always have to restart the server.

--

James R. Perkins

[nuno.godinhomatos]

Thanks for the tip.
I will use the CLI more often for this type of thing.

Many thanks.