Declaring a Logger

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.

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

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:

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:

Some logging systems such as SLF4J support parameterized logging statements, which are preferable if the logging system supports it. The examples in this document do not show parameterized logging. However, when possible, instead of the following:

LOG.debug("-- execute() > Got param: " + param);

This is preferred:

LOG.debug("-- execute() > Got param: {}", param);

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:

Note that if you use SLF4J for logging, the necessity for guarded logging is reduced or eliminated as SLF4J has a nice pattern substitution mechanism that avoids the need for string concatenation and unnecessary evaluations and object instantiations.

SLF4J Parameter Substitution Example

log.debug("Found {} records matching filter: '{}'", records, filter);

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.

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:

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:

In the example above, since the newline must be merged into the String at runtime. Since Strings are immutable in Java, this forces the JVM to create more String objects than are necessary. 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. 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:

Use Delegates, Managers, or Service classes 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:

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.

How to setup Log4i in a web app - fast This page provides a quick guide for setting up Log4j in a web application. It is intended for those who are already familiar with Log4j and just need a rapid reminder.

About the author

Cody Burleson is an Enterprise Web Architect, entrepreneur, and writer. He designs and builds solutions with his team at Base22 using IBM WebSphere Portal, IBM Web Content Manager, IBM Connections, and Java/J2EE. He is a tireless student of information technology who loves to invent things, improve things, and share what he learns. You can find more at his blog, codyburleson.com.

15 Comments

Anonymous

Anonymous

Anonymous

Excellent article! I have a few things to add...

I dislike having to put code like this into every class:

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

Not only is it verbose and distracting, sprinkling logging methods everywhere means that you're a prisoner to your logging abstraction because you'd have to change all of your code everywhere. (Although I heard there's a new logging abstraction library that takes care of that for you, so who knows, what follows might all "old hat" already.)

So I've encapsulated it further as follows (this isn't quite how I do it as I'm doing it from memory, so there may be errors):

public class Log() {
private static (Log or Logger) LOG; // the actual logger class, not this class!
private Log() { // prevent instantiation }
/* for each logging level there are methods similar to what follows, along with variations of the methods for automatic Exception logging and the like */
public static void error(Object obj, String error) {
LOG = LogFactory.getLog(obj.class);
LOG.error(error);
}
}

You could elaborate on the Log class throughout, then you can log to your heart's content with just one line:

Log.error(this, "this was an error");

Your Log.trace method could check to see if trace is enabled and only output it if was, so you wouldn't have to check it manually every time.

Your great formatting suggestions can be encapsulated in the methods themselves, meaning you don't need to remember to write the markers manually every time, and the code would read cleaner. So inside of the Log class you would have...

You should check to see how much overhead there is getting a logger for the class each time before implementing this, so use this suggestion with caution I think we don't use a per-class logger, but my memory is fuzzy at the moment.

These are interesting suggestions. I am going to have to do some testing before coming to any conclusions, however. If I can find an even better approach based on these suggestions, I will update the article.

I am not sure if it is true that you can pass a String into a method and have the guard within the method. I think just defining the String there instantiates it before it even reaches the guard, no? That's one of the things I need to test. I'm not sure.

Anonymous

The problem with Anonymous's suggest public static methods is if you have a complex log message, the JVM will construct the string and ignores the authors point, "Use StringBuffers and toString() or toPrint() to ease and improve logging" and "Use Guarded Logging"

Anonymous

"I am not sure if it is true that you can pass a String into a method and have the guard within the method. I think just defining the String there instantiates it before it even reaches the guard, no? That's one of the things I need to test. I'm not sure."

Yes, of course the strings are going to be instantiates before it reaches the guard. Still its nicer to use it in place when you do not need to worry about string creation overhead.

Anonymous

First, if you all realized how log4j, commons-logging and slf4j handle instances of loggers, you wouldn't bother making the LOG variables static or final.
Read further the documentation of logger services. Making their variables static is not necessary, nor desirable.

Second, don't put logs in the beggining and the end of each method, which is terribly error-prone (I've witnessed several methods logging wrong method names). Instead, log through an interceptor. All the decent frameworks offer this possibility, these days.

Anonymous

Anonymous

You are talking about trace logging inside of each method, logging at the entering and exiting of the method. I have implemented this using AOP so can only talk about my implementation.

The class requiring this trace logging is typically a Spring managed bean and the calls to its methods can be intercepted using Aspect Oriented Programming. This interceptor will typically be a BeforeAdvice (intercepting entry to method) and AfterReturningAdvice (intercepts exit of method).

The interceptor implements the expected methods of these interfaces and looks at the Object to determine its class, looks at the Method to determine its name (and if required its argument types). It can then log the method being invoked. I implemented it by getting the logger for the Target object and adding "[AOP]" to the logged message to show that the logging statement would not be found in the target object.

I've just finished working on legacy code that had its own Logger class with static methods. The code was awful. Lines of log statements logged using the Logger's classname and line numbers was incredibly frustrating. Logging the method name in each log statement seems a bit daft too to be honest. With access to the source code and uncorrupted logging (line numbers not hidden) you can see the method being invoked.

isDebugEnabled() - lots of good people use it but I like my code to run through the same path regardless of the logging levels. Simply put - if you don't need your code to run through the same exact path in development as in production then put in the isDebugEnabled() and good luck!