Expeditor Developers: java.util.logging best practices

The following is a set of best practices for JSR47 usage:

Is there a good way to get logger?
The following pattern can be used in each class to obtain a JSR47 logger:
```
private static final String CLAZZ_NAME = MyClass.class.getName();
private static final String PKG = MyClass.class.getPackage().getName();
private static final String LOG_RB = PKG + "." + “Messages.properties);
private static Logger _logger = Logger.getLogger(PKG,LOG_RB);
```
Substitute your class name for MyClass and ensure you have a properties file with the same name as the leaf node of the package.

Note: If you use this pattern, use caution when later renaming your packages.
Why not just use LogManager.getLogger("com.ibm.rcp.mypackage");?
java.util.logging.LogManager.getLogger(String name) returns the logger with a matching name if it already exists. Otherwise it returns null. There is no guarantee that a given logger will exist when your class gets instantiated since the order of class instantiation is not determinate. Even if it were currently, the order could change later. Therefore, it is necessary to use the get methods from the Logger class to ensure that a Logger is returned. Whether you use LogManager or Logger to get a logger, no more than one instance of a named logger is ever in existence within a VM at any given time.

Additionally, since it is possible to instantiate a logger at first with no resource bundle and then later use it with a resource bundle, consistently requesting it by means of the Logger class ensures that the expected resource bundle will be available. If you use LogManager you will get the logger (if it exists). However, it must already have an associated resource bundle. There are alternatives, such as testing to see if the logger has a ResourceBundle already, and if not, using Logger,getLogger(String name, String resourceBundleName) to fix the situations. Alternatively, you could adopt the convention of only using the logbr methods of Logger instead.
How do I change the log level for my loggers?
The LogManager is initialized from values in the file <workspace>/.config/rcpinstall.properties. There, you can set the logger level. For example, if you want to see all log entries for your code in the package com.ibm.rcp.mypackage, add the following string:
```
com.ibm.rcp.mypackage.level=FINEST
```
If you want to hear less from other JSR47 loggers, simply change the default values in the rcpinstall.properties to SEVERE.
Where are my logs?
The system log can be found in <workspace>\logs\error-log-0.xml where n is a number 0 (current log) or 1 log from the last time it was run.

The system trace file can be found in <workspace>\logs\trace-log-0.xml where n is a number 0 (current log) or 1 log from the last time it was run.
What is "guarded logging" and why do I need it?
"Guarded logging" is a pattern that checks to see if a log statement will result in output before it is executed. Since the logger itself makes this check, it may seem redundant to do this for every call. However, as almost every logging call creates String objects, it is critical. The accumulation of these Strings causes memory fragmentation and unnecessary garbage collection. Garbage collection, while beneficial, also produces significant performance loss. To reduce this as much as possible, always guard logging statements with a severity less than SEVERE. Since SEVERE is always expressed by the logger, these do not need a guard. Here is an example, given the declarations in FAQ 1.
```
            if(_logger.isLoggable(WARNING)){
                _logger.logp(WARNING,CLAZZ_NAME,method,
                     "warn.unable.to.get.preference",
                   new Object[]{pid,key});
           }
```
What are guidelines for using each logging level?
INFO
Do: Use INFO for events that represent the normal operation of a component, and will be useful in resolving problems that may occur in other code segments. For example, After verifying that install operations are complete, the following message is logged from the launcher:
```
Done with install operations
```
Don't: Use INFO for debug information, for tracing program execution, in potentially frequently repeating events, or to simply confirm an event unless it will be useful in determining the cause of a problem with a related event.

WARNING
Do: Use WARNING when a problem has occurred that will effect normal operations adversely, but will not prevent most operations to continue. A good example would be the following message from provisioning:
```
Failed to retrieve page file for URL EXPEDITOR.png.
```
Don't: Use WARNING if the problem completely or severely eliminates the use of a function, or for information messages that do not indicate impaired function.

SEVERE
Do: Use SEVERE to indicate an event causing a significant or complete loss of some function. An example of a SEVERE message is written by the platform plug-in when the plugin_customization.ini can not be read:
```
Error loading plugin customization file
```
Don't: Use SEVERE if all or most functionality will continue to be available or if the problem is transient.
How tracing accomplished? What about developer-only tracing?
Tracing is off by default. Trace is intended for use by developers, Quality Engineers and Support.

There are three trace levels: FINE, FINER and FINEST.

