Logging Best Practices

uPortal 2.4 uses Apache Commons Logging.

This page describes best practices for you, the developer.

Best Practices Summary:

• Use Commons Logging
• Use a Log instance for your specific class
• Use logging levels effectively
• Log Throwables as Throwables, not as Strings
• Conditionally log dynamic messages at TRACE and DEBUG levels
• Implement toString() so other classes can log your class

Getting a logger

Importing Apache Commons Logging

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

Getting a Log reference

You obtain a Log from the static LogFactory provided by Commons Logging

public class FooClass {

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

   ....

}

You can choose to do this statically once or you could choose to obtain a Log instance for each instance of your class – Log s are threadsafe.

Declare your Log instance to be private – only you should log to your log instance. Note: there is a trick whereby some classes expose a protected Log instance which is instantiated to be the Log for the runtime class of the object returned by getClass(). This works, but strikes me as unnecessarily complex and clever. Perhaps you disagree and wish to embrace this trick. Fine, but whatever you do, don't declare one public Log instance and use it from all your classes – doing so throws away the benefit to be had from Commons Logging.

Logging levels

The following levels are available in Commons logging:

Trace is intended to log the maximum pedantic detail and the finest granularity.

Fatal is intended to be reserved for only those problems that result in complete failure of your component.

In between, it's somewhat a matter of aesthetics.

FATAL

FATAL log messages are messages about failures so core to what your component does that it simply cannot continue, will not recover, and is throwing in the towel. Inability to connect to your must-have database is probably FATAL. Anything that keeps the Portal from starting at all is FATAL. FATAL is not for the minor inconveniences of life, though – if your Weather channel can't get an updated forcast on the first try but is designed to retry periodically and this is just the first try, that's just not FATAL. Maybe it's...

ERROR

Error should be reserved for genuine errors in your component – problems from elsewhere that you are reporting or coping with successfully are probably more WARNings than ERRORs. This way a deployer can set log level ERROR for your component and thereby filter out all the noise, obtaining just the ERRORs in your component itself.

Author's note: this is a "Best practices" document and so an opportunity to preach what I am not myself virtuous enough to practice – I certainly write a lot of code that catches Thowable, log.error()'s it, and recovers. Presumably I should be writing log.warn() in those instances where I regard the error as not my component's problem directly.

WARN

WARNings are likely problems that are recovered from, perhaps. Warning, I'm not behaving ideally here, but I nonetheless can have some fallback behavior that makes sense.

INFO

INFOrmation should inform a deployer – not about problems (those are WARNings or ERRORs) – but informative nonetheless. INFOrmation is log messages a Portal administrator or deployer plausibly would welcome receiving. Of course, your sysadmin or deployer may turn off or on INFO level logging as she sees fit – I'm just saying that when she turns on INFO, it should be informative.

DEBUG

Debug is lower level information concerning program logic decisions, internal state, etc. Running a component with DEBUG logging should result in a log that narrates the choices and behaviors of the component.

TRACE

Trace is the finest granularity logging level. Ideally, TRACE should result in logging of entrance and exit of every method of your class, logging the state of the class. Plausibly, only the component developer or the poor guy eight months later performing code maintenance will ever run your component with TRACE on. TRACE is in some sense an alternative to running an interactive debugger. Don't get me wrong - both approaches have their niche. But the result from exercising a component under TRACE is conceptually similar to the approach of stepping through it.

Writing code that logs

Calling your log

Once you have created your log instance, you call one of the methods from the Log interface to perform your logging. There are three methods corresponding to each of the levels listed above. Taking error as an example:

public Interface Log {
...
void error(String message);
void error(String message, Throwable t);
boolean log.isErrorEnabled();
...
}

You use your log like this:

log.warning("No remote user set, so RemoteUserSecurityContext considering itself unauthenticated.");

log.error("Unable to validate the CAS ticket.", casException);

if (log.isTraceEnabled()){
   log.trace("entering doRender() with state " + this);
}

Logging throwables

Don't do this:

...
catch (SomeException badThing) {
   log.error("Something bad happened:" + badThing);
    ...
}
...

This throws away all the good information to be had from the throwable's stack trace. Also, "something bad happened" provided no new information, just noise. Try to have something useful to say about exceptions you are logging. Your class is likely uniquely well situated to add some context or information about what the exception thrown by some underlying component means or what its consequences are likely to be. The underlying component can tell you that the argument you passed was illegal. Only you can tell the developer responding to the problem where the bogus argument likely came from.

Saying something useful:

...
catch (SomeException badThing) {
   log.error("PersonDirectory couldn't provide attributes for user [" + user + "]", badThing);
    ...
}
...

Conditional logging

When you call log.error("Some error message"), Commons Logging will log or not your message according to its configuration. It's safe to say, though, that error messages likely will be logged somewhere.

Trace messages, on the other hand, almost never will be logged. When you call:

log.trace("My state is: " + this);

Java first evaluates the arguments to the method, calling the toString() method on your object. If you're implemented toString() (and it would be a good thing if you did), this can be an expensive computation. This String is computed, passed to the Log instance, which down inside its guts realizes that it is not configured to log at level "TRACE" and throws away the String, returns, and you code continues.

Potentially this results in a performance cost of having all these low-level logging messages in our code. What to do?

The answer here isn't to not write low level logging messages or to comment them out or delete them when you are no longer immediately using them. After all, they will be useful to whoever next wants to run your class with detailed logging. Fortunately, Commons Logging has a good answer here:

if (log.isTraceEnabled()){
   log.trace("Entering doFoo() with state " + this);
}

The isTraceEnabled() (isDebugEnabled(), is isInfoEnabled(), etc.) method returns TRUE if messages logged at level TRACE (DEBUG, INFO, etc., respectively) will actually be loggged anywhere. This allows your class to only compute your log messages if it makes sense to do so.

Best practice: dynamic log messages at low levels (TRACE and DEBUG) should be wrapped by a check to see if logging at that level is desired.

The conditional logging at more serious logging levels probably isn't worth doing since ERRORs will almost always be logged in practice anyway.

Making your class loggable

Implement toString(). toString() should expose as a human-readable String the state of your class. toString() should never ever fail. toString() should convey the class name of your class. Write this:

public String toString(){
   StringBuffer sb = new StringBuffer();
   sb.append(getClass().getName())
   sb.append(" myProperty=[").append(this.myProperty).append("]");
   sb.append(" anotherProperty=[").append(this.anotherProperty).append("]");
   return sb.toString();
}

This code has the advantage that if any of your properties are null, they will appear as the String "null".
If instead you had written:

public String toString(){
   StringBuffer sb = new StringBuffer();
   sb.append(getClass().getName())
   sb.append(" myProperty=[").append(this.myProperty.toString()).append("]");
   sb.append(" anotherProperty=[").append(this.anotherProperty.toString()).append("]");
   return sb.toString();
}

then your toString() method will throw a NullPointerException if someone tries to call toString() on it when one of its properties was null.