JBoss EAP 7.3 does not start when attaching the javaagent

[DerMuedeJoe]

Hello

I try to apply the opentelemetry-java-instrumentation as a javaagent to the JBoss Application Server 7.3.x (also tried 7.2.9).
The documentation states 7.3.x as supported.
Unfortunately, the server does not start after attaching the agent.

The log when starting the server shows following:

INFO Configuring JGroups cluster traffic encryption protocol to SYM_ENCRYPT.
WARN Detected missing JGroups encryption configuration, the communication within the cluster WILL NOT be encrypted.
WARN No password defined for JGroups cluster. AUTH protocol will be disabled. Please define JGROUPS_CLUSTER_PASSWORD.
WARN Environment variable OPENSHIFT_KUBE_PING_NAMESPACE undefined. Clustering will be unavailable. Please refer to the documentation for configuration.
INFO Configuring JGroups discovery protocol to kubernetes.KUBE_PING
INFO Using PicketBox SSL configuration.
INFO Access log is disabled, ignoring configuration.
WARN Configuration of an embedded messaging broker within the appserver is enabled but is not recommended. Support for such a configuration will be removed in a future release.
WARN If you are not configuring messaging destinations, to disable configuring an embedded messaging broker set the DISABLE_EMBEDDED_JMS_BROKER environment variable to true.
INFO Configuring the server using embedded server
INFO Duration: 7376 milliseconds
INFO Running jboss-eap-7/eap73-openjdk8-openshift-rhel7 image, version 7.3.5
JAVA_OPTS already set in environment; overriding default settings with values:     -javaagent:/tmp/opentelemetry-javaagent-all.jar 
=========================================================================

  JBoss Bootstrap Environment

  JBOSS_HOME: /opt/eap

  JAVA: /usr/lib/jvm/java-1.8.0/bin/java

  JAVA_OPTS:  -server -verbose:gc -Xloggc:"/opt/eap/standalone/log/gc.log" -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=3M -XX:-TraceClassUnloading -javaagent:/tmp/opentelemetry-javaagent-all.jar -Xbootclasspath/p:/opt/eap/jboss-modules.jar:/opt/jboss/container/wildfly/s2i/galleon/galleon-m2-repository/org/jboss/logmanager/jboss-logmanager/2.1.17.Final-redhat-00001/jboss-logmanager-2.1.17.Final-redhat-00001.jar:/opt/jboss/container/wildfly/s2i/galleon/galleon-m2-repository/org/glassfish/jakarta.json/1.1.6.redhat-00001/jakarta.json-1.1.6.redhat-00001.jar:/opt/jboss/container/wildfly/s2i/galleon/galleon-m2-repository/jakarta/json/jakarta.json-api/1.1.6.redhat-00001/jakarta.json-api-1.1.6.redhat-00001.jar:/opt/jboss/container/wildfly/s2i/galleon/galleon-m2-repository/org/wildfly/common/wildfly-common/1.5.2.Final-redhat-00002/wildfly-common-1.5.2.Final-redhat-00002.jar -Djava.util.logging.manager=org.jboss.logmanager.LogManager -Dsun.util.logging.disableCallerCheck=true -XX:+UseParallelOldGC -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=20 -XX:GCTimeRatio=4 -XX:AdaptiveSizePolicyWeight=90 -XX:MaxMetaspaceSize=256m -XX:MetaspaceSize=96m -XX:+ExitOnOutOfMemoryError -Djava.security.egd=file:/dev/./urandom   -Djboss.modules.settings.xml.url=file:///opt/jboss/container/wildfly/s2i/galleon/settings.xml 

=========================================================================

