The Server Labs Blog Rotating Header Image

logging

Dynamically changing log level with Weblogic, log4j, JMX and WLST

Logging is an uninteresting but nevertheless fundamental part of application development. It is useful not just when you are coding an application but in diagnosing problems of any nature once an application passes into production.

Unfortunately, it is not that clear how to do logging well when developing JEE applications that are to be deployed on a Weblogic server. With this article, I hope to clear up some of the confusion or, at the very least, explain a method that works for me!

The article is based on the use of Apache log4j since that is the most commonly used logging library. The article explains:

  • how to configure log4j properly in a JEE app to be run on Weblogic
  • how to dynamically configure the log level using JMX and Weblogic Scripting Tool

The article assumes some familiarity with Apache Maven, Eclipse and Weblogic.

The code is available here, although you may just prefer to download the EAR file which saves you having to compile any code with Maven. The code.zip file contains the code for the JEE application, the code for the JMX library developed by The Server Labs and used in this article and the scripts for WLST.

Configuring log4j in Weblogic

Weblogic 10 comes with a modified version of log4j by default so you can use log4j in your application without having to deploy the log4j library in your application. Unfortunately, my experience (in WLS 10.0) is that if you do this, you will not be able to configure log4j for your application because the classloader in which log4j is loaded is one that is separate to that of your application. Any log4j.properties that you include will be ignored.

Instead, what you have to do is the following:

1) Include the log4j JAR in your application. If your app is an EAR (like mine), then the log4j JAR should go in the .ear file (in the root directory or in /APP-INF/lib). In my project, I have used a Maven multi-project setup with 3 projects – 1 for the EAR, 1 for the EJBs and 1 webapp. In this case, I have to add the log4j JAR to the EAR project’s pom.xml:

	
		
			log4j
			log4j
			1.2.12
		
	 

2) Tell Weblogic to use your version of the log4j library and not it’s own. To do this, you specify the following in the weblogic-application.xml file which is in the EAR (/META-INF/weblogic-application.xml):

	
		org.apache.log4j.*
	

This basically says that when the app asks for a class in the package org.apache.log4j or it’s sub-packages, that it should look for it on the app’s classloader and not in the Weblogic server classloader.

3) Configure log4j using log4j.properties

Log4j requires that you configure it in order to receive log messages. I include the following contents in the /APP-INF/classes/log4j.properties file which is in the EAR file:

log4j.rootLogger=INFO, stdout, file

log4j.debug=true

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=[%d] %-5p %c %x - %m%n

log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.File=/bea/logs/aplicaciones/blog-logging/logging_${weblogic.Name}.log
log4j.appender.file.Append = false
log4j.appender.file.layout = org.apache.log4j.PatternLayout
log4j.appender.file.MaxFileSize = 20000Kb
log4j.appender.file.MaxBackupIndex = 5
log4j.appender.file.layout.ConversionPattern=[%d] %-5p %c %x - %m%n


log4j.category.com.theserverlabs.blog.wls=DEBUG

This configures log4j to send output both to the console in which Weblogic was started and to a file (/bea/logs/aplicaciones/blog-logging/logging_${weblogic.Name}.log). You will probably want to change the file path to something that works on your machine.

Testing that log4j is working OK

In order to test these changes, download the EAR file and deploy it to a Weblogic server. I tested on Weblogic 10.3 but it should work on any Weblogic 10.x server or later I believe.

Go to the URL http://localhost:7001/logging/test and you should see a very basic HTML page that tells you to check the logs:

servlet

Take a look at the console in which weblogic is running (or the Server.out file if you have the output redirected) and you should see output like that shown below:

