Instrumenting JBoss with javaagent jars

As the author of Feenix, a class reloading framework, I have recently been investigating how to reload web resources such as JSPs, JSF, and other web resources (images, css, etc). Unlike class reloading, web reloading is unique to each web container and consequently each web container implementation must be researched and tested individually. JBoss has a large market share and warrants being one of the first supported containers. However, whenever I always dread working with JBoss because of its incompatibilities with javaagent instrumentation. Googling tells me I am not the only developer or javaagent provider suffering through this problem. It has been such a pain to deal with, I finally did some of my own R&D to figure out what exactly is going on and how to resolve it.

There is no handbook for figuring out how each web container handles web requests. Further, even when the container is open source, it is not always clear how the code will executes (i.e. many if/else branches that depend on variables only known at run time). To help me over this hurdle, I use a home grown tool called Execution Profiler. This tool is extremely handy for determining the execution path for a given request. Execution profiler is a javaagent, which instruments the target classes such that each method invocation is recorded. Unfortunately, it doesn’t play very nicely with JBoss (I am using 7.1.1) out of the box. Unlike most web containers (or their parent application servers), JBoss using the OSGI model, which does some unexpected things with the system classpath. It would be too much of a tangent for me to research and document what OSGI is supposed to do classloader-wise, so I’ll just be documenting how it behaved and how I was able to overcome these obstacles.

Here is how I configured Execution Profiler standalone.bat initially:

set JAVA_OPTS=%JAVA_OPTS% -javaagent:"C:\agents\discotek.execution-profiler-agent-1.0.jar"=classes="javax.servlet.*|org.jboss.as.web.*|org.apache.catalina.*|org.jboss.servlet.*|org.apache.tomcat.*|org.jboss.security.*|org.apache.naming.resources.*"

If you are reading this article then your probably already know what set JAVA_OPTS=… is for. This allows one to modify the JBoss JVM environment. The above configuration will install the Execution Profiler and will pass it a classes parameter whose value is a (Java) regular expression. This expression specifies the set of classes to be instrumented by Execution Profiler. Here is the error you get when you run JBoss with this configuration:

Exception in thread "main" java.lang.ExceptionInInitializerError
        at org.jboss.as.server.Main.main(Main.java:73)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.modules.Module.run(Module.java:260)
        at org.jboss.modules.Main.main(Main.java:291)
Caused by: 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:60)
        at org.jboss.logmanager.log4j.BridgeRepositorySelector.(BridgeRepositorySelector.java:42)
        ... 7 more

The Caused by exception provides some fairly simply instructions for fixing this problem. Let’s add this instruction to standalone.bat, so we now have:

set JAVA_OPTS=%JAVA_OPTS% -javaagent:"C:\agents\discotek.execution-profiler-agent-1.0.jar"=classes="javax.servlet.*|org.jboss.as.web.*|org.apache.catalina.*|org.jboss.servlet.*|org.apache.tomcat.*|org.jboss.security.*|org.apache.naming.resources.*" set JAVA_OPTS=%JAVA_OPTS% -Djava.util.logging.manager=org.jboss.logmanager.LogManager

Running standalone.bat again now gives us this error:

Could not load Logmanager "org.jboss.logmanager.LogManager"
java.lang.ClassNotFoundException: org.jboss.logmanager.LogManager
        at java.net.URLClassLoader$1.run(URLClassLoader.java:203)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:191)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
        at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:276)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
        at java.util.logging.LogManager$1.run(LogManager.java:168)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.util.logging.LogManager.<clinit>(LogManager.java:158)
        at java.util.logging.Logger.getLogger(Logger.java:281)
        at sun.awt.SunToolkit.<clinit>(SunToolkit.java:51)
        at java.lang.Class.forName0(Native Method)
        at java.lang.Class.forName(Class.java:169)
        at java.awt.Toolkit$2.run(Toolkit.java:849)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.awt.Toolkit.getDefaultToolkit(Toolkit.java:841)
        at java.awt.SystemTray.isSupported(SystemTray.java:186)
        at ca.discotek.profiler.SystemTraySupport.install(SystemTraySupport.java:30)
        at ca.discotek.profiler.ExecutionProfilerAgent.premain(ExecutionProfilerAgent.java:147)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:323)
        at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:338)

 

This error is not so helpful. However, there is some useful information here:

  1. The message tells us that the org.jboss.logmanager.LogManager class cannot be found
  2. The stack tells us that the error occurs when trying to install the Execution Profiler System Tray

