Bug 258705 - Implement tracing api
Summary: Implement tracing api
Status: RESOLVED FIXED
Alias: None
Product: Equinox
Classification: Eclipse Project
Component: Framework (show other bugs)
Version: 3.5   Edit
Hardware: PC Windows XP
: P3 enhancement (vote)
Target Milestone: 3.5 M6   Edit
Assignee: John Arthorne CLA
QA Contact:
URL:
Whiteboard:
Keywords:
: 139752 162347 (view as bug list)
Depends on:
Blocks:
 
Reported: 2008-12-12 17:04 EST by Christophe Elek CLA
Modified: 2011-05-06 14:34 EDT (History)
13 users (show)

See Also:


Attachments
sample trace API (7.54 KB, text/plain)
2009-01-21 10:10 EST, Troy Bishop CLA
no flags Details
initial submission for discussing any comments/concerns (80.06 KB, patch)
2009-02-25 16:34 EST, Troy Bishop CLA
no flags Details | Diff
Example resulting trace file (151.20 KB, text/plain)
2009-02-25 16:35 EST, Troy Bishop CLA
no flags Details
Updated patch (62.89 KB, patch)
2009-03-04 14:55 EST, John Arthorne CLA
no flags Details | Diff
Updated patch - fixes a few bugs and includes John's modifications (71.46 KB, patch)
2009-03-04 20:48 EST, Troy Bishop CLA
no flags Details | Diff
Updated patch - fixes a few bugs and includes John's modifications (72.07 KB, patch)
2009-03-04 23:42 EST, Troy Bishop CLA
tjwatson: iplog+
Details | Diff
Updated patch (65.94 KB, patch)
2009-03-05 15:28 EST, Thomas Watson CLA
no flags Details | Diff
some listener suggestions (74.27 KB, application/octet-stream)
2009-03-05 17:07 EST, Troy Bishop CLA
no flags Details
Updated patch (67.39 KB, patch)
2009-03-05 18:17 EST, John Arthorne CLA
no flags Details | Diff
Updated patch (84.73 KB, patch)
2009-03-05 22:49 EST, Thomas Watson CLA
no flags Details | Diff
Updated patch (94.70 KB, patch)
2009-03-06 00:17 EST, Thomas Watson CLA
no flags Details | Diff
Implementation changes (70.47 KB, patch)
2009-03-06 10:35 EST, John Arthorne CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Christophe Elek CLA 2008-12-12 17:04:20 EST
We wanted to contribute some simple tracing API to the eclipse platform.
I know we have other framework like Log4j and JUL and other OSGI spec.
I just wanted to open the discussion here and have us deliver some code that would benefit everybody.

The reason for the API is that , some of our product need to have dynamic change in the trace , where right now , plugins seem to setup the static boolean at load time and never refresh.
The other reason was to have some API so we can implement some flight recorder and other even management for embedded system.
We wanted to set the API deep in core so all plugins would use them and we wanted to be compliant with the existing .options code...

I am attaching a very rough draft of our thoughts and also some answer I got from John A (which are very good)
Comment 1 Christophe Elek CLA 2008-12-12 17:07:09 EST
Goal
Provide a set of tracing API for developer
Allow easy and simple code migration from current coding practices
Support current .options
Allow dynamic change of tracing options while the platform is running
Allow for future extensions (different trace file, different formatter, flight recorder, event framework)

Coding
- Developers create instances of logger based on a String in their plugin class
	ITrace myWorkingSetTrace = FrameworkTrace.createTrace("org.eclipse.help.webapp/debug/workingsets");

-Developers send a trace String to the trace object
	myPlugin.myWorkingSetTrace.trace("Entering the method getObject, parameter +"+item);
	
- If a complex manipulation has to be done before tracing , developers can use
	if (myWorkingSetTrace.isDebug()){
	    myPlugin.myWorkingSetTrace.trace("Entering the method getObject, parameter +"+item.getUUIDFromDatabase());
	}	
	
How do we solve the goals?
1) Provide a set of tracing API for developer
	The simplest API is one line of coding. 
	
2) Allow easy and simple code migration from current coding practices
	Replacing the current code is trivial as it follows the same pattern

current code
	boolean DEBUG_WORKINGSET = getOptions("org.eclipse.help.webapp/debug/workingsets")==true;
	if (DEBUG_WORKINGSET)
		System.out.println("a String"):

new code
	ITrace DEBUG_WORKINGSET = FrameworkTrace.createTrace("org.eclipse.help.webapp/debug/workingsets");
	if (DEBUG_WORKINGSET.isDebug()){
	    DEBUG_WORKINGSET.trace("a String");
	}	
	
3) Support current .options
	Current .options String are preserved
	
4) Allow dynamic change of tracing options while the platform is running
	The creation of the Trace object registers the String with a listener of the instance
	When the string is changed, an event is sent to the factory
	The factory notifies the listeners and the instance refreshes itself
	Question: We need to have a method to remove the instance right ?
	
5) Allow for future extensions (different trace file, different formatter)
	We will follow the log4j and other practices as well as the ILog practices when it comes to 
	extension points and OSGI registration.

*********

