jmx_exporter icon indicating copy to clipboard operation
jmx_exporter copied to clipboard

Attaching prometheus to javaagent leads to Logger errors

Open Anshuamrita opened this issue 4 years ago • 8 comments
trafficstars

I attached prometheus javaagent to Jboss JAVA_OPTS="$JAVA_OPTS -javaagent:<full_path>/jmx_prometheus_javaagent.jar=8686/jmx_exporter.yaml"

This starts giving LogManager execption. Then I passed options to JVM to set and configure LogManager as below: JAVA_OPTS="$JAVA_OPTS -Dlogging.configuration=file:<full_path>/logging.properties -Djava.util.logging.manager=org.jboss.logmanager.LogManager -Dorg.jboss.logging .Logger.pluginClass=org.jboss.logging.logmanager.LoggerPluginImpl -Dlog4j.defaultInitOverride=true and post this I am attaching javaagent. Previous errors are gone but now new error is observed:

__ Unable to set property fileName on class org.jboss.logmanager.handlers.SizeRotatingFileHandler: java.lang.reflect.InvocationTargetException 13:01:04.114 nnm-core> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 13:01:04.114 nnm-core> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 13:01:04.114 nnm-core> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 13:01:04.114 nnm-core> at java.lang.reflect.Method.invoke(Method.java:498) 13:01:04.115 nnm-core> at org.jboss.logmanager.PropertyConfigurator.configureProperties(PropertyConfigurator.java:187) 13:01:04.115 nnm-core> at org.jboss.logmanager.PropertyConfigurator.configureHandler(PropertyConfigurator.java:312) 13:01:04.115 nnm-core> at org.jboss.logmanager.PropertyConfigurator.configure(PropertyConfigurator.java:128) 13:01:04.115 nnm-core> at org.jboss.logmanager.PropertyConfigurator.configure(PropertyConfigurator.java:86) 13:01:04.115 nnm-core> at org.jboss.logmanager.LogManager.readConfiguration(LogManager.java:246) 13:01:04.115 nnm-core> at org.jboss.logmanager.LogManager.readConfiguration(LogManager.java:231) 13:01:04.115 nnm-core> at java.util.logging.LogManager$3.run(LogManager.java:399) 13:01:04.115 nnm-core> at java.util.logging.LogManager$3.run(LogManager.java:396) 13:01:04.115 nnm-core> at java.security.AccessController.doPrivileged(Native Method) 13:01:04.115 nnm-core> at java.util.logging.LogManager.readPrimordialConfiguration(LogManager.java:396) 13:01:04.115 nnm-core> at java.util.logging.LogManager.access$800(LogManager.java:145) 13:01:04.116 nnm-core> at java.util.logging.LogManager$2.run(LogManager.java:345) 13:01:04.116 nnm-core> at java.security.AccessController.doPrivileged(Native Method) 13:01:04.116 nnm-core> at java.util.logging.LogManager.ensureLogManagerInitialized(LogManager.java:338) 13:01:04.116 nnm-core> at java.util.logging.LogManager.getLogManager(LogManager.java:378) 13:01:04.116 nnm-core> at java.util.logging.Logger.demandLogger(Logger.java:448) 13:01:04.116 nnm-core> at java.util.logging.Logger.getLogger(Logger.java:502) 13:01:04.116 nnm-core> at io.prometheus.jmx.shaded.io.prometheus.jmx.JmxCollector.(JmxCollector.java:39) 13:01:04.116 nnm-core> at io.prometheus.jmx.shaded.io.prometheus.jmx.JavaAgent.premain(JavaAgent.java:29) 13:01:04.116 nnm-core> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 13:01:04.116 nnm-core> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 13:01:04.116 nnm-core> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 13:01:04.117 nnm-core> at java.lang.reflect.Method.invoke(Method.java:498) 13:01:04.117 nnm-core> at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:386) 13:01:04.117 nnm-core> at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:401) 13:01:04.117 nnm-core> Caused by: java.io.FileNotFoundException: ${jboss.boot.server.log.dir}/boot.log (No such file or directory) _

Application logs are getting created but boot.log is not getting created. Can anyone help here the right way to configure log and javaagent. So that it works properly. Probably here boot.log is looked upon by javaagent before logManager sets it up and initialization happens. We are using Java8 and prometheus javaagent version: 0.16.1

Anshuamrita avatar Oct 18 '21 13:10 Anshuamrita

Wildfly (and JBoss) use java.util.logging for logging, and the implementation assumes that org.jboss.logmanager.LogManager is used as the underlying log manager.

The issue is, if anything touches java.util.logging before Wildfly, the default log manager will be installed and Wildfly will fail to start, because it cannot initialize org.jboss.logmanager.LogManager. This happens if you start Wildfly with the jmx_exporter attached, because jmx_exporter touches java.util.logging before Wildfly.

The workaround is to tell the jmx_exporter agent to use org.jboss.logmanager.LogManager, so that this is initialized with the implementation Wildfly expects.

In order to do that, you need to set a couple of system properties, and you need to put the implementation of org.jboss.logmanager.LogManager into the boot class path.

I created a little script that sets JAVA_OPTS with a configuration that works with Wildfly 25 and Java 11:

export JAVA_OPTS=""