[2010-04-21 15:29:47,888] WARN  com.theserverlabs.blog.wls.logging.view.servlet.LoggingTestServlet  - warn
[2010-04-21 15:29:47,888] INFO  com.theserverlabs.blog.wls.logging.view.servlet.LoggingTestServlet  - info
[2010-04-21 15:29:47,888] DEBUG com.theserverlabs.blog.wls.logging.view.servlet.LoggingTestServlet  - debug
[2010-04-21 15:29:47,889] ERROR com.theserverlabs.blog.wls.logging.view.servlet.LoggingTestServlet  - error
[2010-04-21 15:29:47,889] FATAL com.theserverlabs.blog.wls.logging.view.servlet.LoggingTestServlet  - fatal
[2010-04-21 15:29:48,056] WARN  com.theserverlabs.blog.wls.logging.services.ejb.SessionLoggingTestService  - warn
[2010-04-21 15:29:48,056] INFO  com.theserverlabs.blog.wls.logging.services.ejb.SessionLoggingTestService  - info
[2010-04-21 15:29:48,056] DEBUG com.theserverlabs.blog.wls.logging.services.ejb.SessionLoggingTestService  - debug
[2010-04-21 15:29:48,056] ERROR com.theserverlabs.blog.wls.logging.services.ejb.SessionLoggingTestService  - error
[2010-04-21 15:29:48,056] FATAL com.theserverlabs.blog.wls.logging.services.ejb.SessionLoggingTestService  - fatal

If you examine the application, you can see that accessing the URL causes a Servlet to get executed. The servlet writes it’s messages to the log (those recorded with the class “com.theserverlabs.blog.wls.logging.view.servlet.LoggingTestServlet”) and invokes an EJB3 session bean which also writes messages to the log (those tagged with “com.theserverlabs.blog.wls.logging.services.ejb.SessionLoggingTestService”).

This shows that this log solution works equally for web as for EJB and that there is no interference with the weblogic logging system.

Making it dynamic

This is a great solution when you’re still developing the app because you can change the debug level just by modifying the log4j.properties file and redeploying the app. However, this is not something you can feasibly do in a production environment – not at the companies I’ve worked at anyway – due to the interruption in service this causes to the end users.

Why would you want to change the log level? Well, if you have to diagnose a problem in the application, it often makes sense to increase the log level of either the whole application or a subset of it such that you receive more information which helps you to diagnose the problem. Once you have diagnosed the problem, you return the logging to it’s original level so as not to affect the performance of the application unnecesarily.

What we really want is to be able to change the log level dynamically (i.e. without redeploying the application), ideally using administrator tools (since that is what the people who manage production systems tend to use) – not developer tools.

First I’ll show you how to change the log level and then I’ll explain how it works.

Using WLST and JMX to change the log level

If you have deployed the example application, go to your domain home in a terminal window and execute the setDomainEnv script. The idea is to update your shell with the domain environment variables such as JAVA_HOME, CLASSPATH etc. On my linux box, I execute the following:

$ cd $DOMAIN_HOME/bin
$ source setDomainEnv.sh

To check it has worked, run “echo $CLASSPATH” on unix or “echo %CLASSPATH%” on windows and you should see a long classpath.

Once you have set up the environment, execute the changeAppLogLevel.py script that is included in the /scripts directory of the code ZIP:

java -classpath $CLASSPATH  $JAVA_OPTIONS  weblogic.WLST changeAppLogLevel.py

You should see the following output:

$ java -classpath $CLASSPATH  $JAVA_OPTIONS  weblogic.WLST changeAppLogLevel.py

Initializing WebLogic Scripting Tool (WLST) ...

Welcome to WebLogic Server Administration Scripting Shell

Type help() for help on available commands

==>Insufficient arguments
==>Syntax: changeAppLogLevel.py [APP NAME] [LOGGER] [LEVEL]
==> where: APP NAME=context root of the app e.g. xxx for /xxx
==>        LOGGER=log4j logger name
==>        LEVEL=TRACE/DEBUG/WARN/INFO/ERROR/FATAL
==>   e.g: changeAppLogLevel.py xxx com.theserverlabs.blog.logging DEBUG

As the instructions indicate, you have to call the script with the name of the app (which is the context root of the application web), the Log4j logger that you wish to modify (normally a Java package name) and the level that you want to set (TRACE/DEBUG/WARN/INFO/ERROR/FATAL).

In the example below, we set the log level to INFO for the package com.theserverlabs.blog.wls in the application “logging”, which is what the example application is called. The output is the following:

java -classpath $CLASSPATH  $JAVA_OPTIONS  weblogic.WLST changeAppLogLevel.py logging com.theserverlabs.blog.wls ERROR 

Initializing WebLogic Scripting Tool (WLST) ...

Welcome to WebLogic Server Administration Scripting Shell

Type help() for help on available commands

Connecting to t3://localhost:7001 with userid weblogic ...
Successfully connected to Admin Server 'AdminServer' that belongs to domain 'log4j'.

