Wednesday, November 15, 2006

Using java.util.logging in BEA Weblogic

Some weeks ago I was making sure that the JMSJCA connector runs properly on BEA Weblogic 9.1. Of course I ran into some issues: never assume that your code is really portable until you try it out. I also found some issues in Weblogic. Now I don't want to make this into a bashing session of Weblogic: since I work for Sun Microsystems, and Weblogic can be considered a competitor or Glassfish, that would be in bad taste. However, there's one thing that bugged me a lot and for which I want to share a solution: logging.

Dude, where's my log output?

At SeeBeyond (and of course at Sun) we standardized on the use of java.util.logging. You could argue whether java.util.logging is technically the best solution, but since it's a standard it's a lot better if you use that package than it is to write your own or use other third party logging tools. Standardization gives portability! So, JMSJCA, STCMS, etc all use java.util.logging.

When I started to run my test suite on Weblogic, I was surprised that the log output from the tests did not end up in one of the Weblogic log files. Instead, output appeared on the console. Surely there was a configuration option somewhere in Weblogic to fix this, right? I couldn't find one. The problem became even more annoying when I tried to enable debug logging. In Glassfish you go to the logging configuration screen, and you simply type the name of the logging category that you want to change, select the level and that's it. Not so in Weblogic. What was going on? It was time to look a little deeper into this.

How Weblogic uses java.util.logging.

I must admit that the Weblogic documentation is good, and very easily accessible. I wish we had the same situation at SeeBeyond. Anyway, from the documentation it appeared that Weblogic fully supports java.util.logging: I quote from the documentation: To distribute messages, WebLogic Server supports Java based logging by default. The LoggingHelper class provides access to the java.util.logging.Logger object used for server logging. [snip] If your application is configured for Java Logging or Log4j, in order to publish application events using WebLogic logging services, create a custom handler or appender that relays the application events to WebLogic logging services using the message catalogs or Commons API.

Eh, what do you mean... LoggingHelper class? Can't I just use java.util.logging without depending on any Weblogic classes? Do I have to write custom code?

And how do I change log levels dynamically? Isn't there an option in the admin console to do that? An MBean perhaps? I was really surprised to find this recommendation: If you use the DEBUG severity level, BEA recommends that you create a "debug mode" for your application. For example, your application can create an object that contains a Boolean value. To enable or disable the debug mode, you toggle the value of the Boolean. Then, for each DEBUG message, you can create a wrapper that outputs the message only if your application's debug mode is enabled.

For example, the following code can produce a debug message:


private static boolean debug = Boolean.getBoolean("my.debug.enabled");
if (debug) {
   mylogger.debug("Something debuggy happened");
}
[snip]
To enable your application to print this message, you include the following Java option when you start the application's JVM:

-Dmy.debug.enabled=true

That was a good recommendation... TEN YEARS AGO!

A fix

Fortunately, things are not as grim as they look. It's quite easy to write a little bit of code that is deployed globally independently of your application, so that you can continue to use java.util.logging without sprinkling Weblogic dependencies all over your application. First of all, what's all this with this BEA logger? As it turns out, during startup, Weblogic instantiates a java.util.logging.Logger object and hooks a number of Handler objects to it. So if you log to that particular logger, your log output will appear in one of the Weblogic log files. Can't you get access to this Logger using Logger.getLogger(name)? No you cannot: Weblogic is not using the LogManager at all. That particular logger is not registered in the LogManager. That is the reason why you need to use the weblogic.logging.LoggingHelper.getServerLogger() method.

Once we have a reference to this special Logger object,  we can get a list of the Handler objects. Next, we can assign this list to the root logger object. As a result, whenever you use a Logger object obtained through Logger.getLogger(), the output will go to the Weblogic handlers. Problem solved!

Of course we want to centralize this code: afterall we don't want to introduce this dependency in our application code. There are two ways of doing this: we can write our own LogManager and set that as the JVM's LogManager singleton. We can do this because Weblogic doesn't set a LogManager. The other approach is to write a Weblogic startup class. An instance of this class is created at server startup and its startup() method is called. This is the approach I've taken:

package com.sun.bealog;

import java.util.Hashtable;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.Logger;
import javax.management.MBeanServer;
import javax.management.ObjectName;
import javax.naming.Context;
import javax.naming.InitialContext;
import javax.naming.NamingException;
import weblogic.common.T3ServicesDef;
import weblogic.common.T3StartupDef;
import weblogic.logging.LoggingHelper;

