Last week I had to debug an Eclipse plugin of one of my clients. The plugin was already instrumented by a few simple tracing output statements here and there, as we know them all:

System.out.println("Entering fooBar()");

Because time was pressing, I followed this example during the debugging process. Afterwards, however, I had some time to refactor the code and I wanted to use the standard Eclipse tracing facility.

I had last used Eclipse tracing a few years ago. Back then, Eclipse tracing was done as described in the Eclipse FAQ by creating a .options file, putting the desired debug and trace options in there, and reading and storing the debug options in fields when the plugin was activated:

public static boolean DEBUG = false;
public static boolean TRACE = false;
 
public void start(BundleContext bundleContext) throws Exception {
	DEBUG = isDebugging();
	TRACE = Boolean.valueOf(Platform.getDebugOption(PLUGIN_ID + "/trace")).
}

In your code, you would then check for the value of TRACE and if the flag is enabled, you print out the message using println as above.

But the API has changed in two ways since then.

First, OSGi services became popular. In most current Eclipse Plugins, you can see the use of a ServiceTracker which is used to access the debug settings (actually, even Plugin.isDebugging() now uses this style internally to be backwards compatible):

public void start(BundleContext bundleContext) throws Exception {
	// ... (do other initialization work) 
	debugTracker = new ServiceTracker<DebugOptions,DebugOptions>(bundleContext, DebugOptions.class.getName(), null);
	debugTracker.open();
}
 
public boolean isTracingEnabled() {
	DebugOptions service = debugTracker.getService();
	String option = service.getOption(PLUGIN_ID + "/trace");
	return option == null ? false : Boolean.valueOf(option).booleanValue();
}
 

The ServiceTracker theoretically makes it possible to dynamically change the service (and thus, the values of the debug flags). Therefore, in the above code, every tracing statement would have to check the current status via a call to isTracingEnabled(). The disadvantage is obvious: getting the service from the tracker and querying the option each and every time leads to a bad performance. This is why most users of this style retrieve the debug options just once and cache them as before. 

This is where the second change comes into play. I quickly found out that there is a new (actually it was new in Eclipse 3.5!) interface org.eclipse.osgi.service.debug.DebugTrace which does very nice things like checking the debug options directly and enriching the trace messages with method and line information. But I did not, at first, find a lot of documentation on how to use this new interface and its implementation.  Then I had the idea of searching through the Eclipse Bugzilla and I found the originating contribution in Bug 258705 which again pointed me to the JavaDoc of the class DebugOptionsListener which includes the example code snippet I was looking for.

What you do with the new API (in contrast to the approach above) is, instead of consuming a service, you implement and announce a service yourself which listenes for debug option changes. You can then reflect the changed options in your cached debug flags. Using this API is really easy. Just let your plugin activator class implement DebugOptionsListener and implement start() as follows: 

public void start(BundleContext context) throws Exception {
	super.start(context);
 
	Dictionary<String, String> props = new Hashtable<String,String>(4);
	props.put(DebugOptions.LISTENER_SYMBOLICNAME, PLUGIN_ID);
 	context.registerService(DebugOptionsListener.class.getName(), this, props);
 
	plugin = this;
}

Next, you implement the event callback:

// fields to cache the debug flags
public static boolean DEBUG = false;
public static DebugTrace TRACE = null;
 
public void optionsChanged(DebugOptions options) {
	DEBUG = options.getBooleanOption(PLUGIN_ID + "/debug", false);
	TRACE = options.newDebugTrace(PLUGIN_ID);
}
 

The optionsChanged() callback is called by the framework once the service is registered. Therefore, you do not need to perform any additional initialization. It is done by that first call automatically.

As you can see, the second call in optionsChanged() creates a DebugTrace instance. This can now be used to conveniently log quite verbose tracing messages. To test it, I have created a plugin with the Hello World command template and instrumented the handler as follows:

public Object execute(ExecutionEvent event) throws ExecutionException {
	if(MyPlugin.DEBUG) {
		MyPlugin.TRACE.traceEntry("/trace", event.getCommand());
	}
 
	IWorkbenchWindow window = HandlerUtil.getActiveWorkbenchWindowChecked(event);
 
	if(MyPlugin.DEBUG) {
		MyPlugin.TRACE.trace("/trace", "This is a test trace");
	}
 
	MessageDialog.openInformation(window.getShell(), "Tracing", "Hello, Eclipse world");
 
	if(MyPlugin.DEBUG) {
		MyPlugin.TRACE.traceExit("/trace");
	}
 
	return null;
}

There are even direct calls for method entry (with parameters) and exit (with result value). (Note however, that I had to use event.getCommand() instead of event directly, because event.toString() produces a string which is not parseable by the message formatter, because it uses curly braces ...).

The trace messages go to a file named trace.log which is located next to the platform log file. For the code above, it contains

# !SESSION 2011-08-14 17:57:20.857
# version: 1.1
# verbose: true
# The following option strings are specified for this debug session:
# 	net.winklerweb.test.tracing/trace=true
# 	net.winklerweb.test.tracing/debug=true
| Thread-1 | 2011-08-14 17:57:20.857 | net.winklerweb.test.tracing | /trace | net.winklerweb.test.tracing.handlers.SampleHandler | execute | 30 | Entering method with parameters: (Command(net.winklerweb.test.tracing.commands.sampleCommand,Sample Command,
		,
		Category(net.winklerweb.test.tracing.commands.category,Sample Category,null,true),
		net.winklerweb.test.tracing.handlers.SampleHandler@7647b3ee,
		,,true)) |
| Thread-1 | 2011-08-14 17:57:20.860 | net.winklerweb.test.tracing | /trace | net.winklerweb.test.tracing.handlers.SampleHandler | execute | 36 | This is a test trace |
| Thread-1 | 2011-08-14 17:57:26.788 | net.winklerweb.test.tracing | /trace | net.winklerweb.test.tracing.handlers.SampleHandler | execute | 45 | Exiting method with a void return |

As you can see, it logs the thread, a timestamp, the plugin ID, the option ("/trace"), the class, method and line number in which the trace message originated and the message itself.

I really like the way I now can produce very verbose tracing messages with very few lines of code. 

Additionally, it is possible to turn on and off single tracing options dynamically at runtime. There is even a contribution for a runtime preference sheet which can be used to do this in Bug 296631. Sadly, it is currently not explicitly scheduled for inclusion. But if you like the idea as much as I do, please follow my example and vote for that bug.