Why log?

Good developers know the importance of careful design, testing, and debugging, and Eclipse helps with all these tasks, but what about logging? Many developers believe that logging is integral to good software development practices; you'll no doubt agree if you've ever had to fix a problem in someone else's already deployed application. Fortunately, the impact of log statements on performance is minimal or nonexistent for most cases, and because the logging tools are easy to use, the learning curve is very small. So, with the excellent tools available, there is no excuse for not including log statements in your applications.

Back to top

Tools at your disposal

If you are writing an Eclipse plug-in, you can use the services provided by org.eclipse.core.runtime.ILog that is accessed through the method getLog() from your Plugin class. Just create an instance of org.eclipse.core.runtime.Status with the right information and call the log() method on ILog.

This log object accepts more than one log listener instance. Eclipse adds two listeners:

• A Listener that writes logs to the "Error Log" View
• A Listener that writes logs to the log file located at “${workspace}/.metadata/.log"

You can also create your own log listener. Just implement the interface org.eclipse.core.runtime.ILogListener and add it to the log object through the method addLogListener(). The logging() method in your class will be called for each log event.

All this is very nice, but there are some problems with this approach. What if you want to change the log destination of an already deployed plug-in? Or control the amount of information logged? Also, this implementation may impact performance as it always sends log events to all listeners. That is why you might normally see logs only in extreme cases, like error conditions.

On the other hand, there are two great tools specialized just for logging. One comes with Java 2 SDK 1.4 in the java.util.logging package. The other is from Apache, called Log4j.

Both have the concept of a hierarchy of Logger objects that can send log events to any number of Handlers (called Appenders in Log4j), which delegate the message formatting to Formatters (called Layouts in Log4j). Both can be configured by property files. Log4j also uses xml files for configuration.

A logger can have a name and be associated to a Level. A logger can inherit its settings (levels, handlers) from its parent. A logger named "org" is automatically the parent of another, named "org.eclipse", so whatever you set for "org" in the configuration file can be inherited by the "org.eclipse" logger.

My preference? I have used both, and I have a special preference for Log4j. I use java.util.logging only if I have a very simple application and I don't want to add the log4j.jar to it. For full explanations of both, please refer to the Java docs and Apache site (see Resources for links).

Back to top

An improved log

Wouldn't it be great if there was a way to improve the Eclipse log experience? The two main problems with it are:

• Lack of an external configuration file
• Performance issues associated with the fact that there is no fine grained control of its behavior

Given this challenge, I started thinking about ways to integrate logging tools into Eclipse. My first candidate was java.util.logging, simply because it is already in the JSDK1.4 distribution.

I wanted to allow a plug-in writer to be able to customize logging through a configuration file and have the log event go to any handler already available. I planned to create two additional handlers: one that would send the log event to the "Error Log" view and another that would write it to the Plug-in state location: “${workspace}/.metadata/.plugins/${plugin.name}".

All this would be contained in a Plug-in Log Manager. You would just add it to your plug-in dependencies and get the logger objects from it.

From my experience, however, I would not recommend using java.util.logging for this. Its implementation goes to great lengths to keep only one single LogManager instance. It uses the system class loader to achieve this. Thus you have only one hierarchy of loggers for all users. You lose isolation. So, if more than one application is using loggers, they will share settings, and one application’s logger instance can potentially inherit settings from another application’s logger.

So, why not extend the LogManager and instantiate one yourself? The problem with this approach is that the LogManager instance uses the system class loader to instantiate classes from the configuration file. One of the strengths of plug-ins is to provide isolation through the usage of different class loaders. If you need isolation for your log manager, java.util.logging would not be suitable due to architectural limitations.

On the other hand, Log4j has proved to be very useful. Its hierarchy of loggers is kept in an object called, believe it or not, Hierarchy. So, you can create one hierarchy per plug-in. Problem solved. You can also create a custom appender (handler) to send events to the "Error Log" view and another to send it to the plug-in state location. Life is good.

Let’s review how to do this, starting from the plug-in writer's point of view. Just create your plug-in, add com.tools.logging to its dependency list, and create a Log4j configuration file. Instantiate a PluginLogManager and configure it with this file. This should be done only once, so you can do it when the plug-in starts. For the log statements, just use them as you would do with Log4j. Listing 1 shows you an example:

private static final String LOG_PROPERTIES_FILE = "logger.properties";

public void start(BundleContext context) throws Exception {
   super.start(context);
   configure();
}