/\*\*
\* Allows logging by applications and components using the java.util.logging
\* package by sending output from java.util.logging.Logger-s to the
\* WebLogic trace file.
\*
\* @author fkieviet
\*/
public class BeaLog implements T3StartupDef {

public String startup(String string, Hashtable hashtable) throws Exception {
String result = "";
Logger wllogger = LoggingHelper.getServerLogger();
Handler[] wlhandlers = wllogger.getHandlers();

// Change log level on log file handler
for (int i = 0; i < wlhandlers.length; i++) {
if (wlhandlers[i].getLevel().intValue() >= 530) {
result += "log level changed of " + wlhandlers[i] + "; ";
wlhandlers[i].setLevel(Level.FINEST);
}
}

// Copy handlers from wllogger to rootlogger
Logger rootlogger = Logger. getLogger("");
Handler[] toremove = rootlogger.getHandlers();
for (int j = 0; j < toremove.length; j++) {
rootlogger.removeHandler(toremove[j]);
}
for (int i = 0; i < wlhandlers.length; i++) {
rootlogger.addHandler(wlhandlers[i]);
}
result += "root handler now has " + rootlogger.getHandlers().length + " handlers; ";

// Register wllogger so that it can be manipulated through the mbean
boolean alreadythere = !LogManager.getLogManager().addLogger(wllogger);

// Register mbean
InitialContext ctx = null;
String[] names = new String[] {"java:comp/jmx/runtime", "java:comp/env/jmx/runtime"};
for (int i = 0; i < names.length; i++) {
try {
ctx = new InitialContext();
MBeanServer mbeanServer = (MBeanServer) ctx.lookup(names[i]);
mbeanServer.registerMBean(LogManager.getLoggingMXBean(),
new ObjectName("java.util.logging:type=Logging"));
result += "mbean registered; ";
} catch (Exception e) {
// ignore
} finally {
safeClose(ctx);
}
}

// For Java CAPS: disable two commonly used loggers that are used to
// relay call context information
Logger.getLogger("com.stc.EnterContext").setLevel(Level.OFF);
Logger.getLogger("com.stc.ExitContext").setLevel(Level.OFF);

return this.getClass().getName() + result;
}

private void safeClose(Context ctx) {
if (ctx != null) {
try {
ctx.close();
} catch (NamingException ignore) {
// ignore
}
}
}

public void setServices(T3ServicesDef t3ServicesDef) {
}
}

As you may have noticed, there's another problem that's solved in the code snippet above: dynamice log level configuration. The JVM's logging package ships with an MBean that allows you to set the log levels dynamically. The only thing that needs to be done is to register this MBean in Weblogic's MBeanServer (Weblogic has an unusual way to access its MBeanServer as you can see in the code). From then on, you can use a tool like jmx-console to access the logging mbean and set the log levels.

Download a NetBeans project that contains the BeaLog code.

12 comments:

Roger P said...

Given your experience with WLS what is the best way to connect to JMS Grid? Bea has their concept of foreign JMS Servers which is very easy to setup. It supports testing of the connection, reconnection and connection pooling. Using JMSJCA would give a few extra features but I assume it wouldn't be supported either by Bea or Sun.



Currently we are using WLS 8.1 which isn't working at all when connection pooling is used.

Frank Kieviet said...

Hi Roger,


You can use JMSJCA if you're using WebLogic 9.0 or better, and in that case I recommend this approach. Although I cannot speak with authority, I do think that it is possible to get support from Sun on this combination since we do support CAPS on WebLogic 9.0 and up.




WebLogic 8.1.6 does not support J2EE 1.4 and in that case you probably should use the foreign JMS capabilities of WebLogic. I ran into some issues with this though: WebLogic takes some liberty with the JMS spec that some JMS servers have trouble with, e.g. the multi-threaded access of JMS sessions and XAResource-s. WebLogic also makes some assumptions about the behavior of JMS servers that is causing some problems with some JMS implementations, e.g. WebLogic assumes that a queue receiver on a connection that was started, will not cache any messages if there is no active receive() call.


Frank


eliad said...

Do you have any exmple of how to send TextMessage from openESB (using jms binding) to weblogic jms queue?

thanks in advance!!

Eliad.

Frank Kieviet said...

Re Eliad,

You can simply specify a WL url in the JMS binding, e.g. t3://server:7001.

Frank

Narender Ranganathan said...

Hi there,

I just read through your article and thought you could help me out in the following:

"How do we either purge, or turn off the connect_null.log created in Weblogic?"

You prompt reply would be highly appreciated,

Thanks

regards

Narender

Frank Kieviet said...

Re Narender:

Sorry, I don't know. I don't recall anything about "connect_null.log".

Frank

jaideep said...

whether java 1.6 version support weblogic 8.1 version or not

Narender said...

re:whether java 1.6 version support weblogic 8.1 version or not

Yes it does support from my knowledge

cheers

Narender

Donald Isaak said...

Hey, thanks for this post. I used it as the basis for doing what you suggest in WebLogic 11g.

weblogic.common.T3StartupDef has been deprecated so if anyone wants working code like you see above that works with WebLogic 11g, you can grab it from my post on Migrating to WebLogic - Use java.util.logging.Logger at http://disaak.blogspot.com/2009/11/migrating-to-weblogic-use.html

Vinod Pillai said...

Excellent post Frank. Your fix is what I needed to get out of the nasty work of replacing logger.finest() with System.out.println() for debugging purposes. You can imagine how thankful I am to you for this blog.

Hiren Dedhia said...

I am using Weblogic 8.1. We have clustered environment having that many nodes. At a time application executes on one of the node. Within application we have implemented JMS Queue. The message are getting processed using JMS queues. Now the problem is that these messages are getting processed on same node while other nodes are idle. Means tah if I have 100 messages and I have configured 10 consumers then the node is processing 10 messages at a time instead of 30 messages considering I have 3 nodes.

Anonymous said...

Hi,
I want to dynamic enable of debug levels in weblogic ,with a cluster environments. Ideally my application should have a web page ,from there I want to enable the logger.So that it will affect to the current instance and all other instances also.what should be my approach.I don't want to do through jConsole.