Friday, September 23, 2011

Dynamically changing app-specific logging under JBoss AS: JMX

01.12.2011. Update: Go read first this post. Then come back here if you want.

I have already blogged on JBoss 6 application specific logging, see here.

The setup works as expected. But I still miss a very important piece of functionality. The logging is not the main (you'd be surprised what some creative people can do!) reason why an application is developed. The logging helps identifying and finding problems in the application. One of the requirements to the logging framework is the ability to change at least some setting without a new deployment of the application:
  1. Changing log levels is a must. If I have a problem with a running application I want to be able to change log levels of some loggers and see the changes being applied as soon as possible.

  2. Changing the output formatting might come handy in some cases. I have been in a situation when I really wanted to change the formatting only once: the output did not include thread names.

  3. Changing where the log is written is not that important. Well, of course, it the log is currently written to nowhere then it is important to be able to change it. But normally the log is written somewhere and it is good enough to investigate a problem.
None of this is possible by default with the application-specific logging in JBoss AS 6. It looks like a crude joke: the standard logging configuration in JBoss is hot-deployable. Any change to <jboss>/server/<server_name>/deploy/jboss-logging.xml is applied almost immediately. There is a JMX MBean (java.util.logging:type=Logging) which can be used to query and change log levels. And if I want to change some configuration in the application-specific logging configuration? Only by redeploying the application.

I must say I find it more and more annoying. It looks suspiciously close to early versions of red hat linux :-) The things seem to work but if I need just a bit more functionality, which I know is there, I need a hammer. Or a debugger this time.

Anyway after some quality swearing, mainly at jboss, but maven and eclipse got their share of attention, and countless attempts to deploy an application and change some configuration files I have found several ways to (partially) change the per-application logging without redeploying the application.

Most of the solutions are just variations of the same approach. They allow changing every detail of the application logging with various degrees of cumbersomeness.

One solution stands really apart. It is quite easy to setup and use, with a single limitation: only log levels can be changed, no other change is possible. But this is exactly what is needed most of the time. The solution offers the possibility to perform changes locally and remotely. Another advantage: if you have already an application with the app-specific logging configured and are just dying to change the log level "right now" you can do it without redeploying the application. The solution is described below:

Changing log levels via JMX.


Changing logging details looks like a perfect candidate for JMX. When I was experimenting with the logging I was a bit surprised by the lack of any logging JMX. JBoss is full with JMX beans, yet there is no JMX related to the logging except the one which comes from JDK: java.util.logging:type=Logging. (JBoss replaces it with its own at startup, but this is beyond the point.)

After inspecting JBoss logging source code I came across some mentioning of JMX. The most promising were classes org.jboss.logmanager.LogContext with its getLoggingMXBean() method and org.jboss.logmanager.LoggingMXBeanImpl implementing java.util.logging.LoggingMXBean interface. So I concentrated on them.

I must say JBoss guys have really interesting sence of humor. It walks like a duck, it swims like a duck, it quacks like a duck, yet it is not a duck. Now I have an example of such a beast. You see, the class is named LoggingMXBeanImpl, it implements LoggingMXBean, the method is getLoggingMXBean, and yet an instance of class org.jboss.logmanager.LoggingMXBeanImpl does not pass the validation rules of the JBoss JMX server. You can't do better than that even on purpose.

Anyway, here is it:
  1. Configure your application to use the app-specific logging. You end up creating a file named jboss-logging.xml that looks like this:
    <logging xmlns="urn:jboss:logging:6.0" context="MyWonderfulLogContext">
    <define-context name="MyWonderfulLogContext"/>

    <!-- Here come definitions of handlers, loggers, etc -->
    ...
    </logging>

  2. Deploy your application; make sure the app-specific logging actually works and the logging goes where it supposed to go.

  3. Create somewhere a file named for example MyWonderfulLog-jboss-beans.xml with the following content:
    <?xml version="1.0" encoding="UTF-8"?>
    <deployment xmlns="urn:jboss:bean-deployer:2.0">
    <bean name="MyWonderfulLogContextMBean" class="java.util.logging.LoggingMXBean">
    <constructor factoryMethod="getLoggingMXBean">
    <factory bean="Logging:CONTEXT:MyWonderfulLogContext"/>
    </constructor>
    <annotation>@org.jboss.aop.microcontainer.aspects.jmx.JMX(
    exposedInterface=java.util.logging.LoggingMXBean.class,
    name="boom.tralala:context=MyWonderfulLogContext",
    registerDirectly=false)</annotation>
    </bean>
    </deployment>
    Attention: the annotation element must be on a single line!

  4. Deploy this file by copying it to <jboss>/server/<server_name>/deploy. If everything went OK and there are no errors in console or in <jboss>/server/<server_name>/log/server.log, then navigate to http://<jboss-host>:<jboss-port>/jmx-console. You should see something like this:




  5. Click on context=MyWonderfulLogContext link and you get to the page that allows you to query some information and, more importantly, change log levels with operation setLoggerLevel. The first parameter is the logger name like 'org.jboss' or 'com.mycompany.app.package'. The second parameter is the logging level like 'INFO' or 'DEBUG'. Go ahead and play with it.

  6. If everything is working you can repackage your application so that there is no need to deploy 2 files, your application and MyWonderfulLog-jboss-beans.xml. Rename the file to jboss-beans.xml and place it next to your jboss-logging.xml, for example, in EAR/META-INF. If you already have jboss-beans.xml just add MyWonderfulLogContextMBean bean definition to your file. Next time you deploy your application you get the logging JMX bean automatically.

That is it.