private void configure() {
   try {
      URL url = getBundle().getEntry("/" + LOG_PROPERTIES_FILE);
      InputStream propertiesInputStream = url.openStream();
      if (propertiesInputStream != null) {
         Properties props = new Properties();
         props.load(propertiesInputStream);
         propertiesInputStream.close();
         this.logManager = new PluginLogManager(this, props);
         this.logManager.hookPlugin(
          TestPlugin.getDefault().getBundle().getSymbolicName(),
          TestPlugin.getDefault().getLog()); 
      }	
   } 
   catch (Exception e) {
      String message = "Error while initializing log properties." +
                       e.getMessage();
      IStatus status = new Status(IStatus.ERROR,
      getDefault().getBundle().getSymbolicName(),
      IStatus.ERROR, message, e);
      getLog().log(status);
      throw new RuntimeException(
           "Error while initializing log properties.",e);
   }         
}

Deploy the plug-in and anyone at any time can change its log configuration file and filter logging or change its output without touching one single line of your code. Even better, if the log is disabled, all those statements will not impact performance, since performance has been one of the major design considerations for Log4j. So you can sprinkle logger methods anywhere you find it necessary.

Back to top

How it was done

So much for usage; let’s look now at its implementation in com.tools.logging.

First, the class PluginLogManager. There is one log manager for each plug-in. It contains a hierarchy object plus data necessary for the custom appenders as shown in Listing 2. It doesn't derive directly from the Hierarchy class in order not to expose it to the end user. This provides more freedom with the implementation. The constructor creates a hierarchy object with the default level DEBUG and then configures it using the provided properties. It would also have been easy to allow xml properties; it would only be necessary to add a dependency to the Xerces plug-in and use the DOMConfigurator instead of PropertyConfigurator. This is left as an exercise for the reader.

public PluginLogManager(Plugin plugin,Properties properties) {
   this.log = plugin.getLog();  
   this.stateLocation = plugin.getStateLocation(); 
   this.hierarchy = new Hierarchy(new RootCategory(Level.DEBUG));
   this.hierarchy.addHierarchyEventListener(new PluginEventListener());
   new PropertyConfigurator().doConfigure(properties,this.hierarchy);	
   LoggingPlugin.getDefault().addLogManager(this); 
}

Notice how there is a PluginLogManager inner class that implements org.apache.log4j.spi.HierarchyEventListener. This is a solution to pass the necessary information to the custom appenders. The method addAppenderEvent() gets called when an appender is instantiated and fully configured, ready to append, as shown in Listing 3:

private class PluginEventListener implements HierarchyEventListener {
		
   public void addAppenderEvent(Category cat, Appender appender) {
      if (appender instanceof PluginLogAppender) {
         ((PluginLogAppender)appender).setLog(log);
      }			
      if (appender instanceof PluginFileAppender) {
         ((PluginFileAppender)appender).setStateLocation(stateLocation);
      }
   }
	
   public void removeAppenderEvent(Category cat, Appender appender) {
   }
}

To better understand the lifecycle of an appender and some of the decisions, a UML Sequence Diagram may help. Figure 1 shows the trickiest one, the sequence of events that lead to the creation and configuration of a PluginFileAppender instance.

For that appender, org.apache.log4j.RollingFileAppender is extended. This not only allows you to get file manipulation for free, but also provides nice additions like maximum file size limitation and the ability to automatically cascade log writing to another file once the maximum size is reached.

By choosing to extend the RollingFileAppender, you have to contend with its behavior as well. Once Log4j creates an appender, it initializes its properties from the configuration file by calling "setter" methods and then calls activateOptions() to let the append finish any outstanding initialization. When this happens, the RollingFileAppender instance will call setFile(), which will open the log file and have it ready for writing. Only then will Log4j notify the PluginEventListener instance.

Obviously, you cannot let the file be opened before you have the opportunity to set the state location. So when activateOptions() is called and, if there is no state information yet, it is flagged as pending and when the state location is finally set, it is called again and the appender is ready for business.

The other appender, PluginLogAppender, has the same lifecycle, but, since it doesn't extend an existing appender, you don't have to worry about initialization problems. An appender won't start working before the addAppenderEvent method is called. The Log4j documentation provides ample discussion on writing your own custom appender. Listing 4 shows its append method.

public void append(LoggingEvent event) {
		
   if (this.layout == null) {
      this.errorHandler.error("Missing layout for appender " +
             this.name,null,ErrorCode.MISSING_LAYOUT); 
      return;
   }

   String text = this.layout.format(event);

   Throwable thrown = null;
   if (this.layout.ignoresThrowable()) {
      ThrowableInformation info = event.getThrowableInformation();
      if (info != null)
         thrown = info.getThrowable(); 
   }
		
   Level level = event.getLevel();
   int severity = Status.OK;

   if (level.toInt() >= Level.ERROR_INT) 
      severity = Status.ERROR;
   else
   if (level.toInt() >= Level.WARN_INT)
      severity = Status.WARNING;
   else
   if (level.toInt() >= Level.DEBUG_INT) 
      severity = Status.INFO;
	
   this.pluginLog.log(new Status(severity,
             this.pluginLog.getBundle().getSymbolicName(),
             level.toInt(),text,thrown));
}

