Following are some standards and guidelines (syntax, etc.) for logging statements. Following these guidelines can help you make your logging output as consistent as possible across classes.

Declaring a Logger

For consistency, declare your logger as the first field (top of code) in your class and declare it as follows:

static Logger log = Logger.getLogger(MyClassName.class.getName());

Notice that we have used the instance variable named "log" and not "logger". The term "log" (in lieu of "logger") is more efficient to type and makes for cleaner code while not reducing any developer's ability to understand the code. Follow this convention for both efficiency and consistency. Though it is conventional to use all caps for static variables, you might consider an exception in this case to ease development.

If you are declaring you logger to pipe through Apache Commons Logging, the declaration will be a little bit different:

private static final Log log = LogFactory.getLog(MyClassName.class);

Use TRACE only for tracing execution flow

In general, trace-level logging should be used only for tracing the flow of execution through a program and for flagging particular positions in a program (i.e. to ensure they have been reached). While you may want to trace every method of a class in early stages of development, you should ensure that you are only tracing key aspects of the flow when it is time to pass the code onto other developers. An overabundance of TRACE statements (especially in simple getter and setter methods) can hinder others rather than help them.

Entering a Method

  • Logging the entrance to a method should always be done with the level: TRACE
  • Use the abbreviated symbol for 'entering' which is '>>' followed by the method name. Use a parenthesis to help clarify that the item is a method. Example:
public void myMethod(){

     if(log.isTraceEnabled()){
          log.trace(">> myMethod()");
     }

     // My code...
}

Exiting a Method

  • Logging the exit from a method should always be done with the level: TRACE
  • Use the abbreviated symbol for 'exiting' which is '<<' followed by the method name. Use a parenthesis to help clarify that the item is a method. Example:
public void myMethod(){

     // My code...

     if(log.isTraceEnabled()){
          log.trace("<< myMethod()");
     }

}

Prefix all logging statements with a method name

Assuming that you will set your logging configuration to print class names, it is then helpful to prefix the statements with the name of the method from which the statement is being executed.

For example:

if(log.isDebugEnabled()){
     log.debug("-- execute() > Got param: " + param);
}

Notice also that two hyphens are used before the method name. This helps to improve legibility in log files where trace may be also used with '>>' specifying the entry of a method and '<<' specifying exit. Adding '--' in the middle of methods provides a visual indication that the statement is executed somewhere in the middle after entry and before exit. So you get a clean visual pattern like this:

TRACE >> execute()
DEBUG -- execute() > Got param: 'myParam'.
TRACE << execute() < Returning: 'myParam'.

Use DEBUG to report results to yourself and other developers

Use INFO to report results to Administrators and Users

Use Guarded Logging

"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:

if(log.isTraceEnabled()){
     log.trace("This is " + "a best practice " + "example");
}

Use StringBuffers and toString() or toPrint() to ease and improve logging

Sometimes, when you want to print all the values of an object, it is helpful to use a StringBuffer or StringBuilder. In this way, you can assemble all of the data into one clean output statement and avoid cluttering up your log file with redundant data (i.e. multiple lines with several time and level stamps for just one object). The snippet below shows an example of how to do this, but it is still not the best approach.

if(log.isDebugEnabled()){
	StringBuffer sb = new StringBuffer();
	sb.append("\n           label: " + cat.getLabel());
	sb.append("\n    categoryType: " + cat.getCategoryType());
	sb.append("\n       attribute: " + cat.getAttribute());
	sb.append("\n           value: " + cat.getValue());
	sb.append("\n      Child Cats: " + cat.getCategories().toString());
	sb.append("\n           links: " + cat.getLinks().toString());
	log.debug(">> saveCategory(Category cat, Connection con, boolean closeCon)-> passing this cat: " + sb.toString());
}

While the code above creates a clean logging statement without multiple lines containing redundant data, there is still a problem. Notice that we are printing the values of the object "cat" (of the class Category). What would be better is to move most of this code into a toString() method on the Category class itself. In this way, all developers can simply call the toString() method to get a print of all the object's current data. Sometimes, however, you might find that you'd rather use a toString() method for application functionality instead of for logging or because the toString() method is already being used in another way. In this case, you could create a method called toPrint() instead. Following is an example:

/**
* @return a String representation of this object on multiple lines
*         (primarily to be used for debugging and logging)
*/
public String toPrint() {
	StringBuffer sb = new StringBuffer();

	if (categories != null) {
		sb.append("\n categories.size: " + categories.size());
	} else {
		sb.append("\n      categories: null");
	}
	if (links != null) {
		sb.append("\n      links.size: " + links.size());
	} else {
		sb.append("\n           links: null");
	}
	sb.append("\n         ownerID: " + this.ownerID);
	sb.append("\n          userID: " + this.userID);
	sb.append("\n       attribute: " + this.attribute);
	sb.append("\n           value: " + this.value);
	sb.append("\n          locale: " + this.locale);
	sb.append("\n     description: " + this.description);
	sb.append("\n      categoryId: " + this.categoryId);
	sb.append("\nparentCategoryId: " + this.parentCategoryId);
	sb.append("\n         labelId: " + this.labelId);
	sb.append("\n    categoryType: " + this.categoryType);

	return sb.toString();
}

Notice also in the code snippet above that we have taken care to align all of the colons separating the key from value. This makes the toPrint() method's output much easier to read. Also notice that we've added a newline character to the beginning of each property statement that appends to the StringBuffer. If you get in the habit of adding a newline character to the end of the line, you might end up with something like this:

sb.append("          locale: " + this.locale + "\n");
sb.append("     description: " + this.description + "\n");
sb.append("     categoryId: " + this.categoryId + "\n");

In the example above, since the newline must be merged into the String at runtime, your asking the JVM to do unnecessary work. By putting the newline in the beginning of the String instead, you'll need no addition operator and thus, your saving the JVM from having to do that operation. It all adds up!

Now, in any point of the code's execution, it is easy for a developer to inspect the object using just a few statements like this:

if(log.isDebugEnabled()){
	log.debug("Submitting this category to delegate.getCategory(invisibleRootCategory):\n" + invisibleRootCategory.toPrint());
}

Use Delegates or Managers as a logging juncture

Typically Delegate or Manager classes act as junction or integration points. And the delegates often have very simple methods that act as proxies to actual implementations in other classes. You can take advantage of this delegate or manager class to act as a place to log the entry and exit of methods at the integration point including the data being passed in and the data returned. Here is an example of a simple method in a delegate class that logs entry, exit, and the data going in, and the data coming out:

public List getUserLinks(String OwnerAttribute , String OwnerValue, boolean anonymousView) throws Exception {
	if(log.isTraceEnabled()){
		StringBuffer sb = new StringBuffer();
		sb.append("\n>> getUserLinks(OwnerAttribute,OwnerValue,anonymousView)");
		sb.append("\nOwnerAttribute: " + OwnerAttribute);
		sb.append("\nOwnerValue: " + OwnerValue);
		sb.append("\nanonymousView: " + anonymousView);
		log.debug(sb.toString());
	}
	List userLinks = elinksDAO.getUserLinks(OwnerAttribute, OwnerValue, anonymousView);
	if(log.isTraceEnabled()){
		log.debug("<< getUserLinks() <- returning: List userLinks:\n" + userLinks.toString());
	}
	return userLinks;
}

The key here is that we have standardized on WHERE to do the primary logging so it is consistent. In this way, we don't have a random mix of primary logging code in the delegate and in the implementation classes.

There are currently no attachments on this page.

Labels:

Enter labels to add to this page:
Wait Image 
Tip: Looking for a label? Just start typing.