Oh, yeah. Some technical details:
  1. When JBoss deploys your logging configuration it creates some objects (beans) and registers them internally. These objects are not JMX beans. One of the objects is LogContext and it is registered under the name Logging:CONTEXT:<name attribute of define-context element from jboss-logging.xml>. Thus the bean name <factory bean="Logging:CONTEXT:MyWonderfulLogContext"/> in *-jboss-beans.xml must match the name JBoss uses internally.

  2. Ignoring 'annotation' element the definition can be read as "look up JBoss bean named Logging:CONTEXT:MyWonderfulLogContext, invoke its method getLoggingMXBean and place the result of invocation in the JBoss bean registry under the name MyWonderfulLogContextMBean". There is yet no JMX in sight.

  3. Now comes the annotation element. JBoss allows you to annotate bean instances dynamically. The result looks as if java class of the instance had this annotation. In this case: as if class org.jboss.logmanager.LoggingMXBeanImpl had annotation @org.jboss.aop.microcontainer.aspects.jmx.JMX. The only difference is that the annotation is not there if you have any instance of this class itself but it is there if you have MyWonderfulLogContextMBean bean. Important: the annotation element must be on a single line, and must not start (and probably end) with whitespaces. JBoss annotation parser is very picky.

  4. The annotation itself says that JBoss bean named MyWonderfulLogContextMBean has to be registered as a JMX bean. Attribute 'name' specifies the ObjectName under which the bean has to be registered. It is a good idea to include the name of your LogContext there. And try not to use 'jboss' anywhere in the name to avoid future naming conflicts.

    I have created a JBoss issue and if its fixed JBoss would have to come up with a naming scheme. I doubt 'boom.tralala' would be their first choice but I would not be surprised if they stick 'jboss' somewhere in the name.

    If attribute 'registerDirectly' is true JBoss expects that the bean is already a JMX MBean. Remember I said above that the instance of org.jboss.logmanager.LoggingMXBeanImpl does not pass the validation rules of the JBoss JMX server? This is the reason 'registerDirectly' is set to false. This makes JBoss wrap our instance in an instance of class javax.management.StandardMBean, which is recognized as a valid JMX MBean by the JBoss JMX server.

    And StandardMBean needs to know what interface it is going to represent. This explains attribute 'exposedInterface'.

Next time I explain how to change every aspect of the logging configuration at runtime.

Thursday, September 8, 2011

Assorted facts about JBoss. Fact 3: how to make per-application logging work

01.12.2011. Update: Go read first this post. Then come back here if you want.

I am now busy with some JBoss AS6 related work. One of the things I wanted to be able to do is to have a separate application specific log file. Very easy, very understandable requirement.

Except not under JBoss. It looks like there is a completely new logging subsystem in JBoss AS 6. No advice on how to do it in previous versions would help. And there is not much documentation on how to do it except of some examples here and there and complains that this functionality is broken. There is also a corresponding JBoss issue.

The issue page describes the problem and offers a workaround. The issue is marked as resolved in JBoss AS 6.1.0 Final. The "fix" is actually a proposed workaround; the fact that I immediately did not like.

I have created jboss-logging.xml so that all the logging from my application would go not to ${jboss.server.log.dir}/server.log but to ${jboss.server.log.dir}/my-app.log. After deploying my application I immediately noticed that the fix worked: there was no error. I also got my-app.log next to server.log. All nice and dice. Brand new empty my-app.log no matter what I did in my application. All the logging still went to server.log. So much for the fix.

And it looks like I am not alone. This post mentions the same problem: "My new log file is empty."

But the new wonderful logging subsystem does more for me! When I undeploy my application I get the following exception:
ERROR [org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer]
Error during undeploy: Logging:REGISTRATION:MyAppLogContext:Anonymous-5: java.lang.NullPointerException
at org.jboss.logging.metadata.GetClassLoaderBeanMetaData.setClassLoader(GetClassLoaderBeanMetaData.java:52)
at org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer.undeploy(BeanMetaDataDeployer.java:237)
at org.jboss.deployers.vfs.deployer.kernel.BeanMetaDataDeployer.undeploy(BeanMetaDataDeployer.java:58)
Bummer!

After some poking around jboss configuration and the source code I have found a solution. Actually a workaround and a fix.

Workaround:
  1. If you are still working on JBoss AS 6.0.0.Final then you have to apply the workaround described in this issue: change file JBOSS_HOME/server/<servername>/deployers/jboss-logging.deployer/META-INF/logmanager-jboss-beans.xml. Now you have the same configuration as JBoss AS 6.1.0.Final.
  2. Change the logging deployer configuration (file JBOSS_HOME/server/<servername&g;/deployers/jboss-logging.deployer/META-INF/logmanager-jboss-beans.xml) by removing that mode="On Demand" from
    OnDemandJBossLogManagerContextSelector bean:
    <bean name="OnDemandJBossLogManagerContextSelector"
    class="org.jboss.logmanager.LogContextSelectorService"
    mode="On Demand">
    <property name="selector">
    <inject bean="JBossLogManagerContextSelectorService"/>
    </property>
    </bean>
    You can also remove that comment above about lazy loading. It is not true anyway.

Congratulations, you have now your application specific log file and your logging really goes to this file. Unfortunately you will get NPE (see above) when your application is undeployed. This can't be worked around.

The fix is actually a code patch. I have submitted it to JBoss (see here). Unfortunately it means we have to wait until it is accepted and incorporated into some release. For those who are not afraid of javac: you can download the patch from the issue page and build it yourself. You will have to update the logging deployer configuration (file JBOSS_HOME/server/<servername&g;/deployers/jboss-logging.deployer/META-INF/logmanager-jboss-beans.xml). It is also included in the patch.