This information is useful because it tells us that this error is a result of the two changes we made in standalone.bat. That is, it is searching for the org.jboss.logmanager.LogManager class because we configured java.util.logging to use this class and installing the Execution Profiler agent caused JBoss to load classes that require the JBoss java.util.logging resources to be available before the OSGI model makes them available. The next step is to make the org.jboss.logmanager.LogManager (and other classes from the same jar) immediately available.

 

Googling tells me there is a JBoss system property called jboss.modules.system.pkgs that tells JBoss to allow its comma-delimited list of packages to be allowed to be discovered from any class loader. We could blindly set this property, but it might override packages set by this property elsewhere. Specifically, if you look standalone.conf, you’ll see the following:

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

I have no idea what byteman is, but I don’t want to remove it. Hence, we should include it in our configuration, which now looks like this:

set JAVA_OPTS=%JAVA_OPTS% -javaagent:"C:\agents\discotek.execution-profiler-agent-1.0.jar"=classes="javax.servlet.*|org.jboss.as.web.*|org.apache.catalina.*|org.jboss.servlet.*|org.apache.tomcat.*|org.jboss.security.*|org.apache.naming.resources.*" set JAVA_OPTS=%JAVA_OPTS% -Djava.util.logging.manager=org.jboss.logmanager.LogManager set JAVA_OPTS=%JAVA_OPTS% -Djboss.modules.system.pkgs=org.jboss.byteman,org.jboss.logmanager

Here is the output after running standalone.bat with the above configuration:

Could not load Logmanager "org.jboss.logmanager.LogManager"
java.lang.ClassNotFoundException: org.jboss.logmanager.LogManager
        at java.net.URLClassLoader$1.run(URLClassLoader.java:203)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:191)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
        at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:276)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
        at java.util.logging.LogManager$1.run(LogManager.java:168)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.util.logging.LogManager.(LogManager.java:158)
        at java.util.logging.Logger.getLogger(Logger.java:281)
        at sun.awt.SunToolkit.(SunToolkit.java:51)
        at java.lang.Class.forName0(Native Method)
        at java.lang.Class.forName(Class.java:169)
        at java.awt.Toolkit$2.run(Toolkit.java:849)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.awt.Toolkit.getDefaultToolkit(Toolkit.java:841)
        at java.awt.SystemTray.isSupported(SystemTray.java:186)
        at ca.discotek.profiler.SystemTraySupport.install(SystemTraySupport.java:30)
        at ca.discotek.profiler.ExecutionProfilerAgent.premain(ExecutionProfilerAgent.java:147)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:323)
        at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:338)

 

This is the exact same stack trace as the previous run. We now now know that JBoss will allow this package to be discovered, so perhaps we need to explicitly make it available using and -Xbootclasspath entry. Our configuration now looks like this:

set JAVA_OPTS=%JAVA_OPTS% -javaagent:"C:\agents\discotek.execution-profiler-agent-1.0.jar"=classes="javax.servlet.*|org.jboss.as.web.*|org.apache.catalina.*|org.jboss.servlet.*|org.apache.tomcat.*|org.jboss.security.*|org.apache.naming.resources.*" set JAVA_OPTS=%JAVA_OPTS% -Djava.util.logging.manager=org.jboss.logmanager.LogManager set JAVA_OPTS=%JAVA_OPTS% -Djboss.modules.system.pkgs=org.jboss.byteman,org.jboss.logmanager set JAVA_OPTS=%JAVA_OPTS% -Xbootclasspath/a:C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\main\jboss-logmanager-1.2.2.GA.jar

Here is the output after running standalone.bat with the above configuration:

Exception in thread "main" java.lang.NoClassDefFoundError: org/jboss/logmanager/log4j/BridgeRepositorySelector
        at org.jboss.as.server.Main.main(Main.java:73)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.modules.Module.run(Module.java:260)
        at org.jboss.modules.Main.main(Main.java:291)
Caused by: java.lang.ClassNotFoundException: org.jboss.logmanager.log4j.BridgeRepositorySelector
        at java.net.URLClassLoader$1.run(URLClassLoader.java:203)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findClass(URLClassLoader.java:191)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
        at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:276)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
        at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:395)
        at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:120)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
        ... 7 more

 