The LoggingPlugin class maintains a list of PluginLogManagers. This is needed so that when the plug-in stops, it will be possible to shut down all the hierarchies and allow the appenders and loggers to be correctly removed as you can see in Listing 5.

private ArrayList logManagers = new ArrayList(); 

public void stop(BundleContext context) throws Exception {
   synchronized (this.logManagers) {
      Iterator it = this.logManagers.iterator();
      while (it.hasNext()) {
         PluginLogManager logManager = (PluginLogManager) it.next();
         logManager.internalShutdown(); 
      }
     this.logManagers.clear(); 
   }
   super.stop(context);
}

void addLogManager(PluginLogManager logManager) {
   synchronized (this.logManagers) {
      if (logManager != null)
         this.logManagers.add(logManager); 
   }
}
	
void removeLogManager(PluginLogManager logManager) {
   synchronized (this.logManagers) {
      if (logManager != null)
         this.logManagers.remove(logManager); 
   }
}

One more thing was added to the PluginLogManager class. Sometimes plug-ins that you depend on, especially those that depend on the workbench, may throw exceptions. Those exceptions are usually logged by Eclipse. It would be useful to allow a dependent plug-in to be hooked into the log framework. When an exception arises, any of its Eclipse logging will be funneled to the log framework and share its configuration with the other loggers. This is very useful, as you can concentrate everything in one single location and have a history of facts that will allow you to fix your application.

This can be achieved by implementing org.eclipse.core.runtime.ILogListener and adding it to the dependent plug-in ILog instance. Basically, you are just hooking it into the Eclipse logging. This implementation then redirects all the requests to a Logger created with the name you chose, usually the plug-in identifier. You can then configure its output through the same property file; you only need to specify the Logger name and filter it, add appenders, etc. The class is shown in Listing 6:

class PluginLogListener implements ILogListener {

   private ILog log;
   private Logger logger;

   PluginLogListener(ILog log,Logger logger) {
      this.log = log;
      this.logger = logger;
      log.addLogListener(this);
   }

   void dispose() {
      if (this.log != null) {
         this.log.removeLogListener(this);
         this.log = null;
         this.logger = null;
      } 
   }

   public void logging(IStatus status, String plugin) {
      if (null == this.logger || null == status) 
         return;
	
      int severity = status.getSeverity();
      Level level = Level.DEBUG;  
      if (severity == Status.ERROR)
         level = Level.ERROR;
      else
      if (severity == Status.WARNING)
         level = Level.WARN;
      else
      if (severity == Status.INFO)
         level = Level.INFO;
      else
      if (severity == Status.CANCEL)
         level = Level.FATAL;

      plugin = formatText(plugin);
      String statusPlugin = formatText(status.getPlugin());
      String statusMessage = formatText(status.getMessage());
      StringBuffer message = new StringBuffer();
      if (plugin != null) {
         message.append(plugin);
         message.append(" - ");
      }    
      if (statusPlugin != null && 
           (plugin == null || !statusPlugin.equals(plugin))) {
         message.append(statusPlugin);
         message.append(" - ");
      }	
      message.append(status.getCode());
      if (statusMessage != null) {
         message.append(" - ");
         message.append(statusMessage);
      } 		
      this.logger.log(level,message.toString(),status.getException());	
   }
   
   static private String formatText(String text) {
      if (text != null) {
         text = text.trim();
         if (text.length() == 0) return null;
      } 
      return text;
   }
}

The whole framework is implemented in a plug-in project called com.tools.logging. In order to show it working, I created two plug-ins:

1. HelloPlugin is built from one of the project templates and shows a message box with the words "Hello, Eclipse world".
2. TestPluginLog is added as a dependency of HelloPlugin, so it can be hooked into the same log hierarchy. It has a method called dummyCall() that adds a dummy message using the Eclipse API, which then gets redirected to HelloPlugin's log.

Any other plug-in dependency could have been hooked as well, like org.eclipse.ui or org.eclipse.core.runtime.

I was careful when creating the logger.properties configuration file in order to show some of its strengths. As you can see in Listing 7, there are two appenders defined: The appender A1 is a PluginFileAppender and assigned to the root logger. All the other loggers can inherit from the root and use this appender. Thus, all the logs, including the one from TestPluginLog, go to a file under the plug-in state location.