FINE: Use this level for significant events that explain the flow or state of the system when trying to understand or debug a problem. These are usually at the level of object creation, catch clauses for exceptions that do not constitute errors, and so on.
FINER: There is a set of Logger methods that generate messages with a FINER level. These are entry(...), exit(..), finer(..) and throwing(..).
- Entering and exiting should be used for method entry and exit.
- Finer can be used for any tracing that is more verbose than desired for fine, but is not method entry/exit or used before throwing an exception.
- Throwing should be used when you are about to throw or re-throw an exception.
FINEST: Finest is usually thought of as developer or debug tracing. This is used during development, when attempting to learn the behavior of a system at a fine level of detail and when trying to diagnose difficult problems once the code is released.

Tracing is a valuable tool, both during and after development. There is a common misunderstanding that there is "Developer Only" tracing. Tracing that developers want to be able to turn on and off should be done using the java.util.logging.Logger API. The level should be FINEST. Such tracing can be valuable to support when diagnosing a difficult customer problem. Having it available will be one factor in reducing the support team’s dependence on development. The rule of thumb should be: If it is valuable now, it may be valuable later. Use Java™ logging at the FINEST level and you will have virtually no impact on performance (with proper guarding), and you will create a valuable tool for someone else. If you use println or printStackTrace you are not tying into the manageable Java logging framework, and are likely going to create a distraction for someone else.
What should I do about Logging Exceptions?
All exceptions should be noted in a logging statement. Normally, this would be at the WARNING or SEVERE level unless the exception is trivial or being rethrown. Some further guidelines:
- Always provide a specific message for the log entry including the exception. This should explain the impact of the exception.
- Log the exception, not its message. Unless you set it yourself, you have no guarantee that the message will be intelligible or even exist.
- Do not call printStackTrace on the exception. The logger will do this for you, and in a way that will allow things like autonomics to respond to the exception. .
- If you catch the exception and then throw a new one (frequently the case in well written API) you should use the caught exception as the cause of the thrown exception. Generally, you should not log the caught exception in this case, assuming everybody up the stack follows the same guidelines.
- Sometimes it makes sense to log the exception anyway, even though you are going to throw another one if you believe this information may be of use to the user.

What is an example of logging?

The following two code samples are common logging patterns.

if (_logger.isLoggable(Level.INFO)) {
  _logger.logp(Level.INFO, CLAZZ_NAME, "execute", "info.process.reqs");
  }

And...

_logger.logp(Level.SEVERE,CLAZZ_NAME,"run","err.rcpapplication.error",
   throwable);

What is an example of tracing?

The following code examples illustrate tracing.

Tracing example 1:

if (_logger.isLoggable(Level.FINE)) 
        	            	_logger.fine("Setting activities for page 
                           " + _model.getName() + ":");

Tracing example 2:

private static final String CLASSNAME = 
	CompositeApplicationAdapterServiceImpl.CLASSNAME;  
// If you refactor the class name changes

	private GUID methodX(URL url, IProgressMonitor pM, boolean overrideCache) {
		if (logger.isLoggable(Level.FINER)) {
			logger.entering(CLASSNAME, "methodX", url==
                             null?"null":url.toExternalForm());
		}
		GUID res = null;
		…
	}

In this example, only the URL is logged on enter, as the other arguments are not that useful during debugging; often when an application does not load, it is a problem with a partially corrupted URL which is partially computed, so it is very useful to see exactly what URL is being passed into the load call. Also, this is a private method; there are many public methods that do their job by calling this private method, so it funnels the logging into this method instead of having the URL logged several times by the public calls.

} finally {
			if (logger.isLoggable(Level.FINER)) {
				logger.exiting(CLASSNAME, "methodX", res);
			}
		}

The "exiting" call is in a finally clause so that it logs the exit even if the method throws an exception. It also logs the result being return from this method, which is, again, very useful for debugging purposes to figure out what, if anything, went wrong.

Tracing example 3:

public void showApplication(URL url, String pageId, IProgressMonitor 
          progressMonitor)
		 throws IllegalArgumentException, CompositeApplicationException {

		if (logger.isLoggable(Level.FINER)) {
			logger.entering(CLASSNAME, 
				"showApplication(URL,String,IProgressMonitor)", 
				new Object[] {url, pageId, progressMonitor});
		}
} catch (RuntimeException e) {
			logger.log(Level.SEVERE,
				PortalCaiUIPlugin.getString(
					"str.caiuiplugin.calling.applications.update.job.error"), e);
			throw new CompositeApplicationException(e);
		}

Should I cache my logger level?
It may seem tempting to check the level of your logger once during your execution, and then simply refer to that cached level instead of asking for the level each time you want to guard your calls. This is not recommended, however, since it can cause your code to not respond to dynamic updates to logger level configuration such as via the OSGi command prompt.

Java.util.logging best practices