This is an improvement. JBoss can now find the org.jboss.logmanager classes. It now cannot find the org.jboss.logmanager.log4j classes. Let’s now modify the above configuration so that this package is included in the jboss.modules.system.pkgs and the -Xbootclasspath entries:

set JAVA_OPTS=%JAVA_OPTS% -javaagent:"C:\agents\discotek.execution-profiler-agent-1.0.jar"=classes="javax.servlet.*|org.jboss.as.web.*|org.apache.catalina.*|org.jboss.servlet.*|org.apache.tomcat.*|org.jboss.security.*|org.apache.naming.resources.*" set JAVA_OPTS=%JAVA_OPTS% -Djava.util.logging.manager=org.jboss.logmanager.LogManager set JAVA_OPTS=%JAVA_OPTS% -Djboss.modules.system.pkgs=org.jboss.byteman,org.jboss.logmanager,org.jboss.logmanager.log4j set JAVA_OPTS=%JAVA_OPTS% -Xbootclasspath/a:C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\main\jboss-logmanager-1.2.2.GA.jar;C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\log4j\main\jboss-logmanager-log4j-1.0.0.GA.jar

Here is the error with the next run:

Exception in thread "main" java.lang.NoClassDefFoundError: org/apache/log4j/spi/RepositorySelector
        at java.lang.ClassLoader.findBootstrapClass(Native Method)
        at java.lang.ClassLoader.findBootstrapClass0(ClassLoader.java:891)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:301)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:299)
        at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:276)
        at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
        at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:395)
        at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:120)
        at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
        at org.jboss.as.server.Main.main(Main.java:73)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.jboss.modules.Module.run(Module.java:260)
        at org.jboss.modules.Main.main(Main.java:291)

 

We are getting closer. We now need to repeat the above with the Log4j jar/package:

set JAVA_OPTS=%JAVA_OPTS% -javaagent:"C:\agents\discotek.execution-profiler-agent-1.0.jar"=classes="javax.servlet.*|org.jboss.as.web.*|org.apache.catalina.*|org.jboss.servlet.*|org.apache.tomcat.*|org.jboss.security.*|org.apache.naming.resources.*" set JAVA_OPTS=%JAVA_OPTS% -Djava.util.logging.manager=org.jboss.logmanager.LogManager set JAVA_OPTS=%JAVA_OPTS% -Djboss.modules.system.pkgs=org.jboss.byteman,org.jboss.logmanager,org.jboss.logmanager.log4j,org.apache.log4j set JAVA_OPTS=%JAVA_OPTS% -Xbootclasspath/a:C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\main\jboss-logmanager-1.2.2.GA.jar;C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\log4j\main\jboss-logmanager-log4j-1.0.0.GA.jar;C:\java\jboss-as-7.1.1.Final\modules\org\apache\log4j\main\log4j-1.2.16.jar

Here is the error with the next run:

19:45:42,578 ERROR [org.jboss.as.server] JBAS015956: Caught exception during boot: org.jboss.as.controller.persistence.ConfigurationPersistenceException: JBAS01676: Failed to parse configuration
        at org.jboss.as.controller.persistence.XmlConfigurationPersister.load(XmlConfigurationPersister.java:141) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final]
        at org.jboss.as.server.ServerService.boot(ServerService.java:266) [jboss-as-server-7.1.1.Final.jar:7.1.1.Final]
        at org.jboss.as.controller.AbstractControllerService$1.run(AbstractControllerService.java:155) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final]
        at java.lang.Thread.run(Thread.java:619) [rt.jar:1.7.0-ea]
Caused by: javax.xml.stream.XMLStreamException: Failed to load module org.jboss.as.web
        at org.jboss.as.controller.parsing.ExtensionXml.parseExtensions(ExtensionXml.java:154) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final]
        at org.jboss.as.server.parsing.StandaloneXml.readServerElement_1_1(StandaloneXml.java:305) [jboss-as-server-7.1.1.Final.jar:7.1.1.Final]
        at org.jboss.as.server.parsing.StandaloneXml.readElement(StandaloneXml.java:127) [jboss-as-server-7.1.1.Final.jar:7.1.1.Final]
        at org.jboss.as.server.parsing.StandaloneXml.readElement(StandaloneXml.java:100) [jboss-as-server-7.1.1.Final.jar:7.1.1.Final]
        at org.jboss.staxmapper.XMLMapperImpl.processNested(XMLMapperImpl.java:110) [staxmapper-1.1.0.Final.jar:1.1.0.Final]
        at org.jboss.staxmapper.XMLMapperImpl.parseDocument(XMLMapperImpl.java:69) [staxmapper-1.1.0.Final.jar:1.1.0.Final]
        at org.jboss.as.controller.persistence.XmlConfigurationPersister.load(XmlConfigurationPersister.java:133) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final]
        ... 3 more