Warning: An insecure protocol was used to connect to the 
server. To ensure on-the-wire security, the SSL port or 
Admin port should be used instead.

Location changed to custom tree. This is a writable tree with No root.
For more help, use help(custom)

changing log level to ERROR for app logging on server t3://localhost:7001
  ... done. New log levels are:
{com.theserverlabs.blog.wls=ERROR}


Exiting WebLogic Scripting Tool.

As you can see from the line “New log levels are:{com.theserverlabs.blog.wls=ERROR}”, the log level was changed from the default in the log4j.properties file (DEBUG) to ERROR.

If you go to the logging test page again (http://localhost:7001/logging/test), you should see that there are no longer entries for the DEBUG, INFOR or WARN levels:

[2010-04-21 17:47:09,728] ERROR com.theserverlabs.blog.wls.logging.view.servlet.LoggingTestServlet  - error
[2010-04-21 17:47:09,728] FATAL com.theserverlabs.blog.wls.logging.view.servlet.LoggingTestServlet  - fatal
[2010-04-21 17:47:09,728] ERROR com.theserverlabs.blog.wls.logging.services.ejb.SessionLoggingTestService  - error
[2010-04-21 17:47:09,728] FATAL com.theserverlabs.blog.wls.logging.services.ejb.SessionLoggingTestService  - fatal

So, we can now dynamically change the log level of a logger in our application using an administrator tool (WLST). Pretty cool, huh?

Here I have specified a single logger “com.theserverlabs.blog.wls” which is a high-level logger in my application. You can only pass 1 logger as arguments to the script but there is nothing to stop you from running the same script different times with different loggers e.g. once to set com.theserverlabs.blog.wls.logging.services.ejb to DEBUG to get detailed logging of EJB session beans and another time to set org.hibernate to INFO to get more info on what hibernate is doing.

How do I get this to work in my application?

Simple. Include our JMX-logging JAR in your WEB application and add the following lines to your web.xml file:

	
		com.theserverlabs.jmx.web.JmxServletContextListener
	

At startup time, a JMX Mbean will be registered with the Weblogic JMX subsystem. The Mbean will be registered under a name which includes your application name, meaning there will be one MBean per application deployed on the server.

Once deployed, you can use the WLST script discussed in the previous section to interact with the MBean for your application and thereby change the log level of your application.

OK, how does all this really work?

If you look at the source code for the jmx-logging JAR (included in the source code bundle, you will find a class called com.theserverlabs.jmx.ApplicationLogManager. This class implements the interface ApplicationLogManagerMBean, whose methods are JMX MBean-compatible. It provides methods that allow a caller to set the log level for a given log4j logger:

	public void setLogLevel(String logger, String level) {
		Logger l = Logger.getLogger(logger);
		l.setLevel(Level.toLevel(level));
	}

and to interrogate log4j for the currently-configured loggers and their levels, returning a map of Strings:

	@SuppressWarnings("unchecked")
	public Map getLogLevels() {
		HashMap result = new HashMap();
		Enumeration e = Logger.getRootLogger().getLoggerRepository().getCurrentLoggers();
		while (e.hasMoreElements()) {
			Logger l = e.nextElement();
			if (l.getLevel() != null) {
				result.put(l.getName(), l.getLevel().toString());
			}
		}
		return result;
	}

This MBean can be registered with any JMX system, allowing it’s methods to be invoked via JMX calls. In this case, we really want to register it with the Weblogic JMX system when the application starts up. To accomplish this, we use the class com.theserverlabs.jmx.web.JmxServletContextListener, which is registered in the web.xml of the web application:

	
		com.theserverlabs.jmx.web.JmxServletContextListener
	

A modified version of the source code for JmxServletContextListener is shown below which error-handling and logging removed for clarity. It is pretty clear that when Weblogic starts our application and calls the contextInitialized() method, we register a new instance of ApplicationLogManager with the object name “com.theserverlabs.jmx:type=ApplicationLogManager,name=[NAME OF APPLICATION]LogManager”. This name is generated in the getObjectName() method. When Weblogic stops the web application, it calls the contextDestroyed() method which un-registers the instance of ApplicationLogManager from the JMX MBean server.

public class JmxServletContextListener implements ServletContextListener {

	private InitialContext ctx;
	private MBeanServer server;

	{
	    ctx = new InitialContext();
	    server = MBeanServer.class.cast(ctx.lookup("java:comp/env/jmx/runtime"));
	}

	public void contextInitialized(ServletContextEvent sce) {
		server.registerMBean(new ApplicationLogManager(), getObjectName(sce));
	}

	public void contextDestroyed(ServletContextEvent sce) {
		if (server.isRegistered(getObjectName(sce))) {
		    server.unregisterMBean(getObjectName(sce));
		} 
	}

	private ObjectName getObjectName(ServletContextEvent sce) throws MalformedObjectNameException, NullPointerException { 
		String appName = sce.getServletContext().getContextPath().substring(1);
		return new ObjectName("com.theserverlabs.jmx:type=ApplicationLogManager,name=" + appName + "LogManager");
	}

}

The WLST script

That’s pretty much all there is to it in terms of application code. The only thing left to discuss is the Weblogic Scripting Tool (WLST) script that modifies the log level. Below is the source code (it is Python code):

def changeServerAppLogLevel(app, logger, level, serverUrl):

    ## connect to the server
    connect("weblogic", "weblogic", url=serverUrl)

    ## go to the custom MBean tree 
    custom()

    ## go to the place where our app log level mbeans are stored. 
    cd('com.theserverlabs.jmx/com.theserverlabs.jmx:type=ApplicationLogManager,name=' + app + 'LogManager')

    ## horrible code necessary to invoke a Java method that changes the log level
    args = jarray.array([java.lang.String(logger), java.lang.String(level)],java.lang.Object)
    sig = jarray.array(['java.lang.String', 'java.lang.String'],java.lang.String)
    print 'changing log level to ' + level + ' for app ' + app + ' on server ' + serverUrl
    invoke('setLogLevel',args,sig)

    print '  ... done. New log levels are:'
    print(get('LogLevels'))

# "main method" of the python script
argslength = len(sys.argv)

if argslength < 3 :

    print '==>Insufficient arguments'
    print '==>Syntax: changeAppLogLevel.py [APP NAME] [LOGGER] [LEVEL]'
    print '==> where: APP NAME=context root of the app e.g. xxx for /xxx'
    print '==>        LOGGER=log4j logger name'
    print '==>        LEVEL=TRACE/DEBUG/WARN/INFO/ERROR/FATAL'
    print '==>   e.g: changeAppLogLevel.py xxx com.theserverlabs.blog.logging DEBUG'
    exit()

else:

    app = sys.argv[1]
    logger = sys.argv[2]
    level = sys.argv[3]

    # change the log level for the server. if there was more than one server
    # in the cluster, you could add multiple calls here, each with a different 
    # server URL
    changeServerAppLogLevel(app, logger, level, 't3://localhost:7001')
    
    exit()

Hopefully the majority of this code will be clear, even if you don’t understand python. The method/function changeServerAppLogLevel() declared at the start modifies the log level for a defined logger in an application running on a specific Weblogic server. To do this it:

  • Connects to the Weblogic server at the specified URL (note that this example uses the hardcoded username and password weblogic/weblogic
  • Moves to the custom JMX MBean tree which is where Weblogic puts all non-Weblogic MBeans
  • Moves to the place where our MBean is stored in the tree
  • Executes the setLogLevel() method of the MBean with the required arguments to change the log level. This translates to an invocation of the ApplicationLogManager.setLogLevel() method.
  • Lists the new log levels

In the “main” method of the script (i.e. everything that is not in a method/function), there is some basic code to make sure the script is properly invoked and, if it is, a call to changeServerAppLogLevel() with the supplied arguments and the hard-coded URL of ‘t3://localhost:7001’. Obviously you should modify this value to reflect your Weblogic environment.

One interesting aspect of using a script to do this is that you can include a call to changeServerAppLogLevel() for each server in your cluster, if you have a multi-node setup. MBeans are published at server level so there is no concept of publishing a cluster-wide MBean (so far as I know anyway).

An interesting extension of this script would be to interrogate a Weblogic Admin server to find all the nodes in the cluster that were up and then execute the code to change the log level against each available node.

Conclusion

Hopefully this article has cleared up any confusion as to how to perform logging with log4j in a JEE app deployed on Weblogic. I think that the ability to modify dynamically the log level for a given log4j logger without having to redeploy the application is extremely useful and hopefully will be of use to people looking to do a similar thing either with Weblogic or any other JEE server that supports JMX.