From John


Although the migration is not complex, this would require everyone to rewrite all of their tracing instrumentation to use the new API. I'm wondering if the current DebugOptions can't be used as the basis for this work without reinventing the wheel. I.e., what is fundamentally different between ITrace and DebugOptions?  From experience developers are very reluctant to move to a new API if there is an existing API that is good enough for them, so you might get more buy-in from evolving the old API. If a DebugOptions#print(String) method was added, plus a notification mechanism to allow clients to be updated when options change, would that satisfy the requirements? There is nothing tying the DebugOptions API to the .options file back-end, so there is already the possibility today of providing a different implementation of the DebugOptions service with an alternate implementation.

There are cases (such as class-loader tracing) where even an extra method call would cause unacceptable overhead. I think this could be addressed using a callback for changed options like this:

private static boolean DEBUG = debugOptions.getBooleanOption("org.eclipse.osgi/debug/loader", false);

debugOptions.addListener(new DebugOptionListener() {
   public void optionsChanged() {
      DEBUG = debugOptions.getBooleanOption("org.eclipse.osgi/debug/loader", false);
   }
});

In the instrumented code:

if (DEBUG)
   debugOptions.print("loading class " + clazz);

This way there is still only a field reference to determine if the tracing output should be created, but it allows the value to be changed at runtime. How does this sound?

John
  

Comment 2 Christophe Elek CLA 2009-01-05 12:04:11 EST
Just a thought, so we do not forget it :)

We should enable the 'tree' tracing options

so if I have the following 2 options of tracing

org.eclipse.osgi/debug/loader
org.eclipse.osgi/debug/loader/details