Caused by: java.util.concurrent.ExecutionException: java.util.ServiceConfigurationError: org.jboss.as.controller.Extension: Provider org.jboss.as.web.WebExtension could not be instantiated: java.lang.NoClassDefFoundError: ca/discotek/profiler/Recorder
        at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:224) [rt.jar:1.7.0-ea]
        at java.util.concurrent.FutureTask.get(FutureTask.java:83) [rt.jar:1.7.0-ea]
        at org.jboss.as.controller.parsing.ExtensionXml.parseExtensions(ExtensionXml.java:146) [jboss-as-controller-7.1.1.Final.jar:7.1.1.Final]
        ... 9 more

 

It may not be obvious from this error, but we have gotten over the initial hurdle of JBoss loading the JBoss java.util.logging implementation. The relevant information in this error is java.lang.NoClassDefFoundError: ca/discotek/profiler/Recorder. References to the Recorder class are inserted into classes instrumented by Execution Profiler. This error tells us that JBoss doesn’t know how to find the ca.discotek.profiler classes. We now have to repeat the above process for this package. However, javaagent classes are already on the system classpath, so we won’t need to modify -Xbootclasspath:

set JAVA_OPTS=%JAVA_OPTS% -javaagent:"C:\agents\discotek.execution-profiler-agent-1.0.jar"=classes="javax.servlet.*|org.jboss.as.web.*|org.apache.catalina.*|org.jboss.servlet.*|org.apache.tomcat.*|org.jboss.security.*|org.apache.naming.resources.*" set JAVA_OPTS=%JAVA_OPTS% -Djava.util.logging.manager=org.jboss.logmanager.LogManager set JAVA_OPTS=%JAVA_OPTS% -Djboss.modules.system.pkgs=org.jboss.byteman,org.jboss.logmanager,org.jboss.logmanager.log4j,org.apache.log4j,ca.discotek.profiler set JAVA_OPTS=%JAVA_OPTS% -Xbootclasspath/a:C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\main\jboss-logmanager-1.2.2.GA.jar;C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\log4j\main\jboss-logmanager-log4j-1.0.0.GA.jar;C:\java\jboss-as-7.1.1.Final\modules\org\apache\log4j\main\log4j-1.2.16.jar

With these final changes, Execution Profiler now works with JBoss. I hope if you run into similar issues, the above information can help resolve your own problems with JBoss.

BTW, it is worth noting that I use a version of Execution Profiler that is not obfuscated, but the publicly available one is. The obfuscated version has package paths ca.discotek.profiler and discotek_exprof, whereas the version documented above uses only ca.discotek.profiler. To get the public/obfuscated version to work with JBoss, you will probably need to modify the working configuration above to include discotek_exprof in the jboss.modules.system.pkgs entry like this:

set JAVA_OPTS=%JAVA_OPTS% -javaagent:"C:\agents\discotek.execution-profiler-agent-1.0.jar"=classes="javax.servlet.*|org.jboss.as.web.*|org.apache.catalina.*|org.jboss.servlet.*|org.apache.tomcat.*|org.jboss.security.*|org.apache.naming.resources.*" set JAVA_OPTS=%JAVA_OPTS% -Djava.util.logging.manager=org.jboss.logmanager.LogManager set JAVA_OPTS=%JAVA_OPTS% -Djboss.modules.system.pkgs=org.jboss.byteman,org.jboss.logmanager,org.jboss.logmanager.log4j,org.apache.log4j,ca.discotek.profiler,discotek_exprof set JAVA_OPTS=%JAVA_OPTS% -Xbootclasspath/a:C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\main\jboss-logmanager-1.2.2.GA.jar;C:\java\jboss-as-7.1.1.Final\modules\org\jboss\logmanager\log4j\main\jboss-logmanager-log4j-1.0.0.GA.jar;C:\java\jboss-as-7.1.1.Final\modules\org\apache\log4j\main\log4j-1.2.16.jar

 

 

 

This entry was posted in Byte Code Engineering, Developer Tool, JBoss. Bookmark the permalink.

Leave a Reply

Your email address will not be published. Required fields are marked *

*

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>