export PORT=9123
export WILDFLY_DIR="${HOME}/Downloads/wildfly-25.0.0.Final"
export JMX_EXPORTER_DIR="${HOME}/src/github.com/prometheus/jmx_exporter"

export JAVA_OPTS="${JAVA_OPTS} -Djava.util.logging.manager=org.jboss.logmanager.LogManager"
export JAVA_OPTS="${JAVA_OPTS} -Djboss.modules.system.pkgs=org.jboss.logmanager"
export JAVA_OPTS="${JAVA_OPTS} -Dsun.util.logging.disableCallerCheck=true"
export JAVA_OPTS="${JAVA_OPTS} -Xbootclasspath/a:${WILDFLY_DIR}/modules/system/layers/base/org/jboss/logmanager/main/jboss-logmanager-2.1.18.Final.jar:${WILDFLY_DIR}/modules/system/layers/base/org/wildfly/common/main/wildfly-common-1.5.4.Final.jar"
export JAVA_OPTS="${JAVA_OPTS} -javaagent:${JMX_EXPORTER_DIR}/jmx_prometheus_javaagent/target/jmx_prometheus_javaagent-0.16.2-SNAPSHOT.jar=${PORT}:${JMX_EXPORTER_DIR}/integration_tests/agent_smoke_test/src/test/resources/config.yml"

echo "${JAVA_OPTS}"

With JAVA_OPTS set as defined above, you should be able to run ./bin/standalone.sh and the jmx_exporter should attach successfully.

Hope that helps.

fstab avatar Oct 18 '21 18:10 fstab

Thanks for the prompt reply. Also wanted to check what is the default interval for javaagent to expose JVM metrics? And how do we tune it,if required

Anshuamrita avatar Oct 19 '21 07:10 Anshuamrita

The poll interval is configured in the Prometheus server. The javaagent just responds to requests coming from the Prometheus server, so it exposes metrics every time it gets a request from the server.

fstab avatar Oct 19 '21 08:10 fstab

We configured scrape_interval of 5s in our serviceMonitor. But despite that Grafana dashboard shows datapoint every 60s. Whereas it should have been generated evry 5s? Why the configured scrape interval not being honored?

Anshuamrita avatar Oct 19 '21 13:10 Anshuamrita

The configuration in Grafana says how often it pulls data from the Prometheus server, the configuration in Prometheus says how often it scrapes data from the exporter. A scrape interval of 5s seems a bit much, I would assume that a higher value like 60s is sufficient.

fstab avatar Oct 21 '21 21:10 fstab

Getting this error when performing operation for application running on Jboss Exception in thread "main" java.lang.reflect.InvocationTargetException at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:386) at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:401) Caused by: java.net.BindException: Address already in use at sun.nio.ch.Net.bind0(Native Method) at sun.nio.ch.Net.bind(Net.java:461) at sun.nio.ch.Net.bind(Net.java:453) at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:222) at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:85) at sun.net.httpserver.ServerImpl.(ServerImpl.java:100) at sun.net.httpserver.HttpServerImpl.(HttpServerImpl.java:50) at sun.net.httpserver.DefaultHttpServerProvider.createHttpServer(DefaultHttpServerProvider.java:35) at com.sun.net.httpserver.HttpServer.create(HttpServer.java:130) at io.prometheus.jmx.shaded.io.prometheus.client.exporter.HTTPServer.(HTTPServer.java:190) at io.prometheus.jmx.shaded.io.prometheus.jmx.JavaAgent.premain(JavaAgent.java:31)

Currently I have specified javaagent as javaagent:/jmx_prometheus_javaagent.jar=8686:/jmx_exporter.yaml

Anshuamrita avatar Oct 29 '21 11:10 Anshuamrita

This means that another process is also trying to use port 8686 on the same host.

fstab avatar Oct 29 '21 20:10 fstab

I would suggest a small enhancement to the earlier answer which might help to stop searching for a new logger lib after each update:

export JAVA_OPTS="${JAVA_OPTS} -Xbootclasspath/a:$(ls $WILDFLY_DIR/modules/system/layers/base/org/jboss/logmanager/main/jboss-logmanager-*.jar):$(ls $WILDFLY_DIR/modules/system/layers/base/org/wildfly/common/main/wildfly-common-*.jar)"

ndimitry avatar Nov 10 '21 18:11 ndimitry

@Anshuamrita

Have you resolved this issue?

If there are no updates within 1 week, this will be closed as inactive.

dhoard avatar Apr 14 '23 12:04 dhoard

Just for information which may help a lot.

WildFly and JBoss implemented a special way to attach java agents. Use this way to attach jmx java agent:

export MODULE_OPTS=-javaagent:/artifacts/jmx_prometheus_javaagent-0.XX.X.jar=<port>:/artifacts/config.yml

Or set the very same MODULE_OPTS property (variable) in the end of the Wildfly/JBoss setup script (something like standalone.sh, etc.).

Starting from one of the Wilfdly/JBoss versions (checked, it is WF21, search for MODULE_OPTS in the release description) they changed the way WF/JBoss is loaded. This automatically resolved this issue with logger. Now if an agent is attached using MODULE_OPTS variable, WF loads its main libraries also as agents. This leads to the logger being available on the start up. So there is no need for these crazy solutions to manually attach libraries which contain implementation of logging

ndimitry avatar May 16 '23 11:05 ndimitry