and if I setup the debug to org.eclipse.osgi/debug/*=true
then both loader and loader/details will be 'on'

... or is it a different RFE/feature request ?

Comment 3 Troy Bishop CLA 2009-01-21 10:10:23 EST
John,

Thanks for the feedback you had provided earlier to Christophe.  The main purpose of this request is so that there is a standardized way for a product to be able to provide tracing messages so that each message is written in a consistent way allowing it to be easily read back in using a UI tool.  Right now, most plug-ins do something like:

if(DEBUG) {
  System.out.println("<timestamp> tracing message");
}

However this tracing is not ideal because:
  1) Everyones timestamp value could be in a different foramat (if there is one at all)
  2) It doesn't provide the thread that is invoking this code (i.e. thread name or thread id)
  3) We may or may not know the name of the class + method + line number that caused this message to be written
  4) all of the information above may not be in the same order meaning parsing it will be difficult

Attached is an example of what we were thinking of adding as ITrace (implementation can come later) but could easily be added to DebugOptions instead (which is a good suggestion).  The original thought was that the tracing framework could take the option-path as a parameter and let it handle whether or not the trace message should be written. This would mean you would have code like the following:

public class AClass {
   public MyObject readFileToMyObject(String fileName) {
      debugOptions.traceEntry("/trace-option/finest", fileName); // value: "Entering method A.readFileToMyObject() with parmeters: fileNameValue"
      // logic to open and read a file
      File f = new File(fileName);
      debugOptions.trace("/trace-option/normal", "file being read: " + f.getAbsolutePath()); // value: "file being read <value>"
      MyObject m = null;
      if(f.exists()) {
         m = <read file>
      }
      debugOptions.traceExit("/trace-option/finest", result); // value: "Exiting method A.readFileToMyObject() with result: <toString value of MyObject>"
      return m;
   }
}

where DebugOptions.trace(optionPath, message) would basically do:

String value = debugOptions.getOption("com.test.sample" + optionPath);
if((value != null)  && value.equalsIgnoreCase("true")) {
  // handle writing the trace message
}

but with this API any trace call would require a method invocation + evaluation into whether or not tracing is enabled for the specified option-path which, as you stated, may not be ideal due to the extra overhead.  I like your idea of using a listener for each plug-in to react to dynamic enablement of the tracing - that works very well.  What we were thinking from a UI perspective is something similar to the PDE launcher 'Tracing' tab where it shows all available plug-ins and trace options for the product - but take this and put it in the workspace preferences (i.e. introduce a new page under General > Tracing).  This would allow a product support person to tell their client to go to Window > General > Tracing and enable check the option for '/trace-option' under the plug-in 'com.test.sample'.  The plug-ins that are selected in this UI would then react via their listener and set their corresponding static DEBUG flag to true, allowing their functionality to output trace strings to a file without the need of restarting the product.  Along with this, do you see any concern with introducing a new file (i.e. ./metadata/.trace) where this output would be written, rather than using standard output/error?
Comment 4 Troy Bishop CLA 2009-01-21 10:10:57 EST
Created attachment 123241 [details]
sample trace API
Comment 5 Christophe Elek CLA 2009-01-23 11:06:10 EST
Hey John, The RFE is targeted for 4.0
If we provide a patch (and we all agree on it) which does not disturb the current behavior.
Could we have it in 3.5 so our products can start implementing it ?

So then we have the api in 3.5, but we move the eclipse code on it only in 4.0 ?
Or is it too late or too risky at this point in time ?

Thanks :)
Comment 6 John Arthorne CLA 2009-01-27 16:15:52 EST
Some questions:

Q1) What is the value of all the traceAttribute(...) methods? This seems to add a lot of bulk to the API so I'm wondering what this gets you. I.e., currently people do things like:

 println("The object is" + object.toString());

which I suppose in your API would become:

 traceAttribute(object, "the object")

What does that change gain for you as far as traceability?

Q2) Do the traceEntry() and traceExit() methods work by using reflection to determine the name of the calling method, or does someone have to create a new "trace" object instance for each method?
Comment 7 Troy Bishop CLA 2009-01-29 09:30:39 EST
Q1) These were added more for completeness.  You're correct in that there isn't any major value as most people will likely do what you said,

trace("the value of 'my attribute' is: " + myAttribute);

However I wanted to make sure everything was covered by the API for tracing any possible artifact (i.e. methods, exceptions, objects, primitive types, etc).  If you feel that they're not needed then I really don't mind excluding these trace methods (it was a last minute thought).

Q2) Right now, the method information is retrieved via:

StackTraceElement[] stackElements = Thread.currentThread().getStackTrace();

and then it iterates over the stack elements to find the method that made the call to traceEntry/traceExit.  I haven't spent a lot of time on this but it finds the caller by iterating over the entries and skips any stack entries that belong to a set of predefined package names.
Comment 8 John Arthorne CLA 2009-02-02 14:03:28 EST
Ok, overall it looks good. My inclination would be to omit the traceAttribute(..) methods since they add a fair amount of complexity to the API with no apparent gain. They can always be added in the future if needed, but if we add them now we are stuck with them. The traceEntry/traceExit methods are a useful addition. The only remaining piece is the listener API so that clients can update their boolean DEBUG_* fields when trace options change.
Comment 9 Troy Bishop CLA 2009-02-25 16:33:39 EST
Hi John, I am attaching a patch (based on the CVS HEAD content as of the time when I write this) to give you an idea of what we had in mind.  This in by no means "final" as there are a few things to still do, but I wanted to make it available now for any comments that you may have.  The plug-ins that needed to be modified to accomplish the request are org.eclipse.core.runtime, org.eclipse.equinox.common, org.eclipse.osgi.  I will also attach an example .trace file that is produced by some example code that I added to the Plugin#getPluginPreferences() API call:

// EXAMPLE BEGIN
FrameworkDebugTrace trace = Platform.createTrace("org.eclipse.core.runtime");
this.setDebugOption("/debug", Boolean.TRUE.toString());
trace.trace("/debug/", "This trace message should not be written");
Platform.enableDebugMode(); // dynamically enable tracing
this.setDebugOption("/debug", Boolean.TRUE.toString());
trace.trace("/debug/", "Hello from Plugin#getPluginPreferences()!");
this.setDebugOption("/debug/fine", Boolean.TRUE.toString()); // dynamically enable /debug/fine option-path to 'true'
trace.traceDumpStack("/debug/fine");
this.setDebugOption("/debug/fine", Boolean.FALSE.toString()); // dynamically enable /debug/fine option-path to 'false'
trace.trace("/debug/fine", "TODO: This fine trace message should not be written");
trace.trace("/debug/info", "TODO: This trace info message should not be written");
Platform.disableDebugMode(); // dynamically disable tracing
trace.trace("/debug/", "This trace message should not be written");
// EXAMPLE END
Comment 10 Troy Bishop CLA 2009-02-25 16:34:40 EST
Created attachment 126786 [details]
initial submission for discussing any comments/concerns
Comment 11 Troy Bishop CLA 2009-02-25 16:35:16 EST
Created attachment 126787 [details]
Example resulting trace file
Comment 12 Christophe Elek CLA 2009-02-25 17:03:26 EST
Hey Troy, can I still do something like that ...


Declaration
-----------
new DebugListener() {
public optionsChanged() {
DEBUG = Plugin.getInstance().getBooleanDebugOptionValue("/debug", false);
DEBUG_PERF = Plugin.getInstance().getBooleanDebugOptionValue("/debug/perf", false);
}
}

FrameworkDebugTrace myTrace = Platform.createTrace("org.mycompany.mypluginid");

then register listener 



In my code
----------
if (DEBUG_PERF){
myTrace.trace("delta"+delta);
}
Comment 13 Troy Bishop CLA 2009-02-25 22:21:56 EST
Christophe,

Yes, definitely, that is possible.  The functionality is in place to do that - I just didn't use it for the example code.  The example code is more for testing purposes to show the dynamic enablement of the tracing.  Some of the sample code will likely not be possible with the "final" API but I just wanted a way to quickly show what can be done.

John,

One thing I should have mentioned before (which is different than what Eclipse previously used) is that there will always be a DebugOptions OSGi service now.  Previously, the DebugOptions service only existed if the product was started with -debug.  Now, the service is always there and the existence of a framework property (osgi.debug) will determine whether or not debugging is enabled or not.
Comment 14 John Arthorne CLA 2009-03-04 14:55:29 EST
Created attachment 127542 [details]
Updated patch

I have updated the patch with some small changes:

 - Moved some of the implementation classes out of API packages and into internal packages
 - Updated copyright dates, added @since tags to new methods

I have also omitted the changes to equinox.common and org.eclipse.core.runtime. We are phasing out the org.eclipse.core.runtime bundle and generally never adding new functionality to it. Most of what is there is just convenience methods for accessing various services in different bundles. Your changes were the same - they were just a convenience layer on top of the DebugOptions services. There are a number of arguments for this but I won't get into it here.

Overall I like the shape of it. In the end there are just two new API classes: DebugTraceListener and FrameworkDebugTrace, and some new methods on the existing DebugOptions API. This enables the key functionality you want - dynamic enablement/disablement, and adds some easier to use utility methods for clients in the traceEntry/traceExit methods.

One major problem in the current code is that you use Java 5 API's to access a running thread's stack trace. The framework must run on the OSGI Minimum 1.2 class library that doesn't support this method. One possibility is to have a separate bundle that requires Java 5 to provide the trace implementation, although that wouldn't enable tracing in smaller class library configurations I'm not sure how prevalent that is. Another option is to use reflection to optionally do this when Java 5 is present, and fall back to a naive implementation when Java 5 is not present.
Comment 15 Min Idzelis CLA 2009-03-04 15:11:47 EST
I also developed a tracing api (for my own code) and I also generally like the shape of this api. 

It would be nice as a convenience that ITrace had a "shouldTrace()" method on there...

In my performance sensitive code, I need to wrap everything in should trace, as simply constructing the tracing message adds a lot of performance drag. 

I usually do something like this (in my code)

if (Logger.shouldTrace(Category)) {
   Logger.trace(Category, Severity, String msg, [Exception])
}

I see that this is the equivalent...

if (Plugin.getInstance().getBooleanDebugOptionValue("/debug", false)) {
  trace.trace(...)
}

This is really wordy to write. Could make this common scenario a pain. 

One more thing that is missing is a Listener notification to register for notifications of the traces themselves. 

My my Logger/tracer framework I use an IOConsole/TextConsoleViewer to show the log messages to the user. Additionally, this allows me to install some "hyperlink detectors" i.e. IPatternMatchListener on the console. This allows me to display more details when certain traces are met. (I.E. If I show that a database object was added, when I detect the object id in the console, that becomes a hyperlink. When you click on it, I show record details in a different textbox)

By having a trace listener, it will also allow you to put the data into a different format, so you won't be stuck with the "common log format" that the default implementation provides. 
Comment 16 John Arthorne CLA 2009-03-04 15:38:26 EST
Min, the idea here is to use the listener mechanism to update your static boolean DEBUG_* fields when trace values change. Then your code can just have a field reference (even the overhead of a shouldTrace() method call can have an impact in highly sensitive areas like class loaders). See example in comment #12.
Comment 17 Christophe Elek CLA 2009-03-04 15:43:30 EST
Regarding the ITrace listener (the same way we have a ILog listener), I believe Troy and I wanted to do that, but that would require OSGI dependencies/extensions and complexity we wanted to avoid for this first release (i.e not over-engineer this 1.0 code)

Min, do you want something like the StatusHandler Code for the trace or the ILog listener ? So you want to handle something before we trace or want to be notified after we trace ?

I am worried we won't be able to put more code in before March 16... :(

Comment 18 John Arthorne CLA 2009-03-04 15:51:48 EST
Yes, the simpler the better for this release. Our deadline for this is closer to March 9th, since next week is M6 which is the API freeze.
Comment 19 Troy Bishop CLA 2009-03-04 16:14:32 EST
Thanks John,

I've merged your changes in with my code as I have updated it since I last
attached it (found a few bugs and also updated a lot of the javadoc).

You mentioned that the code for equinox.common was removed.  Is there a better
place where this logic should occur?  I was treating the .trace file the same
way that the .log file is treated (you probably saw a lot of the .log code
copied for the .trace file handling ;), and if this code is removed then right
now there is no way to set the tracing file.  Like the log file, this .trace
file isn't created unless something is written to it.

As for removing the org.eclipse.core.runtime code, that sounds fine to me...
they really were just convenience methods. However, it does reduce the need for
each plug-in to write their own DebugOptions service lookup method as well as
the implementation to Plugin.isDebugging() is rather different.  What if only
the change to Plugin.isDebugging() was kept as well as introducing a
getDebugOptions() method to the Plugin class (acquired during start() and
released during stop())?

Regading the Java 5 code usage - I'll look into this.  I didn't see initially
that the compilance needed for this plug-in needed to be 'OSGI Minimum 1.2'.

Min,

I can certainly add in an IDebugOptionsTraceListener so you that notifications
can be fired off to whomever wants to listen (assuming John approves). 
However, Christophe and my thought on this initially was that it would produce
a large amount of notifications (one for each trace message produced - which
can really add up quickly) as well as it really would be best if everyone used
the 'default' format.  This is one of the main reasons for the tracing request
is so that anyone (Eclipse or adopting products) can then look into providing
tooling to read the trace information - if the trace file isn't in a consistent
format then reading it back in will, of course, be rather difficult.
Comment 20 John Arthorne CLA 2009-03-04 16:22:35 EST
Troy, you're right about the equinox.common code. This is just "turning on" the tracing and giving it a file to write to. We wouldn't put that in the framework itself because we don't want to presuppose a writeable file system. Also the changed implementation of Plugin.isDebugging and Plugin.setDebugging makes sense. The nice effect here is that previously setDebugging never really worked because we had no event mechanism, so this is just make the API do what it was always intended to do.
Comment 21 John Arthorne CLA 2009-03-04 16:25:58 EST
Troy, can you attach an updated merged patch when you have a chance?
Comment 22 Min Idzelis CLA 2009-03-04 16:38:02 EST
(In reply to comment #16)
> Min, the idea here is to use the listener mechanism to update your static
> boolean DEBUG_* fields when trace values change. Then your code can just have a
> field reference (even the overhead of a shouldTrace() method call can have an
> impact in highly sensitive areas like class loaders). See example in comment
> #12.
> 

Ah, I see now. That is perfectly ok with me then. Of course, that means that the you can't pass in a parameter to shouldTrace(). You'd need to do something like this for handling things like severity

normal and above...
if (SEV_NORMAL || SEV_HIGHER || SEV_HIGEST) 
   trace.trace("this is normal and higher")

for just the highest
if (SEV_HIGHEST) 
   trace.trace("this is high priority only")


(In reply to comment #17)
> Regarding the ITrace listener (the same way we have a ILog listener), I believe
> Troy and I wanted to do that, but that would require OSGI
> dependencies/extensions and complexity we wanted to avoid for this first
> release (i.e not over-engineer this 1.0 code)
> 
> Min, do you want something like the StatusHandler Code for the trace or the
> ILog listener ? So you want to handle something before we trace or want to be
> notified after we trace ?
> 
> I am worried we won't be able to put more code in before March 16... :(
> 

It doesn't matter if the trace listener runs before or after the trace runs. I do not need/want to "intercept" the trace attempt or have any desire to control whether the trace should be performed or not. In fact, I would agree that you shouldn't allow code to interfere with the "system trace log." 

Unlike StatusHandler, I also have no desire to be the "policy" for tracing. Though, I would like my listener to be toggleable independently from the system-wide-tracing options. Also, it would be nice to register to only specific trace option events (I only care about my events most of the time...)
Comment 23 Min Idzelis CLA 2009-03-04 16:47:03 EST
(In reply to comment #19)
> Min,
> 
> I can certainly add in an IDebugOptionsTraceListener so you that notifications
> can be fired off to whomever wants to listen (assuming John approves). 
> However, Christophe and my thought on this initially was that it would produce
> a large amount of notifications (one for each trace message produced - which
> can really add up quickly) as well as it really would be best if everyone used
> the 'default' format.  This is one of the main reasons for the tracing request
> is so that anyone (Eclipse or adopting products) can then look into providing
> tooling to read the trace information - if the trace file isn't in a consistent
> format then reading it back in will, of course, be rather difficult.
> 

Right. I agree that it will produce a large number of notifications. But only for listeners that are actively participating. I only plan on "listening" to trace events while a special dialog is open. And, if you implement filtering as a ListenerList per option, you will only notify a subset of all the global listeners. 

I agree about having a default system trace format. (Reminds me of the apache common log format for web servers.) This is definitely useful and desired. I was just talking about possibilities of using this trace framework as a base for a higher more domain-specific tracing/runtime debugger view. (Mine is implemented as a component-specific info-dialog that contains runtime toggleable trace options, a console that dispaces traces, and other domain-specific details.) 

There's a lot of stuff that is logged by this tracing framework: caller, stack traces, etc, method name entry/exist, and this is not always wanted/needed. I'm afraid that it can clutter things up, especially for domain specific trace viewers. 
Comment 24 Thomas Watson CLA 2009-03-04 17:06:19 EST
I need to do a more indepth review once Troy attaches a new patch.  Some initial easy comments to make:

- The org.eclipse.osgi bundle manifest should not remove the x-internal directive from the org.eclipse.osgi.framework.debug package.  We are not making that package API.

- The following classes should be moved to the org.eclipse.osgi.framework.debug package along with the other implementations of debug API

org.eclipse.osgi.framework.internal.core.EclipseDebugTrace
org.eclipse.osgi.framework.internal.core.FrameworkDebugTraceEntry
org.eclipse.osgi.framework.internal.core.StackTraceHandler

I would also like to move the two static methods from StackTraceHandler and get rid of that class.  Each class eats up more perm gen space.  Be careful when moving FrameworkDebugTraceEntry it has a constant string to its fully qualified class name in the initialize method (it currently is incorrect).

We will have to use reflection to call getStatckTrace.  Not sure what to do when the method is not present.  Isn't there some hack you can do by calling java.lang.Throwable.printStackTrace(PrintWriter) and parsing the result.  I'm sure that will perform like a champ :-)

We should do the bare minimum WRT listeners.

I don't understand the changes to org.eclipse.osgi.framework.internal.core.SystemBundleActivator they do not seem needed and will not re-register the DebugOptions service if the system bundle is restarted (i.e. SystemBundle.update()).  In org.eclipse.osgi.framework.debug.FrameworkDebugOptions.enableDebugMode() we call the SystemBundleActivator.getInstance().registerDebugOptions() but I see no way that anyone could call this method if the DebugOptions service was not registered in the first place.  I don't think we should be doing that and it should not be necessary if we always register the service anyways.
Comment 25 Troy Bishop CLA 2009-03-04 20:48:05 EST
Created attachment 127595 [details]
Updated patch - fixes a few bugs and includes John's modifications

Here is an updated patch that fixes a few bugs that I had found as well as merges in the changes that John had done.  This update also includes two new API method on DebugOptions

DebugOptions#removeOption(String option) - to allow for removing an option.
DebugOptions#getOptionsForBundle(String symbolicName) - to allow for retrieval of an array of options set for a specified bundle name.

The changes to the org.eclipse.osgi plug-in should address all of the concerns John and Thomas previous mentioned except for the JDK 1.5 code dependency.  I had originally used an implementation where Throwable.printStackTrace() was used (and parsed) but when I stumbled on Thread#getStackTrace() I moved over, not realizing the dependency to JDK 1.5.  I will look into switching to use that code and update a patch soon (this will likely change the entire implementation of FrameworkDebugTraceEntry#initialize(...) so ignore this method for now :))

John,  I removed most of the changes to the org.eclipse.core.runtime plug-in; However, there are still a few changes to the Plugin class.  Please let me know if you have any concern with these changes.
Comment 26 Min Idzelis CLA 2009-03-04 22:59:34 EST
(In reply to comment #25)

> The changes to the org.eclipse.osgi plug-in should address all of the concerns
> John and Thomas previous mentioned except for the JDK 1.5 code dependency.  I
> had originally used an implementation where Throwable.printStackTrace() was
> used (and parsed) but when I stumbled on Thread#getStackTrace() I moved over,
> not realizing the dependency to JDK 1.5.  I will look into switching to use
> that code and update a patch soon (this will likely change the entire
> implementation of FrameworkDebugTraceEntry#initialize(...) so ignore this
> method for now :))

See Throwable#getStackTrace() which is JDK 1.4 level. Should be better than parsing Throwable#printStackTrace(). Thread#getStackTrace() is mostly useful when you want to retrieve the stack for a Thread other than Thread.currentThread(). 
Comment 27 Thomas Watson CLA 2009-03-04 23:05:39 EST
(In reply to comment #26)
> See Throwable#getStackTrace() which is JDK 1.4 level. Should be better than
> parsing Throwable#printStackTrace(). Thread#getStackTrace() is mostly useful
> when you want to retrieve the stack for a Thread other than
> Thread.currentThread(). 
> 

This method is also available on OSGi min 1.2 so it should be OK to use it in the core framework.
Comment 28 Troy Bishop CLA 2009-03-04 23:42:20 EST
Created attachment 127604 [details]
Updated patch - fixes a few bugs and includes John's modifications

Thanks!  I just stumbled on that information as well.  Attached is a patch to use new Exception().getStackTrace();
Comment 29 Thomas Watson CLA 2009-03-05 15:28:08 EST
Created attachment 127706 [details]
Updated patch

Patch does the following clean up

- moved EclipseDebugTrace and FrameworkDebugTraceEntry to org.eclipse.osgi.framework.debug pacakge

- Fixed org.eclipse.core.runtime.Plugin.setDebugging(boolean) to not use the Boolean.toString(boolean) method which doesn't exist on the min EE of core.runtime

- updated .api_filters in org.eclipse.osgi to avoid errors from added @noimplement and @noextend javadoc.

- Gutted FrameworkDebugTraceEntry of all set* methods.  I saw no callers and this allowed me to make all fields final.  Was there a real need to make this a "bean"?
Comment 30 John Arthorne CLA 2009-03-05 16:50:37 EST
Troy, I am currently working on some further changes after discussing with Tom. I'll attach a new patch soon.
Comment 31 Troy Bishop CLA 2009-03-05 17:07:46 EST
Created attachment 127721 [details]
some listener suggestions

I'm attaching a new patch (which includes Tom's latest changes except for the .api_filters file change - I couldn't find that in the patch) that does the following:

1) Renames DebugTraceListener to DebugOptionListener so the name of the listener class is more in line with what it's listening on (i.e. it's listening to option changes, not traces)

2) Added the interface FrameworkDebugTraceRecord in org.eclipse.osgi.service.debug which is implemented by FrameworkDebugTraceEntry.

3) Add DebugStatementListener - this allows a client to listen to any trace record that is produced.  The FrameworkDebugTraceRecord object is given to the client so that they can do whatever they want with the data.  (this would allow Min to listen and react on any trace entry that he wants to listen on)

4) Modified the initialization of FrameworkDebugTraceEntry so that the "heavier" actions are only initialized when requested (i.e. in the getClassName(), getLineNumber(), and getMethodName() methods).

The purpose for (4) is so that we can move towards a scenario where tracing is enabled but writing of the trace file is disabled.  Other listeners can then collect only the data they want and not get hit with the performance impact of iterating the stack elements if they don't need the class details of the caller (i.e. when doing development tracing of code).

Items 2, 3, 4 are suggestions (which can be handy in some situations) but ultametly it's up to John and Tom to decide if they want to include it :)
Comment 32 John Arthorne CLA 2009-03-05 17:18:35 EST
I think we'll have to wait for the next go round for further enhancements. I'm sure once people start using it there will be new things to add. Tom and I just did a detailed review and I'm in the middle of some polish work that came out of that. We just don't have the cycles right now to go back and consider new things. The important thing is that the current API shape doesn't hinder the ability to add these new ideas later. I will incorporate 1) from your list into my current changes though.
Comment 33 John Arthorne CLA 2009-03-05 18:17:25 EST
Created attachment 127727 [details]
Updated patch

Changes:

Proper example in DebugTraceListener with listener cleanup

Changed factory method on DebugOptions to match our usual factory method conventions (newDebugTrace)

FrameworkDebugTrace renamed to DebugTrace

Allow a null value for optionPath on DebugTrace
Change optionPath argument to "option" to be consistent with DebugOptions API

Significant polish changes to API of all three API classes.
Comment 34 Troy Bishop CLA 2009-03-05 20:26:18 EST
Thanks John, just one comment on your latest patch.  In DebugOptions, can the methods:

public abstract void addTraceListener(final String bundleSymbolicName, final DebugOptionListener listener);
public abstract void removeTraceListener(final String bundleSymbolicName);

be renamed to:

public abstract void addDebugOptionListener (final String bundleSymbolicName, final DebugOptionListener listener);
public abstract void removeDebugOptionListener (final String bundleSymbolicName);

so that the method name aligns better to the listener type being added?
Comment 35 Thomas Watson CLA 2009-03-05 22:49:16 EST
Created attachment 127769 [details]
Updated patch

I fixed a bug in Debug class it was never seeting DEBUG_ENABLED boolean
We cannot reference EclipseStarter from supplement source folder otherwise supplement bundle will fail to compile 
I also renamed the add/remove listener methods
Comment 36 Thomas Watson CLA 2009-03-06 00:17:19 EST
Created attachment 127774 [details]
Updated patch

Renamed DebugOptionListener to DebugOptionsListener (plural).

The major change to this patch is the removal of the add/remove DebugOptionsListener methods.  This pattern makes for ugly code that needs to ensure they remove themselves from the listener list.  This patch instead uses a services approach where clients register DebugOptionsListener services and use a sevice property to specify their symbolic name.  The debug options facility will initially call out to these services once they are registered so that the can get an initial reference to the DebugOptions service and prepopulate their internal flags.  They will also get called if one of their options change.

The other advantage of this approach is that it supports multiple listeners to the same symbolic name.  See DebugOptionsListener javadoc to see examples of this approach.
Comment 37 John Arthorne CLA 2009-03-06 10:35:53 EST
Created attachment 127821 [details]
Implementation changes

This patch includes:

 - Updated example javadoc in DebugOptionsListener
 - Changed trace output file to trace.out (file names starting with dot are a pain to use on some platforms (Windows, Mac), and it's already in a folder starting with dot so it's hidden from regular users)
 - Changed date format in trace file to be same as the error log file
 - Some javadoc cleanup
Comment 38 John Arthorne CLA 2009-03-06 10:55:49 EST
I think the patch is ready to go in HEAD, but there are some minor implementation details to iron out. The important thing is that the API shape is looking good.

 - Since the options can change dynamically, it seems misleading to write the current set of options in the trace.out file header. Those options might not actually match the ones currently running when a trace statement is written
 - We'll likely need a mechanism for dealing with file overflow when the trace file gets too big. See how we handle long error log files
 - If a bundle writes a trace statement before DataArea sets the file location, then for the rest of that session the traces for that bundle will be written on std.out. It seems like it should update when the trace location is set.
 - Each bundle writes a SESSION header to the same trace file, so once N-bundles are using it there will be N SESSION headers per session. There should only be one session header per session.
Comment 39 John Arthorne CLA 2009-03-06 10:57:33 EST
Sorry, one API detail is I'm not sure we need DebugOption#getAllOptions. Currently this is only used by the implementation class so it doesn't need to be API. And, it's only being used to write the session header, which has questionable value anyway as mentioned above.
Comment 40 Troy Bishop CLA 2009-03-06 11:23:22 EST
John,

Re:  We'll likely need a mechanism for dealing with file overflow when the trace
file gets too big. See how we handle long error log files

I basically copied the file-handling code from the EclipseLog class (in the org.eclipse.osgi bundle) so the trace file is handled in the same manner as the .log.  It has the equivalent system properties for controlling filesize and the number of files as well.  Right now it traces 1000KB of data and then rotates (same as the .log) and produces up to 10 trace backup file (same as the .log).  I don't think this item is a concern unless you're seeing otherwise?

The rest definitely sound like bugs.

I see the flaw in the options being written to the session header, but the value is more on the support side to have validation that the client enabled the correct trace options.  The use-case I was thinking of is:
1) Product support analysts either provides a .options file to the client or asks the client to enable trace strings.
2) This begins a new 'session' and writes the trace options to the trace file (when the first trace occurs).
3) Client runs the functionality that is failing and produces the trace file.
4) Client disables tracing - this ends the session.
5) Client sends the trace file to the product support analyst.

so, if possible, I'd like to keep the API but maybe we can find a better way to handle this scenario.
Comment 41 Troy Bishop CLA 2009-03-06 11:27:00 EST
sorry, my mistake (clicked commit too quickly).  DebugOption#getAllOptions doesn't need to be API, but I'd like to keep the implementation in FrameworkDebugOptions and work out the problems mentioned above when using it in the trace file.
Comment 42 John Arthorne CLA 2009-03-06 11:30:57 EST
Ok, I didn't check that you were actually rotating the trace file. Cool.

As for writing session headers, I'm ok with it (once per session). Until we have a UI for changing properties, the 99% case will be accurate.
Comment 43 Thomas Watson CLA 2009-03-06 11:38:50 EST
(In reply to comment #41)
> sorry, my mistake (clicked commit too quickly).  DebugOption#getAllOptions
> doesn't need to be API, but I'd like to keep the implementation in
> FrameworkDebugOptions and work out the problems mentioned above when using it
> in the trace file.
> 

What about DebugOptions.getOptionsForBundle(String).  Why is that needed?  Is there some UI that would need this list?
Comment 44 Troy Bishop CLA 2009-03-06 12:03:24 EST
(In reply to comment #43)
> (In reply to comment #41)
> > sorry, my mistake (clicked commit too quickly).  DebugOption#getAllOptions
> > doesn't need to be API, but I'd like to keep the implementation in
> > FrameworkDebugOptions and work out the problems mentioned above when using it
> > in the trace file.
> > 
> 
> What about DebugOptions.getOptionsForBundle(String).  Why is that needed?  Is
> there some UI that would need this list?
> 

Yep, that's exactly why :)  I'm working on a UI similar to the PDE's 'Tracing' tab in the Eclipse launcher where you select a bundle and retrieve a list of options for that bundle to check.
Comment 45 Thomas Watson CLA 2009-03-06 14:11:11 EST
(In reply to comment #44)

> Yep, that's exactly why :)  I'm working on a UI similar to the PDE's 'Tracing'
> tab in the Eclipse launcher where you select a bundle and retrieve a list of
> options for that bundle to check.
> 

But isn't that the purpose of the .options files we ship with our bundles?  Just getting the raw list of trace keys is not good enough.  You also need to get the default values and be able to deduce their type (e.g. boolean, int, or String).  Otherwise you have to assume all options are of a single type.  the getOptionsForBundle() will also only return the options explicitly set, it will not give you all the possible options (and default values).  That is something the .options file will give you.
Comment 46 Troy Bishop CLA 2009-03-06 14:29:58 EST
(In reply to comment #45)
> (In reply to comment #44)
> 
> > Yep, that's exactly why :)  I'm working on a UI similar to the PDE's 'Tracing'
> > tab in the Eclipse launcher where you select a bundle and retrieve a list of
> > options for that bundle to check.
> > 
> 
> But isn't that the purpose of the .options files we ship with our bundles? 
> Just getting the raw list of trace keys is not good enough.  You also need to
> get the default values and be able to deduce their type (e.g. boolean, int, or
> String).  Otherwise you have to assume all options are of a single type.  the
> getOptionsForBundle() will also only return the options explicitly set, it will
> not give you all the possible options (and default values).  That is something
> the .options file will give you.
> 

You are absolutely correct.  The code I had right now was using DebugOptions#getOptionsForBundle() for a specified bundle and if entries were found then it only used them.  Otherwise, it would read from the .options file of the bundle itself.  This is not 100% correct as it's possible (due to the dynamic nature of this tracing) that the entries in DebugOptions may not match the .options file, so I think this API should be removed.  I will always read from the .options file of the bundle.  Thanks!
Comment 47 Thomas Watson CLA 2009-03-06 16:07:11 EST
I updated DebugOptions to remove the getAllOptions and getOptionsForBundle methods.  I left the implementation of getAllOptions bug made the method package private.

I released this to HEAD along with some very basic sniff testcases to make sure the listeners were getting called correctly and I could dynamically enable trace.

Leaving bug open for John to release common and runtime portions.  Also moving to Equinox->Framework since that is where the bulk of the API and changes are.
Comment 48 John Arthorne CLA 2009-03-06 16:32:02 EST
Thanks all, I have released the rest of the patch to HEAD. I have opened bug 267448 to address the trace file issues raised in comment 38.
Comment 49 Troy Bishop CLA 2009-03-09 13:29:35 EDT
Thanks John and Tom for all your help with getting this added.

I've also opened bug 267683 to continue discussion of some of the enhancement items that Min had requested.
Comment 50 Thomas Watson CLA 2010-01-27 15:36:09 EST
*** Bug 162347 has been marked as a duplicate of this bug. ***
Comment 51 Thomas Watson CLA 2010-01-27 15:38:15 EST
*** Bug 139752 has been marked as a duplicate of this bug. ***