[opentelemetry.auto.trace 2021-03-10 10:32:08:931 +0000] [main] INFO io.opentelemetry.javaagent.tooling.VersionLogger - opentelemetry-javaagent - version: 1.0.0
10:32:12,572 INFO  [org.jboss.modules] (main) JBoss Modules version 1.11.0.Final-redhat-00001
java.lang.IllegalStateException: The LogManager was not properly installed (you must set the "java.util.logging.manager" system property to "org.jboss.logmanager.LogManager")
	at org.jboss.logmanager.Logger.getLogger(Logger.java:57)
	at org.jboss.as.server.Main.main(Main.java:89)
	at org.jboss.modules.Module.run(Module.java:353)
	at org.jboss.modules.Module.run(Module.java:321)
	at org.jboss.modules.Main.main(Main.java:617)
10:32:12,803 FATAL [org.jboss.as.server] (main) WFLYSRV0239: Aborting with exit code 1
[opentelemetry.auto.trace 2021-03-10 10:32:12:993 +0000] [grpc-default-executor-1] WARN io.opentelemetry.exporter.otlp.metrics.OtlpGrpcMetricExporter - Failed to export metrics
io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
	at io.grpc.Status.asRuntimeException(Status.java:534)
	at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:533)

This is not the real exception as hidden by the catch.
The original message is org.jboss.logmanager.Logger cannot be cast to org.jboss.logmanager.Logger.
Also see the screenshot provided of my first glimpse.

With the agent attached, there seem to be an issue with the ClassLoading or some trouble with the ModuleClassLoader from JBoss.
So far, i did not find out, where the "wrong" Loading is coming from.

Maybe i am simply doing something wrong.
I am grateful for every hint.

Thank you in advance.
Roman

Reporducer

Simply build and run the image.
I tried different version and also tired different commands to start.
(The base image defaults to /opt/eap/bin/openshift-launch.sh)

$ docker build -t otel -f Dockerfile .
$ docker container run -it --rm --name test -p 5005:8787 otel

Dockerfile:

#FROM registry.redhat.io/jboss-eap-7/eap72-openshift:1.2-23
FROM registry.redhat.io/jboss-eap-7/eap73-openjdk8-openshift-rhel7

RUN set -o errexit -o nounset \
    && curl -L "https://github.com/open-telemetry/opentelemetry-java-instrumentation/releases/download/v1.0.0/opentelemetry-javaagent-all.jar" -o /tmp/opentelemetry-javaagent-all.jar

ENV JAVA_OPTS="\
    -javaagent:/tmp/opentelemetry-javaagent-all.jar \ 
    -Dotel.javaagent.debug=true \
    -agentlib:jdwp=transport=dt_socket,server=y,suspend=y,address=8787 "
ENV AB_JOLOKIA_OFF=true

#CMD ["/opt/eap/bin/standalone.sh", "-b", "0.0.0.0", "-bmanagement", "0.0.0.0","-c", "standalone-full.xml"]

Environment

• OS: Fedoera 33 / Linux 5.10.20-200.fc33.x86_64 test PR to enable CLA #1 SMP Thu Mar 4 13:18:27 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
• Runtime (from Docker image):
  openjdk version "1.8.0_275"
  OpenJDK Runtime Environment (build 1.8.0_275-b01)
  OpenJDK 64-Bit Server VM (build 25.275-b01, mixed mode)

What version are you using?

opentelemetry-java-instrumentation 1.0.0

What did you expect to see?

The application server starts normally.

[trask]

hi @DerMuedeJoe! can you run with -verbose:class and attach the output? that will give us clues on where the initial access to java.util.logging is coming from

[DerMuedeJoe]

Hi @trask
Sure i will.
The log is created by running this image:

FROM registry.redhat.io/jboss-eap-7/eap73-openjdk8-openshift-rhel7

RUN set -o errexit -o nounset \
    && curl -L "https://github.com/open-telemetry/opentelemetry-java-instrumentation/releases/download/v1.0.0/opentelemetry-javaagent-all.jar" -o /tmp/opentelemetry-javaagent-all.jar

ENV JAVA_OPTS="\
    -verbose:class \
    -javaagent:/tmp/opentelemetry-javaagent-all.jar "
ENV AB_JOLOKIA_OFF=true

log.txt

[ncabanis]

Hello together,
I have tested, if the solution to the linked issue #2591 has also solved this problem - unfortunately, it seems not to.