log4j.rootCategory=, A1

# A1 is set to be a PluginFileAppender

log4j.appender.A1=com.tools.logging.PluginFileAppender
log4j.appender.A1.File=helloplugin.log
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%p %t %c - %m%n

# A2 is set to be a PluginLogAppender

log4j.appender.A2=com.tools.logging.PluginLogAppender
log4j.appender.A2.layout=org.apache.log4j.PatternLayout
log4j.appender.A2.layout.ConversionPattern=%p %t %c - %m%n

# add appender A2 to helloplugin level only

log4j.logger.helloplugin=, A2

The other appender, A2, is a PluginLogAppender and only added to the logger "helloplugin", so TestPluginLog won't use it. Otherwise, there would be two entries in the "Error View" window for "TestPluginLog": one from Eclipse and one from com.tools.logging. You can experiment with it and see what I mean. Just add A2 to the log4j.rootCategory and remove the line with log4j.logger.helloplugin altogether.

Listing 8 shows the contents of ${workspace}/.metadata/.plugins/HelloPlugin/helloplugin.log after the "sample menu" item is clicked and the message box appears. Notice how the TestPluginLog Eclipse log was written in the last line. By combining your logs and the dependent plug-ins Eclipse log in one single output, you can preserve the sequence of events.

INFO main helloplugin.actions.SampleAction - starting constructor.
INFO main helloplugin.actions.SampleAction - ending constructor.
WARN main helloplugin.actions.SampleAction - init
WARN main helloplugin.actions.SampleAction - run method
WARN main TestPluginLog - TestPluginLog - 0 - Logging using the Eclipse API.

Back to top

Summary

You have seen two approaches to improve Eclipse logging. One approach is to use com.tools.logging in your plug-in so you can have all the nice features of Log4j and still be part of the Eclipse log framework if you desire. The other approach is to hook a plug-in that does not have any knowledge of Log4j whatsoever and be able to configure its log output even though it only uses the Eclipse log API.

Actually, you don't even need to have com.tools.logging. At this point you could extract the sample code and add it to your own plug-in, possibly as a separate jar file. Just don't forget the Log4j jar file, of course.

The plug-ins were created with the new OSGI manifest. All the code was developed and tested using Eclipse 3.0 Release Candidate 1, Sun Java 2 SDK 1.4.2, and Log4j version 1.2.8. I didn't include the file log4j-1.2.8.jar in the code available for download. If you download the code, you should get this jar file from Apache Log4j and include it in the com.tools.logging project and in the com.tools.logging_1.0.0 plug-in directory.

Back to top

Downloads

Information about download methods

Resources

• Find plug-in documentation, source code, and latest Eclipse builds at the eclipse.org site.
  
  
• Get the Java runtime plus documentation for java.util.logging at the Sun Java 2 SDK 1.4.2 site.
  
  
• Find everything you need about Log4j at Apache's Log4j Logging Services site.
  
  
• Find more articles for Eclipse users in the Open source projects zone on developerWorks. Also see the latest Eclipse technology downloads on alphaWorks.
  
  
• Browse for books on these and other technical topics.
  
  
• Develop and test your applications using the latest IBM tools and middleware with a developerWorks Subscription: you get IBM software from WebSphere®, such as the Eclipse-based WebSphere Studio Application Developer for Linux and WebSphere Studio Application Developer for Windows, as well as DB2®, Lotus®, Rational®, and Tivoli®, and a license to use the software for 12 months, all for less money than you might think.
  
  

About the author

Manoel Marques has been a software developer and technology consultant for over 15 years and has worked on a wide variety of projects from business to research, in Brazil and the United States. He holds a Master of Science degree in Computer Science from Pontificia Universidade Catolica in Rio de Janeiro, Brazil. You can contact Manoel at manoel@themsslink.com.

Comments (Undergoing maintenance)

Back to top

Trademarks  |  My developerWorks terms and conditions

Table of contents

• Why log?
• Tools at your disposal
• An improved log
• How it was done
• Summary
• Downloads
• Resources
• About the author
• Comments

Local resources

• IBM Innovation Center - Austin, TX
• IBM Innovation Center - Chicago, IL
• IBM Innovation Center - Dallas, TX
• IBM Innovation Center - San Mateo, CA
• IBM Innovation Center - Waltham, MA
• Technical Briefings in North America

My developerWorks community

Dig deeper into Open source on developerWorks

Rate a product. Write a review.

Write a review for Rational products today!

Special offers