I have tested using the Dockerfile as described above using all combinations of:

• FROM registry.redhat.io/jboss-eap-7/eap73-openjdk8-openshift-rhel7 (Java 8)
• FROM registry.redhat.io/jboss-eap-7/eap73-openjdk11-openshift-rhel8 (Java 11)
• opentelemetry-javaagent-all.jar v1.0.0
• opentelemetry-javaagent-1.1.0-20210329.034440-18.jar

Each combination fails with the same error as described above.

[mateuszrzeszutek]

I have investigated it a bit further and I found a few things that worry me a bit. The agent 100% goes into the late component installer initialization path, which is good - but somehow it's still broken.
First:

[Loaded io.opentelemetry.javaagent.tooling.AgentInstaller$ClassLoadCallBack$1 from x-internal-jar:/]
[Loaded java.util.logging.LogManager from /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.275.b01-0.el7_9.x86_64/jre/lib/rt.jar]
[Loaded io.opentelemetry.javaagent.shaded.instrumentation.runtimemetrics.GarbageCollector from x-internal-jar:/]
[Loaded java.util.logging.LogManager$1 from /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.275.b01-0.el7_9.x86_64/jre/lib/rt.jar]
[Loaded java.lang.management.MemoryMXBean from /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.275.b01-0.el7_9.x86_64/jre/lib/rt.jar]
[Loaded javax.management.NotificationBroadcaster from /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.275.b01-0.el7_9.x86_64/jre/lib/rt.jar]
[Loaded javax.management.NotificationEmitter from /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.275.b01-0.el7_9.x86_64/jre/lib/rt.jar]
[Loaded org.jboss.logmanager.LogManager from /opt/jboss/container/wildfly/s2i/galleon/galleon-m2-repository/org/jboss/logmanager/jboss-logmanager/2.1.17.Final-redhat-00001/jboss-logmanager-2.1.17.Final-redhat-00001.jar]

AgentInstaller$ClassLoadCallBack$1 should be loaded AFTER LogManager, because this is the Runnable created by InstallComponentAfterByteBuddyCallback -- which is supposed to run only after LogManager has loaded. I have no idea why it would be loaded before LogManager, it's a bit strange.

Second:

[Loaded io.opentelemetry.sdk.extension.resources.ProcessResource from x-internal-jar:/]
[Loaded java.lang.management.ManagementFactory from /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.275.b01-0.el7_9.x86_64/jre/lib/rt.jar]
[Loaded sun.management.ManagementFactoryHelper from /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.275.b01-0.el7_9.x86_64/jre/lib/rt.jar]

ProcessResource uses JMX classes to get necessary info - this does not seems to be causing any issues here (LogManager stuff happens way later) but maybe it should get command line args the same way OpenTelemetryAgent does - to be extra safe.

This is just a guess, but I think that maybe what's causing this problem is our runtime-metrics instrumentation (uses JMX classes). @DerMuedeJoe @ncabanis try disabling it (-Dotel.instrumentation.runtime-metrics.enabled=false) and see if JBoss starts.

[ncabanis]

No, that seems not to change anything.

[DerMuedeJoe]

After fiddeling around some hours and spend some hours debugging, i found a running solution.

FROM registry.redhat.io/jboss-eap-7/eap73-openjdk8-openshift-rhel7

RUN set -o errexit -o nounset \
    && curl -L "https://github.com/open-telemetry/opentelemetry-java-instrumentation/releases/download/v1.1.0/opentelemetry-javaagent-all.jar" -o /tmp/opentelemetry-javaagent-all.jar

ENV JAVA_OPTS_APPEND="\
    -javaagent:/tmp/opentelemetry-javaagent-all.jar "
ENV AB_JOLOKIA_OFF=true

This adds the agentlib to the end of the argument list and then magically it works. I did not dig deeper into this for now after spending hours in the debugger.

[DerMuedeJoe]

I will close this ticket as the provided solution works for me and probably won't provide any deeper analysis on this.